[DISPATCH-1927] TCP adaptor Assertion `(link->undelivered).head' failed.

• Type: Bug
• Status: Closed
• Priority: Major
• Resolution: Fixed
• Fix Version/s: 1.15.0
• Component/s: Protocol Adaptors, Router Node

Environment

Fedora 31

• Assignee: Ted Ross
• Reporter: Charles E. Rolke
• Created: 22/Jan/21 15:54
• Updated: 11/Feb/21 17:55
• Resolved: 03/Feb/21 16:31

Description

Test setup:

• Proton git: branch master @ 5e7d7af8f
• Dispatch git: branch master @ ec39e5e
• Debug build
• Running the configuration described in DISPATCH-1777

Seven clients run TCP_echo_client continuously against the server:

• Four run  --size 0
• One runs --size 100
• One runs --size 100000
• One runs --size 1000000

Eventually the router running the tcpConnector fails with the assertion.

Tail of the router log:

Two router setup with a TCP listener on one router and a TCP connector on the other router.
 This is the log from the second tcpConnector router

     Here comes a message from core to TCP needing a new connection to egress server
2021-01-22 09:37:57.979054 -0500 TCP_ADAPTOR (debug) [C1] on_activate
2021-01-22 09:37:57.979594 -0500 TCP_ADAPTOR (debug) [C1][L1] qdr_tcp_push
2021-01-22 09:37:57.979619 -0500 TCP_ADAPTOR (debug) [C1][L1][D46793] qdr_tcp_deliver Delivery event
2021-01-22 09:37:57.979641 -0500 TCP_ADAPTOR (debug) [C1][L1][D46793] tcp_adaptor initiating egress connection
2021-01-22 09:37:57.979671 -0500 TCP_ADAPTOR (info) [C11768] Connecting to: 127.0.0.1:9090
2021-01-22 09:37:57.979789 -0500 TCP_ADAPTOR (debug) [C11767] qdr_tcp_activate: waking raw connection
2021-01-22 09:37:57.979974 -0500 TCP_ADAPTOR (info) [C11768] PN_RAW_CONNECTION_CONNECTED Egress connected to 127.0.0.1:9090
2021-01-22 09:37:57.980003 -0500 TCP_ADAPTOR (info) [C11768] Opening server-side core connection 127.0.0.1:9090
2021-01-22 09:37:57.980057 -0500 ROUTER_CORE (info) [C11768] Connection Opened: dir=out host=127.0.0.1:9090 vhost= encrypted=no auth=no user= container_id=TcpAdaptor props=

     Delivery is handed off to new connection/link
2021-01-22 09:37:57.980153 -0500 TCP_ADAPTOR (debug) [C1][L1][D46793] initial_delivery ownership passed to [C11768][L23564][D46793]

2021-01-22 09:37:57.980191 -0500 TCP_ADAPTOR (debug) [C11768] PN_RAW_CONNECTION_NEED_WRITE_BUFFERS
2021-01-22 09:37:57.980215 -0500 TCP_ADAPTOR (debug) [C11768] PN_RAW_CONNECTION_NEED_READ_BUFFERS
2021-01-22 09:37:57.980243 -0500 TCP_ADAPTOR (debug) [C11768][L23564] Waiting for credit to initiate message

     POOF! link_process_delivery has no deliveries yet.
     This is happening too soon. Probably.
qdrouterd: /home/chug/git/qpid-dispatch/src/router_core/transfer.c:231: qdr_link_process_deliveries: Assertion `(link->undelivered).head' failed.
     from gdb: delivery_id = 46793, link_id = 23564, conn_id = 11768 or: [C11768][L23564][D46793] for failed process

     Moments later the rest of the connection/link setup happens
2021-01-22 09:37:57.980312 -0500 ROUTER_CORE (info) [C11768][L23564] Link attached: dir=out source={foo expire:link} target={<none> expire:link}
2021-01-22 09:37:57.980332 -0500 TCP_ADAPTOR (debug) [C11768] qdr_tcp_activate: waking raw connection
2021-01-22 09:37:57.980356 -0500 TCP_ADAPTOR (debug) [C11767] qdr_tcp_activate: waking raw connection
2021-01-22 09:37:57.980386 -0500 TCP_ADAPTOR (debug) [C11768] PN_RAW_CONNECTION_WAKE
2021-01-22 09:37:57.980404 -0500 TCP_ADAPTOR (debug) [C11768][L23564] qdr_tcp_second_attach
2021-01-22 09:37:57.980430 -0500 TCP_ADAPTOR (debug) [C11768][L23564] qdr_tcp_get_credit: NOOP
2021-01-22 09:37:57.980453 -0500 TCP_ADAPTOR (debug) [C11768][L23564] qdr_tcp_push
2021-01-22 09:37:57.980471 -0500 TCP_ADAPTOR (debug) [C11768][L23564][D46793] qdr_tcp_deliver Delivery event
2021-01-22 09:37:57.980563 -0500 TCP_ADAPTOR (debug) [C11768][L23565] Create Link to amqp:/_topo/0/router-b/temp.tsMXbvjL9M01_l8
2021-01-22 09:37:57.980591 -0500 TCP_ADAPTOR (debug) [C11768][L23564] Waiting for credit to initiate message
2021-01-22 09:37:57.980621 -0500 TCP_ADAPTOR (debug) [C11768] Writing 2040 bytes
2021-01-22 09:37:57.980640 -0500 TCP_ADAPTOR (debug) [C11768] Writing 2048 bytes
2021-01-22 09:37:57.980657 -0500 TCP_ADAPTOR (debug) [C11768] Writing 2048 bytes
2021-01-22 09:37:57.980674 -0500 TCP_ADAPTOR (debug) [C11768] Writing 1104 bytes
2021-01-22 09:37:57.980691 -0500 TCP_ADAPTOR (debug) [C11768][L23564] qdr_tcp_get_credit: NOOP
Aborted (core dumped)

 

Issue Links

• relates to: DISPATCH-1951 system_tests_http2 failing with router crash