Page MenuHomePhabricator

Cinder Backups: deleting snapshot failed, dependent volumes
Closed, InvalidPublic

Description

sudo journalctl -u cinder-volume.service

Jun 06 17:17:11 cloudcontrol1005 cinder-volume[3297194]: 2022-06-06 17:17:11.182 3297194 INFO cinder.volume.manager [req-6e13162a-cd38-43fe-b1c3-bce0e33fac0f novaadmin admin - - -] Initialize volume connection completed successfully.
Jun 07 18:23:57 cloudcontrol1005 cinder-volume[3297194]: 2022-06-07 18:23:57.173 3297194 ERROR oslo_db.sqlalchemy.engines [req-53fdc38f-298e-4e86-a2fc-9c1881d9a114 - - - - -] Database connection was found disconnected; reconnecting: oslo_db.exception.DBConnectionError: (pymysql.err.OperationalError) (2013, 'Lost connection to MySQL server during query')
                                                         [SQL: SELECT 1]
                                                         (Background on this error at: http://sqlalche.me/e/13/e3q8)
                                                         2022-06-07 18:23:57.173 3297194 ERROR oslo_db.sqlalchemy.engines Traceback (most recent call last):
                                                         2022-06-07 18:23:57.173 3297194 ERROR oslo_db.sqlalchemy.engines   File "/usr/lib/python3/dist-packages/sqlalchemy/engine/base.py", line 1276, in _execute_context
                                                         2022-06-07 18:23:57.173 3297194 ERROR oslo_db.sqlalchemy.engines     self.dialect.do_execute(
                                                         2022-06-07 18:23:57.173 3297194 ERROR oslo_db.sqlalchemy.engines   File "/usr/lib/python3/dist-packages/sqlalchemy/engine/default.py", line 609, in do_execute
                                                         2022-06-07 18:23:57.173 3297194 ERROR oslo_db.sqlalchemy.engines     cursor.execute(statement, parameters)
                                                         2022-06-07 18:23:57.173 3297194 ERROR oslo_db.sqlalchemy.engines   File "/usr/lib/python3/dist-packages/pymysql/cursors.py", line 148, in execute
                                                         2022-06-07 18:23:57.173 3297194 ERROR oslo_db.sqlalchemy.engines     result = self._query(query)
                                                         2022-06-07 18:23:57.173 3297194 ERROR oslo_db.sqlalchemy.engines   File "/usr/lib/python3/dist-packages/pymysql/cursors.py", line 310, in _query
                                                         2022-06-07 18:23:57.173 3297194 ERROR oslo_db.sqlalchemy.engines     conn.query(q)
                                                         2022-06-07 18:23:57.173 3297194 ERROR oslo_db.sqlalchemy.engines   File "/usr/lib/python3/dist-packages/pymysql/connections.py", line 548, in query
                                                         2022-06-07 18:23:57.173 3297194 ERROR oslo_db.sqlalchemy.engines     self._affected_rows = self._read_query_result(unbuffered=unbuffered)
                                                         2022-06-07 18:23:57.173 3297194 ERROR oslo_db.sqlalchemy.engines   File "/usr/lib/python3/dist-packages/pymysql/connections.py", line 775, in _read_query_result
                                                         2022-06-07 18:23:57.173 3297194 ERROR oslo_db.sqlalchemy.engines     result.read()
                                                         2022-06-07 18:23:57.173 3297194 ERROR oslo_db.sqlalchemy.engines   File "/usr/lib/python3/dist-packages/pymysql/connections.py", line 1156, in read
                                                         2022-06-07 18:23:57.173 3297194 ERROR oslo_db.sqlalchemy.engines     first_packet = self.connection._read_packet()
                                                         2022-06-07 18:23:57.173 3297194 ERROR oslo_db.sqlalchemy.engines   File "/usr/lib/python3/dist-packages/pymysql/connections.py", line 692, in _read_packet
                                                         2022-06-07 18:23:57.173 3297194 ERROR oslo_db.sqlalchemy.engines     packet_header = self._read_bytes(4)
                                                         2022-06-07 18:23:57.173 3297194 ERROR oslo_db.sqlalchemy.engines   File "/usr/lib/python3/dist-packages/pymysql/connections.py", line 748, in _read_bytes
                                                         2022-06-07 18:23:57.173 3297194 ERROR oslo_db.sqlalchemy.engines     raise err.OperationalError(
                                                         2022-06-07 18:23:57.173 3297194 ERROR oslo_db.sqlalchemy.engines pymysql.err.OperationalError: (2013, 'Lost connection to MySQL server during query')
                                                         2022-06-07 18:23:57.173 3297194 ERROR oslo_db.sqlalchemy.engines 
                                                         2022-06-07 18:23:57.173 3297194 ERROR oslo_db.sqlalchemy.engines The above exception was the direct cause of the following exception:
                                                         2022-06-07 18:23:57.173 3297194 ERROR oslo_db.sqlalchemy.engines 
                                                         2022-06-07 18:23:57.173 3297194 ERROR oslo_db.sqlalchemy.engines Traceback (most recent call last):
                                                         2022-06-07 18:23:57.173 3297194 ERROR oslo_db.sqlalchemy.engines   File "/usr/lib/python3/dist-packages/oslo_db/sqlalchemy/engines.py", line 73, in _connect_ping_listener
                                                         2022-06-07 18:23:57.173 3297194 ERROR oslo_db.sqlalchemy.engines     connection.scalar(select([1]))
                                                         2022-06-07 18:23:57.173 3297194 ERROR oslo_db.sqlalchemy.engines   File "/usr/lib/python3/dist-packages/sqlalchemy/engine/base.py", line 941, in scalar
                                                         2022-06-07 18:23:57.173 3297194 ERROR oslo_db.sqlalchemy.engines     return self.execute(object_, *multiparams, **params).scalar()
                                                         2022-06-07 18:23:57.173 3297194 ERROR oslo_db.sqlalchemy.engines   File "/usr/lib/python3/dist-packages/sqlalchemy/engine/base.py", line 1011, in execute
                                                         2022-06-07 18:23:57.173 3297194 ERROR oslo_db.sqlalchemy.engines     return meth(self, multiparams, params)
                                                         2022-06-07 18:23:57.173 3297194 ERROR oslo_db.sqlalchemy.engines   File "/usr/lib/python3/dist-packages/sqlalchemy/sql/elements.py", line 298, in _execute_on_connection
                                                         2022-06-07 18:23:57.173 3297194 ERROR oslo_db.sqlalchemy.engines     return connection._execute_clauseelement(self, multiparams, params)
                                                         2022-06-07 18:23:57.173 3297194 ERROR oslo_db.sqlalchemy.engines   File "/usr/lib/python3/dist-packages/sqlalchemy/engine/base.py", line 1124, in _execute_clauseelement
                                                         2022-06-07 18:23:57.173 3297194 ERROR oslo_db.sqlalchemy.engines     ret = self._execute_context(
                                                         2022-06-07 18:23:57.173 3297194 ERROR oslo_db.sqlalchemy.engines   File "/usr/lib/python3/dist-packages/sqlalchemy/engine/base.py", line 1316, in _execute_context
                                                         2022-06-07 18:23:57.173 3297194 ERROR oslo_db.sqlalchemy.engines     self._handle_dbapi_exception(
                                                         2022-06-07 18:23:57.173 3297194 ERROR oslo_db.sqlalchemy.engines   File "/usr/lib/python3/dist-packages/sqlalchemy/engine/base.py", line 1508, in _handle_dbapi_exception
                                                         2022-06-07 18:23:57.173 3297194 ERROR oslo_db.sqlalchemy.engines     util.raise_(newraise, with_traceback=exc_info[2], from_=e)
                                                         2022-06-07 18:23:57.173 3297194 ERROR oslo_db.sqlalchemy.engines   File "/usr/lib/python3/dist-packages/sqlalchemy/util/compat.py", line 182, in raise_
                                                         2022-06-07 18:23:57.173 3297194 ERROR oslo_db.sqlalchemy.engines     raise exception
                                                         2022-06-07 18:23:57.173 3297194 ERROR oslo_db.sqlalchemy.engines   File "/usr/lib/python3/dist-packages/sqlalchemy/engine/base.py", line 1276, in _execute_context
                                                         2022-06-07 18:23:57.173 3297194 ERROR oslo_db.sqlalchemy.engines     self.dialect.do_execute(
                                                         2022-06-07 18:23:57.173 3297194 ERROR oslo_db.sqlalchemy.engines   File "/usr/lib/python3/dist-packages/sqlalchemy/engine/default.py", line 609, in do_execute
                                                         2022-06-07 18:23:57.173 3297194 ERROR oslo_db.sqlalchemy.engines     cursor.execute(statement, parameters)
                                                         2022-06-07 18:23:57.173 3297194 ERROR oslo_db.sqlalchemy.engines   File "/usr/lib/python3/dist-packages/pymysql/cursors.py", line 148, in execute
                                                         2022-06-07 18:23:57.173 3297194 ERROR oslo_db.sqlalchemy.engines     result = self._query(query)
                                                         2022-06-07 18:23:57.173 3297194 ERROR oslo_db.sqlalchemy.engines   File "/usr/lib/python3/dist-packages/pymysql/cursors.py", line 310, in _query
                                                         2022-06-07 18:23:57.173 3297194 ERROR oslo_db.sqlalchemy.engines     conn.query(q)
                                                         2022-06-07 18:23:57.173 3297194 ERROR oslo_db.sqlalchemy.engines   File "/usr/lib/python3/dist-packages/pymysql/connections.py", line 548, in query
                                                         2022-06-07 18:23:57.173 3297194 ERROR oslo_db.sqlalchemy.engines     self._affected_rows = self._read_query_result(unbuffered=unbuffered)
                                                         2022-06-07 18:23:57.173 3297194 ERROR oslo_db.sqlalchemy.engines   File "/usr/lib/python3/dist-packages/pymysql/connections.py", line 775, in _read_query_result
                                                         2022-06-07 18:23:57.173 3297194 ERROR oslo_db.sqlalchemy.engines     result.read()
                                                         2022-06-07 18:23:57.173 3297194 ERROR oslo_db.sqlalchemy.engines   File "/usr/lib/python3/dist-packages/pymysql/connections.py", line 1156, in read
                                                         2022-06-07 18:23:57.173 3297194 ERROR oslo_db.sqlalchemy.engines     first_packet = self.connection._read_packet()
                                                         2022-06-07 18:23:57.173 3297194 ERROR oslo_db.sqlalchemy.engines   File "/usr/lib/python3/dist-packages/pymysql/connections.py", line 692, in _read_packet
                                                         2022-06-07 18:23:57.173 3297194 ERROR oslo_db.sqlalchemy.engines     packet_header = self._read_bytes(4)
                                                         2022-06-07 18:23:57.173 3297194 ERROR oslo_db.sqlalchemy.engines   File "/usr/lib/python3/dist-packages/pymysql/connections.py", line 748, in _read_bytes
                                                         2022-06-07 18:23:57.173 3297194 ERROR oslo_db.sqlalchemy.engines     raise err.OperationalError(
                                                         2022-06-07 18:23:57.173 3297194 ERROR oslo_db.sqlalchemy.engines oslo_db.exception.DBConnectionError: (pymysql.err.OperationalError) (2013, 'Lost connection to MySQL server during query')
                                                         2022-06-07 18:23:57.173 3297194 ERROR oslo_db.sqlalchemy.engines [SQL: SELECT 1]
                                                         2022-06-07 18:23:57.173 3297194 ERROR oslo_db.sqlalchemy.engines (Background on this error at: http://sqlalche.me/e/13/e3q8)
                                                         2022-06-07 18:23:57.173 3297194 ERROR oslo_db.sqlalchemy.engines
Jun 07 19:39:49 cloudcontrol1005 cinder-volume[3297194]: 2022-06-07 19:39:49.960 7f39f4ff9700 -1 librbd::SnapshotUnprotectRequest: cannot unprotect: at least 1 child(ren) [a5b8032e0c7ced] in pool 'eqiad1-cinder'
Jun 07 19:39:49 cloudcontrol1005 cinder-volume[3297194]: 2022-06-07 19:39:49.960 7f39f4ff9700 -1 librbd::SnapshotUnprotectRequest: encountered error: (16) Device or resource busy
Jun 07 19:39:49 cloudcontrol1005 cinder-volume[3297194]: 2022-06-07 19:39:49.960 7f39f4ff9700 -1 librbd::SnapshotUnprotectRequest: 0x7f39980b89a0 should_complete_error: ret_val=-16
Jun 07 19:39:49 cloudcontrol1005 cinder-volume[3297194]: 2022-06-07 19:39:49.960 7f39f4ff9700 -1 librbd::SnapshotUnprotectRequest: 0x7f39980b89a0 should_complete_error: ret_val=-16
Jun 07 19:39:50 cloudcontrol1005 cinder-volume[3297194]: 2022-06-07 19:39:50.003 3297194 INFO cinder.volume.drivers.rbd [req-93ddec16-9035-4ba6-abc4-bded5a5ebcbd novaadmin admin - - -] Image eqiad1-cinder/volume-3e2506a8-a6e2-4140-9edd-b66299416c1a is dependent on the snapshot snapshot-c7773cad-832a-4286-a60c-f79c76e41c9c.
Jun 07 19:39:50 cloudcontrol1005 cinder-volume[3297194]: 2022-06-07 19:39:50.013 3297194 ERROR cinder.volume.manager [req-93ddec16-9035-4ba6-abc4-bded5a5ebcbd novaadmin admin - - -] Delete snapshot failed, due to snapshot busy.: cinder.exception.SnapshotIsBusy: deleting snapshot snapshot-c7773cad-832a-4286-a60c-f79c76e41c9c that has dependent volumes
Jun 07 19:39:50 cloudcontrol1005 cinder-volume[3297194]: 2022-06-07 19:39:50.024 3297194 INFO cinder.message.api [req-93ddec16-9035-4ba6-abc4-bded5a5ebcbd novaadmin admin - - -] Creating message record for request_id = req-93ddec16-9035-4ba6-abc4-bded5a5ebcbd
Jun 07 19:39:50 cloudcontrol1005 cinder-volume[3297194]: 2022-06-07 19:39:50.355 3297194 INFO cinder.volume.manager [req-dcc0275d-1ecc-4b4b-a4b0-e688e1713a44 - - - - -] Trying to delete temp volume: 3e2506a8-a6e2-4140-9edd-b66299416c1a
Jun 07 19:39:51 cloudcontrol1005 cinder-volume[3297194]: 2022-06-07 19:39:51.240 3297194 INFO cinder.volume.manager [req-dcc0275d-1ecc-4b4b-a4b0-e688e1713a44 - - - - -] Deleted volume successfully.

sudo journalctl -u backup_cinder_volumes.service

Jun 06 17:17:06 cloudcontrol1005 wmcs-cinder-backup-manager[51132]: wmcs-cinder-backup-manager: 2022-06-06 17:17:06,246: INFO: Backing up ['8d687b46-03b8-4308-9b71-13704a664290'] in project maps
Jun 06 17:17:07 cloudcontrol1005 wmcs-cinder-backup-manager[867577]: wmcs-cinder-volume-backup: 2022-06-06 17:17:07,141: INFO: Backup up volume 8d687b46-03b8-4308-9b71-13704a664290
Jun 06 17:17:07 cloudcontrol1005 wmcs-cinder-backup-manager[867577]: wmcs-cinder-volume-backup: 2022-06-06 17:17:07,201: INFO: Full backup is available; doing incremental backup
Jun 06 17:17:07 cloudcontrol1005 wmcs-cinder-backup-manager[867577]: wmcs-cinder-volume-backup: 2022-06-06 17:17:07,202: INFO: Backup up from snapshot
Jun 06 17:17:07 cloudcontrol1005 wmcs-cinder-backup-manager[867577]: wmcs-cinder-volume-backup: 2022-06-06 17:17:07,511: INFO: current status is creating; waiting for it to change to ['available']
Jun 06 17:17:09 cloudcontrol1005 wmcs-cinder-backup-manager[867577]: wmcs-cinder-volume-backup: 2022-06-06 17:17:09,657: INFO: Just made snapshot c7773cad-832a-4286-a60c-f79c76e41c9c
Jun 06 17:17:09 cloudcontrol1005 wmcs-cinder-backup-manager[867577]: wmcs-cinder-volume-backup: 2022-06-06 17:17:09,836: INFO: Generating backup maps-2022-06-06T17:17:07.141689 (be627da3-3f95-4136-b885-945c7255436c)
Jun 06 17:17:09 cloudcontrol1005 wmcs-cinder-backup-manager[867577]: wmcs-cinder-volume-backup: 2022-06-06 17:17:09,897: INFO: current status is creating; waiting for it to change to ['available']
Jun 07 19:39:49 cloudcontrol1005 wmcs-cinder-backup-manager[867577]: wmcs-cinder-volume-backup: 2022-06-07 19:39:49,756: ERROR: Waiting for state ['available'] but state is error
Jun 07 19:39:49 cloudcontrol1005 wmcs-cinder-backup-manager[867577]: wmcs-cinder-volume-backup: 2022-06-07 19:39:49,757: INFO: Cleaning up snapshot c7773cad-832a-4286-a60c-f79c76e41c9c
Jun 07 19:39:49 cloudcontrol1005 wmcs-cinder-backup-manager[867577]: Traceback (most recent call last):
Jun 07 19:39:49 cloudcontrol1005 wmcs-cinder-backup-manager[867577]:   File "/usr/local/sbin/wmcs-cinder-volume-backup", line 244, in <module>
Jun 07 19:39:49 cloudcontrol1005 wmcs-cinder-backup-manager[867577]:     
Jun 07 19:39:49 cloudcontrol1005 wmcs-cinder-backup-manager[867577]:   File "/usr/local/sbin/wmcs-cinder-volume-backup", line 172, in backup_volume
Jun 07 19:39:49 cloudcontrol1005 wmcs-cinder-backup-manager[867577]:     logging.info("Generating backup %s (%s)" % (new_backup_name, self.backup_id))
Jun 07 19:39:49 cloudcontrol1005 wmcs-cinder-backup-manager[867577]:   File "/usr/local/sbin/wmcs-cinder-volume-backup", line 46, in wait_for_resource_status
Jun 07 19:39:49 cloudcontrol1005 wmcs-cinder-backup-manager[867577]:     )
Jun 07 19:39:49 cloudcontrol1005 wmcs-cinder-backup-manager[867577]: RuntimeError: Openstack resource be627da3-3f95-4136-b885-945c7255436c in error state.
Jun 07 19:39:49 cloudcontrol1005 wmcs-cinder-backup-manager[51132]: wmcs-cinder-backup-manager: 2022-06-07 19:39:49,996: WARNING: Failed to backup volume 8d687b46-03b8-4308-9b71-13704a664290
Jun 07 19:39:49 cloudcontrol1005 wmcs-cinder-backup-manager[51132]: wmcs-cinder-backup-manager: 2022-06-07 19:39:49,996: INFO: Purging old backups of 8d687b46-03b8-4308-9b71-13704a664290
Jun 07 19:39:50 cloudcontrol1005 wmcs-cinder-backup-manager[4015561]: wmcs-cinder-volume-backup: 2022-06-07 19:39:50,996: INFO: Purged 0 backups
Jun 07 19:39:51 cloudcontrol1005 wmcs-cinder-backup-manager[51132]: wmcs-cinder-backup-manager: 2022-06-07 19:39:51,079: ERROR: Got 2 errors, see logs for details.
Jun 07 19:39:51 cloudcontrol1005 systemd[1]: backup_cinder_volumes.service: Main process exited, code=exited, status=1/FAILURE
Jun 07 19:39:51 cloudcontrol1005 systemd[1]: backup_cinder_volumes.service: Failed with result 'exit-code'.

Event Timeline

Note, the sql timeout which occurred after just over 24 hours of realtime.

Leaving as-is with no planned follow-up unless it repeats.