network mount hangs on shutdown - NetworkManager needs to stop after network.target

[Colin Law]

To replicate, perform a manual cifs mount, for example:

sudo mount -t cifs -o credentials=****,user,rw,uid=1000 //192.168.1.nnn/docs /media/test_mount

Then shutdown. When booted with systemd there is a 1 to 2 minute delay before shutdown. In syslog the last shutdown (09:47:11 13th March) showed the effect, though I fear that syslog shuts down too early to see anything.

If booted with upstart there is no noticeable delay on shutdown.

ProblemType: Bug
DistroRelease: Ubuntu 15.04
Package: systemd 219-4ubuntu5 [modified: usr/share/dbus-1/system-services/org.freedesktop.systemd1.service]
ProcVersionSignature: Ubuntu 3.19.0-9.9-generic 3.19.1
Uname: Linux 3.19.0-9-generic x86_64
ApportVersion: 2.16.2-0ubuntu3
Architecture: amd64
CurrentDesktop: Unity
Date: Fri Mar 13 09:50:08 2015
InstallationDate: Installed on 2014-10-21 (142 days ago)
InstallationMedia: Ubuntu 14.10 "Utopic Unicorn" - Alpha amd64 (20141017)
MachineType: FUJITSU LIFEBOOK A544
ProcKernelCmdLine: BOOT_IMAGE=/boot/vmlinuz-3.19.0-9-generic root=UUID=c68c6484-d8d6-44f6-b429-892aa6ef74cf ro
SourcePackage: systemd
UpgradeStatus: Upgraded to vivid on 2015-02-25 (15 days ago)
dmi.bios.date: 12/01/2014
dmi.bios.vendor: FUJITSU // Phoenix Technologies Ltd.
dmi.bios.version: Version 1.18
dmi.board.name: FJNBB35
dmi.board.vendor: FUJITSU
dmi.chassis.type: 10
dmi.chassis.vendor: FUJITSU
dmi.modalias: dmi:bvnFUJITSU//PhoenixTechnologiesLtd.:bvrVersion1.18:bd12/01/2014:svnFUJITSU:pnLIFEBOOKA544:pvr:rvnFUJITSU:rnFJNBB35:rvr:cvnFUJITSU:ct10:cvr:
dmi.product.name: LIFEBOOK A544
dmi.sys.vendor: FUJITSU

[Martin Pitt (pitti)]

/usr/share/doc/systemd/README.Debian explains how to debug shutdown hangs. I suspect it's hanging on the relevant .mount unit? Can you "systemctl cat whatever.mount" it in the debug shell and copy that into a file, and attach that here? Would also be nice to capture "journalctl -b > journal.txt" in the debug shell while it's hanging, and attach that here.

Thanks!

[Colin Law (colin-law)]

I enabled the debug shell via "sudo systemctl start debug-shell" and checked that I could get into it ok. When I then shutdown it went to the debug shell by itself but the keyboard was dead so I could not do anything. It shutdown after the delay.

Before the shutdown, in the debug shell, I got

#systemctl status media-test_mount.mount
   Loaded: loaded (/proc/self/mountinfo)
   Active: active (mounted) since Fri 2015-03-13 11:44:55 GMT; 1min 15s ago
    Where: /media/test_mount
     What: //192.168.1.***/docs

But systemctl cat media-test_mount.mount said
No files found for media-test_mount.mount

[Martin Pitt (pitti)]

Sorry, I meant "systemctl show", not "cat" (the latter only works for non-virtual units). Thanks!

(I'll reproduce this after my holidays, but I don't have a samba server at hand, so it'll take some setup and learning how to create one)

[Launchpad Janitor (janitor)]

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

[Martin Pitt (pitti)]

Hm, you just did an attachment, but apparently removed it again? (Still had credentials in it, I figure :) )

[Colin Law (colin-law)]

I have removed the syslog attachment as I had not sanitised it, let me know if it is needed.

[Colin Law (colin-law)]

Martin, yes, have re-attached the systemclt show results.
Have also marked the previous bug which I thought was an error in an init script as a dup of this as I believe this is the fundamental problem.

[Martin Pitt (pitti)]

sanitized is fine, I'm mostly interested in the dependencies. But they look fine:

