Multipath services fails to start on Ubuntu 17.04 on boot and kdump (initramfs)

Default Comment by Bridge

Hi Mauricio,
thank you for the report!

I checked on a system with 2LUNs and 4 paths each.
Mine seemed to work just fine at first so I tried to get closer to your case.
It did so after reboot and in general, but maybe my setup needs tweaking to trigger.

Yet unable to reproduce I focused on the code.

For now I'd want to:
1. get your help to recreate the issue - what more than having multipath devices and rebooting do I need? Any special setup to force it to be more active in the initramfs?
2. understand if we need to clear up more on /var/run vs /run? (see below)
3. why do I actually have both pid files populated - is that the same in your case?
4. a few mods to your patch (see below)

----- 2 -------

I can at least confirm confusion on the .pid file, but don't know yet if that might have been intentional:
sudo multipathd -k'show daemon'
pid 46392 idle
$ ll /var/run/multipathd.pid /run/multipathd.pid
-rw-r--r-- 1 root root 5 Mär 18 04:16 /run/multipathd.pid
-rw-r--r-- 1 root root 5 Mär 18 04:16 /var/run/multipathd.pid
$ cat /var/run/multipathd.pid
46392
$ cat /run/multipathd.pid
46392

So in a running system (not initrd) I have both pid files and they both point to the right pid at least for me.

The define of the run dir gets to be only /run and then is in build log as -DRUN_DIR=\"run\".
That just did not exist in Xenial/Yakkety at all, that is why we changed now.
Would we want/need to just get this to be /var/run/.. again?
If not there are way more references that need to be fixed up.
=> debian/multipath-tools.init isn't really used anyway other than for Debian backports.
But while local-bottom is Ubuntu only, at least for this we might bother Debian to know about.

Also there is this in Ubuntu's hooks:
 63 # multipathd requires /var/run/multipathd.pid
 64 mkdir -p $DESTDIR/var/run
Does it need it then it should now be /run right?

------4------

In the patch I think it overall makes sense to harden/improve the shutdown - even not being able to reproduce yet, here some patch feedback:

+pid="$(pidof multipathd)"

I think this should get some safety if this does not return a pid.
There might be reasons to do so, and these should skip the whole shutdown part.

Also there might be some theoretical cases where the
+out="$(/sbin/multipathd -k'shutdown')"
As a side effect could make the pid change, so please re-arrange the pidof and the shutdown.
BTW - Is the shutdown synchronous?

Status changed to 'Confirmed' because the bug affects multiple users.

------- Comment From <email address hidden> 2017-03-27 21:18 EDT-------
*** Bug 152908 has been marked as a duplicate of this bug. ***

I agree this could benefit some rework, but I think we could do with fixing the issue now with a simpler fix (just using /run directly in the initramfs scripts), while we get to a concensus on the improved local-bottom code.

Thanks to share your opinion cyphermox.

I agree and wanted to provide a quick way to test, so there is the search&replace all /var/run with /run approach test ppa at: https://launchpad.net/~ci-train-ppa-service/+archive/ubuntu/2665

