systemd-networkd failing to acquire a DHCP6 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

Is this only seen with glibc 2.34?

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.

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

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

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.

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.

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.

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=...

We must be hitting this line, right? https://sourceware.org/git/?p=glibc.git;a=blob;f=sysdeps/unix/sysv/linux/convert_scm_timestamps.c;h=00c934c4135f0d4256068adcf23a3de024fadd43;hb=HEAD#l87

IOW, ddstreet was right in comment #10.

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.

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.

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

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