failed to reach SHELVED_OFFLOADED status during tempest-dsvm

[Matt Fischer]

I added 2 log messages to glance and then my gate broke. It looks like it got stuck in "SHELVED" and failed to reach "SHELVED_OFFLOADED", although I lack the knowledge to know what this really means. I'm not even sure if this bug belongs in nova or elsewhere.

http://logs.openstack.org/89/68189/9/gate/gate-tempest-dsvm-postgres-full/ff84764/console.html

 Traceback (most recent call last):
2014-02-01 09:59:15.116 | File "tempest/api/compute/v3/servers/test_servers_negative.py", line 403, in test_shelve_shelved_server
2014-02-01 09:59:15.116 | extra_timeout=offload_time)
2014-02-01 09:59:15.116 | File "tempest/services/compute/v3/json/servers_client.py", line 169, in wait_for_server_status
2014-02-01 09:59:15.116 | raise_on_error=raise_on_error)
2014-02-01 09:59:15.116 | File "tempest/common/waiters.py", line 89, in wait_for_server_status
2014-02-01 09:59:15.116 | raise exceptions.TimeoutException(message)
2014-02-01 09:59:15.116 | TimeoutException: Request timed out
2014-02-01 09:59:15.116 | Details: Server d193bafb-11cf-4592-8be7-174d2f94a68d failed to reach SHELVED_OFFLOADED status and task state "None" within the required time (196 s). Current status: SHELVED. Current task state: None.
2014-02-01 09:59:15.116 |

[Matt Riedemann (mriedem)]

It's not just postgres:

http://logs.openstack.org/15/64915/8/check/check-tempest-dsvm-full/915e738/console.html

[Matt Riedemann (mriedem)]

Looks like it started showing up on 1/28:

http://logstash.openstack.org/#eyJzZWFyY2giOiJtZXNzYWdlOlwiRGV0YWlsczogU2VydmVyXCIgQU5EIG1lc3NhZ2U6XCJmYWlsZWQgdG8gcmVhY2ggU0hFTFZFRF9PRkZMT0FERUQgc3RhdHVzIGFuZCB0YXNrIHN0YXRlIFxcXCJOb25lXFxcIiB3aXRoaW4gdGhlIHJlcXVpcmVkIHRpbWVcIiBBTkQgbWVzc2FnZTpcIkN1cnJlbnQgc3RhdHVzOiBTSEVMVkVELiBDdXJyZW50IHRhc2sgc3RhdGU6IE5vbmUuXCIgQU5EIGZpbGVuYW1lOlwiY29uc29sZS5odG1sXCIiLCJmaWVsZHMiOltdLCJvZmZzZXQiOjAsInRpbWVmcmFtZSI6ImFsbCIsImdyYXBobW9kZSI6ImNvdW50IiwidGltZSI6eyJ1c2VyX2ludGVydmFsIjowfSwic3RhbXAiOjEzOTE1NDc5MTQwODB9

[Matt Riedemann (mriedem)]

This is the candidate regression:

https://review.openstack.org/61462

There are a lot of rechecks in that patch and it's related to shelving and went in around the same time this shows up in logstash.

[Matt Riedemann (mriedem)]

e-r query patch is up: https://review.openstack.org/#/c/71118/

I have a nova revert patch up also: https://review.openstack.org/#/c/71105/

[Matt Riedemann (mriedem)]

This might actually be the real fail:

http://logstash.openstack.org/#eyJzZWFyY2giOiJtZXNzYWdlOlwiRXJyb3IgZnJvbSBsaWJ2aXJ0IGR1cmluZyB1bmZpbHRlci4gQ29kZT01NSBFcnJvcj1SZXF1ZXN0ZWQgb3BlcmF0aW9uIGlzIG5vdCB2YWxpZDogbndmaWx0ZXIgaXMgaW4gdXNlXCIgQU5EIGZpbGVuYW1lOlwibG9ncy9zY3JlZW4tbi1jcHUudHh0XCIiLCJmaWVsZHMiOltdLCJvZmZzZXQiOjAsInRpbWVmcmFtZSI6ImFsbCIsImdyYXBobW9kZSI6ImNvdW50IiwidGltZSI6eyJ1c2VyX2ludGVydmFsIjowfSwic3RhbXAiOjEzOTE2MjM5MzE5MDN9

message:"Error from libvirt during unfilter. Code=55 Error=Requested operation is not valid: nwfilter is in use" AND filename:"logs/screen-n-cpu.txt"

[Matt Riedemann (mriedem)]

Wondering if this is maybe a result of bug 1276772.

[Matt Riedemann (mriedem)]

Looks like this might have actually fixed the root cause:

https://review.openstack.org/#/c/71363/

Because the trends for the shelving error are correlating with this:

http://logstash.openstack.org/#eyJzZWFyY2giOiJtZXNzYWdlOlwiRXJyb3IgZnJvbSBsaWJ2aXJ0IGR1cmluZyB1bmZpbHRlci4gQ29kZT01NSBFcnJvcj1SZXF1ZXN0ZWQgb3BlcmF0aW9uIGlzIG5vdCB2YWxpZDogbndmaWx0ZXIgaXMgaW4gdXNlXCIgQU5EIGZpbGVuYW1lOlwibG9ncy9zY3JlZW4tbi1jcHUudHh0XCIiLCJmaWVsZHMiOltdLCJvZmZzZXQiOjAsInRpbWVmcmFtZSI6ImFsbCIsImdyYXBobW9kZSI6ImNvdW50IiwidGltZSI6eyJ1c2VyX2ludGVydmFsIjowfSwic3RhbXAiOjEzOTE2MjM5MzE5MDN9

And they both showed up around the same time and are dropping out of logstash around the same time, after the above patch was merged.

[Joe Gordon (jogo)]

looks like this was resolved

[Ihar Hrachyshka (ihar-hrachyshka)]

Seeing it in Icehouse too: http://logs.openstack.org/periodic-stableperiodic-tempest-dsvm-full-icehouse/8326295/logs/testr_results.html.gz