log level verbosde hard coded

[JasperAlgra]

I've noticed since version 1.5.5 the --verbose flag only logs INFO to the console, even when level is set to DEBUG.

Is this suppose to happen? If so I can update the documentation. This is also related to my other issue #382

I think it would be better to let the log level be set both for file-logging and console-logging, so a user can check on their preferred output.

MySQL-AutoXtraBackup/autoxtrabackup.py

Line 200 in 51afdd4

ch.setLevel(logging.INFO)

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

[ShahriyarR]

Hmmm yes, there is an inconsistency.
What do you advise for both issues?

[JasperAlgra]

I'd say regarding the logging; let both the logfile and the console logging be set with the same log level. Or create two log levels (e.g. file_loglevel and console_loglevel), maybe that would suite everyone (in case you want simple log to the console but very verbose debug in a file or so).

I can make a PR for this if you like, what do you prefer?

• let the console and file level both be set by one loglevel
• have two seperate loglevels for file and console

Regarding the other issue I have to do some digging. That will be a bit of a challenge on windows so i'll let you know if I can debug it.

[ShahriyarR]

Well, for me making them both the same is somehow more elegant.
It will not require an extra argument as well. Let's make them both the same with a single option/argument.

[gitmstoute]

Hey guys,
I just noticed this issue, and my PR #390 touches a small part of it too.
For my 2 cents, I think we should just not have a 'verbose' option; it seems like 2 different ways to set log-level, and we should only have 1 way (Specify log-level via config or command line param: -l DEBUG, log= in config).