Cinder volume failed to build and went to ERROR state - No valid backend was found ( Stderr: ' Volume group "cinder-volumes" not found\n)

[Sandeep Yadav]

Description
===========

Cinder volume failed to build and went to ERROR state - No valid backend was found ( Stderr: ' Volume group "cinder-volumes" not found\n)

Error Snippet
=============

https://9323961f9b936186ab18-8b23fb57107c099fc623f82f25f9ddb3.ssl.cf1.rackcdn.com/719441/1/gate/tripleo-ci-centos-8-standalone/d3002ff/job-output.txt

~~~
2020-04-15 01:15:58.537228 | primary | TASK [os_tempest : Execute tempest tests] **************************************
2020-04-15 01:15:58.537249 | primary | Wednesday 15 April 2020 01:15:58 +0000 (0:00:00.072) 1:25:23.938 *******
2020-04-15 01:29:47.889427 | primary | fatal: [undercloud]: FAILED! => {
2020-04-15 01:29:47.889530 | primary | "changed": false,
2020-04-15 01:29:47.889565 | primary | "cmd": "set -e\nif [ -d /openstack/venvs/tempest-untagged/bin ];\nthen\n. /openstack/venvs/tempest-untagged/bin/activate\nfi\ntempest run --concurrency 2 --blacklist-file /home/zuul/tempest/etc/tempest_blacklist.txt --whitelist-file /home/zuul/tempest/etc/tempest_whitelist.txt > /var/log/tempest/tempest_run.log\n",
2020-04-15 01:29:47.889593 | primary | "delta": "0:13:48.239156",
2020-04-15 01:29:47.889616 | primary | "end": "2020-04-15 01:29:47.335787",
2020-04-15 01:29:47.889642 | primary | "rc": 1,
2020-04-15 01:29:47.889663 | primary | "start": "2020-04-15 01:15:59.096631"
2020-04-15 01:29:47.889700 | primary | }
~~~

https://9323961f9b936186ab18-8b23fb57107c099fc623f82f25f9ddb3.ssl.cf1.rackcdn.com/719441/1/gate/tripleo-ci-centos-8-standalone/d3002ff/logs/undercloud/var/log/tempest/tempest_run.log
~~~

{0} tempest.scenario.test_minimum_basic.TestMinimumBasicScenario.test_minimum_basic_scenario [34.963675s] ... FAILED

Captured traceback:
~~~~~~~~~~~~~~~~~~~
    Traceback (most recent call last):
      File "/usr/lib/python3.6/site-packages/tempest/common/utils/__init__.py", line 89, in wrapper
        return f(*func_args, **func_kwargs)
      File "/usr/lib/python3.6/site-packages/tempest/scenario/test_minimum_basic.py", line 118, in test_minimum_basic_scenario
        volume = self.create_volume()
      File "/usr/lib/python3.6/site-packages/tempest/scenario/manager.py", line 327, in create_volume
        volume['id'], 'available')
      File "/usr/lib/python3.6/site-packages/tempest/common/waiters.py", line 210, in wait_for_volume_resource_status
        resource_name=resource_name, resource_id=resource_id)
    tempest.exceptions.VolumeResourceBuildErrorException: volume b975e166-9c64-4adb-93bd-2735821bd1fb failed to build and is in ERROR status
~~~

https://9323961f9b936186ab18-8b23fb57107c099fc623f82f25f9ddb3.ssl.cf1.rackcdn.com/719441/1/gate/tripleo-ci-centos-8-standalone/d3002ff/logs/undercloud/var/log/containers/cinder/cinder-scheduler.log

~~~
6c6f2c96a667478abe6fbe2d77871a2b - default default] Setting Volume b975e166-9c64-4adb-93bd-2735821bd1fb to error due to: No valid backend was found. No weighed backends available error_out /usr/lib/python3.6/site-packages/cinder/volume/flows/common.py:83
~~~

https://9323961f9b936186ab18-8b23fb57107c099fc623f82f25f9ddb3.ssl.cf1.rackcdn.com/719441/1/gate/tripleo-ci-centos-8-standalone/d3002ff/logs/undercloud/var/log/containers/cinder/cinder-volume.log

