Backup Central

I woke up this morning to nasty errors from my rdiff-backup cron job,
which I assume are most likely caused by the DST switch. First, I got
"AssertionError: Time 1112514303 is out of bounds", and the backup
failed. Now, when I try to regress the archive, I get
"AssertionError: Too many recent increments".

I'm using rdiff-backup 0.12.7. Full backtrace of the first error:

Traceback (most recent call last):
File "/usr/bin/rdiff-backup", line 23, in ?
rdiff_backup.Main.Main(sys.argv[1:])
File "/usr/lib/python2.3/site-packages/rdiff_backup/Main.py", line 254, in Main
take_action(rps)
File "/usr/lib/python2.3/site-packages/rdiff_backup/Main.py", line 226, in take_action
elif action == "backup": Backup(rps[0], rps[1])
File "/usr/lib/python2.3/site-packages/rdiff_backup/Main.py", line 267, in Backup
Time.setprevtime(prevtime)
File "/usr/lib/python2.3/site-packages/rdiff_backup/Time.py", line 52, in setprevtime
assert 0 < timeinseconds < curtime, \
AssertionError: Time 1112514303 is out of bounds


And the error when trying to regress:

Traceback (most recent call last):
File "/usr/bin/rdiff-backup", line 23, in ?
rdiff_backup.Main.Main(sys.argv[1:])
File "/usr/lib/python2.3/site-packages/rdiff_backup/Main.py", line 254, in Main
take_action(rps)
File "/usr/lib/python2.3/site-packages/rdiff_backup/Main.py", line 236, in take_action
elif action == "check-destination-dir": CheckDest(rps[0])
File "/usr/lib/python2.3/site-packages/rdiff_backup/Main.py", line 634, in CheckDest
dest_rp.conn.regress.Regress(dest_rp)
File "/usr/lib/python2.3/site-packages/rdiff_backup/regress.py", line 70, in Regress
for rf in iterate_meta_rfs(mirror_rp, inc_rpath): ITR(rf.index, rf)
File "/usr/lib/python2.3/site-packages/rdiff_backup/regress.py", line 159, in iterate_meta_rfs
raw_rfs = iterate_raw_rfs(mirror_rp, inc_rp)
File "/usr/lib/python2.3/site-packages/rdiff_backup/regress.py", line 129, in iterate_raw_rfs
root_rf = RegressFile(mirror_rp, inc_rp, restore.get_inclist(inc_rp))
File "/usr/lib/python2.3/site-packages/rdiff_backup/regress.py", line 181, in __init__
self.set_regress_inc()
File "/usr/lib/python2.3/site-packages/rdiff_backup/regress.py", line 196, in set_regress_inc
assert len(newer_incs) <= 1, "Too many recent increments"
AssertionError: Too many recent increments


So... how do I fix this?

Thanks,

Randall

On Sun, 3 Apr 2005 08:44:33 -0400
Randall Nortman <rdiffbackuplist < at > wonderclown.com> wrote:

Quote:

I woke up this morning to nasty errors from my rdiff-backup cron job,
which I assume are most likely caused by the DST switch.

Interesting. I had some errors last weekend (the UK changed to British
Summer Time last weekend), and I put them down to the time changing while
rdiff-backup was processing. At the next backup everything sorted itself
out OK.

Keith

--
----------------------------------------------------------------------
Business computing support: http://www.tiger-computing.co.uk
Linux consultancy: http://www.TheLinuxConsultancy.co.uk
----------------------------------------------------------------------

Quote:

Quote:

Quote:

Quote:

Quote:

Randall Nortman <rdiffbackuplist < at > wonderclown.com>
wrote the following on Sun, 3 Apr 2005 08:44:33 -0400

Quote:

I woke up this morning to nasty errors from my rdiff-backup cron
job, which I assume are most likely caused by the DST switch.
First, I got "AssertionError: Time 1112514303 is out of bounds", and
the backup failed. Now, when I try to regress the archive, I get
"AssertionError: Too many recent increments".

Hmm, the first error happens when rdiff-backup thinks the previous
backup occurred after the current one (time-travel!). Is it possible
that your timezone information is bugged in some way? I don't see why
you would get this error, especially since clocks get ahead, not
behind.

Also rdiff-backup checks the time and time once at the beginning of
the backup, so in theory the timezone changing during the backup
shouldn't matter.

