遅めのマシンでNFSの起動時マウントに失敗した話¶
概要¶
/etc/fstabの設定はあっている（mount -aしたら成功する）のに起動時にNFSのマウントに失敗したという話
原因¶
ネットワークが立ち上がるのほうが後だった。
対策¶
ネットワークの起動を待つサービスの待ち時間を長くする
作業¶
とりあえずログでも見る
# tac /var/log/messages | grep -ni nfs 2819:Dec 7 23:21:30 ringo systemd: Unit mnt-nfs.mount entered failed state. 2822:Dec 7 23:21:30 ringo systemd: Failed to mount /mnt/nfs. 2823:Dec 7 23:21:30 ringo systemd: mnt-nfs.mount mount process exited, code=exited status=32 2824:Dec 7 23:21:30 ringo mount: mount.nfs4: Network is unreachable 2827:Dec 7 23:21:30 ringo kernel: NFS: Registering the id_resolver key type 2829:Dec 7 23:21:30 ringo kernel: FS-Cache: Netfs 'nfs' registered for caching 2834:Dec 7 23:21:30 ringo systemd: Started Notify NFS peers of a restart. 2838:Dec 7 23:21:30 ringo systemd: Mounting /mnt/nfs... 2845:Dec 7 23:21:30 ringo systemd: Starting Notify NFS peers of a restart...
2845行目付近を見ると
# tac /var/log/messages | cat -n | head -n 3000 | tail -n 300 2844 Dec 7 23:21:30 ringo systemd: Dependency failed for Remote File Systems. 2845 Dec 7 23:21:30 ringo systemd: Failed to mount /mnt/nfs. 2846 Dec 7 23:21:30 ringo systemd: mnt-nfs.mount mount process exited, code=exited status=32 2847 Dec 7 23:21:30 ringo mount: mount.nfs4: Network is unreachable 2848 Dec 7 23:21:30 ringo kernel: Key type id_legacy registered 2849 Dec 7 23:21:30 ringo kernel: Key type id_resolver registered 2850 Dec 7 23:21:30 ringo kernel: NFS: Registering the id_resolver key type 2851 Dec 7 23:21:30 ringo kernel: Key type dns_resolver registered 2852 Dec 7 23:21:30 ringo kernel: FS-Cache: Netfs 'nfs' registered for caching 2853 Dec 7 23:21:30 ringo systemd: Started OpenSSH server daemon. 2854 Dec 7 23:21:30 ringo kernel: FS-Cache: Loaded 2855 Dec 7 23:21:30 ringo systemd: Started System Logging Service. 2856 Dec 7 23:21:30 ringo rsyslogd: [origin software="rsyslogd" swVersion="8.24.0" x-pid="1053" x-info="http://www.rsyslog.com"] start 2857 Dec 7 23:21:30 ringo systemd: Started Notify NFS peers of a restart. 2858 Dec 7 23:21:30 ringo systemd: Starting Postfix Mail Transport Agent... 2859 Dec 7 23:21:30 ringo systemd: Starting OpenSSH server daemon... 2860 Dec 7 23:21:30 ringo systemd: Starting System Logging Service... 2861 Dec 7 23:21:30 ringo systemd: Mounting /mnt/nfs...
ネットワークに失敗してる…
2480 Dec 7 23:21:39 ringo NetworkManager[709]: <info> [1575728499.1356] device (enp1s0): Activation: successful, device activated. 2481 Dec 7 23:21:39 ringo NetworkManager[709]: <info> [1575728499.1307] policy: set 'enp1s0' (enp1s0) as default for IPv4 routing and DNS 2482 Dec 7 23:21:39 ringo NetworkManager[709]: <info> [1575728499.1304] manager: NetworkManager state is now CONNECTED_SITE 2483 Dec 7 23:21:39 ringo dhclient[816]: bound to 192.168.0.20 -- renewal in 4294967295 seconds. 2484 Dec 7 23:21:39 ringo NetworkManager[709]: <info> [1575728499.1209] manager: NetworkManager state is now CONNECTED_LOCAL 2485 Dec 7 23:21:39 ringo NetworkManager[709]: <info> [1575728499.1202] device (enp1s0): state change: secondaries -> activated (reason 'none', sys-iface-state: 'managed') 2486 Dec 7 23:21:39 ringo NetworkManager[709]: <info> [1575728499.1191] device (enp1s0): state change: ip-check -> secondaries (reason 'none', sys-iface-state: 'managed') 2487 Dec 7 23:21:39 ringo NetworkManager[709]: <info> [1575728499.1161] device (enp1s0): state change: ip-config -> ip-check (reason 'none', sys-iface-state: 'managed') 2488 Dec 7 23:21:39 ringo NetworkManager[709]: <info> [1575728499.1090] dhcp4 (enp1s0): state changed unknown -> bound 2489 Dec 7 23:21:39 ringo NetworkManager[709]: <info> [1575728499.1089] dhcp4 (enp1s0): domain name '**********' 2490 Dec 7 23:21:39 ringo NetworkManager[709]: <info> [1575728499.1089] dhcp4 (enp1s0): nameserver '192.168.0.1' 2491 Dec 7 23:21:39 ringo NetworkManager[709]: <info> [1575728499.1088] dhcp4 (enp1s0): lease time 4294967295 2492 Dec 7 23:21:39 ringo NetworkManager[709]: <info> [1575728499.1087] dhcp4 (enp1s0): gateway 192.168.0.1 2493 Dec 7 23:21:39 ringo NetworkManager[709]: <info> [1575728499.1086] dhcp4 (enp1s0): plen 24 (255.255.255.0) 2494 Dec 7 23:21:39 ringo NetworkManager[709]: <info> [1575728499.1076] dhcp4 (enp1s0): address 192.168.0.20 2495 Dec 7 23:21:39 ringo dhclient[816]: DHCPACK from 192.168.0.1 (xid=0x35f43909) 2496 Dec 7 23:21:39 ringo dhclient[816]: DHCPOFFER from 192.168.0.1
ネットワークデバイスの有効化のほうが後なのが原因っぽい。
下記によるとネットワークの起動を待てばいいらしい。
systemd-networkd で共有を自動マウント
systemd-networkd を使っている場合、起動時に nfs がマウントされないことがあります。以下のようなエラーが表示されます:
mount[311]: mount.nfs4: Network is unreachable解決方法は簡単です。systemd-networkd-wait-online.service を有効化して、ネットワークが完全に設定されるまで待機するように systemd を設定してください。サービスが平行して起動しなくなるので起動時間は多少長くなります。
NetworkManager環境では「NetworkManager-wait-online.service」が該当するユニットだった。
さて、こいつを調べるとenabledだし、実行に失敗もしている。たぶん、これかなー。
Fedora 29 のKVM仮想マシンで Failed to start Network Manager Wait Online. が発生する
NetworkManager-wait-online サービスは、設定されているタイムアウト(–timeout=30 秒)を超えても NetworkManager の準備が完了していない場合にこのエラーを出力する。
参考：https://www.tomoyan.net/linux/fedora_29_failed_to_start_network_manager_wait_online
あぁたぶんこれ。マシンの起動ちょっと時間かかるし。
上記サイトの手順に従って設定していく
まず、
# cp -p /usr/lib/systemd/system/NetworkManager-wait-online.service /etc/systemd/system/. # vim /etc/systemd/system/NetworkManager-wait-online.service
ExecStartの--timeoutオプションを30秒から120秒に変更してあげるとうまくいった。
おわり。