BiT continually stuck on Comparing snapshot...and permission problems

[Cyberdude]

I'm posting this as requested by Dan on the Answers section https://answers.launchpad.net/backintime/+question/97137

BiT seems to have stopped working for me on a fresh installation of openSUSE 11.2. It seems to create the first snapshot fine but thereafter just gets stuck on Comparing snapshot. I have it configured to take a snapshot once every hour.

I have the default excludes and tried adding .gvfs as an exclude (as mentioned in another thread) but couldn't.

When I run BiT from the terminal as "backintime -b" it seems to run fine except I get a lot of permission denied errors. See output below.

Back In Time
Version: 0.9.26

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: Include folders: ['/boot', '/srv', '/VAULT/Documents', '/home', '/etc', '/usr/local', '/usr/lib', '/usr/share']
INFO: Ignore folders: []
INFO: Last snapshots: {}
INFO: [KDE4Plugin.Systray.run]
INFO: [KDE4Plugin.Systray.run] begin loop
INFO: Compare with old snapshot: 20100112-090001
rsync: opendir "/boot/lost+found" 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)
...etc

I also get...
rsync error: some files/attrs were not transferred (see previous errors) (code 23) at main.c(1039) [sender=3.0.6]
WARNING: Command "rsync -aEAX -i --dry-run --chmod=Fa-w,D+w --whole-file --delete --exclude="/media/Backup/TPX60s" --exclude="/home/Gxxxx/.local/share/backintime" --include="/boot/" --include="/srv/" --include="/VAULT/Documents/" --include="/VAULT/" --include="/home/" --include="/etc/" --include="/usr/local/" --include="/usr/" --include="/usr/lib/" --include="/usr/share/" --exclude="*.backup*" --exclude="*~" --include="/boot/**" --include="/srv/**" --include="/VAULT/Documents/**" --include="/home/**" --include="/etc/**" --include="/usr/local/**" --include="/usr/lib/**" --include="/usr/share/**" --exclude="*" / "/media/Backup/TPX60s/backintime/20100112-090001/backup/"" returns 5888

Then lots more permission denied errors
INFO: Create hard-links
INFO: Command "cp -al "/media/Backup/TPX60s/backintime/20100112-090001/backup/"* "/media/Backup/TPX60s/backintime/new_snapshot/backup/"" returns 0
INFO: Call rsync to take the snapshot
rsync: opendir "/boot/lost+found" 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: send_files failed to open "/boot/backup_mbr": Permission denied (13)
rsync: send_files failed to open "/boot/grub/device.map": Permission denied (13)
rsync: send_files failed to open "/boot/grub/device.map.old": Permission denied (13)
rsync: send_files failed to open "/boot/grub/menu.lst": Permission denied (13)
rsync: send_files failed to open "/boot/grub/menu.lst.old": Permission denied (13)
rsync: send_files failed to open "/etc/.pwd.lock": Permission denied (13)
rsync: send_files failed to open "/etc/at.deny": Permission denied (13)
rsync: send_files failed to open "/etc/autofs_ldap_auth.conf": Permission denied (13)
rsync: send_files failed to open "/etc/cron.deny": Permission denied (13)
...etc..

And then completes wit
rsync: send_files failed to open "/usr/share/omc/svcinfo.d/syslog.xml": Permission denied (13)
rsync error: some files/attrs were not transferred (see previous errors) (code 23) at main.c(1039) [sender=3.0.6]
WARNING: Command "rsync -aEAX -v --delete-excluded --chmod=Fa-w,D+w --whole-file --delete --exclude="/media/Backup/TPX60s" --exclude="/home/Gxxxx/.local/share/backintime" --include="/boot/" --include="/srv/" --include="/VAULT/Documents/" --include="/VAULT/" --include="/home/" --include="/etc/" --include="/usr/local/" --include="/usr/" --include="/usr/lib/" --include="/usr/share/" --exclude="*.backup*" --exclude="*~" --include="/boot/**" --include="/srv/**" --include="/VAULT/Documents/**" --include="/home/**" --include="/etc/**" --include="/usr/local/**" --include="/usr/lib/**" --include="/usr/share/**" --exclude="*" / "/media/Backup/TPX60s/backintime/new_snapshot/backup/"" returns 5888
INFO: Save permissions
INFO: [smart remove] keep all >= 20100111-000000
INFO: [smart remove] keep first >= 20100104-000000 and < 20100111-000000
INFO: [smart remove] keep first >= 20091228-000000 and < 20100104-000000
INFO: [smart remove] keep snapshots: ['20100112-121613', '20100112-090001', '20100111-141531']
INFO: Keep min free disk space: 200 Mb
INFO: [KDE4Plugin.Systray.run] end loop
INFO: Unlock

Why am I getting these permission errors and what are those WARNINGS?

This is the what's logged in the syslog from BiT started by the Cron job.

Jan 12 11:00:01 suntp001 /usr/sbin/cron[11440]: (Gxxxx) CMD (nice -n 19 /usr/bin/backintime --backup-job >/dev/null 2>&1)
Jan 12 11:00:01 suntp001 backintime (Gxxxx): INFO: Lock
Jan 12 11:00:01 suntp001 backintime (Gxxxx): INFO: Include folders: ['/boot', '/srv', '/VAULT/Documents', '/home', '/etc', '/usr/local', '/usr/lib', '/usr/share']
Jan 12 11:00:01 suntp001 backintime (Gxxxx): INFO: Ignore folders: []
Jan 12 11:00:01 suntp001 backintime (Gxxxx): INFO: Last snapshots: {}
Jan 12 11:00:01 suntp001 backintime (Gxxxx): INFO: [KDE4Plugin.Systray.run]
Jan 12 11:00:02 suntp001 backintime (Gxxxx): INFO: Compare with old snapshot: 20100112-090001
Jan 12 11:00:02 suntp001 backintime (Gxxxx): INFO: [KDE4Plugin.Systray.run] begin loop
Jan 12 11:15:59 suntp001 su: (to root) Gxxxx on /dev/pts/4
Jan 12 11:16:00 suntp001 su: (to root) Gxxxx on /dev/pts/4
Jan 12 11:26:04 suntp001 smartd[2752]: Device: /dev/sda [SAT], SMART Usage Attribute: 194 Temperature_Celsius changed from 148 to 144
Jan 12 11:45:54 suntp001 rsyslogd: -- MARK --
Jan 12 12:00:01 suntp001 /usr/sbin/cron[13050]: (Gxxxx) CMD (nice -n 19 /usr/bin/backintime --backup-job >/dev/null 2>&1)
Jan 12 12:00:02 suntp001 backintime (Gxxxx): WARNING: A backup is already running

Notice that a hour passes and a warning is thrown that BiT is already running. Nothing really happened during that hour and the whole time the tray icon just showed Comparing with snapshot 20100112-090001.

If you require any other info or log output let me know.

[Cyberdude (gabor-sunseaker)]

In response to Dan's questions:
>>What is your backup support ? (local drive, usb driver, remote)
>>What is your backup file systems ?

>>The command BIT runs is:
>>rsync -aEAX -v --delete-excluded --chmod=Fa-w,D+w --whole-file --delete --exclude="/media/Backup/TPX60s" --exclude="/home/Gxxxx/.local/share/backintime" --include="/boot/" --include="/srv/" --include="/VAULT/Documents/" --include="/VAULT/" --include="/home/" --include="/etc/" --include="/usr/local/" --include="/usr/" --include="/usr/lib/" --include="/usr/share/" --exclude="*.backup*" --exclude="*~" --include="/boot/**" --include="/srv/**" --include="/VAULT/Documents/**" --include="/home/**" --include="/etc/**" --include="/usr/local/**" --include="/usr/lib/**" --include="/usr/share/**" --exclude="*" / "/media/Backup/TPX60s/backintime/new_snapshot/backup/"

>>Can you try it from command line ? (Create manually "/media/Backup/TPX60s/backintime/new_snapshot/backup/" directory)

I'm backing up to a USB HDD formatted as ext4.

Running rsync from the command line seems to be working fine altough it wasn't able to complete as my HDD ran out of space.

[Cyberdude (gabor-sunseaker)]

OK, an update. As an experiment I tried a different usb HDD that was formatted as vfat. Same problem. the first snapshot worked fine but then the ones scheduled afterwards just stick at comparing.

[Dan (danleweb)]

Comparing is done using the command:
rsync -aEAX -i --dry-run --chmod=Fa-w,D+w --whole-file --delete --exclude="/media/Backup/TPX60s" --exclude="/home/Gxxxx/.local/share/backintime" --include="/boot/" --include="/srv/" --include="/VAULT/Documents/" --include="/VAULT/" --include="/home/" --include="/etc/" --include="/usr/local/" --include="/usr/" --include="/usr/lib/" --include="/usr/share/" --exclude="*.backup*" --exclude="*~" --include="/boot/**" --include="/srv/**" --include="/VAULT/Documents/**" --include="/home/**" --include="/etc/**" --include="/usr/local/**" --include="/usr/lib/**" --include="/usr/share/**" --exclude="*" / "/media/Backup/TPX60s/backintime/20100112-090001/backup/"

Please try it (modify old snapshot name if needed).
Are you having a lot of files ? (rsync can be very slow in this case)

[Cyberdude (gabor-sunseaker)]

Ok ,I ran the compare from the command line.

It all seemed to run fine but terminated with the following message.

rsync error: some files/attrs were not transferred (see previous errors) (code 23) at main.c(1039) [sender=3.0.6]

I'm backing up around 40GB so quite a lot files I guess but previously BiT would take no more than 35 mins in the worse (but ususally ~15mins) case to complete a compare and backup.

[Dan (danleweb)]

If you using ext4 please check this:
http://backintime.le-web.org/2009/04/30/system-freeze-on-ubuntu/

[Cyberdude (gabor-sunseaker)]

I don't believe I'm experiencing any ext4 related problems. Those problems were reported almost a year ago. I'm using openSUSE 11.2 with the 2.6.31 kernel and I don't have any system freezing issues with reading / writing files to the ext4 disks with other apps.

Also, the backups appear to work when run manually from the command line.

OK, I tried another experiment. I configured BiT to only backup my /boot and another folder with around 1GB of mp3. It seems to be working fine. That is backing up from a ext4 file system to a ext4 file system.

So what can the problem be? Could file permissions be causing a problem? It seems like there is a permission problem as indicated in the logs posted above. e.g.
"rsync: send_files failed to open "/boot/backup_mbr": Permission denied (13)"

Could it be the BiT is not running with the appropriate privileges? I just launched BiT as a user and configured it as necessary.

[Dan (danleweb)]

rsync tries to set user/group/right as the surce. If you are not root that you backup an item that belong to 'root', rsync will not be able to set destination file owner to root.

This is happens all the time event on a linux fs. Ex: if you backup /home/user/abx.txt
the '/home' belong to 'root' but '/home/user' and '/home/user/abc.txt' belongs to 'user'.

BIT also makes snapshots read-only.
To restore things right BIT keep a special file with this kind of information.

[Cyberdude (gabor-sunseaker)]

OK, so what is my problem? I don't know where else to look.

I tried again on my main backup drive. I launched the BiT GUI and clicked the snapshot icon to take a snapshot (Log-1). It seemed to work apart for a couple of warning with 5888 and 3072 errors. But BiT went through the complete process. Then when the next scheduled snapshot was due BIT got stuck again on compare with previous snapshot for an hour (Log-2). I then killed the python process and launched the BiT GUI and clicked the snapshot icon to take another snapshot and it worked again (Log-3). So it seems killing the python BiT process and taking another snapshot via the BiT GUi works but the scheduled snapshot doesn't. Also, I don't think the problem is that it's taking too long to compare snapshots because when I start a snapshot from the GUi it completes in about 30mins.

Log-1:

Jan 15 14:36:21 suntp001 backintime (Gxxxx): INFO: Lock
Jan 15 14:36:21 suntp001 backintime (Gxxxx): INFO: Include folders: ['/boot', '/srv', '/VAULT/Documents', '/home/Gxxxx', '/etc', '/usr/local', '/usr/lib', '/usr/share']
Jan 15 14:36:21 suntp001 backintime (Gxxxx): INFO: Ignore folders: []
Jan 15 14:36:21 suntp001 backintime (Gxxxx): INFO: Last snapshots: {}
Jan 15 14:36:21 suntp001 backintime (Gxxxx): INFO: [KDE4Plugin.Systray.run]
Jan 15 14:36:21 suntp001 backintime (Gxxxx): INFO: Compare with old snapshot: 20100113-130225
Jan 15 14:36:22 suntp001 backintime (Gxxxx): INFO: [KDE4Plugin.Systray.run] begin loop
Jan 15 14:37:08 suntp001 backintime (Gxxxx): WARNING: Command "rsync -aEAX -i --dry-run --chmod=Fa-w,D+w --whole-file --delete --exclude="/media/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/" --exclude="*.backup*" --exclude="*~" --exclude="/home/Gxxxx/.local/share/Trash/" --exclude="/home/Gxxxx/.gvfs" --exclude="/VAULT/Documents/WebSite" --exclude="/VAULT/Downloads" --include="/boot/**" --include="/srv/**" --include="/VAULT/Documents/**" --include="/home/Gxxxx/**" --include="/etc/**" --include="/usr/local/**" --include="/usr/lib/**" --include="/usr/share/**" --exclude="*" / "/media/Backup/TPX60s/backintime/20100113-130225/backup/"" returns 5888
Jan 15 14:37:08 suntp001 backintime (Gxxxx): INFO: Create hard-links
Jan 15 14:37:36 suntp001 backintime (Gxxxx): INFO: Command "cp -al "/media/Backup/TPX60s/backintime/20100113-130225/backup/"* "/media/Backup/TPX60s/backintime/new_snapshot/backup/"" returns 0
Jan 15 14:37:36 suntp001 backintime (Gxxxx): INFO: Call rsync to take the snapshot
Jan 15 14:50:45 suntp001 rsyslogd: -- MARK --
Jan 15 14:51:30 suntp001 smartd[4593]: Device: /dev/sda [SAT], SMART Usage Attribute: 194 Temperature_Celsius changed from 137 to 127
Jan 15 14:55:38 suntp001 backintime (Gxxxx): WARNING: Command "rsync -aEAX -v --delete-excluded --chmod=Fa-w,D+w --whole-file --delete --exclude="/media/Backup/TPX60s" --exclude="/home/Gxxxx/.local/share/backintime" --include="/boot/" --include="/srv/" --include="/VAULT/Documents/" --...

[Chaote (chaote)]

I Have the same problem, after an upgrade to Opensuse 11.2.
Only difference is that I am using an Ext3 fileystem.

Scheduled backup hangs but manual backup completes without problems.

[Dan (danleweb)]

By default scheduled backups runs 'nice'. There is an option in 'Expert options' tab to disable this. Please try it.

[Chaote (chaote)]

That does not help. It still hangs during backup:

ps -ef |grep back
coen 4209 4199 0 00:00 ? 00:00:00 /bin/sh -c /usr/bin/backintime --backup-job >/dev/null 2>&1
coen 4212 4209 0 00:00 ? 00:00:00 /bin/sh /usr/bin/backintime --backup-job
coen 4216 4212 0 00:00 ? 00:01:23 python /usr/share/backintime/common/backintime.py --backup-job

coen 4266 4216 0 00:00 ? 00:00:00 rsync -aEAX -i --dry-run --chmod=Fa-w,D+w --whole-file --delete --exclude=/home/backup --exclude=/home/coen/.local/share/backintime --include=/home/coen/ --include=/home/ --include=/storage/documenten/ --include=/storage/ --include=/srv/ --exclude=*~ --exclude=.tmp --exclude=.wine --exclude=.temp --exclude=/home/coen/download --include=/home/coen/** --include=/storage/documenten/** --include=/srv/** --exclude=* / /home/backup/backintime/20100115-080115/backup/

coen 4268 4266 0 00:00 ? 00:00:00 rsync -aEAX -i --dry-run --chmod=Fa-w,D+w --whole-file --delete --exclude=/home/backup --exclude=/home/coen/.local/share/backintime --include=/home/coen/ --include=/home/ --include=/storage/documenten/ --include=/storage/ --include=/srv/ --exclude=*~ --exclude=.tmp --exclude=.wine --exclude=.temp --exclude=/home/coen/download --include=/home/coen/** --include=/storage/documenten/** --include=/srv/** --exclude=* / /home/backup/backintime/20100115-080115/backup/

coen 4271 4268 0 00:00 ? 00:00:00 rsync -aEAX -i --dry-run --chmod=Fa-w,D+w --whole-file --delete --exclude=/home/backup --exclude=/home/coen/.local/share/backintime --include=/home/coen/ --include=/home/ --include=/storage/documenten/ --include=/storage/ --include=/srv/ --exclude=*~ --exclude=.tmp --exclude=.wine --exclude=.temp --exclude=/home/coen/download --include=/home/coen/** --include=/storage/documenten/** --include=/srv/** --exclude=* / /home/backup/backintime/20100115-080115/backup/

If I manualy kill the "python /usr/share/backintime/common/backintime.py --backup-job" thread the rest stops after a few minutes.

[Cyberdude (gabor-sunseaker)]

Disabling 'Nice' in the expert options didn't help me either.

[Dan (danleweb)]

You said it stopped working "fresh installation of openSUSE 11.2".
Before it was working ? On the same version ?
If it fails only on openSUSE 11.2 I can try it on a VBox.

[Cyberdude (gabor-sunseaker)]

It was working perfectly with openSUSE 11.1. I then did a clean installation of 11.2 replacing 11.1 on my laptop over Christmas. After than BiT started giving me problems. I copied the BiT configuration over from my 11.1 installation. I also tried a clean configuration of BiT but that didn't help.

My installation is 11.2 using KDE 4.3.4 with ext 4 filesystem on the backup drive and my system.

[Dan (danleweb)]

I didn't know you are using kde4 version.
I think this is a duplicate of the bug: https://bugs.launchpad.net/backintime/+bug/441628 (and it's duplicates).
You should try the beta version. There is an Ubuntu repository but for OpenSUSE you need to build it from sources (you can checkout sources from launchpad).

[Cyberdude (gabor-sunseaker)]

Hi Dan. I'm sorry I didn't make it clear that I'm using KDE4 but it was in my logs (KDE4systray...) so I didn't think to point it out explicitly.

I'm not sure if the link to bug 441628 is the same bug. I never did experience the problems reported in that bug, i.e. the tray icon not terminating. As you see from my logs above, the process never goes beyond comparing old snapshots.

I will try as you suggest the beta version but I'm quite inexperienced with Linux so it'll take me a little time to try build it from source.

[Dan (danleweb)]

Hi Cyberdude,

I think there is a easier way to see if this bug is related to kde4plugin.
You need to rename kde4plugin.py (ex: kde4plugin.py.org) so it won't be loaded.
The file should be installed in: /usr/share/backintime/plugins/
This plugin is just to display systray icon so it won't interrupt backup process.

[Cyberdude (gabor-sunseaker)]

OK. I've renamed the kde4plugin.py file and now the scheduled backups are working and completing. So it appears the problem is related to the kde4plugin. But what changed recently? I used KDE4.3.4 with openSUSE 11.1 and BiT worked fine so I and am using the same KDE version in openSUSE 11.2.

I'm still getting the warning though.

Do you know what they mean?

WARNING: Command "rsync -aEAX -i --dry-run --chmod=Fa-w,D+w --whole-file --delete --exclude="/media/Backup/TPX60s" --exclude="/home/Gabor/.local/share/backintime" --include="/boot/" --include="/srv/" --include="/VAULT/Documents/" --include="/VAULT/" --include="/home/Gabor/" --include="/home/" --include="/etc/" --include="/usr/local/" --include="/usr/" --include="/usr/lib/" --include="/usr/share/" --exclude="*.backup*" --exclude="*~" --exclude="/home/Gabor/.local/share/Trash/" --exclude="/home/Gabor/.gvfs" --exclude="/VAULT/Documents/WebSite" --exclude="/VAULT/Downloads" --include="/boot/**" --include="/srv/**" --include="/VAULT/Documents/**" --include="/home/Gabor/**" --include="/etc/**" --include="/usr/local/**" --include="/usr/lib/**" --include="/usr/share/**" --exclude="*" / "/media/Backup/TPX60s/backintime/20100119-111001/backup/"" returns 5888

And...

WARNING: Command "rsync -aEAX -v --delete-excluded --chmod=Fa-w,D+w --whole-file --delete --exclude="/media/Backup/TPX60s" --exclude="/home/Gabor/.local/share/backintime" --include="/boot/" --include="/srv/" --include="/VAULT/Documents/" --include="/VAULT/" --include="/home/Gabor/" --include="/home/" --include="/etc/" --include="/usr/local/" --include="/usr/" --include="/usr/lib/" --include="/usr/share/" --exclude="*.backup*" --exclude="*~" --exclude="/home/Gabor/.local/share/Trash/" --exclude="/home/Gabor/.gvfs" --exclude="/VAULT/Documents/WebSite" --exclude="/VAULT/Downloads" --include="/boot/**" --include="/srv/**" --include="/VAULT/Documents/**" --include="/home/Gabor/**" --include="/etc/**" --include="/usr/local/**" --include="/usr/lib/**" --include="/usr/share/**" --exclude="*" / "/media/Backup/TPX60s/backintime/new_snapshot/backup/"" returns 5888

Shouldn't these be returning 0 and not 5888?

[Dan (danleweb)]

Well, no. When rsync transfer files/directories it tries to set them the source user/group/rights.
If you backup /home/user/abc.txt then:
- /home belongs to 'root'
- /home/user & /home/user/abc.txt belongs to 'user'

If you run BIT as 'user' you can't set '<path to snapshot>/home' owner to 'root'.
This is why you receive the 5888 warning.

[Dan (danleweb)]

kde4plugin bug is related to kde4/qt4/pyKDE4 libraries. Maybe OpenSUSE 11.2 use different version of this libraries. Maybe older versions didn't crashed ...

If this answer your question I'll mark this bug as duplicate for bug 441628 since kde4plugin is the real problem.

[Cyberdude (gabor-sunseaker)]

OK, thanks for clarifying. So I have nothing to worry about - my snapshots are working fine and I should be able to restore them without permission problems - correct? If these warnings are nothing to worry about then yes you can mark this as duplicate of bug 441628.

openSUSE switch from QT4.5 to QT4.6 going from 11.1 to 11.2 so perhaps that's where the problem got introduced.

[Dan (danleweb)]

Restore is like backup you may encounter the same warning.
It is safer this way to backup/restore user data than running it as root.