I have a scheduled backup set for every 12 hours and it was working ok until a few weeks ago I noticed that every 12 hours I get TWO backups instead of one.
The second one comes 4 minutes after.
One thing is that the site runs a cron once per hour and I have some parsing in a module that creates multiple threads and this can cause backup on cron to run multiple times. But it shouldn't and why twice?
My .zip backups are now ~70MB and they need around 8 minutes to complete.

CommentFileSizeAuthor
#1 backup_migrate_duplicate_run.diff618 bytesnicorac

Comments

nicorac’s picture

StatusFileSize
new618 bytes

I have the same issue using the integrated Poorman's cron in D7.
I scheduled backup to happen each day, and each time it runs I receive two messages: the first is a success, the second (after a minute) is a failure.
This let me think that cron is running twice, just because integrated D7 cron runs after each page request.

I attached a patch to (try to) fix the issue.
It adds a semaphore just before running the cron task; the semaphore is destroyed after backup completion.
If another cron run will trigger a duplicate backup, it will be discarded.

It works well on my side, but it surely can be improved (especially for people using a real cron).
Feel free to comment it...

alesr’s picture

This is a welcomed patch. Thanks.

I moved my cron call to crontab and fixed this problem for me.

ronan’s picture

Version: 7.x-2.2 » 7.x-2.x-dev
Status: Active » Postponed

Can you check if the problem exists in the latest dev? I've made a change to how the cron timestamp is updated which may have fixed this.

nicorac’s picture

Just installed 2.x-dev version... waiting for next run.
Thanks for your work.

nicorac’s picture

Sadly the issue reappeared, but I suppose a double backup is not really happening.
These are the notices I received this morning from the two (supposed) concurrent backups running this night: the first is successful, the other is failed.

1st message: May 7 20:23:35 2013 (date from mail header)

The site backup has completed successfully with the following messages:
Default Database backed up successfully to xxx-2013-05-08-05-23-14 in destination Scheduled Backups Directory in 21010.84 ms.

2nd message: May 7 20:23:35 2013 (date from mail header)

The site backup has failed with the following messages:
Default Database backed up successfully to xxx-2013-05-08-05-23-14 in destination Scheduled Backups Directory in 21010.84 ms.
The operation timed out. Try increasing your PHP max_execution_time setting.

As you can see they have the same length (21010.84 ms) and exactly the same send time.
That let me think they're not two distinct concurrent backups but, maybe, the second one started sent a wrong failure message while the first was still running.

BTW the backup file xxx-2013-05-08-05-23-14 exists and its content is perfect, not truncated or broken.

My patch #1 reduced the issue a lot, but it's still present and related to integrated cron.
Hope this could shed some light on this bug.

nicorac’s picture

Status: Postponed » Needs work

Same thing happened today...

ronan’s picture

Status: Needs work » Postponed (maintainer needs more info)

Please try the latest dev. I've moved the cron timestamp updating to BEFORE the backup starts so that simultaneous attempts to back up a site shouldn't be a problem anymore.

I suspect what was happening, was that cron was running again before the first backup was complete causing a second backup (attempt) to start.

ronan’s picture

Damnit, I already said all that above.

Never mind.

ronan’s picture

@nicorac

I think you're correct, both of these messages are from the same backup attempt (which appears to be working fine). Or at least from the same cron run. I'm curios: what is your max_execution_time? I'm assuming 30s because the backup takes 21s and you're timing out. What happens if you double that to 60s? Do you still get the errant error?

nicorac’s picture

My 'max_execution_time' is set to 30s and, sadly, I can't change it (it's a free hosting).
Maybe I should split it into parts...

ronan’s picture

Maybe, though it seems that your backup (being only 21 seconds in duration) is working fine. It may be timing out some time during the cleanup. I'm not sure what other implications this might have other than the errant warning message.

ronan’s picture

Issue summary: View changes
Status: Postponed (maintainer needs more info) » Closed (cannot reproduce)

Reopen this if it's still an issue with the latest dev.