Re: [rdiff-backup-users] Assertion errors in rdiff-backup 0.13.3

[Gr We]

Here is an interesting thing I found out yesterday (with my hard-fixed time 
problem) after I made some test backups. The hours of increments are messed 
up, see it yourself:

Local system (Debian):
# date
Sun Feb  1 19:10:25 CET 2004
# rdiff-backup -l address@hidden::/bck/test
Found 2 increments:
   increments.2004-02-01T19:08:25Z.dir   Sun Feb  1 21:08:25 2004
   increments.2004-02-01T19:09:20Z.dir   Sun Feb  1 21:09:20 2004
Current mirror: Sun Feb  1 20:09:44 2004

On the remote system (FreeBSD):
# date
Sun Feb  1 19:10:30 CET 2004
And the contents of the directory rdiff-backup-data (strange filenames):
-rw-------  1 root  www    0 Feb  1 19:09 
current_mirror.2004-02-01T18:09:44Z.data
-rw-------  1 root  www   89 Feb  1 19:08 
error_log.2004-02-01T19:08:25+02:00.data.gz
-rw-------  1 root  www   89 Feb  1 19:09 
error_log.2004-02-01T19:09:20+02:00.data.gz
-rw-------  1 root  www   89 Feb  1 19:09 
error_log.2004-02-01T19:09:44+02:00.data.gz
-rw-------  1 root  www  198 Feb  1 19:08 
file_statistics.2004-02-01T18:08:25Z.data.gz
-rw-------  1 root  www  200 Feb  1 19:09 
file_statistics.2004-02-01T18:09:20Z.data.gz
-rw-------  1 root  www  201 Feb  1 19:09 
file_statistics.2004-02-01T18:09:44Z.data.gz
drwx------  2 root  www  512 Feb  1 19:09 increments
-rwxr-x---  1 101   101    0 Feb  1 19:08 
increments.2004-02-01T19:08:25Z.dir
-rwxr-x---  1 101   101    0 Feb  1 19:08 
increments.2004-02-01T19:09:20Z.dir
-rw-------  1 root  www  217 Feb  1 19:08 
mirror_metadata.2004-02-01T18:08:25Z.snapshot.gz
-rw-------  1 root  www  221 Feb  1 19:09 
mirror_metadata.2004-02-01T18:09:20Z.snapshot.gz
-rw-------  1 root  www  221 Feb  1 19:09 
mirror_metadata.2004-02-01T18:09:44Z.snapshot.gz
-rw-------  1 root  www  462 Feb  1 19:08 
session_statistics.2004-02-01T18:08:25Z.data
-rw-------  1 root  www  470 Feb  1 19:09 
session_statistics.2004-02-01T18:09:20Z.data
-rw-------  1 root  www  474 Feb  1 19:09 
session_statistics.2004-02-01T18:09:44Z.data
The file creation date of the files backed up is OK.


Here is also another thing I always see when I try to make a second backup 
of something:
# rdiff-backup . address@hidden::/bck/test
.........
Warning, metadata file not found.
Metadata will be read from filesystem.

It seems that this problem is the reaction to the previos one and my 
hard-fix.


> > Hello, I almost always get an error like this when I try to copy between 
> a
> > Debian and FreeBSD box:
> ...
> > If I run the command many times - the first time it works and then about
> > every 10th run again. Because of that I modified
> > /usr/lib/python2.3/site-packages/rdiff_backup/Time.py, to get more 
> verbose
> > output and when it doesn't work it looks like this:
> > AssertionError: Time 1075591119 is out of bounds (curtime: 1075588293)
> > AssertionError: Time 1075591966 is out of bounds (curtime: 1075588546)
> > Why is the curtime number smaller? How could this happen? Both systems 
> have
> > the clock set to the same time (only +- one second). I tryed the 
> argument
> > for setting current time, but it is ignored by this funcion.
>
> Yes indeed, how could it happen?  If you want to test then you could
> start to narrow down the possibilities:
>
> 1)  The previously existing
>     rdiff-backup-data/current_mirror.<time>.snapshot file has the
>     wrong time.

-rw-------  1 root  www  217 Feb  1 19:08 
mirror_metadata.2004-02-01T18:08:25Z.snapshot.gz
The example file has a strange name, but its contents has things like:
ModTime 1075658891
This is Sun Feb  1 19:08:11 2004 - OK.

> 2)  The time in that filename is being converted to a number wrong
>     (i.e. prevtime is wrong).
> 3)  curtime is wrong

I made a test (fist backup was OK, but the second:) with the extra debug 
output at Sun Feb  1 19:41:30 2004.
AssertionError: Time 1075664397 is out of bounds (curtime: 1075660890)
1075664397 = Sun Feb  1 20:39:57 2004
1075660890 = Sun Feb  1 19:41:30 2004
That means that the curtime is OK.

If I look at the
# rdiff-backup -l address@hidden::/bck/test/xxx
Found 0 increments:
Current mirror: Sun Feb  1 20:39:57 2004
Interestingly the time of the previous backup absolutely matches the 
variable timeinseconds at:
 File "/usr/lib/python2.3/site-packages/rdiff_backup/Time.py", line 52, in 
setprevtime
   assert 0 < timeinseconds < curtime, \

So it seems that the time somewhere is converted in a wrong way and the 
strange thing by this is, that sometimes (rarely) it is ok.

> Well it's finding a bug so it's not just using up cpu+memory :-) About
> everything working fine, have you tried restoring yet??

I tryed restoring and it isn't fully functional. I can restore the latest 
backup, but none of the increments - it say's that the metafile can't be 
found and restores the latest version only. I tryed to restore with 
different ways always the same result (even if I tryed to restore it with 
times +-1 or +- 2 hours).


I am starting to wonder what functions for getting time are used in python? 
Could someone tell me how to simply write the current time in python in the 
way that is done in rdiff-backup? The problem could lay in the fact, that 
FreeBSD likes to have it's system clock set to UTC (and it automaticly 
calculates the localtime when it is requested), but afaik I set it to 
GMT+1:00 and turned this conversions off. I hope someone will have an idea.

_________________________________________________________________
Express yourself with cool new emoticons http://www.msn.co.uk/specials/myemo