Long boot time due to systemd-networkd-wait-online.service failure

#> ifquery --list
lo

#> ip link show
1: lo: <LOOPBACK,UP,LOWER_UP> mtu 65536 qdisc noqueue state UNKNOWN mode DEFAULT group default qlen 1000
    link/loopback 00:00:00:00:00:00 brd 00:00:00:00:00:00
2: eth0: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc mq state UP mode DEFAULT group default qlen 1000
    link/ether 00:16:3e:71:31:57 brd ff:ff:ff:ff:ff:ff

#> ifconfig
eth0: flags=4163<UP,BROADCAST,RUNNING,MULTICAST> mtu 1500
        inet 192.168.2.159 netmask 255.255.255.0 broadcast 192.168.2.255
        inet6 fe80::216:3eff:fe71:3157 prefixlen 64 scopeid 0x20<link>
        ether 00:16:3e:71:31:57 txqueuelen 1000 (Ethernet)
        RX packets 1879 bytes 290874 (290.8 KB)
        RX errors 0 dropped 255 overruns 0 frame 0
        TX packets 1052 bytes 390313 (390.3 KB)
        TX errors 0 dropped 0 overruns 0 carrier 0 collisions 0

lo: flags=73<UP,LOOPBACK,RUNNING> mtu 65536
        inet 127.0.0.1 netmask 255.0.0.0
        inet6 ::1 prefixlen 128 scopeid 0x10<host>
        loop txqueuelen 1000 (Local Loopback)
        RX packets 326 bytes 24232 (24.2 KB)
        RX errors 0 dropped 0 overruns 0 frame 0
        TX packets 326 bytes 24232 (24.2 KB)
        TX errors 0 dropped 0 overruns 0 carrier 0 collisions 0