Before=umount.target remote-fs.target
After=-.mount system.slice network-online.target network.target remote-fs-pre.target systemd-journald.socket

i. e. it should shut this down before shutting down the network. But I have a hunch that the networking goes down before that somehow, and thus the umount hangs as it can't properly "sign off" from the server any more. For that I would need the journal.

It's weird/sad that the debug shell doesn't work, but there's a plan B: Enable persistant journal with "sudo mkdir /var/log/journal", then reboot, do the mount, shut down, wait for the timeout, then reboot again. Now do

  journalctl -b -1 > /tmp/journal.txt

and attach /tmp/journal.txt here. (the -b -1 means "logs from the previous boot"). After that you are welcome to "sudo rm -r /var/log/journal" again if you don't care about that.

[Colin Law (colin-law)]

I have got the journal but there is a lot of potentially sensitive stuff there. Would it be possible to make the bug private while you review it?
I think it is more subtle than the network going down early.

[Colin Law (colin-law)]

Alternatively this may be enough.

Mar 13 16:19:26 tigger systemd[1]: Stopped ACPI event daemon.
Mar 13 16:19:28 tigger mysql[2887]: ...done.
Mar 13 16:19:28 tigger systemd-journal[256]: Forwarding to syslog missed 68 messages.
Mar 13 16:19:28 tigger systemd[1]: Stopped LSB: Start and stop the mysql database server daemon.
Mar 13 16:19:28 tigger systemd[1]: Stopped target System Time Synchronized.
Mar 13 16:19:28 tigger systemd[1]: Stopping System Time Synchronized.
Mar 13 16:19:28 tigger systemd[1]: Stopped target Remote File Systems.
Mar 13 16:19:28 tigger systemd[1]: Stopping Remote File Systems.
Mar 13 16:19:28 tigger systemd[1]: Unmounting /media/test_mount...
Mar 13 16:20:58 tigger systemd[1]: media-test_mount.mount unmounting timed out. Stopping.
Mar 13 16:21:14 tigger kernel: CIFS VFS: Server 192.168.1.96 has not responded in 120 seconds. Reconnecting...
Mar 13 16:21:34 tigger umount[3012]: umount: /media/test_mount: target is busy
Mar 13 16:21:34 tigger umount[3012]: (In some cases useful info about processes that
Mar 13 16:21:34 tigger umount[3012]: use the device is found by lsof(8) or fuser(1).)
Mar 13 16:21:34 tigger systemd[1]: media-test_mount.mount mount process exited, code=exited status=32
Mar 13 16:21:34 tigger systemd[1]: Failed unmounting /media/test_mount.
Mar 13 16:21:34 tigger systemd[1]: Stopped target Network is Online.
Mar 13 16:21:34 tigger systemd[1]: Stopping Network is Online.
Mar 13 16:21:34 tigger systemd[1]: Stopped Wait for all "auto" /etc/network/interfaces to be up for network-online.target.
Mar 13 16:21:34 tigger systemd[1]: Stopping Wait for all "auto" /etc/network/interfaces to be up for network-online.target...
Mar 13 16:21:34 tigger systemd[1]: Stopped target Basic System.
Mar 13 16:21:34 tigger systemd[1]: Stopping Basic System.
Mar 13 16:21:34 tigger systemd[1]: Stopped target Slices.

[Martin Pitt (pitti)]

> Would it be possible to make the bug private while you review it?

Feel free to do that, or just send me the log via private mail. But indeed I'm mostly interested in the relation of when eth0/wifi is brought down during shutdown, and when media-test_mount.mount gets unmounted. The log excerpt certainly suggests that the wifi/eth stopped *before* this snippet? Do you see related log output for that?

Do you use NetworkManager with dynamic devices, or /etc/network/interfaces?

[Colin Law (colin-law)]

Yes, you are right, NetworkManager was stopped earlier, I had missed that. Connection is wired, wifi is disabled. I do use NM.

Wasn't sure whether if I made it private you would be able to see it. Will send the log by PM.

[Martin Pitt (pitti)]

Indeed, thanks for the logs and your patience!

