| View previous topic :: View next topic |
| Author |
Message |
Randall Nortman
Guest
|
 Posted: Sun Apr 03, 2005 4:46 am Post subject: Daylight Saving Time problem? |
 |
|
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 |
|
| Back to top |
|
 |
Keith Edmunds
Guest
|
| Posted: Sun Apr 03, 2005 5:34 am Post subject: Daylight Saving Time problem? |
|
|
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
---------------------------------------------------------------------- |
|
| Back to top |
|
|
Ben Escoto
Guest
|
| Posted: Mon Apr 04, 2005 7:17 am Post subject: Daylight Saving Time problem? |
|
|
| 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 |
|
| Back to top |
|
|
Randall Nortman
Guest
|
| Posted: Mon Apr 04, 2005 7:19 am Post subject: Daylight Saving Time problem? |
|
|
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 |
|
| Back to top |
|
|
David Kempe
Guest
|
| Posted: Mon Apr 04, 2005 7:32 am Post subject: Daylight Saving Time problem? |
|
|
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 |
|
| Back to top |
|
|
Ben Escoto
Guest
|
| Posted: Mon Apr 04, 2005 5:07 pm Post subject: Daylight Saving Time problem? |
|
|
| 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 |
|
| Back to top |
|
|
Randall Nortman
Guest
|
| Posted: Mon Apr 04, 2005 5:27 pm Post subject: Daylight Saving Time problem? |
|
|
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 |
|
| Back to top |
|
|
Ben Escoto
Guest
|
| Posted: Tue Apr 05, 2005 8:58 pm Post subject: Daylight Saving Time problem? |
|
|
| 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 |
|
| Back to top |
|
|
Randall Nortman
Guest
|
| Posted: Wed Apr 06, 2005 6:15 am Post subject: Daylight Saving Time problem? |
|
|
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 |
|
| Back to top |
|
|
Ben Escoto
Guest
|
| Posted: Thu Apr 07, 2005 9:56 am Post subject: Daylight Saving Time problem? |
|
|
| 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 |
|
| Back to top |
|
|
Randall Nortman
Guest
|
| Posted: Thu Apr 07, 2005 2:38 pm Post subject: Daylight Saving Time problem? |
|
|
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 |
|
| Back to top |
|
|
Ben Escoto
Guest
|
| Posted: Thu Apr 07, 2005 7:58 pm Post subject: Daylight Saving Time problem? |
|
|
| 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 |
|
| Back to top |
|
|
|
FAQ
Search
Register
Log in to check your private messages
Log in