~~~
2020-04-15 01:11:30.059 68 ERROR cinder.volume.manager Traceback (most recent call last):
2020-04-15 01:11:30.059 68 ERROR cinder.volume.manager File "/usr/lib/python3.6/site-packages/cinder/volume/manager.py", line 467, in _init_host
2020-04-15 01:11:30.059 68 ERROR cinder.volume.manager self.driver.check_for_setup_error()
2020-04-15 01:11:30.059 68 ERROR cinder.volume.manager File "/usr/lib/python3.6/site-packages/cinder/volume/drivers/lvm.py", line 319, in check_for_setup_error
2020-04-15 01:11:30.059 68 ERROR cinder.volume.manager self.configuration.lvm_suppress_fd_warnings))
2020-04-15 01:11:30.059 68 ERROR cinder.volume.manager File "/usr/lib/python3.6/site-packages/cinder/brick/local_dev/lvm.py", line 107, in __init__
2020-04-15 01:11:30.059 68 ERROR cinder.volume.manager if self._vg_exists() is False:
2020-04-15 01:11:30.059 68 ERROR cinder.volume.manager File "/usr/lib/python3.6/site-packages/cinder/brick/local_dev/lvm.py", line 140, in _vg_exists
2020-04-15 01:11:30.059 68 ERROR cinder.volume.manager run_as_root=True)
2020-04-15 01:11:30.059 68 ERROR cinder.volume.manager File "/usr/lib/python3.6/site-packages/os_brick/executor.py", line 52, in _execute
2020-04-15 01:11:30.059 68 ERROR cinder.volume.manager result = self.__execute(*args, **kwargs)
2020-04-15 01:11:30.059 68 ERROR cinder.volume.manager File "/usr/lib/python3.6/site-packages/cinder/utils.py", line 126, in execute
2020-04-15 01:11:30.059 68 ERROR cinder.volume.manager return processutils.execute(*cmd, **kwargs)
2020-04-15 01:11:30.059 68 ERROR cinder.volume.manager File "/usr/lib/python3.6/site-packages/oslo_concurrency/processutils.py", line 424, in execute
2020-04-15 01:11:30.059 68 ERROR cinder.volume.manager cmd=sanitized_cmd)
2020-04-15 01:11:30.059 68 ERROR cinder.volume.manager oslo_concurrency.processutils.ProcessExecutionError: Unexpected error while running command.
2020-04-15 01:11:30.059 68 ERROR cinder.volume.manager Command: env LC_ALL=C vgs --noheadings -o name cinder-volumes
2020-04-15 01:11:30.059 68 ERROR cinder.volume.manager Exit code: 5
2020-04-15 01:11:30.059 68 ERROR cinder.volume.manager Stdout: ''
2020-04-15 01:11:30.059 68 ERROR cinder.volume.manager Stderr: ' Volume group "cinder-volumes" not found\n Cannot process volume group cinder-volumes\n'
2020-04-15 01:11:30.059 68 ERROR cinder.volume.manager
~~~

Another example:-

https://storage.gra.cloud.ovh.net/v1/AUTH_dcaab5e32b234d56b626f72581e3644c/zuul_opendev_logs_bac/719438/4/gate/tripleo-ci-centos-8-scenario002-standalone/baccdd9/logs/undercloud/var/log/tempest/tempest_run.log

barbican_tempest_plugin.tests.scenario.test_volume_encryption.VolumeEncryptionTest.test_encrypted_cinder_volumes_cryptsetup [46.582934s] ... FAILED

Captured traceback:
~~~~~~~~~~~~~~~~~~~
    Traceback (most recent call last):
      File "/usr/lib/python3.6/site-packages/tempest/common/utils/__init__.py", line 89, in wrapper
        return f(*func_args, **func_kwargs)
      File "/usr/lib/python3.6/site-packages/barbican_tempest_plugin/tests/scenario/test_volume_encryption.py", line 121, in test_encrypted_cinder_volumes_cryptsetup
        volume_type='cryptsetup')
      File "/usr/lib/python3.6/site-packages/barbican_tempest_plugin/tests/scenario/test_volume_encryption.py", line 55, in create_encrypted_volume
        return self.create_volume(volume_type=volume_type['name'])
      File "/usr/lib/python3.6/site-packages/barbican_tempest_plugin/tests/scenario/manager.py", line 236, in create_volume
        volume['id'], 'available')
      File "/usr/lib/python3.6/site-packages/tempest/common/waiters.py", line 210, in wait_for_volume_resource_status
        resource_name=resource_name, resource_id=resource_id)
    tempest.exceptions.VolumeResourceBuildErrorException: volume 81ce11e9-c98f-48fc-a576-fda0dcb58713 failed to build and is in ERROR status

