Activity log for bug #1765173

Date Who What changed Old value New value Message
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