[systemd-devel] Hang when mounting NFS via systemd

Mon Oct 8 10:57:10 PDT 2012

On 09/24/2012 12:56 PM, Lennart Poettering wrote:
> On Sun, 23.09.12 17:21, Bardur Arantsson (spam at scientician.net) wrote:
> 
>> Hi all,
>>
[--snip--]
> 
> This indicates a bug i systemd actually. For some reason systemd appears
> to believe that your NFS share is a device to wait for.
> 
> I tried to fix this in git with two commits. Please test!
> 
> Lennart
> 

It seems to work perfectly now (v194) when I do the mounting post-boot
in a shell, using

   # systemctl start data.mount

However, it still hangs during boot, waits for the defined timeout
period and then... proceeds to work perfectly.

I'm not sure, but could it have something to do with my use of two
automounts where one is nested inside the other? I have

    /data
and /data/music mounted inside that.

Here's what I hope is the relevant portion of the boot log from journalctl:

Oct 07 11:20:05 gwendolyn systemd[1]: Reached target Remote File Systems
(Pre).
Oct 07 11:20:05 gwendolyn systemd[1]: Mounting /data...
Oct 07 11:20:05 gwendolyn NetworkManager[297]: <info> WiFi enabled by
radio killswitch; enabled by state file
Oct 07 11:20:05 gwendolyn NetworkManager[297]: <info> WWAN enabled by
radio killswitch; enabled by state file
Oct 07 11:20:05 gwendolyn NetworkManager[297]: <info> WiMAX enabled by
radio killswitch; enabled by state file
Oct 07 11:20:05 gwendolyn NetworkManager[297]: <info> Networking is
enabled by state file
Oct 07 11:20:05 gwendolyn NetworkManager[297]: <warn> failed to allocate
link cache: (-10) Operation not supported
Oct 07 11:20:05 gwendolyn NetworkManager[297]: <info> (eth0): carrier is OFF
Oct 07 11:20:05 gwendolyn NetworkManager[297]: <info> (eth0): new
Ethernet device (driver: 'r8169' ifindex: 2)
Oct 07 11:20:05 gwendolyn NetworkManager[297]: <info> (eth0): exported
as /org/freedesktop/NetworkManager/Devices/0
Oct 07 11:20:05 gwendolyn NetworkManager[297]: <info> (eth0): now managed
Oct 07 11:20:05 gwendolyn NetworkManager[297]: <info> (eth0): device
state change: unmanaged -> unavailable (reason 'managed') [10 20 2]
Oct 07 11:20:05 gwendolyn NetworkManager[297]: <info> (eth0): bringing
up device.
Oct 07 11:20:05 gwendolyn NetworkManager[297]: <info> (eth0): preparing
device.
Oct 07 11:20:05 gwendolyn ntpd[314]: ntpd 4.2.6p5 at 1.2349-o Tue Aug 21
15:06:24 UTC 2012 (1)
Oct 07 11:20:05 gwendolyn ntpd[317]: proto: precision = 0.489 usec
Oct 07 11:20:05 gwendolyn ntpd[317]: ntp_io: estimated max descriptors:
1024, initial socket boundary: 16
Oct 07 11:20:05 gwendolyn ntpd[317]: Listen and drop on 0 v4wildcard
0.0.0.0 UDP 123
Oct 07 11:20:05 gwendolyn NetworkManager[297]: <info> (eth0):
deactivating device (reason 'managed') [2]
Oct 07 11:20:05 gwendolyn NetworkManager[297]: <info> Added default
wired connection 'Wired connection 1' for
/sys/devices/pci0000:00/0000:00:1c.4/0000:04:00.0/net/eth
Oct 07 11:20:05 gwendolyn kernel: r8169 0000:04:00.0: >eth0: link down
Oct 07 11:20:05 gwendolyn systemd[1]: Started Network Time Service.
Oct 07 11:20:05 gwendolyn systemd[1]: Started RPC Bind.
Oct 07 11:20:05 gwendolyn systemd[1]: Starting RPC Port Mapper.
Oct 07 11:20:05 gwendolyn systemd[1]: Reached target RPC Port Mapper.
Oct 07 11:20:05 gwendolyn kernel: r8169 0000:04:00.0: >eth0: link down
Oct 07 11:20:05 gwendolyn kernel: IPv6: ADDRCONF(NETDEV_UP): eth0: link
is not ready
Oct 07 11:20:05 gwendolyn NetworkManager[297]: <warn> failed to allocate
link cache: (-10) Operation not supported
Oct 07 11:20:05 gwendolyn NetworkManager[297]: <info> (eth1): carrier is OFF
Oct 07 11:20:05 gwendolyn NetworkManager[297]: <info> (eth1): new
Ethernet device (driver: 'r8169' ifindex: 3)
Oct 07 11:20:05 gwendolyn NetworkManager[297]: <info> (eth1): exported
as /org/freedesktop/NetworkManager/Devices/1
Oct 07 11:20:05 gwendolyn NetworkManager[297]: <info> (eth1): now managed
Oct 07 11:20:05 gwendolyn NetworkManager[297]: <info> (eth1): device
state change: unmanaged -> unavailable (reason 'managed') [10 20 2]
Oct 07 11:20:05 gwendolyn NetworkManager[297]: <info> (eth1): bringing
up device.
Oct 07 11:20:05 gwendolyn ntpd[317]: Listen and drop on 1 v6wildcard ::
UDP 123
Oct 07 11:20:05 gwendolyn ntpd[317]: Listen normally on 2 lo 127.0.0.1
UDP 123
Oct 07 11:20:05 gwendolyn ntpd[317]: Listen normally on 3 lo ::1 UDP 123
Oct 07 11:20:05 gwendolyn NetworkManager[297]: <info> (eth1): preparing
device.
Oct 07 11:20:05 gwendolyn NetworkManager[297]: <info> (eth1):
deactivating device (reason 'managed') [2]
Oct 07 11:20:05 gwendolyn ntpd[317]: peers refreshed
Oct 07 11:20:05 gwendolyn ntpd[317]: Listening on routing socket on fd
#20 for interface updates
Oct 07 11:20:05 gwendolyn NetworkManager[297]: <info> Added default
wired connection 'Wired connection 2' for
/sys/devices/pci0000:00/0000:00:1c.5/0000:05:00.0/net/eth
Oct 07 11:20:05 gwendolyn NetworkManager[297]: <warn>
/sys/devices/virtual/net/lo: couldn't determine device driver; ignoring...
Oct 07 11:20:05 gwendolyn NetworkManager[297]: <warn>
/sys/devices/virtual/net/lo: couldn't determine device driver; ignoring...
Oct 07 11:20:05 gwendolyn kernel: r8169 0000:05:00.0: >eth1: link down
Oct 07 11:20:05 gwendolyn kernel: IPv6: ADDRCONF(NETDEV_UP): eth1: link
is not ready
Oct 07 11:20:05 gwendolyn colord[306]: (colord:306): Cd-WARNING **:
CdProfileStore: failed to add profile
'/usr/share/color/icc/krita/README': failed to parse /usr/sha
Oct 07 11:20:05 gwendolyn dbus-daemon[302]: dbus[302]: [system]
Activating via systemd: service name='org.freedesktop.colord-sane'
unit='colord-sane.service'
Oct 07 11:20:05 gwendolyn dbus[302]: [system] Activating via systemd:
service name='org.freedesktop.colord-sane' unit='colord-sane.service'
Oct 07 11:20:05 gwendolyn systemd[1]: Starting Daemon for monitoring
attached scanners and registering them with colord...
Oct 07 11:20:05 gwendolyn dbus-daemon[302]: dbus[302]: [system]
Successfully activated service 'org.freedesktop.colord-sane'
Oct 07 11:20:05 gwendolyn dbus[302]: [system] Successfully activated
service 'org.freedesktop.colord-sane'
Oct 07 11:20:05 gwendolyn systemd[1]: Started Daemon for monitoring
attached scanners and registering them with colord.
Oct 07 11:20:06 gwendolyn dbus-daemon[302]: dbus[302]: [system]
Activating via systemd: service name='org.freedesktop.Avahi'
unit='dbus-org.freedesktop.Avahi.service'
Oct 07 11:20:06 gwendolyn dbus-daemon[302]: dbus[302]: [system]
Activation via systemd failed for unit
'dbus-org.freedesktop.Avahi.service': Unit dbus-org.freedesktop.
Oct 07 11:20:06 gwendolyn dbus[302]: [system] Activating via systemd:
service name='org.freedesktop.Avahi'
unit='dbus-org.freedesktop.Avahi.service'
Oct 07 11:20:06 gwendolyn dbus[302]: [system] Activation via systemd
failed for unit 'dbus-org.freedesktop.Avahi.service': Unit
dbus-org.freedesktop.Avahi.service fail
Oct 07 11:20:07 gwendolyn NetworkManager[297]: <info> (eth0): carrier
now ON (device state 20)
Oct 07 11:20:07 gwendolyn kernel: r8169 0000:04:00.0: >eth0: link up
Oct 07 11:20:07 gwendolyn kernel: IPv6: ADDRCONF(NETDEV_CHANGE): eth0:
link becomes ready
Oct 07 11:20:07 gwendolyn NetworkManager[297]: <info> (eth0): device
state change: unavailable -> disconnected (reason 'carrier-changed') [20
30 40]
Oct 07 11:20:07 gwendolyn NetworkManager[297]: <info> Auto-activating
connection 'Wired connection 1'.
Oct 07 11:20:07 gwendolyn NetworkManager[297]: <info> Activation (eth0)
starting connection 'Wired connection 1'
Oct 07 11:20:07 gwendolyn NetworkManager[297]: <info> (eth0): device
state change: disconnected -> prepare (reason 'none') [30 40 0]
Oct 07 11:20:07 gwendolyn NetworkManager[297]: <info> Activation (eth0)
Stage 1 of 5 (Device Prepare) scheduled...
Oct 07 11:20:07 gwendolyn NetworkManager[297]: <info> Activation (eth0)
Stage 1 of 5 (Device Prepare) started...
Oct 07 11:20:07 gwendolyn NetworkManager[297]: <info> Activation (eth0)
Stage 2 of 5 (Device Configure) scheduled...
Oct 07 11:20:07 gwendolyn NetworkManager[297]: <info> Activation (eth0)
Stage 1 of 5 (Device Prepare) complete.
Oct 07 11:20:07 gwendolyn NetworkManager[297]: <info> Activation (eth0)
Stage 2 of 5 (Device Configure) starting...
Oct 07 11:20:07 gwendolyn NetworkManager[297]: <info> (eth0): device
state change: prepare -> config (reason 'none') [40 50 0]
Oct 07 11:20:07 gwendolyn NetworkManager[297]: <info> Activation (eth0)
Stage 2 of 5 (Device Configure) successful.
Oct 07 11:20:07 gwendolyn NetworkManager[297]: <info> Activation (eth0)
Stage 3 of 5 (IP Configure Start) scheduled.
Oct 07 11:20:07 gwendolyn NetworkManager[297]: <info> Activation (eth0)
Stage 2 of 5 (Device Configure) complete.
Oct 07 11:20:07 gwendolyn NetworkManager[297]: <info> Activation (eth0)
Stage 3 of 5 (IP Configure Start) started...
Oct 07 11:20:07 gwendolyn NetworkManager[297]: <info> (eth0): device
state change: config -> ip-config (reason 'none') [50 70 0]
Oct 07 11:20:07 gwendolyn NetworkManager[297]: <info> Activation (eth0)
Beginning DHCPv4 transaction (timeout in 45 seconds)
Oct 07 11:20:07 gwendolyn NetworkManager[297]: <info> dhcpcd started
with pid 326
Oct 07 11:20:07 gwendolyn NetworkManager[297]: <info> Activation (eth0)
Beginning IP6 addrconf.
Oct 07 11:20:07 gwendolyn dhcpcd[326]: version 5.6.2 starting
Oct 07 11:20:07 gwendolyn NetworkManager[297]: <info> Activation (eth0)
Stage 3 of 5 (IP Configure Start) complete.
Oct 07 11:20:07 gwendolyn dhcpcd[326]: eth0: sending IPv6 Router
Solicitation
Oct 07 11:20:07 gwendolyn dhcpcd[326]: eth0: sendmsg: Cannot assign
requested address
Oct 07 11:20:07 gwendolyn NetworkManager[297]: <info> (eth0): DHCPv4
state changed nbi -> preinit
Oct 07 11:20:07 gwendolyn dhcpcd[326]: eth0: rebinding lease of 192.168.0.10
Oct 07 11:20:07 gwendolyn dhcpcd[326]: eth0: acknowledged 192.168.0.10
from 192.168.0.1
Oct 07 11:20:07 gwendolyn dhcpcd[326]: eth0: checking for 192.168.0.10
Oct 07 11:20:07 gwendolyn dbus-daemon[302]: dbus[302]: [system]
Activating via systemd: service name='org.freedesktop.Avahi'
unit='dbus-org.freedesktop.Avahi.service'
Oct 07 11:20:07 gwendolyn dbus[302]: [system] Activating via systemd:
service name='org.freedesktop.Avahi'
unit='dbus-org.freedesktop.Avahi.service'
Oct 07 11:20:07 gwendolyn dbus[302]: [system] Activation via systemd
failed for unit 'dbus-org.freedesktop.Avahi.service': Unit
dbus-org.freedesktop.Avahi.service fail
Oct 07 11:20:07 gwendolyn dbus-daemon[302]: dbus[302]: [system]
Activation via systemd failed for unit
'dbus-org.freedesktop.Avahi.service': Unit dbus-org.freedesktop.
Oct 07 11:20:09 gwendolyn dbus-daemon[302]: dbus[302]: [system]
Activating via systemd: service name='org.freedesktop.Avahi'
unit='dbus-org.freedesktop.Avahi.service'
Oct 07 11:20:09 gwendolyn dbus[302]: [system] Activating via systemd:
service name='org.freedesktop.Avahi'
unit='dbus-org.freedesktop.Avahi.service'
Oct 07 11:20:09 gwendolyn dbus[302]: [system] Activation via systemd
failed for unit 'dbus-org.freedesktop.Avahi.service': Unit
dbus-org.freedesktop.Avahi.service fail
Oct 07 11:20:09 gwendolyn dbus-daemon[302]: dbus[302]: [system]
Activation via systemd failed for unit
'dbus-org.freedesktop.Avahi.service': Unit dbus-org.freedesktop.
Oct 07 11:20:10 gwendolyn dbus-daemon[302]: dbus[302]: [system]
Activating via systemd: service name='org.freedesktop.Avahi'
unit='dbus-org.freedesktop.Avahi.service'
Oct 07 11:20:10 gwendolyn dbus[302]: [system] Activating via systemd:
service name='org.freedesktop.Avahi'
unit='dbus-org.freedesktop.Avahi.service'
Oct 07 11:20:10 gwendolyn dbus[302]: [system] Activation via systemd
failed for unit 'dbus-org.freedesktop.Avahi.service': Unit
dbus-org.freedesktop.Avahi.service fail
Oct 07 11:20:10 gwendolyn dbus-daemon[302]: dbus[302]: [system]
Activation via systemd failed for unit
'dbus-org.freedesktop.Avahi.service': Unit dbus-org.freedesktop.
Oct 07 11:20:11 gwendolyn dhcpcd[326]: eth0: sending IPv6 Router
Solicitation
Oct 07 11:20:12 gwendolyn dhcpcd[326]: eth0: leased 192.168.0.10 for
43200 seconds
Oct 07 11:20:12 gwendolyn NetworkManager[297]: <info> (eth0): DHCPv4
state changed preinit -> bound
Oct 07 11:20:12 gwendolyn NetworkManager[297]: <info>   address 192.168.0.10
Oct 07 11:20:12 gwendolyn NetworkManager[297]: <info>   prefix 24
(255.255.255.0)
Oct 07 11:20:12 gwendolyn NetworkManager[297]: <info>   gateway 192.168.0.1
Oct 07 11:20:12 gwendolyn NetworkManager[297]: <info>   hostname 'gwendolyn'
Oct 07 11:20:12 gwendolyn NetworkManager[297]: <info>   nameserver
'192.168.0.1'
Oct 07 11:20:12 gwendolyn NetworkManager[297]: <info>   domain name
'scientician.net'
Oct 07 11:20:12 gwendolyn NetworkManager[297]: <info> Activation (eth0)
Stage 5 of 5 (IPv4 Configure Commit) scheduled...
Oct 07 11:20:12 gwendolyn NetworkManager[297]: <info> Activation (eth0)
Stage 5 of 5 (IPv4 Commit) started...
Oct 07 11:20:13 gwendolyn NetworkManager[297]: <info> (eth0): device
state change: ip-config -> activated (reason 'none') [70 100 0]
Oct 07 11:20:13 gwendolyn NetworkManager[297]: <info> Policy set 'Wired
connection 1' (eth0) as default for IPv4 routing and DNS.
Oct 07 11:20:13 gwendolyn NetworkManager[297]: <info> Activation (eth0)
successful, device activated.
Oct 07 11:20:13 gwendolyn NetworkManager[297]: <info> Activation (eth0)
Stage 5 of 5 (IPv4 Commit) complete.
Oct 07 11:20:13 gwendolyn dbus[302]: [system] Activating service
name='org.freedesktop.nm_dispatcher' (using servicehelper)
Oct 07 11:20:13 gwendolyn dbus-daemon[302]: dbus[302]: [system]
Activating service name='org.freedesktop.nm_dispatcher' (using
servicehelper)
Oct 07 11:20:14 gwendolyn dbus-daemon[302]: dbus[302]: [system]
Successfully activated service 'org.freedesktop.nm_dispatcher'
Oct 07 11:20:13 gwendolyn dbus[302]: [system] Successfully activated
service 'org.freedesktop.nm_dispatcher'
Oct 07 11:20:15 gwendolyn dhcpcd[326]: eth0: sending IPv6 Router
Solicitation
Oct 07 11:20:19 gwendolyn dhcpcd[326]: eth0: sending IPv6 Router
Solicitation
Oct 07 11:20:19 gwendolyn dhcpcd[326]: eth0: no IPv6 Routers available
Oct 07 11:20:27 gwendolyn NetworkManager[297]: <info> (eth0): IP6
addrconf timed out or failed.
Oct 07 11:20:27 gwendolyn NetworkManager[297]: <info> Activation (eth0)
Stage 4 of 5 (IPv6 Configure Timeout) scheduled...
Oct 07 11:20:27 gwendolyn NetworkManager[297]: <info> Activation (eth0)
Stage 4 of 5 (IPv6 Configure Timeout) started...
Oct 07 11:20:27 gwendolyn NetworkManager[297]: <info> Activation (eth0)
Stage 4 of 5 (IPv6 Configure Timeout) complete.
Oct 07 11:21:05 gwendolyn systemd[1]: Mounted /data.
Oct 07 11:21:05 gwendolyn systemd[1]: Starting data-music.automount.
Oct 07 11:21:05 gwendolyn systemd[1]: Set up automount data-music.automount.
Oct 07 11:21:05 gwendolyn systemd[1]: Starting Remote File Systems.
Oct 07 11:21:05 gwendolyn systemd[1]: Reached target Remote File Systems.
Oct 07 11:21:05 gwendolyn systemd[1]: Starting Trigger Flushing of
Journal to Persistent Storage...
Oct 07 11:21:05 gwendolyn systemd[1]: Started Trigger Flushing of
Journal to Persistent Storage.
Oct 07 11:21:05 gwendolyn systemd[1]: Starting Permit User Sessions...

I'll just note that the two lines are quite odd in that the apparent
time delay doesn't correspond to any particularly logical multiplier of
the configured timeout (15s at the moment).

Oct 07 11:20:05 gwendolyn systemd[1]: Mounting /data...
Oct 07 11:21:05 gwendolyn systemd[1]: Mounted /data.

It also seems that there's some attempt to configure IPv6 which is quite
slow (and finally times out), but there's still a looong delay after that.

Regards,