And what about /etc/netplan/*.yaml

and /run/systemd/network/*

If you can attach the journal binary file, we can query the state
independently from you

tar up /run/log/journal/

Thanks

On Tue, Jun 13, 2017 at 11:33 AM, Stefan Bader <email address hidden>
wrote:

> #> ifquery --list
> lo
>
> #> ip link show
> 1: lo: <LOOPBACK,UP,LOWER_UP> mtu 65536 qdisc noqueue state UNKNOWN mode
> DEFAULT group default qlen 1000
> link/loopback 00:00:00:00:00:00 brd 00:00:00:00:00:00
> 2: eth0: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc mq state UP
> mode DEFAULT group default qlen 1000
> link/ether 00:16:3e:71:31:57 brd ff:ff:ff:ff:ff:ff
>
> #> ifconfig
> eth0: flags=4163<UP,BROADCAST,RUNNING,MULTICAST> mtu 1500
> inet 192.168.2.159 netmask 255.255.255.0 broadcast 192.168.2.255
> inet6 fe80::216:3eff:fe71:3157 prefixlen 64 scopeid 0x20<link>
> ether 00:16:3e:71:31:57 txqueuelen 1000 (Ethernet)
> RX packets 1879 bytes 290874 (290.8 KB)
> RX errors 0 dropped 255 overruns 0 frame 0
> TX packets 1052 bytes 390313 (390.3 KB)
> TX errors 0 dropped 0 overruns 0 carrier 0 collisions 0
>
> lo: flags=73<UP,LOOPBACK,RUNNING> mtu 65536
> inet 127.0.0.1 netmask 255.0.0.0
> inet6 ::1 prefixlen 128 scopeid 0x10<host>
> loop txqueuelen 1000 (Local Loopback)
> RX packets 326 bytes 24232 (24.2 KB)
> RX errors 0 dropped 0 overruns 0 frame 0
> TX packets 326 bytes 24232 (24.2 KB)
> TX errors 0 dropped 0 overruns 0 carrier 0 collisions 0
>
> --
> You received this bug notification because you are subscribed to the bug
> report.
> https://bugs.launchpad.net/bugs/1697730
>
> Title:
> Long boot time due to systemd-networkd-wait-online.service failure
>
> To manage notifications about this bug go to:
> https://bugs.launchpad.net/ubuntu/+source/systemd/+bug/
> 1697730/+subscriptions
>

Is this delay reproducible post-boot if you run '/lib/systemd/systemd-networkd-wait-online' from the commandline?

Here the netcat config. Note only eth0 appearing here (for KVM guests, the same happens but with ensX NIC names).

I created the directory and rebooted once ;) Here is the tarball.

@Steve, yes it does. And if the wait is related to the list of NICs from ifquery, it does make sense (in some way) as that list only contains "lo", not "eth0". Also "ifquery --state eth0" does not return anything while it does return "lo=lo" for "lo".

Sorry, forgot above:

#> cat /run/systemd/network/10-netplan-eth0.network
[Match]
Name=eth0

[Network]
DHCP=ipv4

[DHCP]
RouteMetric=100

This is annoying:

% journalctl -D var/log/journal -o short-precise Journal file
var/log/journal/1fe5c5ed88c14c81bd52acb9f96f3a18/system.journal uses an
unsupported feature, ignoring file.
-- No entries --

Why can't xenial systemd journalctl read an artful one? That seems like a
terrible idea w.r.t features here; are we enabling new features that we
can't read outside of the same distro release?

https://bugzilla.redhat.com/show_bug.cgi?id=1413388

We should get this fixed when it;s available. Or disable the LZ4 for
compat until it's done

On Wed, Jun 14, 2017 at 5:04 AM, Stefan Bader <email address hidden>
wrote:

> Sorry, forgot above:
>
> #> cat /run/systemd/network/10-netplan-eth0.network
> [Match]
> Name=eth0
>
> [Network]
> DHCP=ipv4
>
> [DHCP]
> RouteMetric=100
>
> --
> You received this bug notification because you are subscribed to the bug
> report.
> https://bugs.launchpad.net/bugs/1697730
>
> Title:
> Long boot time due to systemd-networkd-wait-online.service failure
>
> To manage notifications about this bug go to:
> https://bugs.launchpad.net/ubuntu/+source/systemd/+bug/
> 1697730/+subscriptions
>

On Wed, Jun 14, 2017 at 10:04:28AM -0000, Stefan Bader wrote:
> Sorry, forgot above:

> #> cat /run/systemd/network/10-netplan-eth0.network
> [Match]
> Name=eth0

> [Network]
> DHCP=ipv4

> [DHCP]
> RouteMetric=100

I know you say this is also reproducible for you when using ensX names, but
for completeness, why do you have eth0 here? That's not a name that should
be appearing anywhere on an artful system, unless you've set net.ifnames=0,
which is strongly discouraged.

On Wed, Jun 14, 2017 at 07:37:50AM -0000, Stefan Bader wrote:
> @Steve, yes it does. And if the wait is related to the list of NICs from
> ifquery, it does make sense (in some way) as that list only contains
> "lo", not "eth0". Also "ifquery --state eth0" does not return anything
> while it does return "lo=lo" for "lo".

networkd doesn't care at all about ifquery. systemd-networkd-wait-online(8)
documents that this should return as soon as "all links it is aware of and
which are managed by systemd-network [are] fully configured or failed, and
[...] at least one link [gains] a carrier."

So this is definitely not working as designed, if you have only a single
interface configured in systemd-network and its link is up, but -wait-online
is not returning success.

--
Steve Langasek Give me a lever long enough and a Free OS
Debian Developer to set it on, and I can move the world.
Ubuntu Developer http://www.debian.org/
<email address hidden> <email address hidden>

The journal shows, two minutes after the start of the wait-online job:

Jun 14 00:11:42 bar-artful6401 systemd-networkd-wait-online[618]: Event loop failed: Connection timed out
Jun 14 00:11:42 bar-artful6401 systemd[1]: systemd-networkd-wait-online.service: Main process exited, code=exited, status=1/FAILURE
Jun 14 00:11:42 bar-artful6401 systemd[1]: Failed to start Wait for Network to be Configured.
Jun 14 00:11:42 bar-artful6401 systemd[1]: systemd-networkd-wait-online.service: Unit entered failed state.
Jun 14 00:11:42 bar-artful6401 systemd[1]: systemd-networkd-wait-online.service: Failed with result 'exit-code'.
Jun 14 00:11:43 bar-artful6401 systemd[1]: Reached target Network is Online.

So this sounds like a protocol/socket issue, rather than an issue with networkd reporting wrong state of the network devices.

@Steve, eth0 is normal when you use Xen HVM guests. What I see when I strace the wait command is that is is in some epoll most of the time. That was the reason I was thinking that maybe it is waiting on some status change. But then I also believe it did find two entries in /run/systemd/netif/links which seem to be lo and eth0. So it should be aware of both. Just not sure what it is waiting for.

Hm, maybe that helps. This is the contents of /run/systemd/netif/links/2 (which is my eth0):

# This is private data. Do not parse.
ADMIN_STATE=configuring
OPER_STATE=routable
NETWORK_FILE=/run/systemd/network/10-netplan-eth0.network
DNS=192.168.2.1 fe80::c66e:1fff:fe3b:bdcd
NTP=
DOMAINS=
ROUTE_DOMAINS=
LLMNR=yes
MDNS=no
ADDRESSES=192.168.2.159/24
ROUTES=192.168.2.1/32/0/100/254/18446744073709551615 0.0.0.0/0/0/100/254/18446744073709551615
DHCP4_ADDRESS=192.168.2.159
DHCP_LEASE=/run/systemd/netif/leases/2

ADMIN_STATE sounds suspicious.

Fresh install of an artful-server image in a VM, and I can't reproduce this problem. For some reason, on your system networkd never logs that the network interface has been 'configured'. So in fact, systemd-networkd-wait-online is behaving correctly; you're somehow just never getting the OK from systemd-networkd.

ubuntu@artful-server:~$ time sudo /lib/systemd/systemd-networkd-wait-online
ignoring: lo

real 0m0.018s
user 0m0.012s
sys 0m0.000s
ubuntu@artful-server:~$ echo $?
0
ubuntu@artful-server:~$ ip link
1: lo: <LOOPBACK,UP,LOWER_UP> mtu 65536 qdisc noqueue state UNKNOWN mode DEFAULT group default qlen 1000
    link/loopback 00:00:00:00:00:00 brd 00:00:00:00:00:00
2: ens3: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc pfifo_fast state UP mode DEFAULT group default qlen 1000
    link/ether 52:54:00:68:21:e2 brd ff:ff:ff:ff:ff:ff
ubuntu@artful-server:~$ ip addr
1: lo: <LOOPBACK,UP,LOWER_UP> mtu 65536 qdisc noqueue state UNKNOWN group default qlen 1000
    link/loopback 00:00:00:00:00:00 brd 00:00:00:00:00:00
    inet 127.0.0.1/8 scope host lo
       valid_lft forever preferred_lft forever
    inet6 ::1/128 scope host
       valid_lft forever preferred_lft forever
2: ens3: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc pfifo_fast state UP group default qlen 1000
    link/ether 52:54:00:68:21:e2 brd ff:ff:ff:ff:ff:ff
    inet 192.168.15.68/24 brd 192.168.15.255 scope global dynamic ens3
       valid_lft 3269sec preferred_lft 3269sec
    inet6 2001:470:e980:0:5054:ff:fe68:21e2/64 scope global mngtmpaddr noprefixroute dynamic
       valid_lft 86295sec preferred_lft 14295sec
    inet6 fe80::5054:ff:fe68:21e2/64 scope link
       valid_lft forever preferred_lft forever
ubuntu@artful-server:~$ cat /etc/netplan/01-netcfg.yaml
# This file describes the network interfaces available on your system
# For more information, see netplan(5).
network:
  version: 2
  renderer: networkd
  ethernets:
    ens3:
      dhcp4: yes
      dhcp6: yes
ubuntu@artful-server:~$ cat /run/systemd/network/10-netplan-ens3.network
[Match]
Name=ens3

[Network]
DHCP=yes

[DHCP]
RouteMetric=100
ubuntu@artful-server:~$ dpkg -l systemd|grep ^ii
ii systemd 233-6ubuntu3 amd64 system and service manager
ubuntu@artful-server:~$

And, perhaps most crucially:

ubuntu@artful-server:~$ sudo journalctl -u systemd-networkd --no-pager
-- Logs begin at Wed 2017-06-14 09:20:15 PDT, end at Wed 2017-06-14 09:27:38 PDT. --
Jun 14 09:20:17 artful-server systemd[1]: Starting Network Service...
Jun 14 09:20:17 artful-server systemd-networkd[451]: Enumeration completed
Jun 14 09:20:17 artful-server systemd[1]: Started Network Service.
Jun 14 09:20:17 artful-server systemd-networkd[451]: ens3: IPv6 successfully enabled
Jun 14 09:20:17 artful-server systemd-networkd[451]: ens3: Gained carrier
Jun 14 09:20:18 artful-server systemd-networkd[451]: ens3: DHCPv4 address 192.168.15.68/24 via 192.168.15.1
Jun 14 09:20:18 artful-server systemd-networkd[451]: ens3: Gained IPv6LL
Jun 14 09:20:20 artful-server systemd-networkd[451]: ens3: Configured
ubuntu@artful-server:~$

It looks a lot like this issue:

https://github.com/systemd/systemd/issues/1645

Where DHCP works, it has an ip and can sync time and other items, but the
wait service isn't happy.

On Wed, Jun 14, 2017 at 10:46 AM, Steve Langasek <
<email address hidden>> wrote:

> The journal shows, two minutes after the start of the wait-online job:
>
> Jun 14 00:11:42 bar-artful6401 systemd-networkd-wait-online[618]: Event
> loop failed: Connection timed out
> Jun 14 00:11:42 bar-artful6401 systemd[1]: systemd-networkd-wait-online.service:
> Main process exited, code=exited, status=1/FAILURE
> Jun 14 00:11:42 bar-artful6401 systemd[1]: Failed to start Wait for
> Network to be Configured.
> Jun 14 00:11:42 bar-artful6401 systemd[1]: systemd-networkd-wait-online.service:
> Unit entered failed state.
> Jun 14 00:11:42 bar-artful6401 systemd[1]: systemd-networkd-wait-online.service:
> Failed with result 'exit-code'.
> Jun 14 00:11:43 bar-artful6401 systemd[1]: Reached target Network is
> Online.
>
> So this sounds like a protocol/socket issue, rather than an issue with
> networkd reporting wrong state of the network devices.
>
> --
> You received this bug notification because you are subscribed to the bug
> report.
> https://bugs.launchpad.net/bugs/1697730
>
> Title:
> Long boot time due to systemd-networkd-wait-online.service failure
>
> To manage notifications about this bug go to:
> https://bugs.launchpad.net/ubuntu/+source/systemd/+bug/
> 1697730/+subscriptions
>

What does your networkctl status eth0 show?

On Wed, Jun 14, 2017 at 11:34 AM, Ryan Harper <email address hidden>
wrote:

> It looks a lot like this issue:
>
> https://github.com/systemd/systemd/issues/1645
>
> Where DHCP works, it has an ip and can sync time and other items, but the
> wait service isn't happy.
>
> On Wed, Jun 14, 2017 at 10:46 AM, Steve Langasek <
> <email address hidden>> wrote:
>
>> The journal shows, two minutes after the start of the wait-online job:
>>
>> Jun 14 00:11:42 bar-artful6401 systemd-networkd-wait-online[618]: Event
>> loop failed: Connection timed out
>> Jun 14 00:11:42 bar-artful6401 systemd[1]: systemd-networkd-wait-online.service:
>> Main process exited, code=exited, status=1/FAILURE
>> Jun 14 00:11:42 bar-artful6401 systemd[1]: Failed to start Wait for
>> Network to be Configured.
>> Jun 14 00:11:42 bar-artful6401 systemd[1]: systemd-networkd-wait-online.service:
>> Unit entered failed state.
>> Jun 14 00:11:42 bar-artful6401 systemd[1]: systemd-networkd-wait-online.service:
>> Failed with result 'exit-code'.
>> Jun 14 00:11:43 bar-artful6401 systemd[1]: Reached target Network is
>> Online.
>>
>> So this sounds like a protocol/socket issue, rather than an issue with
>> networkd reporting wrong state of the network devices.
>>
>> --
>> You received this bug notification because you are subscribed to the bug
>> report.
>> https://bugs.launchpad.net/bugs/1697730
>>
>> Title:
>> Long boot time due to systemd-networkd-wait-online.service failure
>>
>> To manage notifications about this bug go to:
>> https://bugs.launchpad.net/ubuntu/+source/systemd/+bug/16977
>> 30/+subscriptions
>>
>
>

I noticed one difference between our configs was that you did not have public ipv6 set up. I shut down radvd on my router and rebooted as a test; this seems to cause a slight delay at boot (long enough for systemd to send a message warning that it's waiting for the network to be configured), but this takes about 15s before it gives up on ipv6, not 2 minutes.

@Ryan:

2: eth0
       Link File: /lib/systemd/network/99-default.link
    Network File: /run/systemd/network/10-netplan-eth0.network
            Type: ether
           State: routable (configuring)
            Path: xen-vif-0
          Driver: vif
      HW Address: 00:16:3e:71:31:57 (Xensource, Inc.)
         Address: 192.168.2.159
                  fe80::216:3eff:fe71:3157
         Gateway: 192.168.2.1 (PC Engines GmbH)
             DNS: 192.168.2.1
                  fe80::c66e:1fff:fe3b:bdcd

Similar on the KVM guest, just being ens3 then.

So from what Steve wrote and what I see. the missing part is moving from "Gained IPv6LL" to "Configured".

This is a known issue w.r.t waiting for IPV6 LL, on Xenial KVM, qemu -net
user does not provide IPV6 LL response (yakkety and newer do), so there's a
delay; it does sound like the IPV6 LL timeout is longer than it used to be
as I've seen a 5 to 10 second delay in VMs launched on KVM on xenial, but
not a full 120 seconds which breaks the wait-online.

On Wed, Jun 14, 2017 at 12:31 PM, Stefan Bader <email address hidden>
wrote:

> So from what Steve wrote and what I see. the missing part is moving from
> "Gained IPv6LL" to "Configured".
>
> --
> You received this bug notification because you are subscribed to the bug
> report.
> https://bugs.launchpad.net/bugs/1697730
>
> Title:
> Long boot time due to systemd-networkd-wait-online.service failure
>
> To manage notifications about this bug go to:
> https://bugs.launchpad.net/ubuntu/+source/systemd/+bug/
> 1697730/+subscriptions
>

On Wed, Jun 14, 2017 at 05:58:06PM -0000, Ryan Harper wrote:
> This is a known issue w.r.t waiting for IPV6 LL, on Xenial KVM, qemu -net
> user does not provide IPV6 LL response (yakkety and newer do), so there's a
> delay; it does sound like the IPV6 LL timeout is longer than it used to be
> as I've seen a 5 to 10 second delay in VMs launched on KVM on xenial, but
> not a full 120 seconds which breaks the wait-online.

If it were just a delay, networkd should still eventually recognize the
device as configured. Maybe some packets are going missing? We probably
need a network trace from within the guest.

Also probably interesting to know if 'sudo service networkd-resolved
restart' changes the state of things, or if the device remains
'configuring'.

--
Steve Langasek Give me a lever long enough and a Free OS
Debian Developer to set it on, and I can move the world.
Ubuntu Developer http://www.debian.org/
<email address hidden> <email address hidden>

Started to bring up real HW with the same woes and timeout on boot. After some more cursing and faffing around I realized an odd element of the resulting setup:

There is some weird ipv6 link local address for DNS server: fe80::c66e:1fff:fe3b:bdcd. It is the same for the VM doing dhcp and for real HW where I manually set everything and that does *not* include any fancy ipv6 address. Matter of fact I cannot enter any ipv6 address in the nameservers address section without getting complaints about unexpected ':'s. But that is another story.

So does anybody have a clue were that comes from? It is not in the generated netplan files in /run/systemd/network but systemd-resolvd gets it (probably from /run/systemd/netif/links/*).

So that link local is from a Wireless AP that runs open-wrt. But why it is picked up and how can I stop this madness?

Finally found a work-around that also proves the failure to become configured is caused by that stupid ipv6ll address added to the DNS server list. But I did not find any way which integrates into netplan. I basically took /run/systemd/network/10-netplan-br0.network and copied it as /etc/systemd/network/05-br0.network.

Then added: "IPv6AcceptRA=no" to the [Network] section and rebooted. Now the DNS list only contains the one server I specify and the status ends up as "routable (configured)".

ok sounds like this needs to be addressed in netplan.

Adding some random thoughts on this. First I finally was able to change the AP configuration to not do IPv6RA. That solved the immediate problem. But it was not straight forward to do and what other cases of broken IPv6 setup there is in the wild.

One thing systemd-netword was doing wrong (imo) was to take a fe80:: link local address and put this into the list of DNS servers without a interface specifier (a %<iface name> appended to the ll address). That seems to be mandatory for link local addresses to be usable and maybe the bringup would have succeeded if that were present.

Generally wondering: would it make sense, that if the netplan yaml contained neither DHCP6 turned on, nor IPv6 addresses for an interface, to then add IPv6AcceptRA=no generally to the the generated config? If I read the systemd man page correctly that is the method of turning off IPv6 support.

Hi, I'm also affected by this bug on real hardware (Lenovo Yoga 2 13 laptop), let me know if I can give feedback to help fix this bug.

I am also affected in real hardware. Running artful with a wireless and ethernet card (there are also some docker bridges from some images that don't run at startup)

I don't have any contents in /etc/systemd/network but I do in '/lib/systemd/network'

After it times out I can run 'systemctl start systemd-networkd-wait-online.service' and it does not complain

Added attachment with contents of '/lib/systemd/network'

Reproduced on a Dell XPS 13, latest generation.

At startup I have a 2+ min delay relating to this, syslog shows the same messages as the OP.

I can run 'systemctl start systemd-networkd-wait-online.service' with no problems post startup

Also affected on real hardware after upgrading from 17.04. Lenovo T450s.
Same messages as above.

Affected on ThinkPad X240 after upgrade from 17.04 when booting in an environment with no known wifi networks. If a known wifi network is available (and set accessible to all users) the boot time is more reasonable.

I have an XPS 13 9350 and have this problem. I found that I had both systemd-networkd and NetworkManager services enabled, but no configuration for systemd-networkd in /etc/systemd/network, and no configuration in /etc/netplan.

I noticed on a artful VM I had /etc/netplan/01-network-manager-all.yaml but not on my laptop. I created /etc/netplan/01-network-manager-all.yaml on my laptop and did 'sudo netplan apply' and rebooted, but no difference. I then looked again at my logs and saw that my wireless interface was scanning (ie, not in failed state (I was in an area with no known APs)) when systemd-networkd-wait-online finally timed out after 2 minutes. Since I knew that I use NetworkManager, I simply did `sudo systemctl disable systemd-networkd`, rebooted and had a fast boot (with NetworkManager not blocking when no known APs were available and connecting when one was).

Is it intentional that systemd-networkd is enabled at the same time NetworkManager is when there is no configuration? If so, is it expected that wireless is being attempted when systemd-networkd has no configuration?

My part of this is resolved by the fixed for https://bugs.launchpad.net/ubuntu/+source/systemd/+bug/1714301

If you are looking for newer bug reports with this issue try
LP: #1717152
LP: #1728181