Systemd: NFS mount by FQDN at boot failing on name resolution

[ph448]

I'm seeing a persistent failure trying to mount NFS shares by DNS name from /etc/fstab.
Given a line in /etc/fstab like this (note that gos.lan is the FQDN of the host):

gos.lan:/srv/media      /mnt/media  nfs     defaults,rsize=65536,wsize=65536,timeo=10   0   0

I expect the filesystem to be mounted on boot. Instead, the following is logged in the journal:

Jul 08 20:41:28 apu systemd[1]: Started Network Time Synchronization.
Jul 08 20:41:28 apu systemd[1]: Reached target System Time Synchronized.
Jul 08 20:41:28 apu systemd[1]: Reached target System Initialization.
Jul 08 20:41:28 apu systemd[1]: Listening on RPCbind Server Activation Socket.
Jul 08 20:41:28 apu systemd[1]: Listening on D-Bus System Message Bus Socket.
Jul 08 20:41:28 apu systemd[1]: Started Daily Cleanup of Temporary Directories.
Jul 08 20:41:28 apu systemd[1]: Starting Docker Socket for the API.
Jul 08 20:41:28 apu systemd[1]: Started Daily rotation of log files.
Jul 08 20:41:28 apu systemd[1]: Started Daily verification of password and group files.
Jul 08 20:41:28 apu systemd[1]: Reached target Timers.
Jul 08 20:41:28 apu systemd[1]: Listening on Docker Socket for the API.
Jul 08 20:41:28 apu systemd[1]: Reached target Sockets.
Jul 08 20:41:28 apu systemd[1]: Reached target Basic System.
Jul 08 20:41:28 apu systemd[1]: Started D-Bus System Message Bus.
Jul 08 20:41:28 apu systemd[1]: Starting Network Service...
Jul 08 20:41:28 apu systemd[1]: Starting Login Service...
Jul 08 20:41:28 apu systemd[1]: Starting Save/Restore Sound Card State...
Jul 08 20:41:28 apu systemd[1]: Started Save/Restore Sound Card State.
Jul 08 20:41:28 apu systemd[1]: Started Login Service.
Jul 08 20:41:28 apu systemd-logind[248]: Watching system buttons on /dev/input/event4 (Power Button)
Jul 08 20:41:28 apu systemd-logind[248]: Watching system buttons on /dev/input/event3 (Power Button)
Jul 08 20:41:28 apu systemd-logind[248]: New seat seat0.
Jul 08 20:41:28 apu systemd-networkd[247]: Enumeration completed
Jul 08 20:41:28 apu systemd[1]: Started Network Service.
Jul 08 20:41:28 apu systemd[1]: Reached target Network.
Jul 08 20:41:28 apu systemd-networkd[247]: enp4s0: Renamed to eth0
Jul 08 20:41:28 apu systemd-networkd[247]: eth0: Renamed to enp4s0
Jul 08 20:41:28 apu systemd-networkd[247]: enp4s0: IPv6 enabled for interface: Success
Jul 08 20:41:28 apu systemd[1]: Starting Docker Application Container Engine...
Jul 08 20:41:28 apu systemd[1]: Started OpenSSH Daemon.
Jul 08 20:41:28 apu systemd[1]: Reached target Network is Online.
Jul 08 20:41:28 apu systemd[1]: Mounting /mnt/media...
Jul 08 20:41:28 apu systemd[1]: Starting Network Name Resolution...
Jul 08 20:41:29 apu systemd-resolved[254]: Positive Trust Anchors:
Jul 08 20:41:29 apu systemd-resolved[254]: . IN DS 19036 8 2 49aac11d7b6f6446702e54a1607371607a1a41855200fd2ce1cdde32f24e8fb5
Jul 08 20:41:29 apu systemd-resolved[254]: Negative trust anchors: 10.in-addr.arpa 16.172.in-addr.arpa 17.172.in-addr.arpa 18.172.in-addr.arpa 19.172.in-addr.arpa 20.172.in-addr.arpa 21.172.in-addr.arpa 22.172
Jul 08 20:41:29 apu systemd-resolved[254]: Using system hostname 'apu'.
Jul 08 20:41:29 apu mount[253]: mount.nfs: Failed to resolve server gos.lan: Name or service not known
Jul 08 20:41:29 apu systemd[1]: mnt-media.mount: Mount process exited, code=exited status=32
Jul 08 20:41:29 apu systemd[1]: Failed to mount /mnt/media.
Jul 08 20:41:29 apu systemd[1]: Dependency failed for Remote File Systems.
Jul 08 20:41:29 apu systemd[1]: remote-fs.target: Job remote-fs.target/start failed with result 'dependency'.
Jul 08 20:41:29 apu systemd[1]: mnt-media.mount: Unit entered failed state.
Jul 08 20:41:29 apu systemd[1]: Starting Permit User Sessions...
Jul 08 20:41:29 apu systemd[1]: Started Permit User Sessions.
Jul 08 20:41:29 apu systemd[1]: Starting X-Window Display Manager...
Jul 08 20:41:29 apu systemd[1]: Started Getty on tty1.
Jul 08 20:41:29 apu systemd[1]: Reached target Login Prompts.
Jul 08 20:41:29 apu kernel: r8169 0000:04:00.0 enp4s0: link down
Jul 08 20:41:29 apu kernel: IPv6: ADDRCONF(NETDEV_UP): enp4s0: link is not ready
Jul 08 20:41:29 apu systemd[1]: Started Network Name Resolution.
... <snipped DRM stuff>
Jul 08 20:41:31 apu systemd-networkd[247]: enp4s0: Gained carrier
Jul 08 20:41:31 apu docker[251]: time="2016-07-08T20:41:31.309369075+01:00" level=info msg="Firewalld running: false"
Jul 08 20:41:31 apu docker[251]: time="2016-07-08T20:41:31.570823469+01:00" level=info msg="Default bridge (docker0) is assigned with an IP address 172.17.0.0/16. Daemon option --bip can be used to set a prefe
Jul 08 20:41:31 apu kernel: IPv6: ADDRCONF(NETDEV_UP): docker0: link is not ready
Jul 08 20:41:31 apu docker[251]: time="2016-07-08T20:41:31.705447529+01:00" level=info msg="Loading containers: start."
Jul 08 20:41:31 apu docker[251]: ..
Jul 08 20:41:31 apu docker[251]: time="2016-07-08T20:41:31.719613433+01:00" level=info msg="Loading containers: done."
Jul 08 20:41:31 apu docker[251]: time="2016-07-08T20:41:31.719845203+01:00" level=info msg="Daemon has completed initialization"
Jul 08 20:41:31 apu docker[251]: time="2016-07-08T20:41:31.720018602+01:00" level=info msg="Docker daemon" commit=b9f10c9 graphdriver=devicemapper version=1.11.2
Jul 08 20:41:31 apu docker[251]: time="2016-07-08T20:41:31.744268457+01:00" level=info msg="API listen on /var/run/docker.sock"
Jul 08 20:41:31 apu systemd[1]: Started Docker Application Container Engine.
Jul 08 20:41:31 apu systemd[1]: Reached target Multi-User System.
Jul 08 20:41:31 apu systemd[1]: Reached target Graphical Interface.
Jul 08 20:41:31 apu systemd[1]: Startup finished in 2.303s (kernel) + 4.752s (userspace) = 15.401s.
Jul 08 20:41:32 apu systemd-networkd[247]: enp4s0: Gained IPv6LL
Jul 08 20:41:32 apu systemd-timesyncd[241]: Network configuration changed, trying to establish connection.
Jul 08 20:41:33 apu systemd-networkd[247]: enp4s0: DHCPv6 address fd17:94b2:411b:0000:0000:0000:0000:0f53/128 timeout preferred -1 valid -1
Jul 08 20:41:33 apu systemd-timesyncd[241]: Network configuration changed, trying to establish connection.
Jul 08 20:41:33 apu kernel: random: nonblocking pool is initialized
Jul 08 20:41:34 apu systemd-networkd[247]: enp4s0: DHCPv4 address 192.168.117.129/24 via 192.168.117.1
Jul 08 20:41:34 apu dbus[246]: [system] Activating via systemd: service name='org.freedesktop.hostname1' unit='dbus-org.freedesktop.hostname1.service'
Jul 08 20:41:34 apu systemd-timesyncd[241]: Network configuration changed, trying to establish connection.
Jul 08 20:41:34 apu systemd[1]: Starting Hostname Service...
Jul 08 20:41:34 apu dbus[246]: [system] Successfully activated service 'org.freedesktop.hostname1'
Jul 08 20:41:34 apu systemd[1]: Started Hostname Service.
Jul 08 20:41:35 apu systemd-networkd[247]: enp4s0: Configured
Jul 08 20:41:35 apu systemd-timesyncd[241]: Network configuration changed, trying to establish connection.
Jul 08 20:41:37 apu xdm[352]: pam_unix(xdm:session): session opened for user pheiner by (uid=0)
Jul 08 20:41:37 apu systemd[1]: Created slice User Slice of pheiner.
Jul 08 20:41:37 apu systemd[1]: Starting User Manager for UID 1000...
Jul 08 20:41:37 apu systemd[1]: Started Session c1 of user pheiner.
Jul 08 20:41:37 apu systemd-logind[248]: New session c1 of user pheiner.
Jul 08 20:41:37 apu systemd[452]: pam_unix(systemd-user:session): session opened for user pheiner by (uid=0)
Jul 08 20:41:37 apu systemd[452]: Starting D-Bus User Message Bus Socket.
Jul 08 20:41:37 apu systemd[452]: Reached target Timers.
Jul 08 20:41:37 apu systemd[452]: Reached target Paths.
Jul 08 20:41:37 apu systemd[452]: Listening on D-Bus User Message Bus Socket.
Jul 08 20:41:37 apu systemd[452]: Reached target Sockets.
Jul 08 20:41:37 apu systemd[452]: Reached target Basic System.
Jul 08 20:41:37 apu systemd[452]: Reached target Default.
Jul 08 20:41:37 apu systemd[452]: Startup finished in 93ms.
Jul 08 20:41:37 apu systemd[1]: Started User Manager for UID 1000.
Jul 08 20:41:52 apu systemd[452]: Started D-Bus User Message Bus.
Jul 08 20:41:53 apu systemd-resolved[254]: Switching to DNS server 192.168.117.1 for interface enp4s0.
Jul 08 20:42:05 apu systemd-timesyncd[241]: Synchronized to time server 91.134.209.213:123 (2.arch.pool.ntp.org).
Jul 08 20:46:57 apu sudo[1049]:  pheiner : TTY=pts/0 ; PWD=/home/pheiner ; USER=root ; COMMAND=/bin/bash
Jul 08 20:46:57 apu sudo[1049]: pam_unix(sudo:session): session opened for user root by (uid=0)
Jul 08 20:55:01 apu systemd-resolved[254]: Using degraded feature set (UDP) for DNS server 192.168.117.1.

