control: retitile -1 NetworkManager-wait-online.service fails to start and delays boot without a dhcp server present
Hi Michael, On Sun, Aug 07, 2016 at 01:56:45PM +0200, Michael Biebl wrote: > Hi > > Am 22.07.2016 um 10:42 schrieb Guido Günther: > > NetworkManager-wait-online.service fails to start during boot like > > > > $ journalctl -b --unit=NetworkManager-wait-online.service > > -- Logs begin at Do 2015-08-06 09:54:25 SAST, end at Fr 2016-07-22 10:34:27 > > SAST. -- > > Jul 22 09:57:14 bogon systemd[1]: Starting Network Manager Wait Online... > > Jul 22 09:57:46 bogon systemd[1]: NetworkManager-wait-online.service: Main > > process exited, code=exited, status=1/FAILURE > > Jul 22 09:57:46 bogon systemd[1]: Failed to start Network Manager Wait > > Online. > > Jul 22 09:57:46 bogon systemd[1]: NetworkManager-wait-online.service: Unit > > entered failed state. > > Jul 22 09:57:46 bogon systemd[1]: NetworkManager-wait-online.service: > > Failed with result 'exit-code'. > > > > If it strat it later on it works as expected (although an ethernet cable > > is plugged in all the time). > > > nm-wait-online exiting non-zero usually means, there was no network > connection configured by NM. This could have different reasons. E.g. for > WLAN the credentials could be stored in the user session and not be > available during boot. > > If it's an ethernet connection, NM should establish the network > connection. It would be interesting to know, why it doesn't autoconnect. > > Hm, could you send me a NetworkManager debug log from the boot > https://wiki.gnome.org/Projects/NetworkManager/Debugging This is what I grabbed: Dec 27 18:03:24 foo kernel: ax88179_178a 7-1:1.0 eth0: register 'ax88179_178a' at usb-0000:00:1d.7-1, ASIX AX88179 USB 3.0 Gigabit Ethernet, 00:24:9b:09:5a:90 Dec 27 18:03:27 foo NetworkManager[503]: <info> [1482858207.9418] devices added (path: /sys/devices/pci0000:00/0000:00:1d.7/usb7/7-1/7-1:1.0/net/eth0, iface: eth0) Dec 27 18:03:27 foo NetworkManager[503]: <info> [1482858207.9419] device added (path: /sys/devices/pci0000:00/0000:00:1d.7/usb7/7-1/7-1:1.0/net/eth0, iface: eth0): no ifupdown configuration found. Dec 27 18:03:29 foo NetworkManager[503]: <info> [1482858209.7097] manager: (eth0): new Ethernet device (/org/freedesktop/NetworkManager/Devices/2) Dec 27 18:03:29 foo NetworkManager[503]: <info> [1482858209.7195] device (eth0): state change: unmanaged -> unavailable (reason 'managed') [10 20 2] Dec 27 18:03:29 foo kernel: IPv6: ADDRCONF(NETDEV_UP): eth0: link is not ready Dec 27 18:03:30 foo kernel: IPv6: ADDRCONF(NETDEV_UP): eth0: link is not ready Dec 27 18:03:33 foo kernel: ax88179_178a 7-1:1.0 eth0: ax88179 - Link status is: 1 Dec 27 18:03:33 foo NetworkManager[503]: <info> [1482858213.1928] device (eth0): link connected Dec 27 18:03:33 foo kernel: IPv6: ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready Dec 27 18:03:33 foo NetworkManager[503]: <info> [1482858213.1971] device (eth0): state change: unavailable -> disconnected (reason 'carrier-changed') [20 30 40] Dec 27 18:03:33 foo NetworkManager[503]: <info> [1482858213.2130] device (eth0): Activation: starting connection 'Wired connection 1' (3c713def-f9a0-3f7d-955f-7271826c0498) Dec 27 18:03:33 foo NetworkManager[503]: <info> [1482858213.2169] device (eth0): state change: disconnected -> prepare (reason 'none') [30 40 0] Dec 27 18:03:33 foo NetworkManager[503]: <info> [1482858213.2302] device (eth0): state change: prepare -> config (reason 'none') [40 50 0] Dec 27 18:03:33 foo NetworkManager[503]: <info> [1482858213.2340] device (eth0): state change: config -> ip-config (reason 'none') [50 70 0] Dec 27 18:03:33 foo NetworkManager[503]: <info> [1482858213.2395] dhcp4 (eth0): activation: beginning transaction (timeout in 45 seconds) Dec 27 18:03:33 foo NetworkManager[503]: <info> [1482858213.2568] dhcp4 (eth0): dhclient started with pid 818 Dec 27 18:03:33 foo dhclient[818]: DHCPDISCOVER on eth0 to 255.255.255.255 port 67 interval 8 Dec 27 18:03:35 foo avahi-daemon[510]: Joining mDNS multicast group on interface eth0.IPv6 with address fe80::6959:3647:6dd:b1b7. Dec 27 18:03:35 foo avahi-daemon[510]: New relevant interface eth0.IPv6 for mDNS. Dec 27 18:03:35 foo avahi-daemon[510]: Registering new address record for fe80::6959:3647:6dd:b1b7 on eth0.*. Dec 27 18:03:36 foo avahi-daemon[510]: Leaving mDNS multicast group on interface eth0.IPv6 with address fe80::6959:3647:6dd:b1b7. Dec 27 18:03:36 foo avahi-daemon[510]: Joining mDNS multicast group on interface eth0.IPv6 with address <addr removed> Dec 27 18:03:36 foo avahi-daemon[510]: Registering new address recordfor <addr removed> Dec 27 18:03:36 foo NetworkManager[503]: <info> [1482858216.3372] device (eth0): state change: ip-config -> ip-check (reason 'none') [70 80 0] Dec 27 18:03:36 foo avahi-daemon[510]: Withdrawing address record for fe80::6959:3647:6dd:b1b7 on eth0. Dec 27 18:03:36 foo NetworkManager[503]: <info> [1482858216.3496] device (eth0): state change: ip-check -> secondaries (reason 'none') [80 90 0] Dec 27 18:03:36 foo NetworkManager[503]: <info> [1482858216.3592] device (eth0): state change: secondaries -> activated (reason 'none') [90 100 0] Dec 27 18:03:36 foo NetworkManager[503]: <info> [1482858216.3778] policy: set 'Wired connection 1' (eth0) as default for IPv6 routing and DNS Dec 27 18:03:36 foo NetworkManager[503]: <info> [1482858216.3849] device (eth0): Activation: successful, device activated. Dec 27 18:03:36 foo nm-dispatcher[642]: req:3 'up' [eth0]: new request (1 scripts) Dec 27 18:03:36 foo nm-dispatcher[642]: req:3 'up' [eth0]: start running ordered scripts... Dec 27 18:03:41 foo dhclient[818]: DHCPDISCOVER on eth0 to 255.255.255.255 port 67 interval 12 Dec 27 18:03:53 foo dhclient[818]: DHCPDISCOVER on eth0 to 255.255.255.255 port 67 interval 9 Dec 27 18:04:02 foo dhclient[818]: DHCPDISCOVER on eth0 to 255.255.255.255 port 67 interval 15 Dec 27 18:04:17 foo dhclient[818]: DHCPDISCOVER on eth0 to 255.255.255.255 port 67 interval 15 Dec 27 18:04:17 foo NetworkManager[503]: <warn> [1482858257.5595] dhcp4 (eth0): request timed out Dec 27 18:04:17 foo NetworkManager[503]: <info> [1482858257.5597] dhcp4 (eth0): state changed unknown -> timeout Dec 27 18:04:17 foo NetworkManager[503]: <info> [1482858257.5778] dhcp4 (eth0): canceled DHCP transaction, DHCP client pid 818 Dec 27 18:04:17 foo NetworkManager[503]: <info> [1482858257.5779] dhcp4 (eth0): state changed timeout -> done The network doesn't have a dhcp server but ipv6 SLAAC. If I disable dhcp on the connection like [ipv4] method=disabled [ipv6] addr-gen-mode=stable-privacy dns-search= may-fail=false method=auto NetworkManager-wait-online.service does not time out. It has ipv6 set up at 18:03:36 but waits for dhcp until 18:04:17. So NetworkManager should net require IPv4 for assuming online. Cheers, -- Guido