https://storage.gra.cloud.ovh.net/v1/AUTH_dcaab5e32b234d56b626f72581e3644c/zuul_opendev_logs_bac/719438/4/gate/tripleo-ci-centos-8-scenario002-standalone/baccdd9/logs/undercloud/var/log/containers/cinder/cinder-scheduler.log

~~~
42569dbea34c47fa8043148e84e9d0d4 - default default] Setting Volume 81ce11e9-c98f-48fc-a576-fda0dcb58713 to error due to: No valid backend was found. No weighed backends available error_out /usr/lib/python3.6/site-packages/cinder/volume/flows/common.py:83
~~~

~~~
Stderr: ' Volume group "cinder-volumes" not found\n Cannot process volume group cinder-volumes\n'
2020-04-14 23:04:56.541 65 ERROR cinder.volume.manager Traceback (most recent call last):
2020-04-14 23:04:56.541 65 ERROR cinder.volume.manager File "/usr/lib/python3.6/site-packages/cinder/volume/manager.py", line 467, in _init_host
2020-04-14 23:04:56.541 65 ERROR cinder.volume.manager self.driver.check_for_setup_error()
2020-04-14 23:04:56.541 65 ERROR cinder.volume.manager File "/usr/lib/python3.6/site-packages/cinder/volume/drivers/lvm.py", line 319, in check_for_setup_error
2020-04-14 23:04:56.541 65 ERROR cinder.volume.manager self.configuration.lvm_suppress_fd_warnings))
2020-04-14 23:04:56.541 65 ERROR cinder.volume.manager File "/usr/lib/python3.6/site-packages/cinder/brick/local_dev/lvm.py", line 107, in __init__
2020-04-14 23:04:56.541 65 ERROR cinder.volume.manager if self._vg_exists() is False:
2020-04-14 23:04:56.541 65 ERROR cinder.volume.manager File "/usr/lib/python3.6/site-packages/cinder/brick/local_dev/lvm.py", line 140, in _vg_exists
2020-04-14 23:04:56.541 65 ERROR cinder.volume.manager run_as_root=True)
2020-04-14 23:04:56.541 65 ERROR cinder.volume.manager File "/usr/lib/python3.6/site-packages/os_brick/executor.py", line 52, in _execute
2020-04-14 23:04:56.541 65 ERROR cinder.volume.manager result = self.__execute(*args, **kwargs)
2020-04-14 23:04:56.541 65 ERROR cinder.volume.manager File "/usr/lib/python3.6/site-packages/cinder/utils.py", line 126, in execute
2020-04-14 23:04:56.541 65 ERROR cinder.volume.manager return processutils.execute(*cmd, **kwargs)
2020-04-14 23:04:56.541 65 ERROR cinder.volume.manager File "/usr/lib/python3.6/site-packages/oslo_concurrency/processutils.py", line 424, in execute
2020-04-14 23:04:56.541 65 ERROR cinder.volume.manager cmd=sanitized_cmd)
2020-04-14 23:04:56.541 65 ERROR cinder.volume.manager oslo_concurrency.processutils.ProcessExecutionError: Unexpected error while running command.
2020-04-14 23:04:56.541 65 ERROR cinder.volume.manager Command: env LC_ALL=C vgs --noheadings -o name cinder-volumes
2020-04-14 23:04:56.541 65 ERROR cinder.volume.manager Exit code: 5
2020-04-14 23:04:56.541 65 ERROR cinder.volume.manager Stdout: ''
2020-04-14 23:04:56.541 65 ERROR cinder.volume.manager Stderr: ' Volume group "cinder-volumes" not found\n Cannot process volume group cinder-volumes\n'
2020-04-14 23:04:56.541 65 ERROR cinder.volume.manager
~~~