Quote:

AssertionError: Too many recent increments

So... how do I fix this?

Since the failed backup never really got started, it should be ok to
delete the rdiff-backup-data/current-mirror.xxxx file corresponding to
the failed backup. My guess is you need to delete the earlier one but
if you posted the relevant files it would be easier to tell.


--
Ben Escoto

On Sun, Apr 03, 2005 at 09:33:46PM -0700, Ben Escoto wrote:

Quote:

Quote:

Quote:

Quote:

Quote:

Quote:

Randall Nortman <rdiffbackuplist < at > wonderclown.com>
wrote the following on Sun, 3 Apr 2005 08:44:33 -0400

Quote:

I woke up this morning to nasty errors from my rdiff-backup cron
job, which I assume are most likely caused by the DST switch.
First, I got "AssertionError: Time 1112514303 is out of bounds", and
the backup failed. Now, when I try to regress the archive, I get
"AssertionError: Too many recent increments".

Hmm, the first error happens when rdiff-backup thinks the previous
backup occurred after the current one (time-travel!). Is it possible
that your timezone information is bugged in some way? I don't see why
you would get this error, especially since clocks get ahead, not
behind.

Also rdiff-backup checks the time and time once at the beginning of
the backup, so in theory the timezone changing during the backup
shouldn't matter.

Quote:

AssertionError: Too many recent increments

So... how do I fix this?

Since the failed backup never really got started, it should be ok to
delete the rdiff-backup-data/current-mirror.xxxx file corresponding to
the failed backup. My guess is you need to delete the earlier one but
if you posted the relevant files it would be easier to tell.

Not knowing exactly what the relevant files are, I'm offering a
directory listing of the rdiff-backup-data and
rdiff-backup-data/increments directories. Both of these directories
are very large, so I'm sorting by time and including the head and the
tail. I'm including the tail because I noticed a lot of files dated
well in the past but with names indicating that they are recent --
what is the deal with these? Some are Aug 9, 2004, and some are Aug
16, 2003. I only maintain at most 30 days of increments in this
archive, so there should be nothing from these dates. Are these magic
dates, with special meaning for rdiff-backup?

Note that this particular backup is scheduled to run every 15
minutes. It seems to jump from 01:45 to 03:00, as expected.

First rdiff-backup-data:

total 527627
drwx------ 3 rbackup users 727968 Apr 3 03:15 .
-rw------- 1 rbackup users 0 Apr 3 03:00 current_mirror.2005-04-03T03:00:04-04:00.data
-rw------- 1 rbackup users 108 Apr 3 03:00 error_log.2005-04-03T03:00:04-04:00.data.gz
drwx------ 4 rbackup users 242184 Apr 3 01:45 increments
-rw------- 1 rbackup users 0 Apr 3 01:45 current_mirror.2005-04-03T01:45:03-05:00.data
-rw------- 1 rbackup users 116 Apr 3 01:30 error_log.2005-04-03T01:30:08-05:00.data.gz
-rw------- 1 rbackup users 109827 Apr 3 01:30 file_statistics.2005-04-03T01:30:08-05:00.data.gz
-rw------- 1 rbackup users 134451 Apr 3 01:30 mirror_metadata.2005-04-03T01:30:08-05:00.snapshot.gz
-rw------- 1 rbackup users 507 Apr 3 01:30 session_statistics.2005-04-03T01:30:08-05:00.data

...

-rwxr-xr-x 1 rbackup users 0 Aug 9 2004 increments.2005-04-02T23:15:03-05:00.dir
-rwxr-xr-x 1 rbackup users 0 Aug 9 2004 increments.2005-04-02T23:30:04-05:00.dir
-rwxr-xr-x 1 rbackup users 0 Aug 9 2004 increments.2005-04-02T23:45:03-05:00.dir
-rwxr-xr-x 1 rbackup users 0 Aug 9 2004 increments.2005-04-03T00:00:04-05:00.dir
-rwxr-xr-x 1 rbackup users 0 Aug 9 2004 increments.2005-04-03T00:15:03-05:00.dir
-rwxr-xr-x 1 rbackup users 0 Aug 9 2004 increments.2005-04-03T00:30:04-05:00.dir
-rwxr-xr-x 1 rbackup users 0 Aug 9 2004 increments.2005-04-03T00:45:03-05:00.dir
-rwxr-xr-x 1 rbackup users 0 Aug 9 2004 increments.2005-04-03T01:00:08-05:00.dir
-rwxr-xr-x 1 rbackup users 0 Aug 9 2004 increments.2005-04-03T01:15:04-05:00.dir
-rwxr-xr-x 1 rbackup users 0 Aug 9 2004 increments.2005-04-03T01:30:08-05:00.dir


