regression: networkd-wait-online times out, interface never goes from "carrier" to "routable"

[martinpitt]

Our "networkd" integration test got broken since the last few days in master. networkd itself seems to work fine:

# cat /etc/systemd/network/e.network
[Match]
Name=eth0
[Network]
DHCP=yes

# systemctl start systemd-networkd
#networkctl status eth0
● 2: eth0
       Link File: n/a
    Network File: /etc/systemd/network/e.network
            Type: ether
           State: carrier (configured)
          Vendor: Red Hat, Inc
           Model: Virtio network device
      HW Address: 52:54:00:12:34:56
             MTU: 1500
         Address: 10.0.2.15
                  fe80::5054:ff:fe12:3456
         Gateway: 10.0.2.2
             DNS: 10.0.2.3

# ip route
default via 10.0.2.2 dev eth0  proto dhcp  src 10.0.2.15  metric 1024 
10.0.2.0/24 dev eth0  proto kernel  scope link  src 10.0.2.15 
10.0.2.2 dev eth0  proto dhcp  scope link  src 10.0.2.15  metric 1024 

Network is operational, I can ssh in and ping out etc. However:

# /lib/systemd/systemd-networkd-wait-online --interface eth0 --timeout=10
ignoring: lo
Event loop failed: Connection timed out
# /lib/systemd/systemd-networkd-wait-online --timeout=10
ignoring: lo
Event loop failed: Connection timed out

Going to bisect now.

[martinpitt]

I suppose the reason for that is that "State" used to be "routable (configured)" but now is "carrier (configured)", although the routes do look okay.

[martinpitt]

Another observation: Our network test has four checks: (IPv4 or IPv6) x (hotplug or coldplug). Not all of them always fail, sometimes one or two actually succeed. So this smells like a race condition.

[martinpitt]

Bisected to 84de38c5691 . That's quite a big one; @teg, do you see this as well? This doesn't say anything about changing status names, so I figure "status carrier" is the bug here, and wait-online timing out is merely telling that it never goes to "routable"?

[martinpitt]

Things work again if I revert just this one hunk, i. e. I apply this patch:

diff --git a/src/network/networkd-link.c b/src/network/networkd-link.c
index 1144c82..1104033 100644
--- a/src/network/networkd-link.c
+++ b/src/network/networkd-link.c
@@ -2377,6 +2377,8 @@ int link_save(Link *link) {
         assert(link->lease_file);
         assert(link->manager);

+        link_update_operstate(link);
+
         if (link->state == LINK_STATE_LINGER) {
                 unlink(link->state_file);
                 return 0;

I'm fairly sure that this isn't what @teg intended with 84de38c5691, but it goes back to a known-working state, so I'll apply that to my "trunk CI" branch for the time being to be able to run tests on trunk again. (This doesn't get released to anywhere but the daily PPA).

[martinpitt]

I can still reproduce this at 84de38c, but not any more on current master. So I'm closing this.

I ran a git bisect but that was inconclusive; this is a race condition and thus the automatic test doesn't catch this every time; also, they occasionally fail for other reasons. I might do it again tomorrow with manual testing, just to turn this from "magically fixed" to "aah, so that was it".

[ILMostro]

I'm seeing this on a raspberry-pi2 with ArchLinux on Arm (ALArm) after I disabled IPv6 via kernel boot commandline; though, I'm not sure if the problem is directly related to that or a recent update.

systemd-networkd-wait-online[300]: ignoring: lo

Followed by the failed state line

[ILMostro]

systemctl status -l systemd-networkd            
* systemd-networkd.service - Network Service
   Loaded: loaded (/usr/lib/systemd/system/systemd-networkd.service; enabled; vendor preset: enabled)
   Active: active (running) since Thu 2015-12-03 23:39:53 CST; 2 days ago
     Docs: man:systemd-networkd.service(8)
 Main PID: 275 (systemd-network)
   Status: "Processing requests..."
   CGroup: /system.slice/systemd-networkd.service
           `-275 /usr/lib/systemd/systemd-networkd
systemd[1]: Starting Network Service...
systemd-networkd[275]: [/etc/systemd/network/eth0.network:3] Unknown lvalue 'MACAdress' in section 'Match'
systemd-networkd[275]: Enumeration completed
systemd[1]: Started Network Service.

systemd-networkd[275]: eth0: Could not set route: Network is unreachable

systemd-networkd[275]: eth0: Gained carrier
systemd-networkd[275]: eth0: DHCPv4 address 10.20.32.7/24 via 10.20.32.1