failed to take snapshot

[Jamin W. Collins]

I recently found that backintime has not been completing my nightly backups. Can't say for certain when this started happening but the last successful backup was about two weeks ago.

The last few lings of the log output are as follows:

[I] Take snapshot (rsync: home/jcollins/.config/google-chrome/Default/Extensions/gighmmpiobklfepjocnamgkkbiglidom/2.1.4_0/)
[I] Take snapshot (rsync: home/jcollins/.config/google-chrome/Default/Extensions/gighmmpiobklfepjocnamgkkbiglidom/2.1.4_0/Icon.png)
[I] Take snapshot (rsync: home/jcollins/.config/google-chrome/Default/Extensions/gighmmpiobklfepjocnamgkkbiglidom/2.1.4_0/Info.plist)
[I] Take snapshot (rsync: home/jcollins/.config/google-chrome/Default/Extensions/gighmmpiobklfepjocnamgkkbiglidom/2.1.4_0/adblock.js)
[I] Take snapshot (rsync: home/jcollins/.config/google-chrome/Default/Extensions/gighmmpiobklfepjocnamgkkbiglidom/2.1.4_0/adblock_start.js)
[I] Take snapshot (rsync: home/jcollins/.config/google-chrome/Default/Extensions/gighmmpiobklfepjocnamgkkbiglidom/2.1.4_0/adreport.html)
[I] Take snapshot (rsync: rsync: writefd_unbuffered failed to write 4 bytes to socket [sender]: Broken pipe (32))
[E] Error: rsync: writefd_unbuffered failed to write 4 bytes to socket [sender]: Broken pipe (32)
[I] Take snapshot (rsync: File-list index 111 not in 8908 - 10023 (finish_hard_link) [generator])
[I] Take snapshot (rsync: rsync error: protocol incompatibility (code 2) at rsync.c(646) [generator=3.0.7])
[I] Take snapshot (rsync: rsync: connection unexpectedly closed (59086 bytes received so far) [sender])
[I] Take snapshot (rsync: rsync error: error in rsync protocol data stream (code 12) at io.c(601) [sender=3.0.7])
[E] Failed to take snapshot 09/01/2010 09:47:33 !!!

[Dan (danleweb)]

Did you updated BIT about two weeks ago ?

[Jamin W. Collins (jcollins)]

Did some digging through my apt logs and seems that there was an update to backintime on August 17th, which is when the last successful backup appears to have been done. Based on the following log entries, it looks like the package was upgraded from 0.9.99.64~lucid to 0.9.99.78~lucid:

backintime-common (0.9.99.64~lucid, 0.9.99.78~lucid), backintime-gnome (0.9.99.64~lucid, 0.9.99.78~lucid)

[Dan (danleweb)]

Can you attach all error lines ? (lines starting with "[E]")

[Jamin W. Collins (jcollins)]

I did. Those are all the error lines in context in the log file. Here's the grep output:

grep '^\[E\]' takesnapshot_.log
[E] Error: rsync: writefd_unbuffered failed to write 4 bytes to socket [sender]: Broken pipe (32)
[E] Failed to take snapshot 09/01/2010 09:47:33 !!!

[Dan (danleweb)]

What is you destination file system ?

[Jamin W. Collins (jcollins)]

The same as it's always been, an ext3 filesystem on a 1.5TB drive (single partition whole volume), accessed via esata.

[Dan (danleweb)]

All I could find:
http://ubuntuforums.org/archive/index.php/t-1029687.html
https://bugs.launchpad.net/backintime/+bug/617827
http://lists.samba.org/archive/rsync/2009-July/023622.html

I'm not sure it helps.

[Jamin W. Collins (jcollins)]

First one is concerning FAT32 volumes, not relevant as there are no FAT32 volumes in use here on either side.

The second appears to be something about changing backup formats. Again doesn't appear to be relevant unless the backup format changed between the above referenced versions, which I don't believe it did.

The third is about odd characters in the file names, which doesn't apply.

