systemd-networkd failing to acquire a DHCP6 lease from dnsmasq on armhf

Bug #1940635 reported by Lukas Märdian
12
This bug affects 2 people
Affects Status Importance Assigned to Milestone
glibc (Ubuntu)
Undecided
Unassigned
netplan.io (Ubuntu)
Undecided
Simon Chopin
systemd (Ubuntu)
Undecided
Unassigned

Bug Description

systemd-networkd is failing to acquire a DCHP6 lease from dnsmasq on armhf since glibc 2.34-0ubuntu1, failing systemd (tests-name=networkd-test.py) and netplan.io (test-name=ethernets) tests on armhf.

Reproducer:
* Setup an armhf container, e.g. via:
autopkgtest systemd --test-name=networkd-test.py --shell -U --apt-pocket=proposed=src:systemd,src:glibc -s -- lxd autopkgtest/ubuntu/impish/armhf
* It will fail and drop you into the shell
* cd test/ && apt install python3-nose
* nosetests3 -v -s -m "test_.*_dhcp_ip6" networkd-test.py

This is unrelated to the recent dnsmasq changes (LP: #1894619), as that would fail on all architectures, not just armhf.

It still passes inside an amd64 LXD container, so it is also not related to armhf being tested inside a container. But it shows the difference between armhf vs amd64 container, that on armhf we're missing the DHCPSOLICIT (and therefore DHCPREPLY) messages, as can be seen from the dnsmasq log:
dnsmasq-dhcp[]: DHCPSOLICIT(router_eth42) 00:02:00:00:ab:11:57:1e:20:2f:9e:56:5f:34
dnsmasq-dhcp[]: DHCPREPLY(router_eth42) 2600::1f 00:02:00:00:ab:11:57:1e:20:2f:9e:56:5f:34 autopkgtest-lxd-rtypaf

The issue is most probably the same that causes the currently failing netplan.io/ethernets autopkgtest on armhf, if tested against glibc 2.34-0ubuntu1.

Revision history for this message
Lukas Märdian (slyon) wrote :
Revision history for this message
Lukas Märdian (slyon) wrote :
summary: - Failing to acquire a DCHP6 lease on armhf
+ systemd-networkd failing to acquire a DCHP6 lease from dnsmasq on armhf
Revision history for this message
Lukas Märdian (slyon) wrote (last edit ): Re: systemd-networkd failing to acquire a DCHP6 lease from dnsmasq on armhf

The systemd-networkd debug log (inside armhf container) reveals an interesting error message: "NDISC: Unexpected error while reading from ICMPv6, ignoring: Exchange full"

Aug 20 09:40:22 autopkgtest-lxd-ytcddy systemd-networkd[5450]: NDISC: Started IPv6 Router Solicitation client
Aug 20 09:40:22 autopkgtest-lxd-ytcddy systemd-networkd[5450]: test_eth42: Remembering foreign route: dst: fe80::dcad:beff:feef:4711/128, src: n/a, gw: n/a, prefsrc: n/a, scope: global, table: local(255), proto: kernel, type: local, nexthop: 0
Aug 20 09:40:22 autopkgtest-lxd-ytcddy systemd-networkd[5450]: router_eth42: Gained new hardware address: b6:f9:18:ed:b5:5c
Aug 20 09:40:22 autopkgtest-lxd-ytcddy systemd-networkd[5450]: rtnl: received non-static neighbor, ignoring.
Aug 20 09:40:22 autopkgtest-lxd-ytcddy systemd-networkd[5450]: rtnl: received non-static neighbor, ignoring.
Aug 20 09:40:22 autopkgtest-lxd-ytcddy systemd-networkd[5450]: rtnl: received non-static neighbor, ignoring.
Aug 20 09:40:22 autopkgtest-lxd-ytcddy systemd-networkd[5450]: rtnl: received non-static neighbor, ignoring.
Aug 20 09:40:23 autopkgtest-lxd-ytcddy systemd-networkd[5450]: NDISC: Sent Router Solicitation, next solicitation in 3s
Aug 20 09:40:23 autopkgtest-lxd-ytcddy systemd-networkd[5450]: rtnl: received non-static neighbor, ignoring.
Aug 20 09:40:23 autopkgtest-lxd-ytcddy systemd-networkd[5450]: NDISC: Unexpected error while reading from ICMPv6, ignoring: Exchange full

And also:
Aug 20 09:40:34 autopkgtest-lxd-ytcddy systemd-networkd[5450]: NDISC: No RA received before link confirmation timeout
Aug 20 09:40:34 autopkgtest-lxd-ytcddy systemd-networkd[5450]: NDISC: Invoking callback for 'timeout' event.
Aug 20 09:40:34 autopkgtest-lxd-ytcddy systemd-networkd[5450]: test_eth42: NDisc handler get timeout event

Revision history for this message
Lukas Märdian (slyon) wrote :
Lukas Märdian (slyon)
summary: - systemd-networkd failing to acquire a DCHP6 lease from dnsmasq on armhf
+ systemd-networkd failing to acquire a DHCP6 lease from dnsmasq on armhf
Revision history for this message
Michael Hudson-Doyle (mwhudson) wrote :

Is this only seen with glibc 2.34?

Revision history for this message
Simon Chopin (schopin) wrote :

Can somebody confirm my assumptions on the architecture of the test ?

First, it sets up a veth with router_eth42 at one end and test_eth42 at the other (the itf names might be different ?). dnsmasq is bound against router_eth42 which is configured manually via iproute with both IPv4 and IPv6 addresses.

networkd is in charge of configuring test_eth42. In this specific case, it is expected that it sends a DHCPv6 request via test_eth42, and that we get an answer from dnsmasq with an lease to an address between 2600::10 and 2600::20.

When running tcpdump on test_eth42, I can only see some ICMPv6 router solicitations (from both ends of the tunnel), with no router advertisement as answer. This bit is expected AFAIK. However, I do not see any other traffic, crucially, no DHCPv6 traffic at all.

Revision history for this message
Simon Chopin (schopin) wrote :

Allright.

I was going to post in-depth investigation results to sum up what stepping through the code taught me (pretty much nothing, it all goes well until I lose the stepping thread due to callback/async stuff), but right before sending the text I let GDB finish the program execution, and lo and behold, some DHCP6 traffic appeared in my tcpdump terminal, and the tests finally pass. I'm thus assuming that some timeout somewhere expired while I was stepping through the code (I of course dialed up all the test timeouts).

I thus suspect that the bug lies within this call and its side-effects : https://git.launchpad.net/ubuntu/+source/systemd/tree/src/libsystemd-network/sd-dhcp6-client.c?h=applied/ubuntu/impish-proposed#n1648

Steve Langasek (vorlon)
Changed in netplan.io (Ubuntu):
assignee: nobody → Simon Chopin (schopin)
Revision history for this message
Simon Chopin (schopin) wrote (last edit ):

I can now confirm that the bug has been introduced strictly by the glibc 2.34, and not another package in the -proposed pocket.

My reproduction steps were as following:

Boot an Ubuntu Impish qemu VM (fully up-to-date (funnily enough, far from being a trivial thing to do, see at the bottom for pointers).

In the VM, install the dpkg-dev and dnsmasq-base packages, get the systemd sources, go into the test subdirectory of the sources, and run the following command:

sudo python3 networkd-test.py DnsmasqClientTest.test_coldplug_dhcp_ip6

It should succeed (it has, in my case).

Then enable the -proposed pocket in the APT sources, with APT preferences looking like so

Package: *
Pin: release a=impish-proposed
Pin-Priority: 50

Finally, update *only* the glibc:

sudo apt install -t impish-proposed libc6

Reboot the VM, go into the test directory, and run the same python3 command as above. It now fails.

To revert to the previous state of the VM (if you haven't made a snapshot), simply use an apt preference > 1000 for the a=impish packages, the resolver will downgrade every package.

I captured straces for both debug runs for the networkd daemon, I'll attach them to the post. For reference, to get them, I changed the ExecStart line in /lib/systemd/system/systemd-networkd.service to

ExecStart=sh -c "strace -o /tmp/networkd.strace --output-separately -p $$$$ & exec /lib/systemd/systemd-networkd"

, added this line

ReadWritePaths=/tmp

and added CAP_SYS_PTRACE to the AmbiantCapabilties and CapabilitiesBoundingSet lines.

How I finally managed to get a VM up and running:

* used `autopkgtest-buildvm-ubuntu-cloud -v -r impish --arch armhf` using autopkgtest git master
-> This gave me an image with credentials and disk space
* Used `mount-image-callback my.img --mountpoint /mnt -- cp -L /mnt/boot/vmlinuz /mnt/boot/initrd.img` to extract the kernel and initrd
-> couldn't figure out how to use a proper bootloader, so direct kernel boot
* use virtio for the img, and add root=/dev/vda1 as a kernel argument when launching qemu.
* fixed /etc/apt/sources.list to point to https://ports.ubuntu.com/ubuntu-ports
* sudo dpkg --remove-architecture i386

EDIT: removed the attached traces as they're of the wrong thing, fixed the strace invocation snippet, and added the post-boot VM configuration fixes

Revision history for this message
Dan Streetman (ddstreet) wrote :

A quick guess would be the problem is glibc upstream commit 13c51549e2077f2f3bf84e8fd0b46d8b0c615912, combined with upstream commit a26918cfda4bc4b9dad8aae1496e3ef7cbb63d96 setting __ASSUME_TIME64_SYSCALLS based on the *build* time kernel (not runtime kernel), and since our build farm runs a kernel older than 5.1, __ASSUME_TIME64_SYSCALLS remains unset for armhf. For all our other archs, __WORDSIZE == 64 I think, so only armhf would be affected.

Haven't looked very deep at what a proper fix would be though.

Revision history for this message
Dimitri John Ledkov (xnox) wrote :

We must build armhf glibc which is y2038 safe, like our v5.1+ kernels are (bionic-hwe and up). Thus yes, glibc should assume TIME64 SYSCALLS, on armhf.

Also, maybe our farm can move to focal and focal kernel; or like at least to bionic-hwe kernel.

Revision history for this message
Simon Chopin (schopin) wrote :

Attached are new strace logs, I'll remove the previous files as there was something wrong with my test setup, so the captured trace isn't necessarily during the DHCPv6 tests.

Revision history for this message
Simon Chopin (schopin) wrote :
Revision history for this message
Simon Chopin (schopin) wrote :
Revision history for this message
Simon Chopin (schopin) wrote :
Download full text (3.3 KiB)

Beginner error on my part : there are debug logs in networkd, I didn't even check them. As often, it turns out part of the answer lies in there.

Here are the logs from 2.33:

autopkgtest systemd-networkd[942]: test_eth42: Gained IPv6LL
autopkgtest systemd-networkd[942]: test_eth42: link_check_ready(): DHCP4, DHCP6 or IPv4LL is enabled but no dynamic address is assigned yet.
autopkgtest systemd-networkd[942]: test_eth42: Discovering IPv6 routers
autopkgtest systemd-networkd[942]: NDISC: Started IPv6 Router Solicitation client
autopkgtest systemd-networkd[942]: test_eth42: Remembering foreign route: dst: fe80::dcad:beff:feef:4711/128, src: n/a, gw: n/a, prefsrc: n/a, scope: global, table: local(255), proto: kernel, type: local, nexthop: 0
autopkgtest systemd-networkd[942]: NDISC: Sent Router Solicitation, next solicitation in 4s
autopkgtest systemd-networkd[942]: rtnl: received non-static neighbor, ignoring.
autopkgtest systemd-networkd[942]: NDISC: Received Router Advertisement: flags MANAGED preference medium lifetime 1800 sec
autopkgtest systemd-networkd[942]: NDISC: Invoking callback for 'router' event.
autopkgtest systemd-networkd[942]: DHCPv6 CLIENT: Started in Managed mode
autopkgtest systemd-networkd[942]: test_eth42: Acquiring DHCPv6 lease on NDisc request
autopkgtest systemd-networkd[942]: test_eth42: Configuring route: dst: n/a, src: n/a, gw: fe80::6051:85ff:fe70:4c03, prefsrc: n/a, scope: global, table: main(254), proto: ra, type: unicast, nexthop: 0

And the equivalent in 2.34:

Aug 27 14:28:27 autopkgtest systemd-networkd[939]: test_eth42: Gained IPv6LL
Aug 27 14:28:27 autopkgtest systemd-networkd[939]: test_eth42: link_check_ready(): DHCP4, DHCP6 or IPv4LL is enabled but no dynamic address is assigned yet.
Aug 27 14:28:27 autopkgtest systemd-networkd[939]: test_eth42: Discovering IPv6 routers
Aug 27 14:28:27 autopkgtest systemd-networkd[939]: NDISC: Started IPv6 Router Solicitation client
Aug 27 14:28:27 autopkgtest systemd-networkd[939]: test_eth42: Remembering foreign route: dst: fe80::dcad:beff:feef:4711/128, src: n/a, gw: n/a, prefsrc: n/a, scope: global, table: local(255), proto: kernel, type: local, nexthop: 0
Aug 27 14:28:29 autopkgtest systemd-networkd[939]: NDISC: Sent Router Solicitation, next solicitation in 4s
Aug 27 14:28:29 autopkgtest systemd-networkd[939]: rtnl: received non-static neighbor, ignoring.
Aug 27 14:28:29 autopkgtest systemd-networkd[939]: NDISC: Unexpected error while reading from ICMPv6, ignoring: Exchange full

Looking through the code, one can trace the EXFULL error to this function:

https://github.com/systemd/systemd/blob/main/src/basic/socket-util.c#L1260

Which checks the msg flags and finds MSG_CTRUNC.
The thing is, the recvmsg in strace looks like this:

recvmsg(20, {msg_name={sa_family=AF_INET6, sin6_port=htons(0), sin6_flowinfo=htonl(0), inet_pton(AF_INET6, "fe80::6051:85ff:fe70:4c03", &sin6_addr), sin6_scope_id=if_nametoindex("test_eth42")}, msg_namelen=128->28, msg_iov=[{iov_base="\206\0000\276@\300\7\10\0\0\0\0\0\0\0\0\3\4@\200\377\377\377\377\377\377\377\377\0\0\0\0"..., iov_len=88}], msg_iovlen=1, msg_control=[{cmsg_len=20, cmsg_level=SOL_SOCKET, cmsg_type=SO_TIMESTAMP_OLD, cmsg_data=...

Read more...

Revision history for this message
Michael Hudson-Doyle (mwhudson) wrote :
Revision history for this message
Michael Hudson-Doyle (mwhudson) wrote :

So what is going on is this:

In icmp6_receive systemd passes a buffer for control messages to recvmsg that is only big enough for the messages it expects to receive. glibc now attempts to append an extra control message to the buffer (translating SO_TIMESTAMP / COMPAT_SO_TIMESTAMP_OLD to SO_TIMESTAMP_NEW) and sets MSG_CTRUNC in flags if it can't fit this in. So this is where that EXFULL comes from.

So the fix for this is simple, right? Just pass a bigger buffer to recvmsg? No, if you do this networkd segfaults. I think __convert_scm_timestamps fails to handle a subtlety of the control message buffer, which is that the control messages don't always (it seems) occupy all of the buffer up to msg_controllen (!). If you look at the definition of CMSG_NXTHDR, the test for the end of the buffer has two clauses (https://sourceware.org/git/?p=glibc.git;a=blob;f=bits/socket.h;h=05ac0249c7da7218cbd11be99a67529161cfa7f7;hb=HEAD#l265):

  if ((unsigned char *) (__cmsg + 1) > ((unsigned char *) __mhdr->msg_control
     + __mhdr->msg_controllen)
      || ((unsigned char *) __cmsg + CMSG_ALIGN (__cmsg->cmsg_len)
   > ((unsigned char *) __mhdr->msg_control + __mhdr->msg_controllen)))
    /* No more entries. */
    return (struct cmsghdr *) 0;

I think after glibc's alterations, calling this on the last message ends up with garbage in __cmsg->cmsg_len, so __cmsg+__cmsg->cmsg_len is overflowing and the program then goes off to read uninitialized memory and hilarity ensues.

I'm attaching a glibc patch which *may* help (it's building in a ppa now, will test it in a bit). But it's all a bit uncertain. Haven't filed an upstream glibc bug report yet.

tags: added: patch
Revision history for this message
Michael Hudson-Doyle (mwhudson) wrote :

I filed a bug in systemd (although I'm not really sure it's systemd's bug) https://github.com/systemd/systemd/issues/20564 and uploaded a simple workaround (in systemd) that passed systemd armhf autopkgtests in my PPA. Fingers crossed!

We should come back and review this fix after glibc has migrated, but I wanted to get something done asap and it doesn't seem overly harmful.

Changed in systemd (Ubuntu):
status: New → Fix Committed
Revision history for this message
Launchpad Janitor (janitor) wrote :

Status changed to 'Confirmed' because the bug affects multiple users.

Changed in glibc (Ubuntu):
status: New → Confirmed
Changed in netplan.io (Ubuntu):
status: New → Confirmed
tags: added: rls-ii-incoming
Lukas Märdian (slyon)
Changed in netplan.io (Ubuntu):
status: Confirmed → Fix Released
Lukas Märdian (slyon)
Changed in glibc (Ubuntu):
status: Confirmed → Invalid
tags: removed: rls-ii-incoming
Revision history for this message
Launchpad Janitor (janitor) wrote :

This bug was fixed in the package systemd - 248.3-1ubuntu7

---------------
systemd (248.3-1ubuntu7) impish; urgency=medium

  * d/tests/tests-in-lxd: suppress the cgroups v2 warning on stderr from
    lxd/lxc even more comprehensively until the snapd change required to
    do it nicely gets into a release.

 -- Michael Hudson-Doyle <email address hidden> Wed, 01 Sep 2021 19:21:58 +1200

Changed in systemd (Ubuntu):
status: Fix Committed → Fix Released
To post a comment you must log in.
This report contains Public information  Edit
Everyone can see this information.

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.