Description:
After upgrade cinder-backup from queens version (12.0.9) to rocky version (13.0.9 - taken from ubuntu cloud archive repo) restoring of backup stopped working. Backup is created. Important part in this problem: main backend storage is on disk array (Huawei dorado), and backup is made on ceph backup pool.
Revelant logs:
Creating backup:
2020-11-22 19:16:53.960 6442 DEBUG cinder.backup.drivers.ceph [req-9d0ec11c-498a-464e-b9a8-00120126054e 833873b8f04842188a0709c3ef23ab6b 2037dd6132e348749e830b89af87df7d - default default] Starting backup of volume='47f9cc77-5660-4dd2-b5ab-2b02ea952257'. backup /usr/lib/python2.7/dist-packages/cinder/backup/drivers/ceph.py:945
2020-11-22 19:16:53.962 6442 DEBUG cinder.backup.drivers.ceph [req-9d0ec11c-498a-464e-b9a8-00120126054e 833873b8f04842188a0709c3ef23ab6b 2037dd6132e348749e830b89af87df7d - default default] Volume file is NOT RBD: will do full backup. backup /usr/lib/python2.7/dist-packages/cinder/backup/drivers/ceph.py:968
2020-11-22 19:16:53.997 6442 DEBUG cinder.backup.drivers.ceph [req-9d0ec11c-498a-464e-b9a8-00120126054e 833873b8f04842188a0709c3ef23ab6b 2037dd6132e348749e830b89af87df7d - default default] Creating backup base image='volume-47f9cc77-5660-4dd2-b5ab-2b02ea952257.backup.2032a748-a734-4836-a4ef-90fcb817f938' for volume 47f9cc77-5660-4dd2-b5ab-2b02ea952257. _full_backup /usr/lib/python2.7/dist-packages/cinder/backup/drivers/ceph.py:803
2020-11-22 19:16:54.036 6442 DEBUG cinder.backup.drivers.ceph [req-9d0ec11c-498a-464e-b9a8-00120126054e 833873b8f04842188a0709c3ef23ab6b 2037dd6132e348749e830b89af87df7d - default default] Copying data from volume 47f9cc77-5660-4dd2-b5ab-2b02ea952257. _full_backup /usr/lib/python2.7/dist-packages/cinder/backup/drivers/ceph.py:813
2020-11-22 19:16:54.059 6442 DEBUG cinder.backup.drivers.ceph [req-9d0ec11c-498a-464e-b9a8-00120126054e 833873b8f04842188a0709c3ef23ab6b 2037dd6132e348749e830b89af87df7d - default default] Transferring data between 'volume-47f9cc77-5660-4dd2-b5ab-2b02ea952257' and 'volume-47f9cc77-5660-4dd2-b5ab-2b02ea952257.backup.2032a748-a734-4836-a4ef-90fcb817f938' _transfer_data /usr/lib/python2.7/dist-packages/cinder/backup/drivers/ceph.py:376
2020-11-22 19:16:54.061 6442 DEBUG cinder.backup.drivers.ceph [req-9d0ec11c-498a-464e-b9a8-00120126054e 833873b8f04842188a0709c3ef23ab6b 2037dd6132e348749e830b89af87df7d - default default] 24 chunks of 134217728 bytes to be transferred _transfer_data /usr/lib/python2.7/dist-packages/cinder/backup/drivers/ceph.py:380
2020-11-22 19:16:54.900 6442 DEBUG cinder.backup.drivers.ceph [req-9d0ec11c-498a-464e-b9a8-00120126054e 833873b8f04842188a0709c3ef23ab6b 2037dd6132e348749e830b89af87df7d - default default] Transferred chunk 1 of 24 (156521K/s) _transfer_data /usr/lib/python2.7/dist-packages/cinder/backup/drivers/ceph.py:402
[..]
2020-11-22 19:17:44.105 6442 DEBUG cinder.backup.drivers.ceph [req-9d0ec11c-498a-464e-b9a8-00120126054e 833873b8f04842188a0709c3ef23ab6b 2037dd6132e348749e830b89af87df7d - default default] Transferred chunk 24 of 24 (28910K/s) _transfer_data /usr/lib/python2.7/dist-packages/cinder/backup/drivers/ceph.py:402
2020-11-22 19:17:44.215 6442 DEBUG cinder.backup.drivers.ceph [req-9d0ec11c-498a-464e-b9a8-00120126054e 833873b8f04842188a0709c3ef23ab6b 2037dd6132e348749e830b89af87df7d - default default] Backing up metadata for volume 47f9cc77-5660-4dd2-b5ab-2b02ea952257. _backup_metadata /usr/lib/python2.7/dist-packages/cinder/backup/drivers/ceph.py:922
2020-11-22 19:17:44.249 6442 DEBUG cinder.backup.drivers.ceph [req-9d0ec11c-498a-464e-b9a8-00120126054e 833873b8f04842188a0709c3ef23ab6b 2037dd6132e348749e830b89af87df7d - default default] Backup '2032a748-a734-4836-a4ef-90fcb817f938' of volume 47f9cc77-5660-4dd2-b5ab-2b02ea952257 finished. backup /usr/lib/python2.7/dist-packages/cinder/backup/drivers/ceph.py:987
backup is created on ceph, but without 'backup.base' extension:
[TEST][root@ceph-mon-01 ~]# rbd du backup/volume-47f9cc77-5660-4dd2-b5ab-2b02ea952257.backup.2032a748-a734-4836-a4ef-90fcb817f938
warning: fast-diff map is not enabled for volume-47f9cc77-5660-4dd2-b5ab-2b02ea952257.backup.2032a748-a734-4836-a4ef-90fcb817f938. operation may be slow.
NAME PROVISIONED USED
volume-47f9cc77-5660-4dd2-b5ab-2b02ea952257.backup.2032a748-a734-4836-a4ef-90fcb817f938 3GiB 3GiB
[TEST][root@ceph-mon-01 ~]#
restore of backup:
2020-11-22 19:03:08.985 12598 DEBUG os_brick.initiator.connectors.iscsi [req-79c19d75-4a18-4a6f-bca2-3a86a3e0b9a8 833873b8f04842188a0709c3ef23ab6b 2037dd6132e348749e830b89af87df7d - default default] All connection threads finished, giving 10 seconds for dm to appear. _connect_multipath_volume /usr/lib/python2.7/dist-packages/os_brick/initiator/connectors/iscsi.py:737
2020-11-22 19:03:09.986 12598 DEBUG oslo_concurrency.lockutils [req-79c19d75-4a18-4a6f-bca2-3a86a3e0b9a8 833873b8f04842188a0709c3ef23ab6b 2037dd6132e348749e830b89af87df7d - default default] Lock "connect_volume" released by "os_brick.initiator.connectors.iscsi.connect_volume" :: held 2.440s inner /usr/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:285
2020-11-22 19:03:09.988 12598 DEBUG os_brick.initiator.connectors.iscsi [req-79c19d75-4a18-4a6f-bca2-3a86a3e0b9a8 833873b8f04842188a0709c3ef23ab6b 2037dd6132e348749e830b89af87df7d - default default] <== connect_volume: return (2442ms) {'path': u'/dev/dm-0', 'scsi_wwn': u'36e00084100ee7e7e16910c78000024db', 'type': u'block', 'multipath_id': u'36e00084100ee7e7e16910c78000024db'} trace_logging_wrapper /usr/lib/python2.7/dist-packages/os_brick/utils.py:170
2020-11-22 19:03:09.990 12598 DEBUG oslo_concurrency.processutils [req-79c19d75-4a18-4a6f-bca2-3a86a3e0b9a8 833873b8f04842188a0709c3ef23ab6b 2037dd6132e348749e830b89af87df7d - default default] Running cmd (subprocess): sudo cinder-rootwrap /etc/cinder/rootwrap.conf chown 64061 /dev/dm-0 execute /usr/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:372
2020-11-22 19:03:10.266 12598 DEBUG oslo_concurrency.processutils [req-79c19d75-4a18-4a6f-bca2-3a86a3e0b9a8 833873b8f04842188a0709c3ef23ab6b 2037dd6132e348749e830b89af87df7d - default default] CMD "sudo cinder-rootwrap /etc/cinder/rootwrap.conf chown 64061 /dev/dm-0" returned: 0 in 0.276s execute /usr/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:409
2020-11-22 19:03:10.493 12598 DEBUG cinder.backup.drivers.ceph [req-79c19d75-4a18-4a6f-bca2-3a86a3e0b9a8 833873b8f04842188a0709c3ef23ab6b 2037dd6132e348749e830b89af87df7d - default default] Starting restore from Ceph backup=9752bd00-8572-40e0-b20e-a9883d3cd665 to volume=volume-4a6208e4-c54f-4307-9183-3abbae9009d0 restore /usr/lib/python2.7/dist-packages/cinder/backup/drivers/ceph.py:1247
2020-11-22 19:03:20.559 12598 DEBUG cinder.backup.drivers.ceph [req-79c19d75-4a18-4a6f-bca2-3a86a3e0b9a8 833873b8f04842188a0709c3ef23ab6b 2037dd6132e348749e830b89af87df7d - default default] Image 'volume-b97c7ec6-53e1-41d6-acc5-103482eae519.backup.base' not found - trying diff format name _rbd_image_exists /usr/lib/python2.7/dist-packages/cinder/backup/drivers/ceph.py:635
2020-11-22 19:03:20.567 12598 DEBUG cinder.backup.drivers.ceph [req-79c19d75-4a18-4a6f-bca2-3a86a3e0b9a8 833873b8f04842188a0709c3ef23ab6b 2037dd6132e348749e830b89af87df7d - default default] Running full restore. _restore_volume /usr/lib/python2.7/dist-packages/cinder/backup/drivers/ceph.py:1215
2020-11-22 19:03:20.627 12598 DEBUG oslo_concurrency.processutils [req-79c19d75-4a18-4a6f-bca2-3a86a3e0b9a8 833873b8f04842188a0709c3ef23ab6b 2037dd6132e348749e830b89af87df7d - default default] Running cmd (subprocess): sudo cinder-rootwrap /etc/cinder/rootwrap.conf chown 0 /dev/dm-0 execute /usr/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:372
2020-11-22 19:03:20.982 12598 DEBUG oslo_concurrency.processutils [req-79c19d75-4a18-4a6f-bca2-3a86a3e0b9a8 833873b8f04842188a0709c3ef23ab6b 2037dd6132e348749e830b89af87df7d - default default] CMD "sudo cinder-rootwrap /etc/cinder/rootwrap.conf chown 0 /dev/dm-0" returned: 0 in 0.355s execute /usr/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:409
2020-11-22 19:03:20.987 12598 ERROR cinder.backup.manager [req-79c19d75-4a18-4a6f-bca2-3a86a3e0b9a8 833873b8f04842188a0709c3ef23ab6b 2037dd6132e348749e830b89af87df7d - default default] Restoring backup 9752bd00-8572-40e0-b20e-a9883d3cd665 to volume 4a6208e4-c54f-4307-9183-3abbae9009d0 failed.: ImageNotFound: [errno 2] error opening image volume-b97c7ec6-53e1-41d6-acc5-103482eae519.backup.base at snapshot None
2020-11-22 19:03:20.987 12598 ERROR cinder.backup.manager Traceback (most recent call last):
2020-11-22 19:03:20.987 12598 ERROR cinder.backup.manager File "/usr/lib/python2.7/dist-packages/cinder/backup/manager.py", line 665, in _run_restore
2020-11-22 19:03:20.987 12598 ERROR cinder.backup.manager tpool.Proxy(device_file))
2020-11-22 19:03:20.987 12598 ERROR cinder.backup.manager File "/usr/lib/python2.7/dist-packages/cinder/backup/drivers/ceph.py", line 1250, in restore
2020-11-22 19:03:20.987 12598 ERROR cinder.backup.manager self._restore_volume(backup, target_volume, volume_file)
2020-11-22 19:03:20.987 12598 ERROR cinder.backup.manager File "/usr/lib/python2.7/dist-packages/cinder/backup/drivers/ceph.py", line 1217, in _restore_volume
2020-11-22 19:03:20.987 12598 ERROR cinder.backup.manager length, src_snap=restore_point)
2020-11-22 19:03:20.987 12598 ERROR cinder.backup.manager File "/usr/lib/python2.7/dist-packages/cinder/backup/drivers/ceph.py", line 1012, in _full_restore
2020-11-22 19:03:20.987 12598 ERROR cinder.backup.manager read_only=True))
2020-11-22 19:03:20.987 12598 ERROR cinder.backup.manager File "rbd.pyx", line 2954, in rbd.Image.__init__
2020-11-22 19:03:20.987 12598 ERROR cinder.backup.manager ImageNotFound: [errno 2] error opening image volume-b97c7ec6-53e1-41d6-acc5-103482eae519.backup.base at snapshot None
2020-11-22 19:03:20.987 12598 ERROR cinder.backup.manager
Most important part in my opinion is here:
2020-11-22 19:03:10.493 12598 DEBUG cinder.backup.drivers.ceph [req-79c19d75-4a18-4a6f-bca2-3a86a3e0b9a8 833873b8f04842188a0709c3ef23ab6b 2037dd6132e348749e830b89af87df7d - default default] Starting restore from Ceph backup=9752bd00-8572-40e0-b20e-a9883d3cd665 to volume=volume-4a6208e4-c54f-4307-9183-3abbae9009d0 restore /usr/lib/python2.7/dist-packages/cinder/backup/drivers/ceph.py:1247
2020-11-22 19:03:20.559 12598 DEBUG cinder.backup.drivers.ceph [req-79c19d75-4a18-4a6f-bca2-3a86a3e0b9a8 833873b8f04842188a0709c3ef23ab6b 2037dd6132e348749e830b89af87df7d - default default] Image 'volume-b97c7ec6-53e1-41d6-acc5-103482eae519.backup.base' not found - trying diff format name _rbd_image_exists /usr/lib/python2.7/dist-packages/cinder/backup/drivers/ceph.py:635
2020-11-22 19:03:20.567 12598 DEBUG cinder.backup.drivers.ceph [req-79c19d75-4a18-4a6f-bca2-3a86a3e0b9a8 833873b8f04842188a0709c3ef23ab6b 2037dd6132e348749e830b89af87df7d - default default] Running full restore. _restore_volume /usr/lib/python2.7/dist-packages/cinder/backup/drivers/ceph.py:1215
2020-11-22 19:03:20.987 12598 ERROR cinder.backup.manager [req-79c19d75-4a18-4a6f-bca2-3a86a3e0b9a8 833873b8f04842188a0709c3ef23ab6b 2037dd6132e348749e830b89af87df7d - default default] Restoring backup 9752bd00-8572-40e0-b20e-a9883d3cd665 to volume 4a6208e4-c54f-4307-9183-3abbae9009d0 failed.: ImageNotFound: [errno 2] error opening image volume-b97c7ec6-53e1-41d6-acc5-103482eae519.backup.base at snapshot None
The diff format doesn't work in case of full backup created the way rocky version do this.
I think this bug might be related to https:/