test_volume_extend_when_volume_has_snapshot fails with VolumeNotDeactivated

[Ihar Hrachyshka]

http://logs.openstack.org/08/460908/2/check/gate-tempest-dsvm-neutron-full-ubuntu-xenial/70f8559/logs/testr_results.html.gz

Traceback (most recent call last):
  File "tempest/api/volume/test_volumes_extend.py", line 51, in test_volume_extend_when_volume_has_snapshot
    volume['id'], 'available')
  File "tempest/common/waiters.py", line 210, in wait_for_volume_resource_status
    raise lib_exc.TimeoutException(message)
tempest.lib.exceptions.TimeoutException: Request timed out
Details: volume e1133173-dc69-4e1f-8836-6c9bd2c0b65b failed to reach available status (current error_extending) within the required time (196 s).

In c-vol log, we see: http://logs.openstack.org/08/460908/2/check/gate-tempest-dsvm-neutron-full-ubuntu-xenial/70f8559/logs/screen-c-vol.txt.gz#_2017-04-28_13_23_25_455

2017-04-28 13:23:25.455 4268 ERROR cinder.volume.manager [req-3703d0d1-effc-4f4a-8616-4f59220022c0 tempest-VolumesExtendTest-1726373799 -] Extend volume failed.
2017-04-28 13:23:25.455 4268 ERROR cinder.volume.manager Traceback (most recent call last):
2017-04-28 13:23:25.455 4268 ERROR cinder.volume.manager File "/opt/stack/new/cinder/cinder/volume/manager.py", line 2208, in extend_volume
2017-04-28 13:23:25.455 4268 ERROR cinder.volume.manager self.driver.extend_volume(volume, new_size)
2017-04-28 13:23:25.455 4268 ERROR cinder.volume.manager File "/opt/stack/new/cinder/cinder/volume/drivers/lvm.py", line 594, in extend_volume
2017-04-28 13:23:25.455 4268 ERROR cinder.volume.manager self._sizestr(new_size))
2017-04-28 13:23:25.455 4268 ERROR cinder.volume.manager File "/opt/stack/new/cinder/cinder/brick/local_dev/lvm.py", line 810, in extend_volume
2017-04-28 13:23:25.455 4268 ERROR cinder.volume.manager self.deactivate_lv(lv_name)
2017-04-28 13:23:25.455 4268 ERROR cinder.volume.manager File "/opt/stack/new/cinder/cinder/brick/local_dev/lvm.py", line 639, in deactivate_lv
2017-04-28 13:23:25.455 4268 ERROR cinder.volume.manager self._wait_for_volume_deactivation(name)
2017-04-28 13:23:25.455 4268 ERROR cinder.volume.manager File "/opt/stack/new/cinder/cinder/utils.py", line 796, in _wrapper
2017-04-28 13:23:25.455 4268 ERROR cinder.volume.manager return r.call(f, *args, **kwargs)
2017-04-28 13:23:25.455 4268 ERROR cinder.volume.manager File "/usr/local/lib/python2.7/dist-packages/retrying.py", line 212, in call
2017-04-28 13:23:25.455 4268 ERROR cinder.volume.manager raise attempt.get()
2017-04-28 13:23:25.455 4268 ERROR cinder.volume.manager File "/usr/local/lib/python2.7/dist-packages/retrying.py", line 247, in get
2017-04-28 13:23:25.455 4268 ERROR cinder.volume.manager six.reraise(self.value[0], self.value[1], self.value[2])
2017-04-28 13:23:25.455 4268 ERROR cinder.volume.manager File "/usr/local/lib/python2.7/dist-packages/retrying.py", line 200, in call
2017-04-28 13:23:25.455 4268 ERROR cinder.volume.manager attempt = Attempt(fn(*args, **kwargs), attempt_number, False)
2017-04-28 13:23:25.455 4268 ERROR cinder.volume.manager File "/opt/stack/new/cinder/cinder/brick/local_dev/lvm.py", line 648, in _wait_for_volume_deactivation
2017-04-28 13:23:25.455 4268 ERROR cinder.volume.manager raise exception.VolumeNotDeactivated(name=name)
2017-04-28 13:23:25.455 4268 ERROR cinder.volume.manager VolumeNotDeactivated: Volume volume-e1133173-dc69-4e1f-8836-6c9bd2c0b65b was not deactivated in time.
2017-04-28 13:23:25.455 4268 ERROR cinder.volume.manager

