test_02_credit_replenish failure in system_tests_http1_adaptor

[ganeshmurthy]

+++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++ Timeout ++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++

~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ Stack of Thread-44 (_run) (140049403713216) ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
  File "/usr/lib64/python3.11/threading.py", line 995, in _bootstrap
    self._bootstrap_inner()
  File "/usr/lib64/python3.11/threading.py", line 1038, in _bootstrap_inner
    self.run()
  File "/usr/lib64/python3.11/threading.py", line 975, in run
    self._target(*self._args, **self._kwargs)
  File "/home/runner/work/skupper-router/skupper-router/skupper-router/tests/http1_tests.py", line 452, in _run
    server.handle_request()
  File "/usr/lib64/python3.11/socketserver.py", line 297, in handle_request
    return self._handle_request_noblock()
  File "/usr/lib64/python3.11/socketserver.py", line 312, in _handle_request_noblock
    request, client_address = self.get_request()
  File "/home/runner/work/skupper-router/skupper-router/skupper-router/tests/http1_tests.py", line 241, in get_request
    sock, addr = super().get_request()
  File "/usr/lib64/python3.11/socketserver.py", line 505, in get_request
    return self.socket.accept()
  File "/usr/lib64/python3.11/ssl.py", line 1392, in accept
    newsock = self.context.wrap_socket(newsock,
  File "/usr/lib64/python3.11/ssl.py", line 517, in wrap_socket
    return self.sslsocket_class._create(
  File "/usr/lib64/python3.11/ssl.py", line 1075, in _create
    self.do_handshake()
  File "/usr/lib64/python3.11/ssl.py", line 1346, in do_handshake
    self._sslobj.do_handshake()

~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ Stack of Thread-43 (_run) (140049420494528) ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
  File "/usr/lib64/python3.11/threading.py", line 995, in _bootstrap
    self._bootstrap_inner()
  File "/usr/lib64/python3.11/threading.py", line 1038, in _bootstrap_inner
    self.run()
  File "/usr/lib64/python3.11/threading.py", line 975, in run
    self._target(*self._args, **self._kwargs)
  File "/home/runner/work/skupper-router/skupper-router/skupper-router/tests/http1_tests.py", line 452, in _run
    server.handle_request()
  File "/usr/lib64/python3.11/socketserver.py", line 297, in handle_request
    return self._handle_request_noblock()
  File "/usr/lib64/python3.11/socketserver.py", line 317, in _handle_request_noblock
    self.process_request(request, client_address)
  File "/usr/lib64/python3.11/socketserver.py", line 348, in process_request
    self.finish_request(request, client_address)
  File "/usr/lib64/python3.11/socketserver.py", line 361, in finish_request
    self.RequestHandlerClass(request, client_address, self)
  File "/usr/lib64/python3.11/socketserver.py", line 755, in __init__
    self.handle()
  File "/usr/lib64/python3.11/http/server.py", line 434, in handle
    self.handle_one_request()
  File "/usr/lib64/python3.11/http/server.py", line 400, in handle_one_request
    self.raw_requestline = self.rfile.readline(65537)
  File "/usr/lib64/python3.11/socket.py", line 706, in readinto
    return self._sock.recv_into(b)
  File "/usr/lib64/python3.11/ssl.py", line 1278, in recv_into
    return self.read(nbytes, buffer)
  File "/usr/lib64/python3.11/ssl.py", line 1134, in read
    return self._sslobj.read(len, buffer)

+++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++ Timeout ++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++
FAILED
::Http1AdaptorEdge2EdgeTLSTest::test_02_credit_replenish FAILED

https://github.com/skupperproject/skupper-router/actions/runs/4294065080/jobs/7482579568#step:30:3803

[kgiusti]

Looking at the logs it appears that is caused by PROTON-2673

The connection to the test server has been initiated, but there's no corresponding proactor CONNECTED or DISCONNECTED event. No further proactor events arrive. The http1 adaptor is attempting to wake the "in flight" connection but no wake event is generated.

From the server side logs, we can see that the connection has been accepted, but no activity occurs on the connection at all. The last line shows the test is shutting down the server 5 minutes later:

2023-02-28 14:45:35.999357 Accepting new client connection...
2023-02-28 14:50:36.143041 TestServer localhost:29454 requesting shut down

And the logs on the server-facing adaptor consistent with PROTON-2673, the reconnect attempt does not complete and no further proactor events are generated even though the core is trying to wake the connection:

2023-02-28 14:45:35.992410 +0000 HTTP_ADAPTOR (trace) [C2] HTTP server proactor event PN_RAW_CONNECTION_CLOSED_READ (/home/runner/work/skupper-router/skupper-router/skupper-router/src/adaptors/http1/http1_server.c:818)
2023-02-28 14:45:35.992452 +0000 HTTP_ADAPTOR (trace) [C2] HTTP server proactor event PN_RAW_CONNECTION_DISCONNECTED (/home/runner/work/skupper-router/skupper-router/skupper-router/src/adaptors/http1/http1_server.c:818)
2023-02-28 14:45:35.995227 +0000 HTTP_ADAPTOR (debug) [C2] Connecting to HTTP server... (/home/runner/work/skupper-router/skupper-router/skupper-router/src/adaptors/http1/http1_server.c:538)
2023-02-28 14:45:36.063728 +0000 HTTP_ADAPTOR (debug) [C2] Connection activated (/home/runner/work/skupper-router/skupper-router/skupper-router/src/adaptors/http1/http1_adaptor.c:335)
2023-02-28 14:45:36.171534 +0000 HTTP_ADAPTOR (debug) [C2] Connection activated (/home/runner/work/skupper-router/skupper-router/skupper-router/src/adaptors/http1/http1_adaptor.c:335)
2023-02-28 14:45:36.179496 +0000 HTTP_ADAPTOR (debug) [C2] Connection activated (/home/runner/work/skupper-router/skupper-router/skupper-router/src/adaptors/http1/http1_adaptor.c:335)
2023-02-28 14:45:36.181538 +0000 HTTP_ADAPTOR (debug) [C2] Connection activated (/home/runner/work/skupper-router/skupper-router/skupper-router/src/adaptors/http1/http1_adaptor.c:335)
2023-02-28 14:45:36.183426 +0000 HTTP_ADAPTOR (debug) [C2] Connection activated (/home/runner/work/skupper-router/skupper-router/skupper-router/src/adaptors/http1/http1_adaptor.c:335)
2023-02-28 14:45:36.185381 +0000 HTTP_ADAPTOR (debug) [C2] Connection activated (/home/runner/work/skupper-router/skupper-router/skupper-router/src/adaptors/http1/http1_adaptor.c:335)
2023-02-28 14:45:36.187471 +0000 HTTP_ADAPTOR (debug) [C2] Connection activated (/home/runner/work/skupper-router/skupper-router/skupper-router/src/adaptors/http1/http1_adaptor.c:335)
2023-02-28 14:45:36.189456 +0000 HTTP_ADAPTOR (debug) [C2] Connection activated (/home/runner/work/skupper-router/skupper-router/skupper-router/src/adaptors/http1/http1_adaptor.c:335)
2023-02-28 14:45:36.193063 +0000 HTTP_ADAPTOR (debug) [C2] Connection activated (/home/runner/work/skupper-router/skupper-router/skupper-router/src/adaptors/http1/http1_adaptor.c:335)
2023-02-28 14:45:36.196809 +0000 HTTP_ADAPTOR (debug) [C2] Connection activated (/home/runner/work/skupper-router/skupper-router/skupper-router/src/adaptors/http1/http1_adaptor.c:335)
2023-02-28 14:45:36.199083 +0000 HTTP_ADAPTOR (debug) [C2] Connection activated (/home/runner/work/skupper-router/skupper-router/skupper-router/src/adaptors/http1/http1_adaptor.c:335)
2023-02-28 14:45:36.204916 +0000 HTTP_ADAPTOR (debug) [C2] Connection activated (/home/runner/work/skupper-router/skupper-router/skupper-router/src/adaptors/http1/http1_adaptor.c:335)