Volume group for uuid not found

[Sean Dague]

There is a periodically occurring race condition on Volumes that exposes as the following error in Cinder Volume service in the gate:

2014-06-30 14:07:17.205 19616 ERROR cinder.brick.local_dev.lvm [req-3f6d886d-cf19-4fe8-a917-d0ff6c97940b dd9fe73bc43e440fab74983df09b4888 2a9f335f064a4466b37daddbb1a1ff7e - - -] Cmd :sudo cinder-rootwrap /etc/cinder/rootwrap.conf lvcreate --name _snapshot-207e0ef0-dc73-4c1e-955f-375358fa7b51 --snapshot stack-volumes/volume-13b6dbcf-e414-4939-bfce-1eea3b272f4f -L 1.00g
2014-06-30 14:07:17.205 19616 ERROR cinder.brick.local_dev.lvm [req-3f6d886d-cf19-4fe8-a917-d0ff6c97940b dd9fe73bc43e440fab74983df09b4888 2a9f335f064a4466b37daddbb1a1ff7e - - -] StdOut :
2014-06-30 14:07:17.205 19616 ERROR cinder.brick.local_dev.lvm [req-3f6d886d-cf19-4fe8-a917-d0ff6c97940b dd9fe73bc43e440fab74983df09b4888 2a9f335f064a4466b37daddbb1a1ff7e - - -] StdErr : /dev/loop1: Checksum error
  Volume group for uuid not found: JddPC4d4gvMd9RxcWM5Tzqn8W6Jh8BtbPaCSTd1yKHMK3chelWx8EFdNx0R4Ag0x
  Problem reactivating origin volume-13b6dbcf-e414-4939-bfce-1eea3b272f4f
  libdevmapper exiting with 2 device(s) still suspended.

2014-06-30 14:07:17.236 19616 ERROR oslo.messaging.rpc.dispatcher [req-3f6d886d-cf19-4fe8-a917-d0ff6c97940b dd9fe73bc43e440fab74983df09b4888 2a9f335f064a4466b37daddbb1a1ff7e - - -] Exception during message handling: Unexpected error while running command.
Command: sudo cinder-rootwrap /etc/cinder/rootwrap.conf lvcreate --name _snapshot-207e0ef0-dc73-4c1e-955f-375358fa7b51 --snapshot stack-volumes/volume-13b6dbcf-e414-4939-bfce-1eea3b272f4f -L 1.00g
Exit code: 5
Stdout: ''
Stderr: ' /dev/loop1: Checksum error\n Volume group for uuid not found: JddPC4d4gvMd9RxcWM5Tzqn8W6Jh8BtbPaCSTd1yKHMK3chelWx8EFdNx0R4Ag0x\n Problem reactivating origin volume-13b6dbcf-e414-4939-bfce-1eea3b272f4f\n libdevmapper exiting with 2 device(s) still suspended.\n'

Error log here - http://logs.openstack.org/35/103535/3/gate/gate-tempest-dsvm-full/08c8ed9/logs/screen-c-vol.txt.gz?level=TRACE#_2014-06-30_14_07_17_205

[Boris Pavlovic (boris-42)]

Rally gates are catching this race as well:

http://logs.openstack.org/80/146580/19/check/gate-rally-dsvm-neutron-rally/6153646/rally-plot/results.html.gz

and logs are here:
http://logs.openstack.org/80/146580/19/check/gate-rally-dsvm-neutron-rally/6153646/logs/screen-c-vol.txt.gz

[John Griffith (john-griffith)]

My bad... I was confusing this with the old "delete snapshot", but this is on create; and a checksum error on /dev/loop0 that's causing the error

[OpenStack Infra (hudson-openstack)]

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

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/149360
Committed: https://git.openstack.org/cgit/openstack/cinder/commit/?id=e302cefafc18754a4495ad061062732b97d326ea
Submitter: Jenkins
Branch: master

commit e302cefafc18754a4495ad061062732b97d326ea
Author: John Griffith <email address hidden>
Date: Thu Jan 22 11:22:25 2015 -0700

    Add retry to lvm snapshot create

    We have some occasional issues with snapshot-create
    failing for what looks to be conflicts with udev. It
    looks like this problem is a status conflict between LVM
    cache and udev, and in most cases the best way to get
    around this is to retry the command a few times until
    the cache and udev are back in sync.

    This patch uses the newly added retry decorator and
    for now we're just adding it to the snapshot create
    call. We're using the default values for interval and
    retry count but we can certainly adjust this as needed.

    Change-Id: Ic884b829591361da979fde968f5710237b34565f
    Closes-Bug: #1335905

[John Griffith (john-griffith)]

Looks like we should probably backport this to Juno as well

[Mike Perez (thingee)]

