Exit with error (no backup) but still logging falsly 'completed successfully'

[JasperAlgra]

Hi all,

I'm trying to run autoxtrabackup in a cron and thus I'm doublechecking all outcomes and trying to find a way to monitor good/bad results.

When the command below the console echos "Autoxtrabackup completed successfully!" but when checking the log file you can see "error: cannot open /mnt/backup/backups/inc/2020-03-11_13-13-19//xtrabackup" So, without loglevel set to DEBUG and without checking the log file you won't notice the backups failing.

command: /usr/local/bin/autoxtrabackup -l DEBUG -lf /mnt/backup/autoxtrabackup.log --backup

Output from console:

2020-03-11 13:13:16 INFO [check_env:49] Running mysqladmin command -> /usr/bin/mysqladmin --defaults-file=/etc/mysql/my.cnf --user=backup --password='*' status --socket=/var/run/mysqld/mysqld.sock
2020-03-11 13:13:16 INFO [check_env:54] OK: Server is Up and running
2020-03-11 13:13:16 INFO [check_env:81] OK: /usr/bin/mysql exists
2020-03-11 13:13:16 INFO [check_env:93] OK: /usr/bin/mysqladmin exists
2020-03-11 13:13:16 INFO [check_env:72] OK: MySQL configuration file exists
2020-03-11 13:13:16 INFO [check_env:105] OK: XtraBackup exists
2020-03-11 13:13:16 INFO [check_env:118] OK: Main backup directory exists
2020-03-11 13:13:16 INFO [check_env:162] OK: Full Backup directory exists
2020-03-11 13:13:16 INFO [check_env:182] OK: Increment directory exists
2020-03-11 13:13:16 INFO [check_env:140] OK: Archive folder directory exists
2020-03-11 13:13:16 INFO [check_env:215] OK: Check status
2020-03-11 13:13:16 INFO [backuper:747] - - - - You have a full backup that is less than 86400.0 seconds old. - - - -
2020-03-11 13:13:16 INFO [backuper:748] - - - - We will take an incremental one based on recent Full Backup - - - -
2020-03-11 13:13:19 INFO [process_runner:45] SUBPROCESS STARTING: /usr/bin/xtrabackup --defaults-file=/etc/mysql/my.cnf --user=backup --password='*'  --target-dir=/mnt/backup/backups/inc/2020-03-11_13-13-19 --incremental-basedir=/mnt/backup/backups/inc/2020-03-11_13-13-01 --backup --socket=/var/run/mysqld/mysqld.sock
2020-03-11 13:13:19 INFO [process_runner:52] SUBPROCESS /usr/bin/xtrabackup COMPLETED with exit code: 1
2020-03-11 13:13:19 INFO [backuper:47] TAGGING SKIPPED
2020-03-11 13:13:19 INFO [autoxtrabackup:335] Xtrabackup command history:
2020-03-11 13:13:19 INFO [autoxtrabackup:337] ['command', 'xtrabackup_function', 'start time', 'end time', 'duration', 'exit code']
2020-03-11 13:13:19 INFO [autoxtrabackup:337] ['xtrabackup', 'backup', '2020-03-11 13:13:19', '2020-03-11 13:13:19', '0s', 1]
2020-03-11 13:13:19 INFO [autoxtrabackup:338] Autoxtrabackup completed successfully!

Output in logfile:

