tempest.api.compute.images.test_images_oneserver.ImagesOneServerTestXML.test_delete_image_that_is_not_yet_active spurious failure

[Christopher Yeoh]

Looks like this is an intermittent failure:

ft45.7: tempest.api.compute.images.test_images_oneserver.ImagesOneServerTestXML.test_delete_image_that_is_not_yet_active[gate,negative]_StringException: Empty attachments:
  stderr
  stdout

Traceback (most recent call last):
  File "tempest/api/compute/images/test_images_oneserver.py", line 161, in test_delete_image_that_is_not_yet_active
    resp, body = self.client.create_image(self.server['id'], snapshot_name)
  File "tempest/services/compute/xml/images_client.py", line 105, in create_image
    str(Document(post_body)), self.headers)
  File "tempest/common/rest_client.py", line 260, in post
    return self.request('POST', url, headers, body)
  File "tempest/common/rest_client.py", line 388, in request
    resp, resp_body)
  File "tempest/common/rest_client.py", line 443, in _error_checker
    raise exceptions.Duplicate(resp_body)
Duplicate: An object with that identifier already exists

Details: {'message': "Cannot 'createImage' while instance is in task_state image_uploading", 'code': '409'}

http://logs.openstack.org/50/41350/3/gate/gate-nova-python26/80bbbf0/testr_results.html.gz

[Christopher Yeoh (cyeoh-0)]

Oops that should be http://logs.openstack.org/08/40608/5/check/gate-tempest-devstack-vm-full/8600884/testr_results.html.gz

[Adalberto Medeiros (adalbas)]

Two testcases are executed consecutively:
test_create_second_image_when_first_image_is_being_saved and
test_delete_image_that_is_not_yet_active
In the first, the image created from a certain instance gets active, but the instance remains in uploading status. When the next testcase comes to be executed, it tries to create another snapshot from the uploading image and causes an error

My suggestion here is to wait for the instance to become available before trying to create the snapshot in the second testcase.

The logs on n-api related to that:

2013-08-29 13:03:06.331 DEBUG nova.api.openstack.wsgi [req-68611dfc-e6ab-4f27-a813-dd97baab4878 ImagesOneServerTestXML256228464-user ImagesOneServerTestXML954616129-tenant] No Content-Type provided in request get_body /opt/stack/new/nova/nova/api/openstack/wsgi.py:801
2013-08-29 13:03:06.331 DEBUG nova.api.openstack.wsgi [req-68611dfc-e6ab-4f27-a813-dd97baab4878 ImagesOneServerTestXML256228464-user ImagesOneServerTestXML954616129-tenant] Calling method <bound method Controller.delete of <nova.api.openstack.compute.servers.Controller object at 0x47cc450>> _process_stack /opt/stack/new/nova/nova/api/openstack/wsgi.py:928
2013-08-29 13:03:06.368 DEBUG nova.compute.api [req-68611dfc-e6ab-4f27-a813-dd97baab4878 ImagesOneServerTestXML256228464-user ImagesOneServerTestXML954616129-tenant] [instance: 476fc5e9-e5b5-468f-a744-145837dfc7e2] Going to try to terminate instance delete /opt/stack/new/nova/nova/compute/api.py:1465
2013-08-29 13:03:06.429 DEBUG nova.quota [req-68611dfc-e6ab-4f27-a813-dd97baab4878 ImagesOneServerTestXML256228464-user ImagesOneServerTestXML954616129-tenant] Created reservations ['0454632b-10e4-4f56-934f-5fcb16982e53', '55a79376-c1b9-48c5-b7d4-af3ef4950f4a', 'a7e219c5-9eb3-4bbe-a6ae-a7cee63d3d78'] reserve /opt/stack/new/nova/nova/quota.py:1256
2013-08-29 13:03:06.438 DEBUG nova.servicegroup.api [req-68611dfc-e6ab-4f27-a813-dd97baab4878 ImagesOneServerTestXML256228464-user ImagesOneServerTestXML954616129-tenant] Check if the given member [<nova.db.sqlalchemy.models.Service object at 0x7a16f90>] is part of the ServiceGroup, is up service_is_up /opt/stack/new/nova/nova/servicegroup/api.py:94
2013-08-29 13:03:06.439 DEBUG nova.servicegroup.drivers.db [req-68611dfc-e6ab-4f27-a813-dd97baab4878 ImagesOneServerTestXML256228464-user ImagesOneServerTestXML954616129-tenant] DB_Driver.is_up last_heartbeat = 2013-08-29 13:02:59 elapsed = 7.439029 is_up /opt/stack/new/nova/nova/servicegroup/drivers/db.py:67
2013-08-29 13:03:06.442 DEBUG nova.openstack.common.rpc.amqp [req-68611dfc-e6ab-4f27-a813-dd97baab4878 ImagesOneServerTestXML256228464-user ImagesOneServerTestXML954616129-tenant] Making asynchronous cast on compute.devstack-precise-hpcloud-az3-190744... cast /opt/stack/new/nova/nova/openstack/common/rpc/amqp.py:542
2013-08-29 13:03:06.442 DEBUG nova.openstack.common.rpc.amqp [req-68611dfc-e6ab-4f27-a813-dd97baab4878 ImagesOneServerTestXML256228464-user ImagesOneServerTestXML954616129-tenant] UNIQUE_ID is 0d6d5d3ba5624a4087a3f9d641225a08. _add_unique_id /opt/stack/new/nova/nova/openstack/common/rpc/amqp.py:322
2013-08-29 13:03:06.444 23111 DEBUG amqp [-] Closed channel #1 _do_close /usr/local/lib/py...

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: master
Review: https://review.openstack.org/45326

