timeout in wait_for_resource_deletion in tempest teardown

[Jamie Lennox]

From: http://logs.openstack.org/61/77961/7/check/check-tempest-dsvm-full-icehouse/d8e6ebf/console.html#_2014-05-07_16_56_50_553

2014-05-07 16:56:50.553 | {0} tearDownClass (tempest.api.volume.test_volumes_list.VolumesListTest) [0.000000s] ... FAILED
2014-05-07 16:56:50.553 |
2014-05-07 16:56:50.553 | Captured traceback:
2014-05-07 16:56:50.553 | ~~~~~~~~~~~~~~~~~~~
2014-05-07 16:56:50.553 | Traceback (most recent call last):
2014-05-07 16:56:50.553 | File "tempest/api/volume/test_volumes_list.py", line 79, in tearDownClass
2014-05-07 16:56:50.553 | cls.client.wait_for_resource_deletion(volid)
2014-05-07 16:56:50.553 | File "tempest/common/rest_client.py", line 522, in wait_for_resource_deletion
2014-05-07 16:56:50.554 | raise exceptions.TimeoutException
2014-05-07 16:56:50.554 | TimeoutException: Request timed out
2014-05-07 16:56:50.554 |

I can't see any corresponding errors in either tempest, or cinder-api logs.

[Florent Flament (florentflament)]

Looks like we hit the same bug there: http://logs.openstack.org/22/121422/20/check/check-tempest-dsvm-full/1653e82/console.html

 2014-09-21 22:57:32.845 | tearDownClass (tempest.api.compute.servers.test_server_rescue_negative.ServerRescueNegativeTestJSON)
 2014-09-21 22:57:32.845 | ----------------------------------------------------------------------------------------------------
 2014-09-21 22:57:32.845 |
 2014-09-21 22:57:32.845 | Captured traceback:
 2014-09-21 22:57:32.845 | ~~~~~~~~~~~~~~~~~~~
 2014-09-21 22:57:32.846 | Traceback (most recent call last):
 2014-09-21 22:57:32.846 | File "tempest/api/compute/servers/test_server_rescue_negative.py", line 60, in tearDownClass
 2014-09-21 22:57:32.846 | cls.delete_volume(cls.volume['id'])
 2014-09-21 22:57:32.846 | File "tempest/api/compute/base.py", line 365, in delete_volume
 2014-09-21 22:57:32.846 | cls._delete_volume(cls.volumes_extensions_client, volume_id)
 2014-09-21 22:57:32.846 | File "tempest/api/compute/base.py", line 305, in _delete_volume
 2014-09-21 22:57:32.846 | volumes_client.wait_for_resource_deletion(volume_id)
 2014-09-21 22:57:32.846 | File "tempest/common/rest_client.py", line 561, in wait_for_resource_deletion
 2014-09-21 22:57:32.846 | raise exceptions.TimeoutException(message)
 2014-09-21 22:57:32.846 | TimeoutException: Request timed out
 2014-09-21 22:57:32.846 | Details: (ServerRescueNegativeTestJSON:tearDownClass) Failed to delete resource 8a1d2b63-7ace-4627-8335-cfc5ccc7e833 within the required time (196 s).

Regards

[Boden R (boden)]

hitting it as well... logstash e-r query: http://logstash.openstack.org/#eyJzZWFyY2giOiJtZXNzYWdlOlwiRGV0YWlsczogKFNlcnZlclJlc2N1ZU5lZ2F0aXZlVGVzdEpTT046dGVhckRvd25DbGFzcykgRmFpbGVkIHRvIGRlbGV0ZSByZXNvdXJjZVwiIEFORCBtZXNzYWdlOlwid2l0aGluIHRoZSByZXF1aXJlZCB0aW1lXCIgQU5EIHRhZ3M6XCJjb25zb2xlXCIiLCJmaWVsZHMiOltdLCJvZmZzZXQiOjAsInRpbWVmcmFtZSI6IjYwNDgwMCIsImdyYXBobW9kZSI6ImNvdW50IiwidGltZSI6eyJ1c2VyX2ludGVydmFsIjowfSwic3RhbXAiOjE0MTE3NDYxNTE3MzV9

[OpenStack Infra (hudson-openstack)]

Related fix proposed to branch: master
Review: https://review.openstack.org/124456

[Joe Gordon (jogo)]

