Systemd NFS – Failed to Mount NFS Share: Network is Unreachable Until Later in Boot Process

bootnetworkingnfssystemdusb device

My laptop has a USB Ethernet adapter. Apparently the network doesn't come up until later in the boot process than normal. My NFS shares are not mounting at boot. However, as soon as the laptop is booted up, I can mount all shares with this command:

mount -a -t nfs,nfs4

There are no errors and everything is fine at that point. However, I would like the shares to mount at boot time automatically. Therefore, this is not an NFS configuration question. I believe this issue is related to systemd, the boot process and maybe the timing of the USB Ethernet adapter availability.

Here is everything I know to check including the relevant parts of the journal showing that the network comes up after the NFS shares have given up trying to mount. I included the relevant config files, but they have not been changed from the defaults (as far as I know).

Jul 31 21:22:32 host systemd[1]: Mounted /var/log.
...
Jul 31 21:22:33 host mount[898]: mount.nfs: Network is unreachable
...
Jul 31 21:22:34 host mount[880]: mount.nfs: Resource temporarily unavailable
Jul 31 21:22:34 host systemd[1]: share1.mount: Mount process exited, code=exited status=32
Jul 31 21:22:34 host systemd[1]: share1.mount: Failed with result 'exit-code'.
Jul 31 21:22:34 host autossh[896]: starting ssh (count 9)
Jul 31 21:22:34 host autossh[896]: ssh child pid is 1033
Jul 31 21:22:34 host systemd[1]: Failed to mount /share1.
...
Jul 31 21:22:37 host autossh[899]: ssh: connect to host 10.10.0.201 port 22: Network is unreachable
Jul 31 21:22:37 host autossh[899]: ssh exited with error status 255; restarting ssh
...
Jul 31 21:22:38 host NetworkManager[792]: <info>  [1533086558.3237] manager: NetworkManager state is now CONNECTING
...
Jul 31 21:22:38 host NetworkManager[792]: <info>  [1533086558.3487] manager: NetworkManager state is now CONNECTED_LOCAL
Jul 31 21:22:38 host NetworkManager[792]: <info>  [1533086558.3492] manager: NetworkManager state is now CONNECTED_SITE
Jul 31 21:22:38 host NetworkManager[792]: <info>  [1533086558.3493] policy: set 'Wired connection 1' (eth1) as default for IPv4 routing and DNS
Jul 31 21:22:38 host NetworkManager[792]: <info>  [1533086558.3497] device (eth1): Activation: successful, device activated.
Jul 31 21:22:38 host nm-dispatcher[1017]: req:3 'up' [eth1]: new request (0 scripts)


# systemctl status  NetworkManager.service 
● NetworkManager.service - Network Manager
Loaded: loaded (/usr/lib/systemd/system/NetworkManager.service; enabled; vendor preset: disabled)
Drop-In: /usr/lib/systemd/system/NetworkManager.service.d
        └─NetworkManager-ovs.conf
Active: active (running) since Tue 2018-07-31 21:22:33 EDT; 42min ago
    Docs: man:NetworkManager(8)
Main PID: 792 (NetworkManager)
    Tasks: 3 (limit: 4915)
Memory: 33.4M
CGroup: /system.slice/NetworkManager.service
        └─792 /usr/bin/NetworkManager --no-daemon

Jul 31 22:00:59 host NetworkManager[792]: <info>  [1533088859.6259] dhcp4 (eth1):   gateway 192.168.0.1
Jul 31 22:00:59 host NetworkManager[792]: <info>  [1533088859.6334] dhcp4 (eth1): state changed bound -> bound
Jul 31 22:03:12 host NetworkManager[792]: <info>  [1533088992.7755] dhcp4 (eth1):   address 192.168.0.237
Jul 31 22:03:12 host NetworkManager[792]: <info>  [1533088992.7756] dhcp4 (eth1):   plen 24
Jul 31 22:03:12 host NetworkManager[792]: <info>  [1533088992.7756] dhcp4 (eth1):   expires in 300 seconds
Jul 31 22:03:12 host NetworkManager[792]: <info>  [1533088992.7757] dhcp4 (eth1):   nameserver '192.168.0.1'
Jul 31 22:03:12 host NetworkManager[792]: <info>  [1533088992.7758] dhcp4 (eth1):   domain name 'oaks'
Jul 31 22:03:12 host NetworkManager[792]: <info>  [1533088992.7758] dhcp4 (eth1):   hostname 'host'
Jul 31 22:03:12 host NetworkManager[792]: <info>  [1533088992.7759] dhcp4 (eth1):   gateway 192.168.0.1
Jul 31 22:03:12 host NetworkManager[792]: <info>  [1533088992.7769] dhcp4 (eth1): state changed bound -> bound