Nope, still broken!

From dup bug:

http://logs.openstack.org/80/174480/15/check/check-tempest-dsvm-full/27b3bb4/console.html#_2015-04-29_15_26_48_298

2015-04-29 15:26:48.298 | tearDownClass (tempest.thirdparty.boto.test_ec2_instance_run.InstanceRunTest)
2015-04-29 15:26:48.298 | -----------------------------------------------------------------------------
2015-04-29 15:26:48.298 |
2015-04-29 15:26:48.299 | Captured traceback:
2015-04-29 15:26:48.299 | ~~~~~~~~~~~~~~~~~~~
2015-04-29 15:26:48.299 | Traceback (most recent call last):
2015-04-29 15:26:48.299 | File "tempest/test.py", line 288, in tearDownClass
2015-04-29 15:26:48.300 | teardown()
2015-04-29 15:26:48.300 | File "tempest/thirdparty/boto/test.py", line 283, in resource_cleanup
2015-04-29 15:26:48.300 | raise exceptions.TearDownException(num=fail_count)
2015-04-29 15:26:48.301 | tempest.exceptions.TearDownException: 1 cleanUp operation failed

http://logstash.openstack.org/#eyJzZWFyY2giOiJtZXNzYWdlOlwiRmlsZSBcXFwidGVtcGVzdC90aGlyZHBhcnR5L2JvdG8vdGVzdC5weVxcXCJcIiBBTkQgbWVzc2FnZTpcImluIHJlc291cmNlX2NsZWFudXBcIiIsImZpZWxkcyI6W10sIm9mZnNldCI6MCwidGltZWZyYW1lIjoiNjA0ODAwIiwiZ3JhcGhtb2RlIjoiY291bnQiLCJ0aW1lIjp7InVzZXJfaW50ZXJ2YWwiOjB9LCJzdGFtcCI6MTQzMDMyMjY0NzIwNn0=

The tempest log has a more specific error:

http://logs.openstack.org/80/174480/15/check/check-tempest-dsvm-full/27b3bb4/logs/tempest.txt.gz?level=TRACE#_2015-04-29_15_22_12_234

2015-04-29 15:22:12.234 5359 ERROR tempest.thirdparty.boto.test [-] Cleanup failed APIClientEC2.deregister_image(aki-00000010)
2015-04-29 15:22:12.234 5359 TRACE tempest.thirdparty.boto.test Traceback (most recent call last):
2015-04-29 15:22:12.234 5359 TRACE tempest.thirdparty.boto.test File "tempest/thirdparty/boto/test.py", line 272, in resource_cleanup
2015-04-29 15:22:12.234 5359 TRACE tempest.thirdparty.boto.test function(*pos_args, **kw_args)
2015-04-29 15:22:12.234 5359 TRACE tempest.thirdparty.boto.test File "tempest/services/botoclients.py", line 68, in func
2015-04-29 15:22:12.234 5359 TRACE tempest.thirdparty.boto.test return getattr(conn, name)(*args, **kwargs)
2015-04-29 15:22:12.234 5359 TRACE tempest.thirdparty.boto.test File "/opt/stack/new/tempest/.tox/full/local/lib/python2.7/site-packages/boto/ec2/connection.py", line 394, in deregister_image
2015-04-29 15:22:12.234 5359 TRACE tempest.thirdparty.boto.test params, verb='POST')
2015-04-29 15:22:12.234 5359 TRACE tempest.thirdparty.boto.test File "/opt/stack/new/tempest/.tox/full/local/lib/python2.7/site-packages/boto/connection.py", line 1227, in get_status
2015-04-29 15:22:12.234 5359 TRACE tempest.thirdparty.boto.test raise self.ResponseError(response.status, response.reason, body)
2015-04-29 15:22:12.234 5359 TRACE tempest.thirdparty.boto.test EC2ResponseError: EC2ResponseError: 404 Not Found
2015-04-29 15:22:12.234 5359 TRACE tempest.thirdparty.boto.test <?xml version="1.0"?>
2015-04-29 15:22:12.234 5359 TRACE tempest.thirdparty.boto.test <Response><Errors><Error><Code>ImageNotFound</Code><Message>Image 19f1e137-3765-48ef-a57e-ab166d26d746 could not be found.</Message></Error></Errors><RequestID>req-5cc6958d-3ae1-40f1-9b8e-3afd08c7d494</RequestID></Response>
2015-04-29 15:22:...

[John Griffith (john-griffith)]

@Mike
This is a different bug, this issue was for snapshot-create, the issue being seen currently that you're marking as "still broken" and dup is: 1450110 which is specifically on snapshot-delete.

Two separate issues IMO

[Mike Perez (thingee)]

@John Ok fixed, thanks!