[Sandeep Yadav (sandeepyadav93)]

Investigation so far:-

Cinder error:-

2020-04-15 01:11:30.059 68 ERROR cinder.volume.manager Stderr: ' Volume group "cinder-volumes" not found\n Cannot process volume group cinder-volumes\n'

Good:-

https://e8dabbe3d00824f512de-e25d1f8bae8601aed7ec89510f7333bc.ssl.cf2.rackcdn.com/718545/19/check/tripleo-ci-centos-8-standalone/ab81b23/logs/undercloud/home/zuul/ansible.log

~~~
2020-04-14 02:06:41,931 p=17519 u=root | TASK [cinder create LVM volume group] ******************************************
2020-04-14 02:06:41,932 p=17519 u=root | Tuesday 14 April 2020 02:06:41 +0000 (0:00:00.333) 0:01:17.941 *********
2020-04-14 02:06:42,599 p=17519 u=root | changed: [standalone]
~~~

https://e8dabbe3d00824f512de-e25d1f8bae8601aed7ec89510f7333bc.ssl.cf2.rackcdn.com/718545/19/check/tripleo-ci-centos-8-standalone/ab81b23/logs/undercloud/var/log/extra/lvm.txt

~~~
  VG #PV #LV #SN Attr VSize VFree
  cinder-volumes 1 1 0 wz--n- <10.04g 484.00m
  PV VG Fmt Attr PSize PFree
  /dev/loop2 cinder-volumes lvm2 a-- <10.04g 484.00m
  LV VG Attr LSize Pool Origin Data% Meta% Move Log Cpy%Sync Convert
  cinder-volumes-pool cinder-volumes twi-aotz-- <9.54g 0.00 10.58

~~~

https://e8dabbe3d00824f512de-e25d1f8bae8601aed7ec89510f7333bc.ssl.cf2.rackcdn.com/718545/19/check/tripleo-ci-centos-8-standalone/ab81b23/logs/undercloud/var/log/journal.txt
~~~
Apr 14 02:06:42 standalone.localdomain ansible-command[20051]: Invoked with creates=/dev/loop2 executable=/bin/bash _raw_params=if ! losetup /dev/loop2; then
                                                                 losetup /dev/loop2 /var/lib/cinder/cinder-volumes
                                                               fi
                                                               if ! pvdisplay | grep cinder-volumes; then
                                                                 pvcreate /dev/loop2
                                                               fi
                                                               if ! vgdisplay | grep cinder-volumes; then
                                                                 vgcreate cinder-volumes /dev/loop2
                                                               fi
                                                                _uses_shell=True warn=True stdin_add_newline=True strip_empty_ends=True argv=None chdir=None removes=None stdin=None
Apr 14 02:06:42 standalone.localdomain kernel: loop: module loaded
Apr 14 02:06:42 standalone.localdomain systemd[1]: Created slice system-lvm2\x2dpvscan.slice.
Apr 14 02:06:42 standalone.localdomain systemd[1]: Starting LVM event activation on device 7:2...
Apr 14 02:06:42 standalone.localdomain lvm[20065]: pvscan[20065] PV /dev/loop2 not used.
~~~

Bad:-

https://storage.gra.cloud.ovh.net/v1/AUTH_dcaab5e32b234d56b626f72581e3644c/zuul_opendev_logs_3ea/715006/8/gate/tripleo-ci-centos-8-standalone/3ea0819/logs/undercloud/home/zuul/ansible.log

~~~
2020-04-14 12:43:13,479 p=28349 u=root | TASK [cinder create LVM volume group] **************************...

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: master
Review: https://review.opendev.org/720132

[Bogdan Dobrelya (bogdando)]

https://review.opendev.org/#/c/720139/ may be also related fix

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: master
Review: https://review.opendev.org/720232

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.opendev.org/720132
Committed: https://git.openstack.org/cgit/openstack/tripleo-heat-templates/commit/?id=f85caaf411c4b8d9db39350862d6d52f734f559b
Submitter: Zuul
Branch: master

