tempest

connection timeout during various create operations

Bug #1999893 reported by Balazs Gibizer
10
This bug affects 1 person
Affects Status Importance Assigned to Milestone
tempest
Confirmed
Undecided
Unassigned

Bug Description

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 |
+----------------------------------+---------------------+----------------+----------+-----------------------------------+--------+------------------------+

Revision history for this message
Martin Kopec (mkopec) wrote :

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

Changed in tempest:
status: New → Confirmed
Revision history for this message
Balazs Gibizer (balazs-gibizer) wrote :

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 |
 +----------------------------------+---------------------+------------------+----------+-----------------------------------+-------------+----------------------------+

Revision history for this message
Sylvain Bauza (sylvain-bauza) wrote :
Download full text (9.9 KiB)

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...

Revision history for this message
yatin (yatinkarel) wrote :

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

To post a comment you must log in.
This report contains Public information  
Everyone can see this information.
Subscribing...

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.