[systemd-devel] [networkd] intermittent failure to get DHCP lease on a bond interface

[Tom Gundersen]

On Tue, Aug 5, 2014 at 5:24 PM, Leonid Isaev <lisaev at umail.iu.edu> wrote:
> Hi,
>
>         Ever since updating to kernel 3.16, systemd-networkd very often fails
> to get a DHCPv4 lease on a bond interface. This happens irregularly which makes
> me suspect some kind of a race. The bond enslaves eth and wlan cards. Here is
> the config:
> ------
> /etc/systemd/network/bond0.netdev
> [NetDev]
> Name=bond0
> Kind=bond
>
> /etc/systemd/network/bond0.network
> [Match]
> Name=bond0
> [Network]
> Description=Bond interface
> DHCP=v4
> [DHCPv4]
> UseDNS=false
>
> /etc/systemd/network/eth.network
> [Match]
> Name=eno1
> [Network]
> Description=Wired interface
> Bond=bond0
>
> /etc/systemd/network/wlan.network
> [Match]
> Name=wlp3s0
> [Network]
> Description=Wireless interface
> Bond=bond0
>
> $ cat /etc/modprobe.d/bonding.conf
> options bonding mode=active-backup
> options bonding primary=eno1
> options bonding miimon=1000
> ------
>
> The wlan interface is managed by wpa_supplicant which is ordered
> "After=systemd-networkd.service". There is nothing suspicious in journald and
> by running networkd via cmdline with SYSTEMD_LOG_LEVEL=debug (I only see
> endless DISCOVER messages):
> ------
> $ journalctl -u systemd-networkd.service
> -- Logs begin at Tue 2014-08-05 10:13:29 EDT, end at Tue 2014-08-05 11:05:07 EDT. --
> Aug 05 10:13:29 borei systemd[1]: Starting Network Service...
> Aug 05 10:13:29 borei systemd-networkd[446]: bond0           : netdev ready
> Aug 05 10:13:29 borei systemd-networkd[446]: lo              : gained carrier
> Aug 05 10:13:29 borei systemd-networkd[446]: bond0           : link configured
> Aug 05 10:13:29 borei systemd[1]: Started Network Service.
> Aug 05 10:13:29 borei systemd-networkd[446]: eno1            : link configured
> Aug 05 10:13:29 borei systemd-networkd[446]: wlp3s0          : link configured
> Aug 05 10:13:33 borei systemd-networkd[446]: wlp3s0          : gained carrier
> Aug 05 10:13:34 borei systemd-networkd[446]: bond0           : gained carrier
> ------
>
> Interestingly, on the server side (dnsmasq) I see DISCOVER and OFFER messages
> for an IP address every 3 sec, but on the client no address is assigned to
> bond0.
>
> The bond itself is set up properly. And, of course, dhcpcd _is_ able to obtain
> a lease (I can also get a working network by assigning a static IP on the
> correct subnet):
> ------
> $ journalctl -u dhcpcd at bond0.service
> -- Logs begin at Tue 2014-08-05 10:13:29 EDT, end at Tue 2014-08-05 11:13:29 EDT. --
> Aug 05 10:24:13 borei systemd[1]: Starting dhcpcd on bond0...
> Aug 05 10:24:13 borei dhcpcd[916]: version 6.4.3 starting
> Aug 05 10:24:13 borei dhcpcd[916]: all: IPv6 kernel autoconf disabled
> Aug 05 10:24:13 borei dhcpcd[916]: bond0: adding address fe80::18f7:74d:5764:92e9
> Aug 05 10:24:13 borei dhcpcd[916]: if_addaddress6: Operation not supported
> Aug 05 10:24:13 borei dhcpcd[916]: error writing DUID: /etc/dhcpcd.duid: Read-only file system
> Aug 05 10:24:13 borei dhcpcd[916]: DUID 00:03:00:01:f0:1f:af:4d:36:99
> Aug 05 10:24:13 borei dhcpcd[916]: bond0: IAID af:4d:36:99
> Aug 05 10:24:14 borei dhcpcd[916]: bond0: rebinding lease of 10.0.0.21
> Aug 05 10:24:19 borei dhcpcd[916]: bond0: leased 10.0.0.21 for 86400 seconds
> Aug 05 10:24:19 borei dhcpcd[916]: bond0: adding route to 10.0.0.0/24
> Aug 05 10:24:19 borei dhcpcd[916]: bond0: adding default route via 10.0.0.1
> Aug 05 10:24:19 borei dhcpcd[916]: forked to background, child pid 923
> Aug 05 10:24:19 borei systemd[1]: Started dhcpcd on bond0.
>
> $ systemctl cat dhcpcd at bond0.service
> # /usr/lib/systemd/system/dhcpcd at .service
> [Unit]
> Description=dhcpcd on %I
> Wants=network.target
> Before=network.target
> BindsTo=sys-subsystem-net-devices-%i.device
> After=sys-subsystem-net-devices-%i.device
>
> [Service]
> Type=forking
> PIDFile=/run/dhcpcd-%I.pid
> ExecStart=/usr/bin/dhcpcd -q -w %I
> ExecStop=/usr/bin/dhcpcd -x %I
>
> [Install]
> WantedBy=multi-user.target
> ------
>
> I am a bit at a loss of how to debug this further... Any ideas?
>
> Thanks,
> --
> Leonid Isaev
> GPG fingerprints: DA92 034D B4A8 EC51 7EA6  20DF 9291 EE8A 043C B8C4
>                   C0DF 20D0 C075 C3F1 E1BE  775A A7AE F6CB 164B 5A6D


Hi Leonid,

I have tried to reproduce this, but I have not been successful. If you
can still reproduce with current git, could you attach the output of
"ip addr show" and any relevant parts of dmesg?

Lastly, is the problem reproducible also if you name your bond
something different from bond0? (bond0 is created by the kernel,
anything else is created by networkd)

Cheers,

Tom