commit f85caaf411c4b8d9db39350862d6d52f734f559b
Author: Sandeep Yadav <email address hidden>
Date: Wed Apr 15 03:03:06 2020 -0400

    Rename loopback creates file

    We are hitting bug[1] and it looks like because /dev/loop2 file
    already exists the ansible task which creates loop didn't trigger.
    Creating file with different name "/dev/loop2cinder" to pass the
    issue[1]

    [1] https://bugs.launchpad.net/tripleo/+bug/1872881

    Change-Id: I4e18bee7864b71afca387fbea5857c9530faa2fc
    Partial-Bug: #1872881

[yatin (yatinkarel)]

So https://review.opendev.org/720132 workarounds the issue and https://review.opendev.org/720232 from Alan will be the right fix for not utilizing hardcoded loop2.

With respect to root cause why the issue appeared now:-
- mock-2.2 was added in RDO build-deps recently to go remove usage of EPEL[1].
- mock > 2 has changed behavior related to nspawn usage and is now started creating /dev/loop[0-11] devices[2]. Log [3](before mock update), [4](after mock update) confirm this.
- Jobs even failed during update testing[5], but we missed checking failure results :( else we would have avoided this issue and have fix before updating.

[1] https://review.rdoproject.org/r/#/c/26405/
[2] https://github.com/rpm-software-management/mock/blob/42df0034f0046fb84f989af83a9d2f2aa7085901/mock/py/mockbuild/buildroot.py#L560-L573
[3] https://b98ce9c8104d56300a20-c8df7fee768f0a38e1c53a0e9f1f4351.ssl.cf1.rackcdn.com/719476/1/check/tripleo-ci-centos-8-standalone/10853f9/logs/delorean_logs/component/tripleo/df/7c/df7c32c707c94a09d7e44f19ffdbb37e9563ba90_dev/mock.log.txt.gz
main config related here:- nspawn_args: ['--capability=cap_ipc_lock', '--bind=/tmp/mock-resolv.6kpzlkje:/etc/resolv.conf']
[4] https://c82a74845ac55bc40cbe-e564cc116dd6d65d7c4300b6ac54c802.ssl.cf5.rackcdn.com/719389/2/check/tripleo-ci-centos-8-standalone/ea65635/logs/delorean_logs/component/tripleo/6b/7f/6b7f10c757488b46eb8bbd70667f26040deed644_dev/mock.log.txt.gz
main config related here:- nspawn_args: ['--capability=cap_ipc_lock', '--bind=/tmp/mock-resolv._ddvaq4v:/etc/resolv.conf', '--bind=/dev/loop-control', '--bind=/dev/loop0', '--bind=/dev/loop1', '--bind=/dev/loop2', '--bind=/dev/loop3', '--bind=/dev/loop4', '--bind=/dev/loop5', '--bind=/dev/loop6', '--bind=/dev/loop7', '--bind=/dev/loop8', '--bind=/dev/loop9', '--bind=/dev/loop10', '--bind=/dev/loop11']
[5] https://review.opendev.org/#/c/719553/

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.opendev.org/720232
Committed: https://git.openstack.org/cgit/openstack/tripleo-heat-templates/commit/?id=502947b4beed6bc7f3f7f58706b1934766561c0e
Submitter: Zuul
Branch: master

commit 502947b4beed6bc7f3f7f58706b1934766561c0e
Author: Alan Bishop <email address hidden>
Date: Wed Apr 15 08:41:56 2020 -0700

    Remove hardcoded reference to cinder LVM loopback device

    Replace hardcoded reference to "/dev/loop2" by allowing losetup to
    dynamically choose the next available loopback device number.

    Eliminate hiera data that set cinder_lvm_loop_device_size. This is not
    needed because the associated file is created by a host prep task, and
    the puppet code will be removed by https://review.opendev.org/720139.

    Closes-Bug: #1872881
    Change-Id: Ia0302d1d55dcb8333d7db9713822075d32cd852a

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: stable/train
Review: https://review.opendev.org/721166

[OpenStack Infra (hudson-openstack)]

Related fix proposed to branch: master
Review: https://review.opendev.org/721250

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.opendev.org/721250
Committed: https://git.openstack.org/cgit/openstack/tripleo-quickstart-extras/commit/?id=c57822580d7524456922feb0fe2154a87a69e31a
Submitter: Zuul
Branch: master

commit c57822580d7524456922feb0fe2154a87a69e31a
Author: yatinkarel <email address hidden>
Date: Mon Apr 20 17:33:40 2020 +0530

    Ensure loop devices created by DLRN get's cleaned up

    DLRN with mock-2.2 creates /dev/loop[0-11] devices,
    in CI we rely on /dev/loop devices for setting up block
    devices, so let's ensure the loop devices get's cleaned up.

    Related-Bug: #1872881
    Change-Id: I5295fbb45b79a3e2edea2b24fa007fc011549d77

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: stable/train
Review: https://review.opendev.org/723375

[OpenStack Infra (hudson-openstack)]

Change abandoned by yatin (<email address hidden>) on branch: stable/train
Review: https://review.opendev.org/721166
Reason: squashed with https://review.opendev.org/#/c/723375/3 https://review.opendev.org/#/c/723375/3 and handled losetup -n centos7 issue

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.opendev.org/723375
Committed: https://git.openstack.org/cgit/openstack/tripleo-heat-templates/commit/?id=b938f7cd9e639b48c2169ca7d96222f827cd8bf2
Submitter: Zuul
Branch: stable/train

commit b938f7cd9e639b48c2169ca7d96222f827cd8bf2
Author: Jesse Pretorius <email address hidden>
Date: Wed Apr 15 03:03:06 2020 -0400

    [train-squash] Remove hardcoded reference to cinder LVM loopback device

    Backport note:
    In CentOS 7, losetup does not include the -n option. We therefore use
    a slightly different way to get the same output in this backport.

    This is a squash commit of the following patches:

    Rename loopback creates file

    We are hitting bug[1] and it looks like because /dev/loop2 file
    already exists the ansible task which creates loop didn't trigger.
    Creating file with different name "/dev/loop2cinder" to pass the
    issue[1]

    [1] https://bugs.launchpad.net/tripleo/+bug/1872881

    Change-Id: I4e18bee7864b71afca387fbea5857c9530faa2fc
    Partial-Bug: #1872881
    (cherry picked from commit f85caaf411c4b8d9db39350862d6d52f734f559b)

    Remove hardcoded reference to cinder LVM loopback device

    Replace hardcoded reference to "/dev/loop2" by allowing losetup to
    dynamically choose the next available loopback device number.

    Eliminate hiera data that set cinder_lvm_loop_device_size. This is not
    needed because the associated file is created by a host prep task, and
    the puppet code will be removed by https://review.opendev.org/720139.

    Closes-Bug: #1872881
    Change-Id: Ia0302d1d55dcb8333d7db9713822075d32cd852a
    (cherry picked from commit 502947b4beed6bc7f3f7f58706b1934766561c0e)

    Improve the cinder LVM loopback device setup

    The current implementation has the following issues:

    1. It uses two tasks to get the loopback device information,
       and another to set a fact which is only used in the same
       play, which is unnecessary. This can all be done in a
       single task without the fact setting.

    2. The setup of the loopback device is not idempotent. If any
       of the tasks fail, another device will be setup and the
       the tasks will continue to fail because it cannot handle
       multiple value returns.

    3. The LVM PV & VG are setup using a shell task. This could
       be done using an Ansible module instead, which also makes
       the task idempotent.

    4. The oneshot systemd unit starts very late in the boot cycle.
       It can be set to start much sooner, ensuring that the
       cinder-volume service starts successfully sooner.

    5. The oneshot systemd unit starts a bash subshell unnecessarily.

    This patch aims to resolve all these issues, improving the
    execution time and idempotency of these tasks.

    Closes-Bug: #1873899
    Change-Id: I9421cf54f498b3f99a7e5afa11425a0b2419b399
    (cherry picked from commit 580aca40e538b2a57b1a9e67c29c9d8233564a98)

    [cinder-lvm] Resolve issue when there are multiple loop devices

    If a deployment fails, there may end up being multiple loopback
    devices pointing to the sam...

[OpenStack Infra (hudson-openstack)]

This issue was fixed in the openstack/tripleo-heat-templates 11.4.0 release.