Serverfault on API tests

[Kevin Benton]

One of the test runs failed in several unrelated categories to the tested patch with an error like the one below:

ft15.1: setUpClass (tempest.api.compute.v3.servers.test_server_addresses.ServerAddressesV3Test)_StringException: Traceback (most recent call last):
  File "tempest/api/compute/v3/servers/test_server_addresses.py", line 32, in setUpClass
    resp, cls.server = cls.create_test_server(wait_until='ACTIVE')
  File "tempest/api/compute/base.py", line 247, in create_test_server
    raise ex
ServerFault: Got server fault
Details: The server has either erred or is incapable of performing the requested operation.

Full test results: http://logs.openstack.org/57/96957/1/check/check-grenade-dsvm-neutron/e15aebd/logs/testr_results.html.gz

[Joshua Harlow (harlowja)]

Seeing another case of this (in another test).

http://logs.openstack.org/79/103379/2/check/check-tempest-dsvm-full/9983737/logs/testr_results.html.gz

pythonlogging:'': {{{
2014-07-06 18:25:56,442 28145 INFO [tempest.common.rest_client] Request (ImagesTestXML:test_delete_saving_image): 200 POST http://127.0.0.1:5000/v2.0/tokens
2014-07-06 18:25:57,140 28145 INFO [tempest.common.rest_client] Request (ImagesTestXML:test_delete_saving_image): 202 POST http://127.0.0.1:8774/v2/c096c75fabea46b29a05714337d42e88/servers 0.697s
2014-07-06 18:25:57,276 28145 INFO [tempest.common.rest_client] Request (ImagesTestXML:test_delete_saving_image): 200 GET http://127.0.0.1:8774/v2/c096c75fabea46b29a05714337d42e88/servers/64599860-1d91-4a5c-a1c7-4d2f5547da54 0.135s
2014-07-06 18:25:58,451 28145 INFO [tempest.common.rest_client] Request (ImagesTestXML:test_delete_saving_image): 200 GET http://127.0.0.1:8774/v2/c096c75fabea46b29a05714337d42e88/servers/64599860-1d91-4a5c-a1c7-4d2f5547da54 0.170s
2014-07-06 18:25:58,452 28145 INFO [tempest.common.waiters] State transition "BUILD/scheduling" ==> "BUILD/spawning" after 1 second wait
2014-07-06 18:25:59,818 28145 INFO [tempest.common.rest_client] Request (ImagesTestXML:test_delete_saving_image): 200 GET http://127.0.0.1:8774/v2/c096c75fabea46b29a05714337d42e88/servers/64599860-1d91-4a5c-a1c7-4d2f5547da54 0.363s
2014-07-06 18:26:01,073 28145 INFO [tempest.common.rest_client] Request (ImagesTestXML:test_delete_saving_image): 200 GET http://127.0.0.1:8774/v2/c096c75fabea46b29a05714337d42e88/servers/64599860-1d91-4a5c-a1c7-4d2f5547da54 0.251s
2014-07-06 18:26:02,520 28145 INFO [tempest.common.rest_client] Request (ImagesTestXML:test_delete_saving_image): 200 GET http://127.0.0.1:8774/v2/c096c75fabea46b29a05714337d42e88/servers/64599860-1d91-4a5c-a1c7-4d2f5547da54 0.443s
2014-07-06 18:26:03,666 28145 INFO [tempest.common.rest_client] Request (ImagesTestXML:test_delete_saving_image): 200 GET http://127.0.0.1:8774/v2/c096c75fabea46b29a05714337d42e88/servers/64599860-1d91-4a5c-a1c7-4d2f5547da54 0.140s
2014-07-06 18:26:03,667 28145 INFO [tempest.common.waiters] State transition "BUILD/spawning" ==> "ACTIVE/None" after 6 second wait
2014-07-06 18:26:04,282 28145 INFO [tempest.common.rest_client] Request (ImagesTestXML:test_delete_saving_image): 202 POST http://127.0.0.1:8774/v2/c096c75fabea46b29a05714337d42e88/servers/64599860-1d91-4a5c-a1c7-4d2f5547da54/action 0.613s
2014-07-06 18:26:04,373 28145 INFO [tempest.common.rest_client] Request (ImagesTestXML:test_delete_saving_image): 200 GET http://127.0.0.1:8774/v2/c096c75fabea46b29a05714337d42e88/images/796d488f-c17c-4239-b1ee-b734be21350c 0.090s
2014-07-06 18:26:04,584 28145 INFO [tempest.common.rest_client] Request (ImagesTestXML:test_delete_saving_image): 200 GET http://127.0.0.1:8774/v2/c096c75fabea46b29a05714337d42e88/images/796d488f-c17c-4239-b1ee-b734be21350c 0.208s
2014-07-06 18:26:05,035 28145 INFO [tempest.common.rest_client] Request (ImagesTestXML:test_delete_saving_image): 500 DELETE http://127.0.0.1:8774/v2/c096c75fabea46b29a05714337d42e88/images/796d488f-c17c-4239-b1ee-b734be21350c 0.447s
2014-07-06 18:26:05,...

[Mauro S M Rodrigues (maurorodrigues)]

The underlying reason seems to be on glance's side:
http://logs.openstack.org/79/103379/2/check/check-tempest-dsvm-full/9983737/logs/screen-g-reg.txt.gz#_2014-07-06_18_26_04_913
specifically:
2014-07-06 18:26:04.913 24609 TRACE glance.registry.api.v1.images DBDeadlock: (OperationalError) (1213, 'Deadlock found when trying to get lock; try restarting transaction') 'UPDATE image_properties SET updated_at=%s, deleted_at=%s, deleted=%s WHERE image_properties.image_id = %s AND image_properties.deleted = false' (datetime.datetime(2014, 7, 6, 18, 26, 4, 860639), datetime.datetime(2014, 7, 6, 18, 26, 4, 835672), 1, '796d488f-c17c-4239-b1ee-b734be21350c')

Few hits found using >
http://logstash.openstack.org/#eyJzZWFyY2giOiJtZXNzYWdlOlwiVFJBQ0UgZ2xhbmNlLnJlZ2lzdHJ5LmFwaS52MS5pbWFnZXMgREJEZWFkbG9jazogKE9wZXJhdGlvbmFsRXJyb3IpXCIiLCJmaWVsZHMiOlsiYnVpbGRfbmFtZSJdLCJvZmZzZXQiOjAsInRpbWVmcmFtZSI6IjYwNDgwMCIsImdyYXBobW9kZSI6ImNvdW50IiwidGltZSI6eyJ1c2VyX2ludGVydmFsIjowfSwic3RhbXAiOjE0MTI2MDYzNzI0NTR9

5 hits in 7 days

[Abhishek Kekane (abhishek-kekane)]

Pretty old and not encountered again by anyone else.