Is the older package version (0.9.99.64~lucid) still available anywhere? I'd be very interested to see if rolling back to the older version resulted in functional backups again.

[Dan (danleweb)]

The code is always available in launchpad: https://code.launchpad.net/~bit-team/backintime/trunk

0.9.99.64 it is in the revision 740:
      bzr checkout lp:backintime -r 740

I will attach some packages I build myself (common & gnome).
Please try it.

[Jamin W. Collins (jcollins)]

The more I dig into this issue, the less sense it seems to make. The older package versions wouldn't take a backup either. However, if I change the backup location (start fresh) it is able to take a backup. However, if I merge the new backup with the existing backups, via fslint, then I can no longer complete a backup. It would appear that there is something corrupt or problematic in the existing backups.

I can move forward with new backups, but in doing so I lose the automatic smart deletion of the existing backups and the backups now take nearly twice the space due to having two locations.

[Dan (danleweb)]

The good news is that there is no problem with current version.
Can you do a check disk on your backup drive ?

[Jamin W. Collins (jcollins)]

Already checked both the backup drive and the source drive, no problems on either drive.

[Jamin W. Collins (jcollins)]

Backups to the new location are now failing as well. If I remove my home directory from the locations to backup, the backup completes. I'm working through a process of elimination trying to find the specific area that is causing the problem. I'll keep you posted.

[Jamin W. Collins (jcollins)]

It would appear that the problem directory is the ~/.dropbox* directories within my home directory. Specifically excluding these subdirectories allows the backup to succeed.

[Dan (danleweb)]

OK, so BIT should exclude by default ".dropbox". This is all I can do.

[Jamin W. Collins (jcollins)]

There are two dot directories created in the user's home directory by dropbox

$ ls -ld .drop*
drwxr-xr-x 3 jcollins jcollins 4096 2010-09-09 06:43 .dropbox
drwxr-xr-x 4 jcollins jcollins 4096 2010-05-06 13:14 .dropbox-dist

My current (working) exclusion lists it this way:

  */.dropbox*

Beyond the default exclusion, which I see as a very good thing, I think some investigation into the error reporting might be useful. I'm not sure how one would go about getting more detailed information regarding where rsync is failing. However, it's pretty clear that the information being given currently is vague to say the least. It's very misleading.

[Dan (danleweb)]

I don't know how to increase error logs. I can only display errors reported by rsync.

[Balinny (balinny)]

> I don't know how to increase error logs. I can only display errors reported by rsync.
You could show the rsync command being run, then for debugging purposes it could be run from a terminal with -v flag. Or even inside strace if needed.

It seems that in rsync. flist_for_ndx() failed when called from finish_hard_link() Maybe it is a race condition where dropbox removes the file file while rsync is working with it?
Does it still fail with dropbox daemon disabled?

[Jamin W. Collins (jcollins)]

Just tested a backup without the exclusion and with the dropbox agent stopped, it completed fine. So it appears that either is a viable option.

[mr_hangman (mrhangman)]

Hi, I'm have this problem with BIT 1.0.4 on arch linux.

I set 2 separate backup schedules for my root and home partitions every day at 6pm and 7pm respectively.
Just today I noticed that BIT didn't do a backup at 7pm for the home partition.
This is the last part of the very long log.

