Click to close the image preview
I've a system that runs a cron-triggered, and cron-stopped, manual backup daily. On this particular system - and I've seen this on others running mozybackup as well - at some point in the backup, a "307 Temporary Redirect" message is logged, after which things seem to go wonky. Queued or running transfers get messages like the following:
2015-04-21T22:41:13.128286 **Removed** VERBOSE 7058 0xaad3cf8 msync:file_queue send_queue.cpp:639 Starting send batch 1 items, **Removed** bytes (limited by size)
2015-04-21T22:43:18.092823 **Removed** VERBOSE 7058 0xab156f50 msync:http request_logger.cpp:75 8-58 307 Temporary Redirect | PUT /namedObjects/8630056/%PATH_TO_FILE_REDACTED_____
2015-04-22T05:37:20.522772 **Removed** VERBOSE 7057 0xaae2938 msync:file_queue send_queue.cpp:359 Too late to cancel upload of /etc/mrtg/mrtg.cfg.dynamic
2015-04-22T05:37:21.542445 **Removed** VERBOSE 7057 0xaae2938 msync:sync local_sync.cpp:770 Finished delay before sending deletion on recently uploaded file /etc/mrtg/mrtg.cfg.dynamic
2015-04-22T05:37:21.546572 **Removed** VERBOSE 7057 0xaae2938 msync:file_queue send_queue.cpp:359 Too late to cancel upload of /etc/mrtg/mrtg.ok
2015-04-22T05:37:22.548261 **Removed** VERBOSE 7057 0xaae2938 msync:sync local_sync.cpp:770 Finished delay before sending deletion on recently uploaded file /etc/mrtg/mrtg.ok
2015-04-22T05:37:22.566550 **Removed** VERBOSE 7057 0xaae2938 msync:file_queue send_queue.cpp:359 Too late to cancel upload of /etc/rc.d/rc.firewall.local
2015-04-22T05:37:23.569133 **Removed** VERBOSE 7057 0xaae2938 msync:sync local_sync.cpp:770 Finished delay before sending deletion on recently uploaded file /etc/rc.d/rc.firewall.local
and so on. Running "mozyutil history" shows the backup as a Failure with different numbers of failures per backup but I'm unable to identify which log entries match up to the listed number of failures.
Is there something on the mozy/server side issuing these redirects which the client is unable to deal with?
Solved! Go to Solution.
We are currently investigating the cause of the issue at this time. I have been able to pull the logs for the machine referenced. This provides a lot of good information as you have enabled Debug logging.
One indication of the error is reported during backup: 2015-04-21T07:10:01.852256. There is an error and the /var/run/mozy.sock removed. Do we know what the system resources were at during this time, or during other instances similar to this?
Other times when the engine goes into a stopping state its just before a users .pst file is about to upload. I'm curious, is that file in use during the backup?
At that specified timestamp:
2015-04-21T07:10:01.852256 **Removed** INFO 14232 0xaa25ba0 msync:cmdsvr command_server.cpp:202 command server stopping
I've a cron in place at 7:10am to restart mozybackup so that's likely the origin of that message.
As to the pst file use, I don't have any records of their use really. If they're large pst files, getting backed up one at a time due to their size, I could see the system still churning away trying to get the older files backed up only to hit that restart at 7:10am.
I use a restart of mozybackup to stop a running manual backup (generally triggered 10+ hours prior) because a 'stop' of the service was acting in unexpected ways - timing out or generally leaving the daemon in an unusable state where the following 'start' command would fail.
Can you tell us more about the gap from timestamp:
and the large delay between the next entry? We are concerned about this delay and if it may also be related to the issue.
To improve logging for this machine, please adjust Logging to include the following:
log.verbosemask : msync.*
log.debugmask : mordor:http:client|msync.*
log.tracemask : msync.transfer_job
We are continuing to investigate the issue more at this time.
The file noted in the log entry at that timestamp is a 2GB pst file (likely not open as it's dated in 2008. The upload speed at this site is roughly 0.5Mbit/sec.
I've enabled the log options.
We have been able to pin down the issue and this will be corrected in 1.3.0.
As for a time frame, I do not yet have that, but will keep you updated as more information is made available.
I'm sorry for the longer delay in reply.
I can verify that the latest 1.3.0 version of Mozy Linux does correct the failed backups with CancelError0. This version is now available to download now.