test_force_delete_snapshot fails with no volume device file path

Bug #1291108 reported by Mike Perez on 2014-03-11
6
This bug affects 1 person
Affects Status Importance Assigned to Milestone
Cinder
High
Mike Perez

Bug Description

2014-03-11 18:50:26.524 | FAIL: cinder.tests.api.contrib.test_admin_actions.AdminActionsTest.test_force_delete_snapshot
2014-03-11 18:50:26.524 | tags: worker-0
2014-03-11 18:50:26.524 | ----------------------------------------------------------------------
2014-03-11 18:50:26.524 | Empty attachments:
2014-03-11 18:50:26.524 | pythonlogging:''-1
2014-03-11 18:50:26.524 | stderr
2014-03-11 18:50:26.524 | stdout
2014-03-11 18:50:26.524 |
2014-03-11 18:50:26.525 | pythonlogging:'': {{{
2014-03-11 18:50:26.525 | Starting cinder-volume node (version 2014.1)
2014-03-11 18:50:26.525 | Starting volume driver FakeISCSIDriver (2.0.0)
2014-03-11 18:50:26.525 | volume cedd21ea-cd89-45ca-82d8-5a7cf1e0e6b5: skipping export
2014-03-11 18:50:26.525 | Updating volume status
2014-03-11 18:50:26.525 | Initializing extension manager.
2014-03-11 18:50:26.525 | Loaded extension: os-vol-tenant-attr
2014-03-11 18:50:26.525 | Loaded extension: os-types-extra-specs
2014-03-11 18:50:26.525 | Loaded extension: os-vol-host-attr
2014-03-11 18:50:26.525 | Loaded extension: os-volume-encryption-metadata
2014-03-11 18:50:26.525 | Loaded extension: OS-SCH-HNT
2014-03-11 18:50:26.525 | Loaded extension: os-availability-zone
2014-03-11 18:50:26.526 | Loaded extension: os-vol-image-meta
2014-03-11 18:50:26.526 | Loaded extension: os-snapshot-actions
2014-03-11 18:50:26.526 | Loaded extension: os-quota-sets
2014-03-11 18:50:26.526 | Loaded extension: os-volume-actions
2014-03-11 18:50:26.526 | Loaded extension: os-volume-manage
2014-03-11 18:50:26.526 | Loaded extension: os-image-create
2014-03-11 18:50:26.526 | Loaded extension: qos-specs
2014-03-11 18:50:26.526 | Loaded extension: backups
2014-03-11 18:50:26.526 | Loaded extension: encryption
2014-03-11 18:50:26.526 | Loaded extension: os-used-limits
2014-03-11 18:50:26.526 | Loaded extension: os-types-manage
2014-03-11 18:50:26.526 | Loaded extension: os-vol-mig-status-attr
2014-03-11 18:50:26.527 | Loaded extension: os-extended-services
2014-03-11 18:50:26.527 | Loaded extension: os-quota-class-sets
2014-03-11 18:50:26.527 | Loaded extension: os-volume-transfer
2014-03-11 18:50:26.527 | Loaded extension: os-volume-unmanage
2014-03-11 18:50:26.527 | Loaded extension: os-hosts
2014-03-11 18:50:26.527 | Loaded extension: os-extended-snapshot-attributes
2014-03-11 18:50:26.527 | Loaded extension: os-services
2014-03-11 18:50:26.527 | Loaded extension: os-admin-actions
2014-03-11 18:50:26.527 | POST http://localhost/v2/fake/snapshots/5ccb04ea-6a62-4e57-9299-e8ae34ecc34b/action
2014-03-11 18:50:26.527 | http://localhost/v2/fake/snapshots/5ccb04ea-6a62-4e57-9299-e8ae34ecc34b/action returned with HTTP 202
2014-03-11 18:50:26.527 | Arguments dropped when creating context: {'user': 'admin', 'tenant': 'fake'}
2014-03-11 18:50:26.527 | snapshot 5ccb04ea-6a62-4e57-9299-e8ae34ecc34b: deleting
2014-03-11 18:50:26.528 | Volume device file path /tmp/tmp.udMSkMDFJg/tmpKYdE0X/tmpSeiWSd/tmpzCdDA-cow does not exist.
2014-03-11 18:50:26.528 | Exception during message handling: Bad or unexpected response from the storage volume backend API: Volume device file path /tmp/tmp.udMSkMDFJg/tmpKYdE0X/tmpSeiWSd/tmpzCdDA-cow does not exist.
2014-03-11 18:50:26.528 | Traceback (most recent call last):
2014-03-11 18:50:26.528 | File "/home/jenkins/workspace/gate-cinder-python27/.tox/py27/local/lib/python2.7/site-packages/oslo/messaging/rpc/dispatcher.py", line 133, in _dispatch_and_reply
2014-03-11 18:50:26.528 | incoming.message))
2014-03-11 18:50:26.528 | File "/home/jenkins/workspace/gate-cinder-python27/.tox/py27/local/lib/python2.7/site-packages/oslo/messaging/rpc/dispatcher.py", line 176, in _dispatch
2014-03-11 18:50:26.528 | return self._do_dispatch(endpoint, method, ctxt, args)
2014-03-11 18:50:26.528 | File "/home/jenkins/workspace/gate-cinder-python27/.tox/py27/local/lib/python2.7/site-packages/oslo/messaging/rpc/dispatcher.py", line 122, in _do_dispatch
2014-03-11 18:50:26.528 | result = getattr(endpoint, method)(ctxt, **new_args)
2014-03-11 18:50:26.528 | File "cinder/volume/manager.py", line 166, in lso_inner1
2014-03-11 18:50:26.528 | return lso_inner2(inst, context, snapshot_id, **kwargs)
2014-03-11 18:50:26.529 | File "cinder/openstack/common/lockutils.py", line 247, in inner
2014-03-11 18:50:26.529 | retval = f(*args, **kwargs)
2014-03-11 18:50:26.529 | File "cinder/volume/manager.py", line 165, in lso_inner2
2014-03-11 18:50:26.529 | return f(*_args, **_kwargs)
2014-03-11 18:50:26.529 | File "cinder/volume/manager.py", line 542, in delete_snapshot
2014-03-11 18:50:26.529 | {'status': 'error_deleting'})
2014-03-11 18:50:26.529 | File "cinder/openstack/common/excutils.py", line 68, in __exit__
2014-03-11 18:50:26.529 | six.reraise(self.type_, self.value, self.tb)
2014-03-11 18:50:26.529 | File "cinder/volume/manager.py", line 530, in delete_snapshot
2014-03-11 18:50:26.529 | self.driver.delete_snapshot(snapshot_ref)
2014-03-11 18:50:26.529 | File "cinder/volume/drivers/lvm.py", line 252, in delete_snapshot
2014-03-11 18:50:26.529 | self._delete_volume(snapshot, is_snapshot=True)
2014-03-11 18:50:26.530 | File "cinder/volume/drivers/lvm.py", line 128, in _delete_volume
2014-03-11 18:50:26.530 | self._clear_volume(volume, is_snapshot)
2014-03-11 18:50:26.530 | File "cinder/volume/drivers/lvm.py", line 155, in _clear_volume
2014-03-11 18:50:26.530 | raise exception.VolumeBackendAPIException(data=msg)
2014-03-11 18:50:26.530 | VolumeBackendAPIException: Bad or unexpected response from the storage volume backend API: Volume device file path /tmp/tmp.udMSkMDFJg/tmpKYdE0X/tmpSeiWSd/tmpzCdDA-cow does not exist.
2014-03-11 18:50:26.530 | }}}
2014-03-11 18:50:26.530 |
2014-03-11 18:53:19.295 | Traceback (most recent call last):
2014-03-11 18:53:19.295 | File "cinder/tests/api/contrib/test_admin_actions.py", line 312, in test_force_delete_snapshot
2014-03-11 18:53:19.296 | snapshot['id'])
2014-03-11 18:53:19.296 | File "/home/jenkins/workspace/gate-cinder-python27/.tox/py27/local/lib/python2.7/site-packages/testtools/testcase.py", line 393, in assertRaises
2014-03-11 18:53:19.296 | self.assertThat(our_callable, matcher)
2014-03-11 18:53:19.296 | File "/home/jenkins/workspace/gate-cinder-python27/.tox/py27/local/lib/python2.7/site-packages/testtools/testcase.py", line 406, in assertThat
2014-03-11 18:53:19.296 | raise mismatch_error
2014-03-11 18:53:19.296 | MismatchError: <function snapshot_get at 0x2348848> returned <cinder.db.sqlalchemy.models.Snapshot object at 0x6d02050>