Looks like this is an issue with taking too long to delete volumes

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/124456
Committed: https://git.openstack.org/cgit/openstack-infra/elastic-recheck/commit/?id=969950d7ab2fbc0f793c34266cd4721c45663cbe
Submitter: Jenkins
Branch: master

commit 969950d7ab2fbc0f793c34266cd4721c45663cbe
Author: Boden R <email address hidden>
Date: Fri Sep 26 12:13:17 2014 -0400

    query for teardown bug 1317298

    Since it's a timeout bug I'm fingerprinting on the
    error in the console log, which at least has the test
    class in the message.

    32 hits in 7 days, all failures.

    Change-Id: Ibd83994a194ae6c8e2aaf05126c270b8c5111d83
    Related-Bug: 1317298

[git-harry (git-harry)]

http://logs.openstack.org/51/111051/3/check/check-tempest-dsvm-full/51e856c/logs/screen-c-vol.txt.gz

I had a review affected by this bug. The logs suggest the issue relates to two lvm calls - specifically lvs and lvdisplay. The following extracts from the log file show the duration of three lvm calls that make up the delete:

2014-09-19 15:12:13.847 24218 DEBUG cinder.openstack.common.processutils [req-53fb1b6a-3732-432b-b3c1-225d356b7d56 bb0b7281d2c34c14a2416c3d042c8ec0 50ebe5fb0de148838d4f423feafcab07 - - -] Running cmd (subprocess): sudo cinder-rootwrap /etc/cinder/rootwrap.conf env LC_ALL=C lvs --noheadings --unit=g -o vg_name,name,size --nosuffix stack-volumes-lvmdriver-1 execute /opt/stack/new/cinder/cinder/openstack/common/processutils.py:158

2014-09-19 15:14:13.531 24218 DEBUG cinder.openstack.common.processutils [req-53fb1b6a-3732-432b-b3c1-225d356b7d56 bb0b7281d2c34c14a2416c3d042c8ec0 50ebe5fb0de148838d4f423feafcab07 - - -] Result was 0 execute /opt/stack/new/cinder/cinder/openstack/common/processutils.py:192

~120 seconds

2014-09-19 15:14:13.533 24218 DEBUG cinder.openstack.common.processutils [req-53fb1b6a-3732-432b-b3c1-225d356b7d56 bb0b7281d2c34c14a2416c3d042c8ec0 50ebe5fb0de148838d4f423feafcab07 - - -] Running cmd (subprocess): sudo cinder-rootwrap /etc/cinder/rootwrap.conf env LC_ALL=C lvdisplay --noheading -C -o Attr stack-volumes-lvmdriver-1/volume-aeeaad03-c438-41f9-8fac-43b2e58a1933 execute /opt/stack/new/cinder/cinder/openstack/common/processutils.py:158

2014-09-19 15:15:29.323 24218 DEBUG cinder.openstack.common.processutils [req-53fb1b6a-3732-432b-b3c1-225d356b7d56 bb0b7281d2c34c14a2416c3d042c8ec0 50ebe5fb0de148838d4f423feafcab07 - - -] Result was 0 execute /opt/stack/new/cinder/cinder/openstack/common/processutils.py:192

~75 seconds

2014-09-19 15:15:29.324 24218 DEBUG cinder.openstack.common.processutils [req-53fb1b6a-3732-432b-b3c1-225d356b7d56 bb0b7281d2c34c14a2416c3d042c8ec0 50ebe5fb0de148838d4f423feafcab07 - - -] Running cmd (subprocess): sudo cinder-rootwrap /etc/cinder/rootwrap.conf lvremove --config activation { retry_deactivation = 1} -f stack-volumes-lvmdriver-1/volume-aeeaad03-c438-41f9-8fac-43b2e58a1933 execute /opt/stack/new/cinder/cinder/openstack/common/processutils.py:158

2014-09-19 15:15:29.708 24218 DEBUG cinder.openstack.common.processutils [req-53fb1b6a-3732-432b-b3c1-225d356b7d56 bb0b7281d2c34c14a2416c3d042c8ec0 50ebe5fb0de148838d4f423feafcab07 - - -] Result was 0 execute /opt/stack/new/cinder/cinder/openstack/common/processutils.py:192

~1 second

[Matt Riedemann (mriedem)]

This is probably just a duplicate of bug 1373513.

[Matt Riedemann (mriedem)]

The rescue test failure in comment 1 is probably bug 1353939.

[OpenStack Infra (hudson-openstack)]

Related fix proposed to branch: master
Review: https://review.openstack.org/128107