rsync completes, but BiT doesn't?

[Mario Metzler]

Hi,

It's been years that I haven't used BiT so I may be completely wrong, but after havin rsync successfully backing up over 1 TB, BiT does not continue with whatever it usually does. In the "Snapshots" area of the kde4-GUI, only one Snapshot "Now" is being displayed; status line displays "Take snapshot (rsync: total size is 1,149,143,245,890 speedup is 1.00)"; the Logfile takesnapshot_.log does not contain any [E] or [W] messages. Maybe the problem was that at one time I accidentally closed the GUI window?

Is it possible to continue a backup after it has been stopped for whatever reason?

Thanks for any help ...

Regards
Mario

[Mario Metzler (l1234)]

Additional Info:

openSUSE 13.1 64-bit

grep backintime /var/log/messages
-------
2014-02-09T10:17:31.609682+01:00 linux-251m backintime (mario): INFO: Lock
2014-02-09T10:17:31.777758+01:00 linux-251m backintime (mario): INFO: on process begins
2014-02-09T10:17:31.854707+01:00 linux-251m backintime (mario): INFO: Profile_id: 1
2014-02-09T10:17:59.774966+01:00 linux-251m backintime (mario): INFO: Command "find "/mnt/t/backintime/backintime/linux-251m/mario/1/new_snapshot" -type d -exec chmod u+wx {} +" returns 0
2014-02-09T10:19:27.864628+01:00 linux-251m backintime (mario): INFO: Command "rm -rf "/mnt/t/backintime/backintime/linux-251m/mario/1/new_snapshot"" returns 0
2014-02-09T10:19:27.871767+01:00 linux-251m backintime (mario): INFO: Call rsync to take the snapshot
-------

Begin of takesnapshot_.log
-------
========== Take snapshot (profile 1): So 09 Feb 2014 10:17:31 ==========

[I] ...
[I] Take snapshot
[I] rsync -rtDH --links --no-p --no-g --no-o --delete --delete-excluded -v --chmod=Du+wx --exclude="/mnt/t/backintime" --exclude="/root/.local/share/backintime" --exclude="/tmp/backintime" --include="/store/" --exclude=".gvfs" --exclude=".cache*" --exclude="[Cc]ache*" --exclude=".thumbnails*" --exclude="[Tt]rash*" --exclude="*.backup*" --exclude="*~" --exclude="/root/Ubuntu One" --exclude=".dropbox*" --exclude="/proc/*" --exclude="/sys/*" --exclude="/dev/*" --exclude="/run/*" --include="/store/**" --exclude="*" / "/mnt/t/backintime/backintime/linux-251m/mario/1/new_snapshot/backup/"
[I] Take snapshot (rsync: sending incremental file list)
[I] Take snapshot (rsync: ./)
----------

End of takesnapshot_.log
----------
[I] Take snapshot (rsync: )
[I] Take snapshot (rsync: sent 1,149,569,885,629 bytes received 41,434,840 bytes 59,174,434.20 bytes/sec)
[I] Take snapshot (rsync: total size is 1,149,143,245,890 speedup is 1.00)
---------

Output of backintime
---------
Back In Time
Version: 1.0.34