The problem seems to be that name resolution is not yet operational when the mount is attempted. Mounting the share once booted, either manually or automatically, works on all systems. Using an IP address or adding the host to /etc/hosts also works.

I've observed this with systemd-215 on Debian/armv7l, systemd-230 on Arch/x86_64 with both netctl and systemd-networkd-managed networking, against FreeBSD 10.1/amd64 and Ubuntu/amd64 and SLES11 NFS servers, NFS versions 3 and 4.

I've tried adding an explicit x-systemd.requires=systemd-resolved.service to the mount options, which made systemd say Started Network Name Resolution before the mount attempt, but it failed with the same error.

Let me know if you need anything further to troubleshoot this.

[arvidjaar]

08.07.2016 23:26, Peter Heiner пишет:
...

Jul 08 20:41:28 apu systemd[1]: Reached target Network is Online.
...

Jul 08 20:41:32 apu systemd-networkd[247]: enp4s0: Gained IPv6LL
Jul 08 20:41:32 apu systemd-timesyncd[241]: Network configuration changed, trying to establish connection.
Jul 08 20:41:33 apu systemd-networkd[247]: enp4s0: DHCPv6 address fd17:94b2:411b:0000:0000:0000:0000:0f53/128 timeout preferred -1 valid -1
Jul 08 20:41:33 apu systemd-timesyncd[241]: Network configuration changed, trying to establish connection.
Jul 08 20:41:33 apu kernel: random: nonblocking pool is initialized
Jul 08 20:41:34 apu systemd-networkd[247]: enp4s0: DHCPv4 address 192.168.117.129/24 via 192.168.117.1
Jul 08 20:41:34 apu dbus[246]: [system] Activating via systemd: service name='org.freedesktop.hostname1' unit='dbus-org.freedesktop.hostname1.service'
Jul 08 20:41:34 apu systemd-timesyncd[241]: Network configuration changed, trying to establish connection.
Jul 08 20:41:34 apu systemd[1]: Starting Hostname Service...
Jul 08 20:41:34 apu dbus[246]: [system] Successfully activated service 'org.freedesktop.hostname1'
Jul 08 20:41:34 apu systemd[1]: Started Hostname Service.
Jul 08 20:41:35 apu systemd-networkd[247]: enp4s0: Configured
Jul 08 20:41:35 apu systemd-timesyncd[241]: Network configuration changed, trying to establish connection.

Note that network-online.target is reached before network is actually
being configured. Do you have systemd-networkd-wait-online.service enabled?

[ph448]

@arvidjaar I knew network-online.target did not imply a working network connection. The slightly surprising thing was that systemd-resolved.service did not imply working name resolution.

I did not know of systemd-networkd-wait-online.service and apparently my Google-fu failed me on that one. Enabling it does indeed solve the problem for the machine using systemd-networkd. I don't think this will solve the netctl case, but I can move to using systemd-networkd there with some effort.

I think systemd-fstab-generator could/should automatically take care of ensuring the network is actually up, mounting NFS is not exactly a corner case now that everything runs systemd.

[poettering]

fstab-generator automatically adds deps to network-online.target for nfs mounts. However, network-online.target needs to be filled with meaning by the admin, for example by enabling systemd-network-wait-online.service.

I don't think there's anything to fix here in systemd. The tools are just there, but we cannot guess what kind of networking you are using, hence by default network-online.target has no meaning until you give it one.

resolved may run any time, and does not imply working DNS. it will try to provide the best DNS possible anytime, but if there's no network it will say so in clean errors. If you want to make sure that DNS lookups work,make sure you are connected to the network properly, and only talk to resolved then.

Hope this makes sense, closing.