Assertion error in system_tests_cert_rotation.py

[ganeshmurthy]

>       self.assertTrue(ok, f"Bad control links: {router_C.get_active_inter_router_control_links()}")
E       AssertionError: None is not true : Bad control links: [{'name': 'qdlink.ZGyofWN43urhRE7', 'identity': '5', 'type': 'io.skupper.router.router.link', 'linkName': 'qdlink.ZGyofWN43urhRE7', 'linkType': 'router-control', 'linkDir': 'in', 'owningAddr': None, 'capacity': uint(250), 'undeliveredCount': ulong(0), 'unsettledCount': ulong(0), 'deliveryCount': ulong(13), 'connectionId': '13', 'operStatus': 'up', 'presettledCount': ulong(13), 'droppedPresettledCount': ulong(0), 'acceptedCount': ulong(0), 'rejectedCount': ulong(0), 'releasedCount': ulong(0), 'modifiedCount': ulong(0), 'deliveriesDelayed1Sec': ulong(0), 'deliveriesDelayed10Sec': ulong(0), 'deliveriesStuck': ulong(0), 'openMovedStreams': ulong(0), 'ingressHistogram': None, 'priority': uint(9), 'settleRate': uint(0), 'creditAvailable': uint(250), 'zeroCreditSeconds': uint(0), '': None}, {'name': 'qdlink.5Cea2ObuB3BxGiO', 'identity': '77', 'type': 'io.skupper.router.router.link', 'linkName': 'qdlink.5Cea2ObuB3BxGiO', 'linkType': 'router-control', 'linkDir': 'in', 'owningAddr': None, 'capacity': uint(250), 'undeliveredCount': ulong(0), 'unsettledCount': ulong(0), 'deliveryCount': ulong(310), 'connectionId': '30', 'operStatus': 'up', 'presettledCount': ulong(310), 'droppedPresettledCount': ulong(0), 'acceptedCount': ulong(0), 'rejectedCount': ulong(0), 'releasedCount': ulong(0), 'modifiedCount': ulong(0), 'deliveriesDelayed1Sec': ulong(0), 'deliveriesDelayed10Sec': ulong(0), 'deliveriesStuck': ulong(0), 'openMovedStreams': ulong(0), 'ingressHistogram': None, 'priority': uint(9), 'settleRate': uint(0), 'creditAvailable': uint(250), 'zeroCreditSeconds': uint(0), '': None}, {'name': 'qdlink.7rnN0h43z2f06+g', 'identity': '78', 'type': 'io.skupper.router.router.link', 'linkName': 'qdlink.7rnN0h43z2f06+g', 'linkType': 'router-control', 'linkDir': 'out', 'owningAddr': 'Lqdhello', 'capacity': uint(250), 'undeliveredCount': ulong(0), 'unsettledCount': ulong(0), 'deliveryCount': ulong(309), 'connectionId': '30', 'operStatus': 'up', 'presettledCount': ulong(309), 'droppedPresettledCount': ulong(0), 'acceptedCount': ulong(0), 'rejectedCount': ulong(0), 'releasedCount': ulong(0), 'modifiedCount': ulong(0), 'deliveriesDelayed1Sec': ulong(0), 'deliveriesDelayed10Sec': ulong(0), 'deliveriesStuck': ulong(0), 'openMovedStreams': ulong(0), 'ingressHistogram': None, 'priority': uint(9), 'settleRate': uint(1), 'creditAvailable': uint(250), 'zeroCreditSeconds': uint(0), '': None}]

/home/runner/work/skupper-router/skupper-router/skupper-router/tests/system_tests_cert_rotation.py:348: AssertionError

https://github.com/skupperproject/skupper-router/actions/runs/14378608842/job/40316846127?pr=1775#step:33:4703

[kgiusti]

Analysis of logs:

The connector-side router appears to be correctly upgrading to the new connection. As part of that upgrade it will detach the two control links. I see those detaches being sent in the connector-side router's logs.

I can also see these detaches arrive on the listener-side router in the protocol trace. I can see that the listener router then processes the detaches, but one of the links never completes the detach and only one reply detach is sent:

