urllib3.exceptions.ReadTimeoutError: HTTPSConnectionPool in tempest jobs

[Matt Riedemann]

For example:

http://logs.openstack.org/14/554314/1/gate/neutron-tempest-linuxbridge/07e5f8d/job-output.txt.gz#_2018-04-11_00_41_42_274451

2018-04-11 00:41:42.264074 | primary | {0} tempest.api.network.test_ports.PortsTestJSON.test_create_port_in_allowed_allocation_pools [71.645642s] ... FAILED
2018-04-11 00:41:42.264150 | primary |
2018-04-11 00:41:42.264224 | primary | Captured traceback:
2018-04-11 00:41:42.264283 | primary | ~~~~~~~~~~~~~~~~~~~
2018-04-11 00:41:42.264374 | primary | Traceback (most recent call last):
2018-04-11 00:41:42.264575 | primary | File "tempest/api/network/test_ports.py", line 105, in test_create_port_in_allowed_allocation_pools
2018-04-11 00:41:42.264646 | primary | **allocation_pools)
2018-04-11 00:41:42.264777 | primary | File "tempest/api/network/base.py", line 145, in create_subnet
2018-04-11 00:41:42.267762 | primary | **kwargs)
2018-04-11 00:41:42.267966 | primary | File "tempest/lib/services/network/subnets_client.py", line 27, in create_subnet
2018-04-11 00:41:42.268078 | primary | return self.create_resource(uri, post_data)
2018-04-11 00:41:42.268224 | primary | File "tempest/lib/services/network/base.py", line 61, in create_resource
2018-04-11 00:41:42.268335 | primary | resp, body = self.post(req_uri, req_post_data)
2018-04-11 00:41:42.268461 | primary | File "tempest/lib/common/rest_client.py", line 279, in post
2018-04-11 00:41:42.268607 | primary | return self.request('POST', url, extra_headers, headers, body, chunked)
2018-04-11 00:41:42.268737 | primary | File "tempest/lib/common/rest_client.py", line 653, in request
2018-04-11 00:41:42.268817 | primary | body=body, chunked=chunked)
2018-04-11 00:41:42.268948 | primary | File "tempest/lib/common/rest_client.py", line 549, in _request
2018-04-11 00:41:42.269008 | primary | chunked=chunked
2018-04-11 00:41:42.269168 | primary | File "tempest/lib/common/rest_client.py", line 582, in raw_request
2018-04-11 00:41:42.269252 | primary | body=body, chunked=chunked)
2018-04-11 00:41:42.269371 | primary | File "tempest/lib/common/http.py", line 100, in request
2018-04-11 00:41:42.269440 | primary | *args, **new_kwargs)
2018-04-11 00:41:42.269652 | primary | File "/opt/stack/new/tempest/.tox/tempest/local/lib/python2.7/site-packages/urllib3/request.py", line 70, in request
2018-04-11 00:41:42.269711 | primary | **urlopen_kw)
2018-04-11 00:41:42.269944 | primary | File "/opt/stack/new/tempest/.tox/tempest/local/lib/python2.7/site-packages/urllib3/request.py", line 148, in request_encode_body
2018-04-11 00:41:42.270050 | primary | return self.urlopen(method, url, **extra_kw)
2018-04-11 00:41:42.270271 | primary | File "/opt/stack/new/tempest/.tox/tempest/local/lib/python2.7/site-packages/urllib3/poolmanager.py", line 321, in urlopen
2018-04-11 00:41:42.270388 | primary | response = conn.urlopen(method, u.request_uri, **kw)
2018-04-11 00:41:42.270613 | primary | File "/opt/stack/new/tempest/.tox/tempest/local/lib/python2.7/site-packages/urllib3/connectionpool.py", line 639, in urlopen
2018-04-11 00:41:42.270697 | primary | _stacktrace=sys.exc_info()[2])
2018-04-11 00:41:42.270920 | primary | File "/opt/stack/new/tempest/.tox/tempest/local/lib/python2.7/site-packages/urllib3/util/retry.py", line 357, in increment
2018-04-11 00:41:42.271033 | primary | raise six.reraise(type(error), error, _stacktrace)
2018-04-11 00:41:42.272106 | primary | File "/opt/stack/new/tempest/.tox/tempest/local/lib/python2.7/site-packages/urllib3/connectionpool.py", line 601, in urlopen
2018-04-11 00:41:42.273277 | primary | chunked=chunked)
2018-04-11 00:41:42.273561 | primary | File "/opt/stack/new/tempest/.tox/tempest/local/lib/python2.7/site-packages/urllib3/connectionpool.py", line 389, in _make_request
2018-04-11 00:41:42.273714 | primary | self._raise_timeout(err=e, url=url, timeout_value=read_timeout)
2018-04-11 00:41:42.273999 | primary | File "/opt/stack/new/tempest/.tox/tempest/local/lib/python2.7/site-packages/urllib3/connectionpool.py", line 320, in _raise_timeout
2018-04-11 00:41:42.274203 | primary | raise ReadTimeoutError(self, url, "Read timed out. (read timeout=%s)" % timeout_value)
2018-04-11 00:41:42.274451 | primary | urllib3.exceptions.ReadTimeoutError: HTTPSConnectionPool(host='198.72.124.120', port=9696): Read timed out. (read timeout=60)

http://logstash.openstack.org/#dashboard/file/logstash.json?query=message%3A%5C%22urllib3.exceptions.ReadTimeoutError%5C%22%20AND%20tags%3A%5C%22console%5C%22%20AND%20voting%3A1&from=7d

433 hits in 7 days in voting jobs, check and gate, all failures.

I seem to remember we hit this awhile ago (maybe over a year ago) and mtreinish played with keepalive settings in apache config in devstack.

[David Hill (david-hill-ubisoft)]

I get this too on my lab with slow virtual controllers when testing test_dualnet_multi_prefix_dhcpv6_stateless ...

[David Hill (david-hill-ubisoft)]

{0} tempest.scenario.test_network_v6.TestGettingAddress.test_dualnet_slaac_from_os [153.546098s] ... FAILED

Captured traceback:
~~~~~~~~~~~~~~~~~~~
    Traceback (most recent call last):
      File "/usr/lib/python2.7/site-packages/tempest/common/utils/__init__.py", line 89, in wrapper
        return f(*func_args, **func_kwargs)
      File "/usr/lib/python2.7/site-packages/tempest/scenario/test_network_v6.py", line 239, in test_dualnet_slaac_from_os
        self._prepare_and_test(address6_mode='slaac', dualnet=True)
      File "/usr/lib/python2.7/site-packages/tempest/scenario/test_network_v6.py", line 162, in _prepare_and_test
        dualnet=dualnet)
      File "/usr/lib/python2.7/site-packages/tempest/scenario/test_network_v6.py", line 83, in prepare_network
        router = self._get_router()
      File "/usr/lib/python2.7/site-packages/tempest/scenario/manager.py", line 1142, in _get_router
        external_gateway_info=dict(network_id=network_id))['router']
      File "/usr/lib...

[David Hill (david-hill-ubisoft)]

Question: Is the following the proper value to tweak here ?

[service-clients]

#
# From tempest.config
#

# Timeout in seconds to wait for the http request to return (integer
# value)
#http_timeout = 60

[Matt Riedemann (mriedem)]

Slawek noticed that n-api is hitting a MessagingTimeout during a resize call and I traced that down to a POST /allocations call from nova to placement:

http://lists.openstack.org/pipermail/openstack-discuss/2019-October/010494.html