Hi Matthew,
Nothing in the debug logs, I tried to isolate the issue and this is where I’m at now.
When I do PXB with single database (delta_sap_qa) everything works as expected,
xtrabackup --backup --databases=‘delta_sap_qa’ --compress --compress-threads=4 --target-dir=/backups/databases/physical/sunday_full/
Below is extract of the log file proving that there is no issue with Vault and decryption.
2024-06-05T08:53:37.457715+02:00 0 [Note] [MY-011825] [Xtrabackup] recognized server arguments: --datadir=/mysqldata --innodb_flush_method=O_DIRECT --innodb_log_files_in_group=2 --innodb_log_file_size=1G --innodb_flush_log_at_trx_commit=1 --innodb_file_per_table=1 --innodb_buffer_pool_size=16G --log_bin=mysql-bin --server-id=1 --open_files_limit=65535
2024-06-05T08:53:37.457982+02:00 0 [Note] [MY-011825] [Xtrabackup] recognized client arguments: --backup=1 --databases=delta_sap_qa --compress --compress-threads=4 --target-dir=/backups/databases/physical/sunday_full/ --user=pxbackup --password=*
xtrabackup version 8.0.35-30 based on MySQL server 8.0.35 Linux (x86_64) (revision id: 6beb4b49)
240605 08:53:37 version_check Connecting to MySQL server with DSN ‘dbi:mysql:;mysql_read_default_group=xtrabackup’ as ‘pxbackup’ (using password: YES).
240605 08:53:37 version_check Connected to MySQL server
240605 08:53:37 version_check Executing a version check against the server…
240605 08:53:37 version_check Done.
2024-06-05T08:53:37.548873+02:00 0 [Note] [MY-011825] [Xtrabackup] Connecting to MySQL server host: localhost, user: pxbackup, password: set, port: not set, socket: not set
2024-06-05T08:53:37.555508+02:00 0 [Note] [MY-011825] [Xtrabackup] Using server version 8.0.35-27
2024-06-05T08:53:37.592460+02:00 0 [Note] [MY-011825] [Xtrabackup] Executing LOCK TABLES FOR BACKUP …
2024-06-05T08:53:37.596348+02:00 0 [Note] [MY-011825] [Xtrabackup] uses posix_fadvise().
2024-06-05T08:53:37.596461+02:00 0 [Note] [MY-011825] [Xtrabackup] cd to /mysqldata
2024-06-05T08:53:37.596537+02:00 0 [Note] [MY-011825] [Xtrabackup] open files limit requested 65535, set to 65535
2024-06-05T08:53:37.908957+02:00 0 [Note] [MY-011825] [Xtrabackup] using the following InnoDB configuration:
2024-06-05T08:53:37.909000+02:00 0 [Note] [MY-011825] [Xtrabackup] innodb_data_home_dir = .
2024-06-05T08:53:37.909174+02:00 0 [Note] [MY-011825] [Xtrabackup] innodb_data_file_path = ibdata1:12M:autoextend
2024-06-05T08:53:37.909249+02:00 0 [Note] [MY-011825] [Xtrabackup] innodb_log_group_home_dir = ./
2024-06-05T08:53:37.909261+02:00 0 [Note] [MY-011825] [Xtrabackup] innodb_log_files_in_group = 2
2024-06-05T08:53:37.909364+02:00 0 [Note] [MY-011825] [Xtrabackup] innodb_log_file_size = 1073741824
2024-06-05T08:53:37.909427+02:00 0 [Note] [MY-011825] [Xtrabackup] using O_DIRECT
2024-06-05T08:53:37.911313+02:00 0 [Note] [MY-011825] [Xtrabackup] Added plugin ‘keyring_vault.so’ to load list.
2024-06-05T08:53:37.930232+02:00 0 [Note] [MY-011825] [Xtrabackup] inititialize_service_handles suceeded
2024-06-05T08:53:38.007301+02:00 0 [Note] [MY-011825] [Xtrabackup] Connecting to MySQL server host: localhost, user: pxbackup, password: set, port: not set, socket: not set
2024-06-05T08:53:38.011558+02:00 0 [Note] [MY-011825] [Xtrabackup] Redo Log Archiving is not set up.
2024-06-05T08:53:38.111993+02:00 0 [Note] [MY-011825] [Xtrabackup] Starting to parse redo log at lsn = 1189845649521
2024-06-05T08:53:38.113484+02:00 0 [Note] [MY-012564] [InnoDB] Recovery parsing buffer extended to 4194304.
2024-06-05T08:53:38.114905+02:00 0 [Note] [MY-012564] [InnoDB] Recovery parsing buffer extended to 8388608.
2024-06-05T08:53:38.594500+02:00 1 [Note] [MY-011825] [Xtrabackup] >> log scanned up to (1190011941336)
2024-06-05T08:53:39.595486+02:00 1 [Note] [MY-011825] [Xtrabackup] >> log scanned up to (1190011954383)
2024-06-05T08:53:39.803999+02:00 0 [Note] [MY-012953] [InnoDB] Disabling background ibuf IO read threads.
2024-06-05T08:53:40.006587+02:00 0 [Note] [MY-011825] [Xtrabackup] Generating a list of tablespaces
2024-06-05T08:53:40.006672+02:00 0 [Note] [MY-012204] [InnoDB] Scanning ‘./’
2024-06-05T08:53:40.115561+02:00 0 [Note] [MY-012207] [InnoDB] Using 4 threads to scan 28684 tablespace files
2024-06-05T08:53:40.118331+02:00 0 [Note] [MY-012208] [InnoDB] Completed space ID check of 2 files.
2024-06-05T08:53:40.129102+02:00 0 [Warning] [MY-012091] [InnoDB] Allocated tablespace ID 22335 for delta_sap_qa/tmp_log, old maximum was 0
2024-06-05T08:53:40.151007+02:00 0 [Note] [MY-013252] [InnoDB] Using undo tablespace ‘./undo_001’.
2024-06-05T08:53:40.155448+02:00 0 [Note] [MY-013252] [InnoDB] Using undo tablespace ‘./undo_002’.
2024-06-05T08:53:40.157103+02:00 0 [Note] [MY-012910] [InnoDB] Opened 2 existing undo tablespaces.
2024-06-05T08:53:40.157893+02:00 2 [Note] [MY-011825] [Xtrabackup] Compressing ./ibdata1 to /backups/databases/physical/sunday_full/ibdata1.zst
2024-06-05T08:53:40.596027+02:00 1 [Note] [MY-011825] [Xtrabackup] >> log scanned up to (1190012008255)
2024-06-05T08:53:41.454191+02:00 2 [Note] [MY-011825] [Xtrabackup] Done: Compressing ./ibdata1 to /backups/databases/physical/sunday_full/ibdata1.zst
2024-06-05T08:53:41.472221+02:00 2 [Note] [MY-011825] [Xtrabackup] Compressing ./delta_sap_qa/api_log.ibd to /backups/databases/physical/sunday_full/delta_sap_qa/api_log.ibd
…
2024-06-05T08:53:45.278308+02:00 0 [Note] [MY-011825] [Xtrabackup] Compressing /backups/databases/physical/sunday_full/mysql-bin.index.zst
2024-06-05T08:53:45.278343+02:00 0 [Note] [MY-011825] [Xtrabackup] Done: Compressing file /backups/databases/physical/sunday_full/mysql-bin.index.zst
2024-06-05T08:53:45.281461+02:00 0 [Note] [MY-011825] [Xtrabackup] Compressing /backups/databases/physical/sunday_full/xtrabackup_binlog_info.zst
2024-06-05T08:53:45.281507+02:00 0 [Note] [MY-011825] [Xtrabackup] Done: Compressing file /backups/databases/physical/sunday_full/xtrabackup_binlog_info.zst
2024-06-05T08:53:45.282570+02:00 0 [Note] [MY-011825] [Xtrabackup] Executing FLUSH NO_WRITE_TO_BINLOG ENGINE LOGS…
2024-06-05T08:53:45.283819+02:00 0 [Note] [MY-011825] [Xtrabackup] The latest check point (for incremental): ‘1189847317178’
2024-06-05T08:53:45.283845+02:00 0 [Note] [MY-011825] [Xtrabackup] Stopping log copying thread at LSN 1190014683250
2024-06-05T08:53:45.284419+02:00 1 [Note] [MY-011825] [Xtrabackup] >> log scanned up to (1190014683821)
2024-06-05T08:53:46.303262+02:00 0 [Note] [MY-011825] [Xtrabackup] Executing UNLOCK TABLES
2024-06-05T08:53:46.303432+02:00 0 [Note] [MY-011825] [Xtrabackup] All tables unlocked
2024-06-05T08:53:46.303531+02:00 0 [Note] [MY-011825] [Xtrabackup] Compressing ib_buffer_pool to /backups/databases/physical/sunday_full/ib_buffer_pool.zst
2024-06-05T08:53:46.317353+02:00 0 [Note] [MY-011825] [Xtrabackup] Done: Compressing ib_buffer_pool to /backups/databases/physical/sunday_full/ib_buffer_pool.zst
2024-06-05T08:53:46.319455+02:00 0 [Note] [MY-011825] [Xtrabackup] Backup created in directory ‘/backups/databases/physical/sunday_full/’
2024-06-05T08:53:46.319480+02:00 0 [Note] [MY-011825] [Xtrabackup] MySQL binlog position: filename ‘mysql-bin.000691’, position ‘935’
2024-06-05T08:53:46.319597+02:00 0 [Note] [MY-011825] [Xtrabackup] Compressing /backups/databases/physical/sunday_full/backup-my.cnf.zst
2024-06-05T08:53:46.319632+02:00 0 [Note] [MY-011825] [Xtrabackup] Done: Compressing file /backups/databases/physical/sunday_full/backup-my.cnf.zst
2024-06-05T08:53:46.321644+02:00 0 [Note] [MY-011825] [Xtrabackup] Compressing /backups/databases/physical/sunday_full/xtrabackup_info.zst
2024-06-05T08:53:46.321678+02:00 0 [Note] [MY-011825] [Xtrabackup] Done: Compressing file /backups/databases/physical/sunday_full/xtrabackup_info.zst
2024-06-05T08:53:47.324127+02:00 0 [Note] [MY-011825] [Xtrabackup] Transaction log of lsn (1189845584592) to (1190018139793) was copied.
2024-06-05T08:53:47.532170+02:00 0 [Note] [MY-010733] [Server] Shutting down plugin ‘keyring_vault’
2024-06-05T08:53:47.532235+02:00 0 [Note] [MY-010733] [Server] Shutting down plugin ‘daemon_keyring_proxy_plugin’
2024-06-05T08:53:47.535337+02:00 0 [Note] [MY-011825] [Xtrabackup] completed OK!
Next PXB backup with single database (delta_sap_afdis)
xtrabackup --backup --databases=‘delta_sap_afdis’ --compress --compress-threads=4 --target-dir=/backups/databases/physical/sunday_full/
Works as expected same as above logs.
Running PXB with multiple databases
xtrabackup --backup --databases=‘delta_sap_qa delta_sap_afdis’ --compress --compress-threads=4 --target-dir=/backups/databases/physical/sunday_full/
When combining the two databases (delta_sap_qa+delta_sap_afdis) Vault is failing with the below
2024-06-05T08:58:43.861638+02:00 0 [Note] [MY-011825] [Xtrabackup] recognized server arguments: --datadir=/mysqldata --innodb_flush_method=O_DIRECT --innodb_log_files_in_group=2 --innodb_log_file_size=1G --innodb_flush_log_at_trx_commit=1 --innodb_file_per_table=1 --innodb_buffer_pool_size=16G --log_bin=mysql-bin --server-id=1 --open_files_limit=65535
2024-06-05T08:58:43.861789+02:00 0 [Note] [MY-011825] [Xtrabackup] recognized client arguments: --backup=1 --databases=delta_sap_qa delta_sap_afdis --compress --compress-threads=4 --target-dir=/backups/databases/physical/sunday_full/ --user=pxbackup --password=*
xtrabackup version 8.0.35-30 based on MySQL server 8.0.35 Linux (x86_64) (revision id: 6beb4b49)
240605 08:58:43 version_check Connecting to MySQL server with DSN ‘dbi:mysql:;mysql_read_default_group=xtrabackup’ as ‘pxbackup’ (using password: YES).
240605 08:58:43 version_check Connected to MySQL server
240605 08:58:43 version_check Executing a version check against the server…
240605 08:58:43 version_check Done.
2024-06-05T08:58:43.961418+02:00 0 [Note] [MY-011825] [Xtrabackup] Connecting to MySQL server host: localhost, user: pxbackup, password: set, port: not set, socket: not set
2024-06-05T08:58:43.967849+02:00 0 [Note] [MY-011825] [Xtrabackup] Using server version 8.0.35-27
2024-06-05T08:58:43.987951+02:00 0 [Note] [MY-011825] [Xtrabackup] Executing LOCK TABLES FOR BACKUP …
2024-06-05T08:58:43.989870+02:00 0 [Note] [MY-011825] [Xtrabackup] uses posix_fadvise().
2024-06-05T08:58:43.989904+02:00 0 [Note] [MY-011825] [Xtrabackup] cd to /mysqldata
2024-06-05T08:58:43.989923+02:00 0 [Note] [MY-011825] [Xtrabackup] open files limit requested 65535, set to 65535
2024-06-05T08:58:44.280669+02:00 0 [Note] [MY-011825] [Xtrabackup] using the following InnoDB configuration:
2024-06-05T08:58:44.280713+02:00 0 [Note] [MY-011825] [Xtrabackup] innodb_data_home_dir = .
2024-06-05T08:58:44.280722+02:00 0 [Note] [MY-011825] [Xtrabackup] innodb_data_file_path = ibdata1:12M:autoextend
2024-06-05T08:58:44.280749+02:00 0 [Note] [MY-011825] [Xtrabackup] innodb_log_group_home_dir = ./
2024-06-05T08:58:44.280760+02:00 0 [Note] [MY-011825] [Xtrabackup] innodb_log_files_in_group = 2
2024-06-05T08:58:44.280771+02:00 0 [Note] [MY-011825] [Xtrabackup] innodb_log_file_size = 1073741824
2024-06-05T08:58:44.280780+02:00 0 [Note] [MY-011825] [Xtrabackup] using O_DIRECT
2024-06-05T08:58:44.282606+02:00 0 [Note] [MY-011825] [Xtrabackup] Added plugin ‘keyring_vault.so’ to load list.
2024-06-05T08:58:44.299918+02:00 0 [Note] [MY-011825] [Xtrabackup] inititialize_service_handles suceeded
2024-06-05T08:58:44.390866+02:00 0 [Note] [MY-011825] [Xtrabackup] Connecting to MySQL server host: localhost, user: pxbackup, password: set, port: not set, socket: not set
2024-06-05T08:58:44.396345+02:00 0 [Note] [MY-011825] [Xtrabackup] Redo Log Archiving is not set up.
2024-06-05T08:58:44.495340+02:00 0 [Note] [MY-011825] [Xtrabackup] Starting to parse redo log at lsn = 1189991165524
2024-06-05T08:58:44.496848+02:00 0 [Note] [MY-012564] [InnoDB] Recovery parsing buffer extended to 4194304.
2024-06-05T08:58:44.498332+02:00 0 [Note] [MY-012564] [InnoDB] Recovery parsing buffer extended to 8388608.
2024-06-05T08:58:45.245660+02:00 1 [Note] [MY-011825] [Xtrabackup] >> log scanned up to (1190221560208)
2024-06-05T08:58:46.249797+02:00 1 [Note] [MY-011825] [Xtrabackup] >> log scanned up to (1190222386829)
2024-06-05T08:58:46.450063+02:00 0 [Note] [MY-012953] [InnoDB] Disabling background ibuf IO read threads.
2024-06-05T08:58:46.654134+02:00 0 [Note] [MY-011825] [Xtrabackup] Generating a list of tablespaces
2024-06-05T08:58:46.654202+02:00 0 [Note] [MY-012204] [InnoDB] Scanning ‘./’
2024-06-05T08:58:46.766517+02:00 0 [Note] [MY-012207] [InnoDB] Using 4 threads to scan 28684 tablespace files
2024-06-05T08:58:46.767604+02:00 0 [Note] [MY-012208] [InnoDB] Completed space ID check of 2 files.
2024-06-05T08:58:46.784869+02:00 0 [System] [MY-011197] [InnoDB] Plugin keyring_vault reported: ‘Vault Server response does not have “data” member’
2024-06-05T08:58:46.784917+02:00 0 [System] [MY-011197] [InnoDB] Plugin keyring_vault reported: ‘Could not read key from Vault. Vault has returned the following error(s): permission denied’
2024-06-05T08:58:46.784936+02:00 0 [Note] [MY-011825] [InnoDB] Encryption information in datafile: ./delta_sap_afdis/plant.ibd can’t be decrypted, please confirm that keyring is loaded.
…
2024-06-05T08:58:52.294724+02:00 0 [Note] [MY-011825] [Xtrabackup] The latest check point (for incremental): ‘1189992872023’
2024-06-05T08:58:52.294752+02:00 0 [Note] [MY-011825] [Xtrabackup] Stopping log copying thread at LSN 1190229118932
2024-06-05T08:58:52.300792+02:00 0 [ERROR] [MY-011825] [Xtrabackup] Space ID 23973 is missing encryption information.
2024-06-05T08:58:52.300824+02:00 0 [ERROR] [MY-011825] [Xtrabackup] Space ID 22335 is missing encryption information.
2024-06-05T08:58:52.300831+02:00 0 [ERROR] [MY-011825] [Xtrabackup] Space ID 22331 is missing encryption information.
2024-06-05T08:58:52.300836+02:00 0 [ERROR] [MY-011825] [Xtrabackup] Space ID 23976 is missing encryption information.
2024-06-05T08:58:52.300841+02:00 0 [ERROR] [MY-011825] [Xtrabackup] Space ID 22321 is missing encryption information.
2024-06-05T08:58:52.300847+02:00 0 [ERROR] [MY-011825] [Xtrabackup] Space ID 23958 is missing encryption information.
2024-06-05T08:58:52.300851+02:00 0 [ERROR] [MY-011825] [Xtrabackup] Space ID 22334 is missing encryption information.
2024-06-05T08:58:52.300856+02:00 0 [ERROR] [MY-011825] [Xtrabackup] Space ID 23972 is missing encryption information.
2024-06-05T08:58:52.300861+02:00 0 [ERROR] [MY-011825] [Xtrabackup] Space ID 22330 is missing encryption information.
I’m only using the --database option to debug problem as we have over 80 databases that needs to be backed up.