test_image_web_download_import_with_bad_url failing within nova-ceph-multistore on stable/victoria

[Lee Yarwood]

https://536c35b8827b8b580224-106821bd54633d9ce36b8ab43069ea80.ssl.cf2.rackcdn.com/773443/1/gate/nova-ceph-multistore/7c92011/testr_results.html

2021-03-18 04:01:56,230 102018 INFO [tempest.lib.common.rest_client] Request (ImportImagesNegativeTest:test_image_web_download_import_with_bad_url): 202 POST https://199.204.45.116/image/v2/images/7ef5bb22-17b7-4ebc-9d2f-e77e763ce88f/import 0.066s
2021-03-18 04:01:56,230 102018 DEBUG [tempest.lib.common.rest_client] Request - Headers: {'Content-Type': 'application/json', 'X-Auth-Token': '<omitted>'}
        Body: {"method": {"name": "web-download", "uri": "http://does-not.exist/no/possible/way"}, "stores": ["cheap"]}
    Response - Headers: {'date': 'Thu, 18 Mar 2021 04:01:56 GMT', 'server': 'Apache/2.4.41 (Ubuntu)', 'content-type': 'text/html; charset=UTF-8', 'content-length': '0', 'x-openstack-request-id': 'req-35969d62-34d9-4fc6-a9f4-deeff7e0b142', 'connection': 'close', 'status': '202', 'content-location': 'https://199.204.45.116/image/v2/images/7ef5bb22-17b7-4ebc-9d2f-e77e763ce88f/import'}
        Body: b''
[..]
2021-03-18 04:06:56,108 102018 INFO [tempest.lib.common.rest_client] Request (ImportImagesNegativeTest:test_image_web_download_import_with_bad_url): 200 GET https://199.204.45.116/image/v2/images/7ef5bb22-17b7-4ebc-9d2f-e77e763ce88f 0.137s
2021-03-18 04:06:56,108 102018 DEBUG [tempest.lib.common.rest_client] Request - Headers: {'Content-Type': 'application/json', 'Accept': 'application/json', 'X-Auth-Token': '<omitted>'}
        Body: None
    Response - Headers: {'date': 'Thu, 18 Mar 2021 04:06:56 GMT', 'server': 'Apache/2.4.41 (Ubuntu)', 'content-length': '701', 'content-type': 'application/json', 'x-openstack-request-id': 'req-ba7d93bd-4f2e-4dfb-913f-6e82405f4591', 'connection': 'close', 'status': '200', 'content-location': 'https://199.204.45.116/image/v2/images/7ef5bb22-17b7-4ebc-9d2f-e77e763ce88f'}
        Body: b'{"os_glance_failed_import": "", "os_glance_importing_to_stores": "cheap", "name": "test", "disk_format": "raw", "container_format": "bare", "visibility": "shared", "size": null, "virtual_size": null, "status": "queued", "checksum": null, "protected": false, "min_ram": 0, "min_disk": 0, "owner": "de094f49898048a9baa9fafcc74658cb", "os_hidden": false, "os_hash_algo": null, "os_hash_value": null, "id": "7ef5bb22-17b7-4ebc-9d2f-e77e763ce88f", "created_at": "2021-03-18T04:01:56Z", "updated_at": "2021-03-18T04:01:56Z", "locations": [], "tags": [], "self": "/v2/images/7ef5bb22-17b7-4ebc-9d2f-e77e763ce88f", "file": "/v2/images/7ef5bb22-17b7-4ebc-9d2f-e77e763ce88f/file", "schema": "/v2/schemas/image"}'
}}}
[..]
Traceback (most recent call last):
  File "/opt/stack/tempest/tempest/api/image/v2/test_images_negative.py", line 220, in test_image_web_download_import_with_bad_url
    self.fail('Image never reported failed store')
  File "/opt/stack/tempest/.tox/tempest/lib/python3.8/site-packages/unittest2/case.py", line 690, in fail
    raise self.failureException(msg)