Now increments:

total 1509
drwx------ 3 rbackup users 727968 Apr 3 03:15 ..
drwx------ 4 rbackup users 242184 Apr 3 01:45 .
drwx------ 4 rbackup users 224544 Apr 3 01:45 var
drwx------ 7 rbackup users 351232 Apr 3 01:45 home
-rwxrwsr-x 1 rbackup users 0 Aug 6 2004 home.2005-03-10T12:45:04-05:00.dir
-rwxrwsr-x 1 rbackup users 0 Aug 6 2004 home.2005-03-10T13:00:05-05:00.dir
-rwxrwsr-x 1 rbackup users 0 Aug 6 2004 home.2005-03-10T13:15:03-05:00.dir
-rwxrwsr-x 1 rbackup users 0 Aug 6 2004 home.2005-03-10T13:30:03-05:00.dir
-rwxrwsr-x 1 rbackup users 0 Aug 6 2004 home.2005-03-10T13:45:03-05:00.dir

...

-rwxr-xr-x 1 rbackup users 0 Aug 16 2003 var.2005-04-02T23:15:03-05:00.dir
-rwxr-xr-x 1 rbackup users 0 Aug 16 2003 var.2005-04-02T23:30:04-05:00.dir
-rwxr-xr-x 1 rbackup users 0 Aug 16 2003 var.2005-04-02T23:45:03-05:00.dir
-rwxr-xr-x 1 rbackup users 0 Aug 16 2003 var.2005-04-03T00:00:04-05:00.dir
-rwxr-xr-x 1 rbackup users 0 Aug 16 2003 var.2005-04-03T00:15:03-05:00.dir
-rwxr-xr-x 1 rbackup users 0 Aug 16 2003 var.2005-04-03T00:30:04-05:00.dir
-rwxr-xr-x 1 rbackup users 0 Aug 16 2003 var.2005-04-03T00:45:03-05:00.dir
-rwxr-xr-x 1 rbackup users 0 Aug 16 2003 var.2005-04-03T01:00:08-05:00.dir
-rwxr-xr-x 1 rbackup users 0 Aug 16 2003 var.2005-04-03T01:15:04-05:00.dir
-rwxr-xr-x 1 rbackup users 0 Aug 16 2003 var.2005-04-03T01:30:08-05:00.dir


I can post the content of any of these files if that's helpful; just
let me know which ones you'd need to see.

Thanks!

Randall

Randall Nortman wrote:

Quote:

So... how do I fix this?

I dunno,
but i am running 0.13.4 on debian - its only one of my backups that
seem to have failed

I get this error now:
Previous backup seems to have failed, regressing destination now.
Regressing to Fri Mar 18 12:31:46 2005
Sending back exception Too many recent increments of type
exceptions.AssertionError:
File
"/home/tretkowski/rdiff-backup/rdiff-backup-0.13.4/debian/rdiff-backup/usr/lib/python2.2/site-packages/rdiff_backup/connection.py",
line 334, in answer_request
File
"/home/tretkowski/rdiff-backup/rdiff-backup-0.13.4/debian/rdiff-backup/usr/lib/python2.2/site-packages/rdiff_backup/regress.py",
line 70, in Regress
File
"/home/tretkowski/rdiff-backup/rdiff-backup-0.13.4/debian/rdiff-backup/usr/lib/python2.2/site-packages/rdiff_backup/regress.py",
line 160, in iterate_meta_rfs
File
"/home/tretkowski/rdiff-backup/rdiff-backup-0.13.4/debian/rdiff-backup/usr/lib/python2.2/site-packages/rdiff_backup/regress.py",
line 129, in iterate_raw_rfs
File
"/home/tretkowski/rdiff-backup/rdiff-backup-0.13.4/debian/rdiff-backup/usr/lib/python2.2/site-packages/rdiff_backup/regress.py",
line 182, in __init__
File
"/home/tretkowski/rdiff-backup/rdiff-backup-0.13.4/debian/rdiff-backup/usr/lib/python2.2/site-packages/rdiff_backup/regress.py",
line 197, in set_regress_inc