[Ihar Hrachyshka (ihar-hrachyshka)]

http://logstash.openstack.org/#dashboard/file/logstash.json?query=message%3A%5C%22in%20test_volume_extend_when_volume_has_snapshot%5C%22

151 hit in 7 days wow!

[Sean McGinnis (sean-mcginnis)]

Seeing some of these hit cases that should be addressed by https://bugs.launchpad.net/cinder/+bug/1495560

[Ihar Hrachyshka (ihar-hrachyshka)]

Fix? https://review.openstack.org/#/c/461129/

[OpenStack Infra (hudson-openstack)]

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

commit 5744301777e6c557bd44436ad5a45613631d0f08
Author: Sean McGinnis <email address hidden>
Date: Fri Apr 28 14:14:16 2017 -0500

    Give more time for LVM deactivation

    Current code retries three times for deactivation to complete,
    waiting one second between retries. On some heavily loaded
    systems, and apparently the gate, this is not enough time for
    the operation to complete.

    This attempts to work around those slower systems by increasing
    our retries to 5 and adding a backoff of 2 seconds to give it
    more time.

    Change-Id: I4f40a1984fe828c8ff965033f7e25b1d7516ab1e
    Closes-bug: #1687044

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: stable/ocata
Review: https://review.openstack.org/461827

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: stable/newton
Review: https://review.openstack.org/461828

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/461828
Committed: https://git.openstack.org/cgit/openstack/cinder/commit/?id=68e0fb82f3e30c7c503164b30f55ea1662f97244
Submitter: Jenkins
Branch: stable/newton

commit 68e0fb82f3e30c7c503164b30f55ea1662f97244
Author: Sean McGinnis <email address hidden>
Date: Fri Apr 28 14:14:16 2017 -0500

    Give more time for LVM deactivation

    Current code retries three times for deactivation to complete,
    waiting one second between retries. On some heavily loaded
    systems, and apparently the gate, this is not enough time for
    the operation to complete.

    This attempts to work around those slower systems by increasing
    our retries to 5 and adding a backoff of 2 seconds to give it
    more time.

    Change-Id: I4f40a1984fe828c8ff965033f7e25b1d7516ab1e
    Closes-bug: #1687044
    (cherry picked from commit 5744301777e6c557bd44436ad5a45613631d0f08)

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/461827
Committed: https://git.openstack.org/cgit/openstack/cinder/commit/?id=30de1d709e7256c38976a4d11c1ccae99b8b869b
Submitter: Jenkins
Branch: stable/ocata

commit 30de1d709e7256c38976a4d11c1ccae99b8b869b
Author: Sean McGinnis <email address hidden>
Date: Fri Apr 28 14:14:16 2017 -0500

    Give more time for LVM deactivation

    Current code retries three times for deactivation to complete,
    waiting one second between retries. On some heavily loaded
    systems, and apparently the gate, this is not enough time for
    the operation to complete.

    This attempts to work around those slower systems by increasing
    our retries to 5 and adding a backoff of 2 seconds to give it
    more time.

    Change-Id: I4f40a1984fe828c8ff965033f7e25b1d7516ab1e
    Closes-bug: #1687044
    (cherry picked from commit 5744301777e6c557bd44436ad5a45613631d0f08)

[Matt Riedemann (mriedem)]

This is still failing at a pretty high rate on master. Is there anything else that can be done besides increasing timeouts?

[Chhavi Agarwal (chhagarw)]

I am still facing this issue even after increasing the retries to 7
https://review.openstack.org/#/c/461850/7

[OpenStack Infra (hudson-openstack)]

This issue was fixed in the openstack/cinder 10.0.2 release.

[OpenStack Infra (hudson-openstack)]

This issue was fixed in the openstack/cinder 11.0.0.0b2 development milestone.