AssertionError: Image never reported failed store

https://zuul.opendev.org/t/openstack/build/7c920114e97d423fb226985323939b54/log/controller/logs/screen-g-api.txt#10580

Mar 18 04:01:56.393057 ubuntu-focal-vexxhost-ca-ymq-1-0023551666 glance-api[96125]: ERROR glance.async_.flows._internal_plugins.web_download [-] Task 7f38e9e0-6bdb-4bb1-af3c-07c4ede01995 failed with exception <urlopen error [Errno -2] No address found>: urllib.error.URLError: <urlopen error [Errno -2] No address found>
Mar 18 04:01:56.397031 ubuntu-focal-vexxhost-ca-ymq-1-0023551666 glance-api[96125]: WARNING glance.async_.taskflow_executor [-] Task 'api_image_import-WebDownload-7f38e9e0-6bdb-4bb1-af3c-07c4ede01995' (14a04079-502c-4823-971d-865df9fc9c47) transitioned into state 'FAILURE' from state 'RUNNING'
Mar 18 04:01:56.397031 ubuntu-focal-vexxhost-ca-ymq-1-0023551666 glance-api[96125]: 4 predecessors (most recent first):
Mar 18 04:01:56.397031 ubuntu-focal-vexxhost-ca-ymq-1-0023551666 glance-api[96125]: Flow 'api_image_import'
Mar 18 04:01:56.397031 ubuntu-focal-vexxhost-ca-ymq-1-0023551666 glance-api[96125]: |__Atom 'api_image_import-ImageLock-7f38e9e0-6bdb-4bb1-af3c-07c4ede01995' {'intention': 'EXECUTE', 'state': 'SUCCESS', 'requires': {}, 'provides': None}
Mar 18 04:01:56.397031 ubuntu-focal-vexxhost-ca-ymq-1-0023551666 glance-api[96125]: |__Atom 'api_image_import_retry' {'intention': 'EXECUTE', 'state': 'SUCCESS', 'requires': {}, 'provides': [(None, {})]}
Mar 18 04:01:56.397031 ubuntu-focal-vexxhost-ca-ymq-1-0023551666 glance-api[96125]: |__Flow 'api_image_import': urllib.error.URLError: <urlopen error [Errno -2] No address found>
Mar 18 04:01:56.397031 ubuntu-focal-vexxhost-ca-ymq-1-0023551666 glance-api[96125]: ERROR glance.async_.taskflow_executor Traceback (most recent call last):
Mar 18 04:01:56.397031 ubuntu-focal-vexxhost-ca-ymq-1-0023551666 glance-api[96125]: ERROR glance.async_.taskflow_executor File "/usr/lib/python3.8/urllib/request.py", line 1350, in do_open
Mar 18 04:01:56.397031 ubuntu-focal-vexxhost-ca-ymq-1-0023551666 glance-api[96125]: ERROR glance.async_.taskflow_executor h.request(req.get_method(), req.selector, req.data, headers,
Mar 18 04:01:56.397031 ubuntu-focal-vexxhost-ca-ymq-1-0023551666 glance-api[96125]: ERROR glance.async_.taskflow_executor File "/usr/lib/python3.8/http/client.py", line 1255, in request
Mar 18 04:01:56.397031 ubuntu-focal-vexxhost-ca-ymq-1-0023551666 glance-api[96125]: ERROR glance.async_.taskflow_executor self._send_request(method, url, body, headers, encode_chunked)
Mar 18 04:01:56.397031 ubuntu-focal-vexxhost-ca-ymq-1-0023551666 glance-api[96125]: ERROR glance.async_.taskflow_executor File "/usr/lib/python3.8/http/client.py", line 1301, in _send_request
Mar 18 04:01:56.397031 ubuntu-focal-vexxhost-ca-ymq-1-0023551666 glance-api[96125]: ERROR glance.async_.taskflow_executor self.endheaders(body, encode_chunked=encode_chunked)
Mar 18 04:01:56.397031 ubuntu-focal-vexxhost-ca-ymq-1-0023551666 glance-api[96125]: ERROR glance.async_.taskflow_executor File "/usr/lib/python3.8/http/client.py", line 1250, in endheaders
Mar 18 04:01:56.397031 ubuntu-focal-vexxhost-ca-ymq-1-0023551666 glance-api[96125]: ERROR glance.async_.taskflow_executor self._send_output(message_body, encode_chunked=encode_chunked)
Mar 18 04:01:56.397031 ubuntu-focal-vexxhost-ca-ymq-1-0023551666 glance-api[96125]: ERROR glance.async_.taskflow_executor File "/usr/lib/python3.8/http/client.py", line 1010, in _send_output
Mar 18 04:01:56.397031 ubuntu-focal-vexxhost-ca-ymq-1-0023551666 glance-api[96125]: ERROR glance.async_.taskflow_executor self.send(msg)
Mar 18 04:01:56.397031 ubuntu-focal-vexxhost-ca-ymq-1-0023551666 glance-api[96125]: ERROR glance.async_.taskflow_executor File "/usr/lib/python3.8/http/client.py", line 950, in send
Mar 18 04:01:56.397031 ubuntu-focal-vexxhost-ca-ymq-1-0023551666 glance-api[96125]: ERROR glance.async_.taskflow_executor self.connect()
Mar 18 04:01:56.397031 ubuntu-focal-vexxhost-ca-ymq-1-0023551666 glance-api[96125]: ERROR glance.async_.taskflow_executor File "/usr/lib/python3.8/http/client.py", line 921, in connect
Mar 18 04:01:56.397031 ubuntu-focal-vexxhost-ca-ymq-1-0023551666 glance-api[96125]: ERROR glance.async_.taskflow_executor self.sock = self._create_connection(
Mar 18 04:01:56.397031 ubuntu-focal-vexxhost-ca-ymq-1-0023551666 glance-api[96125]: ERROR glance.async_.taskflow_executor File "/usr/local/lib/python3.8/dist-packages/eventlet/green/socket.py", line 44, in create_connection
Mar 18 04:01:56.397031 ubuntu-focal-vexxhost-ca-ymq-1-0023551666 glance-api[96125]: ERROR glance.async_.taskflow_executor for res in getaddrinfo(host, port, 0, SOCK_STREAM):
Mar 18 04:01:56.397031 ubuntu-focal-vexxhost-ca-ymq-1-0023551666 glance-api[96125]: ERROR glance.async_.taskflow_executor File "/usr/local/lib/python3.8/dist-packages/eventlet/support/greendns.py", line 537, in getaddrinfo
Mar 18 04:01:56.397031 ubuntu-focal-vexxhost-ca-ymq-1-0023551666 glance-api[96125]: ERROR glance.async_.taskflow_executor raise socket.gaierror(socket.EAI_NONAME, 'No address found')
Mar 18 04:01:56.397031 ubuntu-focal-vexxhost-ca-ymq-1-0023551666 glance-api[96125]: ERROR glance.async_.taskflow_executor socket.gaierror: [Errno -2] No address found
Mar 18 04:01:56.397031 ubuntu-focal-vexxhost-ca-ymq-1-0023551666 glance-api[96125]: ERROR glance.async_.taskflow_executor
Mar 18 04:01:56.397031 ubuntu-focal-vexxhost-ca-ymq-1-0023551666 glance-api[96125]: ERROR glance.async_.taskflow_executor During handling of the above exception, another exception occurred:
Mar 18 04:01:56.397031 ubuntu-focal-vexxhost-ca-ymq-1-0023551666 glance-api[96125]: ERROR glance.async_.taskflow_executor
Mar 18 04:01:56.397031 ubuntu-focal-vexxhost-ca-ymq-1-0023551666 glance-api[96125]: ERROR glance.async_.taskflow_executor Traceback (most recent call last):
Mar 18 04:01:56.397031 ubuntu-focal-vexxhost-ca-ymq-1-0023551666 glance-api[96125]: ERROR glance.async_.taskflow_executor File "/usr/local/lib/python3.8/dist-packages/taskflow/engines/action_engine/executor.py", line 53, in _execute_task
Mar 18 04:01:56.397031 ubuntu-focal-vexxhost-ca-ymq-1-0023551666 glance-api[96125]: ERROR glance.async_.taskflow_executor result = task.execute(**arguments)
Mar 18 04:01:56.397031 ubuntu-focal-vexxhost-ca-ymq-1-0023551666 glance-api[96125]: ERROR glance.async_.taskflow_executor File "/opt/stack/glance/glance/async_/flows/_internal_plugins/web_download.py", line 117, in execute
Mar 18 04:01:56.397031 ubuntu-focal-vexxhost-ca-ymq-1-0023551666 glance-api[96125]: ERROR glance.async_.taskflow_executor LOG.error("Task %(task_id)s failed with exception %(error)s",
Mar 18 04:01:56.397031 ubuntu-focal-vexxhost-ca-ymq-1-0023551666 glance-api[96125]: ERROR glance.async_.taskflow_executor File "/usr/local/lib/python3.8/dist-packages/oslo_utils/excutils.py", line 220, in __exit__
Mar 18 04:01:56.397031 ubuntu-focal-vexxhost-ca-ymq-1-0023551666 glance-api[96125]: ERROR glance.async_.taskflow_executor self.force_reraise()
Mar 18 04:01:56.397031 ubuntu-focal-vexxhost-ca-ymq-1-0023551666 glance-api[96125]: ERROR glance.async_.taskflow_executor File "/usr/local/lib/python3.8/dist-packages/oslo_utils/excutils.py", line 196, in force_reraise
Mar 18 04:01:56.397031 ubuntu-focal-vexxhost-ca-ymq-1-0023551666 glance-api[96125]: ERROR glance.async_.taskflow_executor six.reraise(self.type_, self.value, self.tb)
Mar 18 04:01:56.397031 ubuntu-focal-vexxhost-ca-ymq-1-0023551666 glance-api[96125]: ERROR glance.async_.taskflow_executor File "/usr/local/lib/python3.8/dist-packages/six.py", line 703, in reraise
Mar 18 04:01:56.397031 ubuntu-focal-vexxhost-ca-ymq-1-0023551666 glance-api[96125]: ERROR glance.async_.taskflow_executor raise value
Mar 18 04:01:56.397031 ubuntu-focal-vexxhost-ca-ymq-1-0023551666 glance-api[96125]: ERROR glance.async_.taskflow_executor File "/opt/stack/glance/glance/async_/flows/_internal_plugins/web_download.py", line 114, in execute
Mar 18 04:01:56.397031 ubuntu-focal-vexxhost-ca-ymq-1-0023551666 glance-api[96125]: ERROR glance.async_.taskflow_executor data = script_utils.get_image_data_iter(self.uri)
Mar 18 04:01:56.397031 ubuntu-focal-vexxhost-ca-ymq-1-0023551666 glance-api[96125]: ERROR glance.async_.taskflow_executor File "/opt/stack/glance/glance/common/scripts/utils.py", line 142, in get_image_data_iter
Mar 18 04:01:56.397031 ubuntu-focal-vexxhost-ca-ymq-1-0023551666 glance-api[96125]: ERROR glance.async_.taskflow_executor return urllib.request.urlopen(uri)
Mar 18 04:01:56.397031 ubuntu-focal-vexxhost-ca-ymq-1-0023551666 glance-api[96125]: ERROR glance.async_.taskflow_executor File "/usr/lib/python3.8/urllib/request.py", line 222, in urlopen
Mar 18 04:01:56.397031 ubuntu-focal-vexxhost-ca-ymq-1-0023551666 glance-api[96125]: ERROR glance.async_.taskflow_executor return opener.open(url, data, timeout)
Mar 18 04:01:56.397031 ubuntu-focal-vexxhost-ca-ymq-1-0023551666 glance-api[96125]: ERROR glance.async_.taskflow_executor File "/usr/lib/python3.8/urllib/request.py", line 525, in open
Mar 18 04:01:56.397031 ubuntu-focal-vexxhost-ca-ymq-1-0023551666 glance-api[96125]: ERROR glance.async_.taskflow_executor response = self._open(req, data)
Mar 18 04:01:56.397031 ubuntu-focal-vexxhost-ca-ymq-1-0023551666 glance-api[96125]: ERROR glance.async_.taskflow_executor File "/usr/lib/python3.8/urllib/request.py", line 542, in _open
Mar 18 04:01:56.397031 ubuntu-focal-vexxhost-ca-ymq-1-0023551666 glance-api[96125]: ERROR glance.async_.taskflow_executor result = self._call_chain(self.handle_open, protocol, protocol +
Mar 18 04:01:56.397031 ubuntu-focal-vexxhost-ca-ymq-1-0023551666 glance-api[96125]: ERROR glance.async_.taskflow_executor File "/usr/lib/python3.8/urllib/request.py", line 502, in _call_chain
Mar 18 04:01:56.397031 ubuntu-focal-vexxhost-ca-ymq-1-0023551666 glance-api[96125]: ERROR glance.async_.taskflow_executor result = func(*args)
Mar 18 04:01:56.397031 ubuntu-focal-vexxhost-ca-ymq-1-0023551666 glance-api[96125]: ERROR glance.async_.taskflow_executor File "/usr/lib/python3.8/urllib/request.py", line 1379, in http_open
Mar 18 04:01:56.397031 ubuntu-focal-vexxhost-ca-ymq-1-0023551666 glance-api[96125]: ERROR glance.async_.taskflow_executor return self.do_open(http.client.HTTPConnection, req)
Mar 18 04:01:56.397031 ubuntu-focal-vexxhost-ca-ymq-1-0023551666 glance-api[96125]: ERROR glance.async_.taskflow_executor File "/usr/lib/python3.8/urllib/request.py", line 1353, in do_open
Mar 18 04:01:56.398319 ubuntu-focal-vexxhost-ca-ymq-1-0023551666 glance-api[96125]: ERROR glance.async_.taskflow_executor raise URLError(err)
Mar 18 04:01:56.398319 ubuntu-focal-vexxhost-ca-ymq-1-0023551666 glance-api[96125]: ERROR glance.async_.taskflow_executor urllib.error.URLError: <urlopen error [Errno -2] No address found>
Mar 18 04:01:56.398319 ubuntu-focal-vexxhost-ca-ymq-1-0023551666 glance-api[96125]: ERROR glance.async_.taskflow_executor

[Lee Yarwood (lyarwood)]

https://zuul.opendev.org/t/openstack/builds?job_name=nova-ceph-multistore&branch=stable%2Fvictoria

Looks like this started failing on the ~12th.

[Lee Yarwood (lyarwood)]

I've posted backports of https://review.opendev.org/c/openstack/glance/+/781235 and https://review.opendev.org/c/openstack/glance/+/781236 that should fix nova-ceph-multistore on stable/victoria.

Note that this is *only* failing there because this job sets GLANCE_USE_IMPORT_WORKFLOW to True:

https://github.com/openstack/nova/blob/35112d7667cee9fc33db660ee241164b38468c31/.zuul.yaml#L363

[OpenStack Infra (hudson-openstack)]

This issue was fixed in the openstack/glance 21.1.0 release.