Bug#837759: network configuration stops working reliably

[Wolfgang Walter]

Hello Martin,

On Monday, 19 September 2016 11:02:08 CEST Martin Pitt wrote:
> Hello Wolfgang,
> 
> Wolfgang Walter [2016-09-14 23:34 +0200]:
> > > > I tested this with a script:
> FTR, I tried this as welll, and I cannot reproduce the bug either.
> 
> Wolfgang Walter [2016-09-14 17:56 +0200]:
> > Yes, systemd-networkd ist active. But on most machines I only have *.link
> 
> > entries, usually one to name the device:
> *.link entries are handled by udev, not networkd. So if you can
> reproduce this on a machine with only has files like
> 
> > ======================
> > [Match]
> > MACAddress=11:22:33:44:55:66
> > 
> > [Link]
> > Name=net
> > WakeOnLan=off
> > ======================
> 
> then can you please "systemctl disable --now systemd-networkd" and
> check if the problem still happens? I suppose not, but if so, this
> tells us that this is being done through udev.

When I disable systemd-networkd the problem disappears.

The reason I think it is a race is because it depends on how many interfaces you set up, if you use systemd-networkd to setup some interfaces and the number of ip-addresses and things you do in /etc/network/interfaces.

For example on that simple machines where I only have *.link and don't use systemd-networkd: sometimes (maybe 2 out of 10) it works, but most of the time I loose some or all ip-adresses.

Here is the log (without) debugging: in this case the interface only kept the IPv6 addresses and lost its ipv4 address, all set up in /etc/network/interfaces.

Sep 19 11:33:25 maiskolben systemd[1]: Starting Raise network interfaces...
Sep 19 11:33:25 maiskolben systemd[1]: Starting Network Service...
Sep 19 11:33:26 maiskolben systemd-networkd[480]: Enumeration completed
Sep 19 11:33:26 maiskolben systemd-networkd[480]: net: Lost carrier
Sep 19 11:33:26 maiskolben systemd-networkd[480]: net: Gained carrier
Sep 19 11:33:26 maiskolben systemd[1]: Started Network Service.
Sep 19 11:33:27 maiskolben systemd-networkd[480]: net: Gained IPv6LL
Sep 19 11:33:27 maiskolben ifup[352]: Waiting for DAD... Done
Sep 19 11:33:27 maiskolben systemd[1]: Started Raise network interfaces.

But there is nothing special about ipv4-addresses. With more interfaces one may loose some or all of the ipv6 adresses, too.

I think the crucial point is that systemd-networkd may declares the interface "net" unamanaged AFTER "net: Lost carrier" so that all addresses confgured until that point are ripped off.

This " Lost carrier" is always there on startup, don't know if this is caused by udev when it detects the interface on startup.


Here is the log with systemd-networkd disabled:

Sep 19 11:37:20 maiskolben systemd[1]: Starting Raise network interfaces...
Sep 19 11:37:22 maiskolben ifup[400]: Waiting for DAD... Done
Sep 19 11:37:23 maiskolben systemd[1]: Started Raise network interfaces.


> 
> If networkd itself is really the culprit, can you please try the
> following:
> 
>  * Keep it disabled, run your test.sh to set up the dummy interface,
>    and run
> 
>      SYSTEMD_LOG_LEVEL=debug /lib/systemd/systemd-networkd
> 
>   (as root). Does this now cause the addresses to be removed? This
>   will run much later than test.sh, so this will tell us if this is a
>   principal logic error or a race condition, i. e. only happens if
>   networkd starts at the right time after test.sh.

No, I don't loose any addresses then. But as you see there is no such "net: Lost carrier" or "TEST: Lost carrier" and so on.

