Failure on restoring imported Ceph backup

Bug #1936431 reported by Daniel de Oliveira Pereira
6
This bug affects 1 person
Affects Status Importance Assigned to Milestone
Cinder
New
Medium
Unassigned

Bug Description

Considering the following scenario:

1- a volume was created using rbd volume driver;
2- a backup from that volume was created using ceph backup driver;
3- the backup metadata was exported from Cinder database and the backup image was exported from ceph pool;
4- the backup was deleted;
5- the backup metadata was imported to Cinder database the backup image was imported to ceph pool (same or another Openstack installation);

Trying to restore the backup to the original (or a new one) volume results on error.

If the backup was created from a volume snapshot, the restore operation succeeds.

Steps to reproduce:

1- create a volume
$ openstack volume create --type ceph-store --size <size> <volume_name>

2- create a volume backup
$ openstack volume backup create --name <backup_name> <volume_name>

3-export the backup metadata
$ cinder backup-export <backup_id> > <backup_metadata_file>

4- export the backup image from ceph pool
$ rbd list -p cinder.backups
$ rbd export -p cinder.backups <backup_image> <exported_image_file>

backup image name pattern: "volume-<volume_id>.backup.<backup_id>"

5- delete the backup
$ openstack volume backup delete <backup_name>

6- import the backup metadata
$ cat <backup_metadata_file>
$ cinder backup-import <backup_service> <backup_url>

7- import backup image to ceph pool
$ rbd import <exported_image_file> cinder.backups/volume-<volume_id>.backup.<backup_id>

8- restore the backup
$ openstack volume backup restore <backup_name> <volume_name>

Logs from cinder-backup:

2021-07-14 09:15:36.599 10 INFO cinder.backup.manager [req-3673b41a-76b3-459c-b743-d0db5fea3fa9 ea82031182f34c569f58ada79994b79e a611e53350da4fac9a3acaf84a1b00f0 - - -] Restore backup started, backup: e8039452-1aa1-498b-9088-41ca5ac5555b volume: 0276e51a-aaa1-4ace-86c6-0729f8a412be.
2021-07-14 09:15:36.599 10 INFO cinder.backup.manager [req-3673b41a-76b3-459c-b743-d0db5fea3fa9 ea82031182f34c569f58ada79994b79e a611e53350da4fac9a3acaf84a1b00f0 - - -] Restore backup started, backup: e8039452-1aa1-498b-9088-41ca5ac5555b volume: 0276e51a-aaa1-4ace-86c6-0729f8a412be.
2021-07-14 09:15:36.622 10 WARNING os_brick.initiator.connectors.iscsi [req-3673b41a-76b3-459c-b743-d0db5fea3fa9 ea82031182f34c569f58ada79994b79e a611e53350da4fac9a3acaf84a1b00f0 - - -] Could not find the iSCSI Initiator File /etc/iscsi/initiatorname.iscsi: oslo_concurrency.processutils.ProcessExecutionError: Unexpected error while running command.
2021-07-14 09:15:36.641 10 WARNING os_brick.initiator.connectors.nvmeof [req-3673b41a-76b3-459c-b743-d0db5fea3fa9 ea82031182f34c569f58ada79994b79e a611e53350da4fac9a3acaf84a1b00f0 - - -] Process execution error in _get_host_uuid: Unexpected error while running command.
Command: blkid overlay -s UUID -o value
Exit code: 2
Stdout: ''
Stderr: '': oslo_concurrency.processutils.ProcessExecutionError: Unexpected error while running command.
2021-07-14 09:15:37.476 10 INFO cinder.backup.drivers.ceph [req-3673b41a-76b3-459c-b743-d0db5fea3fa9 ea82031182f34c569f58ada79994b79e a611e53350da4fac9a3acaf84a1b00f0 - - -] No restore point found for backup='e8039452-1aa1-498b-9088-41ca5ac5555b' of volume 4886a569-967a-445d-8b55-2973b3216676 although base image is found - forcing full copy.
2021-07-14 09:15:37.476 10 INFO cinder.backup.drivers.ceph [req-3673b41a-76b3-459c-b743-d0db5fea3fa9 ea82031182f34c569f58ada79994b79e a611e53350da4fac9a3acaf84a1b00f0 - - -] No restore point found for backup='e8039452-1aa1-498b-9088-41ca5ac5555b' of volume 4886a569-967a-445d-8b55-2973b3216676 although base image is found - forcing full copy.
2021-07-14 09:15:37.571 10 ERROR cinder.backup.manager [req-3673b41a-76b3-459c-b743-d0db5fea3fa9 ea82031182f34c569f58ada79994b79e a611e53350da4fac9a3acaf84a1b00f0 - - -] Restoring backup e8039452-1aa1-498b-9088-41ca5ac5555b to volume 0276e51a-aaa1-4ace-86c6-0729f8a412be failed.: rbd.ImageNotFound: [errno 2] error opening image b'volume-4886a569-967a-445d-8b55-2973b3216676.backup.base' at snapshot None
2021-07-14 09:15:37.571 10 ERROR cinder.backup.manager Traceback (most recent call last):
2021-07-14 09:15:37.571 10 ERROR cinder.backup.manager File "/var/lib/openstack/lib/python3.6/site-packages/cinder/backup/manager.py", line 660, in _run_restore
2021-07-14 09:15:37.571 10 ERROR cinder.backup.manager tpool.Proxy(device_path))
2021-07-14 09:15:37.571 10 ERROR cinder.backup.manager File "/var/lib/openstack/lib/python3.6/site-packages/cinder/backup/drivers/ceph.py", line 1279, in restore
2021-07-14 09:15:37.571 10 ERROR cinder.backup.manager self._restore_volume(backup, target_volume, volume_file)
2021-07-14 09:15:37.571 10 ERROR cinder.backup.manager File "/var/lib/openstack/lib/python3.6/site-packages/cinder/backup/drivers/ceph.py", line 1246, in _restore_volume
2021-07-14 09:15:37.571 10 ERROR cinder.backup.manager length, src_snap=restore_point)
2021-07-14 09:15:37.571 10 ERROR cinder.backup.manager File "/var/lib/openstack/lib/python3.6/site-packages/cinder/backup/drivers/ceph.py", line 1041, in _full_restore
2021-07-14 09:15:37.571 10 ERROR cinder.backup.manager read_only=True))
2021-07-14 09:15:37.571 10 ERROR cinder.backup.manager File "rbd.pyx", line 1821, in rbd.Image.__init__
2021-07-14 09:15:37.571 10 ERROR cinder.backup.manager rbd.ImageNotFound: [errno 2] error opening image b'volume-4886a569-967a-445d-8b55-2973b3216676.backup.base' at snapshot None
2021-07-14 09:15:37.571 10 ERROR cinder.backup.manager
2021-07-14 09:15:37.571 10 ERROR cinder.backup.manager [req-3673b41a-76b3-459c-b743-d0db5fea3fa9 ea82031182f34c569f58ada79994b79e a611e53350da4fac9a3acaf84a1b00f0 - - -] Restoring backup e8039452-1aa1-498b-9088-41ca5ac5555b to volume 0276e51a-aaa1-4ace-86c6-0729f8a412be failed.: rbd.ImageNotFound: [errno 2] error opening image b'volume-4886a569-967a-445d-8b55-2973b3216676.backup.base' at snapshot None
2021-07-14 09:15:37.571 10 ERROR cinder.backup.manager Traceback (most recent call last):
2021-07-14 09:15:37.571 10 ERROR cinder.backup.manager File "/var/lib/openstack/lib/python3.6/site-packages/cinder/backup/manager.py", line 660, in _run_restore
2021-07-14 09:15:37.571 10 ERROR cinder.backup.manager tpool.Proxy(device_path))
2021-07-14 09:15:37.571 10 ERROR cinder.backup.manager File "/var/lib/openstack/lib/python3.6/site-packages/cinder/backup/drivers/ceph.py", line 1279, in restore
2021-07-14 09:15:37.571 10 ERROR cinder.backup.manager self._restore_volume(backup, target_volume, volume_file)
2021-07-14 09:15:37.571 10 ERROR cinder.backup.manager File "/var/lib/openstack/lib/python3.6/site-packages/cinder/backup/drivers/ceph.py", line 1246, in _restore_volume
2021-07-14 09:15:37.571 10 ERROR cinder.backup.manager length, src_snap=restore_point)
2021-07-14 09:15:37.571 10 ERROR cinder.backup.manager File "/var/lib/openstack/lib/python3.6/site-packages/cinder/backup/drivers/ceph.py", line 1041, in _full_restore
2021-07-14 09:15:37.571 10 ERROR cinder.backup.manager read_only=True))
2021-07-14 09:15:37.571 10 ERROR cinder.backup.manager File "rbd.pyx", line 1821, in rbd.Image.__init__
2021-07-14 09:15:37.571 10 ERROR cinder.backup.manager rbd.ImageNotFound: [errno 2] error opening image b'volume-4886a569-967a-445d-8b55-2973b3216676.backup.base' at snapshot None
2021-07-14 09:15:37.571 10 ERROR cinder.backup.manager
2021-07-14 09:15:37.705 10 ERROR oslo_messaging.rpc.server [req-3673b41a-76b3-459c-b743-d0db5fea3fa9 ea82031182f34c569f58ada79994b79e a611e53350da4fac9a3acaf84a1b00f0 - - -] Exception during message handling: rbd.ImageNotFound: [errno 2] error opening image b'volume-4886a569-967a-445d-8b55-2973b3216676.backup.base' at snapshot None
2021-07-14 09:15:37.705 10 ERROR oslo_messaging.rpc.server Traceback (most recent call last):
2021-07-14 09:15:37.705 10 ERROR oslo_messaging.rpc.server File "/var/lib/openstack/lib/python3.6/site-packages/oslo_messaging/rpc/server.py", line 165, in _process_incoming
2021-07-14 09:15:37.705 10 ERROR oslo_messaging.rpc.server res = self.dispatcher.dispatch(message)
2021-07-14 09:15:37.705 10 ERROR oslo_messaging.rpc.server File "/var/lib/openstack/lib/python3.6/site-packages/oslo_messaging/rpc/dispatcher.py", line 309, in dispatch
2021-07-14 09:15:37.705 10 ERROR oslo_messaging.rpc.server return self._do_dispatch(endpoint, method, ctxt, args)
2021-07-14 09:15:37.705 10 ERROR oslo_messaging.rpc.server File "/var/lib/openstack/lib/python3.6/site-packages/oslo_messaging/rpc/dispatcher.py", line 229, in _do_dispatch
2021-07-14 09:15:37.705 10 ERROR oslo_messaging.rpc.server result = func(ctxt, **new_args)
2021-07-14 09:15:37.705 10 ERROR oslo_messaging.rpc.server File "/var/lib/openstack/lib/python3.6/site-packages/cinder/utils.py", line 900, in wrapper
2021-07-14 09:15:37.705 10 ERROR oslo_messaging.rpc.server return func(self, *args, **kwargs)
2021-07-14 09:15:37.705 10 ERROR oslo_messaging.rpc.server File "/var/lib/openstack/lib/python3.6/site-packages/cinder/backup/manager.py", line 599, in restore_backup
2021-07-14 09:15:37.705 10 ERROR oslo_messaging.rpc.server backup.save()
2021-07-14 09:15:37.705 10 ERROR oslo_messaging.rpc.server File "/var/lib/openstack/lib/python3.6/site-packages/oslo_utils/excutils.py", line 227, in __exit__
2021-07-14 09:15:37.705 10 ERROR oslo_messaging.rpc.server self.force_reraise()
2021-07-14 09:15:37.705 10 ERROR oslo_messaging.rpc.server File "/var/lib/openstack/lib/python3.6/site-packages/oslo_utils/excutils.py", line 200, in force_reraise
2021-07-14 09:15:37.705 10 ERROR oslo_messaging.rpc.server raise self.value
2021-07-14 09:15:37.705 10 ERROR oslo_messaging.rpc.server File "/var/lib/openstack/lib/python3.6/site-packages/cinder/backup/manager.py", line 588, in restore_backup
2021-07-14 09:15:37.705 10 ERROR oslo_messaging.rpc.server self._run_restore(context, backup, volume)
2021-07-14 09:15:37.705 10 ERROR oslo_messaging.rpc.server File "/var/lib/openstack/lib/python3.6/site-packages/cinder/backup/manager.py", line 660, in _run_restore
2021-07-14 09:15:37.705 10 ERROR oslo_messaging.rpc.server tpool.Proxy(device_path))
2021-07-14 09:15:37.705 10 ERROR oslo_messaging.rpc.server File "/var/lib/openstack/lib/python3.6/site-packages/cinder/backup/drivers/ceph.py", line 1279, in restore
2021-07-14 09:15:37.705 10 ERROR oslo_messaging.rpc.server self._restore_volume(backup, target_volume, volume_file)
2021-07-14 09:15:37.705 10 ERROR oslo_messaging.rpc.server File "/var/lib/openstack/lib/python3.6/site-packages/cinder/backup/drivers/ceph.py", line 1246, in _restore_volume
2021-07-14 09:15:37.705 10 ERROR oslo_messaging.rpc.server length, src_snap=restore_point)
2021-07-14 09:15:37.705 10 ERROR oslo_messaging.rpc.server File "/var/lib/openstack/lib/python3.6/site-packages/cinder/backup/drivers/ceph.py", line 1041, in _full_restore
2021-07-14 09:15:37.705 10 ERROR oslo_messaging.rpc.server read_only=True))
2021-07-14 09:15:37.705 10 ERROR oslo_messaging.rpc.server File "rbd.pyx", line 1821, in rbd.Image.__init__
2021-07-14 09:15:37.705 10 ERROR oslo_messaging.rpc.server rbd.ImageNotFound: [errno 2] error opening image b'volume-4886a569-967a-445d-8b55-2973b3216676.backup.base' at snapshot None
2021-07-14 09:15:37.705 10 ERROR oslo_messaging.rpc.server

Workaround:

on step 7, execute the following command instead of the one described there:
$ rbd import <path_to_exported_image_file> cinder.backups/volume-<volume_id>.backup.base

Cinder versions tested:
    stable/ussuri,
    master: sha1 0570b168e2a444af0d39750638590db0ebcee1a4

Tested with containerized OpenStack (stx-openstack) running on StarlingX master.

tags: added: backup-service rbd restore ussuri
Changed in cinder:
importance: Undecided → Medium
tags: added: import
To post a comment you must log in.
This report contains Public information  
Everyone can see this information.

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.