systemd-networkd asserts on restart or DHCPv6 PD lease renewal when AssignAcquiredDelegatedPrefixAddress=yes

[mamarley]

systemd version the issue has been seen with

git HEAD

Used distribution

Ubuntu

Expected behaviour you didn't see

systemd-networkd does not crash when renewing DHCPv6 PD

Unexpected behaviour you saw

systemd-networkd crashes when renewing DHCPv6 PD

Steps to reproduce the problem Set up DHCPv6 PD, preferably with a short lease time, start networkd, and wait until the lease is renewed. It will crash with "systemd-networkd[1322]: Assertion 'IN_SET(link->state, LINK_STATE_CONFIGURING, LINK_STATE_FAILED, LINK_STATE_LINGER)' failed at src/network/networkd-link.c:1195, function address_handler(). Aborting.". Setting the new option AssignAcquiredDelegatedPrefixAddress to "no" prevents the crash.

I'm going to reproduce this again tomorrow in a test environment so I can post a full debug log of the crash occurring.

[ssahani]

This sees like race in address_meaages. I guess https://github.com/systemd/systemd/pull/16366 would fix. Please test.

[mamarley]

That improves it slightly. It doesn't assert on a manual restart anymore, but it still asserts on a lease renew. Here's the log:

Jul 06 10:28:58 mamarley-laptop systemd-networkd[13111]: DHCPv6 CLIENT: Timeout T1
Jul 06 10:28:58 mamarley-laptop systemd-networkd[13111]: DHCPv6 CLIENT: Sent RENEW
Jul 06 10:28:58 mamarley-laptop systemd-networkd[13111]: DHCPv6 CLIENT: Next retransmission in 9s
Jul 06 10:28:58 mamarley-laptop systemd-networkd[13111]: DHCPv6 CLIENT: T1 expires in 2min 16s
Jul 06 10:28:58 mamarley-laptop systemd-networkd[13111]: DHCPv6 CLIENT: T2 expires in 3min 7s
Jul 06 10:28:58 mamarley-laptop systemd-networkd[13111]: enx00051bb03daa: DHCPv6 address 2001:db8:0:1::254/128 timeout preferred 200 valid 300
Jul 06 10:28:58 mamarley-laptop systemd-networkd[13111]: enx00051bb03daa: Configuring route: dst: 2001:db8:0:f00::/56, src: n/a, gw: n/a, prefsrc: n/a, scope: global, table: main, proto: 0, type: unreachable
Jul 06 10:28:58 mamarley-laptop systemd-networkd[13111]: enx00051bb03daa: Configuring unreachable route for 2001:db8:0:f00::/56
Jul 06 10:28:58 mamarley-laptop systemd-networkd[13111]: enx00051bb03daa: Assigning up to 256 prefixes from 2001:db8:0:f00::/56
Jul 06 10:28:58 mamarley-laptop systemd-networkd[13111]: pdtarget: The requested prefix 2001:db8:0:f01:: is available. Using it.
Jul 06 10:28:58 mamarley-laptop systemd-networkd[13111]: RADV: Stopping IPv6 Router Advertisement daemon
Jul 06 10:28:58 mamarley-laptop systemd-networkd[13111]: RADV: Updated prefix 2001:db8:0:f01::/64 preferred 3min 20s valid 5min
Jul 06 10:28:58 mamarley-laptop systemd-networkd[13111]: pdtarget: Configuring route: dst: 2001:db8:0:f01::/64, src: n/a, gw: n/a, prefsrc: n/a, scope: global, table: main, proto: 0, type: unicast
Jul 06 10:28:58 mamarley-laptop systemd-networkd[13111]: pdtarget: Adding prefix route 2001:db8:0:f01::/64
Jul 06 10:28:58 mamarley-laptop systemd-networkd[13111]: pdtarget: State changed: configured -> configuring
Jul 06 10:28:58 mamarley-laptop systemd-networkd[13111]: Sent message type=signal sender=n/a destination=n/a path=/org/freedesktop/network1/link/_311 interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=58 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a                                                                                                                               
Jul 06 10:28:58 mamarley-laptop systemd-networkd[13111]: RADV: Started IPv6 Router Advertisement daemon
Jul 06 10:28:58 mamarley-laptop systemd-networkd[13111]: pdtarget: Assigned prefix 2001:db8:0:f01::/64 from 2001:db8:0:f00::/56 to link
Jul 06 10:28:58 mamarley-laptop systemd-networkd[13111]: pdtarget4: The requested prefix 2001:db8:0:f05:: is available. Using it.
Jul 06 10:28:58 mamarley-laptop systemd-networkd[13111]: RADV: Stopping IPv6 Router Advertisement daemon
Jul 06 10:28:58 mamarley-laptop systemd-networkd[13111]: RADV: Updated prefix 2001:db8:0:f05::/64 preferred 3min 20s valid 5min
Jul 06 10:28:58 mamarley-laptop systemd-networkd[13111]: pdtarget4: Configuring route: dst: 2001:db8:0:f05::/64, src: n/a, gw: n/a, prefsrc: n/a, scope: global, table: main, proto: 0, type: unicast
Jul 06 10:28:58 mamarley-laptop systemd-networkd[13111]: pdtarget4: Adding prefix route 2001:db8:0:f05::/64
Jul 06 10:28:58 mamarley-laptop systemd-networkd[13111]: pdtarget4: State changed: configured -> configuring
Jul 06 10:28:58 mamarley-laptop systemd-networkd[13111]: Sent message type=signal sender=n/a destination=n/a path=/org/freedesktop/network1/link/_317 interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=59 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a                                                                                                                               
Jul 06 10:28:58 mamarley-laptop systemd-networkd[13111]: RADV: Started IPv6 Router Advertisement daemon
Jul 06 10:28:58 mamarley-laptop systemd-networkd[13111]: pdtarget4: Assigned prefix 2001:db8:0:f05::/64 from 2001:db8:0:f00::/56 to link
Jul 06 10:28:58 mamarley-laptop systemd-networkd[13111]: pdtarget1: The requested prefix 2001:db8:0:f02:: is available. Using it.
Jul 06 10:28:58 mamarley-laptop systemd-networkd[13111]: RADV: Stopping IPv6 Router Advertisement daemon
Jul 06 10:28:58 mamarley-laptop systemd-networkd[13111]: RADV: Updated prefix 2001:db8:0:f02::/64 preferred 3min 20s valid 5min
Jul 06 10:28:58 mamarley-laptop systemd-networkd[13111]: pdtarget1: Configuring route: dst: 2001:db8:0:f02::/64, src: n/a, gw: n/a, prefsrc: n/a, scope: global, table: main, proto: 0, type: unicast
Jul 06 10:28:58 mamarley-laptop systemd-networkd[13111]: pdtarget1: Adding prefix route 2001:db8:0:f02::/64
Jul 06 10:28:58 mamarley-laptop systemd-networkd[13111]: pdtarget1: State changed: configured -> configuring
Jul 06 10:28:58 mamarley-laptop systemd-networkd[13111]: Sent message type=signal sender=n/a destination=n/a path=/org/freedesktop/network1/link/_314 interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=60 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a                                                                                                                               
Jul 06 10:28:58 mamarley-laptop systemd-networkd[13111]: RADV: Started IPv6 Router Advertisement daemon
Jul 06 10:28:58 mamarley-laptop systemd-networkd[13111]: pdtarget1: Assigned prefix 2001:db8:0:f02::/64 from 2001:db8:0:f00::/56 to link
Jul 06 10:28:58 mamarley-laptop systemd-networkd[13111]: pdtarget3: The requested prefix 2001:db8:0:f04:: is available. Using it.
Jul 06 10:28:58 mamarley-laptop systemd-networkd[13111]: RADV: Stopping IPv6 Router Advertisement daemon
Jul 06 10:28:58 mamarley-laptop systemd-networkd[13111]: RADV: Updated prefix 2001:db8:0:f04::/64 preferred 3min 20s valid 5min
Jul 06 10:28:58 mamarley-laptop systemd-networkd[13111]: pdtarget3: Configuring route: dst: 2001:db8:0:f04::/64, src: n/a, gw: n/a, prefsrc: n/a, scope: global, table: main, proto: 0, type: unicast
Jul 06 10:28:58 mamarley-laptop systemd-networkd[13111]: pdtarget3: Adding prefix route 2001:db8:0:f04::/64
Jul 06 10:28:58 mamarley-laptop systemd-networkd[13111]: pdtarget3: State changed: configured -> configuring
Jul 06 10:28:58 mamarley-laptop systemd-networkd[13111]: Sent message type=signal sender=n/a destination=n/a path=/org/freedesktop/network1/link/_316 interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=61 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a                                                                                                                               
Jul 06 10:28:58 mamarley-laptop systemd-networkd[13111]: RADV: Started IPv6 Router Advertisement daemon
Jul 06 10:28:58 mamarley-laptop systemd-networkd[13111]: pdtarget3: Assigned prefix 2001:db8:0:f04::/64 from 2001:db8:0:f00::/56 to link
Jul 06 10:28:58 mamarley-laptop systemd-networkd[13111]: pdtarget2: The requested prefix 2001:db8:0:f03:: is available. Using it.
Jul 06 10:28:58 mamarley-laptop systemd-networkd[13111]: RADV: Stopping IPv6 Router Advertisement daemon
Jul 06 10:28:58 mamarley-laptop systemd-networkd[13111]: RADV: Updated prefix 2001:db8:0:f03::/64 preferred 3min 20s valid 5min
Jul 06 10:28:58 mamarley-laptop systemd-networkd[13111]: pdtarget2: Configuring route: dst: 2001:db8:0:f03::/64, src: n/a, gw: n/a, prefsrc: n/a, scope: global, table: main, proto: 0, type: unicast
Jul 06 10:28:58 mamarley-laptop systemd-networkd[13111]: pdtarget2: Adding prefix route 2001:db8:0:f03::/64
Jul 06 10:28:58 mamarley-laptop systemd-networkd[13111]: pdtarget2: State changed: configured -> configuring
Jul 06 10:28:58 mamarley-laptop systemd-networkd[13111]: Sent message type=signal sender=n/a destination=n/a path=/org/freedesktop/network1/link/_315 interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=62 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a                                                                                                                               
Jul 06 10:28:58 mamarley-laptop systemd-networkd[13111]: RADV: Started IPv6 Router Advertisement daemon
Jul 06 10:28:58 mamarley-laptop systemd-networkd[13111]: pdtarget2: Assigned prefix 2001:db8:0:f03::/64 from 2001:db8:0:f00::/56 to link
Jul 06 10:28:58 mamarley-laptop systemd-networkd[13111]: enx00051bb03daa: Assigning up to 256 prefixes from 2001:db8:0:f00::/56
Jul 06 10:28:58 mamarley-laptop systemd-networkd[13111]: DHCPv6 CLIENT: Recv REPLY
Jul 06 10:28:58 mamarley-laptop systemd-networkd[13111]: RADV: Next Router Advertisement in 13s
Jul 06 10:28:58 mamarley-laptop systemd-networkd[13111]: RADV: Next Router Advertisement in 8s
Jul 06 10:28:58 mamarley-laptop systemd-networkd[13111]: enx00051bb03daa: Remembering updated address: 2001:db8:0:1::254/128 (valid for 5min)
Jul 06 10:28:58 mamarley-laptop systemd-networkd[13111]: RADV: Next Router Advertisement in 14s
Jul 06 10:28:58 mamarley-laptop systemd-networkd[13111]: RADV: Next Router Advertisement in 8s
Jul 06 10:28:58 mamarley-laptop systemd-networkd[13111]: RADV: Next Router Advertisement in 8s
Jul 06 10:28:58 mamarley-laptop systemd-networkd[13111]: pdtarget: Remembering updated address: 2001:db8:0:f01:e8de:ecff:fe97:3da7/64 (valid for 5min)
Jul 06 10:28:58 mamarley-laptop systemd-networkd[13111]: pdtarget: State changed: configuring -> configured
Jul 06 10:28:58 mamarley-laptop systemd-networkd[13111]: Sent message type=signal sender=n/a destination=n/a path=/org/freedesktop/network1/link/_311 interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=63 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a                                                                                                                               
Jul 06 10:28:58 mamarley-laptop systemd-networkd[13111]: Assertion 'IN_SET(link->state, LINK_STATE_CONFIGURING, LINK_STATE_FAILED, LINK_STATE_LINGER)' failed at src/network/networkd-dhcp6.c:1051, function dhcp6_assign_delegated_prefix_address_handler(). Aborting.
Jul 06 10:28:58 mamarley-laptop systemd[1]: systemd-networkd.service: Main process exited, code=killed, status=6/ABRT
Jul 06 10:28:58 mamarley-laptop systemd[1]: systemd-networkd.service: Failed with result 'signal'.
Jul 06 10:28:58 mamarley-laptop systemd[1]: systemd-networkd.service: Scheduled restart job, restart counter is at 1.
Jul 06 10:28:58 mamarley-laptop systemd[1]: Stopped Network Service.

[mamarley]

Oh, and it seems to happen more (or perhaps only happen if) there are multiple prefix-delegated interfaces. I had five in my example, which reproduces the problem every time. If I had only one, I could not reproduce.

[ssahani]

hmm the link state ie becoming configured I guess link->state . Could you please put in gdb and confirm. Thanks.

[mamarley]

Yep,

(gdb) p link->state
$1 = LINK_STATE_CONFIGURED
(gdb) 

And as soon as I "cont", it aborts.

[ssahani]

if you remove this line https://github.com/systemd/systemd/pull/16366/commits/8975f2422c6a0d212d4b3bac7b8848356e1a6200#diff-30d862b9251b785c8ee19db9d7a0321aR1054 . It won#t happen. But I am waiting for @poettering to respond.

[yuwata]

@mamarley Could you test #16379?

[mamarley]

That works, thanks!