# systemctl status share1.mount
● share1.mount - /share1
Loaded: loaded (/etc/fstab; generated)
Active: failed (Result: exit-code) since Tue 2018-07-31 21:22:34 EDT; 25min ago
    Where: /share1
    What: server:/share1/
    Docs: man:fstab(5)
        man:systemd-fstab-generator(8)

Jul 31 21:22:33 host systemd[1]: Mounting /share1...
Jul 31 21:22:34 host mount[880]: mount.nfs: Resource temporarily unavailable
Jul 31 21:22:34 host systemd[1]: share1.mount: Mount process exited, code=exited status=32
Jul 31 21:22:34 host systemd[1]: share1.mount: Failed with result 'exit-code'.
Jul 31 21:22:34 host systemd[1]: Failed to mount /share1.


# cat /usr/lib/systemd/system/NetworkManager.service
[Unit]
Description=Network Manager
Documentation=man:NetworkManager(8)
Wants=network.target
After=network-pre.target dbus.service
Before=network.target 

[Service]
Type=dbus
BusName=org.freedesktop.NetworkManager
ExecReload=/usr/bin/dbus-send --print-reply --system --type=method_call --dest=org.freedesktop.NetworkManager /org/freedesktop/NetworkManager org.freedesktop.NetworkManager.Reload uint32:0
#ExecReload=/bin/kill -HUP $MAINPID
ExecStart=/usr/bin/NetworkManager --no-daemon
Restart=on-failure
# NM doesn't want systemd to kill its children for it
KillMode=process
CapabilityBoundingSet=CAP_NET_ADMIN CAP_DAC_OVERRIDE CAP_NET_RAW CAP_NET_BIND_SERVICE CAP_SETGID CAP_SETUID CAP_SYS_MODULE CAP_AUDIT_WRITE CAP_KILL CAP_SYS_CHROOT

# ibft settings plugin calls iscsiadm which needs CAP_SYS_ADMIN
#CapabilityBoundingSet=CAP_SYS_ADMIN

ProtectSystem=true
ProtectHome=read-only

[Install]
WantedBy=multi-user.target
Alias=dbus-org.freedesktop.NetworkManager.service
Also=NetworkManager-dispatcher.service

# We want to enable NetworkManager-wait-online.service whenever this service
# is enabled. NetworkManager-wait-online.service has
# WantedBy=network-online.target, so enabling it only has an effect if
# network-online.target itself is enabled or pulled in by some other unit.
Also=NetworkManager-wait-online.service

# cat /usr/lib/systemd/system/NetworkManager.service.d/NetworkManager-ovs.conf 
[Unit]
After=openvswitch.service

# cat /etc/NetworkManager/NetworkManager.conf
# Configuration file for NetworkManager.
# See "man 5 NetworkManager.conf" for details.

# tree /etc/NetworkManager/conf.d/
/etc/NetworkManager/conf.d/
0 directories, 0 files

# cat /usr/lib/systemd/system/NetworkManager-wait-online.service
[Unit]
Description=Network Manager Wait Online
Documentation=man:nm-online(1)
Requires=NetworkManager.service
After=NetworkManager.service
Before=network-online.target

[Service]
Type=oneshot
ExecStart=/usr/bin/nm-online -s -q --timeout=30
RemainAfterExit=yes

[Install]
WantedBy=network-online.target


Arch Linux 4.17.11-arch1 #1 SMP PREEMPT Sun Jul 29 10:11:16 UTC 2018 x86_64 GNU/Linux
KDE