I think there is a case where the backup failed for some reason before
the daylight saving, and now trying to regress its broken.

Ben, do you know if 0.13.5 would help?

thanks

dave

Quote:

Quote:

Quote:

Quote:

Quote:

Randall Nortman <rdiffbackuplist < at > wonderclown.com>
wrote the following on Mon, 4 Apr 2005 09:19:49 -0400

Hi, the relevant files would be the current_mirror.<time> and the
mirror_metadata.<time> ones. One of them (probably the "earlier" one
which is "2005-04-03T03:00:04-04:00") has no mirror_metadata. So you
can delete that one.

The times shed some light on what the bug is. The two times:

2005-04-03T01:45:03-05:00
2005-04-03T03:00:04-04:00

are 45 minutes apart, not 15 minutes. Do you know what the correct
values should be for your timezone and when you ran it?


--
Ben Escoto

On Mon, Apr 04, 2005 at 05:29:35PM -0700, Ben Escoto wrote:

Quote:

Quote:

Quote:

Quote:

Quote:

Quote:

Randall Nortman <rdiffbackuplist < at > wonderclown.com>
wrote the following on Mon, 4 Apr 2005 09:19:49 -0400

Hi, the relevant files would be the current_mirror.<time> and the
mirror_metadata.<time> ones. One of them (probably the "earlier" one
which is "2005-04-03T03:00:04-04:00") has no mirror_metadata. So you
can delete that one.

I have:

current_mirror.2005-04-03T01:45:03-05:00.data
current_mirror.2005-04-03T03:00:04-04:00.data

and:

mirror_metadata.2005-04-03T01:30:08-05:00.snapshot.gz
mirror_metadata.2005-04-03T01:15:04-05:00.snapshot.gz
mirror_metadata.2005-04-03T01:00:08-05:00.snapshot.gz
mirror_metadata.2005-04-03T00:45:03-05:00.snapshot.gz
[... lots more, but the above are the most recent ...]

So, *neither* of the current_mirror files has an associated
mirror_metadata file. Uh oh?

Quote:

The times shed some light on what the bug is. The two times:

2005-04-03T01:45:03-05:00
2005-04-03T03:00:04-04:00

are 45 minutes apart, not 15 minutes. Do you know what the correct
values should be for your timezone and when you ran it?

No offense, but check your math:

2005-04-03 01:45:03-05:00 = 2005-04-03 06:45:03 UTC
2005-04-03 03:00:04-04:00 = 2005-04-03 07:00:04 UTC

So, those are 15 minutes, 1 second apart, and they are at exactly the
times when the backup were supposed to run (plus or minus a few
seconds). It should have run 15 minutes before DST took effect at
01:45, then DST takes effect at 02:00, so the clock jumps forward an
hour from 01:59:59 straight to 03:00:00 (never actually reads 02:00).

The timezone on both machines is US/Eastern, and the clocks are kept
accurate via ntpd. There is some chance that since ntpd was running,
the clock on one of the machines was adjusted while rdiff-backup was
running.

Randall

Quote:

Quote:

Quote:

Quote:

Quote:

Randall Nortman <rdiffbackuplist < at > wonderclown.com>
wrote the following on Mon, 4 Apr 2005 21:53:40 -0400

Quote:

I have:

current_mirror.2005-04-03T01:45:03-05:00.data
current_mirror.2005-04-03T03:00:04-04:00.data

and:

mirror_metadata.2005-04-03T01:30:08-05:00.snapshot.gz
mirror_metadata.2005-04-03T01:15:04-05:00.snapshot.gz
mirror_metadata.2005-04-03T01:00:08-05:00.snapshot.gz
mirror_metadata.2005-04-03T00:45:03-05:00.snapshot.gz
[... lots more, but the above are the most recent ...]

So, *neither* of the current_mirror files has an associated
mirror_metadata file. Uh oh?

Are their any increments corresponding to the 1:45:03 or 3:00:04
times? Also is the latest mirror_metadata (from 1:30 apparently)
uncorrupted/untruncated?

I think we just need to find manually the last session that completed.
Then we can tell rdiff-backup to regress to that.