[Adalberto Medeiros (adalbas)]

This is also addressing this problem, in a more general way: https://review.openstack.org/#/c/35165/

[Peter Portante (peter-a-portante)]

FYI: this has borked swift as well:

http://logs.openstack.org/49/43949/6/check/gate-tempest-devstack-vm-postgres-full/095b91c/console.html

2013-09-11 14:50:22.606 | ======================================================================
2013-09-11 14:50:22.607 | FAIL: tempest.api.compute.images.test_images_oneserver.ImagesOneServerTestJSON.test_create_image_specify_name_over_256_chars[gate,negative]
2013-09-11 14:50:22.607 | tempest.api.compute.images.test_images_oneserver.ImagesOneServerTestJSON.test_create_image_specify_name_over_256_chars[gate,negative]
2013-09-11 14:50:22.607 | ----------------------------------------------------------------------
2013-09-11 14:50:22.607 | _StringException: Empty attachments:
2013-09-11 14:50:22.607 | stderr
2013-09-11 14:50:22.607 | stdout
2013-09-11 14:50:22.608 |
2013-09-11 14:50:22.608 | pythonlogging:'': {{{
2013-09-11 14:50:22.608 | 2013-09-11 14:31:50,254 Request: POST http://127.0.0.1:8774/v2/786adbc00f294b7ca61847e9d1e1e436/servers/d4254776-8c18-41d3-ab43-9076df8cf872/action
2013-09-11 14:50:22.608 | 2013-09-11 14:31:50,343 Response Status: 409
2013-09-11 14:50:22.608 | 2013-09-11 14:31:50,343 Nova request id: req-c03374da-064d-46fc-b6f5-4b6bcc787530
2013-09-11 14:50:22.608 | }}}
2013-09-11 14:50:22.608 |
2013-09-11 14:50:22.609 | Traceback (most recent call last):
2013-09-11 14:50:22.609 | File "tempest/api/compute/images/test_images_oneserver.py", line 154, in test_create_image_specify_name_over_256_chars
2013-09-11 14:50:22.609 | self.server['id'], snapshot_name)
2013-09-11 14:50:22.609 | File "/usr/local/lib/python2.7/dist-packages/testtools/testcase.py", line 394, in assertRaises
2013-09-11 14:50:22.609 | self.assertThat(our_callable, matcher)
2013-09-11 14:50:22.609 | File "/usr/local/lib/python2.7/dist-packages/testtools/testcase.py", line 406, in assertThat
2013-09-11 14:50:22.609 | mismatch = matcher.match(matchee)
2013-09-11 14:50:22.610 | File "/usr/local/lib/python2.7/dist-packages/testtools/matchers/_exception.py", line 99, in match
2013-09-11 14:50:22.610 | mismatch = self.exception_matcher.match(exc_info)
2013-09-11 14:50:22.610 | File "/usr/local/lib/python2.7/dist-packages/testtools/matchers/_higherorder.py", line 61, in match
2013-09-11 14:50:22.610 | mismatch = matcher.match(matchee)
2013-09-11 14:50:22.610 | File "/usr/local/lib/python2.7/dist-packages/testtools/testcase.py", line 386, in match
2013-09-11 14:50:22.610 | reraise(*matchee)
2013-09-11 14:50:22.611 | File "/usr/local/lib/python2.7/dist-packages/testtools/matchers/_exception.py", line 92, in match
2013-09-11 14:50:22.611 | result = matchee()
2013-09-11 14:50:22.611 | File "/usr/local/lib/python2.7/dist-packages/testtools/testcase.py", line 867, in __call__
2013-09-11 14:50:22.611 | return self._callable_object(*self._args, **self._kwargs)
2013-09-11 14:50:22.611 | File "tempest/services/compute/json/images_client.py", line 49, in create_image
2013-09-11 14:50:22.611 | post_body, self.headers)
2013-09-11 14:50:22.611 | File "tempest/common/rest_client.py", line 260, in post
2013-09-11 14:50:22.612 | return self.request('POST', url, headers, body)
201...