[I] Take snapshot (rsync: home/tian/.supertux2/config)
[I] Take snapshot (rsync: home/tian/.supertux2/profile1/world1.stsg)
[I] Take snapshot (rsync: home/tian/.workrave/historystats)
[I] Take snapshot (rsync: home/tian/.workrave/idlelog.79de711200423e91c1b8e28b4ce6abb1.log)
[I] Take snapshot (rsync: rsync: writefd_unbuffered failed to write 4 bytes to socket [sender]: Broken pipe (32))
[E] Error: rsync: writefd_unbuffered failed to write 4 bytes to socket [sender]: Broken pipe (32)
[I] Take snapshot (rsync: deleting home/tian/Desktop/linphone_step2.jpg)
[I] Take snapshot (rsync: deleting home/tian/Desktop/linphone_step1.jpg)
[I] Take snapshot (rsync: deleting home/tian/documents/applications/.~lock.sop.odt#)
[I] Take snapshot (rsync: File-list index 0 not in 20556 - 21556 (finish_hard_link) [generator])
[I] Take snapshot (rsync: rsync error: protocol incompatibility (code 2) at rsync.c(646) [generator=3.0.7])
[I] Take snapshot (rsync: rsync: connection unexpectedly closed (19180 bytes received so far) [sender])
[I] Take snapshot (rsync: rsync error: error in rsync protocol data stream (code 12) at io.c(601) [sender=3.0.7])
[E] Failed to take snapshot 12/01/10 19:00:02 !!!

I tried backing up the root partition after that and it worked fine.

Could it be a problem with some other folders? (I don't have dropbox installed)

[mr_hangman (mrhangman)]

OK, I found the problem. It's .workrave folder in home dir. I excluded it and the backup went fine.

I have been using workrave for a long time and BIT backed it up without a problem. I can still see the backup folder and the files inside which seem to be identical to what I currently have in my home dir. But today it just didn't work. I can send you the files if you need them.

Could this somehow happen to other folders in the future?
Thanks.

[Dan (danleweb)]

Can you explore in deep to understand why it can't backup ?
Do you have full rights on ~/.workrave and all of it's files and folders ?

Regards,
Dan

[mr_hangman (mrhangman)]

The folder and all the files inside are own by me.
Even if it's not own by me it shouldn't be a problem because I backup using root account.

This is the list of the files.

drwx------ 2 tian users 4096 Dec 1 20:04 .
drwx------ 81 tian users 4096 Dec 1 22:19 ..
-rw-r--r-- 1 tian users 588 Dec 1 09:27 historystats
-rw-r--r-- 1 tian users 33 Nov 19 17:54 id
-rw-r--r-- 1 tian users 1649 Dec 1 22:47 idlelog.79de711200423e91c1b8e28b4ce6abb1.log
-rw-r--r-- 1 tian users 84 Dec 1 22:47 idlelog.idx
-rw-r--r-- 1 tian users 169 Dec 1 22:47 state
-rw-r--r-- 1 tian users 158 Dec 1 22:47 todaystats

Right now after one successful backup, including ,workrave to the backup doesn't cause this problem anymore.

I still have no idea what was the actual cause :(
I'll keep you posted if it happens again.
Thanks

[mr_hangman (mrhangman)]

It happened again today but with a different folder in another profile.

This is the backup of root partition. In the log file it says

[I] Take snapshot (rsync: usr/share/man/man8/gencmn.8.gz)
[I] Take snapshot (rsync: usr/share/man/man8/gensprep.8.gz)
[I] Take snapshot (rsync: usr/share/man/man8/icupkg.8.gz)
[I] Take snapshot (rsync: usr/share/man/mann/Tcl.n.gz => usr/share/man/mann/auto_execok.n.gz)
[I] Take snapshot (rsync: rsync: writefd_unbuffered failed to write 4 bytes to socket [sender]: Broken pipe (32))
[E] Error: rsync: writefd_unbuffered failed to write 4 bytes to socket [sender]: Broken pipe (32)
[I] Take snapshot (rsync: File-list index 8021806 not in 211969 - 212759 (finish_hard_link) [generator])
[I] Take snapshot (rsync: rsync error: protocol incompatibility (code 2) at rsync.c(646) [generator=3.0.7])
[I] Take snapshot (rsync: rsync: connection unexpectedly closed (230611 bytes received so far) [sender])
[I] Take snapshot (rsync: rsync error: error in rsync protocol data stream (code 12) at io.c(601) [sender=3.0.7])
[E] Failed to take snapshot 12/09/10 17:00:02 !!!

and when I backed it up again manually from the GUI (root), I got

[I] Take snapshot (rsync: usr/share/man/man8/gencmn.8.gz)
[I] Take snapshot (rsync: usr/share/man/man8/gensprep.8.gz)
[I] Take snapshot (rsync: usr/share/man/man8/icupkg.8.gz)
[I] Take snapshot (rsync: rsync: writefd_unbuffered failed to write 4 bytes to socket [sender]: Broken pipe (32))
[E] Error: rsync: writefd_unbuffered failed to write 4 bytes to socket [sender]: Broken pipe (32)
[I] Take snapshot (rsync: File-list index 8021806 not in 211985 - 212775 (finish_hard_link) [generator])
[I] Take snapshot (rsync: rsync error: protocol incompatibility (code 2) at rsync.c(646) [generator=3.0.7])
[I] Take snapshot (rsync: rsync: connection unexpectedly closed (294911 bytes received so far) [sender])
[I] Take snapshot (rsync: rsync error: error in rsync protocol data stream (code 12) at io.c(601) [sender=3.0.7])
[E] Failed to take snapshot 12/10/2010 00:55:36 !!!

I don't know which file to exclude because there are so many of them.
If I exclude the whole folder and the backup finishes successfully, I won't be able to reproduce it again intentionally.

I think this is a good time to investigate the cause but I don't know what to look for.

[mr_hangman (mrhangman)]

It just happened again with .tucan in home directory.

[I] Take snapshot (rsync: home/tian/.tucan/)
[I] Take snapshot (rsync: home/tian/.tucan/last.session)
[I] Take snapshot (rsync: home/tian/.tucan/tucan.conf)
[I] Take snapshot (rsync: home/tian/.tucan/tucan.history)
[I] Take snapshot (rsync: home/tian/.tucan/tucan.log)
[I] Take snapshot (rsync: rsync: writefd_unbuffered failed to write 4 bytes to socket [sender]: Broken pipe (32))
[E] Error: rsync: writefd_unbuffered failed to write 4 bytes to socket [sender]: Broken pipe (32)
[I] Take snapshot (rsync: deleting home/tian/.tucan/plugins/gigasize/service.conf)
[I] Take snapshot (rsync: deleting home/tian/.tucan/plugins/gigasize/favicon_gigasize.ico)
[I] Take snapshot (rsync: deleting home/tian/.tucan/plugins/gigasize/check_links.pyc)
[I] Take snapshot (rsync: deleting home/tian/.tucan/plugins/gigasize/check_links.py)
[I] Take snapshot (rsync: deleting home/tian/.tucan/plugins/gigasize/anonymous_download.pyc)
[I] Take snapshot (rsync: deleting home/tian/.tucan/plugins/gigasize/anonymous_download.py)
[I] Take snapshot (rsync: deleting home/tian/.tucan/plugins/gigasize/__init__.pyc)
[I] Take snapshot (rsync: deleting home/tian/.tucan/plugins/gigasize/__init__.py)
[I] Take snapshot (rsync: deleting home/tian/.tucan/plugins/gigasize/)
[I] Take snapshot (rsync: deleting home/tian/.tucan/plugins/4shared/parsers.pyc)
[I] Take snapshot (rsync: deleting home/tian/.tucan/plugins/4shared/parsers.py)
[I] Take snapshot (rsync: deleting home/tian/.tucan/plugins/badongo/parsers.pyc)
[I] Take snapshot (rsync: deleting home/tian/.tucan/plugins/badongo/parsers.py)
[I] Take snapshot (rsync: deleting home/tian/.tucan/plugins/depositfiles/parsers.pyc)
[I] Take snapshot (rsync: deleting home/tian/.tucan/plugins/depositfiles/parsers.py)
[I] Take snapshot (rsync: deleting home/tian/.tucan/plugins/easy-share/parsers.pyc)
[I] Take snapshot (rsync: deleting home/tian/.tucan/plugins/easy-share/parsers.py)
[I] Take snapshot (rsync: deleting home/tian/.tucan/plugins/filefactory/parsers.pyc)
[I] Take snapshot (rsync: deleting home/tian/.tucan/plugins/filefactory/parsers.py)
[I] Take snapshot (rsync: deleting home/tian/.tucan/plugins/hotfile/parsers.pyc)
[I] Take snapshot (rsync: deleting home/tian/.tucan/plugins/hotfile/parsers.py)
[I] Take snapshot (rsync: deleting home/tian/.tucan/plugins/mediafire/parsers.pyc)
[I] Take snapshot (rsync: deleting home/tian/.tucan/plugins/mediafire/parsers.py)
[I] Take snapshot (rsync: deleting home/tian/.tucan/plugins/megaupload/premium_parser.pyc)
[I] Take snapshot (rsync: deleting home/tian/.tucan/plugins/megaupload/premium_parser.py)
[I] Take snapshot (rsync: deleting home/tian/.tucan/plugins/megaupload/captcha.pyc)
[I] Take snapshot (rsync: deleting home/tian/.tucan/plugins/megaupload/captcha.py)
[I] Take snapshot (rsync: deleting home/tian/.tucan/plugins/sendspace/parsers.pyc)
[I] Take snapshot (rsync: deleting home/tian/.tucan/plugins/sendspace/parsers.py)
[I] Take snapshot (rsync: deleting home/tian/.tucan/plugins/uploading/parsers.pyc)
[I] Take snapshot (rsync: deleting home/tian/.tucan/plugins/uploading/parsers.py)
[I] Take snapshot (rsync: deleting home/tian/.tucan/plugins/zshar...

[PeterPall (peterpall)]

On my computer problems started the moment I started to include all files beginning with . to the backup.So it might be either .svn dirs, the .gvfs dir or any other configuration directory.

Maybe it is .gvfs. See Bug #534829 and Bug #661650.

Will retry this evening.

[PeterPall (peterpall)]

Nope.

Did exclude any directories starting with "." from back-up, did even delete the whole backup directory tree to be able to begin with a clean tree for backups. Still all I get is:

Check snapshot folder: /media/Media/Backups/book
Create folder: /media/Media/Backups/book/backintime/book/gunter/1
Clearing all Back In Time entries
Clearing system Back In Time entries
Profile: Main profile
Automatic backup: Disabled
INFO: Call rsync to take the snapshot
^[[A^[[A^[[AWARNING: Command "rsync -rtDH --links --no-p --no-g --no-o --delete --delete-excluded -v --chmod=Du+wx --exclude="/media/Media/Backups/book" --exclude="/home/gunter/.local/share/backintime" --include="/home/gunter/" --include="/home/" --include="/media/svn/" --include="/media/" --include="/home/gunter/.gnupg/" --exclude="*.backup*" --exclude="*~" --exclude=".svn" --exclude=".gvfs" --exclude=".*" --include="/home/gunter/**" --include="/media/svn/**" --include="/home/gunter/.gnupg/**" --exclude="*" / "/media/Media/Backups/book/backintime/book/gunter/1/new_snapshot/backup/" 2>&1" returns 5888
INFO: Command "find "/media/Media/Backups/book/backintime/book/gunter/1/new_snapshot" -type d -exec chmod u+wx {} \;" returns 0
INFO: Command "rm -rf "/media/Media/Backups/book/backintime/book/gunter/1/new_snapshot"" returns 0
INFO: Command "rm -rf "/media/Media/Backups/book/backintime/book/gunter/1/20110127-195734-277"" returns 0
ERROR: Failed to take snapshot !!!

** (backintime.py:6221): CRITICAL **: dbus_g_proxy_disconnect_signal: assertion `!DBUS_G_PROXY_DESTROYED (proxy)' failed

** (backintime.py:6221): CRITICAL **: dbus_g_proxy_disconnect_signal: assertion `!DBUS_G_PROXY_DESTROYED (proxy)' failed
INFO: [GnomePlugin.Systray.run] end loop
INFO: Unlock