BiT v1.0 no completing backups in openSUSE 11.2 & 11.3 with KDE4

[Cyberdude]

I've been using BiT for over a year now on various hardware using openSUSE11.2 with KDE4.4. Last week I upgraded BiT to version 1.0 and now see that the backups fail. I've tried on a laptop running openSUSe11.2 with KDE4.4.4 - BiT gets stuck taking a snapshot on the same file every time. I also upgraded BiT on a desktop running openSUSE11.2 with KDE4.4.4 and now BiT fails to complete on that PC too. BiT also fails on a clean installation of openSUSE11.3 with KDE.4.4.4 on a second desktop. In all cases the backup starts but fails when taking snapshots.

BiT was working perfectly before the upgrade to version 1.0.

When starting BiT from the console with backintime -b here is what I get (from the laptop with openSUSE11.2 and KDE4.4.4.)

Back In Time
Version: 1.0

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.

INFO: Lock
INFO: on process begins
INFO: Profile_id: 1
INFO: Command "find "/media/BiT_Backup/TPx60s/backintime/sxxxxx1/Gxxxx/1/new_snapshot" -type d -exec chmod u+wx {} \;" returns 0
INFO: Command "rm -rf "/media/BiT_Backup/TPx60s/backintime/sxxxxx1/Gxxxx/1/new_snapshot"" returns 0
INFO: Compare with old snapshot: 20100917-160004
rsync: opendir "/boot/lost+found" failed: Permission denied (13)
rsync: opendir "/etc/apache2/ssl.key" failed: Permission denied (13)
rsync: opendir "/etc/audisp" failed: Permission denied (13)
rsync: opendir "/etc/audit" failed: Permission denied (13)
rsync: opendir "/etc/cups/ssl" failed: Permission denied (13)
rsync: opendir "/etc/news" failed: Permission denied (13)
rsync: opendir "/etc/ppp" failed: Permission denied (13)
rsync: opendir "/etc/ssl/private" failed: Permission denied (13)
rsync: opendir "/etc/sysconfig/network/providers" failed: Permission denied (13)
rsync: opendir "/etc/uucp" failed: Permission denied (13)
rsync: opendir "/usr/lib/mozilla/extensions" failed: Permission denied (13)
rsync: stat "/media/BiT_Backup/TPx60s/backintime/sxxxxx1/Gxxxx/1/20100917-160004/backup/usr/share/doc/pdfedit/manual/images/filedialog.png" failed: No such file or directory (2)
rsync: stat "/media/BiT_Backup/TPx60s/backintime/sxxxxx1/Gxxxx/1/20100917-160004/backup/usr/share/doc/pdfedit/manual/images/inputitem.png" failed: No such file or directory (2)
rsync: stat "/media/BiT_Backup/TPx60s/backintime/sxxxxx1/Gxxxx/1/20100917-160004/backup/usr/share/doc/pdfedit/manual/images/inputtext.png" failed: No such file or directory (2)
rsync: stat "/media/BiT_Backup/TPx60s/backintime/sxxxxx1/Gxxxx/1/20100917-160004/backup/usr/share/doc/pdfedit/manual/images/messageb1.png" failed: No such file or directory (2)
rsync: stat "/media/BiT_Backup/TPx60s/backintime/sxxxxx1/Gxxxx/1/20100917-160004/backup/usr/share/doc/pdfedit/manual/images/pdfedit.png" failed: No such file or directory (2)
rsync: stat "/media/BiT_Backup/TPx60s/backintime/sxxxxx1/Gxxxx/1/20100917-160004/backup/usr/share/doc/pdfedit/manual/images/qchkbox-w.png" failed: No such file or directory (2)
rsync: stat "/media/BiT_Backup/TPx60s/backintime/sxxxxx1/Gxxxx/1/20100917-160004/backup/usr/share/doc/pdfedit/manual/images/qcombo1-w.png" failed: No such file or directory (2)
rsync: stat "/media/BiT_Backup/TPx60s/backintime/sxxxxx1/Gxxxx/1/20100917-160004/backup/usr/share/doc/pdfedit/manual/images/qgrpbox-w.png" failed: No such file or directory (2)
rsync: stat "/media/BiT_Backup/TPx60s/backintime/sxxxxx1/Gxxxx/1/20100917-160004/backup/usr/share/doc/pdfedit/manual/images/qlined-w.png" failed: No such file or directory (2)
rsync: stat "/media/BiT_Backup/TPx60s/backintime/sxxxxx1/Gxxxx/1/20100917-160004/backup/usr/share/doc/pdfedit/manual/images/qradiobt-w.png" failed: No such file or directory (2)
rsync: stat "/media/BiT_Backup/TPx60s/backintime/sxxxxx1/Gxxxx/1/20100917-160004/backup/usr/share/doc/pdfedit/manual/images/qsdateed.png" failed: No such file or directory (2)
rsync: stat "/media/BiT_Backup/TPx60s/backintime/sxxxxx1/Gxxxx/1/20100917-160004/backup/usr/share/doc/pdfedit/manual/images/qspinbox-w.png" failed: No such file or directory (2)
rsync: stat "/media/BiT_Backup/TPx60s/backintime/sxxxxx1/Gxxxx/1/20100917-160004/backup/usr/share/doc/pdfedit/manual/images/qstimeed.png" failed: No such file or directory (2)
rsync: stat "/media/BiT_Backup/TPx60s/backintime/sxxxxx1/Gxxxx/1/20100917-160004/backup/usr/share/icons/hicolor/16x16/apps/pdfedit.png" failed: No such file or directory (2)
rsync: stat "/media/BiT_Backup/TPx60s/backintime/sxxxxx1/Gxxxx/1/20100917-160004/backup/usr/share/icons/hicolor/32x32/apps/pdfedit.png" failed: No such file or directory (2)
rsync: stat "/media/BiT_Backup/TPx60s/backintime/sxxxxx1/Gxxxx/1/20100917-160004/backup/usr/share/icons/hicolor/48x48/apps/pdfedit.png" failed: No such file or directory (2)
rsync: stat "/media/BiT_Backup/TPx60s/backintime/sxxxxx1/Gxxxx/1/20100917-160004/backup/usr/share/icons/hicolor/64x64/apps/pdfedit.png" failed: No such file or directory (2)
rsync error: some files/attrs were not transferred (see previous errors) (code 23) at main.c(1039) [sender=3.0.6]
WARNING: Command "rsync -rtDH --links --no-p --no-g --no-o --delete --delete-excluded -i --dry-run --out-format="BACKINTIME: %i %n%L" --chmod=Du+wx --exclude="/media/BiT_Backup/TPx60s" --exclude="/home/Gxxxx/.local/share/backintime" --include="/boot/" --include="/srv/" --include="/VAULT/Documents/" --include="/VAULT/" --include="/home/Gxxxx/" --include="/home/" --include="/etc/" --include="/usr/local/" --include="/usr/" --include="/usr/lib/" --include="/usr/share/" --include="/VirtualBoxVM/" --exclude="*.backup*" --exclude="*~" --exclude="/home/Gxxxx/.local/share/Trash/" --exclude="/home/Gxxxx/.gvfs" --exclude="/VAULT/Documents/WebSite" --exclude="/VAULT/Downloads" --exclude="/home/Gxxxx/.mozilla/firefox/at0tg9dt.default/Cache" --exclude="/Repos" --exclude="/home/Gxxxx/KStreamRipper/L I V E 9 - www.Live9.fr - The Best Pop Ever ! Live Music Station From Paris France Commercial Free" --include="/boot/**" --include="/srv/**" --include="/VAULT/Documents/**" --include="/home/Gxxxx/**" --include="/etc/**" --include="/usr/local/**" --include="/usr/lib/**" --include="/usr/share/**" --include="/VirtualBoxVM/**" --exclude="*" / "/media/BiT_Backup/TPx60s/backintime/sxxxxx1/Gxxxx/1/20100917-160004/backup/"" returns 5888
INFO: Create hard-links
INFO: Command "find "/media/BiT_Backup/TPx60s/backintime/sxxxxx1/Gxxxx/1/20100917-160004/backup/" -type d -exec chmod u+wx {} \;" returns 0
INFO: Command "cp -aRl "/media/BiT_Backup/TPx60s/backintime/sxxxxx1/Gxxxx/1/20100917-160004/backup/"* "/media/BiT_Backup/TPx60s/backintime/sxxxxx1/Gxxxx/1/new_snapshot/backup/"" returns 0
INFO: Command "find "/media/BiT_Backup/TPx60s/backintime/sxxxxx1/Gxxxx/1/20100917-160004/backup/" -type d -exec chmod a-w {} \;" returns 0
INFO: Command "chmod -R a+w "/media/BiT_Backup/TPx60s/backintime/sxxxxx1/Gxxxx/1/new_snapshot"" returns 0
INFO: Call rsync to take the snapshot

Then it just hangs there.

Pressing ctrl c to terminate it gives the following trace back

^CTraceback (most recent call last):
  File "/usr/share/backintime/common/backintime.py", line 194, in <module>
    start_app()
  File "/usr/share/backintime/common/backintime.py", line 106, in start_app
    take_snapshot( cfg, True )
  File "/usr/share/backintime/common/backintime.py", line 42, in take_snapshot
    snapshots.Snapshots( cfg ).take_snapshot( force )
  File "/usr/share/backintime/common/snapshots.py", line 750, in take_snapshot
    ret_val, ret_error = self._take_snapshot( snapshot_id, now, include_folders )
  File "/usr/share/backintime/common/snapshots.py", line 1078, in _take_snapshot
    self._execute( cmd + ' 2>&1', self._exec_rsync_callback, params )
  File "/usr/share/backintime/common/snapshots.py", line 1363, in _execute
    line = tools.temp_failure_retry( pipe.readline )
  File "/usr/share/backintime/common/tools.py", line 377, in temp_failure_retry
    return func(*args, **kwargs)

I've also attached the Information part of the log file. It's too large to paste into this bug report.

If you require any other info let me know.

[Dan (danleweb)]

1. The log looks like the process started:
...
[I] Take snapshot (rsync: home/Gxxxx/.hplip/hplip.conf)
...

2. BIT 1.0 does check for errors and report failures like:
[I] Take snapshot (rsync: rsync: opendir "/etc/uucp" failed: Permission denied (13))

3. Do you have enough free space on your destination drive ?

4. Can you do a small test on one of your systems ?
Remove all includes except one (small one) and test again.

[Cyberdude (gabor-sunseaker)]

Hi Dan

1. Yes it does appear to start but just seems to fail during the process.

2. I think the permission errors are all from me backing up system files and folders which have root permissions. I have now removed those from the backup includes and will a backup for those run them separately as root.

3. There is definitely enough space on the drive as rolling back to 0.9.26 works fine. Also, I experienced the problem on a clean install of openSUSE 11.3 backing up 20GB /home/user to a drive with over 160GB free space.

4. I reinstalled BiT1.0 and tried a single small folder in the includes as you suggested and it seems to work fine. I then added a few more small folders and it worked fine.

Finally I added the whole /home/Gxxxx folder (7.4GB) and the backup failed. Here are the last few lines from the info log.

[I] Take snapshot (rsync: home/Gxxxx/public_html/.directory)
[I] Take snapshot (rsync: )
[I] Take snapshot (rsync: sent 5829043691 bytes received 493649 bytes 14305613.10 bytes/sec)
[I] Take snapshot (rsync: total size is 7375681225 speedup is 1.27)
[I] Take snapshot (rsync: rsync error: some files/attrs were not transferred (see previous errors) (code 23) at main.c(1039) [sender=3.0.6])

These are the error logs

[E] Error: rsync: send_files failed to open "/home/Gxxxx/.config/autostart/.directory": Permission denied (13)
[E] Error: rsync: send_files failed to open "/home/Gxxxx/.qt/.qt_plugins_3.3rc.lock": Permission denied (13)
[E] Failed to take snapshot 09/29/10 10:00:21 !!!

BTW, where are the raw logs kept. Viewing the logs with the BiT log viewer is very slow when trying to look at the information log. It takes 2-3 mins to display the information log.

[Cyberdude (gabor-sunseaker)]

An update to my previous post above.

If I check the "continue on errors" option the backup completes but with (FAILED) next to the snapshot date. As expected I guess. As an experiment I installed luckybackup and ran a backup of the /home/user folder and it completed OK. The end of the luckybackup log looks very similar to the BiT log and shows the same rsync error at the end.

Luckybackup end of log below
Number of files: 28194
Number of files transferred: 26374
Total file size: 7.10G bytes
Total transferred file size: 7.10G bytes
Literal data: 7.10G bytes
Matched data: 0 bytes
File list size: 1.00M
File list generation time: 0.891 seconds
File list transfer time: 0.000 seconds
Total bytes sent: 7.11G
Total bytes received: 506.58K
sent 7.11G bytes received 506.58K bytes 15.88M bytes/sec
total size is 7.10G speedup is 1.00
rsync error: some files/attrs were not transferred (see previous errors) (code 23) at main.c(1039) [sender=3.0.6]

From this it looks like BiT is actually completing the task of the snapshots as it's producing the file size / sent / received summaries and the last rsync error similar to last lines of the luckybackup log. But for some reason BiT thinks the backup has failed. Is it that last error that's the problem?

[Dan (danleweb)]

BIT 0.9.26 did't checked for errors. So even dangerour errors was not detected.
BIT 1.0 tries to detect error. For me "some files/attrs were not transferred" can be dangerous.
You can easily exclude:
  "/home/Gxxxx/.config/autostart/.directory"
  "/home/Gxxxx/.qt/.qt_plugins_3.3rc.lock"
so there will be no errors.

[Cyberdude (gabor-sunseaker)]

Yes, excluding those file worked. I looked at the permissions of the files and they are set as root for some reason even though they exist in the user home folder. I'm not sure why that is but I set the permissions back to the user and removed the exclude.

It all seems to work now.

I like the idea of BiT now checking for errors but I think the way errors are handled by BiT 1.0 is a little heavy handed. The whole snapshot fails because of two files with incorrect permissions. I think that the snapshot should still complete with a warning that there was a problem highlighting which files were causing the error and saying that those files were not included in the snapshot. This would at least still give protection to the rest of the system while the problem is analysed and fixed. Perhaps this should be added to the wishlist as a future enhancement. What do you think?

[Dan (danleweb)]

1. The option exists: "continue on errors" :)
In your case you call them warnings but for some this can be critical errors ...

2. I really like the idea of log summary

3. I can try to avoid multimple identical lines in logs but I can't do much the size. It is slow to open them ... but I don't know how to speed this. I can propose an option to open logs with your preferes editor.

[Cyberdude (gabor-sunseaker)]

1. Agree. But it still seems heavy handed to mark a whole snapshot as failed if the errors occurred only on a couple of files when the rest of it is perfectly OK.

3. Yes it would be useful to be able to open logs in an editor of our preference. Would that be quicker than opening them in BiT as is the current case?

[Dan (danleweb)]

1. This more about the right words. I can change it from "FAILED" to "WITH ERRORS"

3. I have no idea :)

[Dan (danleweb)]

1. Fix commited for: "FAILED" => "WITH ERRORS !"
2 & 3 => wishlist