connection timeout during various create operations

[Balazs Gibizer]

Example run:
https://storage.gra.cloud.ovh.net/v1/AUTH_dcaab5e32b234d56b626f72581e3644c/zuul_opendev_logs_276/854119/12/check/nova-grenade-multinode/2762de2/testr_results.html

Traceback (most recent call last):
  File "/opt/stack/new/tempest/.tox/tempest/lib/python3.8/site-packages/urllib3/connectionpool.py", line 449, in _make_request
    six.raise_from(e, None)
  File "<string>", line 3, in raise_from
  File "/opt/stack/new/tempest/.tox/tempest/lib/python3.8/site-packages/urllib3/connectionpool.py", line 444, in _make_request
    httplib_response = conn.getresponse()
  File "/usr/lib/python3.8/http/client.py", line 1348, in getresponse
    response.begin()
  File "/usr/lib/python3.8/http/client.py", line 316, in begin
    version, status, reason = self._read_status()
  File "/usr/lib/python3.8/http/client.py", line 277, in _read_status
    line = str(self.fp.readline(_MAXLINE + 1), "iso-8859-1")
  File "/usr/lib/python3.8/socket.py", line 669, in readinto
    return self._sock.recv_into(b)
socket.timeout: timed out

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/opt/stack/new/tempest/tempest/common/utils/__init__.py", line 70, in wrapper
    return f(*func_args, **func_kwargs)
  File "/opt/stack/new/tempest/tempest/api/compute/admin/test_live_migration.py", line 168, in test_volume_backed_live_migration
    self._test_live_migration(volume_backed=True)
  File "/opt/stack/new/tempest/tempest/api/compute/admin/test_live_migration.py", line 119, in _test_live_migration
    server_id = self.create_test_server(wait_until="ACTIVE",
  File "/opt/stack/new/tempest/tempest/api/compute/base.py", line 272, in create_test_server
    body, servers = compute.create_test_server(
  File "/opt/stack/new/tempest/tempest/common/compute.py", line 285, in create_test_server
    body = clients.servers_client.create_server(name=name, imageRef=image_id,
  File "/opt/stack/new/tempest/tempest/lib/services/compute/servers_client.py", line 115, in create_server
    resp, body = self.post('servers', post_body)
  File "/opt/stack/new/tempest/tempest/lib/common/rest_client.py", line 299, in post
    return self.request('POST', url, extra_headers, headers, body, chunked)
  File "/opt/stack/new/tempest/tempest/lib/services/compute/base_compute_client.py", line 47, in request
    resp, resp_body = super(BaseComputeClient, self).request(
  File "/opt/stack/new/tempest/tempest/lib/common/rest_client.py", line 704, in request
    resp, resp_body = self._request(method, url, headers=headers,
  File "/opt/stack/new/tempest/tempest/lib/common/rest_client.py", line 583, in _request
    resp, resp_body = self.raw_request(
  File "/opt/stack/new/tempest/tempest/lib/common/rest_client.py", line 623, in raw_request
    resp, resp_body = self.http_obj.request(
  File "/opt/stack/new/tempest/tempest/lib/common/http.py", line 110, in request
    r = super(ClosingHttp, self).request(method, url, retries=retry,
  File "/opt/stack/new/tempest/.tox/tempest/lib/python3.8/site-packages/urllib3/request.py", line 78, in request
    return self.request_encode_body(
  File "/opt/stack/new/tempest/.tox/tempest/lib/python3.8/site-packages/urllib3/request.py", line 170, in request_encode_body
    return self.urlopen(method, url, **extra_kw)
  File "/opt/stack/new/tempest/.tox/tempest/lib/python3.8/site-packages/urllib3/poolmanager.py", line 376, in urlopen
    response = conn.urlopen(method, u.request_uri, **kw)
  File "/opt/stack/new/tempest/.tox/tempest/lib/python3.8/site-packages/urllib3/connectionpool.py", line 787, in urlopen
    retries = retries.increment(
  File "/opt/stack/new/tempest/.tox/tempest/lib/python3.8/site-packages/urllib3/util/retry.py", line 550, in increment
    raise six.reraise(type(error), error, _stacktrace)
  File "/opt/stack/new/tempest/.tox/tempest/lib/python3.8/site-packages/urllib3/packages/six.py", line 770, in reraise
    raise value
  File "/opt/stack/new/tempest/.tox/tempest/lib/python3.8/site-packages/urllib3/connectionpool.py", line 703, in urlopen
    httplib_response = self._make_request(
  File "/opt/stack/new/tempest/.tox/tempest/lib/python3.8/site-packages/urllib3/connectionpool.py", line 451, in _make_request
    self._raise_timeout(err=e, url=url, timeout_value=read_timeout)
  File "/opt/stack/new/tempest/.tox/tempest/lib/python3.8/site-packages/urllib3/connectionpool.py", line 340, in _raise_timeout
    raise ReadTimeoutError(
urllib3.exceptions.ReadTimeoutError: HTTPConnectionPool(host='10.176.196.102', port=80): Read timed out. (read timeout=60)

In this time it was in the _create_server but I saw similar with create_subnet and create_volume too (see below). I checked the nova-api logs from the relevant time frame but no related error there, it seems that nova-api is happily serving traffic during this time window too.

It is not super frequent but it hit my patches more than once:

$ logsearch log --job-group nova-devstack --result FAILURE 'tempest/lib/python.*/site-packages/urllib3/connectionpool.py.*_raise_timeout' 'in create_server|in create_volume|in create_subnet' --days 10
[snip]
Builds with matching logs 6/102:
+----------------------------------+---------------------+----------------+----------+-----------------------------------+--------+------------------------+
| uuid | finished | project | pipeline | review | branch | job |
+----------------------------------+---------------------+----------------+----------+-----------------------------------+--------+------------------------+
| 2762de2ce075445ca896c5b3447c3b1b | 2022-12-16T10:43:46 | openstack/nova | check | https://review.opendev.org/854119 | master | nova-grenade-multinode |
| ce01465c7daf416d87dca61ca700bed4 | 2022-12-15T19:58:56 | openstack/nova | check | https://review.opendev.org/854119 | master | nova-next |
| 984628c7ec1646abb70e15c7edd66e93 | 2022-12-14T18:46:02 | openstack/nova | check | https://review.opendev.org/854119 | master | nova-grenade-multinode |
| 3749534d878a4fb58dbf953134f73f50 | 2022-12-13T16:49:16 | openstack/nova | gate | https://review.opendev.org/854118 | master | nova-grenade-multinode |
| a081e5b038dd461dbcc759cd90313d4a | 2022-12-13T14:35:44 | openstack/nova | check | https://review.opendev.org/862876 | master | tempest-ipv6-only |
| 49ce9311e1c34ebbbfc1ec99fac474cd | 2022-12-11T17:57:16 | openstack/nova | check | https://review.opendev.org/864014 | master | nova-grenade-multinode |
+----------------------------------+---------------------+----------------+----------+-----------------------------------+--------+------------------------+

[Martin Kopec (mkopec)]

Also seen in nova-ceph-multistore job (within this patch - https://review.opendev.org/c/openstack/devstack/+/859773):
https://storage.bhs.cloud.ovh.net/v1/AUTH_dcaab5e32b234d56b626f72581e3644c/zuul_opendev_logs_8eb/859773/4/check/nova-ceph-multistore/8eb52da/testr_results.html

[Balazs Gibizer (balazs-gibizer)]

Here are some recent hits

+----------------------------------+---------------------+------------------+----------+-----------------------------------+-------------+----------------------------+
| uuid | finished | project | pipeline | review | branch | job |
+----------------------------------+---------------------+------------------+----------+-----------------------------------+-------------+----------------------------+
| 61e9b3abfb124273a85dccb3d34d524c | 2023-02-06T23:47:21 | openstack/glance | gate | https://review.opendev.org/864909 | stable/yoga | nova-ceph-multistore |
| 4780e2566a0240a68a6bc7a62f9273ad | 2023-02-06T15:27:41 | openstack/nova | check | https://review.opendev.org/872204 | master | nova-grenade-multinode |
| 2cf69c0d0870412aba4d30b320984506 | 2023-02-06T12:25:26 | openstack/nova | check | https://review.opendev.org/868237 | master | nova-grenade-multinode |
| 4d077a76bd9a4f5d982d893dedd4129f | 2023-02-04T00:36:44 | openstack/nova | gate | https://review.opendev.org/872204 | master | nova-grenade-multinode |
| 1adced198c924f349369a4346e90359b | 2023-02-03T23:58:23 | openstack/nova | gate | https://review.opendev.org/872432 | master | tempest-integrated-compute |
| 1fe6270105774a5696d2b5b71c2d6053 | 2023-02-02T16:56:46 | openstack/nova | check | https://review.opendev.org/872010 | master | nova-next |
| 98e41b496f9b4b6a8f15d7c35c2b0d6a | 2023-02-02T13:01:27 | openstack/nova | check | https://review.opendev.org/851029 | master | nova-grenade-multinode |
| c90bed9ea7e44a38afa1d6133260956b | 2023-02-01T12:56:17 | openstack/nova | check | https://review.opendev.org/872010 | master | nova-next |
+----------------------------------+---------------------+------------------+----------+-----------------------------------+-------------+----------------------------+

[Sylvain Bauza (sylvain-bauza)]

This run is worth looking :
https://b37c807ec9e6a66916f3-1265f2e9e3a0fcf75a00d1718ae30bb8.ssl.cf1.rackcdn.com/873584/1/check/tempest-integrated-compute-enforce-scope-new-defaults/f4dafd1/testr_results.html

It failed on 5 different tests, where 2 different API services were called witout a proper response time :
 - neutron-api for generating a security-group (x1), creating a network (x2) and creating a subnet (x1)
 - glance-api for creating an image

I picked arbitrarly for digging tempest.api.network.test_security_groups_negative.NegativeSecGroupTest.test_create_security_group_rule_with_non_existent_remote_groupid

2023-03-02 13:53:50.114341 | controller | {2} tempest.api.network.test_security_groups_negative.NegativeSecGroupTest.test_create_security_group_rule_with_non_existent_remote_groupid [61.923042s] ... FAILED
2023-03-02 13:53:50.114360 | controller |
2023-03-02 13:53:50.114366 | controller | Captured traceback:
2023-03-02 13:53:50.114372 | controller | ~~~~~~~~~~~~~~~~~~~
2023-03-02 13:53:50.114376 | controller | Traceback (most recent call last):
2023-03-02 13:53:50.114382 | controller |
2023-03-02 13:53:50.114387 | controller | File "/opt/stack/tempest/.tox/tempest/lib/python3.10/site-packages/urllib3/connectionpool.py", line 449, in _make_request
2023-03-02 13:53:50.114392 | controller | six.raise_from(e, None)
2023-03-02 13:53:50.114397 | controller |
2023-03-02 13:53:50.114702 | controller | File "<string>", line 3, in raise_from
2023-03-02 13:53:50.114712 | controller |
2023-03-02 13:53:50.114735 | controller | File "/opt/stack/tempest/.tox/tempest/lib/python3.10/site-packages/urllib3/connectionpool.py", line 444, in _make_request
2023-03-02 13:53:50.114741 | controller | httplib_response = conn.getresponse()
2023-03-02 13:53:50.114765 | controller |
2023-03-02 13:53:50.114780 | controller | File "/usr/lib/python3.10/http/client.py", line 1374, in getresponse
2023-03-02 13:53:50.114786 | controller | response.begin()
2023-03-02 13:53:50.114790 | controller |
2023-03-02 13:53:50.115005 | controller | File "/usr/lib/python3.10/http/client.py", line 318, in begin
2023-03-02 13:53:50.115013 | controller | version, status, reason = self._read_status()
2023-03-02 13:53:50.115018 | controller |
2023-03-02 13:53:50.115023 | controller | File "/usr/lib/python3.10/http/client.py", line 279, in _read_status
2023-03-02 13:53:50.115027 | controller | line = str(self.fp.readline(_MAXLINE + 1), "iso-8859-1")
2023-03-02 13:53:50.115032 | controller |
2023-03-02 13:53:50.115037 | controller | File "/usr/lib/python3.10/socket.py", line 705, in readinto
2023-03-02 13:53:50.115041 | controller | return self._sock.recv_into(b)
2023-03-02 13:53:50.115046 | controller |
2023-03-02 13:53:50.115050 | controller | File "/usr/lib/python3.10/ssl.py", line 1274, in recv_into
2023-03-02 13:53:50.115055 | controller | return self.read(nbytes, buffer)
2023-03-02 13:53:50.115059 | controller |
2023-03-02 13:53:50.115070 | controller | File "/usr/lib/python3.10/ssl.py", line 1130, in read
2023-03-02 13:53:50.115075 | controller | return self._sslobj.read(len, buffer)
2023...

[yatin (yatinkarel)]

We seen it in neutron too and investigated as part of https://bugs.launchpad.net/neutron/+bug/2015065, root cause not known yet but please check if you have some idea