Back In Time comes with ABSOLUTELY NO WARRANTY.
This is free software, and you are welcome to redistribute it
under certain conditions; type `backintime --license' for details.
---------

[Germar (germar)]

Hi Mario,
closing the GUI shouldn't effect the running snapshot cause both are separate processes.

You can activate 'Continue on Errors' in Settings. This will make BIT to keep 'new_snapshot' folder if there was an error so you don't need to transfer everything again next time.

Please check if there still is a 'backintime' instance running ('ps ax | grep [b]ackintime') after it stopped working.

Which rsync version do you use?

Regards,
Germar

[Mario Metzler (l1234)]

Hi Germar,

I've started another test, and this time it worked. I don't understand it. The only difference is that I am using another external harddrive.

'Continue on Errors' is enabled, and I am sure that it also was enabled when I tried first.

Output of rsync --version
---
rsync version 3.1.0 protocol version 31
Copyright (C) 1996-2013 by Andrew Tridgell, Wayne Davison, and others.
Web site: http://rsync.samba.org/
Capabilities:
    64-bit files, 64-bit inums, 64-bit timestamps, 64-bit long ints,
    socketpairs, hardlinks, symlinks, IPv6, batchfiles, inplace,
    append, ACLs, xattrs, iconv, symtimes, prealloc, SLP

rsync comes with ABSOLUTELY NO WARRANTY. This is free software, and you
are welcome to redistribute it under certain conditions. See the GNU
General Public Licence for details.
---

Thanks for your response

Regards
Mario

[Mario Metzler (l1234)]

Hi again,

Some additional info:

end of takesnapshot_.log Logfile:
----
[I] Take snapshot (rsync: )
[I] Take snapshot (rsync: sent 1,149,579,092,769 bytes received 41,434,459 bytes 51,523,609.06 bytes/sec)
[I] Take snapshot (rsync: total size is 1,149,152,450,677 speedup is 1.00)
[I] Save config file ...
[I] Save permission ...
[I] Remove old snapshots
[I] Try to keep min free space
[I] Try to keep min 2% free inodes
[I] Finalizing
-----

I'm wondering if the name of the logfile means anything? Shouldn't it be takesnapshot_1.log?

Regards
Mario

[Germar (germar)]

Hi Mario,

Problems which solve by them self are the best! ;-)
May be the other drive is corrupt? Which filesystem do you use? I recommend ext[2|3|4].
I didn't use rsync 3.1.0 yet and didn't get any response on it. So this could be a problem, too.

Log looks good and filename is correct, too. But I agree with you that it's a bit confusing.

Regards,
Germar

[Mario Metzler (l1234)]

Hi Germar,

I'm currently testing again with the other drive where I got the error. (I've rm -R on the old new_snapshot directory, and BiT is now running again.)

Filesystem is ext4.

I really hope it's not the drive, as it's a new 3 TB drive, bought on last Saturday ;-)

3.1.0 is the latest rsync version I could find in a rush using YaST2.

I'll let you know what happens.

Regards
Mario

[Mario Metzler (l1234)]

Hi Germar,

Unfortunately using the 3 TB HDD, the same problem reappears :-(

Final of egrep "[Bb]ackintime" /var/log/messages
------------------
2014-02-10T21:43:19.932451+01:00 linux-251m backintime (mario): INFO: Lock
2014-02-10T21:43:20.095230+01:00 linux-251m backintime (mario): INFO: on process begins
2014-02-10T21:43:20.103300+01:00 linux-251m backintime (mario): INFO: Profile_id: 1
2014-02-10T21:43:20.111023+01:00 linux-251m backintime (mario): INFO: Call rsync to take the snapshot
------------------

Begin of takesnapshot_.log
-----------------------
========== Take snapshot (profile 1): Mo 10 Feb 2014 21:43:19 ==========

[I] ...
[I] Take snapshot
[I] rsync -rtDH --links --no-p --no-g --no-o --delete --delete-excluded -v --chmod=Du+wx --exclude="/mnt/t/backintime" --exclude="/root/.local/share/backintime" --exclude="/tmp/backintime" --include="/store/" --exclude=".gvfs" --exclude=".cache*" --exclude="[Cc]ache*" --exclude=".thumbnails*" --exclude="[Tt]rash*" --exclude="*.backup*" --exclude="*~" --exclude="/root/Ubuntu One" --exclude=".dropbox*" --exclude="/proc/*" --exclude="/sys/*" --exclude="/dev/*" --exclude="/run/*" --include="/store/**" --exclude="*" / "/mnt/t/backintime/backintime/linux-251m/mario/1/new_snapshot/backup/"
[I] Take snapshot (rsync: sending incremental file list)
[I] Take snapshot (rsync: ./)
---------------------------

End of takesnapshot_.log
---------------------------
[I] Take snapshot (rsync: )
[I] Take snapshot (rsync: sent 1,149,905,272,647 bytes received 41,432,444 bytes 56,203,255.30 bytes/sec)
[I] Take snapshot (rsync: total size is 1,149,478,550,730 speedup is 1.00)
---------------------------

What I forgot to tell, both drives are LUKS encrypted. I mount them manually to the same mount point using cryptsetup and mount.

fsck.ext4 -vF /dev/mapper/cr_sde1
---------------------------
e2fsck 1.42.8 (20-Jun-2013)
/dev/mapper/cr_sde1: sauber, 2276770/183148544 Dateien, 293655147/732565760 Blöcke
---------------------------
(Of course I unmounted first)

Theres another thing I recall, the "new" drive is a Seagate, the "old" is by WD and has "only" 2TB... but no idea if that's the problem.

No idea what to do next at the moment...

Regards
Mario

[Germar (germar)]

Hi Mario,

please run the rsync command from takesnapshot_.log manually and redirect the output into a file:
rsync -rtDH --links --no-p --no-g --no-o --delete --delete-excluded -v --chmod=Du+wx --exclude="/mnt/t/backintime" --exclude="/root/.local/share/backintime" --exclude="/tmp/backintime" --include="/store/" --exclude=".gvfs" --exclude=".cache*" --exclude="[Cc]ache*" --exclude=".thumbnails*" --exclude="[Tt]rash*" --exclude="*.backup*" --exclude="*~" --exclude="/root/Ubuntu One" --exclude=".dropbox*" --exclude="/proc/*" --exclude="/sys/*" --exclude="/dev/*" --exclude="/run/*" --include="/store/**" --exclude="*" / "/mnt/t/backintime/backintime/linux-251m/mario/1/new_snapshot/backup/" 2>&1 >~/rsync.log

Then compress the log with 'tar cvjf rsync.log.tar.bz2 rsync.log' and send it to me: germar DOT reitze HOSTED ON gmail DOT com

I suppose that rsync 3.1.0 is printing something which BIT can't handle.

Regards,
Germar

[Mario Metzler (l1234)]

Hi Germar,

Many thanks for your response. However, I'm reluctant to send the whole rsync output by email for security reasons, I must say.

I've run rsync as shown above, and the generated logfile's last line corresponds to the one of takesnapshot_.log created before. I've done so also with the 2TB drive that works, and the log is almost the same, with the only exception of the second last line, where some statistics (bytes sent/received etc) are not identical.

So I don't believe that the rsync output is the problem. It seems to me that it crashes at some point after rsync has finished. I've modified backintimes source (snapshots.py) so that more info is printed to /var/log/messages. I know it's a rather primitive debugging technique to add debug lines, but I am not a Python programmer, and it's the best I could do *now* ;-)

I'll get back to you with my results asap...

Regards
Mario

[Germar (germar)]

Hi Mario,

No worries, I totally understand that. You could have send it encrypted with my gnupgp key in my profile. But that's not necessary if it's the same as takesnapshot_.log.

Most times I do debugging like this as well. But I'm no Python programmer either ;-) I'm just an enthusiastic BIT user who learned Python.
But you could also use python debugger. Just add 'import pdb' at start of snapshots.py and add 'pdb.set_trace' before lines you want to debug. Than run 'backintime -b' in Terminal. Take a look at http://docs.python.org/2/library/pdb.html#debugger-commands on how to control the running instance.

Interesting to know would be if/why params[0] in line 1309 is True or if python never reach line 1309.

Regards,
Germar

[Mario Metzler (l1234)]

Hi Germar,

Sorry for the delay. But I was not able to reproduce the error using the debugging version of BIT. And then even the original version worked.

The only explanation I have is that, without being completely sure, I MAX have cleaned up the /root/.local/share/backintime directory before running the debugging version. It's a mystery to me, howeverI did not dig that much into BIT internals to tell if this is reasonable.

And I have no idea why BIT stopped working when I tried the first time.

However, many thanks. I'll have an eye on this and a nice weekend :-)

Regards
Mario

[Mario Metzler (l1234)]

s/MAX/MAY/

Sorry ;-)

[Germar (germar)]

Thanks for debugging and your feedback. I will change this to 'incomplete' for now, so it will expire in couple weeks. If this happen again please come back here so we can try to trace it down.

Have a nice weekend, too.
Regards,
Germar

[Mario Metzler (l1234)]

Thanks for your work too.

Regards
Mario

[Launchpad Janitor (janitor)]

[Expired for Back In Time because there has been no activity for 60 days.]