UPDATE: here is the requested info regarding fstab:

All nfs mounts have these options:

nfs     _netdev,defaults,noatime,nodiratime,soft,retrans=6,timeo=20,retry=0,rsize=32768,wsize=32768,proto=tcp   0 0

I am indeed using _netdev along with systemd. After reading Filipe Brandenburger's comment, I'm not sure whether this option is meaningless under systemd or harmful.

systemctl cat share1.mount
# /run/systemd/generator/share1.mount
# Automatically generated by systemd-fstab-generator

[Unit]
SourcePath=/etc/fstab
Documentation=man:fstab(5) man:systemd-fstab-generator(8)
Before=remote-fs.target

[Mount]
Where=/share1
What=server:/share1/
Type=nfs
Options=_netdev,defaults,noatime,nodiratime,soft,retrans=6,timeo=20,retry=0,rsize=32768,wsize=32768,proto=tcp

# systemctl show -p Wants network-online.target
Wants=NetworkManager-wait-online.service

Here is an update with the information requested by @sourcejedi

sudo systemctl list-dependencies share1.mount
share1.mount
● ├─-.mount
● ├─home.mount
● ├─system.slice
● └─network-online.target

sudo systemctl list-dependencies --after share1.mount
share1.mount
● ├─-.mount
● ├─home.mount
● ├─system.slice
● ├─systemd-journald.socket
● ├─network-online.target
● │ └─network.target
● │   ├─dhcpcd.service
● │   ├─NetworkManager.service
● │   ├─wpa_supplicant.service
● │   └─network-pre.target
● ├─network.target
● │ ├─dhcpcd.service
● │ ├─NetworkManager.service
● │ ├─wpa_supplicant.service
● │ └─network-pre.target
● └─remote-fs-pre.target