SYSTEMD_LOG_LEVEL=debug /lib/systemd/systemd-networkd
Found container virtualization none
Sent message type=method_call sender=n/a destination=org.freedesktop.DBus object=/org/freedesktop/DBus interface=org.freedesktop.DBus member=Hello cookie=1 reply_cookie=0 error=n/a
Got message type=method_return sender=org.freedesktop.DBus destination=:1.3 object=n/a interface=n/a member=n/a cookie=1 reply_cookie=1 error=n/a
Sent message type=method_call sender=n/a destination=org.freedesktop.DBus object=/org/freedesktop/DBus interface=org.freedesktop.DBus member=AddMatch cookie=2 reply_cookie=0 error=n/a
Got message type=method_return sender=org.freedesktop.DBus destination=:1.3 object=n/a interface=n/a member=n/a cookie=3 reply_cookie=2 error=n/a
Sent message type=method_call sender=n/a destination=org.freedesktop.DBus object=/org/freedesktop/DBus interface=org.freedesktop.DBus member=RequestName cookie=3 reply_cookie=0 error=n/a
Got message type=method_return sender=org.freedesktop.DBus destination=:1.3 object=n/a interface=n/a member=n/a cookie=5 reply_cookie=3 error=n/a
Failed to open configuration file '/etc/systemd/networkd.conf': No such file or directory
timestamp of '/etc/systemd/network' changed
timestamp of '/lib/systemd/network' changed
TEST: Flags change: +UP +LOWER_UP +RUNNING +BROADCAST +NOARP
Sent message type=signal sender=n/a destination=n/a object=/org/freedesktop/network1/link/_34 interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=4 reply_cookie=0 error=n/a
TEST: Link 4 added
TEST: udev initialized link
TEST: Saved original MTU: 1500
dummy0: Flags change: +BROADCAST +NOARP
dummy0: Link 3 added
dummy0: udev initialized link
dummy0: Saved original MTU: 1500
net: Flags change: +UP +LOWER_UP +RUNNING +MULTICAST +BROADCAST
Sent message type=signal sender=n/a destination=n/a object=/org/freedesktop/network1/link/_32 interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=5 reply_cookie=0 error=n/a
net: Link 2 added
net: udev initialized link
net: Saved original MTU: 1500
lo: Flags change: +LOOPBACK +UP +LOWER_UP +RUNNING
Sent message type=signal sender=n/a destination=n/a object=/org/freedesktop/network1/link/_31 interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=6 reply_cookie=0 error=n/a
lo: Link 1 added
lo: udev initialized link
lo: Saved original MTU: 0
TEST: Adding address: fe80::28c4:17ff:fe97:8db8/64 (valid forever)
Sent message type=signal sender=n/a destination=n/a object=/org/freedesktop/network1/link/_34 interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=7 reply_cookie=0 error=n/a
TEST: Gained IPv6LL
TEST: Adding address: 2a01:1:1:1::1/128 (valid forever)
Sent message type=signal sender=n/a destination=n/a object=/org/freedesktop/network1/link/_34 interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=8 reply_cookie=0 error=n/a
TEST: Adding address: 2a01:1:1:1::2/128 (valid forever)
TEST: Adding address: 2a01:1:1:1::3/128 (valid forever)
TEST: Adding address: 2a01:1:1:1::4/128 (valid forever)
TEST: Adding address: 2a01:1:1:1::5/128 (valid forever)
net: Adding address: fe80::b06f:8519:f172:52ef/64 (valid forever)
Sent message type=signal sender=n/a destination=n/a object=/org/freedesktop/network1/link/_32 interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=9 reply_cookie=0 error=n/a
net: Gained IPv6LL
net: Adding address:2a01:1:2:3::1/125 (valid forever)
Sent message type=signal sender=n/a destination=n/a object=/org/freedesktop/network1/link/_32 interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=10 reply_cookie=0 error=n/a
lo: Adding address: ::1/128 (valid forever)
TEST: Adding address: 10.10.10.10/32 (valid forever)
net: Adding address: 10.251.17.66/29 (valid forever)
lo: Adding address: 127.0.0.1/8 (valid forever)
Enumeration completed
Sent message type=signal sender=n/a destination=n/a object=/org/freedesktop/network1 interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=11 reply_cookie=0 error=n/a
TEST: Link state is up-to-date
Virtualization QEMU found in DMI (/sys/class/dmi/id/sys_vendor)
Found VM virtualization qemu
TEST: Unmanaged
Sent message type=signal sender=n/a destination=n/a object=/org/freedesktop/network1/link/_34 interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=12 reply_cookie=0 error=n/a
dummy0: Link state is up-to-date
dummy0: Unmanaged
Sent message type=signal sender=n/a destination=n/a object=/org/freedesktop/network1/link/_33 interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=13 reply_cookie=0 error=n/a
net: Link state is up-to-date
net: Unmanaged
Sent message type=signal sender=n/a destination=n/a object=/org/freedesktop/network1/link/_32 interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=14 reply_cookie=0 error=n/a
lo: Link state is up-to-date
lo: Unmanaged
Sent message type=signal sender=n/a destination=n/a object=/org/freedesktop/network1/link/_31 interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=15 reply_cookie=0 error=n/a
Got message type=signal sender=org.freedesktop.DBus destination=:1.3 object=/org/freedesktop/DBus interface=org.freedesktop.DBus member=NameAcquired cookie=2 reply_cookie=0 error=n/a
Got message type=signal sender=org.freedesktop.DBus destination=:1.3 object=/org/freedesktop/DBus interface=org.freedesktop.DBus member=NameAcquired cookie=4 reply_cookie=0 error=n/a


> 
>  * Enable networkd again, and boot with "debug" in the kernel command
>    line. Does this still reproduce the bug?

Will do that tonight.

> 
>    If so, please attach the output of "journalctl -b".
> 
>    If not, just enable debugging for networkd with
> 
>    mkdir -p /etc/systemd/system/systemd-networkd.service.d/
>    printf '[Service]\nEnvironment=SYSTEMD_LOG_LEVEL=debug' >
> /etc/systemd/system/systemd-networkd.service.d/debug.conf
> 
>    and reboot. If you catch the bug, please attach "journalctl -b".
> 
> Thanks,
> 
> Martin


Regards
-- 
Wolfgang Walter
Studentenwerk München
Anstalt des öffentlichen Rechts