incremental backup fails via cronjob but works manually

[arndtt]

Hi,

we are using ZRM for MySQL Community Edition - version 2.2.0 on a CentOS 6 system in order to backup several remote databases. Tried to activate some incremental backups additionally to the already working full backups which is working fine if i do this manually as user mysql ( ssh without password is not the issue here) but via cronjob it fails. I guess I'm having an environment variable problem here when I look at the timestamps of the logfiles ( Do Okt 31 manual via cronjob Thu Oct 31 ). As I mentioned the manual approach and the crontab is in the same mysql user account. Is it possible that via cron half of the environment is loaded ?

Best Regards,

Tobias


################################################## ############

when I start the backup manually via mysql-zrm-scheduler --now --backup-set fcsv046 --backup-level 1

Do Okt 31 09:01:54 2013: fcsv046:backup:INFO: START OF BACKUP
Do Okt 31 09:01:54 2013: fcsv046:backup:INFO: PHASE START: Initialization
Do Okt 31 09:01:54 2013: fcsv046:backup:INFO: The quick backup-type is supported only for snapshot backups. Setting backup-type to 'regular'
Do Okt 31 09:01:54 2013: fcsv046:backup:INFO: backup-set=fcsv046
Do Okt 31 09:01:54 2013: fcsv046:backup:INFO: backup-date=20131031090154
Do Okt 31 09:01:54 2013: fcsv046:backup:INFO: mysql-server-os=Linux/Unix
Do Okt 31 09:01:54 2013: fcsv046:backup:INFO: backup-type=regular
Do Okt 31 09:01:54 2013: fcsv046:backup:INFO: host=fcsv046.fce.com
Do Okt 31 09:01:54 2013: fcsv046:backup:INFO: backup-date-epoch=1383206514
Do Okt 31 09:01:54 2013: fcsv046:backup:INFO: retention-policy=7D
Do Okt 31 09:01:54 2013: fcsv046:backup:INFO: mysql-zrm-version=ZRM for MySQL Community Edition - version 2.2.0
Do Okt 31 09:01:54 2013: fcsv046:backup:INFO: mysql-version=5.5.31-0ubuntu0.12.10.1-log
Do Okt 31 09:01:54 2013: fcsv046:backup:INFO: backup-directory=/home/zrm/zrm-backups/fcsv046/20131031090154
Do Okt 31 09:01:54 2013: fcsv046:backup:INFO: backup-level=1
Do Okt 31 09:01:54 2013: fcsv046:backup:INFO: PHASE END: Initialization
Do Okt 31 09:01:54 2013: fcsv046:backup:INFO: PHASE START: Running pre backup plugin
Do Okt 31 09:01:54 2013: fcsv046:backup:INFO: PHASE END: Running pre backup plugin
Do Okt 31 09:01:54 2013: fcsv046:backup:INFO: PHASE START: Flushing logs
Do Okt 31 09:01:54 2013: fcsv046:backup:INFO: PHASE END: Flushing logs
Do Okt 31 09:01:54 2013: fcsv046:backup:INFO: PHASE START: Creating incremental backup
Do Okt 31 09:01:55 2013: fcsv046:backup:INFO: incremental=mysql-bin.[0-9]*
Do Okt 31 09:01:55 2013: fcsv046:backup:INFO: PHASE END: Creating incremental backup
Do Okt 31 09:01:55 2013: fcsv046:backup:INFO: PHASE START: Calculating backup size & checksums
Do Okt 31 09:01:55 2013: fcsv046:backup:INFO: next-binlog=mysql-bin.000014
Do Okt 31 09:01:55 2013: fcsv046:backup:INFO: last-backup=/home/zrm/zrm-backups/fcsv046/20131031041001
Do Okt 31 09:01:55 2013: fcsv046:backup:INFO: backup-size=0.16 MB
Do Okt 31 09:01:55 2013: fcsv046:backup:INFO: PHASE END: Calculating backup size & checksums
Do Okt 31 09:01:55 2013: fcsv046:backup:INFO: PHASE START: Compression/Encryption
Do Okt 31 09:01:55 2013: fcsv046:backup:INFO: compress=
Do Okt 31 09:01:55 2013: fcsv046:backup:INFO: backup-size-compressed=0.02 MB
Do Okt 31 09:01:55 2013: fcsv046:backup:INFO: PHASE END: Compression/Encryption
Do Okt 31 09:01:55 2013: fcsv046:backup:INFO: read-locks-time=00:00:00
Do Okt 31 09:01:55 2013: fcsv046:backup:INFO: flush-logs-time=00:00:00
Do Okt 31 09:01:55 2013: fcsv046:backup:INFO: compress-encrypt-time=00:00:00
Do Okt 31 09:01:55 2013: fcsv046:backup:INFO: backup-time=00:00:01
Do Okt 31 09:01:55 2013: fcsv046:backup:INFO: backup-status=Backup succeeded
Do Okt 31 09:01:55 2013: fcsv046:backup:INFO: Backup succeeded
Do Okt 31 09:01:55 2013: fcsv046:backup:INFO: PHASE START: Running post backup plugin
Do Okt 31 09:01:55 2013: fcsv046:backup:INFO: PHASE END: Running post backup plugin
Do Okt 31 09:01:55 2013: fcsv046:backup:INFO: PHASE START: Mailing backup report
Do Okt 31 09:01:55 2013: fcsv046:backup:INFO: PHASE END: Mailing backup report
Do Okt 31 09:01:56 2013: fcsv046:backup:INFO: PHASE START: Cleanup
Do Okt 31 09:01:56 2013: fcsv046:backup:INFO: PHASE END: Cleanup
Do Okt 31 09:01:56 2013: fcsv046:backup:INFO: END OF BACKUP