# sudo journalctl -b -u share1.mount -u network-online.target -u NetworkManager-wait-online -u NetworkManager --no-pager
-- Logs begin at Sun 2018-06-10 17:09:08 EDT, end at Sat 2018-12-22 19:07:16 EST. --
Dec 22 17:58:38 laptop1 systemd[1]: Starting Network Manager...
Dec 22 17:58:38 laptop1 NetworkManager[463]: <info>  [1545519518.3825] NetworkManager (version 1.14.5dev+17+gba83251bb-1) is starting... (for the first time)
Dec 22 17:58:38 laptop1 NetworkManager[463]: <info>  [1545519518.3826] Read config: /etc/NetworkManager/NetworkManager.conf (lib: 20-connectivity.conf)
Dec 22 17:58:38 laptop1 NetworkManager[463]: <info>  [1545519518.3836] wifi-nl80211: (wlan0): using nl80211 for WiFi device control
Dec 22 17:58:38 laptop1 NetworkManager[463]: <info>  [1545519518.3895] bus-manager: acquired D-Bus service "org.freedesktop.NetworkManager"
Dec 22 17:58:38 laptop1 systemd[1]: Started Network Manager.
Dec 22 17:58:38 laptop1 NetworkManager[463]: <info>  [1545519518.3900] manager[0x55b8543f4060]: monitoring kernel firmware directory '/lib/firmware'.
Dec 22 17:58:38 laptop1 systemd[1]: Reached target Network is Online.
Dec 22 17:58:38 laptop1 systemd[1]: share1.mount: Directory /share1 to mount over is not empty, mounting anyway.
Dec 22 17:58:38 laptop1 systemd[1]: Mounting /share1...
Dec 22 17:58:39 laptop1 mount[546]: mount.nfs: Network is unreachable
Dec 22 17:58:39 laptop1 systemd[1]: share1.mount: Mount process exited, code=exited status=32
Dec 22 17:58:39 laptop1 systemd[1]: share1.mount: Failed with result 'exit-code'.
Dec 22 17:58:39 laptop1 systemd[1]: Failed to mount /share1.
Dec 22 17:58:39 laptop1 NetworkManager[463]: <info>  [1545519519.3695] hostname: hostname: using hostnamed
Dec 22 17:58:39 laptop1 NetworkManager[463]: <info>  [1545519519.3696] hostname: hostname changed from (none) to "laptop1"
Dec 22 17:58:39 laptop1 NetworkManager[463]: <info>  [1545519519.3698] dns-mgr[0x98059644079A]: init: dns=default, rc-manager=symlink
Dec 22 17:58:39 laptop1 NetworkManager[463]: <info>  [1545519519.3708] rfkill2: found WiFi radio killswitch (at /sys/devices/pci0000:00/0000:00:1c.1/0000:03:00.0/ieee80211/phy0/rfkill2) (driver iwlwifi)
Dec 22 17:58:39 laptop1 NetworkManager[463]: <info>  [1545519519.3711] manager[0x55b8543f4060]: rfkill: WiFi hardware radio set disabled
Dec 22 17:58:39 laptop1 NetworkManager[463]: <info>  [1545519519.3711] manager[0x55b8543f4060]: rfkill: WWAN hardware radio set enabled
Dec 22 17:58:39 laptop1 NetworkManager[463]: <info>  [1545519519.3926] settings: Loaded settings plugin: NMSKeyfilePlugin (internal)
Dec 22 17:58:39 laptop1 NetworkManager[463]: <info>  [1545519519.3933] settings: Loaded settings plugin: NMSIbftPlugin ("/usr/lib/NetworkManager/1.14.5dev+17+gba83251bb-1/libnm-settings-plugin-ibft.so")
Dec 22 17:58:39 laptop1 NetworkManager[463]: <info>  [1545519519.3958] keyfile: new connection /etc/NetworkManager/system-connections/USB Ethernet Adapter 1 (fc9310,"USB Ethernet Adapter 1")
Dec 22 17:58:39 laptop1 NetworkManager[463]: <info>  [1545519519.3975] keyfile: new connection /etc/NetworkManager/system-connections/walden2
Dec 22 17:58:39 laptop1 NetworkManager[463]: <info>  [1545519519.3983] keyfile: new connection /etc/NetworkManager/system-connections/NETGEAR4
Dec 22 17:58:39 laptop1 NetworkManager[463]: <info>  [1545519519.3991] keyfile: new connection /etc/NetworkManager/system-connections/Tls5
Dec 22 17:58:39 laptop1 NetworkManager[463]: <info>  [1545519519.3999] keyfile: new connection /etc/NetworkManager/system-connections/JONES
Dec 22 17:58:39 laptop1 NetworkManager[463]: <info>  [1545519519.4062] manager: rfkill: WiFi disabled by radio killswitch; disabled by state file
Dec 22 17:58:39 laptop1 NetworkManager[463]: <info>  [1545519519.4063] manager: rfkill: WWAN enabled by radio killswitch; enabled by state file
Dec 22 17:58:39 laptop1 NetworkManager[463]: <info>  [1545519519.4064] manager: Networking is enabled by state file
Dec 22 17:58:39 laptop1 NetworkManager[463]: <info>  [1545519519.4066] dhcp-init: Using DHCP client 'internal'
Dec 22 17:58:39 laptop1 NetworkManager[463]: <info>  [1545519519.4129] Loaded device plugin: NMAtmManager (/usr/lib/NetworkManager/1.14.5dev+17+gba83251bb-1/libnm-device-plugin-adsl.so)
Dec 22 17:58:39 laptop1 NetworkManager[463]: <info>  [1545519519.4210] Loaded device plugin: NMBluezManager (/usr/lib/NetworkManager/1.14.5dev+17+gba83251bb-1/libnm-device-plugin-bluetooth.so)
Dec 22 17:58:39 laptop1 NetworkManager[463]: <info>  [1545519519.4232] Loaded device plugin: NMOvsFactory (/usr/lib/NetworkManager/1.14.5dev+17+gba83251bb-1/libnm-device-plugin-ovs.so)
Dec 22 17:58:39 laptop1 NetworkManager[463]: <info>  [1545519519.4404] Loaded device plugin: NMTeamFactory (/usr/lib/NetworkManager/1.14.5dev+17+gba83251bb-1/libnm-device-plugin-team.so)
Dec 22 17:58:39 laptop1 NetworkManager[463]: <info>  [1545519519.4420] Loaded device plugin: NMWifiFactory (/usr/lib/NetworkManager/1.14.5dev+17+gba83251bb-1/libnm-device-plugin-wifi.so)
Dec 22 17:58:39 laptop1 NetworkManager[463]: <info>  [1545519519.4427] Loaded device plugin: NMWwanFactory (/usr/lib/NetworkManager/1.14.5dev+17+gba83251bb-1/libnm-device-plugin-wwan.so)
Dec 22 17:58:39 laptop1 NetworkManager[463]: <info>  [1545519519.4435] device (lo): carrier: link connected
Dec 22 17:58:39 laptop1 NetworkManager[463]: <info>  [1545519519.4439] manager: (lo): new Generic device (/org/freedesktop/NetworkManager/Devices/1)
Dec 22 17:58:39 laptop1 NetworkManager[463]: <info>  [1545519519.4449] manager: (eth0): new Ethernet device (/org/freedesktop/NetworkManager/Devices/2)
Dec 22 17:58:39 laptop1 NetworkManager[463]: <info>  [1545519519.4461] device (eth0): state change: unmanaged -> unavailable (reason 'managed', sys-iface-state: 'external')
Dec 22 17:58:39 laptop1 NetworkManager[463]: <info>  [1545519519.4481] manager: (eth1): new Ethernet device (/org/freedesktop/NetworkManager/Devices/3)
Dec 22 17:58:39 laptop1 NetworkManager[463]: <info>  [1545519519.4491] device (eth1): state change: unmanaged -> unavailable (reason 'managed', sys-iface-state: 'external')
Dec 22 17:58:39 laptop1 NetworkManager[463]: <info>  [1545519519.4504] device (wlan0): driver supports Access Point (AP) mode
Dec 22 17:58:39 laptop1 NetworkManager[463]: <info>  [1545519519.4508] manager: (wlan0): new 802.11 WiFi device (/org/freedesktop/NetworkManager/Devices/4)
Dec 22 17:58:39 laptop1 NetworkManager[463]: <info>  [1545519519.4513] device (wlan0): state change: unmanaged -> unavailable (reason 'managed', sys-iface-state: 'external')
Dec 22 17:58:39 laptop1 NetworkManager[463]: <info>  [1545519519.4516] device (wlan0): set-hw-addr: set MAC address to 28:ab:29:45:F9:2B (scanning)
Dec 22 17:58:39 laptop1 NetworkManager[463]: <info>  [1545519519.4586] bluez: use BlueZ version 5
Dec 22 17:58:39 laptop1 NetworkManager[463]: <info>  [1545519519.4656] bluez5: NAP: added interface 77:ab:29:45:F9:2F
Dec 22 17:58:39 laptop1 NetworkManager[463]: <info>  [1545519519.5063] supplicant: wpa_supplicant running
Dec 22 17:58:42 laptop1 NetworkManager[463]: <info>  [1545519522.0759] device (eth1): carrier: link connected
Dec 22 17:58:42 laptop1 NetworkManager[463]: <info>  [1545519522.0792] device (eth1): state change: unavailable -> disconnected (reason 'carrier-changed', sys-iface-state: 'managed')
Dec 22 17:58:42 laptop1 NetworkManager[463]: <info>  [1545519522.0798] policy: auto-activating connection 'USB Ethernet Adapter 1' (fc9310)
Dec 22 17:58:42 laptop1 NetworkManager[463]: <info>  [1545519522.0804] device (eth1): Activation: starting connection 'USB Ethernet Adapter 1' (fc9310)
Dec 22 17:58:42 laptop1 NetworkManager[463]: <info>  [1545519522.0806] device (eth1): state change: disconnected -> prepare (reason 'none', sys-iface-state: 'managed')
Dec 22 17:58:42 laptop1 NetworkManager[463]: <info>  [1545519522.0810] manager: NetworkManager state is now CONNECTING
Dec 22 17:58:42 laptop1 NetworkManager[463]: <info>  [1545519522.0895] device (eth1): state change: prepare -> config (reason 'none', sys-iface-state: 'managed')
Dec 22 17:58:42 laptop1 NetworkManager[463]: <info>  [1545519522.0899] device (eth1): state change: config -> ip-config (reason 'none', sys-iface-state: 'managed')
Dec 22 17:58:42 laptop1 NetworkManager[463]: <info>  [1545519522.0902] dhcp4 (eth1): activation: beginning transaction (timeout in 45 seconds)
Dec 22 17:58:45 laptop1 NetworkManager[463]: <info>  [1545519525.7908] device (eth1): carrier: link connected
Dec 22 17:58:47 laptop1 NetworkManager[463]: <info>  [1545519527.1025] dhcp4 (eth1):   address 192.168.5.2
Dec 22 17:58:47 laptop1 NetworkManager[463]: <info>  [1545519527.1026] dhcp4 (eth1):   plen 24
Dec 22 17:58:47 laptop1 NetworkManager[463]: <info>  [1545519527.1026] dhcp4 (eth1):   expires in 108000 seconds
Dec 22 17:58:47 laptop1 NetworkManager[463]: <info>  [1545519527.1027] dhcp4 (eth1):   nameserver '192.168.5.1'
Dec 22 17:58:47 laptop1 NetworkManager[463]: <info>  [1545519527.1027] dhcp4 (eth1):   domain name 'wrkgrp'
Dec 22 17:58:47 laptop1 NetworkManager[463]: <info>  [1545519527.1027] dhcp4 (eth1):   hostname 'usb_laptop1'
Dec 22 17:58:47 laptop1 NetworkManager[463]: <info>  [1545519527.1028] dhcp4 (eth1):   gateway 192.168.5.1
Dec 22 17:58:47 laptop1 NetworkManager[463]: <info>  [1545519527.1040] dhcp4 (eth1): state changed unknown -> bound
Dec 22 17:58:47 laptop1 NetworkManager[463]: <info>  [1545519527.1075] device (eth1): state change: ip-config -> ip-check (reason 'none', sys-iface-state: 'managed')
Dec 22 17:58:47 laptop1 NetworkManager[463]: <info>  [1545519527.1108] device (eth1): state change: ip-check -> secondaries (reason 'none', sys-iface-state: 'managed')
Dec 22 17:58:47 laptop1 NetworkManager[463]: <info>  [1545519527.1117] device (eth1): state change: secondaries -> activated (reason 'none', sys-iface-state: 'managed')
Dec 22 17:58:47 laptop1 NetworkManager[463]: <info>  [1545519527.1134] manager: NetworkManager state is now CONNECTED_LOCAL
Dec 22 17:58:47 laptop1 NetworkManager[463]: <info>  [1545519527.1153] manager: NetworkManager state is now CONNECTED_SITE
Dec 22 17:58:47 laptop1 NetworkManager[463]: <info>  [1545519527.1155] policy: set 'USB Ethernet Adapter 1' (eth1) as default for IPv4 routing and DNS
Dec 22 17:58:47 laptop1 NetworkManager[463]: <info>  [1545519527.1161] device (eth1): Activation: successful, device activated.
Dec 22 17:58:47 laptop1 NetworkManager[463]: <info>  [1545519527.1167] manager: startup complete
Dec 22 17:58:47 laptop1 NetworkManager[463]: <info>  [1545519527.3936] manager: NetworkManager state is now CONNECTED_GLOBAL

(In regard to my controversial use of the soft mount option, the decision to use it was made after years of problems with the hard option. With the hard option, any loss of connectivity freezes the system and forces a hard restart. I'm running BTRFS and I do not wish to risk that. I have decided that my soft is a better fit for my situation. However, along with soft I tweaked the retrans,timeo,and retry options. I'm not sure I have them optimized, but overall the experience has been much better than with the hard option.)

Best Answer

This works for me with systemd. The automount, requires delays the mount request until the network is online.

I am not sure about the nofail. I use it without issue but it doesn't seem quite right. It should be unnecessary with the requires... Perhaps someone has an idea.

10.0.0.110:/export/3T  /mnt/3T  nfs nofail,x-systemd.automount,x-systemd.requires=network-online.target,x-systemd.device-timeout=10 0 0 
Related Question