[Pkg-utopia-maintainers] Bug#832093: Bug#832093: NetworkManager-wait-online.service fails to start and delays boot

Tue Dec 27 17:14:11 UTC 2016

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