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

/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!

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

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)

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

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

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

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.

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.

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.

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.

> 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?

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.

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.

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).

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.

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

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

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)

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

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.

Is the fact that WPA Supplicant has been stopped significant?

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?

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

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)

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

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

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?

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.

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

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

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

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.

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

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

 Thanks

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

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

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!

@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!