I am running into a permission denied error with xtrabackup while attempting a full backup on a mysql replica server. The backup starts, runs for about 10 minutes backing up all of my tables, but then errors out.
backup-mysql.sh: Backup failure! Check /foo/backups/Thu/backup-progress.log for more information
Looking at the progress log file:
2023-10-05T09:27:14.234536-05:00 0 [Note] [MY-011825] [Xtrabackup] recognized client arguments: --user=backup --password=* --backup=1 --extra-lsndir=/foo/backups/Thu --compress --stream=xbstream --encrypt=AES256 --encrypt-key-file=/foo/backup_encryption_key --parallel=2 --compress-threads=2 --encrypt-threads=2 --slave-info=1 --no-server-version-check=1 --safe-slave-backup=1 --target-dir=/foo/backups/Thu
xtrabackup version 8.0.34-29 based on MySQL server 8.0.34 Linux (x86_64) (revision id: 5ba706ee)
231005 09:27:14 version_check Connecting to MySQL server with DSN 'dbi:mysql:;mysql_read_default_group=xtrabackup' as 'backup' (using password: YES).
231005 09:27:14 version_check Connected to MySQL server
231005 09:27:14 version_check Executing a version check against the server...
231005 09:27:14 version_check Done.
2023-10-05T09:27:14.330789-05:00 0 [Note] [MY-011825] [Xtrabackup] Connecting to MySQL server host: localhost, user: backup, password: set, port: not set, socket: not set
2023-10-05T09:27:14.355793-05:00 0 [Note] [MY-011825] [Xtrabackup] Using server version 8.0.34-0ubuntu0.20.04.1
2023-10-05T09:27:14.374161-05:00 0 [Note] [MY-011825] [Xtrabackup] Slave open temp tables: 0
2023-10-05T09:27:14.375200-05:00 0 [Note] [MY-011825] [Xtrabackup] Slave is safe to backup.
2023-10-05T09:27:14.375335-05:00 0 [Note] [MY-011825] [Xtrabackup] Executing LOCK INSTANCE FOR BACKUP ...
2023-10-05T09:27:14.377042-05:00 0 [Note] [MY-011825] [Xtrabackup] uses posix_fadvise().
2023-10-05T09:27:14.377077-05:00 0 [Note] [MY-011825] [Xtrabackup] cd to /var/lib/mysql/
2023-10-05T09:27:14.377090-05:00 0 [Note] [MY-011825] [Xtrabackup] open files limit requested 0, set to 1024
2023-10-05T09:27:14.409152-05:00 0 [Note] [MY-011825] [Xtrabackup] using the following InnoDB configuration:
2023-10-05T09:27:14.409176-05:00 0 [Note] [MY-011825] [Xtrabackup] innodb_data_home_dir = .
2023-10-05T09:27:14.409185-05:00 0 [Note] [MY-011825] [Xtrabackup] innodb_data_file_path = ibdata1:12M:autoextend
2023-10-05T09:27:14.409217-05:00 0 [Note] [MY-011825] [Xtrabackup] innodb_log_group_home_dir = ./
2023-10-05T09:27:14.409227-05:00 0 [Note] [MY-011825] [Xtrabackup] innodb_log_files_in_group = 2
2023-10-05T09:27:14.409239-05:00 0 [Note] [MY-011825] [Xtrabackup] innodb_log_file_size = 50331648
2023-10-05T09:27:14.414176-05:00 0 [Note] [MY-011825] [Xtrabackup] inititialize_service_handles suceeded
2023-10-05T09:27:14.623725-05:00 0 [Note] [MY-011825] [Xtrabackup] Connecting to MySQL server host: localhost, user: backup, password: set, port: not set, socket: not set
2023-10-05T09:27:14.629811-05:00 0 [Note] [MY-011825] [Xtrabackup] Redo Log Archiving is not set up.
2023-10-05T09:27:14.735445-05:00 0 [Note] [MY-011825] [Xtrabackup] Starting to parse redo log at lsn = 546279168587
2023-10-05T09:27:14.737736-05:00 0 [Note] [MY-012564] [InnoDB] Recovery parsing buffer extended to 4194304.
2023-10-05T09:27:14.831536-05:00 1 [Note] [MY-011825] [Xtrabackup] >> log scanned up to (546282501411)
2023-10-05T09:27:14.833799-05:00 0 [Note] [MY-012953] [InnoDB] Disabling background ibuf IO read threads.
2023-10-05T09:27:15.036026-05:00 0 [Note] [MY-011825] [Xtrabackup] Generating a list of tablespaces
2023-10-05T09:27:15.036083-05:00 0 [Note] [MY-012204] [InnoDB] Scanning './'
2023-10-05T09:27:15.037665-05:00 0 [Note] [MY-012208] [InnoDB] Completed space ID check of 2 files.
2023-10-05T09:27:15.039374-05:00 0 [Warning] [MY-012091] [InnoDB] Allocated tablespace ID 1 for sys/sys_config, old maximum was 0
2023-10-05T09:27:15.097423-05:00 0 [Note] [MY-013252] [InnoDB] Using undo tablespace './undo_001'.
2023-10-05T09:27:15.098605-05:00 0 [Note] [MY-013252] [InnoDB] Using undo tablespace './undo_002'.
2023-10-05T09:27:15.100116-05:00 0 [Note] [MY-012910] [InnoDB] Opened 2 existing undo tablespaces.
2023-10-05T09:27:15.100155-05:00 0 [Note] [MY-011825] [Xtrabackup] Starting 2 threads for parallel data files transfer
2023-10-05T09:27:15.100462-05:00 2 [Note] [MY-011825] [Xtrabackup] Compressing, encrypting and streaming ./somedb/tb1.ibd
2023-10-05T09:27:15.103852-05:00 3 [Note] [MY-011825] [Xtrabackup] Compressing, encrypting and streaming ./somedb/tb2.ibd
...
...
2023-10-05T09:37:26.025576-05:00 1 [Note] [MY-011825] [Xtrabackup] >> log scanned up to (546282501411)
2023-10-05T09:37:27.025785-05:00 1 [Note] [MY-011825] [Xtrabackup] >> log scanned up to (546282501411)
2023-10-05T09:37:27.825122-05:00 2 [Note] [MY-011825] [Xtrabackup] Done: Compressing, encrypting and streaming ./somedb/tb45.ibd
2023-10-05T09:37:28.025977-05:00 1 [Note] [MY-011825] [Xtrabackup] >> log scanned up to (546282501411)
2023-10-05T09:37:28.191270-05:00 0 [Note] [MY-011825] [Xtrabackup] Executing FLUSH NO_WRITE_TO_BINLOG TABLES...
2023-10-05T09:37:28.192786-05:00 0 [Note] [MY-011825] [Xtrabackup] Executing FLUSH TABLES WITH READ LOCK...
2023-10-05T09:37:28.192989-05:00 0 [Note] [MY-011825] [Xtrabackup] Starting to backup non-InnoDB tables and files
2023-10-05T09:37:28.196101-05:00 4 [Note] [MY-011825] [Xtrabackup] Compressing, encrypting and streaming performance_schema/replication_conn_2716.sdi to <STDOUT>
...
...
2023-10-05T09:37:28.383917-05:00 4 [Note] [MY-011825] [Xtrabackup] Done: Compressing, encrypting and streaming mysql/slow_log.CSM to <STDOUT>
2023-10-05T09:37:28.383948-05:00 5 [Note] [MY-011825] [Xtrabackup] Done: Compressing, encrypting and streaming mysql/general_log_2968.sdi to <STDOUT>
2023-10-05T09:37:28.385345-05:00 4 [Note] [MY-011825] [Xtrabackup] Compressing, encrypting and streaming mysql/general_log.CSV to <STDOUT>
2023-10-05T09:37:28.385395-05:00 4 [Note] [MY-011825] [Xtrabackup] Done: Compressing, encrypting and streaming mysql/general_log.CSV to <STDOUT>
2023-10-05T09:37:28.386873-05:00 4 [Note] [MY-011825] [Xtrabackup] Compressing, encrypting and streaming mysql/event.MYI to <STDOUT>
2023-10-05T09:37:28.387440-05:00 4 [Note] [MY-011825] [Xtrabackup] Done: Compressing, encrypting and streaming mysql/event.MYI to <STDOUT>
2023-10-05T09:37:28.388922-05:00 4 [Note] [MY-011825] [Xtrabackup] Compressing, encrypting and streaming mysql/slow_log.CSV to <STDOUT>
2023-10-05T09:37:28.388984-05:00 4 [Note] [MY-011825] [Xtrabackup] Done: Compressing, encrypting and streaming mysql/slow_log.CSV to <STDOUT>
2023-10-05T09:37:28.390482-05:00 5 [Note] [MY-011825] [Xtrabackup] Compressing, encrypting and streaming mysql/event_2528.sdi to <STDOUT>
2023-10-05T09:37:28.391038-05:00 5 [Note] [MY-011825] [Xtrabackup] Done: Compressing, encrypting and streaming mysql/event_2528.sdi to <STDOUT>
2023-10-05T09:37:28.395823-05:00 0 [Note] [MY-011825] [Xtrabackup] Finished backing up non-InnoDB tables and files
2023-10-05T09:37:28.395854-05:00 0 [Note] [MY-011825] [Xtrabackup] Executing FLUSH NO_WRITE_TO_BINLOG BINARY LOGS
2023-10-05T09:37:28.405272-05:00 0 [Note] [MY-011825] [Xtrabackup] Selecting LSN and binary log position from p_s.log_status
xtrabackup: File '/var/log/mysql/mysql-bin.000876' not found (OS errno 13 - Permission denied)
2023-10-05T09:37:28.413151-05:00 0 [ERROR] [MY-011825] [Xtrabackup] copy_file() failed.
The xtrabackup version command output is as follows:
# xtrabackup --version
[Note] [MY-011825] [Xtrabackup] recognized server arguments: --datadir=/var/lib/mysql --innodb_buffer_pool_size=3G --server-id=3 --log_bin=/var/log/mysql/mysql-bin.log
xtrabackup version 8.0.34-29 based on MySQL server 8.0.34 Linux (x86_64) (revision id: 5ba706ee)
Any idea what could be causing the issue? The user running the backup is in a group that has read access over the /var/log/mysql/mysql-bin.000876 file.
-rw-r----- 1 mysql mysql 104864781 Oct 5 09:42 mysql-bin.000876