CI sometimes fails due to timeout on query to service

[BenjaminPelletier]

Example

Sometimes, the CI checks fail due to a timeout when uss_qualifier queries a service at port 8074; the error message is:

urllib3.exceptions.ReadTimeoutError: HTTPConnectionPool(host='host.docker.internal', port=8074): Read timed out. (read timeout=60)

When the CI is immediately rerun, this error usually disappears.

The service at port 8074 in the standard local deployment (used by CI) is mock_uss providing scdsc capabilities. Unfortunately, the details of this query attempt are not currently captured.

[BenjaminPelletier]

Additional logging and further investigation seem to suggest that this problem arises when the background daemon of mock_uss's atproxy_client functionality stops working. When this happens, a query to atproxy hangs for the timeout limit (currently 1 minute) and then atproxy responds with a 500 indicating that the handler client didn't handle the request. Looking at recent logs, I see these logs from mock_uss with atproxy_client when a getCapabilities request ends up timing out:

2023-02-10 18:42:51.349 | INFO     | monitoring.mock_uss.atproxy_client.daemon:_poll_atproxy:252 - Handling scd.deleteFlight request, id 60523084-6a32-4a5e-8222-d2254479ac2b
2023-02-10 18:42:51.421 | INFO     | monitoring.mock_uss.atproxy_client.daemon:_poll_atproxy:261 - Request 60523084-6a32-4a5e-8222-d2254479ac2b fulfillment has code 200
2023-02-10 18:42:51.627 | INFO     | monitoring.mock_uss.atproxy_client.daemon:_poll_atproxy:288 - Delivered response to request 60523084-6a32-4a5e-8222-d2254479ac2b to atproxy
2023-02-10 18:42:51.844 | INFO     | monitoring.mock_uss.atproxy_client.daemon:_poll_atproxy:252 - Handling scd.getStatus request, id 188ea33f-fe87-4d01-894a-384a270b52ae
2023-02-10 18:42:51.844 | INFO     | monitoring.mock_uss.atproxy_client.daemon:_poll_atproxy:261 - Request 188ea33f-fe87-4d01-894a-384a270b52ae fulfillment has code 200
2023-02-10 18:42:52.037 | INFO     | monitoring.mock_uss.atproxy_client.daemon:_poll_atproxy:288 - Delivered response to request 188ea33f-fe87-4d01-894a-384a270b52ae to atproxy
2023-02-10 18:42:52.245 | INFO     | monitoring.mock_uss.atproxy_client.daemon:_poll_atproxy:252 - Handling scd.getCapabilities request, id 3b1ae055-2f53-4e0a-8a04-822318676e3d
2023-02-10 18:42:52.245 | INFO     | monitoring.mock_uss.atproxy_client.daemon:_poll_atproxy:261 - Request 3b1ae055-2f53-4e0a-8a04-822318676e3d fulfillment has code 200

The last log line is printed from here, and a successful fulfillment would have then later printed one of the lines in this if block, indicating that this query is responsible for the daemon failure. And indeed, the container is later populated with a stacktrace indicating a connection timeout to port 8075 of host.docker.internal. Port 8075 is the canonical local port for atproxy, confirming that the mock_uss atproxy_client daemon is timing out trying to respond back to atproxy with a result.

[BenjaminPelletier]

This failure appears to not be due to atproxy or mock_uss's atproxy_client functionality. Instead, a call to the scdsc mock_uss (port 8074) to inject a flight intent timed out.

uss_qualifier indicates that the request to inject flight 8b4a497a-825b-47dc-a98a-581320dcd562 was initiated at 16:32:01.04, and the failed (timed-out) result reported at 16:33:01.10. The only other mention of 8b4a497a-825b-47dc-a98a-581320dcd562 in uss_qualifier's logs is port-8074 mock_uss's response to a later request to clear the area where it indicates flight 8b4a497a-825b-47dc-a98a-581320dcd562 was deleted.

The logs of port-8074 mock_uss with scdsc functionality pause at 16:31:58.12 ([inject_flight] Releasing placeholder for flight_id 9b4eb91a-9355-4554-bca6-3a293816eda6), and then a log message at 16:33:01.15 indicates that the inject flight handler started running for flight 8b4a497a-825b-47dc-a98a-581320dcd562.

[BenjaminPelletier]

This is apparently a very difficult problem to diagnose; see my comment here for some additional diagnostic work I've done.

After having this problem occur so often on my local machine that I was essentially unable to complete the local_test uss_qualifier configuration, I was able to reproduce with run_containers_host_docker_internal.sh here, but then the problem vanished and I currently can't reproduce the issue on my local machine.

[barroco]

In addition to @BenjaminPelletier investigation, we have been running periodically the CI job to gather data for the past week here. Please note that when the job fails a tcpdump file which can be open with wireshark is available in the job's artifacts.
In parallel, a monitoring tool has been setup to gather metrics on the node running the CI job to make sure the problem is not due to limited resources. You will find below some screenshots with the resource usage of this job. You will note that the error is reported by the test driver at 12:32:26 (UTC-4).