**** Detaches arrive for both control links
2025-04-10 10:54:33.522313 +0000 PROTOCOL (debug) [C2]:FRAME: 0 <- @detach(22) [handle=0x0, closed=true] (/home/runner/work/skupper-router/skupper-router/skupper-router/src/adaptors/amqp/qd_connection.c:55)
2025-04-10 10:54:33.522330 +0000 PROTOCOL (debug) [C2]:FRAME: 0 <- @detach(22) [handle=0x1, closed=true] (/home/runner/work/skupper-router/skupper-router/skupper-router/src/adaptors/amqp/qd_connection.c:55)

*** detach for L1 is handled but NO DETACH SENT:
2025-04-10 10:54:33.522392 +0000 ROUTER_CORE (debug) Core action 'link_detach_received' (/home/runner/work/skupper-router/skupper-router/skupper-router/src/router_core/router_core_thread.c:250)
2025-04-10 10:54:33.522421 +0000 ROUTER_CORE (debug) [C2][L1] qdr_link_inbound_detach_CT() (/home/runner/work/skupper-router/skupper-router/skupper-router/src/router_core/connections.c:2588)
2025-04-10 10:54:33.522450 +0000 ROUTER_CORE (debug) [C2] Detaching outgoing router control link [L1] (/home/runner/work/skupper-router/skupper-router/skupper-router/src/router_core/connections.c:2012)
2025-04-10 10:54:33.522469 +0000 ROUTER_CORE (debug) [C2][L1][D184] Delivery outcome pre-settled: is unknown (0x0) (/home/runner/work/skupper-router/skupper-router/skupper-router/src/router_core/delivery.c:400)
2025-04-10 10:54:33.522483 +0000 ROUTER_CORE (debug) [C2][L1][D184] Delivery decref_CT: rc:0 qdr_link_cleanup_deliveries_CT - remove from undelivered list (/home/runner/work/skupper-router/skupper-router/skupper-router/src/router_core/delivery.c:679)

*** detach for L2 is handled, detach sent as expected:
2025-04-10 10:54:33.522544 +0000 ROUTER_CORE (debug) Core action 'link_detach_received' (/home/runner/work/skupper-router/skupper-router/skupper-router/src/router_core/router_core_thread.c:250)
2025-04-10 10:54:33.522558 +0000 ROUTER_CORE (debug) [C2][L2] qdr_link_inbound_detach_CT() (/home/runner/work/skupper-router/skupper-router/skupper-router/src/router_core/connections.c:2588)
2025-04-10 10:54:33.522568 +0000 ROUTER_CORE (debug) [C2] Detaching incoming router control link [L2] (/home/runner/work/skupper-router/skupper-router/skupper-router/src/router_core/connections.c:2012)
2025-04-10 10:54:33.522620 +0000 ROUTER_CORE (debug) Core action 'link_notify_closed' (/home/runner/work/skupper-router/skupper-router/skupper-router/src/router_core/router_core_thread.c:250)
2025-04-10 10:54:33.522633 +0000 ROUTER_CORE (debug) [C2][L2] Link closed: del=15 presett=15 psdrop=0 acc=0 rej=0 rel=0 mod=0 delay1=0 delay10=0 blocked=no (/home/runner/work/skupper-router/skupper-router/skupper-router/src/router_core/connections.c:1157)
2025-04-10 10:54:33.522711 +0000 PROTOCOL (debug) [C2]:FRAME: 0 -> @detach(22) [handle=0x1, closed=true] (/home/runner/work/skupper-router/skupper-router/skupper-router/src/adaptors/amqp/qd_connection.c:55)

I appears that the 'link_notify_closed' core action is not being issued for the L1 link. This is a problem and explains why the test failed.

[kgiusti]

The most likely explanation is that the detach failed to be sent is probably due to the following conditional check evaluating to false:

skupper-router/src/router_core/connections.c

Line 2603 in cd290cb

if (first_detach) {

But in order for that to be the case then a detach should have already been sent, which according to the protocol logs has not happened.

Since this is hard to reproduce I propose adding a bit more debug logging to the path to see if we can better understand the flow.

[kgiusti]

Just added more debug logic - bug still remains.