[Monsyne Dragon (mdragon)]

I'm seeing this affect the tempest.api.compute.images.test_images_oneserver.ImagesOneServerTestJSON.test_delete_image_that_is_not_yet_active test as well. (same bug, just the JSON version of the test. )

[Monsyne Dragon (mdragon)]

erf, hit submit too soon...

link:
http://logs.openstack.org/34/46134/3/gate/gate-tempest-devstack-vm-full/014a603/console.html

[Joe Gordon (jogo)]

logstash query (logstash.openstack.org): @message:"Cannot 'createImage'" AND @fields.filename:"console.html" AND @fields.build_status:"FAILURE"

[Adalberto Medeiros (adalbas)]

Waiting on patch https://review.openstack.org/#/c/35165/ to be approved. This will probably fix it.

[Josh Durgin (jdurgin)]

This still happens, albeit with a different state. From http://logs.openstack.org/79/46879/1/check/gate-tempest-devstack-vm-postgres-full/da6e518/console.html:

2013-09-17 08:52:26.319 | ======================================================================
2013-09-17 08:52:26.319 | FAIL: tempest.api.compute.images.test_images_oneserver.ImagesOneServerTestJSON.test_delete_image_that_is_not_yet_active[gate,negative]
2013-09-17 08:52:26.319 | tempest.api.compute.images.test_images_oneserver.ImagesOneServerTestJSON.test_delete_image_that_is_not_yet_active[gate,negative]
2013-09-17 08:52:26.319 | ----------------------------------------------------------------------
2013-09-17 08:52:26.319 | _StringException: Empty attachments:
2013-09-17 08:52:26.319 | stderr
2013-09-17 08:52:26.320 | stdout
2013-09-17 08:52:26.320 |
2013-09-17 08:52:26.320 | pythonlogging:'': {{{
2013-09-17 08:52:26.320 | 2013-09-17 08:40:37,762 Request: POST http://127.0.0.1:8774/v2/4117257ca7ee438db4956291bc0f037a/servers/9a495863-4fe2-4692-adfb-42a481d14336/action
2013-09-17 08:52:26.320 | 2013-09-17 08:40:37,862 Response Status: 409
2013-09-17 08:52:26.320 | 2013-09-17 08:40:37,862 Nova request id: req-783d5fa4-6b61-4080-9a08-e10a2be25efa
2013-09-17 08:52:26.321 | }}}
2013-09-17 08:52:26.321 |
2013-09-17 08:52:26.321 | Traceback (most recent call last):
2013-09-17 08:52:26.321 | File "tempest/api/compute/images/test_images_oneserver.py", line 161, in test_delete_image_that_is_not_yet_active
2013-09-17 08:52:26.321 | resp, body = self.client.create_image(self.server['id'], snapshot_name)
2013-09-17 08:52:26.321 | File "tempest/services/compute/json/images_client.py", line 49, in create_image
2013-09-17 08:52:26.322 | post_body, self.headers)
2013-09-17 08:52:26.322 | File "tempest/common/rest_client.py", line 260, in post
2013-09-17 08:52:26.322 | return self.request('POST', url, headers, body)
2013-09-17 08:52:26.322 | File "tempest/common/rest_client.py", line 394, in request
2013-09-17 08:52:26.322 | resp, resp_body)
2013-09-17 08:52:26.322 | File "tempest/common/rest_client.py", line 449, in _error_checker
2013-09-17 08:52:26.323 | raise exceptions.Duplicate(resp_body)
2013-09-17 08:52:26.323 | Duplicate: An object with that identifier already exists
2013-09-17 08:52:26.323 | Details: {u'conflictingRequest': {u'message': u"Cannot 'createImage' while instance is in task_state image_snapshot", u'code': 409}}
2013-09-17 08:52:26.323 |

[Adalberto Medeiros (adalbas)]

According to the logs in http://logs.openstack.org/79/46879/1/check/gate-tempest-devstack-vm-postgres-full/da6e518/console.html
The image remains in the image_snapshot state for about 7 min and reaches an error for libvirt. Pointing this as a bug in nova as well. However, more investigation on tempest why the timeout exception was not reached is needed.

