Following the problem reported in LP#1951299, I deployed a new cinder unit which did not face the error and I was able to create volumes successfully.
However, upon first creating a VM with a volume attached the VM failed to be created with the following error:
| fault | {'code': 500, 'created': '2021-11-17T17:57:26Z', 'message': 'Build of instance 551c3ac4-6061-434f-be95-18ad8c07ae7f aborted: Unable to update attachment.(Bad or unexpected response from the storage volume backend API: Create export for volume failed (Resource could not be found.).). (HTTP 500) (Request-ID: req-5be6', 'details': 'Traceback (most recent call last):\n File "/usr/lib/python3/dist-packages/nova/compute/manager.py", line 1976, in _prep_block_device\n driver_block_device.attach_block_devices(\n File "/usr/lib/python3/dist-packages/nova/virt/block_device.py", line 874, in attach_block_devices\n _log_and_attach(device)\n File "/usr/lib/python3/dist-packages/nova/virt/block_device.py", line 871, in _log_and_attach\n bdm.attach(*attach_args, **attach_kwargs)\n File "/usr/lib/python3/dist-packages/nova/virt/block_device.py", line 46, in wrapped\n ret_val = method(obj, context, *args, **kwargs)\n File "/usr/lib/python3/dist-packages/nova/virt/block_device.py", line 672, in attach\n self._do_attach(context, instance, volume, volume_api,\n File "/usr/lib/python3/dist-packages/nova/virt/block_device.py", line 657, in _do_attach\n self._volume_attach(context, volume, connector, instance,\n File "/usr/lib/python3/dist-packages/nova/virt/block_device.py", line 571, in _volume_attach\n connection_info = volume_api.attachment_update(\n File "/usr/lib/python3/dist-packages/nova/volume/cinder.py", line 396, in wrapper\n res = method(self, ctx, *args, **kwargs)\n File "/usr/lib/python3/dist-packages/nova/volume/cinder.py", line 447, in wrapper\n res = method(self, ctx, attachment_id, *args, **kwargs)\n File "/usr/lib/python3/dist-packages/nova/volume/cinder.py", line 875, in attachment_update\n LOG.error(\'Update attachment failed for attachment \'\n File "/usr/lib/python3/dist-packages/oslo_utils/excutils.py", line 227, in __exit__\n self.force_reraise()\n File "/usr/lib/python3/dist-packages/oslo_utils/excutils.py", line 200, in force_reraise\n raise self.value\n File "/usr/lib/python3/dist-packages/nova/volume/cinder.py", line 867, in attachment_update\n attachment_ref = cinderclient(\n File "/usr/lib/python3/dist-packages/cinderclient/api_versions.py", line 423, in substitution\n return method.func(obj, *args, **kwargs)\n File "/usr/lib/python3/dist-packages/cinderclient/v3/attachments.py", line 74, in update\n resp = self._update(\'/attachments/%s\' % id, body)\n File "/usr/lib/python3/dist-packages/cinderclient/base.py", line 312, in _update\n resp, body = self.api.client.put(url, body=body, **kwargs)\n File "/usr/lib/python3/dist-packages/cinderclient/client.py", line 220, in put\n return self._cs_request(url, \'PUT\', **kwargs)\n File "/usr/lib/python3/dist-packages/cinderclient/client.py", line 205, in _cs_request\n return self.request(url, method, **kwargs)\n File "/usr/lib/python3/dist-packages/cinderclient/client.py", line 191, in request\n raise exceptions.from_response(resp, body)\ncinderclient.exceptions.ClientException: Unable to update attachment.(Bad or unexpected response from the storage volume backend API: Create export for volume failed (Resource could not be found.).). (HTTP 500) (Request-ID: req-5be680ea-1de6-47a0-98d0-b1b2a2075903)\n\nDuring handling of the above exception, another exception occurred:\n\nTraceback (most recent call last):\n File "/usr/lib/python3/dist-packages/nova/compute/manager.py", line 2605, in _build_resources\n block_device_info = self._prep_block_device(context, instance,\n File "/usr/lib/python3/dist-packages/nova/compute/manager.py", line 1996, in _prep_block_device\n raise exception.InvalidBDM(str(ex))\nnova.exception.InvalidBDM: Unable to update attachment.(Bad or unexpected response from the storage volume backend API: Create export for volume failed (Resource could not be found.).). (HTTP 500) (Request-ID: req-5be680ea-1de6-47a0-98d0-b1b2a2075903)\n\nDuring handling of the above exception, another exception occurred:\n\nTraceback (most recent call last):\n File "/usr/lib/python3/dist-packages/nova/compute/manager.py", line 2232, in _do_build_and_run_instance\n self._build_and_run_instance(context, instance, image,\n File "/usr/lib/python3/dist-packages/nova/compute/manager.py", line 2441, in _build_and_run_instance\n compute_utils.notify_about_instance_create(\n File "/usr/lib/python3/dist-packages/oslo_utils/excutils.py", line 227, in __exit__\n self.force_reraise()\n File "/usr/lib/python3/dist-packages/oslo_utils/excutils.py", line 200, in force_reraise\n raise self.value\n File "/usr/lib/python3/dist-packages/nova/compute/manager.py", line 2392, in _build_and_run_instance\n with self._build_resources(context, instance,\n File "/usr/lib/python3.8/contextlib.py", line 113, in __enter__\n return next(self.gen)\n File "/usr/lib/python3/dist-packages/nova/compute/manager.py", line 2615, in _build_resources\n raise exception.BuildAbortException(instance_uuid=instance.uuid,\nnova.exception.BuildAbortException: Build of instance 551c3ac4-6061-434f-be95-18ad8c07ae7f aborted: Unable to update attachment.(Bad or unexpected response from the storage volume backend API: Create export for volume failed (Resource could not be found.).). (HTTP 500) (Request-ID: req-5be680ea-1de6-47a0-98d0-b1b2a2075903)\n'}
Looking at the cinder-volume logs I found:
2021-11-17 17:35:27.821 85104 DEBUG oslo_concurrency.processutils [-] Running cmd (subprocess): tgtadm --lld iscsi --op show --mode target execute /usr/lib/python3/dist-packages/oslo_concurrency/processutils.py:384
2021-11-17 17:35:27.828 85104 DEBUG oslo_concurrency.processutils [-] 'tgtadm --lld iscsi --op show --mode target' failed. Not Retrying. execute /usr/lib/python3/dist-packages/oslo_concurrency/processutils.py:473
2021-11-17 17:35:27.829 85104 DEBUG oslo.privsep.daemon [-] privsep: Exception during request[140174998504016]: [Errno 2] No such file or directory: 'tgtadm' _process_cmd /usr/lib/python3/dist-packages/oslo_privsep/daemon.py:488
Traceback (most recent call last):
File "/usr/lib/python3/dist-packages/oslo_privsep/daemon.py", line 485, in _process_cmd
ret = func(*f_args, **f_kwargs)
File "/usr/lib/python3/dist-packages/oslo_privsep/priv_context.py", line 249, in _wrap
return func(*args, **kwargs)
File "/usr/lib/python3/dist-packages/cinder/privsep/targets/tgt.py", line 52, in tgtadm_show
return processutils.execute(*cmd)
File "/usr/lib/python3/dist-packages/oslo_concurrency/processutils.py", line 395, in execute
obj = subprocess.Popen(cmd,
File "/usr/lib/python3.8/subprocess.py", line 858, in __init__
self._execute_child(args, executable, preexec_fn, close_fds,
File "/usr/lib/python3.8/subprocess.py", line 1704, in _execute_child
raise child_exception_type(errno_num, err_msg, err_filename)
FileNotFoundError: [Errno 2] No such file or directory: 'tgtadm'
2021-11-17 17:35:27.914 85104 DEBUG oslo.privsep.daemon [-] privsep: reply[140174998504016]: (5, 'builtins.FileNotFoundError', (2, 'No such file or directory')) _call_back /usr/lib/python3/dist-packages/oslo_privsep/daemon.py:510
So I proceeded to install tgt for the tgtadm command:
$ sudo apt install tgt
I restarted the cinder-volume service afterwards but still could not create VMs with attached volumes, new error found in logs:
2021-11-17 17:57:23.408 89792 DEBUG cinder.volume.targets.tgt [req-5be680ea-1de6-47a0-98d0-b1b2a2075903 b8853fd0e865432da309dcb2235352d0 441fc0965933423f8664f9f92495cf29 - - -] Created volume path /var/lib/cinder/volumes/volume-607522fb-5b8a-4bce-a78f-aceec257017b,
content:
<target iqn.2010-10.org.openstack:volume-607522fb-5b8a-4bce-a78f-aceec257017b>
backing-store /dev/cinder-volumes/volume-607522fb-5b8a-4bce-a78f-aceec257017b
driver iscsi
incominguser Z4pFr2yVmcpvoqnSneVr RSPf3i54riFmdTUp
write-cache on
</target>
create_iscsi_target /usr/lib/python3/dist-packages/cinder/volume/targets/tgt.py:155
2021-11-17 17:57:23.409 90010 DEBUG oslo_concurrency.processutils [-] Running cmd (subprocess): tgt-admin --update iqn.2010-10.org.openstack:volume-607522fb-5b8a-4bce-a78f-aceec257017b execute /usr/lib/python3/dist-packages/oslo_concurrency/processutils.py:384
2021-11-17 17:57:23.495 90010 DEBUG oslo_concurrency.processutils [-] CMD "tgt-admin --update iqn.2010-10.org.openstack:volume-607522fb-5b8a-4bce-a78f-aceec257017b" returned: 0 in 0.087s execute /usr/lib/python3/dist-packages/oslo_concurrency/processutils.py:422
2021-11-17 17:57:23.496 90010 DEBUG oslo.privsep.daemon [-] privsep: reply[139650391169856]: (4, ('', '')) _call_back /usr/lib/python3/dist-packages/oslo_privsep/daemon.py:510
2021-11-17 17:57:23.497 89792 DEBUG cinder.volume.targets.tgt [req-5be680ea-1de6-47a0-98d0-b1b2a2075903 b8853fd0e865432da309dcb2235352d0 441fc0965933423f8664f9f92495cf29 - - -] StdOut from tgt-admin --update: _do_tgt_update /usr/lib/python3/dist-packages/cinder/volume/targets/tgt.py:113
2021-11-17 17:57:23.498 89792 DEBUG cinder.volume.targets.tgt [req-5be680ea-1de6-47a0-98d0-b1b2a2075903 b8853fd0e865432da309dcb2235352d0 441fc0965933423f8664f9f92495cf29 - - -] StdErr from tgt-admin --update: _do_tgt_update /usr/lib/python3/dist-packages/cinder/volume/targets/tgt.py:114
2021-11-17 17:57:23.498 90010 DEBUG oslo_concurrency.processutils [-] Running cmd (subprocess): tgtadm --lld iscsi --op show --mode target execute /usr/lib/python3/dist-packages/oslo_concurrency/processutils.py:384
2021-11-17 17:57:23.505 90010 DEBUG oslo_concurrency.processutils [-] CMD "tgtadm --lld iscsi --op show --mode target" returned: 0 in 0.007s execute /usr/lib/python3/dist-packages/oslo_concurrency/processutils.py:422
2021-11-17 17:57:23.505 90010 DEBUG oslo.privsep.daemon [-] privsep: reply[139650391169856]: (4, ('', '')) _call_back /usr/lib/python3/dist-packages/oslo_privsep/daemon.py:510
2021-11-17 17:57:23.507 89792 DEBUG cinder.volume.targets.tgt [req-5be680ea-1de6-47a0-98d0-b1b2a2075903 b8853fd0e865432da309dcb2235352d0 441fc0965933423f8664f9f92495cf29 - - -] Targets after update: create_iscsi_target /usr/lib/python3/dist-packages/cinder/volume/targets/tgt.py:195
2021-11-17 17:57:23.507 90010 DEBUG oslo_concurrency.processutils [-] Running cmd (subprocess): tgt-admin --show execute /usr/lib/python3/dist-packages/oslo_concurrency/processutils.py:384
2021-11-17 17:57:23.580 90010 DEBUG oslo_concurrency.processutils [-] CMD "tgt-admin --show" returned: 0 in 0.073s execute /usr/lib/python3/dist-packages/oslo_concurrency/processutils.py:422
2021-11-17 17:57:23.581 90010 DEBUG oslo.privsep.daemon [-] privsep: reply[139650391169856]: (4, ('', '')) _call_back /usr/lib/python3/dist-packages/oslo_privsep/daemon.py:510
2021-11-17 17:57:23.582 89792 WARNING cinder.volume.targets.tgt [req-5be680ea-1de6-47a0-98d0-b1b2a2075903 b8853fd0e865432da309dcb2235352d0 441fc0965933423f8664f9f92495cf29 - - -] Failed to create iscsi target for Volume ID: volume-607522fb-5b8a-4bce-a78f-aceec257017b. It could be caused by problem with concurrency. Also please ensure your tgtd config file contains 'include /var/lib/cinder/volumes/*'
2021-11-17 17:57:23.583 89792 DEBUG cinder.utils [req-5be680ea-1de6-47a0-98d0-b1b2a2075903 b8853fd0e865432da309dcb2235352d0 441fc0965933423f8664f9f92495cf29 - - -] Finished call to 'cinder.volume.targets.tgt.TgtAdm.create_iscsi_target' after 4.843(s), this was the 3rd time calling it. log_it /usr/lib/python3/dist-packages/tenacity/after.py:30
2021-11-17 17:57:23.584 89792 ERROR cinder.volume.manager [req-5be680ea-1de6-47a0-98d0-b1b2a2075903 b8853fd0e865432da309dcb2235352d0 441fc0965933423f8664f9f92495cf29 - - -] Create export for volume failed (Resource could not be found.).: cinder.exception.NotFound: Resource could not be found.
2021-11-17 17:57:23.584 89792 ERROR cinder.volume.manager Traceback (most recent call last):
2021-11-17 17:57:23.584 89792 ERROR cinder.volume.manager File "/usr/lib/python3/dist-packages/cinder/volume/manager.py", line 4655, in _connection_create
2021-11-17 17:57:23.584 89792 ERROR cinder.volume.manager model_update = self.driver.create_export(ctxt.elevated(),
2021-11-17 17:57:23.584 89792 ERROR cinder.volume.manager File "/usr/lib/python3/dist-packages/cinder/volume/drivers/lvm.py", line 834, in create_export
2021-11-17 17:57:23.584 89792 ERROR cinder.volume.manager export_info = self.target_driver.create_export(
2021-11-17 17:57:23.584 89792 ERROR cinder.volume.manager File "/usr/lib/python3/dist-packages/cinder/volume/targets/iscsi.py", line 194, in create_export
2021-11-17 17:57:23.584 89792 ERROR cinder.volume.manager tid = self.create_iscsi_target(iscsi_name,
2021-11-17 17:57:23.584 89792 ERROR cinder.volume.manager File "/usr/lib/python3/dist-packages/cinder/utils.py", line 614, in _wrapper
2021-11-17 17:57:23.584 89792 ERROR cinder.volume.manager return r.call(f, *args, **kwargs)
2021-11-17 17:57:23.584 89792 ERROR cinder.volume.manager File "/usr/lib/python3/dist-packages/tenacity/__init__.py", line 409, in call
2021-11-17 17:57:23.584 89792 ERROR cinder.volume.manager do = self.iter(retry_state=retry_state)
2021-11-17 17:57:23.584 89792 ERROR cinder.volume.manager File "/usr/lib/python3/dist-packages/tenacity/__init__.py", line 368, in iter
2021-11-17 17:57:23.584 89792 ERROR cinder.volume.manager raise retry_exc.reraise()
2021-11-17 17:57:23.584 89792 ERROR cinder.volume.manager File "/usr/lib/python3/dist-packages/tenacity/__init__.py", line 186, in reraise
2021-11-17 17:57:23.584 89792 ERROR cinder.volume.manager raise self.last_attempt.result()
2021-11-17 17:57:23.584 89792 ERROR cinder.volume.manager File "/usr/lib/python3.8/concurrent/futures/_base.py", line 437, in result
2021-11-17 17:57:23.584 89792 ERROR cinder.volume.manager return self.__get_result()
2021-11-17 17:57:23.584 89792 ERROR cinder.volume.manager File "/usr/lib/python3.8/concurrent/futures/_base.py", line 389, in __get_result
2021-11-17 17:57:23.584 89792 ERROR cinder.volume.manager raise self._exception
2021-11-17 17:57:23.584 89792 ERROR cinder.volume.manager File "/usr/lib/python3/dist-packages/tenacity/__init__.py", line 412, in call
2021-11-17 17:57:23.584 89792 ERROR cinder.volume.manager result = fn(*args, **kwargs)
2021-11-17 17:57:23.584 89792 ERROR cinder.volume.manager File "/usr/lib/python3/dist-packages/cinder/volume/targets/tgt.py", line 207, in create_iscsi_target
2021-11-17 17:57:23.584 89792 ERROR cinder.volume.manager raise exception.NotFound()
2021-11-17 17:57:23.584 89792 ERROR cinder.volume.manager cinder.exception.NotFound: Resource could not be found.
2021-11-17 17:57:23.584 89792 ERROR cinder.volume.manager
2021-11-17 17:57:23.590 89792 ERROR oslo_messaging.rpc.server [req-5be680ea-1de6-47a0-98d0-b1b2a2075903 b8853fd0e865432da309dcb2235352d0 441fc0965933423f8664f9f92495cf29 - - -] Exception during message handling: cinder.exception.VolumeBackendAPIException: Bad or unexpected response from the storage volume backend API: Create export for volume failed (Resource could not be found.).
2021-11-17 17:57:23.590 89792 ERROR oslo_messaging.rpc.server Traceback (most recent call last):
2021-11-17 17:57:23.590 89792 ERROR oslo_messaging.rpc.server File "/usr/lib/python3/dist-packages/cinder/volume/manager.py", line 4655, in _connection_create
2021-11-17 17:57:23.590 89792 ERROR oslo_messaging.rpc.server model_update = self.driver.create_export(ctxt.elevated(),
2021-11-17 17:57:23.590 89792 ERROR oslo_messaging.rpc.server File "/usr/lib/python3/dist-packages/cinder/volume/drivers/lvm.py", line 834, in create_export
2021-11-17 17:57:23.590 89792 ERROR oslo_messaging.rpc.server export_info = self.target_driver.create_export(
2021-11-17 17:57:23.590 89792 ERROR oslo_messaging.rpc.server File "/usr/lib/python3/dist-packages/cinder/volume/targets/iscsi.py", line 194, in create_export
2021-11-17 17:57:23.590 89792 ERROR oslo_messaging.rpc.server tid = self.create_iscsi_target(iscsi_name,
2021-11-17 17:57:23.590 89792 ERROR oslo_messaging.rpc.server File "/usr/lib/python3/dist-packages/cinder/utils.py", line 614, in _wrapper
2021-11-17 17:57:23.590 89792 ERROR oslo_messaging.rpc.server return r.call(f, *args, **kwargs)
2021-11-17 17:57:23.590 89792 ERROR oslo_messaging.rpc.server File "/usr/lib/python3/dist-packages/tenacity/__init__.py", line 409, in call
2021-11-17 17:57:23.590 89792 ERROR oslo_messaging.rpc.server do = self.iter(retry_state=retry_state)
2021-11-17 17:57:23.590 89792 ERROR oslo_messaging.rpc.server File "/usr/lib/python3/dist-packages/tenacity/__init__.py", line 368, in iter
2021-11-17 17:57:23.590 89792 ERROR oslo_messaging.rpc.server raise retry_exc.reraise()
2021-11-17 17:57:23.590 89792 ERROR oslo_messaging.rpc.server File "/usr/lib/python3/dist-packages/tenacity/__init__.py", line 186, in reraise
2021-11-17 17:57:23.590 89792 ERROR oslo_messaging.rpc.server raise self.last_attempt.result()
2021-11-17 17:57:23.590 89792 ERROR oslo_messaging.rpc.server File "/usr/lib/python3.8/concurrent/futures/_base.py", line 437, in result
2021-11-17 17:57:23.590 89792 ERROR oslo_messaging.rpc.server return self.__get_result()
2021-11-17 17:57:23.590 89792 ERROR oslo_messaging.rpc.server File "/usr/lib/python3.8/concurrent/futures/_base.py", line 389, in __get_result
2021-11-17 17:57:23.590 89792 ERROR oslo_messaging.rpc.server raise self._exception
2021-11-17 17:57:23.590 89792 ERROR oslo_messaging.rpc.server File "/usr/lib/python3/dist-packages/tenacity/__init__.py", line 412, in call
2021-11-17 17:57:23.590 89792 ERROR oslo_messaging.rpc.server result = fn(*args, **kwargs)
2021-11-17 17:57:23.590 89792 ERROR oslo_messaging.rpc.server File "/usr/lib/python3/dist-packages/cinder/volume/targets/tgt.py", line 207, in create_iscsi_target
2021-11-17 17:57:23.590 89792 ERROR oslo_messaging.rpc.server raise exception.NotFound()
2021-11-17 17:57:23.590 89792 ERROR oslo_messaging.rpc.server cinder.exception.NotFound: Resource could not be found.
2021-11-17 17:57:23.590 89792 ERROR oslo_messaging.rpc.server
2021-11-17 17:57:23.590 89792 ERROR oslo_messaging.rpc.server During handling of the above exception, another exception occurred:
2021-11-17 17:57:23.590 89792 ERROR oslo_messaging.rpc.server
2021-11-17 17:57:23.590 89792 ERROR oslo_messaging.rpc.server Traceback (most recent call last):
2021-11-17 17:57:23.590 89792 ERROR oslo_messaging.rpc.server File "/usr/lib/python3/dist-packages/oslo_messaging/rpc/server.py", line 165, in _process_incoming
2021-11-17 17:57:23.590 89792 ERROR oslo_messaging.rpc.server res = self.dispatcher.dispatch(message)
2021-11-17 17:57:23.590 89792 ERROR oslo_messaging.rpc.server File "/usr/lib/python3/dist-packages/oslo_messaging/rpc/dispatcher.py", line 309, in dispatch
2021-11-17 17:57:23.590 89792 ERROR oslo_messaging.rpc.server return self._do_dispatch(endpoint, method, ctxt, args)
2021-11-17 17:57:23.590 89792 ERROR oslo_messaging.rpc.server File "/usr/lib/python3/dist-packages/oslo_messaging/rpc/dispatcher.py", line 229, in _do_dispatch
2021-11-17 17:57:23.590 89792 ERROR oslo_messaging.rpc.server result = func(ctxt, **new_args)
2021-11-17 17:57:23.590 89792 ERROR oslo_messaging.rpc.server File "/usr/lib/python3/dist-packages/cinder/volume/manager.py", line 4725, in attachment_update
2021-11-17 17:57:23.590 89792 ERROR oslo_messaging.rpc.server connection_info = self._connection_create(context,
2021-11-17 17:57:23.590 89792 ERROR oslo_messaging.rpc.server File "/usr/lib/python3/dist-packages/cinder/volume/manager.py", line 4660, in _connection_create
2021-11-17 17:57:23.590 89792 ERROR oslo_messaging.rpc.server raise exception.VolumeBackendAPIException(data=err_msg)
2021-11-17 17:57:23.590 89792 ERROR oslo_messaging.rpc.server cinder.exception.VolumeBackendAPIException: Bad or unexpected response from the storage volume backend API: Create export for volume failed (Resource could not be found.).
2021-11-17 17:57:23.590 89792 ERROR oslo_messaging.rpc.server
Adding "include /var/lib/