"EC2ResponseError: EC2ResponseError: 400 Bad Request" in tempest.thirdparty.boto.test_ec2_instance_run.InstanceRunTest.test_integration_1

[YAMAMOTO Takashi]

2014-04-22 00:33:21.197 | 2014-04-22 00:31:41,668 400 Bad Request
2014-04-22 00:33:21.197 | 2014-04-22 00:31:41,669 <?xml version="1.0"?>
2014-04-22 00:33:21.197 | <Response><Errors><Error><Code>IncorrectState</Code><Message>Volume 7ec87937-4a0d-4548-94a1-e85d26b68c08 is not attached to anything</Message></Error></Errors><RequestID>req-8d225660-d8d6-43b8-958e-bf85cd2f4e09</RequestID></Response>
2014-04-22 00:33:21.197 | }}}
2014-04-22 00:33:21.197 |
2014-04-22 00:33:21.197 | Traceback (most recent call last):
2014-04-22 00:33:21.197 | File "tempest/thirdparty/boto/test_ec2_instance_run.py", line 310, in test_integration_1
2014-04-22 00:33:21.197 | volume.detach()
2014-04-22 00:33:21.197 | File "/usr/local/lib/python2.7/dist-packages/boto/ec2/volume.py", line 183, in detach
2014-04-22 00:33:21.198 | dry_run=dry_run
2014-04-22 00:33:21.198 | File "/usr/local/lib/python2.7/dist-packages/boto/ec2/connection.py", line 2357, in detach_volume
2014-04-22 00:33:21.198 | return self.get_status('DetachVolume', params, verb='POST')
2014-04-22 00:33:21.198 | File "/usr/local/lib/python2.7/dist-packages/boto/connection.py", line 1196, in get_status
2014-04-22 00:33:21.198 | raise self.ResponseError(response.status, response.reason, body)
2014-04-22 00:33:21.198 | EC2ResponseError: EC2ResponseError: 400 Bad Request
2014-04-22 00:33:21.198 | <?xml version="1.0"?>
2014-04-22 00:33:21.198 | <Response><Errors><Error><Code>IncorrectState</Code><Message>Volume 7ec87937-4a0d-4548-94a1-e85d26b68c08 is not attached to anything</Message></Error></Errors><RequestID>req-8d225660-d8d6-43b8-958e-bf85cd2f4e09</RequestID></Response>

http://logs.openstack.org/24/88224/2/check/check-tempest-dsvm-neutron/d060a98/console.html#_2014-04-22_00_33_21_197

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

[Joe Gordon (jogo)]

It appears this is due to tempest having bad cleanup logic after a test fails. So it looks like this is a tempest issue.

[Ghanshyam Mann (ghanshyammann)]

Lot of hits in past 24 hrs

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

[Ghanshyam Mann (ghanshyammann)]

Volume creation was failed due to insufficient free space on host. opening for cinder to whether its valid bug for them or not.

c-api log -

2014-10-14 03:06:02.642 22981 INFO eventlet.wsgi.server [req-f33e98ec-1eaf-4631-b174-3d676c5b02e5 1d83c158db7f4d75bd0095707e7d4b13 667fa2f7ecd649319b46e66217e8b8a4 - - -] 127.0.0.1 - - [14/Oct/2014 03:06:02] "POST /v1/667fa2f7ecd649319b46e66217e8b8a4/volumes HTTP/1.1" 200 603 0.607899

c-sch logs-

2014-10-14 03:06:02.649 22995 WARNING cinder.scheduler.filters.capacity_filter [req-f33e98ec-1eaf-4631-b174-3d676c5b02e5 1d83c158db7f4d75bd0095707e7d4b13 667fa2f7ecd649319b46e66217e8b8a4 - - -] Insufficient free space for volume creation on host devstack-trusty-hpcloud-b1-2622048@lvmdriver-1#lvmdriver-1 (requested / avail): 1/0.0
2014-10-14 03:06:02.649 22995 WARNING cinder.scheduler.filter_scheduler [req-f33e98ec-1eaf-4631-b174-3d676c5b02e5 1d83c158db7f4d75bd0095707e7d4b13 667fa2f7ecd649319b46e66217e8b8a4 - - -] No weighed hosts found for volume with properties: {u'name': u'lvmdriver-1', u'qos_specs_id': None, u'deleted': False, u'created_at': u'2014-10-14T01:55:14.000000', u'updated_at': None, u'extra_specs': {u'volume_backend_name': u'lvmdriver-1'}, u'deleted_at': None, u'id': u'345b46fe-09e4-4dd0-b490-c8a71e05321c'}
2014-10-14 03:06:02.653 22995 ERROR cinder.scheduler.flows.create_volume [req-f33e98ec-1eaf-4631-b174-3d676c5b02e5 1d83c158db7f4d75bd0095707e7d4b13 667fa2f7ecd649319b46e66217e8b8a4 - - -] Failed to run task cinder.scheduler.flows.create_volume.ScheduleCreateVolumeTask;volume:create: No valid host was found. No weighed hosts available

[Ghanshyam Mann (ghanshyammann)]

Here Volume creation was failed (above comment) and volume went to "error" state. Tempest cleanup part was not good enough to serve this case.

In destroy_volume_wait, it try to detach volume if volume status is not "available". If volume is in "error" state then, also it try to detach and through error as reported.

Logic in destroy_volume_wait should be checking of state as "in-use" before trying to detach volume. So that if it is in "in-use" state then detach and go for volume delete. If not in "in-use" ("available" or "error" etc) then do not try to detach as it is not attached and go for volume delete.

[OpenStack Infra (hudson-openstack)]

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

[Ghanshyam Mann (ghanshyammann)]

Found same kind of bug for Cinder - https://bugs.launchpad.net/cinder/+bug/1376941

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/128201
Committed: https://git.openstack.org/cgit/openstack/tempest/commit/?id=308640c1121f5a4ca33c7723397457e2288c212e
Submitter: Jenkins
Branch: master

commit 308640c1121f5a4ca33c7723397457e2288c212e
Author: ghanshyam <email address hidden>
Date: Tue Oct 14 17:23:31 2014 +0900

    Fix cleanup for EC2 test_compute_with_volumes

    Volume cleanup for test_compute_with_volumes fails when volume is in
    "error" state.

    cleanup part destroy_volume_wait() is to delete the volume and detach
    before delete if necessary.
    In destroy_volume_wait(), before detaching the volume there is checks if
    volume status is not "available" but that is not sufficient enough to
    guarantee that volume is attached. Volume status can be "error".

    When something wrong happens with Volume and Volume is in "error"
    state then, detach request will through the error as mentioned in
    bug# 1310896.

    Logic in destroy_volume_wait should be checking of state as "in-use" before
    trying to detach volume. So that if it is in "in-use" state then detach and
    go for volume delete. If not in "in-use" ("available" or "error" etc) then
    only go for volume delete.

    Change-Id: I1882dbba947cc294cb4fe119db50f2a1c23b75be
    Related-Bug: #1310896

[Sean McGinnis (sean-mcginnis)]

Closing stale bug. If this is still an issue please reopen.