network-next (v256)

[yuwata]

[yuwata]

@mrc0mmand timeout command is broken on Arch Linux??

https://jenkins-systemd.apps.ocp.cloud.ci.centos.org/job/upstream-vagrant-archlinux/9123/artifact/systemd-centos-ci/artifacts_or7fdz1f/vagrant-logs.yn5/vagrant-arch-testsuite.24S/systemd-networkd-tests.py_FAIL.log

[TASK START] Wed Jan  3 08:10:08 PM UTC 2024
...
[  190.516420] systemd-networkd[72040]: SELinux enabled state cached to: disabled
...
[ 1469.719174] systemd-networkd[374416]: Bus bus-api-network: changing state RUNNING → CLOSEDok
test_nexthop (__main__.NetworkdNetworkTests.test_nexthop) ... 
  test_nexthop (__main__.NetworkdNetworkTests.test_nexthop) (manage_foreign_nexthops=True) ... FAIL
Command exited with non-zero status 124
	Command being timed: "timeout -k 60s 60m ./test/test-network/systemd-networkd-tests.py"
	User time (seconds): 16.44
	System time (seconds): 13.66
	Percent of CPU this job got: 0%
	Elapsed (wall clock) time (h:mm:ss or m:ss): 1:00:00
	Average shared text size (kbytes): 0
	Average unshared data size (kbytes): 0
	Average stack size (kbytes): 0
	Average total size (kbytes): 0
	Maximum resident set size (kbytes): 40092
	Average resident set size (kbytes): 0
	Major (requiring I/O) page faults: 50
	Minor (reclaiming a frame) page faults: 1683380
	Voluntary context switches: 57196
	Involuntary context switches: 3118
	Swaps: 0
	File system inputs: 121576
	File system outputs: 37584
	Socket messages sent: 0
	Socket messages received: 0
	Signals delivered: 0
	Page size (bytes): 4096
	Exit status: 124
[TASK END] Wed Jan  3 10:10:08 PM CET 2024

At least, I have no idea about the CI failure in CentOS CI (Arch).

[mrc0mmand]

It looks like systemd-networkd SIGABRTs and the test then just hangs, leading up to a timeout:

[ 2191.770661] systemd-networkd[365738]: veth99: link_check_ready(): static nexthops are not configured.
[ 2191.770681] systemd-networkd[365738]: veth99: Remembering static nexthop (configured): id: 3, gw: ::, blackhole: no, group: n/a, flags: n/a
[ 2191.770700] systemd-networkd[365738]: veth99: Remembering static nexthop (configured): id: 4, gw: 0.0.0.0, blackhole: no, group: n/a, flags: n/a
[ 2191.770719] systemd-networkd[365738]: veth99: Remembering static nexthop (configured): id: 5, gw: 192.168.10.1, blackhole: no, group: n/a, flags: onlink
[ 2191.770744] systemd-networkd[365738]: veth99: Configuring static route (requesting): dst: 10.10.10.12/32, src: n/a, nexthop: 5, prefsrc: n/a, table: main(254), priority: 0, proto: static, scope: global, type: unicast, flags: n/a
[ 2191.770770] systemd-networkd[365738]: Remembering static nexthop (configured): id: 6, gw: 0.0.0.0, blackhole: yes, group: n/a, flags: n/a
[ 2191.770794] systemd-networkd[365738]: Assertion 'e->p.b.key == i->next_key' failed at src/basic/hashmap.c:614, function hashmap_iterate_in_insertion_order(). Aborting.

[yuwata]

Ah, thanks. And the kernel seems to be confused before that:

[ 1472.995259] systemd-networkd[374538]: veth99: netdev removed
[ 1472.995299] systemd-networkd[374538]: Sent message type=signal sender=n/a destination=n/a path=/org/freedesktop/network1 interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=89 reply_cookie=0 signature=sa{sv}as er
ror-name=n/a error-message=n/a
[ 1472.995337] systemd-networkd[374538]: Could not drop route, ignoring: Nexthop id does not exist. Invalid argument
[ 1472.995365] systemd-networkd[374538]: Forgetting static route (configured,removing): dst: 10.10.10.11/32, src: n/a, nexthop: 7, prefsrc: n/a, table: main(254), priority: 0, proto: static, scope: global, type: blackhole, flags: n/a
[ 1472.995390] systemd-networkd[374538]: Could not drop route, ignoring: Nexthop id does not exist. Invalid argument
[ 1472.995413] systemd-networkd[374538]: Forgetting static route (configured,removing): dst: 10.10.10.10/32, src: n/a, nexthop: 6, prefsrc: n/a, table: main(254), priority: 0, proto: static, scope: global, type: blackhole, flags: n/a
[ 1472.995451] systemd-networkd[374538]: Forgetting removed static route (n/a): dst: 10.10.10.14/32, src: n/a, nexthop: 20, prefsrc: n/a, table: main(254), priority: 0, proto: static, scope: global, type: unicast, flags: n/a
[ 1472.995482] systemd-networkd[374538]: Could not drop route, ignoring: Nexthop id does not exist. Invalid argument
[ 1472.995505] systemd-networkd[374538]: Forgetting static route (configured,removing): dst: 10.10.10.12/32, src: n/a, nexthop: 5, prefsrc: n/a, table: main(254), priority: 0, proto: static, scope: global, type: unicast, flags: n/a
[ 1472.995529] systemd-networkd[374538]: Forgetting removed static route (n/a): dst: 2001:1234:5:8f62::2/128, src: n/a, nexthop: 2, prefsrc: n/a, table: main(254), priority: 1024, proto: static, scope: global, type: blackhole, flags: n/a
[ 1472.995568] systemd-networkd[374538]: Could not drop route, ignoring: Nexthop id does not exist. Invalid argument
[ 1472.995597] systemd-networkd[374538]: Forgetting removed static route (n/a): dst: 10.10.10.13/32, src: n/a, nexthop: 1, prefsrc: n/a, table: main(254), priority: 0, proto: static, scope: global, type: blackhole, flags: n/a
[ 1472.995622] systemd-networkd[374538]: Forgetting removed static nexthop (n/a): id: 11, gw: ::, blackhole: yes, group: n/a, flags: n/a
[ 1472.995646] systemd-networkd[374538]: Forgetting removed static nexthop (n/a): id: 2, gw: ::, blackhole: yes, group: n/a, flags: n/a
[ 1472.995678] systemd-networkd[374538]: Could not drop nexthop, ignoring: No such file or directory
[ 1472.995709] systemd-networkd[374538]: Forgetting static nexthop (configured,removing): id: 6, gw: 192.168.5.1, blackhole: no, group: n/a, flags: n/a
[ 1472.995743] systemd-resolved[71981]: Sent message type=signal sender=n/a destination=n/a path=/org/freedesktop/resolve1 interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=5138 reply_cookie=0 signature=sa{sv}as e
rror-name=n/a error-message=n/a
[ 1472.995775] systemd-networkd[374538]: Could not drop nexthop, ignoring: No such file or directory
[ 1472.995800] systemd-networkd[374538]: Forgetting static nexthop (configured,removing): id: 9, gw: 192.168.5.2, blackhole: no, group: n/a, flags: n/a
[ 1472.995829] systemd-networkd[374538]: Forgetting removed static nexthop (n/a): id: 10, gw: 0.0.0.0, blackhole: yes, group: n/a, flags: n/a
[ 1472.995864] systemd-networkd[374538]: Forgetting removed static nexthop (n/a): id: 1, gw: 0.0.0.0, blackhole: yes, group: n/a, flags: n/a
[ 1472.995894] systemd-networkd[374538]: Could not drop nexthop, ignoring: No such file or directory
[ 1472.995918] systemd-networkd[374538]: Forgetting static nexthop (configured,removing): id: 4, gw: ::, blackhole: no, group: n/a, flags: n/a
[ 1472.995947] systemd-networkd[374538]: Could not drop nexthop, ignoring: No such file or directory
[ 1472.995971] systemd-networkd[374538]: Forgetting static nexthop (configured,removing): id: 8, gw: fe80:0:222:4dff:ff:ff:ff:ff, blackhole: no, group: n/a, flags: n/a
[ 1472.996001] systemd-networkd[374538]: Could not drop nexthop, ignoring: No such file or directory
[ 1472.996024] systemd-networkd[374538]: Forgetting static nexthop (configured,removing): id: 5, gw: 192.168.5.3, blackhole: no, group: n/a, flags: n/a
[ 1472.996054] systemd-networkd[374538]: Could not drop nexthop, ignoring: No such file or directory
[ 1472.996082] systemd-networkd[374538]: Forgetting static nexthop (configured,removing): id: 7, gw: 2001:1234:5:8f63::2, blackhole: no, group: n/a, flags: n/a
[ 1472.996107] systemd-networkd[374538]: Could not drop nexthop, ignoring: No such file or directory
[ 1472.996130] systemd-networkd[374538]: Forgetting static nexthop (configured,removing): id: 3, gw: 0.0.0.0, blackhole: no, group: n/a, flags: n/a
[ 1472.996160] systemd-resolved[71981]: Sent message type=signal sender=n/a destination=n/a path=/org/freedesktop/resolve1 interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=5139 reply_cookie=0 signature=sa{sv}as e
rror-name=n/a error-message=n/a
[ 1483.168782] kernel: unregister_netdevice: waiting for veth99 to become free. Usage count = 3
[ 1493.195436] kernel: unregister_netdevice: waiting for veth99 to become free. Usage count = 3
[ 1503.355634] kernel: unregister_netdevice: waiting for veth99 to become free. Usage count = 3
[ 1513.412465] kernel: unregister_netdevice: waiting for veth99 to become free. Usage count = 3
[ 1523.622482] kernel: unregister_netdevice: waiting for veth99 to become free. Usage count = 3
[ 1533.862577] kernel: unregister_netdevice: waiting for veth99 to become free. Usage count = 3
[ 1544.132648] kernel: unregister_netdevice: waiting for veth99 to become free. Usage count = 3

[yuwata]

It seems, for some reason, networkd triggers a kernel bug...

[LiveFreeAndRoam]

👏 I'll rerun the tests on Monday and report my findings here.