http://logs.openstack.org/68/79568/1/gate/gate-cinder-python27/b823a23/console.html

Mike Perez (thingee) on 2014-03-17
Changed in cinder:
assignee: nobody → Mike Perez (thingee)
status: New → In Progress
Mike Perez (thingee) wrote :

The stub in this test was changing local_path of the snapshot each time self.driver.local_path() was called. LVMVolumeDriver._clear_volume() does a path exists check on local_path(snapshot), which would sometimes fail because the local_path() would right then and there create a new temp file and change the path again. While this should be synchronous, my guess is there is no acknowledgement this is done and sometimes the drive couldn't keep up, so the file wouldn't be there.

https://github.com/openstack/cinder/blob/bcd9f363ff8a10ff30795c54f471a8c6d76450fe/cinder/tests/api/contrib/test_admin_actions.py#L294

https://github.com/openstack/cinder/blob/bcd9f363ff8a10ff30795c54f471a8c6d76450fe/cinder/tests/api/contrib/test_admin_actions.py#L294

Mike Perez (thingee) on 2014-03-18
Changed in cinder:
importance: Undecided → High

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

commit 71853a32111ec9a36f8a2082b41b52519b66be85
Author: Mike Perez <email address hidden>
Date: Sun Mar 16 22:24:38 2014 -0700

    Simplify test force delete snapshot unit test

    Make this test simple in just verifying if we have a snapshot and we do
    a force delete that we get back an ok response from the controller.
    Removing out RPC call and verifying snapshot was deleted since that's
    out of the scope here.

    Closes-Bug: #1291108
    Change-Id: If10b1057cf170e77527a0933a1ddf1a6a59baa1d

Changed in cinder:
status: In Progress → Fix Committed
Thierry Carrez (ttx) on 2014-03-27
Changed in cinder:
status: Fix Committed → Fix Released
Thierry Carrez (ttx) on 2014-04-17
Changed in cinder:
milestone: icehouse-rc1 → 2014.1
To post a comment you must log in.
This report contains Public information  Edit
Everyone can see this information.

Other bug subscribers