| 2018-04-18 19:03:37 |
Ryan Harper |
bug |
|
|
added bug |
| 2018-04-18 19:33:48 |
Launchpad Janitor |
systemd (Ubuntu): status |
New |
Confirmed |
|
| 2018-04-18 19:33:51 |
Andreas Hasenack |
bug |
|
|
added subscriber Andreas Hasenack |
| 2018-04-18 19:38:14 |
David Britton |
bug |
|
|
added subscriber David Britton |
| 2018-04-18 22:58:22 |
Steve Langasek |
bug task added |
|
cloud-init (Ubuntu) |
|
| 2018-04-18 23:00:24 |
Steve Langasek |
bug task added |
|
netplan.io (Ubuntu) |
|
| 2018-04-19 00:17:33 |
Steve Langasek |
bug |
|
|
added subscriber Steve Langasek |
| 2018-04-20 02:43:12 |
Dimitri John Ledkov |
cloud-init (Ubuntu): status |
New |
Fix Released |
|
| 2018-04-20 02:43:15 |
Dimitri John Ledkov |
netplan.io (Ubuntu): status |
New |
Fix Released |
|
| 2018-04-20 02:43:17 |
Dimitri John Ledkov |
systemd (Ubuntu): status |
Confirmed |
In Progress |
|
| 2018-04-20 03:05:56 |
Dimitri John Ledkov |
description |
1.
$ lsb_release -rd
Description: Ubuntu Bionic Beaver (development branch)
Release: 18.04
2.
$ apt-cache policy systemd
systemd:
Installed: 237-3ubuntu8
Candidate: 237-3ubuntu8
Version table:
*** 237-3ubuntu8 500
500 http://archive.ubuntu.com/ubuntu bionic/main amd64 Packages
100 /var/lib/dpkg/status
3. systemd-networkd-wait-online doesn't block for 10 seconds waiting on an IPV6 Router Advertisement
4. systemd-networkd sends at least two RA solicitation packets waiting for a response before setting the link to configured. This blocks the boot for every Ubuntu system where it does not have a IPV6 router responding to solicitations. THis includes bionic containers, cloud instances, vms and physical machines.
--
We can see that we're spending 13 seconds waiting for networkd to say the network is up.
% systemd-analyze blame
13.326s systemd-networkd-wait-online.service
999ms cloud-init-local.service
954ms cloud-init.service
887ms cloud-config.service
749ms dev-vda1.device
666ms cloud-final.service
248ms keyboard-setup.service
175ms systemd-udev-trigger.service
171ms lxd-containers.service
165ms snapd.service
154ms apparmor.service
147ms ssh.service
144ms systemd-timesyncd.service
133ms grub-common.service
130ms systemd-journald.service
130ms accounts-daemon.service
99ms systemd-modules-load.service
98ms systemd-resolved.service
94ms apport.service
92ms rsyslog.service
88ms systemd-logind.service
80ms lvm2-monitor.service
75ms iscsid.service
64ms ebtables.service
62ms user@1000.service
54ms dev-mqueue.mount
53ms ufw.service
52ms systemd-remount-fs.service
52ms kmod-static-nodes.service
34ms systemd-journal-flush.service
34ms polkit.service
32ms systemd-tmpfiles-setup-dev.service
27ms systemd-udevd.service
26ms systemd-networkd.service
26ms systemd-sysctl.service
25ms systemd-tmpfiles-setup.service
21ms dev-hugepages.mount
17ms sys-kernel-debug.mount
16ms console-setup.service
15ms plymouth-read-write.service
15ms snapd.socket
15ms plymouth-quit.service
14ms systemd-update-utmp.service
10ms systemd-user-sessions.service
9ms boot-efi.mount
8ms sys-fs-fuse-connections.mount
8ms systemd-update-utmp-runlevel.service
8ms lxd.socket
7ms blk-availability.service
5ms systemd-random-seed.service
3ms setvtrgb.service
3ms plymouth-quit-wait.service
3ms sys-kernel-config.mount
Here we can see that we start networking at 18:30:51.69, and then IPv6 NDISC runs for 10 seconds
and then the link is configured at 18:31:05. *AND* we see NDISC stays around and continues to see if it gets a RA packet.
$ journalctl -o short-precise -u systemd-networkd.service | egrep "(Starting Network|Discovering IPv6 routers|NDISC|Configured)"
Apr 18 18:30:51.691532 rharper-b1 systemd[1]: Starting Network Service...
Apr 18 18:30:53.031041 rharper-b1 systemd-networkd[603]: ens3: Discovering IPv6 routers
Apr 18 18:30:53.031306 rharper-b1 systemd-networkd[603]: NDISC: Started IPv6 Router Solicitation client
Apr 18 18:30:53.031612 rharper-b1 systemd-networkd[603]: NDISC: Sent Router Solicitation, next solicitation in 4s
Apr 18 18:30:57.092282 rharper-b1 systemd-networkd[603]: NDISC: Sent Router Solicitation, next solicitation in 8s
Apr 18 18:31:05.040895 rharper-b1 systemd-networkd[603]: NDISC: No RA received before link confirmation timeout
Apr 18 18:31:05.040932 rharper-b1 systemd-networkd[603]: NDISC: Invoking callback for 't'.
Apr 18 18:31:05.041099 rharper-b1 systemd-networkd[603]: ens3: Configured
Apr 18 18:31:05.484261 rharper-b1 systemd-networkd[603]: NDISC: Sent Router Solicitation, next solicitation in 16s
Apr 18 18:31:21.550612 rharper-b1 systemd-networkd[603]: NDISC: Sent Router Solicitation, next solicitation in 33s
Apr 18 18:31:54.706283 rharper-b1 systemd-networkd[603]: NDISC: Sent Router Solicitation, next solicitation in 1min 5s
Apr 18 18:33:00.232685 rharper-b1 systemd-networkd[603]: NDISC: Sent Router Solicitation, next solicitation in 2min 15s
Apr 18 18:35:15.436376 rharper-b1 systemd-networkd[603]: NDISC: Sent Router Solicitation, next solicitation in 4min 32s
Apr 18 18:39:48.111413 rharper-b1 systemd-networkd[603]: NDISC: Sent Router Solicitation, next solicitation in 9min 16s
networkd runs ndisc if your host is configured with ipv6 forwarding disabled and accept_ra enabled.
% sysctl net.ipv6.conf.all.forwarding
net.ipv6.conf.all.forwarding = 0
% sysctl net.ipv6.conf.all.accept_ra
net.ipv6.conf.all.accept_ra = 1
So ndisc path is expected per systemd code. We should be able to disable the NDISC link timeout; especially since NDISC stays around to process RA packets later on anyhow. Nothing is gained by blocking boot waiting for an RA packet. This is also a change in behavior on previous LTS, Xenial where the RA handling is done in the kernel rather than netowkrd.
Full debug output of systemd-networkd during this boot.
% journalctl -o short-precise -u systemd-networkd.service
-- Logs begin at Wed 2018-04-18 18:30:19 UTC, end at Wed 2018-04-18 18:35:15 UTC. --
Apr 18 18:30:34.371090 rharper-b1 systemd[1]: Stopping Network Service...
Apr 18 18:30:34.399603 rharper-b1 systemd[1]: Stopped Network Service.
-- Reboot --
Apr 18 18:30:51.691532 rharper-b1 systemd[1]: Starting Network Service...
Apr 18 18:30:51.714593 rharper-b1 systemd-networkd[603]: Bus n/a: changing state UNSET → OPENING
Apr 18 18:30:51.714736 rharper-b1 systemd-networkd[603]: Added inotify watch for /run on bus n/a: 2
Apr 18 18:30:51.714754 rharper-b1 systemd-networkd[603]: Added inotify watch for /run/dbus on bus n/a: -1
Apr 18 18:30:51.714795 rharper-b1 systemd-networkd[603]: Bus n/a: changing state OPENING → WATCH_BIND
Apr 18 18:30:51.715122 rharper-b1 systemd-networkd[603]: Failed to open configuration file '/etc/systemd/networkd.conf': No such file or directory
Apr 18 18:30:51.715134 rharper-b1 systemd-networkd[603]: timestamp of '/etc/systemd/network' changed
Apr 18 18:30:51.715144 rharper-b1 systemd-networkd[603]: timestamp of '/run/systemd/network' changed
Apr 18 18:30:51.715334 rharper-b1 systemd-networkd[603]: Ignoring /run/systemd/network/10-netplan-ens3.network, because it's not a regular file with suffix .netdev.
Apr 18 18:30:51.715342 rharper-b1 systemd-networkd[603]: Ignoring /run/systemd/network/10-netplan-ens3.link, because it's not a regular file with suffix .netdev.
Apr 18 18:30:51.715375 rharper-b1 systemd-networkd[603]: Ignoring /lib/systemd/network/80-container-vz.network, because it's not a regular file with suffix .netdev.
Apr 18 18:30:51.715382 rharper-b1 systemd-networkd[603]: Ignoring /lib/systemd/network/99-default.link, because it's not a regular file with suffix .netdev.
Apr 18 18:30:51.715389 rharper-b1 systemd-networkd[603]: Ignoring /lib/systemd/network/80-container-host0.network, because it's not a regular file with suffix .netdev.
Apr 18 18:30:51.715397 rharper-b1 systemd-networkd[603]: Ignoring /lib/systemd/network/80-container-ve.network, because it's not a regular file with suffix .netdev.
Apr 18 18:30:51.715573 rharper-b1 systemd-networkd[603]: Ignoring /run/systemd/network/10-netplan-ens3.link, because it's not a regular file with suffix .network.
Apr 18 18:30:51.715603 rharper-b1 systemd-networkd[603]: Ignoring /lib/systemd/network/99-default.link, because it's not a regular file with suffix .network.
Apr 18 18:30:51.717227 rharper-b1 systemd-networkd[603]: ens3: Flags change: +MULTICAST +BROADCAST
Apr 18 18:30:51.717240 rharper-b1 systemd-networkd[603]: ens3: Link 2 added
Apr 18 18:30:51.717552 rharper-b1 systemd-networkd[603]: ens3: udev initialized link
Apr 18 18:30:51.717585 rharper-b1 systemd-networkd[603]: ens3: Saved original MTU: 1500
Apr 18 18:30:51.717597 rharper-b1 systemd-networkd[603]: lo: Flags change: +LOOPBACK +UP +LOWER_UP +RUNNING
Apr 18 18:30:51.717628 rharper-b1 systemd-networkd[603]: lo: Link 1 added
Apr 18 18:30:51.717869 rharper-b1 systemd-networkd[603]: lo: udev initialized link
Apr 18 18:30:51.717900 rharper-b1 systemd-networkd[603]: lo: Saved original MTU: 0
Apr 18 18:30:51.717987 rharper-b1 systemd-networkd[603]: lo: Adding address: ::1/128 (valid forever)
Apr 18 18:30:51.717998 rharper-b1 systemd-networkd[603]: lo: Adding address: 127.0.0.1/8 (valid forever)
Apr 18 18:30:51.718115 rharper-b1 systemd-networkd[603]: rtnl: received address with invalid family 129, ignoring
Apr 18 18:30:51.718293 rharper-b1 systemd-networkd[603]: Enumeration completed
Apr 18 18:30:51.718444 rharper-b1 systemd-networkd[603]: ens3: Link state is up-to-date
Apr 18 18:30:51.718493 rharper-b1 systemd[1]: Started Network Service.
Apr 18 18:30:51.720311 rharper-b1 systemd-networkd[603]: ens3: found matching network '/run/systemd/network/10-netplan-ens3.network'
Apr 18 18:30:51.720850 rharper-b1 systemd-networkd[603]: lo: Link is not managed by us
Apr 18 18:30:51.720915 rharper-b1 systemd-networkd[603]: ens3: Bringing link up
Apr 18 18:30:51.720974 rharper-b1 systemd-networkd[603]: ens3: IPv6 successfully enabled
Apr 18 18:30:51.721574 rharper-b1 systemd-networkd[603]: lo: Link state is up-to-date
Apr 18 18:30:51.721778 rharper-b1 systemd-networkd[603]: Virtualization QEMU found in DMI (/sys/class/dmi/id/sys_vendor)
Apr 18 18:30:51.721792 rharper-b1 systemd-networkd[603]: Virtualization found, CPUID=KVMKVMKVM
Apr 18 18:30:51.721799 rharper-b1 systemd-networkd[603]: Found VM virtualization kvm
Apr 18 18:30:51.721808 rharper-b1 systemd-networkd[603]: lo: Unmanaged
Apr 18 18:30:51.722017 rharper-b1 systemd-networkd[603]: ens3: Flags change: +UP +LOWER_UP +RUNNING
Apr 18 18:30:51.727823 rharper-b1 systemd-networkd[603]: LLDP: Started LLDP client
Apr 18 18:30:51.727831 rharper-b1 systemd-networkd[603]: ens3: Started LLDP.
Apr 18 18:30:51.727838 rharper-b1 systemd-networkd[603]: ens3: Gained carrier
Apr 18 18:30:51.727852 rharper-b1 systemd-networkd[603]: ens3: Acquiring DHCPv4 lease
Apr 18 18:30:51.727965 rharper-b1 systemd-networkd[603]: DHCP CLIENT (0x9bbb16d3): STARTED on ifindex 2
Apr 18 18:30:51.728263 rharper-b1 systemd-networkd[603]: DHCP CLIENT (0x9bbb16d3): DISCOVER
Apr 18 18:30:51.729279 rharper-b1 systemd-networkd[603]: DHCP CLIENT (0x9bbb16d3): OFFER
Apr 18 18:30:51.729361 rharper-b1 systemd-networkd[603]: DHCP CLIENT (0x9bbb16d3): REQUEST (requesting)
Apr 18 18:30:51.730084 rharper-b1 systemd-networkd[603]: DHCP CLIENT (0x9bbb16d3): ACK
Apr 18 18:30:51.730212 rharper-b1 systemd-networkd[603]: DHCP CLIENT (0x9bbb16d3): lease expires in 59min 58s
Apr 18 18:30:51.730221 rharper-b1 systemd-networkd[603]: DHCP CLIENT (0x9bbb16d3): T2 expires in 52min 27s
Apr 18 18:30:51.730229 rharper-b1 systemd-networkd[603]: DHCP CLIENT (0x9bbb16d3): T1 expires in 29min 57s
Apr 18 18:30:51.730314 rharper-b1 systemd-networkd[603]: ens3: DHCPv4 address 192.168.122.140/24 via 192.168.122.1
Apr 18 18:30:51.730375 rharper-b1 systemd-networkd[603]: Setting transient hostname: 'rharper-b1'
Apr 18 18:30:51.730385 rharper-b1 systemd-networkd[603]: Not connected to system bus, not setting hostname.
Apr 18 18:30:51.730676 rharper-b1 systemd-networkd[603]: ens3: Updating address: 192.168.122.140/24 (valid for 1h)
Apr 18 18:30:51.731002 rharper-b1 systemd-networkd[603]: ens3: DHCP error: could not get routes: No data available
Apr 18 18:30:53.030808 rharper-b1 systemd-networkd[603]: ens3: Adding address: fe80::5054:ff:feba:2b98/64 (valid forever)
Apr 18 18:30:53.030877 rharper-b1 systemd-networkd[603]: ens3: Gained IPv6LL
Apr 18 18:30:53.031041 rharper-b1 systemd-networkd[603]: ens3: Discovering IPv6 routers
Apr 18 18:30:53.031306 rharper-b1 systemd-networkd[603]: NDISC: Started IPv6 Router Solicitation client
Apr 18 18:30:53.031612 rharper-b1 systemd-networkd[603]: NDISC: Sent Router Solicitation, next solicitation in 4s
Apr 18 18:30:57.092282 rharper-b1 systemd-networkd[603]: NDISC: Sent Router Solicitation, next solicitation in 8s
Apr 18 18:31:05.040895 rharper-b1 systemd-networkd[603]: NDISC: No RA received before link confirmation timeout
Apr 18 18:31:05.040932 rharper-b1 systemd-networkd[603]: NDISC: Invoking callback for 't'.
Apr 18 18:31:05.041099 rharper-b1 systemd-networkd[603]: ens3: Configured
Apr 18 18:31:05.484261 rharper-b1 systemd-networkd[603]: NDISC: Sent Router Solicitation, next solicitation in 16s
Apr 18 18:31:05.495751 rharper-b1 systemd-networkd[603]: Got inotify event on bus n/a.
Apr 18 18:31:05.495842 rharper-b1 systemd-networkd[603]: Added inotify watch for /run on bus n/a: 2
Apr 18 18:31:05.495870 rharper-b1 systemd-networkd[603]: Added inotify watch for /run/dbus on bus n/a: -1
Apr 18 18:31:05.928832 rharper-b1 systemd-networkd[603]: Got inotify event on bus n/a.
Apr 18 18:31:05.928914 rharper-b1 systemd-networkd[603]: Added inotify watch for /run on bus n/a: 2
Apr 18 18:31:05.928935 rharper-b1 systemd-networkd[603]: Added inotify watch for /run/dbus on bus n/a: -1
Apr 18 18:31:06.014785 rharper-b1 systemd-networkd[603]: Got inotify event on bus n/a.
Apr 18 18:31:06.015036 rharper-b1 systemd-networkd[603]: Added inotify watch for /run on bus n/a: 2
Apr 18 18:31:06.017290 rharper-b1 systemd-networkd[603]: Added inotify watch for /run/dbus on bus n/a: -1
Apr 18 18:31:06.017532 rharper-b1 systemd-networkd[603]: Got inotify event on bus n/a.
Apr 18 18:31:06.017581 rharper-b1 systemd-networkd[603]: Added inotify watch for /run on bus n/a: 2
Apr 18 18:31:06.017598 rharper-b1 systemd-networkd[603]: Added inotify watch for /run/dbus on bus n/a: -1
Apr 18 18:31:06.027908 rharper-b1 systemd-networkd[603]: Got inotify event on bus n/a.
Apr 18 18:31:06.028491 rharper-b1 systemd-networkd[603]: Bus n/a: changing state WATCH_BIND → AUTHENTICATING
Apr 18 18:31:06.051721 rharper-b1 systemd-networkd[603]: Bus n/a: changing state AUTHENTICATING → HELLO
Apr 18 18:31:06.051767 rharper-b1 systemd-networkd[603]: Sent message type=method_call sender=n/a destination=org.freedesktop.DBus path=/org/freedesktop/DBus interface=org.freedesktop.DBus member=Hello cookie=1 reply_cookie=0 signature=n/a error-name=n/a error-message=n/a
Apr 18 18:31:06.051782 rharper-b1 systemd-networkd[603]: Sent message type=method_call sender=n/a destination=org.freedesktop.DBus path=/org/freedesktop/DBus interface=org.freedesktop.DBus member=RequestName cookie=2 reply_cookie=0 signature=su error-name=n/a error-message=n/a
Apr 18 18:31:06.051794 rharper-b1 systemd-networkd[603]: Sent message type=method_call sender=n/a destination=org.freedesktop.DBus path=/org/freedesktop/DBus interface=org.freedesktop.DBus member=AddMatch cookie=3 reply_cookie=0 signature=s error-name=n/a error-message=n/a
Apr 18 18:31:06.051807 rharper-b1 systemd-networkd[603]: Sent message type=signal sender=n/a destination=n/a path=/org/freedesktop/network1/link/_31 interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=4 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Apr 18 18:31:06.051819 rharper-b1 systemd-networkd[603]: Sent message type=signal sender=n/a destination=n/a path=/org/freedesktop/network1/link/_32 interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=5 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Apr 18 18:31:06.051831 rharper-b1 systemd-networkd[603]: Sent message type=signal sender=n/a destination=n/a path=/org/freedesktop/network1/link/_31 interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=6 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Apr 18 18:31:06.051842 rharper-b1 systemd-networkd[603]: Sent message type=signal sender=n/a destination=n/a path=/org/freedesktop/network1/link/_32 interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=7 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Apr 18 18:31:06.051854 rharper-b1 systemd-networkd[603]: Sent message type=signal sender=n/a destination=n/a path=/org/freedesktop/network1/link/_32 interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=8 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Apr 18 18:31:06.051868 rharper-b1 systemd-networkd[603]: Sent message type=signal sender=n/a destination=n/a path=/org/freedesktop/network1/link/_32 interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=9 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Apr 18 18:31:06.051881 rharper-b1 systemd-networkd[603]: Sent message type=signal sender=n/a destination=n/a path=/org/freedesktop/network1 interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=10 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Apr 18 18:31:06.051893 rharper-b1 systemd-networkd[603]: Sent message type=signal sender=n/a destination=n/a path=/org/freedesktop/network1/link/_32 interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=11 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Apr 18 18:31:06.051905 rharper-b1 systemd-networkd[603]: Sent message type=signal sender=n/a destination=n/a path=/org/freedesktop/network1 interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=12 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Apr 18 18:31:06.051916 rharper-b1 systemd-networkd[603]: Sent message type=signal sender=n/a destination=n/a path=/org/freedesktop/network1/link/_32 interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=13 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Apr 18 18:31:06.053073 rharper-b1 systemd-networkd[603]: Got message type=method_return sender=org.freedesktop.DBus destination=:1.2 path=n/a interface=n/a member=n/a cookie=1 reply_cookie=1 signature=s error-name=n/a error-message=n/a
Apr 18 18:31:06.053092 rharper-b1 systemd-networkd[603]: Bus n/a: changing state HELLO → RUNNING
Apr 18 18:31:06.053151 rharper-b1 systemd-networkd[603]: Got message type=signal sender=org.freedesktop.DBus.Local destination=n/a path=/org/freedesktop/DBus/Local interface=org.freedesktop.DBus.Local member=Connected cookie=4294967295 reply_cookie=0 signature=n/a error-name=n/a error-message=n/a
Apr 18 18:31:06.053163 rharper-b1 systemd-networkd[603]: Setting transient hostname: 'rharper-b1'
Apr 18 18:31:06.053186 rharper-b1 systemd-networkd[603]: Sent message type=method_call sender=n/a destination=org.freedesktop.hostname1 path=/org/freedesktop/hostname1 interface=org.freedesktop.hostname1 member=SetHostname cookie=14 reply_cookie=0 signature=sb error-name=n/a error-message=n/a
Apr 18 18:31:06.053246 rharper-b1 systemd-networkd[603]: Got message type=signal sender=org.freedesktop.DBus destination=:1.2 path=/org/freedesktop/DBus interface=org.freedesktop.DBus member=NameAcquired cookie=2 reply_cookie=0 signature=s error-name=n/a error-message=n/a
Apr 18 18:31:06.053364 rharper-b1 systemd-networkd[603]: Got message type=signal sender=org.freedesktop.DBus destination=:1.2 path=/org/freedesktop/DBus interface=org.freedesktop.DBus member=NameAcquired cookie=3 reply_cookie=0 signature=s error-name=n/a error-message=n/a
Apr 18 18:31:06.053409 rharper-b1 systemd-networkd[603]: Got message type=method_return sender=org.freedesktop.DBus destination=:1.2 path=n/a interface=n/a member=n/a cookie=4 reply_cookie=2 signature=u error-name=n/a error-message=n/a
Apr 18 18:31:06.053419 rharper-b1 systemd-networkd[603]: Successfully acquired requested service name.
Apr 18 18:31:06.053502 rharper-b1 systemd-networkd[603]: Got message type=method_return sender=org.freedesktop.DBus destination=:1.2 path=n/a interface=n/a member=n/a cookie=5 reply_cookie=3 signature=n/a error-name=n/a error-message=n/a
Apr 18 18:31:06.053511 rharper-b1 systemd-networkd[603]: Match type='signal',sender='org.freedesktop.login1',path='/org/freedesktop/login1',interface='org.freedesktop.login1.Manager',member='PrepareForSleep' successfully installed.
Apr 18 18:31:06.229740 rharper-b1 systemd-networkd[603]: Got message type=method_return sender=:1.6 destination=:1.2 path=n/a interface=n/a member=n/a cookie=3 reply_cookie=14 signature=n/a error-name=n/a error-message=n/a
Apr 18 18:31:21.550612 rharper-b1 systemd-networkd[603]: NDISC: Sent Router Solicitation, next solicitation in 33s
Apr 18 18:31:54.706283 rharper-b1 systemd-networkd[603]: NDISC: Sent Router Solicitation, next solicitation in 1min 5s
Apr 18 18:33:00.232685 rharper-b1 systemd-networkd[603]: NDISC: Sent Router Solicitation, next solicitation in 2min 15s
Apr 18 18:35:15.436376 rharper-b1 systemd-networkd[603]: NDISC: Sent Router Solicitation, next solicitation in 4min 32s
ProblemType: Bug
DistroRelease: Ubuntu 18.04
Package: systemd 237-3ubuntu8
ProcVersionSignature: User Name 4.15.0-15.16-generic 4.15.15
Uname: Linux 4.15.0-15-generic x86_64
ApportVersion: 2.20.9-0ubuntu4
Architecture: amd64
Date: Wed Apr 18 18:25:53 2018
Lsusb: Bus 001 Device 001: ID 1d6b:0001 Linux Foundation 1.1 root hub
MachineType: QEMU Standard PC (i440FX + PIIX, 1996)
ProcEnviron:
TERM=xterm
PATH=(custom, no user)
XDG_RUNTIME_DIR=<set>
LANG=C.UTF-8
SHELL=/bin/bash
ProcKernelCmdLine: BOOT_IMAGE=/boot/vmlinuz-4.15.0-15-generic root=LABEL=cloudimg-rootfs ro console=tty1 console=ttyS0
SourcePackage: systemd
UpgradeStatus: No upgrade log present (probably fresh install)
dmi.bios.date: 04/01/2014
dmi.bios.vendor: SeaBIOS
dmi.bios.version: 1.10.2-1ubuntu1
dmi.chassis.type: 1
dmi.chassis.vendor: QEMU
dmi.chassis.version: pc-i440fx-bionic
dmi.modalias: dmi:bvnSeaBIOS:bvr1.10.2-1ubuntu1:bd04/01/2014:svnQEMU:pnStandardPC(i440FX+PIIX,1996):pvrpc-i440fx-bionic:cvnQEMU:ct1:cvrpc-i440fx-bionic:
dmi.product.name: Standard PC (i440FX + PIIX, 1996)
dmi.product.version: pc-i440fx-bionic
dmi.sys.vendor: QEMU |
[Impact]
* On ipv6 less hosts, boot stalls for 10s
* This is due to implicit RA being on, and wait-online awaiting for RA to timeout
* Expectation is, that since explicit request for RA was not done, it should not block network-online.target, whilst all other aspects of network-online.target should be honored.
[Test Case]
* lxc network set lxdbr0 ipv6.address none
* lxc launch ubuntu-daily:bionic lp1765173
* sleep 20 && lxc exec lp1765173 systemd-analyze blame | head
Bad result is:
12.157s systemd-networkd-wait-online.service
Good result is:
less than 3s
[Regression Potential]
* If explicit IPv6 dhcp/ra was enabled in .network file, the boot will be blocked awaiting RA response
* Only kernel implicit RA configuration will now become "async"
* This is inline with behaviour of xenial systems
[Other Info]
* Original bug report
1.
$ lsb_release -rd
Description: Ubuntu Bionic Beaver (development branch)
Release: 18.04
2.
$ apt-cache policy systemd
systemd:
Installed: 237-3ubuntu8
Candidate: 237-3ubuntu8
Version table:
*** 237-3ubuntu8 500
500 http://archive.ubuntu.com/ubuntu bionic/main amd64 Packages
100 /var/lib/dpkg/status
3. systemd-networkd-wait-online doesn't block for 10 seconds waiting on an IPV6 Router Advertisement
4. systemd-networkd sends at least two RA solicitation packets waiting for a response before setting the link to configured. This blocks the boot for every Ubuntu system where it does not have a IPV6 router responding to solicitations. THis includes bionic containers, cloud instances, vms and physical machines.
--
We can see that we're spending 13 seconds waiting for networkd to say the network is up.
% systemd-analyze blame
13.326s systemd-networkd-wait-online.service
999ms cloud-init-local.service
954ms cloud-init.service
887ms cloud-config.service
749ms dev-vda1.device
666ms cloud-final.service
248ms keyboard-setup.service
175ms systemd-udev-trigger.service
171ms lxd-containers.service
165ms snapd.service
154ms apparmor.service
147ms ssh.service
144ms systemd-timesyncd.service
133ms grub-common.service
130ms systemd-journald.service
130ms accounts-daemon.service
99ms systemd-modules-load.service
98ms systemd-resolved.service
94ms apport.service
92ms rsyslog.service
88ms systemd-logind.service
80ms lvm2-monitor.service
75ms iscsid.service
64ms ebtables.service
62ms user@1000.service
54ms dev-mqueue.mount
53ms ufw.service
52ms systemd-remount-fs.service
52ms kmod-static-nodes.service
34ms systemd-journal-flush.service
34ms polkit.service
32ms systemd-tmpfiles-setup-dev.service
27ms systemd-udevd.service
26ms systemd-networkd.service
26ms systemd-sysctl.service
25ms systemd-tmpfiles-setup.service
21ms dev-hugepages.mount
17ms sys-kernel-debug.mount
16ms console-setup.service
15ms plymouth-read-write.service
15ms snapd.socket
15ms plymouth-quit.service
14ms systemd-update-utmp.service
10ms systemd-user-sessions.service
9ms boot-efi.mount
8ms sys-fs-fuse-connections.mount
8ms systemd-update-utmp-runlevel.service
8ms lxd.socket
7ms blk-availability.service
5ms systemd-random-seed.service
3ms setvtrgb.service
3ms plymouth-quit-wait.service
3ms sys-kernel-config.mount
Here we can see that we start networking at 18:30:51.69, and then IPv6 NDISC runs for 10 seconds
and then the link is configured at 18:31:05. *AND* we see NDISC stays around and continues to see if it gets a RA packet.
$ journalctl -o short-precise -u systemd-networkd.service | egrep "(Starting Network|Discovering IPv6 routers|NDISC|Configured)"
Apr 18 18:30:51.691532 rharper-b1 systemd[1]: Starting Network Service...
Apr 18 18:30:53.031041 rharper-b1 systemd-networkd[603]: ens3: Discovering IPv6 routers
Apr 18 18:30:53.031306 rharper-b1 systemd-networkd[603]: NDISC: Started IPv6 Router Solicitation client
Apr 18 18:30:53.031612 rharper-b1 systemd-networkd[603]: NDISC: Sent Router Solicitation, next solicitation in 4s
Apr 18 18:30:57.092282 rharper-b1 systemd-networkd[603]: NDISC: Sent Router Solicitation, next solicitation in 8s
Apr 18 18:31:05.040895 rharper-b1 systemd-networkd[603]: NDISC: No RA received before link confirmation timeout
Apr 18 18:31:05.040932 rharper-b1 systemd-networkd[603]: NDISC: Invoking callback for 't'.
Apr 18 18:31:05.041099 rharper-b1 systemd-networkd[603]: ens3: Configured
Apr 18 18:31:05.484261 rharper-b1 systemd-networkd[603]: NDISC: Sent Router Solicitation, next solicitation in 16s
Apr 18 18:31:21.550612 rharper-b1 systemd-networkd[603]: NDISC: Sent Router Solicitation, next solicitation in 33s
Apr 18 18:31:54.706283 rharper-b1 systemd-networkd[603]: NDISC: Sent Router Solicitation, next solicitation in 1min 5s
Apr 18 18:33:00.232685 rharper-b1 systemd-networkd[603]: NDISC: Sent Router Solicitation, next solicitation in 2min 15s
Apr 18 18:35:15.436376 rharper-b1 systemd-networkd[603]: NDISC: Sent Router Solicitation, next solicitation in 4min 32s
Apr 18 18:39:48.111413 rharper-b1 systemd-networkd[603]: NDISC: Sent Router Solicitation, next solicitation in 9min 16s
networkd runs ndisc if your host is configured with ipv6 forwarding disabled and accept_ra enabled.
% sysctl net.ipv6.conf.all.forwarding
net.ipv6.conf.all.forwarding = 0
% sysctl net.ipv6.conf.all.accept_ra
net.ipv6.conf.all.accept_ra = 1
So ndisc path is expected per systemd code. We should be able to disable the NDISC link timeout; especially since NDISC stays around to process RA packets later on anyhow. Nothing is gained by blocking boot waiting for an RA packet. This is also a change in behavior on previous LTS, Xenial where the RA handling is done in the kernel rather than netowkrd.
Full debug output of systemd-networkd during this boot.
% journalctl -o short-precise -u systemd-networkd.service
-- Logs begin at Wed 2018-04-18 18:30:19 UTC, end at Wed 2018-04-18 18:35:15 UTC. --
Apr 18 18:30:34.371090 rharper-b1 systemd[1]: Stopping Network Service...
Apr 18 18:30:34.399603 rharper-b1 systemd[1]: Stopped Network Service.
-- Reboot --
Apr 18 18:30:51.691532 rharper-b1 systemd[1]: Starting Network Service...
Apr 18 18:30:51.714593 rharper-b1 systemd-networkd[603]: Bus n/a: changing state UNSET → OPENING
Apr 18 18:30:51.714736 rharper-b1 systemd-networkd[603]: Added inotify watch for /run on bus n/a: 2
Apr 18 18:30:51.714754 rharper-b1 systemd-networkd[603]: Added inotify watch for /run/dbus on bus n/a: -1
Apr 18 18:30:51.714795 rharper-b1 systemd-networkd[603]: Bus n/a: changing state OPENING → WATCH_BIND
Apr 18 18:30:51.715122 rharper-b1 systemd-networkd[603]: Failed to open configuration file '/etc/systemd/networkd.conf': No such file or directory
Apr 18 18:30:51.715134 rharper-b1 systemd-networkd[603]: timestamp of '/etc/systemd/network' changed
Apr 18 18:30:51.715144 rharper-b1 systemd-networkd[603]: timestamp of '/run/systemd/network' changed
Apr 18 18:30:51.715334 rharper-b1 systemd-networkd[603]: Ignoring /run/systemd/network/10-netplan-ens3.network, because it's not a regular file with suffix .netdev.
Apr 18 18:30:51.715342 rharper-b1 systemd-networkd[603]: Ignoring /run/systemd/network/10-netplan-ens3.link, because it's not a regular file with suffix .netdev.
Apr 18 18:30:51.715375 rharper-b1 systemd-networkd[603]: Ignoring /lib/systemd/network/80-container-vz.network, because it's not a regular file with suffix .netdev.
Apr 18 18:30:51.715382 rharper-b1 systemd-networkd[603]: Ignoring /lib/systemd/network/99-default.link, because it's not a regular file with suffix .netdev.
Apr 18 18:30:51.715389 rharper-b1 systemd-networkd[603]: Ignoring /lib/systemd/network/80-container-host0.network, because it's not a regular file with suffix .netdev.
Apr 18 18:30:51.715397 rharper-b1 systemd-networkd[603]: Ignoring /lib/systemd/network/80-container-ve.network, because it's not a regular file with suffix .netdev.
Apr 18 18:30:51.715573 rharper-b1 systemd-networkd[603]: Ignoring /run/systemd/network/10-netplan-ens3.link, because it's not a regular file with suffix .network.
Apr 18 18:30:51.715603 rharper-b1 systemd-networkd[603]: Ignoring /lib/systemd/network/99-default.link, because it's not a regular file with suffix .network.
Apr 18 18:30:51.717227 rharper-b1 systemd-networkd[603]: ens3: Flags change: +MULTICAST +BROADCAST
Apr 18 18:30:51.717240 rharper-b1 systemd-networkd[603]: ens3: Link 2 added
Apr 18 18:30:51.717552 rharper-b1 systemd-networkd[603]: ens3: udev initialized link
Apr 18 18:30:51.717585 rharper-b1 systemd-networkd[603]: ens3: Saved original MTU: 1500
Apr 18 18:30:51.717597 rharper-b1 systemd-networkd[603]: lo: Flags change: +LOOPBACK +UP +LOWER_UP +RUNNING
Apr 18 18:30:51.717628 rharper-b1 systemd-networkd[603]: lo: Link 1 added
Apr 18 18:30:51.717869 rharper-b1 systemd-networkd[603]: lo: udev initialized link
Apr 18 18:30:51.717900 rharper-b1 systemd-networkd[603]: lo: Saved original MTU: 0
Apr 18 18:30:51.717987 rharper-b1 systemd-networkd[603]: lo: Adding address: ::1/128 (valid forever)
Apr 18 18:30:51.717998 rharper-b1 systemd-networkd[603]: lo: Adding address: 127.0.0.1/8 (valid forever)
Apr 18 18:30:51.718115 rharper-b1 systemd-networkd[603]: rtnl: received address with invalid family 129, ignoring
Apr 18 18:30:51.718293 rharper-b1 systemd-networkd[603]: Enumeration completed
Apr 18 18:30:51.718444 rharper-b1 systemd-networkd[603]: ens3: Link state is up-to-date
Apr 18 18:30:51.718493 rharper-b1 systemd[1]: Started Network Service.
Apr 18 18:30:51.720311 rharper-b1 systemd-networkd[603]: ens3: found matching network '/run/systemd/network/10-netplan-ens3.network'
Apr 18 18:30:51.720850 rharper-b1 systemd-networkd[603]: lo: Link is not managed by us
Apr 18 18:30:51.720915 rharper-b1 systemd-networkd[603]: ens3: Bringing link up
Apr 18 18:30:51.720974 rharper-b1 systemd-networkd[603]: ens3: IPv6 successfully enabled
Apr 18 18:30:51.721574 rharper-b1 systemd-networkd[603]: lo: Link state is up-to-date
Apr 18 18:30:51.721778 rharper-b1 systemd-networkd[603]: Virtualization QEMU found in DMI (/sys/class/dmi/id/sys_vendor)
Apr 18 18:30:51.721792 rharper-b1 systemd-networkd[603]: Virtualization found, CPUID=KVMKVMKVM
Apr 18 18:30:51.721799 rharper-b1 systemd-networkd[603]: Found VM virtualization kvm
Apr 18 18:30:51.721808 rharper-b1 systemd-networkd[603]: lo: Unmanaged
Apr 18 18:30:51.722017 rharper-b1 systemd-networkd[603]: ens3: Flags change: +UP +LOWER_UP +RUNNING
Apr 18 18:30:51.727823 rharper-b1 systemd-networkd[603]: LLDP: Started LLDP client
Apr 18 18:30:51.727831 rharper-b1 systemd-networkd[603]: ens3: Started LLDP.
Apr 18 18:30:51.727838 rharper-b1 systemd-networkd[603]: ens3: Gained carrier
Apr 18 18:30:51.727852 rharper-b1 systemd-networkd[603]: ens3: Acquiring DHCPv4 lease
Apr 18 18:30:51.727965 rharper-b1 systemd-networkd[603]: DHCP CLIENT (0x9bbb16d3): STARTED on ifindex 2
Apr 18 18:30:51.728263 rharper-b1 systemd-networkd[603]: DHCP CLIENT (0x9bbb16d3): DISCOVER
Apr 18 18:30:51.729279 rharper-b1 systemd-networkd[603]: DHCP CLIENT (0x9bbb16d3): OFFER
Apr 18 18:30:51.729361 rharper-b1 systemd-networkd[603]: DHCP CLIENT (0x9bbb16d3): REQUEST (requesting)
Apr 18 18:30:51.730084 rharper-b1 systemd-networkd[603]: DHCP CLIENT (0x9bbb16d3): ACK
Apr 18 18:30:51.730212 rharper-b1 systemd-networkd[603]: DHCP CLIENT (0x9bbb16d3): lease expires in 59min 58s
Apr 18 18:30:51.730221 rharper-b1 systemd-networkd[603]: DHCP CLIENT (0x9bbb16d3): T2 expires in 52min 27s
Apr 18 18:30:51.730229 rharper-b1 systemd-networkd[603]: DHCP CLIENT (0x9bbb16d3): T1 expires in 29min 57s
Apr 18 18:30:51.730314 rharper-b1 systemd-networkd[603]: ens3: DHCPv4 address 192.168.122.140/24 via 192.168.122.1
Apr 18 18:30:51.730375 rharper-b1 systemd-networkd[603]: Setting transient hostname: 'rharper-b1'
Apr 18 18:30:51.730385 rharper-b1 systemd-networkd[603]: Not connected to system bus, not setting hostname.
Apr 18 18:30:51.730676 rharper-b1 systemd-networkd[603]: ens3: Updating address: 192.168.122.140/24 (valid for 1h)
Apr 18 18:30:51.731002 rharper-b1 systemd-networkd[603]: ens3: DHCP error: could not get routes: No data available
Apr 18 18:30:53.030808 rharper-b1 systemd-networkd[603]: ens3: Adding address: fe80::5054:ff:feba:2b98/64 (valid forever)
Apr 18 18:30:53.030877 rharper-b1 systemd-networkd[603]: ens3: Gained IPv6LL
Apr 18 18:30:53.031041 rharper-b1 systemd-networkd[603]: ens3: Discovering IPv6 routers
Apr 18 18:30:53.031306 rharper-b1 systemd-networkd[603]: NDISC: Started IPv6 Router Solicitation client
Apr 18 18:30:53.031612 rharper-b1 systemd-networkd[603]: NDISC: Sent Router Solicitation, next solicitation in 4s
Apr 18 18:30:57.092282 rharper-b1 systemd-networkd[603]: NDISC: Sent Router Solicitation, next solicitation in 8s
Apr 18 18:31:05.040895 rharper-b1 systemd-networkd[603]: NDISC: No RA received before link confirmation timeout
Apr 18 18:31:05.040932 rharper-b1 systemd-networkd[603]: NDISC: Invoking callback for 't'.
Apr 18 18:31:05.041099 rharper-b1 systemd-networkd[603]: ens3: Configured
Apr 18 18:31:05.484261 rharper-b1 systemd-networkd[603]: NDISC: Sent Router Solicitation, next solicitation in 16s
Apr 18 18:31:05.495751 rharper-b1 systemd-networkd[603]: Got inotify event on bus n/a.
Apr 18 18:31:05.495842 rharper-b1 systemd-networkd[603]: Added inotify watch for /run on bus n/a: 2
Apr 18 18:31:05.495870 rharper-b1 systemd-networkd[603]: Added inotify watch for /run/dbus on bus n/a: -1
Apr 18 18:31:05.928832 rharper-b1 systemd-networkd[603]: Got inotify event on bus n/a.
Apr 18 18:31:05.928914 rharper-b1 systemd-networkd[603]: Added inotify watch for /run on bus n/a: 2
Apr 18 18:31:05.928935 rharper-b1 systemd-networkd[603]: Added inotify watch for /run/dbus on bus n/a: -1
Apr 18 18:31:06.014785 rharper-b1 systemd-networkd[603]: Got inotify event on bus n/a.
Apr 18 18:31:06.015036 rharper-b1 systemd-networkd[603]: Added inotify watch for /run on bus n/a: 2
Apr 18 18:31:06.017290 rharper-b1 systemd-networkd[603]: Added inotify watch for /run/dbus on bus n/a: -1
Apr 18 18:31:06.017532 rharper-b1 systemd-networkd[603]: Got inotify event on bus n/a.
Apr 18 18:31:06.017581 rharper-b1 systemd-networkd[603]: Added inotify watch for /run on bus n/a: 2
Apr 18 18:31:06.017598 rharper-b1 systemd-networkd[603]: Added inotify watch for /run/dbus on bus n/a: -1
Apr 18 18:31:06.027908 rharper-b1 systemd-networkd[603]: Got inotify event on bus n/a.
Apr 18 18:31:06.028491 rharper-b1 systemd-networkd[603]: Bus n/a: changing state WATCH_BIND → AUTHENTICATING
Apr 18 18:31:06.051721 rharper-b1 systemd-networkd[603]: Bus n/a: changing state AUTHENTICATING → HELLO
Apr 18 18:31:06.051767 rharper-b1 systemd-networkd[603]: Sent message type=method_call sender=n/a destination=org.freedesktop.DBus path=/org/freedesktop/DBus interface=org.freedesktop.DBus member=Hello cookie=1 reply_cookie=0 signature=n/a error-name=n/a error-message=n/a
Apr 18 18:31:06.051782 rharper-b1 systemd-networkd[603]: Sent message type=method_call sender=n/a destination=org.freedesktop.DBus path=/org/freedesktop/DBus interface=org.freedesktop.DBus member=RequestName cookie=2 reply_cookie=0 signature=su error-name=n/a error-message=n/a
Apr 18 18:31:06.051794 rharper-b1 systemd-networkd[603]: Sent message type=method_call sender=n/a destination=org.freedesktop.DBus path=/org/freedesktop/DBus interface=org.freedesktop.DBus member=AddMatch cookie=3 reply_cookie=0 signature=s error-name=n/a error-message=n/a
Apr 18 18:31:06.051807 rharper-b1 systemd-networkd[603]: Sent message type=signal sender=n/a destination=n/a path=/org/freedesktop/network1/link/_31 interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=4 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Apr 18 18:31:06.051819 rharper-b1 systemd-networkd[603]: Sent message type=signal sender=n/a destination=n/a path=/org/freedesktop/network1/link/_32 interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=5 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Apr 18 18:31:06.051831 rharper-b1 systemd-networkd[603]: Sent message type=signal sender=n/a destination=n/a path=/org/freedesktop/network1/link/_31 interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=6 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Apr 18 18:31:06.051842 rharper-b1 systemd-networkd[603]: Sent message type=signal sender=n/a destination=n/a path=/org/freedesktop/network1/link/_32 interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=7 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Apr 18 18:31:06.051854 rharper-b1 systemd-networkd[603]: Sent message type=signal sender=n/a destination=n/a path=/org/freedesktop/network1/link/_32 interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=8 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Apr 18 18:31:06.051868 rharper-b1 systemd-networkd[603]: Sent message type=signal sender=n/a destination=n/a path=/org/freedesktop/network1/link/_32 interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=9 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Apr 18 18:31:06.051881 rharper-b1 systemd-networkd[603]: Sent message type=signal sender=n/a destination=n/a path=/org/freedesktop/network1 interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=10 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Apr 18 18:31:06.051893 rharper-b1 systemd-networkd[603]: Sent message type=signal sender=n/a destination=n/a path=/org/freedesktop/network1/link/_32 interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=11 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Apr 18 18:31:06.051905 rharper-b1 systemd-networkd[603]: Sent message type=signal sender=n/a destination=n/a path=/org/freedesktop/network1 interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=12 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Apr 18 18:31:06.051916 rharper-b1 systemd-networkd[603]: Sent message type=signal sender=n/a destination=n/a path=/org/freedesktop/network1/link/_32 interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=13 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Apr 18 18:31:06.053073 rharper-b1 systemd-networkd[603]: Got message type=method_return sender=org.freedesktop.DBus destination=:1.2 path=n/a interface=n/a member=n/a cookie=1 reply_cookie=1 signature=s error-name=n/a error-message=n/a
Apr 18 18:31:06.053092 rharper-b1 systemd-networkd[603]: Bus n/a: changing state HELLO → RUNNING
Apr 18 18:31:06.053151 rharper-b1 systemd-networkd[603]: Got message type=signal sender=org.freedesktop.DBus.Local destination=n/a path=/org/freedesktop/DBus/Local interface=org.freedesktop.DBus.Local member=Connected cookie=4294967295 reply_cookie=0 signature=n/a error-name=n/a error-message=n/a
Apr 18 18:31:06.053163 rharper-b1 systemd-networkd[603]: Setting transient hostname: 'rharper-b1'
Apr 18 18:31:06.053186 rharper-b1 systemd-networkd[603]: Sent message type=method_call sender=n/a destination=org.freedesktop.hostname1 path=/org/freedesktop/hostname1 interface=org.freedesktop.hostname1 member=SetHostname cookie=14 reply_cookie=0 signature=sb error-name=n/a error-message=n/a
Apr 18 18:31:06.053246 rharper-b1 systemd-networkd[603]: Got message type=signal sender=org.freedesktop.DBus destination=:1.2 path=/org/freedesktop/DBus interface=org.freedesktop.DBus member=NameAcquired cookie=2 reply_cookie=0 signature=s error-name=n/a error-message=n/a
Apr 18 18:31:06.053364 rharper-b1 systemd-networkd[603]: Got message type=signal sender=org.freedesktop.DBus destination=:1.2 path=/org/freedesktop/DBus interface=org.freedesktop.DBus member=NameAcquired cookie=3 reply_cookie=0 signature=s error-name=n/a error-message=n/a
Apr 18 18:31:06.053409 rharper-b1 systemd-networkd[603]: Got message type=method_return sender=org.freedesktop.DBus destination=:1.2 path=n/a interface=n/a member=n/a cookie=4 reply_cookie=2 signature=u error-name=n/a error-message=n/a
Apr 18 18:31:06.053419 rharper-b1 systemd-networkd[603]: Successfully acquired requested service name.
Apr 18 18:31:06.053502 rharper-b1 systemd-networkd[603]: Got message type=method_return sender=org.freedesktop.DBus destination=:1.2 path=n/a interface=n/a member=n/a cookie=5 reply_cookie=3 signature=n/a error-name=n/a error-message=n/a
Apr 18 18:31:06.053511 rharper-b1 systemd-networkd[603]: Match type='signal',sender='org.freedesktop.login1',path='/org/freedesktop/login1',interface='org.freedesktop.login1.Manager',member='PrepareForSleep' successfully installed.
Apr 18 18:31:06.229740 rharper-b1 systemd-networkd[603]: Got message type=method_return sender=:1.6 destination=:1.2 path=n/a interface=n/a member=n/a cookie=3 reply_cookie=14 signature=n/a error-name=n/a error-message=n/a
Apr 18 18:31:21.550612 rharper-b1 systemd-networkd[603]: NDISC: Sent Router Solicitation, next solicitation in 33s
Apr 18 18:31:54.706283 rharper-b1 systemd-networkd[603]: NDISC: Sent Router Solicitation, next solicitation in 1min 5s
Apr 18 18:33:00.232685 rharper-b1 systemd-networkd[603]: NDISC: Sent Router Solicitation, next solicitation in 2min 15s
Apr 18 18:35:15.436376 rharper-b1 systemd-networkd[603]: NDISC: Sent Router Solicitation, next solicitation in 4min 32s
ProblemType: Bug
DistroRelease: Ubuntu 18.04
Package: systemd 237-3ubuntu8
ProcVersionSignature: User Name 4.15.0-15.16-generic 4.15.15
Uname: Linux 4.15.0-15-generic x86_64
ApportVersion: 2.20.9-0ubuntu4
Architecture: amd64
Date: Wed Apr 18 18:25:53 2018
Lsusb: Bus 001 Device 001: ID 1d6b:0001 Linux Foundation 1.1 root hub
MachineType: QEMU Standard PC (i440FX + PIIX, 1996)
ProcEnviron:
TERM=xterm
PATH=(custom, no user)
XDG_RUNTIME_DIR=<set>
LANG=C.UTF-8
SHELL=/bin/bash
ProcKernelCmdLine: BOOT_IMAGE=/boot/vmlinuz-4.15.0-15-generic root=LABEL=cloudimg-rootfs ro console=tty1 console=ttyS0
SourcePackage: systemd
UpgradeStatus: No upgrade log present (probably fresh install)
dmi.bios.date: 04/01/2014
dmi.bios.vendor: SeaBIOS
dmi.bios.version: 1.10.2-1ubuntu1
dmi.chassis.type: 1
dmi.chassis.vendor: QEMU
dmi.chassis.version: pc-i440fx-bionic
dmi.modalias: dmi:bvnSeaBIOS:bvr1.10.2-1ubuntu1:bd04/01/2014:svnQEMU:pnStandardPC(i440FX+PIIX,1996):pvrpc-i440fx-bionic:cvnQEMU:ct1:cvrpc-i440fx-bionic:
dmi.product.name: Standard PC (i440FX + PIIX, 1996)
dmi.product.version: pc-i440fx-bionic
dmi.sys.vendor: QEMU |
|
| 2018-04-20 03:15:08 |
Dimitri John Ledkov |
description |
[Impact]
* On ipv6 less hosts, boot stalls for 10s
* This is due to implicit RA being on, and wait-online awaiting for RA to timeout
* Expectation is, that since explicit request for RA was not done, it should not block network-online.target, whilst all other aspects of network-online.target should be honored.
[Test Case]
* lxc network set lxdbr0 ipv6.address none
* lxc launch ubuntu-daily:bionic lp1765173
* sleep 20 && lxc exec lp1765173 systemd-analyze blame | head
Bad result is:
12.157s systemd-networkd-wait-online.service
Good result is:
less than 3s
[Regression Potential]
* If explicit IPv6 dhcp/ra was enabled in .network file, the boot will be blocked awaiting RA response
* Only kernel implicit RA configuration will now become "async"
* This is inline with behaviour of xenial systems
[Other Info]
* Original bug report
1.
$ lsb_release -rd
Description: Ubuntu Bionic Beaver (development branch)
Release: 18.04
2.
$ apt-cache policy systemd
systemd:
Installed: 237-3ubuntu8
Candidate: 237-3ubuntu8
Version table:
*** 237-3ubuntu8 500
500 http://archive.ubuntu.com/ubuntu bionic/main amd64 Packages
100 /var/lib/dpkg/status
3. systemd-networkd-wait-online doesn't block for 10 seconds waiting on an IPV6 Router Advertisement
4. systemd-networkd sends at least two RA solicitation packets waiting for a response before setting the link to configured. This blocks the boot for every Ubuntu system where it does not have a IPV6 router responding to solicitations. THis includes bionic containers, cloud instances, vms and physical machines.
--
We can see that we're spending 13 seconds waiting for networkd to say the network is up.
% systemd-analyze blame
13.326s systemd-networkd-wait-online.service
999ms cloud-init-local.service
954ms cloud-init.service
887ms cloud-config.service
749ms dev-vda1.device
666ms cloud-final.service
248ms keyboard-setup.service
175ms systemd-udev-trigger.service
171ms lxd-containers.service
165ms snapd.service
154ms apparmor.service
147ms ssh.service
144ms systemd-timesyncd.service
133ms grub-common.service
130ms systemd-journald.service
130ms accounts-daemon.service
99ms systemd-modules-load.service
98ms systemd-resolved.service
94ms apport.service
92ms rsyslog.service
88ms systemd-logind.service
80ms lvm2-monitor.service
75ms iscsid.service
64ms ebtables.service
62ms user@1000.service
54ms dev-mqueue.mount
53ms ufw.service
52ms systemd-remount-fs.service
52ms kmod-static-nodes.service
34ms systemd-journal-flush.service
34ms polkit.service
32ms systemd-tmpfiles-setup-dev.service
27ms systemd-udevd.service
26ms systemd-networkd.service
26ms systemd-sysctl.service
25ms systemd-tmpfiles-setup.service
21ms dev-hugepages.mount
17ms sys-kernel-debug.mount
16ms console-setup.service
15ms plymouth-read-write.service
15ms snapd.socket
15ms plymouth-quit.service
14ms systemd-update-utmp.service
10ms systemd-user-sessions.service
9ms boot-efi.mount
8ms sys-fs-fuse-connections.mount
8ms systemd-update-utmp-runlevel.service
8ms lxd.socket
7ms blk-availability.service
5ms systemd-random-seed.service
3ms setvtrgb.service
3ms plymouth-quit-wait.service
3ms sys-kernel-config.mount
Here we can see that we start networking at 18:30:51.69, and then IPv6 NDISC runs for 10 seconds
and then the link is configured at 18:31:05. *AND* we see NDISC stays around and continues to see if it gets a RA packet.
$ journalctl -o short-precise -u systemd-networkd.service | egrep "(Starting Network|Discovering IPv6 routers|NDISC|Configured)"
Apr 18 18:30:51.691532 rharper-b1 systemd[1]: Starting Network Service...
Apr 18 18:30:53.031041 rharper-b1 systemd-networkd[603]: ens3: Discovering IPv6 routers
Apr 18 18:30:53.031306 rharper-b1 systemd-networkd[603]: NDISC: Started IPv6 Router Solicitation client
Apr 18 18:30:53.031612 rharper-b1 systemd-networkd[603]: NDISC: Sent Router Solicitation, next solicitation in 4s
Apr 18 18:30:57.092282 rharper-b1 systemd-networkd[603]: NDISC: Sent Router Solicitation, next solicitation in 8s
Apr 18 18:31:05.040895 rharper-b1 systemd-networkd[603]: NDISC: No RA received before link confirmation timeout
Apr 18 18:31:05.040932 rharper-b1 systemd-networkd[603]: NDISC: Invoking callback for 't'.
Apr 18 18:31:05.041099 rharper-b1 systemd-networkd[603]: ens3: Configured
Apr 18 18:31:05.484261 rharper-b1 systemd-networkd[603]: NDISC: Sent Router Solicitation, next solicitation in 16s
Apr 18 18:31:21.550612 rharper-b1 systemd-networkd[603]: NDISC: Sent Router Solicitation, next solicitation in 33s
Apr 18 18:31:54.706283 rharper-b1 systemd-networkd[603]: NDISC: Sent Router Solicitation, next solicitation in 1min 5s
Apr 18 18:33:00.232685 rharper-b1 systemd-networkd[603]: NDISC: Sent Router Solicitation, next solicitation in 2min 15s
Apr 18 18:35:15.436376 rharper-b1 systemd-networkd[603]: NDISC: Sent Router Solicitation, next solicitation in 4min 32s
Apr 18 18:39:48.111413 rharper-b1 systemd-networkd[603]: NDISC: Sent Router Solicitation, next solicitation in 9min 16s
networkd runs ndisc if your host is configured with ipv6 forwarding disabled and accept_ra enabled.
% sysctl net.ipv6.conf.all.forwarding
net.ipv6.conf.all.forwarding = 0
% sysctl net.ipv6.conf.all.accept_ra
net.ipv6.conf.all.accept_ra = 1
So ndisc path is expected per systemd code. We should be able to disable the NDISC link timeout; especially since NDISC stays around to process RA packets later on anyhow. Nothing is gained by blocking boot waiting for an RA packet. This is also a change in behavior on previous LTS, Xenial where the RA handling is done in the kernel rather than netowkrd.
Full debug output of systemd-networkd during this boot.
% journalctl -o short-precise -u systemd-networkd.service
-- Logs begin at Wed 2018-04-18 18:30:19 UTC, end at Wed 2018-04-18 18:35:15 UTC. --
Apr 18 18:30:34.371090 rharper-b1 systemd[1]: Stopping Network Service...
Apr 18 18:30:34.399603 rharper-b1 systemd[1]: Stopped Network Service.
-- Reboot --
Apr 18 18:30:51.691532 rharper-b1 systemd[1]: Starting Network Service...
Apr 18 18:30:51.714593 rharper-b1 systemd-networkd[603]: Bus n/a: changing state UNSET → OPENING
Apr 18 18:30:51.714736 rharper-b1 systemd-networkd[603]: Added inotify watch for /run on bus n/a: 2
Apr 18 18:30:51.714754 rharper-b1 systemd-networkd[603]: Added inotify watch for /run/dbus on bus n/a: -1
Apr 18 18:30:51.714795 rharper-b1 systemd-networkd[603]: Bus n/a: changing state OPENING → WATCH_BIND
Apr 18 18:30:51.715122 rharper-b1 systemd-networkd[603]: Failed to open configuration file '/etc/systemd/networkd.conf': No such file or directory
Apr 18 18:30:51.715134 rharper-b1 systemd-networkd[603]: timestamp of '/etc/systemd/network' changed
Apr 18 18:30:51.715144 rharper-b1 systemd-networkd[603]: timestamp of '/run/systemd/network' changed
Apr 18 18:30:51.715334 rharper-b1 systemd-networkd[603]: Ignoring /run/systemd/network/10-netplan-ens3.network, because it's not a regular file with suffix .netdev.
Apr 18 18:30:51.715342 rharper-b1 systemd-networkd[603]: Ignoring /run/systemd/network/10-netplan-ens3.link, because it's not a regular file with suffix .netdev.
Apr 18 18:30:51.715375 rharper-b1 systemd-networkd[603]: Ignoring /lib/systemd/network/80-container-vz.network, because it's not a regular file with suffix .netdev.
Apr 18 18:30:51.715382 rharper-b1 systemd-networkd[603]: Ignoring /lib/systemd/network/99-default.link, because it's not a regular file with suffix .netdev.
Apr 18 18:30:51.715389 rharper-b1 systemd-networkd[603]: Ignoring /lib/systemd/network/80-container-host0.network, because it's not a regular file with suffix .netdev.
Apr 18 18:30:51.715397 rharper-b1 systemd-networkd[603]: Ignoring /lib/systemd/network/80-container-ve.network, because it's not a regular file with suffix .netdev.
Apr 18 18:30:51.715573 rharper-b1 systemd-networkd[603]: Ignoring /run/systemd/network/10-netplan-ens3.link, because it's not a regular file with suffix .network.
Apr 18 18:30:51.715603 rharper-b1 systemd-networkd[603]: Ignoring /lib/systemd/network/99-default.link, because it's not a regular file with suffix .network.
Apr 18 18:30:51.717227 rharper-b1 systemd-networkd[603]: ens3: Flags change: +MULTICAST +BROADCAST
Apr 18 18:30:51.717240 rharper-b1 systemd-networkd[603]: ens3: Link 2 added
Apr 18 18:30:51.717552 rharper-b1 systemd-networkd[603]: ens3: udev initialized link
Apr 18 18:30:51.717585 rharper-b1 systemd-networkd[603]: ens3: Saved original MTU: 1500
Apr 18 18:30:51.717597 rharper-b1 systemd-networkd[603]: lo: Flags change: +LOOPBACK +UP +LOWER_UP +RUNNING
Apr 18 18:30:51.717628 rharper-b1 systemd-networkd[603]: lo: Link 1 added
Apr 18 18:30:51.717869 rharper-b1 systemd-networkd[603]: lo: udev initialized link
Apr 18 18:30:51.717900 rharper-b1 systemd-networkd[603]: lo: Saved original MTU: 0
Apr 18 18:30:51.717987 rharper-b1 systemd-networkd[603]: lo: Adding address: ::1/128 (valid forever)
Apr 18 18:30:51.717998 rharper-b1 systemd-networkd[603]: lo: Adding address: 127.0.0.1/8 (valid forever)
Apr 18 18:30:51.718115 rharper-b1 systemd-networkd[603]: rtnl: received address with invalid family 129, ignoring
Apr 18 18:30:51.718293 rharper-b1 systemd-networkd[603]: Enumeration completed
Apr 18 18:30:51.718444 rharper-b1 systemd-networkd[603]: ens3: Link state is up-to-date
Apr 18 18:30:51.718493 rharper-b1 systemd[1]: Started Network Service.
Apr 18 18:30:51.720311 rharper-b1 systemd-networkd[603]: ens3: found matching network '/run/systemd/network/10-netplan-ens3.network'
Apr 18 18:30:51.720850 rharper-b1 systemd-networkd[603]: lo: Link is not managed by us
Apr 18 18:30:51.720915 rharper-b1 systemd-networkd[603]: ens3: Bringing link up
Apr 18 18:30:51.720974 rharper-b1 systemd-networkd[603]: ens3: IPv6 successfully enabled
Apr 18 18:30:51.721574 rharper-b1 systemd-networkd[603]: lo: Link state is up-to-date
Apr 18 18:30:51.721778 rharper-b1 systemd-networkd[603]: Virtualization QEMU found in DMI (/sys/class/dmi/id/sys_vendor)
Apr 18 18:30:51.721792 rharper-b1 systemd-networkd[603]: Virtualization found, CPUID=KVMKVMKVM
Apr 18 18:30:51.721799 rharper-b1 systemd-networkd[603]: Found VM virtualization kvm
Apr 18 18:30:51.721808 rharper-b1 systemd-networkd[603]: lo: Unmanaged
Apr 18 18:30:51.722017 rharper-b1 systemd-networkd[603]: ens3: Flags change: +UP +LOWER_UP +RUNNING
Apr 18 18:30:51.727823 rharper-b1 systemd-networkd[603]: LLDP: Started LLDP client
Apr 18 18:30:51.727831 rharper-b1 systemd-networkd[603]: ens3: Started LLDP.
Apr 18 18:30:51.727838 rharper-b1 systemd-networkd[603]: ens3: Gained carrier
Apr 18 18:30:51.727852 rharper-b1 systemd-networkd[603]: ens3: Acquiring DHCPv4 lease
Apr 18 18:30:51.727965 rharper-b1 systemd-networkd[603]: DHCP CLIENT (0x9bbb16d3): STARTED on ifindex 2
Apr 18 18:30:51.728263 rharper-b1 systemd-networkd[603]: DHCP CLIENT (0x9bbb16d3): DISCOVER
Apr 18 18:30:51.729279 rharper-b1 systemd-networkd[603]: DHCP CLIENT (0x9bbb16d3): OFFER
Apr 18 18:30:51.729361 rharper-b1 systemd-networkd[603]: DHCP CLIENT (0x9bbb16d3): REQUEST (requesting)
Apr 18 18:30:51.730084 rharper-b1 systemd-networkd[603]: DHCP CLIENT (0x9bbb16d3): ACK
Apr 18 18:30:51.730212 rharper-b1 systemd-networkd[603]: DHCP CLIENT (0x9bbb16d3): lease expires in 59min 58s
Apr 18 18:30:51.730221 rharper-b1 systemd-networkd[603]: DHCP CLIENT (0x9bbb16d3): T2 expires in 52min 27s
Apr 18 18:30:51.730229 rharper-b1 systemd-networkd[603]: DHCP CLIENT (0x9bbb16d3): T1 expires in 29min 57s
Apr 18 18:30:51.730314 rharper-b1 systemd-networkd[603]: ens3: DHCPv4 address 192.168.122.140/24 via 192.168.122.1
Apr 18 18:30:51.730375 rharper-b1 systemd-networkd[603]: Setting transient hostname: 'rharper-b1'
Apr 18 18:30:51.730385 rharper-b1 systemd-networkd[603]: Not connected to system bus, not setting hostname.
Apr 18 18:30:51.730676 rharper-b1 systemd-networkd[603]: ens3: Updating address: 192.168.122.140/24 (valid for 1h)
Apr 18 18:30:51.731002 rharper-b1 systemd-networkd[603]: ens3: DHCP error: could not get routes: No data available
Apr 18 18:30:53.030808 rharper-b1 systemd-networkd[603]: ens3: Adding address: fe80::5054:ff:feba:2b98/64 (valid forever)
Apr 18 18:30:53.030877 rharper-b1 systemd-networkd[603]: ens3: Gained IPv6LL
Apr 18 18:30:53.031041 rharper-b1 systemd-networkd[603]: ens3: Discovering IPv6 routers
Apr 18 18:30:53.031306 rharper-b1 systemd-networkd[603]: NDISC: Started IPv6 Router Solicitation client
Apr 18 18:30:53.031612 rharper-b1 systemd-networkd[603]: NDISC: Sent Router Solicitation, next solicitation in 4s
Apr 18 18:30:57.092282 rharper-b1 systemd-networkd[603]: NDISC: Sent Router Solicitation, next solicitation in 8s
Apr 18 18:31:05.040895 rharper-b1 systemd-networkd[603]: NDISC: No RA received before link confirmation timeout
Apr 18 18:31:05.040932 rharper-b1 systemd-networkd[603]: NDISC: Invoking callback for 't'.
Apr 18 18:31:05.041099 rharper-b1 systemd-networkd[603]: ens3: Configured
Apr 18 18:31:05.484261 rharper-b1 systemd-networkd[603]: NDISC: Sent Router Solicitation, next solicitation in 16s
Apr 18 18:31:05.495751 rharper-b1 systemd-networkd[603]: Got inotify event on bus n/a.
Apr 18 18:31:05.495842 rharper-b1 systemd-networkd[603]: Added inotify watch for /run on bus n/a: 2
Apr 18 18:31:05.495870 rharper-b1 systemd-networkd[603]: Added inotify watch for /run/dbus on bus n/a: -1
Apr 18 18:31:05.928832 rharper-b1 systemd-networkd[603]: Got inotify event on bus n/a.
Apr 18 18:31:05.928914 rharper-b1 systemd-networkd[603]: Added inotify watch for /run on bus n/a: 2
Apr 18 18:31:05.928935 rharper-b1 systemd-networkd[603]: Added inotify watch for /run/dbus on bus n/a: -1
Apr 18 18:31:06.014785 rharper-b1 systemd-networkd[603]: Got inotify event on bus n/a.
Apr 18 18:31:06.015036 rharper-b1 systemd-networkd[603]: Added inotify watch for /run on bus n/a: 2
Apr 18 18:31:06.017290 rharper-b1 systemd-networkd[603]: Added inotify watch for /run/dbus on bus n/a: -1
Apr 18 18:31:06.017532 rharper-b1 systemd-networkd[603]: Got inotify event on bus n/a.
Apr 18 18:31:06.017581 rharper-b1 systemd-networkd[603]: Added inotify watch for /run on bus n/a: 2
Apr 18 18:31:06.017598 rharper-b1 systemd-networkd[603]: Added inotify watch for /run/dbus on bus n/a: -1
Apr 18 18:31:06.027908 rharper-b1 systemd-networkd[603]: Got inotify event on bus n/a.
Apr 18 18:31:06.028491 rharper-b1 systemd-networkd[603]: Bus n/a: changing state WATCH_BIND → AUTHENTICATING
Apr 18 18:31:06.051721 rharper-b1 systemd-networkd[603]: Bus n/a: changing state AUTHENTICATING → HELLO
Apr 18 18:31:06.051767 rharper-b1 systemd-networkd[603]: Sent message type=method_call sender=n/a destination=org.freedesktop.DBus path=/org/freedesktop/DBus interface=org.freedesktop.DBus member=Hello cookie=1 reply_cookie=0 signature=n/a error-name=n/a error-message=n/a
Apr 18 18:31:06.051782 rharper-b1 systemd-networkd[603]: Sent message type=method_call sender=n/a destination=org.freedesktop.DBus path=/org/freedesktop/DBus interface=org.freedesktop.DBus member=RequestName cookie=2 reply_cookie=0 signature=su error-name=n/a error-message=n/a
Apr 18 18:31:06.051794 rharper-b1 systemd-networkd[603]: Sent message type=method_call sender=n/a destination=org.freedesktop.DBus path=/org/freedesktop/DBus interface=org.freedesktop.DBus member=AddMatch cookie=3 reply_cookie=0 signature=s error-name=n/a error-message=n/a
Apr 18 18:31:06.051807 rharper-b1 systemd-networkd[603]: Sent message type=signal sender=n/a destination=n/a path=/org/freedesktop/network1/link/_31 interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=4 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Apr 18 18:31:06.051819 rharper-b1 systemd-networkd[603]: Sent message type=signal sender=n/a destination=n/a path=/org/freedesktop/network1/link/_32 interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=5 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Apr 18 18:31:06.051831 rharper-b1 systemd-networkd[603]: Sent message type=signal sender=n/a destination=n/a path=/org/freedesktop/network1/link/_31 interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=6 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Apr 18 18:31:06.051842 rharper-b1 systemd-networkd[603]: Sent message type=signal sender=n/a destination=n/a path=/org/freedesktop/network1/link/_32 interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=7 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Apr 18 18:31:06.051854 rharper-b1 systemd-networkd[603]: Sent message type=signal sender=n/a destination=n/a path=/org/freedesktop/network1/link/_32 interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=8 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Apr 18 18:31:06.051868 rharper-b1 systemd-networkd[603]: Sent message type=signal sender=n/a destination=n/a path=/org/freedesktop/network1/link/_32 interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=9 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Apr 18 18:31:06.051881 rharper-b1 systemd-networkd[603]: Sent message type=signal sender=n/a destination=n/a path=/org/freedesktop/network1 interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=10 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Apr 18 18:31:06.051893 rharper-b1 systemd-networkd[603]: Sent message type=signal sender=n/a destination=n/a path=/org/freedesktop/network1/link/_32 interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=11 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Apr 18 18:31:06.051905 rharper-b1 systemd-networkd[603]: Sent message type=signal sender=n/a destination=n/a path=/org/freedesktop/network1 interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=12 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Apr 18 18:31:06.051916 rharper-b1 systemd-networkd[603]: Sent message type=signal sender=n/a destination=n/a path=/org/freedesktop/network1/link/_32 interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=13 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Apr 18 18:31:06.053073 rharper-b1 systemd-networkd[603]: Got message type=method_return sender=org.freedesktop.DBus destination=:1.2 path=n/a interface=n/a member=n/a cookie=1 reply_cookie=1 signature=s error-name=n/a error-message=n/a
Apr 18 18:31:06.053092 rharper-b1 systemd-networkd[603]: Bus n/a: changing state HELLO → RUNNING
Apr 18 18:31:06.053151 rharper-b1 systemd-networkd[603]: Got message type=signal sender=org.freedesktop.DBus.Local destination=n/a path=/org/freedesktop/DBus/Local interface=org.freedesktop.DBus.Local member=Connected cookie=4294967295 reply_cookie=0 signature=n/a error-name=n/a error-message=n/a
Apr 18 18:31:06.053163 rharper-b1 systemd-networkd[603]: Setting transient hostname: 'rharper-b1'
Apr 18 18:31:06.053186 rharper-b1 systemd-networkd[603]: Sent message type=method_call sender=n/a destination=org.freedesktop.hostname1 path=/org/freedesktop/hostname1 interface=org.freedesktop.hostname1 member=SetHostname cookie=14 reply_cookie=0 signature=sb error-name=n/a error-message=n/a
Apr 18 18:31:06.053246 rharper-b1 systemd-networkd[603]: Got message type=signal sender=org.freedesktop.DBus destination=:1.2 path=/org/freedesktop/DBus interface=org.freedesktop.DBus member=NameAcquired cookie=2 reply_cookie=0 signature=s error-name=n/a error-message=n/a
Apr 18 18:31:06.053364 rharper-b1 systemd-networkd[603]: Got message type=signal sender=org.freedesktop.DBus destination=:1.2 path=/org/freedesktop/DBus interface=org.freedesktop.DBus member=NameAcquired cookie=3 reply_cookie=0 signature=s error-name=n/a error-message=n/a
Apr 18 18:31:06.053409 rharper-b1 systemd-networkd[603]: Got message type=method_return sender=org.freedesktop.DBus destination=:1.2 path=n/a interface=n/a member=n/a cookie=4 reply_cookie=2 signature=u error-name=n/a error-message=n/a
Apr 18 18:31:06.053419 rharper-b1 systemd-networkd[603]: Successfully acquired requested service name.
Apr 18 18:31:06.053502 rharper-b1 systemd-networkd[603]: Got message type=method_return sender=org.freedesktop.DBus destination=:1.2 path=n/a interface=n/a member=n/a cookie=5 reply_cookie=3 signature=n/a error-name=n/a error-message=n/a
Apr 18 18:31:06.053511 rharper-b1 systemd-networkd[603]: Match type='signal',sender='org.freedesktop.login1',path='/org/freedesktop/login1',interface='org.freedesktop.login1.Manager',member='PrepareForSleep' successfully installed.
Apr 18 18:31:06.229740 rharper-b1 systemd-networkd[603]: Got message type=method_return sender=:1.6 destination=:1.2 path=n/a interface=n/a member=n/a cookie=3 reply_cookie=14 signature=n/a error-name=n/a error-message=n/a
Apr 18 18:31:21.550612 rharper-b1 systemd-networkd[603]: NDISC: Sent Router Solicitation, next solicitation in 33s
Apr 18 18:31:54.706283 rharper-b1 systemd-networkd[603]: NDISC: Sent Router Solicitation, next solicitation in 1min 5s
Apr 18 18:33:00.232685 rharper-b1 systemd-networkd[603]: NDISC: Sent Router Solicitation, next solicitation in 2min 15s
Apr 18 18:35:15.436376 rharper-b1 systemd-networkd[603]: NDISC: Sent Router Solicitation, next solicitation in 4min 32s
ProblemType: Bug
DistroRelease: Ubuntu 18.04
Package: systemd 237-3ubuntu8
ProcVersionSignature: User Name 4.15.0-15.16-generic 4.15.15
Uname: Linux 4.15.0-15-generic x86_64
ApportVersion: 2.20.9-0ubuntu4
Architecture: amd64
Date: Wed Apr 18 18:25:53 2018
Lsusb: Bus 001 Device 001: ID 1d6b:0001 Linux Foundation 1.1 root hub
MachineType: QEMU Standard PC (i440FX + PIIX, 1996)
ProcEnviron:
TERM=xterm
PATH=(custom, no user)
XDG_RUNTIME_DIR=<set>
LANG=C.UTF-8
SHELL=/bin/bash
ProcKernelCmdLine: BOOT_IMAGE=/boot/vmlinuz-4.15.0-15-generic root=LABEL=cloudimg-rootfs ro console=tty1 console=ttyS0
SourcePackage: systemd
UpgradeStatus: No upgrade log present (probably fresh install)
dmi.bios.date: 04/01/2014
dmi.bios.vendor: SeaBIOS
dmi.bios.version: 1.10.2-1ubuntu1
dmi.chassis.type: 1
dmi.chassis.vendor: QEMU
dmi.chassis.version: pc-i440fx-bionic
dmi.modalias: dmi:bvnSeaBIOS:bvr1.10.2-1ubuntu1:bd04/01/2014:svnQEMU:pnStandardPC(i440FX+PIIX,1996):pvrpc-i440fx-bionic:cvnQEMU:ct1:cvrpc-i440fx-bionic:
dmi.product.name: Standard PC (i440FX + PIIX, 1996)
dmi.product.version: pc-i440fx-bionic
dmi.sys.vendor: QEMU |
[Impact]
* On ipv6 less hosts, boot stalls for 10s
* This is due to implicit RA being on, and wait-online awaiting for RA to timeout
* Expectation is, that since explicit request for RA was not done, it should not block network-online.target, whilst all other aspects of network-online.target should be honored.
[Test Case]
* lxc network set lxdbr0 ipv6.address none
* lxc launch ubuntu-daily:bionic lp1765173
* sleep 20 && lxc exec lp1765173 systemd-analyze blame | head
Bad result is:
12.157s systemd-networkd-wait-online.service
Good result is:
739ms systemd-networkd-wait-online.service
[Regression Potential]
* If explicit IPv6 dhcp/ra was enabled in .network file, the boot will be blocked awaiting RA response
* Only kernel implicit RA configuration will now become "async"
* This is inline with behaviour of xenial systems
[Other Info]
* Original bug report
1.
$ lsb_release -rd
Description: Ubuntu Bionic Beaver (development branch)
Release: 18.04
2.
$ apt-cache policy systemd
systemd:
Installed: 237-3ubuntu8
Candidate: 237-3ubuntu8
Version table:
*** 237-3ubuntu8 500
500 http://archive.ubuntu.com/ubuntu bionic/main amd64 Packages
100 /var/lib/dpkg/status
3. systemd-networkd-wait-online doesn't block for 10 seconds waiting on an IPV6 Router Advertisement
4. systemd-networkd sends at least two RA solicitation packets waiting for a response before setting the link to configured. This blocks the boot for every Ubuntu system where it does not have a IPV6 router responding to solicitations. THis includes bionic containers, cloud instances, vms and physical machines.
--
We can see that we're spending 13 seconds waiting for networkd to say the network is up.
% systemd-analyze blame
13.326s systemd-networkd-wait-online.service
999ms cloud-init-local.service
954ms cloud-init.service
887ms cloud-config.service
749ms dev-vda1.device
666ms cloud-final.service
248ms keyboard-setup.service
175ms systemd-udev-trigger.service
171ms lxd-containers.service
165ms snapd.service
154ms apparmor.service
147ms ssh.service
144ms systemd-timesyncd.service
133ms grub-common.service
130ms systemd-journald.service
130ms accounts-daemon.service
99ms systemd-modules-load.service
98ms systemd-resolved.service
94ms apport.service
92ms rsyslog.service
88ms systemd-logind.service
80ms lvm2-monitor.service
75ms iscsid.service
64ms ebtables.service
62ms user@1000.service
54ms dev-mqueue.mount
53ms ufw.service
52ms systemd-remount-fs.service
52ms kmod-static-nodes.service
34ms systemd-journal-flush.service
34ms polkit.service
32ms systemd-tmpfiles-setup-dev.service
27ms systemd-udevd.service
26ms systemd-networkd.service
26ms systemd-sysctl.service
25ms systemd-tmpfiles-setup.service
21ms dev-hugepages.mount
17ms sys-kernel-debug.mount
16ms console-setup.service
15ms plymouth-read-write.service
15ms snapd.socket
15ms plymouth-quit.service
14ms systemd-update-utmp.service
10ms systemd-user-sessions.service
9ms boot-efi.mount
8ms sys-fs-fuse-connections.mount
8ms systemd-update-utmp-runlevel.service
8ms lxd.socket
7ms blk-availability.service
5ms systemd-random-seed.service
3ms setvtrgb.service
3ms plymouth-quit-wait.service
3ms sys-kernel-config.mount
Here we can see that we start networking at 18:30:51.69, and then IPv6 NDISC runs for 10 seconds
and then the link is configured at 18:31:05. *AND* we see NDISC stays around and continues to see if it gets a RA packet.
$ journalctl -o short-precise -u systemd-networkd.service | egrep "(Starting Network|Discovering IPv6 routers|NDISC|Configured)"
Apr 18 18:30:51.691532 rharper-b1 systemd[1]: Starting Network Service...
Apr 18 18:30:53.031041 rharper-b1 systemd-networkd[603]: ens3: Discovering IPv6 routers
Apr 18 18:30:53.031306 rharper-b1 systemd-networkd[603]: NDISC: Started IPv6 Router Solicitation client
Apr 18 18:30:53.031612 rharper-b1 systemd-networkd[603]: NDISC: Sent Router Solicitation, next solicitation in 4s
Apr 18 18:30:57.092282 rharper-b1 systemd-networkd[603]: NDISC: Sent Router Solicitation, next solicitation in 8s
Apr 18 18:31:05.040895 rharper-b1 systemd-networkd[603]: NDISC: No RA received before link confirmation timeout
Apr 18 18:31:05.040932 rharper-b1 systemd-networkd[603]: NDISC: Invoking callback for 't'.
Apr 18 18:31:05.041099 rharper-b1 systemd-networkd[603]: ens3: Configured
Apr 18 18:31:05.484261 rharper-b1 systemd-networkd[603]: NDISC: Sent Router Solicitation, next solicitation in 16s
Apr 18 18:31:21.550612 rharper-b1 systemd-networkd[603]: NDISC: Sent Router Solicitation, next solicitation in 33s
Apr 18 18:31:54.706283 rharper-b1 systemd-networkd[603]: NDISC: Sent Router Solicitation, next solicitation in 1min 5s
Apr 18 18:33:00.232685 rharper-b1 systemd-networkd[603]: NDISC: Sent Router Solicitation, next solicitation in 2min 15s
Apr 18 18:35:15.436376 rharper-b1 systemd-networkd[603]: NDISC: Sent Router Solicitation, next solicitation in 4min 32s
Apr 18 18:39:48.111413 rharper-b1 systemd-networkd[603]: NDISC: Sent Router Solicitation, next solicitation in 9min 16s
networkd runs ndisc if your host is configured with ipv6 forwarding disabled and accept_ra enabled.
% sysctl net.ipv6.conf.all.forwarding
net.ipv6.conf.all.forwarding = 0
% sysctl net.ipv6.conf.all.accept_ra
net.ipv6.conf.all.accept_ra = 1
So ndisc path is expected per systemd code. We should be able to disable the NDISC link timeout; especially since NDISC stays around to process RA packets later on anyhow. Nothing is gained by blocking boot waiting for an RA packet. This is also a change in behavior on previous LTS, Xenial where the RA handling is done in the kernel rather than netowkrd.
Full debug output of systemd-networkd during this boot.
% journalctl -o short-precise -u systemd-networkd.service
-- Logs begin at Wed 2018-04-18 18:30:19 UTC, end at Wed 2018-04-18 18:35:15 UTC. --
Apr 18 18:30:34.371090 rharper-b1 systemd[1]: Stopping Network Service...
Apr 18 18:30:34.399603 rharper-b1 systemd[1]: Stopped Network Service.
-- Reboot --
Apr 18 18:30:51.691532 rharper-b1 systemd[1]: Starting Network Service...
Apr 18 18:30:51.714593 rharper-b1 systemd-networkd[603]: Bus n/a: changing state UNSET → OPENING
Apr 18 18:30:51.714736 rharper-b1 systemd-networkd[603]: Added inotify watch for /run on bus n/a: 2
Apr 18 18:30:51.714754 rharper-b1 systemd-networkd[603]: Added inotify watch for /run/dbus on bus n/a: -1
Apr 18 18:30:51.714795 rharper-b1 systemd-networkd[603]: Bus n/a: changing state OPENING → WATCH_BIND
Apr 18 18:30:51.715122 rharper-b1 systemd-networkd[603]: Failed to open configuration file '/etc/systemd/networkd.conf': No such file or directory
Apr 18 18:30:51.715134 rharper-b1 systemd-networkd[603]: timestamp of '/etc/systemd/network' changed
Apr 18 18:30:51.715144 rharper-b1 systemd-networkd[603]: timestamp of '/run/systemd/network' changed
Apr 18 18:30:51.715334 rharper-b1 systemd-networkd[603]: Ignoring /run/systemd/network/10-netplan-ens3.network, because it's not a regular file with suffix .netdev.
Apr 18 18:30:51.715342 rharper-b1 systemd-networkd[603]: Ignoring /run/systemd/network/10-netplan-ens3.link, because it's not a regular file with suffix .netdev.
Apr 18 18:30:51.715375 rharper-b1 systemd-networkd[603]: Ignoring /lib/systemd/network/80-container-vz.network, because it's not a regular file with suffix .netdev.
Apr 18 18:30:51.715382 rharper-b1 systemd-networkd[603]: Ignoring /lib/systemd/network/99-default.link, because it's not a regular file with suffix .netdev.
Apr 18 18:30:51.715389 rharper-b1 systemd-networkd[603]: Ignoring /lib/systemd/network/80-container-host0.network, because it's not a regular file with suffix .netdev.
Apr 18 18:30:51.715397 rharper-b1 systemd-networkd[603]: Ignoring /lib/systemd/network/80-container-ve.network, because it's not a regular file with suffix .netdev.
Apr 18 18:30:51.715573 rharper-b1 systemd-networkd[603]: Ignoring /run/systemd/network/10-netplan-ens3.link, because it's not a regular file with suffix .network.
Apr 18 18:30:51.715603 rharper-b1 systemd-networkd[603]: Ignoring /lib/systemd/network/99-default.link, because it's not a regular file with suffix .network.
Apr 18 18:30:51.717227 rharper-b1 systemd-networkd[603]: ens3: Flags change: +MULTICAST +BROADCAST
Apr 18 18:30:51.717240 rharper-b1 systemd-networkd[603]: ens3: Link 2 added
Apr 18 18:30:51.717552 rharper-b1 systemd-networkd[603]: ens3: udev initialized link
Apr 18 18:30:51.717585 rharper-b1 systemd-networkd[603]: ens3: Saved original MTU: 1500
Apr 18 18:30:51.717597 rharper-b1 systemd-networkd[603]: lo: Flags change: +LOOPBACK +UP +LOWER_UP +RUNNING
Apr 18 18:30:51.717628 rharper-b1 systemd-networkd[603]: lo: Link 1 added
Apr 18 18:30:51.717869 rharper-b1 systemd-networkd[603]: lo: udev initialized link
Apr 18 18:30:51.717900 rharper-b1 systemd-networkd[603]: lo: Saved original MTU: 0
Apr 18 18:30:51.717987 rharper-b1 systemd-networkd[603]: lo: Adding address: ::1/128 (valid forever)
Apr 18 18:30:51.717998 rharper-b1 systemd-networkd[603]: lo: Adding address: 127.0.0.1/8 (valid forever)
Apr 18 18:30:51.718115 rharper-b1 systemd-networkd[603]: rtnl: received address with invalid family 129, ignoring
Apr 18 18:30:51.718293 rharper-b1 systemd-networkd[603]: Enumeration completed
Apr 18 18:30:51.718444 rharper-b1 systemd-networkd[603]: ens3: Link state is up-to-date
Apr 18 18:30:51.718493 rharper-b1 systemd[1]: Started Network Service.
Apr 18 18:30:51.720311 rharper-b1 systemd-networkd[603]: ens3: found matching network '/run/systemd/network/10-netplan-ens3.network'
Apr 18 18:30:51.720850 rharper-b1 systemd-networkd[603]: lo: Link is not managed by us
Apr 18 18:30:51.720915 rharper-b1 systemd-networkd[603]: ens3: Bringing link up
Apr 18 18:30:51.720974 rharper-b1 systemd-networkd[603]: ens3: IPv6 successfully enabled
Apr 18 18:30:51.721574 rharper-b1 systemd-networkd[603]: lo: Link state is up-to-date
Apr 18 18:30:51.721778 rharper-b1 systemd-networkd[603]: Virtualization QEMU found in DMI (/sys/class/dmi/id/sys_vendor)
Apr 18 18:30:51.721792 rharper-b1 systemd-networkd[603]: Virtualization found, CPUID=KVMKVMKVM
Apr 18 18:30:51.721799 rharper-b1 systemd-networkd[603]: Found VM virtualization kvm
Apr 18 18:30:51.721808 rharper-b1 systemd-networkd[603]: lo: Unmanaged
Apr 18 18:30:51.722017 rharper-b1 systemd-networkd[603]: ens3: Flags change: +UP +LOWER_UP +RUNNING
Apr 18 18:30:51.727823 rharper-b1 systemd-networkd[603]: LLDP: Started LLDP client
Apr 18 18:30:51.727831 rharper-b1 systemd-networkd[603]: ens3: Started LLDP.
Apr 18 18:30:51.727838 rharper-b1 systemd-networkd[603]: ens3: Gained carrier
Apr 18 18:30:51.727852 rharper-b1 systemd-networkd[603]: ens3: Acquiring DHCPv4 lease
Apr 18 18:30:51.727965 rharper-b1 systemd-networkd[603]: DHCP CLIENT (0x9bbb16d3): STARTED on ifindex 2
Apr 18 18:30:51.728263 rharper-b1 systemd-networkd[603]: DHCP CLIENT (0x9bbb16d3): DISCOVER
Apr 18 18:30:51.729279 rharper-b1 systemd-networkd[603]: DHCP CLIENT (0x9bbb16d3): OFFER
Apr 18 18:30:51.729361 rharper-b1 systemd-networkd[603]: DHCP CLIENT (0x9bbb16d3): REQUEST (requesting)
Apr 18 18:30:51.730084 rharper-b1 systemd-networkd[603]: DHCP CLIENT (0x9bbb16d3): ACK
Apr 18 18:30:51.730212 rharper-b1 systemd-networkd[603]: DHCP CLIENT (0x9bbb16d3): lease expires in 59min 58s
Apr 18 18:30:51.730221 rharper-b1 systemd-networkd[603]: DHCP CLIENT (0x9bbb16d3): T2 expires in 52min 27s
Apr 18 18:30:51.730229 rharper-b1 systemd-networkd[603]: DHCP CLIENT (0x9bbb16d3): T1 expires in 29min 57s
Apr 18 18:30:51.730314 rharper-b1 systemd-networkd[603]: ens3: DHCPv4 address 192.168.122.140/24 via 192.168.122.1
Apr 18 18:30:51.730375 rharper-b1 systemd-networkd[603]: Setting transient hostname: 'rharper-b1'
Apr 18 18:30:51.730385 rharper-b1 systemd-networkd[603]: Not connected to system bus, not setting hostname.
Apr 18 18:30:51.730676 rharper-b1 systemd-networkd[603]: ens3: Updating address: 192.168.122.140/24 (valid for 1h)
Apr 18 18:30:51.731002 rharper-b1 systemd-networkd[603]: ens3: DHCP error: could not get routes: No data available
Apr 18 18:30:53.030808 rharper-b1 systemd-networkd[603]: ens3: Adding address: fe80::5054:ff:feba:2b98/64 (valid forever)
Apr 18 18:30:53.030877 rharper-b1 systemd-networkd[603]: ens3: Gained IPv6LL
Apr 18 18:30:53.031041 rharper-b1 systemd-networkd[603]: ens3: Discovering IPv6 routers
Apr 18 18:30:53.031306 rharper-b1 systemd-networkd[603]: NDISC: Started IPv6 Router Solicitation client
Apr 18 18:30:53.031612 rharper-b1 systemd-networkd[603]: NDISC: Sent Router Solicitation, next solicitation in 4s
Apr 18 18:30:57.092282 rharper-b1 systemd-networkd[603]: NDISC: Sent Router Solicitation, next solicitation in 8s
Apr 18 18:31:05.040895 rharper-b1 systemd-networkd[603]: NDISC: No RA received before link confirmation timeout
Apr 18 18:31:05.040932 rharper-b1 systemd-networkd[603]: NDISC: Invoking callback for 't'.
Apr 18 18:31:05.041099 rharper-b1 systemd-networkd[603]: ens3: Configured
Apr 18 18:31:05.484261 rharper-b1 systemd-networkd[603]: NDISC: Sent Router Solicitation, next solicitation in 16s
Apr 18 18:31:05.495751 rharper-b1 systemd-networkd[603]: Got inotify event on bus n/a.
Apr 18 18:31:05.495842 rharper-b1 systemd-networkd[603]: Added inotify watch for /run on bus n/a: 2
Apr 18 18:31:05.495870 rharper-b1 systemd-networkd[603]: Added inotify watch for /run/dbus on bus n/a: -1
Apr 18 18:31:05.928832 rharper-b1 systemd-networkd[603]: Got inotify event on bus n/a.
Apr 18 18:31:05.928914 rharper-b1 systemd-networkd[603]: Added inotify watch for /run on bus n/a: 2
Apr 18 18:31:05.928935 rharper-b1 systemd-networkd[603]: Added inotify watch for /run/dbus on bus n/a: -1
Apr 18 18:31:06.014785 rharper-b1 systemd-networkd[603]: Got inotify event on bus n/a.
Apr 18 18:31:06.015036 rharper-b1 systemd-networkd[603]: Added inotify watch for /run on bus n/a: 2
Apr 18 18:31:06.017290 rharper-b1 systemd-networkd[603]: Added inotify watch for /run/dbus on bus n/a: -1
Apr 18 18:31:06.017532 rharper-b1 systemd-networkd[603]: Got inotify event on bus n/a.
Apr 18 18:31:06.017581 rharper-b1 systemd-networkd[603]: Added inotify watch for /run on bus n/a: 2
Apr 18 18:31:06.017598 rharper-b1 systemd-networkd[603]: Added inotify watch for /run/dbus on bus n/a: -1
Apr 18 18:31:06.027908 rharper-b1 systemd-networkd[603]: Got inotify event on bus n/a.
Apr 18 18:31:06.028491 rharper-b1 systemd-networkd[603]: Bus n/a: changing state WATCH_BIND → AUTHENTICATING
Apr 18 18:31:06.051721 rharper-b1 systemd-networkd[603]: Bus n/a: changing state AUTHENTICATING → HELLO
Apr 18 18:31:06.051767 rharper-b1 systemd-networkd[603]: Sent message type=method_call sender=n/a destination=org.freedesktop.DBus path=/org/freedesktop/DBus interface=org.freedesktop.DBus member=Hello cookie=1 reply_cookie=0 signature=n/a error-name=n/a error-message=n/a
Apr 18 18:31:06.051782 rharper-b1 systemd-networkd[603]: Sent message type=method_call sender=n/a destination=org.freedesktop.DBus path=/org/freedesktop/DBus interface=org.freedesktop.DBus member=RequestName cookie=2 reply_cookie=0 signature=su error-name=n/a error-message=n/a
Apr 18 18:31:06.051794 rharper-b1 systemd-networkd[603]: Sent message type=method_call sender=n/a destination=org.freedesktop.DBus path=/org/freedesktop/DBus interface=org.freedesktop.DBus member=AddMatch cookie=3 reply_cookie=0 signature=s error-name=n/a error-message=n/a
Apr 18 18:31:06.051807 rharper-b1 systemd-networkd[603]: Sent message type=signal sender=n/a destination=n/a path=/org/freedesktop/network1/link/_31 interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=4 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Apr 18 18:31:06.051819 rharper-b1 systemd-networkd[603]: Sent message type=signal sender=n/a destination=n/a path=/org/freedesktop/network1/link/_32 interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=5 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Apr 18 18:31:06.051831 rharper-b1 systemd-networkd[603]: Sent message type=signal sender=n/a destination=n/a path=/org/freedesktop/network1/link/_31 interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=6 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Apr 18 18:31:06.051842 rharper-b1 systemd-networkd[603]: Sent message type=signal sender=n/a destination=n/a path=/org/freedesktop/network1/link/_32 interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=7 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Apr 18 18:31:06.051854 rharper-b1 systemd-networkd[603]: Sent message type=signal sender=n/a destination=n/a path=/org/freedesktop/network1/link/_32 interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=8 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Apr 18 18:31:06.051868 rharper-b1 systemd-networkd[603]: Sent message type=signal sender=n/a destination=n/a path=/org/freedesktop/network1/link/_32 interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=9 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Apr 18 18:31:06.051881 rharper-b1 systemd-networkd[603]: Sent message type=signal sender=n/a destination=n/a path=/org/freedesktop/network1 interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=10 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Apr 18 18:31:06.051893 rharper-b1 systemd-networkd[603]: Sent message type=signal sender=n/a destination=n/a path=/org/freedesktop/network1/link/_32 interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=11 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Apr 18 18:31:06.051905 rharper-b1 systemd-networkd[603]: Sent message type=signal sender=n/a destination=n/a path=/org/freedesktop/network1 interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=12 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Apr 18 18:31:06.051916 rharper-b1 systemd-networkd[603]: Sent message type=signal sender=n/a destination=n/a path=/org/freedesktop/network1/link/_32 interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=13 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Apr 18 18:31:06.053073 rharper-b1 systemd-networkd[603]: Got message type=method_return sender=org.freedesktop.DBus destination=:1.2 path=n/a interface=n/a member=n/a cookie=1 reply_cookie=1 signature=s error-name=n/a error-message=n/a
Apr 18 18:31:06.053092 rharper-b1 systemd-networkd[603]: Bus n/a: changing state HELLO → RUNNING
Apr 18 18:31:06.053151 rharper-b1 systemd-networkd[603]: Got message type=signal sender=org.freedesktop.DBus.Local destination=n/a path=/org/freedesktop/DBus/Local interface=org.freedesktop.DBus.Local member=Connected cookie=4294967295 reply_cookie=0 signature=n/a error-name=n/a error-message=n/a
Apr 18 18:31:06.053163 rharper-b1 systemd-networkd[603]: Setting transient hostname: 'rharper-b1'
Apr 18 18:31:06.053186 rharper-b1 systemd-networkd[603]: Sent message type=method_call sender=n/a destination=org.freedesktop.hostname1 path=/org/freedesktop/hostname1 interface=org.freedesktop.hostname1 member=SetHostname cookie=14 reply_cookie=0 signature=sb error-name=n/a error-message=n/a
Apr 18 18:31:06.053246 rharper-b1 systemd-networkd[603]: Got message type=signal sender=org.freedesktop.DBus destination=:1.2 path=/org/freedesktop/DBus interface=org.freedesktop.DBus member=NameAcquired cookie=2 reply_cookie=0 signature=s error-name=n/a error-message=n/a
Apr 18 18:31:06.053364 rharper-b1 systemd-networkd[603]: Got message type=signal sender=org.freedesktop.DBus destination=:1.2 path=/org/freedesktop/DBus interface=org.freedesktop.DBus member=NameAcquired cookie=3 reply_cookie=0 signature=s error-name=n/a error-message=n/a
Apr 18 18:31:06.053409 rharper-b1 systemd-networkd[603]: Got message type=method_return sender=org.freedesktop.DBus destination=:1.2 path=n/a interface=n/a member=n/a cookie=4 reply_cookie=2 signature=u error-name=n/a error-message=n/a
Apr 18 18:31:06.053419 rharper-b1 systemd-networkd[603]: Successfully acquired requested service name.
Apr 18 18:31:06.053502 rharper-b1 systemd-networkd[603]: Got message type=method_return sender=org.freedesktop.DBus destination=:1.2 path=n/a interface=n/a member=n/a cookie=5 reply_cookie=3 signature=n/a error-name=n/a error-message=n/a
Apr 18 18:31:06.053511 rharper-b1 systemd-networkd[603]: Match type='signal',sender='org.freedesktop.login1',path='/org/freedesktop/login1',interface='org.freedesktop.login1.Manager',member='PrepareForSleep' successfully installed.
Apr 18 18:31:06.229740 rharper-b1 systemd-networkd[603]: Got message type=method_return sender=:1.6 destination=:1.2 path=n/a interface=n/a member=n/a cookie=3 reply_cookie=14 signature=n/a error-name=n/a error-message=n/a
Apr 18 18:31:21.550612 rharper-b1 systemd-networkd[603]: NDISC: Sent Router Solicitation, next solicitation in 33s
Apr 18 18:31:54.706283 rharper-b1 systemd-networkd[603]: NDISC: Sent Router Solicitation, next solicitation in 1min 5s
Apr 18 18:33:00.232685 rharper-b1 systemd-networkd[603]: NDISC: Sent Router Solicitation, next solicitation in 2min 15s
Apr 18 18:35:15.436376 rharper-b1 systemd-networkd[603]: NDISC: Sent Router Solicitation, next solicitation in 4min 32s
ProblemType: Bug
DistroRelease: Ubuntu 18.04
Package: systemd 237-3ubuntu8
ProcVersionSignature: User Name 4.15.0-15.16-generic 4.15.15
Uname: Linux 4.15.0-15-generic x86_64
ApportVersion: 2.20.9-0ubuntu4
Architecture: amd64
Date: Wed Apr 18 18:25:53 2018
Lsusb: Bus 001 Device 001: ID 1d6b:0001 Linux Foundation 1.1 root hub
MachineType: QEMU Standard PC (i440FX + PIIX, 1996)
ProcEnviron:
TERM=xterm
PATH=(custom, no user)
XDG_RUNTIME_DIR=<set>
LANG=C.UTF-8
SHELL=/bin/bash
ProcKernelCmdLine: BOOT_IMAGE=/boot/vmlinuz-4.15.0-15-generic root=LABEL=cloudimg-rootfs ro console=tty1 console=ttyS0
SourcePackage: systemd
UpgradeStatus: No upgrade log present (probably fresh install)
dmi.bios.date: 04/01/2014
dmi.bios.vendor: SeaBIOS
dmi.bios.version: 1.10.2-1ubuntu1
dmi.chassis.type: 1
dmi.chassis.vendor: QEMU
dmi.chassis.version: pc-i440fx-bionic
dmi.modalias: dmi:bvnSeaBIOS:bvr1.10.2-1ubuntu1:bd04/01/2014:svnQEMU:pnStandardPC(i440FX+PIIX,1996):pvrpc-i440fx-bionic:cvnQEMU:ct1:cvrpc-i440fx-bionic:
dmi.product.name: Standard PC (i440FX + PIIX, 1996)
dmi.product.version: pc-i440fx-bionic
dmi.sys.vendor: QEMU |
|
| 2018-04-20 03:38:22 |
Dimitri John Ledkov |
systemd (Ubuntu): status |
In Progress |
Fix Committed |
|
| 2018-04-23 13:39:57 |
Launchpad Janitor |
systemd (Ubuntu): status |
Fix Committed |
Fix Released |
|
