Tempest creating server from image times out after 10 min

Bug #1983597 reported by Bas de Bruijne
6
This bug affects 1 person
Affects Status Importance Assigned to Milestone
OpenStack Nova Cloud Controller Charm
New
Undecided
Unassigned

Bug Description

In testrun https://solutions.qa.canonical.com/testruns/testRun/7f8576a7-d016-4ed2-b944-3c9fbd1ec16b, the Tempest test https://oil-jenkins.canonical.com/artifacts/7f8576a7-d016-4ed2-b944-3c9fbd1ec16b/generated/generated/openstack/tempest_result.html fails with:

```
Traceback (most recent call last):
  File "/home/ubuntu/snap/fcbtest/34/.rally/verification/verifier-cfd99e55-d45b-41e9-8aea-baf8aeaaf4ed/repo/tempest/api/compute/images/test_images.py", line 87, in test_create_image_from_stopped_server
    image = self.create_image_from_server(server['id'],
  File "/home/ubuntu/snap/fcbtest/34/.rally/verification/verifier-cfd99e55-d45b-41e9-8aea-baf8aeaaf4ed/repo/tempest/api/compute/base.py", line 386, in create_image_from_server
    waiters.wait_for_image_status(client, image_id, wait_until)
  File "/home/ubuntu/snap/fcbtest/34/.rally/verification/verifier-cfd99e55-d45b-41e9-8aea-baf8aeaaf4ed/repo/tempest/common/waiters.py", line 198, in wait_for_image_status
    raise lib_exc.TimeoutException(message)
tempest.lib.exceptions.TimeoutException: Request timed out
Details: (ImagesTestJSON:test_create_image_from_stopped_server) Image 1f54570f-1e5d-4831-9249-8982cfeed544 failed to reach ACTIVE state (current state SAVING) within the required time (600 s).
```

10 min should be plenty to save the image, we have already doubled the timeout from the default 5 min to compensate for the slow machines.

