VolumesExtendTest.test_volume_extend_when_volume_has_snapshot intermittently fails with "Extend volume failed.: VolumeNotDeactivated: Volume volume-5514a6ad-abbb-46b3-a464-d73cc67e55af was not deactivated in time."

[Matt Riedemann]

http://logs.openstack.org/68/554568/5/gate/legacy-tempest-dsvm-neutron-full/149004c/logs/screen-c-vol.txt.gz?level=TRACE#_Oct_06_02_19_26_438363

Oct 06 02:19:26.438363 ubuntu-xenial-rax-dfw-0002668652 cinder-volume[16293]: ERROR cinder.volume.manager [None req-e2f03baa-4af1-4ee4-878e-5ed933a73b0c tempest-VolumesExtendTest-313262298 None] Extend volume failed.: VolumeNotDeactivated: Volume volume-5514a6ad-abbb-46b3-a464-d73cc67e55af was not deactivated in time.
Oct 06 02:19:26.438623 ubuntu-xenial-rax-dfw-0002668652 cinder-volume[16293]: ERROR cinder.volume.manager Traceback (most recent call last):
Oct 06 02:19:26.438869 ubuntu-xenial-rax-dfw-0002668652 cinder-volume[16293]: ERROR cinder.volume.manager File "/opt/stack/new/cinder/cinder/volume/manager.py", line 2558, in extend_volume
Oct 06 02:19:26.439106 ubuntu-xenial-rax-dfw-0002668652 cinder-volume[16293]: ERROR cinder.volume.manager self.driver.extend_volume(volume, new_size)
Oct 06 02:19:26.439319 ubuntu-xenial-rax-dfw-0002668652 cinder-volume[16293]: ERROR cinder.volume.manager File "/opt/stack/new/cinder/cinder/volume/drivers/lvm.py", line 587, in extend_volume
Oct 06 02:19:26.439532 ubuntu-xenial-rax-dfw-0002668652 cinder-volume[16293]: ERROR cinder.volume.manager self._sizestr(new_size))
Oct 06 02:19:26.439742 ubuntu-xenial-rax-dfw-0002668652 cinder-volume[16293]: ERROR cinder.volume.manager File "/opt/stack/new/cinder/cinder/brick/local_dev/lvm.py", line 821, in extend_volume
Oct 06 02:19:26.439973 ubuntu-xenial-rax-dfw-0002668652 cinder-volume[16293]: ERROR cinder.volume.manager self.deactivate_lv(lv_name)
Oct 06 02:19:26.440258 ubuntu-xenial-rax-dfw-0002668652 cinder-volume[16293]: ERROR cinder.volume.manager File "/opt/stack/new/cinder/cinder/brick/local_dev/lvm.py", line 643, in deactivate_lv
Oct 06 02:19:26.441078 ubuntu-xenial-rax-dfw-0002668652 cinder-volume[16293]: ERROR cinder.volume.manager self._wait_for_volume_deactivation(name)
Oct 06 02:19:26.441290 ubuntu-xenial-rax-dfw-0002668652 cinder-volume[16293]: ERROR cinder.volume.manager File "/opt/stack/new/cinder/cinder/utils.py", line 799, in _wrapper
Oct 06 02:19:26.441499 ubuntu-xenial-rax-dfw-0002668652 cinder-volume[16293]: ERROR cinder.volume.manager return r.call(f, *args, **kwargs)
Oct 06 02:19:26.441702 ubuntu-xenial-rax-dfw-0002668652 cinder-volume[16293]: ERROR cinder.volume.manager File "/usr/local/lib/python2.7/dist-packages/retrying.py", line 212, in call
Oct 06 02:19:26.441921 ubuntu-xenial-rax-dfw-0002668652 cinder-volume[16293]: ERROR cinder.volume.manager raise attempt.get()
Oct 06 02:19:26.442134 ubuntu-xenial-rax-dfw-0002668652 cinder-volume[16293]: ERROR cinder.volume.manager File "/usr/local/lib/python2.7/dist-packages/retrying.py", line 247, in get
Oct 06 02:19:26.442337 ubuntu-xenial-rax-dfw-0002668652 cinder-volume[16293]: ERROR cinder.volume.manager six.reraise(self.value[0], self.value[1], self.value[2])
Oct 06 02:19:26.442557 ubuntu-xenial-rax-dfw-0002668652 cinder-volume[16293]: ERROR cinder.volume.manager File "/usr/local/lib/python2.7/dist-packages/retrying.py", line 200, in call
Oct 06 02:19:26.442789 ubuntu-xenial-rax-dfw-0002668652 cinder-volume[16293]: ERROR cinder.volume.manager attempt = Attempt(fn(*args, **kwargs), attempt_number, False)
Oct 06 02:19:26.443033 ubuntu-xenial-rax-dfw-0002668652 cinder-volume[16293]: ERROR cinder.volume.manager File "/opt/stack/new/cinder/cinder/brick/local_dev/lvm.py", line 652, in _wait_for_volume_deactivation
Oct 06 02:19:26.443255 ubuntu-xenial-rax-dfw-0002668652 cinder-volume[16293]: ERROR cinder.volume.manager raise exception.VolumeNotDeactivated(name=name)
Oct 06 02:19:26.443457 ubuntu-xenial-rax-dfw-0002668652 cinder-volume[16293]: ERROR cinder.volume.manager VolumeNotDeactivated: Volume volume-5514a6ad-abbb-46b3-a464-d73cc67e55af was not deactivated in time.
Oct 06 02:19:26.443684 ubuntu-xenial-rax-dfw-0002668652 cinder-volume[16293]: ERROR cinder.volume.manager
Oct 06 02:19:27.753010 ubuntu-xenial-rax-dfw-0002668652 sudo[15936]: pam_unix(sudo:session): session closed for user root

http://logstash.openstack.org/#dashboard/file/logstash.json?query=message%3A%5C%22Extend%20volume%20failed.%3A%20VolumeNotDeactivated%5C%22%20AND%20tags%3A%5C%22screen-c-vol.txt%5C%22&from=7d

8 hits in 7 days, check and gate, multiple branches, all failures.

[Matt Riedemann (mriedem)]

Just hit this again: http://logs.openstack.org/66/633566/1/check/tempest-full-pike/4719f27/controller/logs/screen-c-vol.txt.gz?level=TRACE#_Jan_29_14_55_55_994454