Mar 13 16:19:26 tigger systemd[1]: Stopped Network Manager.
Mar 13 16:19:28 tigger systemd[1]: Stopped target Remote File Systems.
Mar 13 16:19:28 tigger systemd[1]: Stopping Remote File Systems.
Mar 13 16:19:28 tigger systemd[1]: Unmounting /media/test_mount...
Mar 13 16:21:34 tigger systemd[1]: Stopped target Network is Online.
Mar 13 16:21:34 tigger systemd[1]: Stopping Network is Online.

So we need to fix that in NetworkManager's units, it needs to stop after network-online.target and network.target.

[Colin Law (colin-law)]

Great, is it as simple as adding
Before=network-online.target network.target
to Unit section of /lib/systemd/system/NetworkManager.service?

Having tried it that does appear to fix the problem (including the problem with the init script in the duplicate bug, where it was timing out on a umount command).

[Martin Pitt (pitti)]

Indeed, this morning it just occurred to me that this is missing. Indeed our unit doesn't have that, this was fixed later upstream. This is indeed fixed in upstream's unit, but not in our's.

[Launchpad Janitor (janitor)]

This bug was fixed in the package network-manager - 0.9.10.0-4ubuntu11

---------------
network-manager (0.9.10.0-4ubuntu11) vivid; urgency=medium

  * Disable 0001-Debian-specific-tweaks-for-NetworkManager-systemd-se.patch.
    We actually do want NetworkManager stop after network.target. Fixes long
    shutdown hangs with remote mounts, and other network services which need
    connectivity on shutdown. (LP: #1431774)
 -- Martin Pitt <email address hidden> Sat, 14 Mar 2015 07:42:18 +0100

[Norbert (asterix52)]

Hello Martin,

I still have a 120sec delay at shutdown.

Mär 14 12:17:58 holze-desktop kernel: CIFS VFS: Server 192.168.178.1 has not responded in 120 seconds. Reconnecting...

Regards,

Norbert

[Norbert (asterix52)]

I have the latest version of network-manager installed:

holze@holze-desktop:~$ dpkg --list | grep network-manager
ii network-manager 0.9.10.0-4ubuntu11 amd64 network management framework (daemon and userspace tools)
ii network-manager-gnome 0.9.10.1-0ubuntu1 amd64 network management framework (GNOME frontend)

[Colin Law (colin-law)]

Having tried with wifi connection (was previously wired) I also still see the problem if connected via wifi.

[Martin Pitt (pitti)]

Hm, in Norbert's journal the "Unmounted /mnt/fritz.nas." now appears before "Stopping Network is Online." and shutting down NetworkManager and wlan0, so this part actually worked now.

The problem seems to be that "Stopping D-Bus System Message Bus..." appears before shutting down NetworkManager, and then NetworkManager complains a lot about not being able to connect to D-Bus any more.

It should work to add an After=dbus.service to /lib/systemd/system/NetworkManager.service's [Unit] section, but that smells like a workaround to me. NetworkManager. basic.target already requires dbus.socket. This needs some more investigation. Either way, this is a separate and new problem now.

[Colin Law (colin-law)]

Is the fact that WPA Supplicant has been stopped significant?

[Michael Biebl (mbiebl)]

Let me chime in here as maintainer of NM in Debian: The reason why we ship the patch, which removes Wants/Before=network.target is, that this lead to dependency cycles if services/sysv init scripts in rcS (sysinit.target) had Should-Start/Required-Start: $network, like for example /etc/init.d/rpcbind in Debian.

If there is no such sysv init script Ubuntu, this patch can be dropped indeed.

As for Colin's remark in #25, sounds sensible, to add After=network.target to wpa_supplicant.service as well.

Have you tried adding that and see if that fixes the problem on shutdown with WiFi?

[Michael Biebl (mbiebl)]

Sorry, meant Before=network.target, of course...

[Martin Pitt (pitti)]

Hey Michael,

Michael Biebl [2015-03-15 3:38 -0000]:
> If there is no such sysv init script Ubuntu, this patch can be dropped
> indeed.

Right, I recently went through and fixed rpcbind and console-setup, so
we should be good in a default installation. I still need to go
through the whole archive wrt. that, though.

> As for Colin's remark in #25, sounds sensible, to add
> After=network.target to wpa_supplicant.service as well.

(Before=) indeed, that sounds plausible too, thanks for pointing out!

Martin

--
Martin Pitt | http://www.piware.de
Ubuntu Developer (www.ubuntu.com) | Debian Developer (www.debian.org)

[Norbert (asterix52)]

holze@holze-desktop:~$ cat /lib/systemd/system/wpa_supplicant.service
[Unit]
Description=WPA supplicant
Before=network.target

[Service]
Type=dbus
BusName=fi.epitest.hostap.WPASupplicant
ExecStart=/sbin/wpa_supplicant -u -s -O /var/run/wpa_supplicant

[Install]
WantedBy=multi-user.target
Alias=dbus-fi.epitest.hostap.WPASupplicant.service

This didn't resolve the issue for me.

In this bugreport is a patch mentioned. Is this part on 219?

https://bugs.freedesktop.org/show_bug.cgi?id=86707

[Launchpad Janitor (janitor)]

This bug was fixed in the package wpa - 2.1-0ubuntu7

---------------
wpa (2.1-0ubuntu7) vivid; urgency=medium

  Cherry-pick from Debian svn:
  * Add wpasupplicant_fix-systemd-unit-dependencies.patch: Fix systemd unit
    dependencies for wpasupplicant, it needs to be started before the network
    target (Closes: 780552, LP: #1431774).
 -- Martin Pitt <email address hidden> Fri, 27 Mar 2015 14:07:35 +0100

[Martin Pitt (pitti)]

So who of the reporters still has this issue?

> It should work to add an After=dbus.service to /lib/systemd/system/NetworkManager.service's [Unit] section, but that smells like a workaround to me.

If you have, can you please try this workaround, if it resolves these problems?

[Colin Law (colin-law)]

I am still seeing the problem when connected via wifi (Ok on wired).

Adding After=dbus.service to /lib/systemd/system/NetworkManager.service's [Unit] section appears to fix it.

[Martin Pitt (pitti)]

Colin, can you please get me a journalctl output without the workaround when this happens? (see comment 3). Thanks!

[Martin Pitt (pitti)]

Colin: I meant with latest wpasupplicant (we already have previous journals here)

[Martin Pitt (pitti)]

@Colin: nevermind, I can reproduce the wrong shutdown ordering here now.

[Martin Pitt (pitti)]

The original issue here was fixed in network-manager 0.9.10.0-4ubuntu11 (see comment 20), and that's what the bug title says too, so closing the NetworkManager task again. The remaining issue, D-Bus stopping too early, is tracked in bug 1438612.

[Martin Pitt (pitti)]

@Colin: I need a journal after all, see bug 1438612. Thanks!

[Norbert (asterix52)]

The latest updates (dbus, networkmanager) solved my problem (wlan, cifs, dbus failure).

 Thanks

[Augustin Riedinger (augustin-riedinger)]

Hello,

I'm having the issue with Debian 8. I know we are in Ubuntu's launchpad but it is the most documented issue I found on the web.
I guess the fix will be similar, though releases will differ.

Could you summarize the fix?

Is it:

Adding `After=dbus.service` to /lib/systemd/system/NetworkManager.service's [Unit] section

Or:

Adding `Before=network.target` to /lib/systemd/system/wpa_supplicant.service's [Unit] section

Or both?

Thanks

[Augustin Riedinger (augustin-riedinger)]

Finally, adding
```
ExecStop=/bin/true
KillMode=none
```
 to `/lib/systemd/system/dbus.service`'s [Service] section fixed it, as mentioned there: https://bugs.launchpad.net/ubuntu/+source/dbus/+bug/1438612

[Daniel (enoch85)]

Don't know if this is the correct place to post this as this seems to be released and fixed, but I experience this on the current Ubuntu 16.04 running as a VM in VMware Workstation 10.

Every time I shut down, it hangs with the message "[OK] Stopped target Netwwork is Online." Then it takes abut 10-15 minutes until it shuts down. Is there any way to troubleshoot this?

Thanks!

[Martin Pitt (pitti)]

@Daniel, please file a new bug with your network config and /etc/fstab details and attach "sudo journalctl -b > /tmp/journal.txt". Without more information it's impossible to say what's wrong, and this report is closed (and most likely a different cause) anyway. Thanks!