2013-09-17 08:40:40.255 21404 DEBUG nova.virt.libvirt.driver [-] Updating host stats update_status /opt/stack/new/nova/nova/virt/libvirt/driver.py:4773
2013-09-17 08:40:42.153 DEBUG nova.compute.manager [req-9d54f462-e8eb-4bdd-b8c4-880e7d46b236 ImagesOneServerTestJSON272219911-user ImagesOneServerTestJSON258432094-tenant] [instance: 9a495863-4fe2-4692-adfb-42a481d14336] Cleaning up image 2cc0a45d-bd7f-4222-8a2e-813ec7f0a516 decorated_function /opt/stack/new/nova/nova/compute/manager.py:314
2013-09-17 08:40:42.153 21404 TRACE nova.compute.manager [instance: 9a495863-4fe2-4692-adfb-42a481d14336] Traceback (most recent call last):
2013-09-17 08:40:42.153 21404 TRACE nova.compute.manager [instance: 9a495863-4fe2-4692-adfb-42a481d14336] File "/opt/stack/new/nova/nova/compute/manager.py", line 310, in decorated_function
2013-09-17 08:40:42.153 21404 TRACE nova.compute.manager [instance: 9a495863-4fe2-4692-adfb-42a481d14336] *args, **kwargs)
2013-09-17 08:40:42.153 21404 TRACE nova.compute.manager [instance: 9a495863-4fe2-4692-adfb-42a481d14336] File "/opt/stack/new/nova/nova/compute/manager.py", line 2301, in snapshot_instance
2013-09-17 08:40:42.153 21404 TRACE nova.compute.manager [instance: 9a495863-4fe2-4692-adfb-42a481d14336] task_states.IMAGE_SNAPSHOT)
2013-09-17 08:40:42.153 21404 TRACE nova.compute.manager [instance: 9a495863-4fe2-4692-adfb-42a481d14336] File "/opt/stack/new/nova/nova/compute/manager.py", line 2332, in _snapshot_instance
2013-09-17 08:40:42.153 21404 TRACE nova.compute.manager [instance: 9a495863-4fe2-4692-adfb-42a481d14336] update_task_state)
2013-09-17 08:40:42.153 21404 TRACE nova.compute.manager [instance: 9a495863-4fe2-4692-adfb-42a481d14336] File "/opt/stack/new/nova/nova/virt/libvirt/driver.py", line 1373, in snapshot
2013-09-17 08:40:42.153 21404 TRACE nova.compute.manager [instance: 9a495863-4fe2-4692-adfb-42a481d14336] virt_dom.managedSave(0)
2013-09-17 08:40:42.153 21404 TRACE nova.compute.manager [instance: 9a495863-4fe2-4692-adfb-42a481d14336] File "/usr/local/lib/python2.7/dist-packages/eventlet/tpool.py", line 179, in doit
2013-09-17 08:40:42.153 21404 TRACE nova.compute.manager [instance: 9a495863-4fe2-4692-adfb-42a481d14336] result = proxy_call(self._autowrap, f, *args, **kwargs)
2013-09-17 08:40:42.153 21404 TRACE nova.compute.manager [instance: 9a495863-4fe2-4692-adfb-42a481d14336] File "/usr/local/lib/python2.7/dist-packages/eventlet/tpool.py", line 139, in proxy_call
2013-09-17 08:40:42.153 21404 TRACE nova.compute.manager [instance: 9a495863-4fe2-4692-adfb-42a481d14336] rv = execute(f,*args,**kwargs)
2013-09-17 08:40:42.153 21404 TRACE nova.compute.manager [instance: 9a495863-4fe2-4692-adfb-42a481d14336] File "/usr/local/lib/python2.7/dist-packages/eventlet/tpool.py", line 77, in tworker
2013-09-17 08:40:42.153 214...

[Joe Gordon (jogo)]

marking this as critical for nova as we are seeing it transiently in tempest gate runs.

[Davanum Srinivas (DIMS) (dims-v)]

I have a review against Tempest - https://review.openstack.org/#/c/47494/

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: master
Review: https://review.openstack.org/52145

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/52145
Committed: http://github.com/openstack/tempest/commit/4629a238b46e93b75e532249ce2a99191dec2260
Submitter: Jenkins
Branch: master

commit 4629a238b46e93b75e532249ce2a99191dec2260
Author: Attila Fazekas <email address hidden>
Date: Wed Oct 16 17:20:45 2013 +0200

    Fixing ImagesOneServerTestXml issue

    Now operations started with the server when it's task state was not
    None. Ie. Idle / 'ready for action'.

    The wait for wait_for_server_status method implicitly waits for the None
    task state, it should be able to fix the issue.

    The server will be rebuilded if otherwise it cannot be move to a clean active
    state, this issue will be logged.
    It is an unexpected exception, so the log verifier should be able to
    report it.

    Fixing bug 1218391

    Change-Id: Ib0e90a06e0e34f134bcca74712939e87e235c1ea

[Sean Dague (sdague)]

there is only 1 hit in the last 2 weeks on this test, I actually think it's closed