Quote:

No offense, but check your math:

2005-04-03 01:45:03-05:00 = 2005-04-03 06:45:03 UTC
2005-04-03 03:00:04-04:00 = 2005-04-03 07:00:04 UTC

Actually I just used rdiff-backup to convert those strings for me.
Since you are correct, there is is a bug in the way it converts the
time strings to seconds (looks like I was misusing mktime(), and it
was taking the timezone into account when converting the strings). So
anyway that explains the problem.


--
Ben Escoto

On Tue, Apr 05, 2005 at 09:25:58PM -0700, Ben Escoto wrote:

Quote:

Are their any increments corresponding to the 1:45:03 or 3:00:04
times? Also is the latest mirror_metadata (from 1:30 apparently)
uncorrupted/untruncated?

I think we just need to find manually the last session that completed.
Then we can tell rdiff-backup to regress to that.

The latest mirror_metadata (from 1:30) has about the same size as the
other mirror_metadata files, and the content looks similar. I guess
that means it's good.

The most recent increments.* file is also from 1:30
(increments.2005-04-03T01:30:08-05:00.dir), and is 0 bytes (like all
the other increments.* files). The increments/ directory itself also
has some 1:30 files, but the directories inside it have a 1:45
timestamp, so it looks like rdiff-backup had already touched some
stuff before it created the metadata files, or else deleted the
metadata files for some reason. Is this bad?

Randall

Quote:

Quote:

Quote:

Quote:

Quote:

Randall Nortman <rdiffbackuplist < at > wonderclown.com>
wrote the following on Wed, 6 Apr 2005 10:41:34 -0400

Quote:

The latest mirror_metadata (from 1:30) has about the same size as the
other mirror_metadata files, and the content looks similar. I guess
that means it's good.

The most recent increments.* file is also from 1:30
(increments.2005-04-03T01:30:08-05:00.dir), and is 0 bytes (like all
the other increments.* files). The increments/ directory itself
also has some 1:30 files, but the directories inside it have a 1:45
timestamp, so it looks like rdiff-backup had already touched some
stuff before it created the metadata files, or else deleted the
metadata files for some reason. Is this bad?

Not necessarily, maybe the metadata file didn't get flushed before the
backed failed. rdiff-backup regresses from the most recent
current_mirror to the older one. It seems you have a good 1:30
backup, and then an aborted 1:45 one. So I would try putting the
current mirror files at 1:45 and 1:30, and then regressing.


--
Ben Escoto

On Thu, Apr 07, 2005 at 10:15:38AM -0700, Ben Escoto wrote:

Quote:

Quote:

Quote:

Quote:

Quote:

Quote:

Randall Nortman <rdiffbackuplist < at > wonderclown.com>
wrote the following on Wed, 6 Apr 2005 10:41:34 -0400

Quote:

The latest mirror_metadata (from 1:30) has about the same size as the
other mirror_metadata files, and the content looks similar. I guess
that means it's good.

The most recent increments.* file is also from 1:30
(increments.2005-04-03T01:30:08-05:00.dir), and is 0 bytes (like all
the other increments.* files). The increments/ directory itself
also has some 1:30 files, but the directories inside it have a 1:45
timestamp, so it looks like rdiff-backup had already touched some
stuff before it created the metadata files, or else deleted the
metadata files for some reason. Is this bad?

Not necessarily, maybe the metadata file didn't get flushed before the
backed failed. rdiff-backup regresses from the most recent
current_mirror to the older one. It seems you have a good 1:30
backup, and then an aborted 1:45 one. So I would try putting the
current mirror files at 1:45 and 1:30, and then regressing.

That fixed it. Backups are proceeding normally now. Thanks!

So, this was an actual bug in rdiff-backup, right, not just a problem
on my system?

Randall

Quote:

Quote:

Quote:

Quote:

Quote:

Randall Nortman <rdiffbackuplist < at > wonderclown.com>
wrote the following on Thu, 7 Apr 2005 19:00:30 -0400

Quote:

So, this was an actual bug in rdiff-backup, right, not just a
problem on my system?

Yeah it was a daylight-savings bug in rdiff-backup converting the time
in seconds that it uses internally to/from timestrings. That messed
up the time on the current_mirror files, and prevented regressing.
The bugs should be fixed in the current versions.


--
Ben Escoto