2020-03-11 13:15:29 DEBUG [__init__:77] <pid.PidFile object at 0x7f69fc07a938> entering setup
2020-03-11 13:15:29 DEBUG [__init__:170] <pid.PidFile object at 0x7f69fc07a938> create pidfile: /tmp/MySQL-AutoXtraBackup/autoxtrabackup.pid
2020-03-11 13:15:29 DEBUG [__init__:157] <pid.PidFile object at 0x7f69fc07a938> check pidfile: /tmp/MySQL-AutoXtraBackup/autoxtrabackup.pid
2020-03-11 13:15:29 INFO [check_env:49] Running mysqladmin command -> /usr/bin/mysqladmin --defaults-file=/etc/mysql/my.cnf --user=backup --password='*' status --socket=/var/run/mysqld/mysqld.sock
2020-03-11 13:15:29 INFO [check_env:54] OK: Server is Up and running
2020-03-11 13:15:29 INFO [check_env:81] OK: /usr/bin/mysql exists
2020-03-11 13:15:29 INFO [check_env:93] OK: /usr/bin/mysqladmin exists
2020-03-11 13:15:29 INFO [check_env:72] OK: MySQL configuration file exists
2020-03-11 13:15:29 INFO [check_env:105] OK: XtraBackup exists
2020-03-11 13:15:29 INFO [check_env:118] OK: Main backup directory exists
2020-03-11 13:15:29 INFO [check_env:162] OK: Full Backup directory exists
2020-03-11 13:15:29 INFO [check_env:182] OK: Increment directory exists
2020-03-11 13:15:29 INFO [check_env:140] OK: Archive folder directory exists
2020-03-11 13:15:29 INFO [check_env:215] OK: Check status
2020-03-11 13:15:29 INFO [backuper:747] - - - - You have a full backup that is less than 86400.0 seconds old. - - - -
2020-03-11 13:15:29 INFO [backuper:748] - - - - We will take an incremental one based on recent Full Backup - - - -
2020-03-11 13:15:32 DEBUG [backuper:675] Starting /usr/bin/xtrabackup
2020-03-11 13:15:32 INFO [process_runner:45] SUBPROCESS STARTING: /usr/bin/xtrabackup --defaults-file=/etc/mysql/my.cnf --user=backup --password='*'  --target-dir=/mnt/backup/backups/inc/2020-03-11_13-15-32 --incremental-basedir=/mnt/backup/backups/inc/2020-03-11_13-13-19 --backup --socket=/var/run/mysqld/mysqld.sock
2020-03-11 13:15:32 DEBUG [process_runner:86] subprocess args are: ['/usr/bin/xtrabackup', '--defaults-file=/etc/mysql/my.cnf', '--user=backup', '--password=xMUNRMM4mjXUQ7Rm', '--target-dir=/mnt/backup/backups/inc/2020-03-11_13-15-32', '--incremental-basedir=/mnt/backup/backups/inc/2020-03-11_13-13-19', '--backup', '--socket=/var/run/mysqld/mysqld.sock']
2020-03-11 13:15:32 DEBUG [process_runner:51] [/usr/bin/xtrabackup:3996] xtrabackup: recognized server arguments: --datadir=/var/lib/mysql --tmpdir=/tmp --server-id=1209327 --open_files_limit=65535 --innodb_flush_method=O_DIRECT --innodb_log_files_in_group=2 --innodb_file_per_table=1 --innodb_buffer_pool_size=10G --parallel=4
2020-03-11 13:15:32 DEBUG [process_runner:51] [/usr/bin/xtrabackup:3996] xtrabackup: recognized client arguments: --port=3306 --socket=/var/run/mysqld/mysqld.sock --user=root --compress-threads=4 --rebuild_threads=4 --user=root --user=backup --password=* --target-dir=/mnt/backup/backups/inc/2020-03-11_13-15-32 --incremental-basedir=/mnt/backup/backups/inc/2020-03-11_13-13-19 --backup=1 --socket=/var/run/mysqld/mysqld.sock
2020-03-11 13:15:32 DEBUG [process_runner:51] [/usr/bin/xtrabackup:3996] xtrabackup: Error: cannot open /mnt/backup/backups/inc/2020-03-11_13-13-19//xtrabackup_checkpoints
2020-03-11 13:15:32 DEBUG [process_runner:51] [/usr/bin/xtrabackup:3996] xtrabackup: error: failed to read metadata from /mnt/backup/backups/inc/2020-03-11_13-13-19//xtrabackup_checkpoints
2020-03-11 13:15:32 INFO [process_runner:52] SUBPROCESS /usr/bin/xtrabackup COMPLETED with exit code: 1
2020-03-11 13:15:32 INFO [backuper:47] TAGGING SKIPPED
2020-03-11 13:15:32 DEBUG [__init__:197] <pid.PidFile object at 0x7f69fc07a938> closing pidfile: /tmp/MySQL-AutoXtraBackup/autoxtrabackup.pid
2020-03-11 13:15:32 INFO [autoxtrabackup:335] Xtrabackup command history:
2020-03-11 13:15:32 INFO [autoxtrabackup:337] ['command', 'xtrabackup_function', 'start time', 'end time', 'duration', 'exit code']
2020-03-11 13:15:32 INFO [autoxtrabackup:337] ['xtrabackup', 'backup', '2020-03-11 13:15:32', '2020-03-11 13:15:32', '0s', 1]
2020-03-11 13:15:32 INFO [autoxtrabackup:338] Autoxtrabackup completed successfully!
2020-03-11 13:15:32 DEBUG [__init__:197] <pid.PidFile object at 0x7f69fc07a938> closing pidfile: /tmp/MySQL-AutoXtraBackup/autoxtrabackup.pid

[gitmstoute]

@JasperAlgra Can you confirm which version you got this result from? I assume 1.5.5?

[JasperAlgra]

@gitmstoute yes, sorry for not mentioning that. It's the latest (1.5.5)

root@dev:~# autoxtrabackup --version
Developed by Shahriyar Rzayev from Azerbaijan MUG(http://mysql.az)
Link : https://github.com/ShahriyarR/MySQL-AutoXtraBackup
Email: rzayev.shahriyar@yandex.com
Based on Percona XtraBackup: https://github.com/percona/percona-xtrabackup/
MySQL-AutoXtraBackup Version: 1.5.5

[gitmstoute]

@JasperAlgra I suspect, if you want to get moving immediately, all you need to do is comment out everything in the [xbstream] section of autoxtrabackup configs.

[ShahriyarR]

@gitmstoute for the new release it was disabled by default as far as I see.

[ShahriyarR]

@JasperAlgra Merged the proposed fix for this issue into release_v2.0 branch.