In the logs I see some errors from glance:
```
21:03:42.185 189949 ERROR glance.api.v2.image_data Traceback (most recent call last):
21:03:42.185 189949 ERROR glance.api.v2.image_data File "/usr/lib/python3/dist-packages/glance/api/v2/image_data.py", line 163, in upload
21:03:42.185 189949 ERROR glance.api.v2.image_data image.set_data(data, size, backend=backend)
21:03:42.185 189949 ERROR glance.api.v2.image_data File "/usr/lib/python3/dist-packages/glance/notifier.py", line 497, in set_data
21:03:42.185 189949 ERROR glance.api.v2.image_data _send_notification(notify_error, 'image.upload', msg)
21:03:42.185 189949 ERROR glance.api.v2.image_data File "/usr/lib/python3/dist-packages/oslo_utils/excutils.py", line 227, in __exit__
21:03:42.185 189949 ERROR glance.api.v2.image_data self.force_reraise()
21:03:42.185 189949 ERROR glance.api.v2.image_data File "/usr/lib/python3/dist-packages/oslo_utils/excutils.py", line 200, in force_reraise
21:03:42.185 189949 ERROR glance.api.v2.image_data raise self.value
21:03:42.185 189949 ERROR glance.api.v2.image_data File "/usr/lib/python3/dist-packages/glance/notifier.py", line 443, in set_data
21:03:42.185 189949 ERROR glance.api.v2.image_data self.repo.set_data(data, size, backend=backend,
21:03:42.185 189949 ERROR glance.api.v2.image_data File "/usr/lib/python3/dist-packages/glance/quota/__init__.py", line 322, in set_data
21:03:42.185 189949 ERROR glance.api.v2.image_data self.image.set_data(data, size=size, backend=backend,
21:03:42.185 189949 ERROR glance.api.v2.image_data File "/usr/lib/python3/dist-packages/glance/location.py", line 585, in set_data
21:03:42.185 189949 ERROR glance.api.v2.image_data self._upload_to_store(data, verifier, backend, size)
21:03:42.185 189949 ERROR glance.api.v2.image_data File "/usr/lib/python3/dist-packages/glance/location.py", line 476, in _upload_to_store
21:03:42.185 189949 ERROR glance.api.v2.image_data multihash, loc_meta) = self.store_api.add_with_multihash(
21:03:42.185 189949 ERROR glance.api.v2.image_data File "/usr/lib/python3/dist-packages/glance_store/multi_backend.py", line 398, in add_with_multihash
21:03:42.185 189949 ERROR glance.api.v2.image_data return store_add_to_backend_with_multihash(
21:03:42.185 189949 ERROR glance.api.v2.image_data File "/usr/lib/python3/dist-packages/glance_store/multi_backend.py", line 480, in store_add_to_backend_with_multihash 21:03:42.185 189949 ERROR glance.api.v2.image_data (location, size, checksum, multihash, metadata) = store.add(
21:03:42.185 189949 ERROR glance.api.v2.image_data File "/usr/lib/python3/dist-packages/glance_store/driver.py", line 279, in add_adapter
21:03:42.185 189949 ERROR glance.api.v2.image_data metadata_dict) = store_add_fun(*args, **kwargs)
21:03:42.185 189949 ERROR glance.api.v2.image_data File "/usr/lib/python3/dist-packages/glance_store/capabilities.py", line 176, in op_checker
21:03:42.185 189949 ERROR glance.api.v2.image_data return store_op_fun(store, *args, **kwargs)
21:03:42.185 189949 ERROR glance.api.v2.image_data File "/usr/lib/python3/dist-packages/glance_store/_drivers/rbd.py", line 645, in add
21:03:42.185 189949 ERROR glance.api.v2.image_data raise exc
21:03:42.185 189949 ERROR glance.api.v2.image_data File "/usr/lib/python3/dist-packages/glance_store/_drivers/rbd.py", line 590, in add
21:03:42.185 189949 ERROR glance.api.v2.image_data for chunk in chunks:
21:03:42.185 189949 ERROR glance.api.v2.image_data File "/usr/lib/python3/dist-packages/glance_store/common/utils.py", line 73, in chunkiter
21:03:42.185 189949 ERROR glance.api.v2.image_data chunk = fp.read(chunk_size)
21:03:42.185 189949 ERROR glance.api.v2.image_data File "/usr/lib/python3/dist-packages/glance/common/utils.py", line 293, in read
21:03:42.185 189949 ERROR glance.api.v2.image_data result = self.data.read(i)
21:03:42.185 189949 ERROR glance.api.v2.image_data File "/usr/lib/python3/dist-packages/glance/common/utils.py", line 120, in readfn
21:03:42.185 189949 ERROR glance.api.v2.image_data result = fd.read(*args)
21:03:42.185 189949 ERROR glance.api.v2.image_data File "/usr/lib/python3/dist-packages/glance/common/format_inspector.py", line 658, in read
21:03:42.185 189949 ERROR glance.api.v2.image_data chunk = self._source.read(size)
21:03:42.185 189949 ERROR glance.api.v2.image_data File "/usr/lib/python3/dist-packages/eventlet/wsgi.py", line 221, in read
21:03:42.185 189949 ERROR glance.api.v2.image_data return self._chunked_read(self.rfile, length)
21:03:42.185 189949 ERROR glance.api.v2.image_data File "/usr/lib/python3/dist-packages/eventlet/wsgi.py", line 192, in _chunked_read
21:03:42.185 189949 ERROR glance.api.v2.image_data raise IOError("unexpected end of file while parsing chunked data")
21:03:42.185 189949 ERROR glance.api.v2.image_data OSError: unexpected end of file while parsing chunked data
21:03:42.185 189949 ERROR glance.api.v2.image_data
21:03:42.185 189949 ERROR glance.api.v2.image_data During handling of the above exception, another exception occurred:
21:03:42.185 189949 ERROR glance.api.v2.image_data
21:03:42.185 189949 ERROR glance.api.v2.image_data Traceback (most recent call last):
21:03:42.185 189949 ERROR glance.api.v2.image_data File "/usr/lib/python3/dist-packages/glance/api/v2/image_data.py", line 66, in _restore
21:03:42.185 189949 ERROR glance.api.v2.image_data image_repo.save(image)
21:03:42.185 189949 ERROR glance.api.v2.image_data File "/usr/lib/python3/dist-packages/glance/notifier.py", line 530, in save
21:03:42.185 189949 ERROR glance.api.v2.image_data super(ImageRepoProxy, self).save(image, from_state=from_state)
21:03:42.185 189949 ERROR glance.api.v2.image_data File "/usr/lib/python3/dist-packages/glance/domain/proxy.py", line 99, in save
21:03:42.185 189949 ERROR glance.api.v2.image_data result = self.base.save(base_item, from_state=from_state)
21:03:42.185 189949 ERROR glance.api.v2.image_data File "/usr/lib/python3/dist-packages/glance/quota/__init__.py", line 121, in save
21:03:42.185 189949 ERROR glance.api.v2.image_data return super(ImageRepoProxy, self).save(image, from_state=from_state)
21:03:42.185 189949 ERROR glance.api.v2.image_data File "/usr/lib/python3/dist-packages/glance/domain/proxy.py", line 99, in save
21:03:42.185 189949 ERROR glance.api.v2.image_data result = self.base.save(base_item, from_state=from_state)
21:03:42.185 189949 ERROR glance.api.v2.image_data File "/usr/lib/python3/dist-packages/glance/location.py", line 82, in save
21:03:42.185 189949 ERROR glance.api.v2.image_data result = super(ImageRepoProxy, self).save(image, from_state=from_state)
21:03:42.185 189949 ERROR glance.api.v2.image_data File "/usr/lib/python3/dist-packages/glance/domain/proxy.py", line 99, in save
21:03:42.185 189949 ERROR glance.api.v2.image_data result = self.base.save(base_item, from_state=from_state)
21:03:42.185 189949 ERROR glance.api.v2.image_data File "/usr/lib/python3/dist-packages/glance/db/__init__.py", line 198, in save
21:03:42.185 189949 ERROR glance.api.v2.image_data new_values = self.db_api.image_update(self.context,
21:03:42.185 189949 ERROR glance.api.v2.image_data File "/usr/lib/python3/dist-packages/glance/db/sqlalchemy/api.py", line 158, in image_update
21:03:42.185 189949 ERROR glance.api.v2.image_data image = _image_update(context, values, image_id, purge_props,
21:03:42.185 189949 ERROR glance.api.v2.image_data File "/usr/lib/python3/dist-packages/retrying.py", line 49, in wrapped_f
21:03:42.185 189949 ERROR glance.api.v2.image_data return Retrying(*dargs, **dkw).call(f, *args, **kw)
21:03:42.185 189949 ERROR glance.api.v2.image_data File "/usr/lib/python3/dist-packages/retrying.py", line 206, in call
21:03:42.185 189949 ERROR glance.api.v2.image_data return attempt.get(self._wrap_exception)
21:03:42.185 189949 ERROR glance.api.v2.image_data File "/usr/lib/python3/dist-packages/retrying.py", line 247, in get
21:03:42.185 189949 ERROR glance.api.v2.image_data six.reraise(self.value[0], self.value[1], self.value[2])
21:03:42.185 189949 ERROR glance.api.v2.image_data File "/usr/lib/python3/dist-packages/six.py", line 703, in reraise
21:03:42.185 189949 ERROR glance.api.v2.image_data raise value
21:03:42.185 189949 ERROR glance.api.v2.image_data File "/usr/lib/python3/dist-packages/retrying.py", line 200, in call
21:03:42.185 189949 ERROR glance.api.v2.image_data attempt = Attempt(fn(*args, **kwargs), attempt_number, False)
21:03:42.185 189949 ERROR glance.api.v2.image_data File "/usr/lib/python3/dist-packages/glance/common/utils.py", line 545, in wrapper
21:03:42.185 189949 ERROR glance.api.v2.image_data return f(*args, **kwargs)
21:03:42.185 189949 ERROR glance.api.v2.image_data File "/usr/lib/python3/dist-packages/glance/db/sqlalchemy/api.py", line 968, in _image_update
21:03:42.185 189949 ERROR glance.api.v2.image_data image_ref = _image_get(context, image_id, session=session)
21:03:42.185 189949 ERROR glance.api.v2.image_data File "/usr/lib/python3/dist-packages/glance/db/sqlalchemy/api.py", line 281, in _image_get
21:03:42.185 189949 ERROR glance.api.v2.image_data raise exception.ImageNotFound(msg)
21:03:42.185 189949 ERROR glance.api.v2.image_data glance.common.exception.ImageNotFound: No image found with ID 1f54570f-1e5d-4831-9249-8982cfeed544
```

It looks like the image may have been corrupted. These logs are a few min after the tempest test failure though.

Link to crashdumps:
https://oil-jenkins.canonical.com/artifacts/7f8576a7-d016-4ed2-b944-3c9fbd1ec16b/index.html

Tags: cdo-tempest
tags: added: cdo-tempest
Revision history for this message
Corey Bryant (corey.bryant) wrote :

Hi Bas,

Are you still hitting this? If the image is corrupted I don't think it would be a charm bug.

If you hit this again some details from glance logs would likely be useful. I tried the first link but it looks like it's empty.

Thanks,
Corey

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

Other bug subscribers

Remote bug watches

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