When I start it via crontab mysql-zrm-scheduler --add --interval daily --start 09:00 --backup-set fcsv046 --backup-level 1
Thu Oct 31 09:00:02 2013: fcsv046:backup:INFO: START OF BACKUP
Thu Oct 31 09:00:02 2013: fcsv046:backup:INFO: PHASE START: Initialization
Thu Oct 31 09:00:02 2013: fcsv046:backup:INFO: The quick backup-type is supported only for snapshot backups. Setting backup-type to 'regular'
Thu Oct 31 09:00:02 2013: fcsv046:backup:INFO: backup-set=fcsv046
Thu Oct 31 09:00:02 2013: fcsv046:backup:INFO: backup-date=20131031090002
Thu Oct 31 09:00:02 2013: fcsv046:backup:INFO: mysql-server-os=Linux/Unix
Thu Oct 31 09:00:02 2013: fcsv046:backup:INFO: backup-type=regular
Thu Oct 31 09:00:02 2013: fcsv046:backup:INFO: host=fcsv046.fce.com
Thu Oct 31 09:00:02 2013: fcsv046:backup:INFO: backup-date-epoch=1383206402
Thu Oct 31 09:00:02 2013: fcsv046:backup:INFO: retention-policy=7D
Thu Oct 31 09:00:02 2013: fcsv046:backup:INFO: mysql-zrm-version=ZRM for MySQL Community Edition - version 2.2.0
Thu Oct 31 09:00:02 2013: fcsv046:backup:INFO: mysql-version=5.5.31-0ubuntu0.12.10.1-log
Thu Oct 31 09:00:02 2013: fcsv046:backup:INFO: backup-directory=/home/zrm/zrm-backups/fcsv046/20131031090002
Thu Oct 31 09:00:02 2013: fcsv046:backup:INFO: backup-level=1
Thu Oct 31 09:00:02 2013: fcsv046:backup:INFO: PHASE END: Initialization
Thu Oct 31 09:00:02 2013: fcsv046:backup:INFO: PHASE START: Running pre backup plugin
Thu Oct 31 09:00:02 2013: fcsv046:backup:INFO: PHASE END: Running pre backup plugin
Thu Oct 31 09:00:02 2013: fcsv046:backup:INFO: PHASE START: Flushing logs
Thu Oct 31 09:00:02 2013: fcsv046:backup:INFO: PHASE END: Flushing logs
Thu Oct 31 09:00:02 2013: fcsv046:backup:INFO: PHASE START: Creating incremental backup
Thu Oct 31 09:00:02 2013: fcsv046:backup:ERROR: Could not copy file "/var/lib/mysql/mysql-bin.000011"
Thu Oct 31 09:00:02 2013: fcsv046:backup:ERROR: copy-plugin exited with error 512
Thu Oct 31 09:00:02 2013: fcsv046:backup:ERROR: Could not copy bin log file /home/zrm/zrm-backups/fcsv046/20131031090002/mysql-bin.000011
Thu Oct 31 09:00:02 2013: fcsv046:backup:ERROR: Could not copy file "/var/lib/mysql/mysql-bin.000012"
Thu Oct 31 09:00:02 2013: fcsv046:backup:ERROR: copy-plugin exited with error 512
Thu Oct 31 09:00:02 2013: fcsv046:backup:ERROR: Could not copy bin log file /home/zrm/zrm-backups/fcsv046/20131031090002/mysql-bin.000012
Thu Oct 31 09:00:02 2013: fcsv046:backup:INFO: incremental=mysql-bin.[0-9]*
Thu Oct 31 09:00:02 2013: fcsv046:backup:INFO: PHASE END: Creating incremental backup
Thu Oct 31 09:00:02 2013: fcsv046:backup:INFO: PHASE START: Calculating backup size & checksums
Thu Oct 31 09:00:02 2013: fcsv046:backup:INFO: next-binlog=mysql-bin.000013
Thu Oct 31 09:00:02 2013: fcsv046:backup:INFO: last-backup=/home/zrm/zrm-backups/fcsv046/20131031041001
Thu Oct 31 09:00:02 2013: fcsv046:backup:INFO: backup-size=0.00 MB
Thu Oct 31 09:00:02 2013: fcsv046:backup:INFO: PHASE END: Calculating backup size & checksums
Thu Oct 31 09:00:02 2013: fcsv046:backup:INFO: PHASE START: Compression/Encryption
Thu Oct 31 09:00:02 2013: fcsv046:backup:INFO: compress=
Thu Oct 31 09:00:02 2013: fcsv046:backup:INFO: backup-size-compressed=0.00 MB
Thu Oct 31 09:00:02 2013: fcsv046:backup:INFO: PHASE END: Compression/Encryption
Thu Oct 31 09:00:02 2013: fcsv046:backup:INFO: read-locks-time=00:00:00
Thu Oct 31 09:00:02 2013: fcsv046:backup:INFO: flush-logs-time=00:00:00
Thu Oct 31 09:00:02 2013: fcsv046:backup:INFO: compress-encrypt-time=00:00:00
Thu Oct 31 09:00:02 2013: fcsv046:backup:INFO: backup-time=00:00:00
Thu Oct 31 09:00:02 2013: fcsv046:backup:INFO: backup-status=Backup done but with errors
Thu Oct 31 09:00:02 2013: fcsv046:backup:INFO: Backup done but with errors
Thu Oct 31 09:00:02 2013: fcsv046:backup:INFO: PHASE START: Running post backup plugin
Thu Oct 31 09:00:02 2013: fcsv046:backup:INFO: PHASE END: Running post backup plugin
Thu Oct 31 09:00:02 2013: fcsv046:backup:INFO: PHASE START: Mailing backup report
Thu Oct 31 09:00:02 2013: fcsv046:backup:INFO: PHASE END: Mailing backup report
Thu Oct 31 09:00:02 2013: fcsv046:backup:INFO: PHASE START: Cleanup
Thu Oct 31 09:00:03 2013: fcsv046:backup:INFO: PHASE END: Cleanup
Thu Oct 31 09:00:03 2013: fcsv046:backup:INFO: END OF BACKUP