@IBM
1. could you please try the ppa if that would be a quick-fix for now until we settled on renewed local-bottom
2. since I couldn't repro with my MP setup I'm still waiting on some hints how exactly to trigger the actual issue (asked in comment #2)

The multipath-tools changes I wrote about are waiting in the unapproved queue right now, I uploaded it immediately after writing the comment.

This bug was fixed in the package multipath-tools - 0.6.4-3ubuntu3

---------------
multipath-tools (0.6.4-3ubuntu3) zesty; urgency=medium

  * debian/initramfs/hooks, debian/initramfs/local-bottom:
    Update hooks and local-bottom to use /run instead of /var/run as a path
    for multipathd.pid in the initramfs. (LP: #1670811)

 -- Mathieu Trudel-Lapierre <email address hidden> Tue, 28 Mar 2017 21:20:22 -0400

Hi Christian,

Apologies, I couldn't get back to you sooner since Friday.

> 1. get your help to recreate the issue - what more than having multipath devices and rebooting do I need? Any special setup to force it to be more active in the initramfs?

Not really special setup needed. Actually no multipath devices needed.

On a 17.04 guest with a single virtio scsi disk, apt-get upgrade'd yesterday, I just install multipath-tools-boot to hit this problem.

It happens in 3 reboots in a row.

No multipath devices required:

 # ls -d /sys/block/sd*
 /sys/block/sda
 #

Just install multipath-tools-boot and reboot.

I see this error in 3 reboots in a row.

 # apt-get install multipath-tools-boot

 # dpkg -s multipath-tools | grep ^Version
 Version: 0.6.4-3ubuntu2

 # reboot
 <...>
 Begin: Waiting for udev to settle (multipath) ... done.
 done.
 Begin: Will now check root file system ... fsck from util-linux 2.29
 [/sbin/fsck.ext4 (1) -- /dev/sda2] fsck.ext4 -a -C0 /dev/sda2
 /dev/sda2: clean, 251692/8388608 files, 5617803/33552128 blocks
 done.
 [ 3.868178] EXT4-fs (sda2): mounted filesystem with ordered data mode. Opts: (null)
 done.
 Begin: Running /scripts/local-bottom ... Begin: Stopping multipathd ... cat: can't open '/var/run/multipathd.pid': No such file or directory
 Failure: inconsistent PIDs (pidof: '349', multipathd.pid: '')
 done.
 Begin: Running /scripts/init-bottom ... done.

 ...

 Welcome to Ubuntu Zesty Zapus (development branch)!

 [ 4.656639] systemd[1]: Set hostname to <ubuntu>.
 [ 5.300761] systemd[1]: Listening on udev Kernel Socket.
 [ OK ] Listening on udev Kernel Socket.
 [ 5.301826] systemd[1]: multipathd.socket: Failed to listen on sockets: Address already in use
 [ 5.302126] systemd[1]: Failed to listen on multipathd control socket.
 [FAILED] Failed to listen on multipathd control socket.
 See 'systemctl status multipathd.socket' for details.
 ...
 [FAILED] Failed to start Device-Mapper Multipath Device Controller.
 See 'systemctl status multipathd.service' for details.

 # systemctl status multipathd.socket
 ● multipathd.socket - multipathd control socket
    Loaded: loaded (/lib/systemd/system/multipathd.socket; static; vendor preset:
    Active: failed (Result: resources)
    Listen: @/org/kernel/linux/storage/multipathd (Stream)

@paelzer @cyphermox

> 2. understand if we need to clear up more on /var/run vs /run? (see below)\

Well, that helps. The version in -proposed works /almost/ perfectly.

With the -proposed version, the kill is OK, the socket unit FAILS, and service unit is OK.

 # dpkg -s multipath-tools | grep ^Version
 Version: 0.6.4-3ubuntu3

 Begin: Waiting for udev to settle (multipath) ... done.
 done.
 Begin: Will now check root file system ... fsck from util-linux 2.29
 [/sbin/fsck.ext4 (1) -- /dev/sda2] fsck.ext4 -a -C0 /dev/sda2
 /dev/sda2: clean, 251701/8388608 files, 5618205/33552128 blocks
 done.
 [ 3.805862] EXT4-fs (sda2): mounted filesystem with ordered data mode. Opts: (null)
 done.
 Begin: Running /scripts/local-bottom ... Begin: Stopping multipathd ... done.
 done.

The socket unit still fails,

 [FAILED] Failed to listen on multipathd control socket.
 See 'systemctl status multipathd.socket' for details.

 ...

But the service unit starts,

 [ OK ] Started Device-Mapper Multipath Device Controller.

 # systemctl status multipathd.socket
 ● multipathd.socket - multipathd control socket
    Loaded: loaded (/lib/systemd/system/multipathd.socket; static; vendor preset: enabled)
    Active: failed (Result: resources)
    Listen: @/org/kernel/linux/storage/multipathd (Stream)

 # systemctl status multipathd.service
 ● multipathd.service - Device-Mapper Multipath Device Controller
    Loaded: loaded (/lib/systemd/system/multipathd.service; enabled; vendor preset: enabled)
    Active: active (running) since Thu 2017-03-30 08:51:44 CDT; 2min 54s ago
  Main PID: 2316 (multipathd)

 # ps ax | grep multipathd
  2316 ? SLsl 0:00 /sbin/multipathd -d -s
  5765 pts/0 S+ 0:00 grep --color=auto multipathd
 #

The important part with that socket is that it is used in udev rules
to detect path add/remove/changes, and update multipath accordingly.

If 'multipath -u /dev/sdX' hangs waiting for the socket, the paths
fail that udev handling, timeout the udev workers, and don't get
the /required/ udev properties to be added to right multipath maps.

There is another bug report here, duplicated to this one internally,
which shows all paths in multipath -l listed with #:#:#:# SCSI addresses
because of that, thus the paths become unused..

All because of that socket failed somehow, causing the hang.

BUT

For some reason, it's working fine despite the socket unit failure
(wondering if the multipathd service dealt with it.)

 # strace -e connect multipath -u /dev/sda
 connect(4, {sa_family=AF_LOCAL, sun_path=@"/org/kernel/linux/storage/multipathd"}, 39) = 0
 connect(4, {sa_family=AF_LOCAL, sun_path="/dev/log"}, 110) = 0
 +++ exited with 1 +++

 # udevadm test --action=add /block/sda
 <...>
 ID_SERIAL=0QEMU_QEMU_HARDDISK_drive-scsi0-0-0-0
 <...>
 # echo $?
 0

So I guess this patch indeed helps.

It would be good (or possibly important, if the socket accidentally working
is actually an intermittent thing) to have the socket unit activation fixed.

For that I think we'll need the timing-based approach to wait for the socket
to be closed/released.

> 3. why do I actually have both pid files populated - is that the same in your case?

No idea, but a suspicion..

Any chance that some other initramfs hook that is present on your setup is symlinking /var/run to /run at initramfs too?

> 4. a few mods to your patch (see below)

Thanks for the careful review :)

> In the patch I think it overall makes sense to harden/improve the shutdown - even not being able to reproduce yet, here some patch feedback:

> +pid="$(pidof multipathd)"

> I think this should get some safety if this does not return a pid.
> There might be reasons to do so, and these should skip the whole shutdown part.

If I understood it correctly, it does.

And the whole shutdown is skipped in case 'multipathd -kshutdown' failed
and PID is null (as kill_stage does not progress into 1,2,3)

+if [ "$out" = 'ok' ] \
+|| ( [ -n "$pid" ] && /bin/kill -SIGINT $pid ) \
+|| ( [ -n "$pid" ] && /bin/kill -SIGKILL $pid ); then
+ kill_stage=1
+fi

Maybe I'm missing something in your point?

> Also there might be some theoretical cases where the
> +out="$(/sbin/multipathd -k'shutdown')"
> As a side effect could make the pid change, so please re-arrange the pidof and the shutdown.

I'm afraid I don't see that theoretical case happening.
Can you please elaborate a bit more on that, for my own education?

As far as I see, the -k switch just connects to the multipathd socket
(which should be running from the daemonized multipathd instance),
sends the argument/command to it, and exit.

multipathd/main.c::main()

                case 'k':
                        conf = load_config(DEFAULT_CONFIGFILE);
                        if (!conf)
                                exit(1);
                        if (verbosity)
                                conf->verbosity = verbosity;
                        uxclnt(optarg, uxsock_timeout + 100);
                        exit(0);

And the uxclnt() call tries to connect to the socket (i.e., implies
multipathd already running), and if it fails (e.g., multipathd not
running), it just exits -- doesn't try to restart it / PID change.

So I'm not sure how that could happen.

> BTW - Is the shutdown synchronous?

No, it's async. Any command from 'multipathd -k' (cli instance)
is sent to multipathd (daemonized instance) via unix socket,
and the cli instance immediately exits.
Then the daemonized instance handles it there.

The shutdown, for example, gets 'running_state' set to
DAEMON_SHUTDOWN, and that is broadcast to other pthreads.

The one which is running child() will take it and proceed
into free/unload/shutdown.

@cyphermox

BTW, the other/duplicate bug of this, is on 16.04.
Can you please upload your fix for it too?

Thanks!

@cyphermox @paelzer

This patch resolves the systemd multipathd.socket unit problem.
It just waits a while until the socket closes.

The error message is gone, and the unit state is OK after booting.

  # systemctl status multipathd.socket
  ● multipathd.socket - multipathd control socket
     Loaded: loaded (/lib/systemd/system/multipathd.socket; static; vendor preset: enabled)
     Active: active (running) since Thu 2017-03-30 11:39:51 CDT; 18min ago
  ...

In my system, I added an echo debug statement to check it, and it took ~4 seconds.
Weird, but obviously that with such delay, the socket would be still open by the time the unit was started.

 while [ $seconds -gt 0 ]; do
+ echo WAITING FOR SOCKET :: seconds $seconds
  grep -q '@/org/kernel/linux/storage/multipathd' /proc/net/unix || break

  Begin: Running /scripts/local-bottom ... Begin: Stopping multipathd ... done.
  WAIT FOR SOCKET :: seconds 10
  WAIT FOR SOCKET :: seconds 9
  WAIT FOR SOCKET :: seconds 8
  WAIT FOR SOCKET :: seconds 7
  done.

On Thu, Mar 30, 2017 at 6:25 PM, Mauricio Faria de Oliveira <
<email address hidden>> wrote:
[...]

> And the whole shutdown is skipped in case 'multipathd -kshutdown' failed
> and PID is null (as kill_stage does not progress into 1,2,3)
>
> +if [ "$out" = 'ok' ] \
> +|| ( [ -n "$pid" ] && /bin/kill -SIGINT $pid ) \
> +|| ( [ -n "$pid" ] && /bin/kill -SIGKILL $pid ); then
> + kill_stage=1
> +fi
>
> Maybe I'm missing something in your point?
>

I think you are fine, I think I just expected the logic inverse.
If there is no pid this is essentially being:
=> "check ok" || false || false

And that should be fine - if none of that it does not go into stage 1 below.

> Also there might be some theoretical cases where the
> > +out="$(/sbin/multipathd -k'shutdown')"
> > As a side effect could make the pid change, so please re-arrange the
> pidof and the shutdown.
>
> I'm afraid I don't see that theoretical case happening.
> Can you please elaborate a bit more on that, for my own education?
>

pid="$(pidof multipathd)"
# lets assume it gets pid 1001 being the current main PID and there are
three sibling processes of a sort of multipath-helper binary with pids:
1002, 1003, 1004

out="$(/sbin/multipathd -k'shutdown')"
# here the shutdown might send signals to all, and helpers 1002, 1003
# But due to an error on terminating 1004 it sends back to its parent that
it has to reload
# main 1001 re-execs itself and 1001 goes away but a new 1005 appears and
spawns two new helpers 1006, 1007.
# now you end up with main 1005, helper 1004, 1006, 1007
# shutdown will reply some error to "out" but you will not know exactly

This is just a case for such an issue - and as I said only theoretical, but
essentially it is a chance to use an out of date value.
By changing order you are at least a bit better off - only "a bit" as if
you start to consider asynchronous behavior it gets worse again.
In some sense juggling with pids is a bit like potential racy "use after
free" and since we are sending kill signals we might at least close the
minimal things we see.

 [... thanks for the great explanation that was following ...]

Yeah I think the current case is safe, never the less IMHO reordering two
lines can't hurt to not have a bug in it in 2022.
I'd agree it is waste if it would be more effort than reordering two lines.

On Thu, Mar 30, 2017 at 6:29 PM, Mauricio Faria de Oliveira <
<email address hidden>> wrote:

> BTW, the other/duplicate bug of this, is on 16.04.
> Can you please upload your fix for it too?
>

I assume you mean you full fix to go back to 16.04/16.10.
But please bear in mind that the fix uploaded for now is only doing the
"use /run instead of /var/run" change.
I might miss something here, but IMHO that is only valid in zesty.

Zesty has -DRUN_DIR=\"run\" see [1] and in the code using it:
libmultipath/defaults.h:45:#define DEFAULT_PIDFILE "/" RUN_DIR
"/multipathd.pid"

But former Xenial/Yakkety versions have:
libmultipath/defaults.h:29:#define DEFAULT_PIDFILE
 "/var/run/multipathd.pid"

So for X/Y we will need to sort out the renewal of the bottom code as
Cyphermox mentioned, and once we know how it looks like consider SRU'ing
that back.

[1]:
https://launchpadlibrarian.net/313425549/buildlog_ubuntu-zesty-ppc64el.multipath-tools_0.6.4-3ubuntu3_BUILDING.txt.gz

Hi Christian,

> > Can you please elaborate a bit more on that, for my own education?

Upfront, thanks for the explanation. It really helped to think a bit
more on the code and go figure out a few things.

I'm writing up an explanation below of why I still think it cannot
happen. And it's _not_ that I want to insist in making my point -- because
actually we don't even need that anymore w/ the much simpler/elegant
fix of changing the /var/run & /run paths :) -- it's more of I liked
to go check it out in the code.

> pid="$(pidof multipathd)"
> # lets assume it gets pid 1001 being the current main PID and there are
> three sibling processes of a sort of multipath-helper binary with pids:
> 1002, 1003, 1004

AFAIK, multipathd only spawns threads (with same PID as parent), but
not other processes (ie, different PIDs). There only point with fork()
calls are in daemonize()'ing the multipathd main() into a child().

After that, only one PID exists (despite several threads running, e.g.,
uevent listener, path checkers).

We can verify that, as with a running/functinal multipathd there's only
a single process running, but all the path checking/uevent listening is
going on all the time.

> out="$(/sbin/multipathd -k'shutdown')"
> # here the shutdown might send signals to all, and helpers 1002, 1003
> # But due to an error on terminating 1004 it sends back to its parent that
> it has to reload

Even considering the PIDs could be different (which doesn't seem to be the
case), the child() loop requires just one evaluation of (running_state != DAEMON_SHUTDOWN)
to get out of the loop in which it could process any other events,
and goes right into tearing down the threads and the process.

And the only place where it could get a different PID would be daemonize()
which has fork() calls, but it's only called from main().

> # main 1001 re-execs itself and 1001 goes away but a new 1005 appears and
> spawns two new helpers 1006, 1007.
> # now you end up with main 1005, helper 1004, 1006, 1007
> # shutdown will reply some error to "out" but you will not know exactly

> This is just a case for such an issue - and as I said only theoretical, but
> essentially it is a chance to use an out of date value.

Sure, I understand. It's been a great exercise analyzing it. Thanks.

Christian,

> I assume you mean you full fix to go back to 16.04/16.10.
> But please bear in mind that the fix uploaded for now is only doing the
> "use /run instead of /var/run" change.
> I might miss something here, but IMHO that is only valid in zesty.

Or maybe me. I'll go check in 16.04.x, because there was a bug report
here with 16.04.x in which I indeed saw multipathd not being killed
on initramfs's local-bottom script.

And it seems even weirder that I just checked that system's initramfs
and it has both /var/run and /run as normal directories (so not sure
that kill has failed at all).

    # lsb_release -d
    Description: Ubuntu 16.04.2 LTS

    # gzip -dc /boot/initrd.img-$(uname -r) | cpio -id

    # ls -ld run var/run
    drwxr-xr-x 2 root root 40 Apr 6 05:40 run
    drwxr-xr-x 2 root root 40 Apr 6 05:40 var/run

I'll go check that out.

> Zesty has -DRUN_DIR=\"run\" see [1] and in the code using it:
> libmultipath/defaults.h:45:#define DEFAULT_PIDFILE "/" RUN_DIR
> "/multipathd.pid"

> But former Xenial/Yakkety versions have:
> libmultipath/defaults.h:29:#define DEFAULT_PIDFILE
> "/var/run/multipathd.pid"

> So for X/Y we will need to sort out the renewal of the bottom code as
> Cyphermox mentioned, and once we know how it looks like consider SRU'ing
> that back.

Okay. I'll go check the 16.04.x problem and follow up here.

cheers

> Okay. I'll go check the 16.04.x problem and follow up here.

Forget about 16.04.x for now.
I have a fresh install from release ISO and couldn't reproduce the problem.

More debugging to happen on the system reaching that problem.

P.S.: for _17.04_ we'd still need the wait-socket patch (comment #15), please.

Investingating the 16.04.x problem.

The multipathd instance in initramfs _sometimes_ does not die with the default signal, only with 9.
It's intermittent.
And refuses to happen with -d / foreground logging enabled. sigh.

I'll try to insert rsyslog into initramfs and get something useful.

It looks like a deadlock among the main and another thread.

Continuing tomorrow.

Begin: Running /scripts/local-bottom ... Begin: Stopping multipathd ... done.
done.
Begin: Running /scripts/init-bottom ... done.
Spawning shell within the initramfs

BusyBox v1.22.1 (Ubuntu 1:1.22.0-15ubuntu1) built-in shell (ash)
Enter 'help' for a list of built-in commands.

(initramfs) ps w | grep multipath
  433 root 1357m S /sbin/multipathd -B
 3486 root 3456 S {exe} grep multipath

(initramfs) kill 433
(initramfs) ps w | grep multipath
  433 root 1357m S /sbin/multipathd -B
 3489 root 3456 S {exe} grep multipath

(initramfs) kill -9 433
(initramfs) ps w | grep multipath
 3492 root 3456 S {exe} grep multipath

(initramfs) grep PRETTY /etc/*release
PRETTY_NAME="Ubuntu 16.04.2 LTS"

...

another run:

(initramfs) ps w | grep multipathd
  434 root 1357m S /sbin/multipathd -B
 3524 root 3456 S {exe} grep multipathd

(initramfs) kill 434

(initramfs) ps w | grep multipathd
  434 root 1357m S /sbin/multipathd -B
 3527 root 3456 S {exe} grep multipathd

(initramfs) ls -ld /proc/434/task/*
dr-xr-xr-x 7 0 /proc/434/task/440
dr-xr-xr-x 7 0 /proc/434/task/434

(initramfs) cat /proc/434/task/434/stack
[<0000000000000a01>] 0xa01
[<c000000000015c78>] __switch_to+0x1f8/0x350
[<c000000000166578>] futex_wait_queue_me+0xf8/0x1e0
[<c000000000167d74>] futex_wait+0x174/0x2c0
[<c000000000169e44>] do_futex+0x234/0xd70
[<c00000000016aa34>] SyS_futex+0xb4/0x1e0
[<c000000000009204>] system_call+0x38/0xb4

(initramfs) cat /proc/434/task/440/stack
[<c0000002afd8adc0>] 0xc0000002afd8adc0
[<c000000000015c78>] __switch_to+0x1f8/0x350
[<c000000000166578>] futex_wait_queue_me+0xf8/0x1e0
[<c000000000167d74>] futex_wait+0x174/0x2c0
[<c000000000169e44>] do_futex+0x234/0xd70
[<c00000000016aa34>] SyS_futex+0xb4/0x1e0
[<c000000000009204>] system_call+0x38/0xb4

(initramfs)