while deploying a fresh simple focal-wallaby environment in the lab, after all units are active/idle I find that I am unable to create volumes. Looking at the logs, the following message can be seen:
2021-11-17 14:31:17.309 46862 ERROR cinder.service [-] Manager for service cinder-volume juju-3bc959-fw-0@LVM is reporting problems, not sending heartbeat. Service will appear "down".
scrolling up, I find the following error message:
2021-11-16 19:08:06.306 38810 DEBUG oslo_concurrency.processutils [req-bc72837e-72b5-4f06-b978-8be437bbf92f - - - - -] Running cmd (subprocess): sudo cinder-rootwrap /etc/cinder/rootwrap.conf env LC_ALL=C lvs --noheadings --unit=g -o size,data_percent --separator : --nosuffix /dev/cinder-volumes/cinder-volumes-pool execute /usr/lib/python3/dist-packages/oslo_concurrency/processutils.py:384
2021-11-16 19:08:06.724 38810 DEBUG oslo_concurrency.processutils [req-bc72837e-72b5-4f06-b978-8be437bbf92f - - - - -] CMD "sudo cinder-rootwrap /etc/cinder/rootwrap.conf env LC_ALL=C lvs --noheadings --unit=g -o size,data_percent --separator : --nosuffix /dev/cinder-volumes/cinder-volumes-pool" returned: 0 in 0.418s execute /usr/lib/python3/dist-packages/oslo_concurrency/processutils.py:422
2021-11-16 19:08:06.725 38810 ERROR cinder.volume.manager [req-bc72837e-72b5-4f06-b978-8be437bbf92f - - - - -] Failed to initialize driver.: ValueError: could not convert string to float: ''
2021-11-16 19:08:06.725 38810 ERROR cinder.volume.manager Traceback (most recent call last):
2021-11-16 19:08:06.725 38810 ERROR cinder.volume.manager File "/usr/lib/python3/dist-packages/cinder/volume/manager.py", line 481, in _init_host
2021-11-16 19:08:06.725 38810 ERROR cinder.volume.manager self.driver.check_for_setup_error()
2021-11-16 19:08:06.725 38810 ERROR cinder.volume.manager File "/usr/lib/python3/dist-packages/cinder/volume/drivers/lvm.py", line 340, in check_for_setup_error
2021-11-16 19:08:06.725 38810 ERROR cinder.volume.manager self.vg.update_volume_group_info()
2021-11-16 19:08:06.725 38810 ERROR cinder.volume.manager File "/usr/lib/python3/dist-packages/cinder/brick/local_dev/lvm.py", line 494, in update_volume_group_info
2021-11-16 19:08:06.725 38810 ERROR cinder.volume.manager tpfs = self._get_thin_pool_free_space(self.vg_name,
2021-11-16 19:08:06.725 38810 ERROR cinder.volume.manager File "/usr/lib/python3/dist-packages/cinder/brick/local_dev/lvm.py", line 203, in _get_thin_pool_free_space
2021-11-16 19:08:06.725 38810 ERROR cinder.volume.manager data_percent = float(data[1])
2021-11-16 19:08:06.725 38810 ERROR cinder.volume.manager ValueError: could not convert string to float: ''
2021-11-16 19:08:06.725 38810 ERROR cinder.volume.manager
Inspecting lvs output I find out the LV was not created succesfully:
root@juju-3bc959-fw-0:/home/ubuntu# vgs
VG #PV #LV #SN Attr VSize VFree
cinder-volumes 1 1 0 wz--n- <5.00g 4.98g
root@juju-3bc959-fw-0:/home/ubuntu# lvs
LV VG Attr LSize Pool Origin Data% Meta% Move Log Cpy%Sync Convert
cinder-volumes-pool cinder-volumes -wi-a----- 8.00m
Meanwhile, a colleague faces the same issue in his focal-ussuri env, but different stack trace and different lvs output as below:
ubuntu@juju-2a6a1a-mts-0:~$ sudo lvs /dev/cinder-volumes/cinder-volumes-pool
LV VG Attr LSize Pool Origin Data% Meta% Move Log Cpy%Sync Convert
cinder-volumes-pool cinder-volumes twi---tz-- 4.75g
f-ba9c-32064a0c6940 - - - - -] Running cmd (subprocess): sudo cinder-rootwrap /etc/cinder/rootwrap.conf lvchange -a y --yes -K cinder-volumes/cinder-volumes-pool execute /usr/lib/python3/dist-packages/oslo_concurrency/processutils.py:372
2021-11-16 16:16:14.157 38168 DEBUG oslo_concurrency.processutils [req-6617118c-a09b-416f-ba9c-32064a0c6940 - - - - -] CMD "sudo cinder-rootwrap /etc/cinder/rootwrap.conf lvchange -a y --yes -K cinder-volumes/cinder-volumes-pool" returned: 5 in 0.416s execute /usr/lib/python3/dist-packages/oslo_concurrency/processutils.py:408
2021-11-16 16:16:14.158 38168 DEBUG oslo_concurrency.processutils [req-6617118c-a09b-416f-ba9c-32064a0c6940 - - - - -] 'sudo cinder-rootwrap /etc/cinder/rootwrap.conf lvchange -a y --yes -K cinder-volumes/cinder-volumes-pool' failed. Not Retrying. execute /usr/lib/python3/dist-packages/oslo_concurrency/processutils.py:456
2021-11-16 16:16:14.158 38168 ERROR cinder.brick.local_dev.lvm [req-6617118c-a09b-416f-ba9c-32064a0c6940 - - - - -] Error activating LV: oslo_concurrency.processutils.ProcessExecutionError: Unexpected error while running command.
Command: sudo cinder-rootwrap /etc/cinder/rootwrap.conf lvchange -a y --yes -K cinder-volumes/cinder-volumes-pool
Exit code: 5
Stdout: ''
Stderr: ' Activation of logical volume cinder-volumes/cinder-volumes-pool is prohibited while logical volume cinder-volumes/cinder-volumes-pool_tmeta is active.\n'
2021-11-16 16:16:14.158 38168 ERROR cinder.brick.local_dev.lvm Traceback (most recent call last):
2021-11-16 16:16:14.158 38168 ERROR cinder.brick.local_dev.lvm File "/usr/lib/python3/dist-packages/cinder/brick/local_dev/lvm.py", line 692, in activate_lv
2021-11-16 16:16:14.158 38168 ERROR cinder.brick.local_dev.lvm self._execute(*cmd,
2021-11-16 16:16:14.158 38168 ERROR cinder.brick.local_dev.lvm File "/usr/lib/python3/dist-packages/os_brick/executor.py", line 52, in _execute
2021-11-16 16:16:14.158 38168 ERROR cinder.brick.local_dev.lvm result = self.__execute(*args, **kwargs)
2021-11-16 16:16:14.158 38168 ERROR cinder.brick.local_dev.lvm File "/usr/lib/python3/dist-packages/cinder/utils.py", line 126, in execute
2021-11-16 16:16:14.158 38168 ERROR cinder.brick.local_dev.lvm return processutils.execute(*cmd, **kwargs)
2021-11-16 16:16:14.158 38168 ERROR cinder.brick.local_dev.lvm File "/usr/lib/python3/dist-packages/oslo_concurrency/processutils.py", line 421, in execute
2021-11-16 16:16:14.158 38168 ERROR cinder.brick.local_dev.lvm raise ProcessExecutionError(exit_code=_returncode,
2021-11-16 16:16:14.158 38168 ERROR cinder.brick.local_dev.lvm oslo_concurrency.processutils.ProcessExecutionError: Unexpected error while running command.
2021-11-16 16:16:14.158 38168 ERROR cinder.brick.local_dev.lvm Command: sudo cinder-rootwrap /etc/cinder/rootwrap.conf lvchange -a y --yes -K cinder-volumes/cinder-volumes-pool
2021-11-16 16:16:14.158 38168 ERROR cinder.brick.local_dev.lvm Exit code: 5
2021-11-16 16:16:14.158 38168 ERROR cinder.brick.local_dev.lvm Stdout: ''
2021-11-16 16:16:14.158 38168 ERROR cinder.brick.local_dev.lvm Stderr: ' Activation of logical volume cinder-volumes/cinder-volumes-pool is prohibited while logical volume cinder-volumes/cinder-volumes-pool_tmeta is active.\n'
2021-11-16 16:16:14.158 38168 ERROR cinder.brick.local_dev.lvm
2021-11-16 16:16:14.164 38168 ERROR cinder.brick.local_dev.lvm [req-6617118c-a09b-416f-ba9c-32064a0c6940 - - - - -] Cmd :sudo cinder-rootwrap /etc/cinder/rootwrap.conf lvchange -a y --yes -K cinder-volumes/cinder-volumes-pool: oslo_concurrency.processutils.ProcessExecutionError: Unexpected error while running command.
2021-11-16 16:16:14.165 38168 ERROR cinder.brick.local_dev.lvm [req-6617118c-a09b-416f-ba9c-32064a0c6940 - - - - -] StdOut :: oslo_concurrency.processutils.ProcessExecutionError: Unexpected error while running command.
2021-11-16 16:16:14.165 38168 ERROR cinder.brick.local_dev.lvm [req-6617118c-a09b-416f-ba9c-32064a0c6940 - - - - -] StdErr : Activation of logical volume cinder-volumes/cinder-volumes-pool is prohibited while logical volume cinder-volumes/cinder-volumes-pool_tmeta is active.
: oslo_concurrency.processutils.ProcessExecutionError: Unexpected error while running command.
2021-11-16 16:16:14.165 38168 DEBUG cinder.utils [req-6617118c-a09b-416f-ba9c-32064a0c6940 - - - - -] Failed attempt 1 _print_stop /usr/lib/python3/dist-packages/cinder/utils.py:680
Further investigating, it was found that it is very likely that the cause is the charm killing the service due to hook executions while it is setting up the LVM:
2021-11-16 16:15:57.778 37635 DEBUG oslo_concurrency.processutils [req-6060360c-a2d3-4cf9-8741-05802d9b0553 - - - - -] Running cmd (subprocess): sudo cinder-rootwrap /etc/cinder/rootwrap.conf env LC_ALL=C vgs --noheadings -o name cinder-volumes execute /usr/lib/python3/dist-packages/oslo_concurrency/processutils.py:372
2021-11-16 16:15:58.197 37635 DEBUG oslo_concurrency.processutils [req-6060360c-a2d3-4cf9-8741-05802d9b0553 - - - - -] CMD "sudo cinder-rootwrap /etc/cinder/rootwrap.conf env LC_ALL=C vgs --noheadings -o name cinder-volumes" returned: 0 in 0.419s execute /usr/lib/python3/dist-packages/oslo_concurrency/processutils.py:408
2021-11-16 16:15:58.198 37635 DEBUG oslo_concurrency.processutils [req-6060360c-a2d3-4cf9-8741-05802d9b0553 - - - - -] Running cmd (subprocess): sudo cinder-rootwrap /etc/cinder/rootwrap.conf env LC_ALL=C lvs --noheadings --unit=g -o vg_name,name,size --nosuffix cinder-volumes/cinder-volumes-pool execute /usr/lib/python3/dist-packages/oslo_concurrency/processutils.py:372
2021-11-16 16:15:58.665 37635 DEBUG oslo_concurrency.processutils [req-6060360c-a2d3-4cf9-8741-05802d9b0553 - - - - -] CMD "sudo cinder-rootwrap /etc/cinder/rootwrap.conf env LC_ALL=C lvs --noheadings --unit=g -o vg_name,name,size --nosuffix cinder-volumes/cinder-volumes-pool" returned: 5 in 0.467s execute /usr/lib/python3/dist-packages/oslo_concurrency/processutils.py:408
2021-11-16 16:15:58.665 37635 DEBUG oslo_concurrency.processutils [req-6060360c-a2d3-4cf9-8741-05802d9b0553 - - - - -] 'sudo cinder-rootwrap /etc/cinder/rootwrap.conf env LC_ALL=C lvs --noheadings --unit=g -o vg_name,name,size --nosuffix cinder-volumes/cinder-volumes-pool' failed. Not Retrying. execute /usr/lib/python3/dist-packages/oslo_concurrency/processutils.py:456
2021-11-16 16:15:58.666 37635 INFO cinder.brick.local_dev.lvm [req-6060360c-a2d3-4cf9-8741-05802d9b0553 - - - - -] Logical Volume not found when querying LVM info. (vg_name=cinder-volumes, lv_name=cinder-volumes-pool
2021-11-16 16:15:59.084 37635 DEBUG oslo_concurrency.processutils [req-6060360c-a2d3-4cf9-8741-05802d9b0553 - - - - -] Running cmd (subprocess): sudo cinder-rootwrap /etc/cinder/rootwrap.conf env LC_ALL=C vgs --noheadings --unit=g -o name,size,free,lv_count,uuid --separator : --nosuffix cinder-volumes execute /usr/lib/python3/dist-packages/oslo_concurrency/processutils.py:372
2021-11-16 16:15:59.413 37635 DEBUG oslo_concurrency.processutils [req-6060360c-a2d3-4cf9-8741-05802d9b0553 - - - - -] CMD "sudo cinder-rootwrap /etc/cinder/rootwrap.conf env LC_ALL=C vgs --noheadings --unit=g -o name,size,free,lv_count,uuid --separator : --nosuffix cinder-volumes" returned: 0 in 0.330s execute /usr/lib/python3/dist-packages/oslo_concurrency/processutils.py:408
2021-11-16 16:15:59.414 37635 DEBUG cinder.brick.local_dev.lvm [req-6060360c-a2d3-4cf9-8741-05802d9b0553 - - - - -] Creating thin pool 'cinder-volumes/cinder-volumes-pool' with size 4.75g of total 5.0g create_thin_pool /usr/lib/python3/dist-packages/cinder/brick/local_dev/lvm.py:524
2021-11-16 16:15:59.415 37635 DEBUG oslo_concurrency.processutils [req-6060360c-a2d3-4cf9-8741-05802d9b0553 - - - - -] Running cmd (subprocess): sudo cinder-rootwrap /etc/cinder/rootwrap.conf env LC_ALL=C lvcreate -T -L 4.75g cinder-volumes/cinder-volumes-pool execute /usr/lib/python3/dist-packages/oslo_concurrency/processutils.py:372
2021-11-16 16:16:03.896 37635 DEBUG oslo_concurrency.lockutils [req-b6c3a830-0c89-4f40-b803-8dca19ec3d6e - - - - -] Acquired lock "singleton_lock" lock /usr/lib/python3/dist-packages/oslo_concurrency/lockutils.py:265
2021-11-16 16:16:03.897 37635 DEBUG oslo_concurrency.lockutils [req-b6c3a830-0c89-4f40-b803-8dca19ec3d6e - - - - -] Releasing lock "singleton_lock" lock /usr/lib/python3/dist-packages/oslo_concurrency/lockutils.py:281
2021-11-16 16:16:03.919 37621 INFO oslo_service.service [req-b6c3a830-0c89-4f40-b803-8dca19ec3d6e - - - - -] Caught SIGTERM, stopping children
2021-11-16 16:16:03.919 37621 DEBUG oslo_concurrency.lockutils [req-b6c3a830-0c89-4f40-b803-8dca19ec3d6e - - - - -] Acquired lock "singleton_lock" lock /usr/lib/python3/dist-packages/oslo_concurrency/lockutils.py:265
2021-11-16 16:16:03.929 37621 DEBUG oslo_concurrency.lockutils [req-b6c3a830-0c89-4f40-b803-8dca19ec3d6e - - - - -] Releasing lock "singleton_lock" lock /usr/lib/python3/dist-packages/oslo_concurrency/lockutils.py:281
2021-11-16 16:16:03.930 37621 DEBUG oslo_service.service [req-b6c3a830-0c89-4f40-b803-8dca19ec3d6e - - - - -] Stop services. stop /usr/lib/python3/dist-packages/oslo_service/service.py:699
2021-11-16 16:16:03.930 37621 DEBUG oslo_service.service [req-b6c3a830-0c89-4f40-b803-8dca19ec3d6e - - - - -] Killing children. stop /usr/lib/python3/dist-packages/oslo_service/service.py:704
2021-11-16 16:16:03.930 37621 INFO oslo_service.service [req-b6c3a830-0c89-4f40-b803-8dca19ec3d6e - - - - -] Waiting on 1 children to exit
2021-11-16 16:16:03.940 37621 INFO oslo_service.service [req-b6c3a830-0c89-4f40-b803-8dca19ec3d6e - - - - -] Child 37635 exited with status 0
2021-11-16 16:16:09.597 37775 DEBUG oslo_concurrency.lockutils [-] Acquired lock "singleton_lock" lock /usr/lib/python3/dist-packages/oslo_concurrency/lockutils.py:265
2021-11-16 16:16:09.609 37775 DEBUG oslo_concurrency.lockutils [-] Releasing lock "singleton_lock" lock /usr/lib/python3/dist-packages/oslo_concurrency/lockutils.py:281
2021-11-16 16:16:11.516 37775 WARNING py.warnings [req-37bc3fd3-ac44-4f96-8964-8d58820a4d8b - - - - -] /usr/lib/python3/dist-packages/pymysql/cursors.py:170: Warning: (3719, "'utf8' is currently an alias for the character set UTF8MB3, but will be an alias for UTF8MB4 in a future release. Please consider using UTF8MB4 in order to be unambiguous.")
result = self._query(query)
2021-11-16 16:16:12.159 37775 DEBUG cinder.volume.drivers.lvm [req-37bc3fd3-ac44-4f96-8964-8d58820a4d8b - - - - -] Attempting to initialize LVM driver with the following target_driver: cinder.volume.targets.tgt.TgtAdm __init__ /usr/lib/python3/dist-packages/cinder/volume/drivers/lvm.py:103
The cinder-volume service being killed in different points in time resulted in different errors in the 2 environments