[arndtt]

I can describe my problem a little clearer now. I'm starting the ssh-agent via .bash_profile on my ZRM Server

####SSHagent settings####
SSH_ENV="$HOME/.ssh/environment"

function start_agent {
echo "Initializing new SSH agent..."
/usr/bin/ssh-agent | sed 's/^echo/#echo/' > "${SSH_ENV}"
echo succeeded
chmod 600 "${SSH_ENV}"
. "${SSH_ENV}" > /dev/null
/usr/bin/ssh-add;
}

# Source SSH settings, if applicable

if [ -f "${SSH_ENV}" ]; then
. "${SSH_ENV}" > /dev/null
ps -ef | grep ${SSH_AGENT_PID} | grep ssh-agent$ > /dev/null || {
start_agent;
}
else
start_agent;
fi

And .bash_profile is normally not loaded via crontab... How do I get my ssh-agent started via crontab jobs ? Thanks for any help!

[martineau]

Most user use a dedicated password-less ssh key when using amanda.

You will not be able to run ssh-add from cron, so ssh-agent must already be running

Add a script in cron that set the ssh env and then execute amdump:

simplified script:

#!/bin/bash
SSH_ENV="$HOME/.ssh/environment"
. "${SSH_ENV}" > /dev/null
amdump ....

[arndtt]

Thanks, martineau works for me this way