RouterTestSslInterRouter::test_connected_tls_sasl_routers, part of system_tests_ssl, takes a long time (>300s)

[jiridanek]

https://github.com/skupperproject/skupper-router/runs/6253209682?check_suite_focus=true#step:26:3238

Note the time difference between previous passing test at 06:48:43 and test_connected_tls_sasl_routers passing at 06:53:52.

2022-05-02T06:48:43.2487811Z 40: ::RouterTestSslClient::test_tls_all �[32mPASSED�[0m
2022-05-02T06:48:43.2492787Z 40: Router QDR.A output file:
2022-05-02T06:48:43.2496696Z 40: >>>>
2022-05-02T06:48:43.2500996Z 40: -----------------------------------------------------
2022-05-02T06:48:43.2504875Z 40: Suppressions used:
2022-05-02T06:48:43.2508657Z 40:   count      bytes template
2022-05-02T06:48:43.2512522Z 40:       4        224 ^IoAdapter_init$
2022-05-02T06:48:43.2516288Z 40:     720     708025 /libpython3.*.so
2022-05-02T06:48:43.2520386Z 40: -----------------------------------------------------
2022-05-02T06:48:43.2524265Z 40: 
2022-05-02T06:48:43.2565966Z 40: 
2022-05-02T06:48:43.2566201Z 40: <<<<
2022-05-02T06:48:43.2566398Z 40: 

[...]

2022-05-02T06:53:52.3057972Z 40: ::RouterTestSslInterRouter::test_connected_tls_sasl_routers �[32mPASSED�[0m

[...]

32/32 Test #40: system_tests_ssl ......................   Passed  325.81 sec

It seems an invariable rule that the ssl tests always finish last.

After setting a 300s timeout per test (here meaning python test method), which is IMO still overly generous, the test gets reported as exceeding that timeout

https://github.com/skupperproject/skupper-router/runs/6263670044?check_suite_focus=true#step:26:3841

        # Wait till listener is running and all expected connectors are connected
        cls.routers[0].wait_ports()
        for router in cls.connected_tls_sasl_routers[1:]:
>           cls.routers[0].wait_router_connected(router)

/home/runner/work/skupper-router/skupper-router/skupper-router/tests/system_tests_ssl.py:744: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 
/home/runner/work/skupper-router/skupper-router/skupper-router/tests/system_test.py:818: in wait_router_connected
    retry(lambda: self.is_router_connected(router_id), **retry_kwargs)
/home/runner/work/skupper-router/skupper-router/skupper-router/tests/system_test.py:144: in retry
    delay = retry_delay(deadline, delay, max_delay)
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 

deadline = 1651524401.7453303, delay = 1, max_delay = 1

    def retry_delay(deadline, delay, max_delay):
        """For internal use in retry. Sleep as required
        and return the new delay or None if retry should time out"""
        remaining = deadline - time.time()
        if remaining <= 0:
            return None
>       time.sleep(min(delay, remaining))
E       Failed: Timeout >300.0s

/home/runner/work/skupper-router/skupper-router/skupper-router/tests/system_test.py:124: Failed
---------------------------------------------------------------------- Captured log setup ----------------------------------------------------------------------
INFO     proton:_reactor.py:1053 Connecting to Url('amqp://0.0.0.0:29029')...
INFO     proton:_reactor.py:1091 Connected to 0.0.0.0
INFO     proton:_reactor.py:1053 Connecting to Url('amqp://0.0.0.0:29029')...
INFO     proton:_reactor.py:1091 Connected to 0.0.0.0
INFO     proton:_reactor.py:1105 Disconnected, already closed
INFO     proton:_reactor.py:1053 Connecting to Url('amqp://0.0.0.0:29029')...
INFO     proton:_reactor.py:1091 Connected to 0.0.0.0
INFO     proton:_reactor.py:1105 Disconnected, already closed
======================================================================= warnings summary =======================================================================

[ganeshmurthy]

I added some prints in the associated PR. This is what I see locally -

44: QDR.A to  QDR.B connecting time: 7.25615668296814 seconds
44: QDR.A to  QDR.C connecting time: 0.021644115447998047 seconds
44: QDR.A to  QDR.D connecting time: 60.00566530227661 seconds
44: test_connected_tls_sasl_routers Execution time: 0.050333499908447266 seconds

Will be interesting to see what the CI reports.

[jiridanek]

Such suspense, I could not resist and had a peek

https://github.com/ganeshmurthy/skupper-router/runs/6275527291?check_suite_focus=true#step:26:3209

40: ::RouterTestSslInterRouter::test_connected_tls_sasl_routers QDR.A to  QDR.B connecting time: 2.0318427085876465 seconds
40: QDR.A to  QDR.C connecting time: 0.07413935661315918 seconds
40: QDR.A to  QDR.D connecting time: 300.0044779777527 seconds
40: test_connected_tls_sasl_routers Execution time: 0.0192108154296875 seconds

Both 60 and 300 are values of QPID_SYSTEM_TEST_TIMEOUT. 60 is the default, and 300 is increased timeout for CI.

[jiridanek]

Not resolved, test still takes long time

[ganeshmurthy]

Not resolved, test still takes long time

I did not use 'Fixes #420' in my commit message but that did not matter, the issue was still closed !!(??)!!

[jiridanek]

I think that @kgiusti is responsible for that :P

[jiridanek]

In any case, I get email when my issues get closed, and the issue list is still of manageable size, so I can remember context and scream "not fixed!"

[ganeshmurthy]

Gotcha ! Thanks.

[ganeshmurthy]

Closing this, might reopen if this problem shows up again.