ncat TCP TLS test fails due to inbound data stall on connector-side inbound flow

[kgiusti]

Very rare, but IMHO a serious issue:

Manifests as a timeout failure in CI running the TcpTlsAdaptor.test_76_half_closed_EA1_EC2_large_message test.

See this test failure

The stall is occurring on the TLS stream coming from the echo server into the connector side TLS. While transferring the large message the TCP adaptor stops taking encrypted inbound buffers off of the raw connection. From the trace the raw connection is posting PN_RAW_CONNECTION_READ events for the incoming data, but the adaptor/tls layer is not taking them from the raw conn and moving them into the TLS decryption layer.

Here's the log trace of the incident as given on the connector-side router:

# The last proper transfer of encrypted data from the raw conn to the TLS layer:

2024-05-01 15:25:19.352879 +0000 TCP_ADAPTOR (debug) [C31] on_connection_event_CSIDE_IO: PN_RAW_CONNECTION_READ (/home/runner/work/skupper-router/skupper-router/skupper-router/src/adaptors/tcp/tcp_adaptor.c:1965)
2024-05-01 15:25:19.352902 +0000 TCP_ADAPTOR (debug) [C31] 166 encrypted bytes read from the raw connection passed to TLS for decryption (1 buffers) (/home/runner/work/skupper-router/skupper-router/skupper-router/src/adaptors/adaptor_tls.c:1301)
2024-05-01 15:25:19.352923 +0000 TCP_ADAPTOR (debug) [C31] 144 decrypted bytes taken from TLS for adaptor input (1 buffers) (/home/runner/work/skupper-router/skupper-router/skupper-router/src/adaptors/adaptor_tls.c:1388)
2024-05-01 15:25:19.352945 +0000 TCP_ADAPTOR (debug) [C31] CSIDE TLS read: Produced 144 octets into stream (/home/runner/work/skupper-router/skupper-router/skupper-router/src/adaptors/tcp/tcp_adaptor.c:1545)
2024-05-01 15:25:19.352988 +0000 TCP_ADAPTOR (debug) [C31] grant_read_buffers_XSIDE_IO - 1 (/home/runner/work/skupper-router/skupper-router/skupper-router/src/adaptors/tcp/tcp_adaptor.c:736)

# here is the point where the failure occurs - note that the read event is posted but there are no
# log messages indicating the buffers are being processed:

2024-05-01 15:25:19.353232 +0000 TCP_ADAPTOR (debug) [C31] on_connection_event_CSIDE_IO: PN_RAW_CONNECTION_READ (/home/runner/work/skupper-router/skupper-router/skupper-router/src/adaptors/tcp/tcp_adaptor.c:1965)
2024-05-01 15:25:19.353589 +0000 TCP_ADAPTOR (debug) [C31] on_connection_event_CSIDE_IO: PN_RAW_CONNECTION_READ (/home/runner/work/skupper-router/skupper-router/skupper-router/src/adaptors/tcp/tcp_adaptor.c:1965)
2024-05-01 15:25:19.353869 +0000 TCP_ADAPTOR (debug) [C31] on_connection_event_CSIDE_IO: PN_RAW_CONNECTION_READ (/home/runner/work/skupper-router/skupper-router/skupper-router/src/adaptors/tcp/tcp_adaptor.c:1965)
2024-05-01 15:25:19.354153 +0000 TCP_ADAPTOR (debug) [C31] on_connection_event_CSIDE_IO: PN_RAW_CONNECTION_READ (/home/runner/work/skupper-router/skupper-router/skupper-router/src/adaptors/tcp/tcp_adaptor.c:1965)
2024-05-01 15:25:19.354498 +0000 TCP_ADAPTOR (debug) [C31] on_connection_event_CSIDE_IO: PN_RAW_CONNECTION_READ (/home/runner/work/skupper-router/skupper-router/skupper-router/src/adaptors/tcp/tcp_adaptor.c:1965)
2024-05-01 15:25:19.354525 +0000 TCP_ADAPTOR (debug) [C31] on_connection_event_CSIDE_IO: PN_RAW_CONNECTION_CLOSED_READ (/home/runner/work/skupper-router/skupper-router/skupper-router/src/adaptors/tcp/tcp_adaptor.c:1965)
2024-05-01 15:25:19.354542 +0000 TCP_ADAPTOR (debug) [C31] on_connection_event_CSIDE_IO: PN_RAW_CONNECTION_DRAIN_BUFFERS (/home/runner/work/skupper-router/skupper-router/skupper-router/src/adaptors/tcp/tcp_adaptor.c:1965)
2024-05-01 15:25:19.354557 +0000 TCP_ADAPTOR (debug) [C31] on_connection_event_CSIDE_IO: PN_RAW_CONNECTION_DISCONNECTED (/home/runner/work/skupper-router/skupper-router/skupper-router/src/adaptors/tcp/tcp_adaptor.c:1965)

The closed read/drain/disconnected is expected as the echo client has completed the message transfer.

There are a few reasons why the adaptor will not take buffers from the raw conn: cut through back pressure, proton tls layer back pressure, possibly others.