Retry backup after network interruption (broken pipe)

bit-team / backintime

Back In Time - An easy-to-use backup tool for GNU/Linux using rsync in the back

https://backintime.readthedocs.io

GNU General Public License v2.0

2.09k stars 204 forks source link

Retry backup after network interruption (broken pipe) #244

Closed Germar closed 2 years ago

Germar commented 9 years ago

I switched today from local backups to backups via ssh (moved the external hdd from my laptop to my raspberry). I cannot backup anymore, as each backup run fails with the error:

[E] Error: rsync: writefd_unbuffered failed to write 4 bytes to socket [sender]: Broken pipe (32)

Back In Time should detect a network problem/closed connection and reconnect, or try to keep the connection alive in the first place.

Imported from Launchpad using lp2gh.

date created: 2013-10-05T22:44:05Z
owner: simon-harhues
the launchpad url was https://bugs.launchpad.net/bugs/1235804

Germar commented 9 years ago

(by germar) Can you please add 'ServerAliveInterval 60' to your /etc/ssh/ssh_config and report back if this helps?

Germar commented 9 years ago

(by simon-harhues) I already do have 'ServerAliveInterval 60' in "/root/.ssh/config" (Back In Time runs as root). (As I use sshfs to mount a patition on another external hdd of my raspberry to my laptop)

Germar commented 9 years ago

(by simon-harhues) correction: 'ServerAliveInterval 15' is my value.

Germar commented 9 years ago

(by germar) Can you please post the output of 'grep backintime /var/log/syslog' and 'sudo grep "^[[IE]]" /root/.local/share/backintime/takesnapshot_.log'

Germar commented 9 years ago

(by simon-harhues)

simon@laptop:~$ grep backintime /var/log/syslog
Oct  6 19:15:02 laptop CRON[16397]: (root) CMD (test -x /usr/sbin/anacron && test -e /root/.config/backintime/anacrontab && /usr/sbin/anacron -s -t /root/.config/backintime/anacrontab -S /root/.local/share/backintime/anacron)
Oct  6 19:30:01 laptop CRON[16499]: (root) CMD (test -x /usr/sbin/anacron && test -e /root/.config/backintime/anacrontab && /usr/sbin/anacron -s -t /root/.config/backintime/anacrontab -S /root/.local/share/backintime/anacron)
Oct  6 19:45:01 laptop CRON[16637]: (root) CMD (test -x /usr/sbin/anacron && test -e /root/.config/backintime/anacrontab && /usr/sbin/anacron -s -t /root/.config/backintime/anacrontab -S /root/.local/share/backintime/anacron)
Oct  6 20:00:01 laptop CRON[16820]: (root) CMD (nice -n 19 ionice -c2 -n7 /usr/bin/backintime  --backup-job >/dev/null 2>&1)
Oct  6 20:00:01 laptop CRON[16822]: (root) CMD (test -x /usr/sbin/anacron && test -e /root/.config/backintime/anacrontab && /usr/sbin/anacron -s -t /root/.config/backintime/anacrontab -S /root/.local/share/backintime/anacron)
Oct  6 20:00:01 laptop backintime (root): INFO: Lock
Oct  6 20:00:02 laptop backintime (root): ERROR: Entsperren des privaten SSH Schlüssels fehlgeschlagen. Falsches Passwort oder das Passwort war nicht verfügbar für cron.
Oct  6 20:00:02 laptop backintime (root): INFO: Unlock
Oct  6 20:15:01 laptop CRON[17035]: (root) CMD (test -x /usr/sbin/anacron && test -e /root/.config/backintime/anacrontab && /usr/sbin/anacron -s -t /root/.config/backintime/anacrontab -S /root/.local/share/backintime/anacron)
Oct  6 20:30:01 laptop CRON[17166]: (root) CMD (test -x /usr/sbin/anacron && test -e /root/.config/backintime/anacrontab && /usr/sbin/anacron -s -t /root/.config/backintime/anacrontab -S /root/.local/share/backintime/anacron)
Oct  6 20:45:01 laptop CRON[17311]: (root) CMD (test -x /usr/sbin/anacron && test -e /root/.config/backintime/anacrontab && /usr/sbin/anacron -s -t /root/.config/backintime/anacrontab -S /root/.local/share/backintime/anacron)
Oct  6 21:00:01 laptop CRON[17461]: (root) CMD (test -x /usr/sbin/anacron && test -e /root/.config/backintime/anacrontab && /usr/sbin/anacron -s -t /root/.config/backintime/anacrontab -S /root/.local/share/backintime/anacron)
Oct  6 21:00:01 laptop CRON[17462]: (root) CMD (nice -n 19 ionice -c2 -n7 /usr/bin/backintime  --backup-job >/dev/null 2>&1)
Oct  6 21:00:01 laptop backintime (root): INFO: Lock
Oct  6 21:00:02 laptop backintime (root): ERROR: Entsperren des privaten SSH Schlüssels fehlgeschlagen. Falsches Passwort oder das Passwort war nicht verfügbar für cron.
Oct  6 21:00:02 laptop backintime (root): INFO: Unlock
simon@laptop:~$ sudo grep "^\[[IE]\]" /root/.local/share/backintime/takesnapshot_.log
[sudo] password for simon: 
simon@laptop:~$

The problem with the "wrong" ssh pasphrase for the private key seems to be an additional problem (which is especially bad as if you start backintime a dialogue pops up saying that the passphrase was false and then closes(!) backintime after confirming the dialogue). The caching of the passphrase seems not to work/corrupt the passphrase. But I wanted to solve the other one first before I go to the next one... ;)

I just started another backup process manually to make sure that the erroneous try is the last one showing up in the logs. I'll post the additional infos once it is failed.

Germar commented 9 years ago

(by germar) There is no snapshot process in this logs. So I'll wait for your current snapshot and those logs.

Just to minimize possible errors can you please run that snapshot over wired network (no Wifi). Also please monitor the RAM ('free -ths2') on your Raspberry. I've read that those 'Broken pipe' errors can happen because of the remote machine runs out of memory and the Pi doesn't have that much at all (maybe you could create a big swap on your external).

Germar commented 9 years ago

(by simon-harhues) This try was over wifi again and I didn't monitor memory either. But I'll give it another try. Memory could indead be a problem if it is neccesary to have the full file in memory(?) as the broken pipe happened during quite big files if I remember correctly. Nevertheless in case it helps, here the logs from last try again:

simon@laptop:~$ grep backintime /var/log/syslog
Oct  6 19:15:02 laptop CRON[16397]: (root) CMD (test -x /usr/sbin/anacron && test -e /root/.config/backintime/anacrontab && /usr/sbin/anacron -s -t /root/.config/backintime/anacrontab -S /root/.local/share/backintime/anacron)
Oct  6 19:30:01 laptop CRON[16499]: (root) CMD (test -x /usr/sbin/anacron && test -e /root/.config/backintime/anacrontab && /usr/sbin/anacron -s -t /root/.config/backintime/anacrontab -S /root/.local/share/backintime/anacron)
Oct  6 19:45:01 laptop CRON[16637]: (root) CMD (test -x /usr/sbin/anacron && test -e /root/.config/backintime/anacrontab && /usr/sbin/anacron -s -t /root/.config/backintime/anacrontab -S /root/.local/share/backintime/anacron)
Oct  6 20:00:01 laptop CRON[16820]: (root) CMD (nice -n 19 ionice -c2 -n7 /usr/bin/backintime  --backup-job >/dev/null 2>&1)
Oct  6 20:00:01 laptop CRON[16822]: (root) CMD (test -x /usr/sbin/anacron && test -e /root/.config/backintime/anacrontab && /usr/sbin/anacron -s -t /root/.config/backintime/anacrontab -S /root/.local/share/backintime/anacron)
Oct  6 20:00:01 laptop backintime (root): INFO: Lock
Oct  6 20:00:02 laptop backintime (root): ERROR: Entsperren des privaten SSH Schlüssels fehlgeschlagen. Falsches Passwort oder das Passwort war nicht verfügbar für cron.
Oct  6 20:00:02 laptop backintime (root): INFO: Unlock
Oct  6 20:15:01 laptop CRON[17035]: (root) CMD (test -x /usr/sbin/anacron && test -e /root/.config/backintime/anacrontab && /usr/sbin/anacron -s -t /root/.config/backintime/anacrontab -S /root/.local/share/backintime/anacron)
Oct  6 20:30:01 laptop CRON[17166]: (root) CMD (test -x /usr/sbin/anacron && test -e /root/.config/backintime/anacrontab && /usr/sbin/anacron -s -t /root/.config/backintime/anacrontab -S /root/.local/share/backintime/anacron)
Oct  6 20:45:01 laptop CRON[17311]: (root) CMD (test -x /usr/sbin/anacron && test -e /root/.config/backintime/anacrontab && /usr/sbin/anacron -s -t /root/.config/backintime/anacrontab -S /root/.local/share/backintime/anacron)
Oct  6 21:00:01 laptop CRON[17461]: (root) CMD (test -x /usr/sbin/anacron && test -e /root/.config/backintime/anacrontab && /usr/sbin/anacron -s -t /root/.config/backintime/anacrontab -S /root/.local/share/backintime/anacron)
Oct  6 21:00:01 laptop CRON[17462]: (root) CMD (nice -n 19 ionice -c2 -n7 /usr/bin/backintime  --backup-job >/dev/null 2>&1)
Oct  6 21:00:01 laptop backintime (root): INFO: Lock
Oct  6 21:00:02 laptop backintime (root): ERROR: Entsperren des privaten SSH Schlüssels fehlgeschlagen. Falsches Passwort oder das Passwort war nicht verfügbar für cron.
Oct  6 21:00:02 laptop backintime (root): INFO: Unlock
Oct  6 21:11:29 laptop backintime (root): INFO: mount ssh: pi@192.168.0.254:/mnt/backup on /tmp/backintime/root/mnt/2A77923B/mountpoint
Oct  6 21:12:39 laptop backintime (root): INFO: Lock
Oct  6 21:12:43 laptop backintime (root): INFO: Mountpoint /tmp/backintime/root/mnt/2A77923B/mountpoint is already mounted
Oct  6 21:12:43 laptop backintime (root): INFO: on process begins
Oct  6 21:12:43 laptop backintime (root): INFO: [GnomePlugin.Systray.run]
Oct  6 21:12:43 laptop backintime (root): INFO: [GnomePlugin.Systray.run] begin loop
Oct  6 21:12:43 laptop backintime (root): INFO: Profile_id: 2
Oct  6 21:12:43 laptop backintime (root): INFO: Compare with old snapshot: 20130918-000001-846
Oct  6 21:14:00 laptop backintime (root): INFO: Command "rsync -rtDH --links --no-p --no-g --no-o --rsh="ssh -p 2222 "  --delete --delete-excluded  -i --dry-run --out-format="BACKINTIME: %i %n%L" --chmod=Du+wx  --exclude="/tmp/backintime/root/2_17797" --exclude="/root/.local/share/backintime" --exclude="/tmp/backintime" --include="/mnt/media/" --include="/mnt/" --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="/tmp/backintime" --include="/mnt/media/**" --exclude="*" / 'pi@192.168.0.254:"/mnt/backup/backintime/laptop/root/2/20130918-000001-846/backup/"'" returns 0
Oct  6 21:14:00 laptop backintime (root): INFO: Create hard-links
Oct  6 21:14:07 laptop backintime (root): INFO: Command "ssh -p 2222  pi@192.168.0.254 'find "/mnt/backup/backintime/laptop/root/2/20130918-000001-846/backup/" -type d -exec chmod u+wx "{}" +'" returns 0
Oct  6 21:14:39 laptop backintime (root): INFO: Command "ssh -p 2222  pi@192.168.0.254 cp -aRl "/mnt/backup/backintime/laptop/root/2/20130918-000001-846/backup/"* "/mnt/backup/backintime/laptop/root/2/new_snapshot/backup/"" returns 0
Oct  6 21:14:44 laptop backintime (root): INFO: Command "ssh -p 2222  pi@192.168.0.254 'find "/mnt/backup/backintime/laptop/root/2/20130918-000001-846/backup/" -type d -exec chmod a-w "{}" +'" returns 0
Oct  6 21:14:51 laptop backintime (root): INFO: Command "ssh -p 2222  pi@192.168.0.254 chmod -R a+w "/mnt/backup/backintime/laptop/root/2/new_snapshot"" returns 0
Oct  6 21:14:51 laptop backintime (root): INFO: Call rsync to take the snapshot
Oct  6 21:15:01 laptop CRON[17856]: (root) CMD (test -x /usr/sbin/anacron && test -e /root/.config/backintime/anacrontab && /usr/sbin/anacron -s -t /root/.config/backintime/anacrontab -S /root/.local/share/backintime/anacron)
Oct  6 21:30:01 laptop CRON[18001]: (root) CMD (test -x /usr/sbin/anacron && test -e /root/.config/backintime/anacrontab && /usr/sbin/anacron -s -t /root/.config/backintime/anacrontab -S /root/.local/share/backintime/anacron)
Oct  6 21:45:01 laptop CRON[18156]: (root) CMD (test -x /usr/sbin/anacron && test -e /root/.config/backintime/anacrontab && /usr/sbin/anacron -s -t /root/.config/backintime/anacrontab -S /root/.local/share/backintime/anacron)
Oct  6 22:00:01 laptop CRON[18302]: (root) CMD (test -x /usr/sbin/anacron && test -e /root/.config/backintime/anacrontab && /usr/sbin/anacron -s -t /root/.config/backintime/anacrontab -S /root/.local/share/backintime/anacron)
Oct  6 22:00:01 laptop CRON[18303]: (root) CMD (nice -n 19 ionice -c2 -n7 /usr/bin/backintime  --backup-job >/dev/null 2>&1)
Oct  6 22:00:01 laptop backintime (root): INFO: Lock
Oct  6 22:00:01 laptop backintime (root): ERROR: Entsperren des privaten SSH Schlüssels fehlgeschlagen. Falsches Passwort oder das Passwort war nicht verfügbar für cron.
Oct  6 22:00:01 laptop backintime (root): INFO: Unlock
Oct  6 22:03:29 laptop backintime (root): WARNING: Command "rsync -rtDH --links --no-p --no-g --no-o --rsh="ssh -p 2222 "  --delete --delete-excluded  -v  --chmod=Du+wx  --exclude="/tmp/backintime/root/2_17797" --exclude="/root/.local/share/backintime" --exclude="/tmp/backintime" --include="/mnt/media/" --include="/mnt/" --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="/tmp/backintime" --include="/mnt/media/**" --exclude="*" / 'pi@192.168.0.254:"/mnt/backup/backintime/laptop/root/2/new_snapshot/backup/"' 2>&1" returns 65280
Oct  6 22:03:29 laptop backintime (root): WARNING: Command "ssh -p 2222  pi@192.168.0.254 'find "/mnt/backup/backintime/laptop/root/2/new_snapshot" -type d -exec chmod u+wx "{}" +'" returns 65280
Oct  6 22:03:29 laptop backintime (root): WARNING: Command "ssh -p 2222  pi@192.168.0.254 rm -rf "/mnt/backup/backintime/laptop/root/2/new_snapshot"" returns 65280
Oct  6 22:03:29 laptop backintime (root): WARNING: Command "ssh -p 2222  pi@192.168.0.254 chmod -R a-w "/mnt/backup/backintime/laptop/root/2/20130918-000001-846/backup/"" returns 65280
Oct  6 22:03:29 laptop backintime (root): INFO: Command "rm -rf "/tmp/backintime/root/2_17797/backintime/laptop/root/2/20131006-211239-828"" returns 0
Oct  6 22:03:29 laptop backintime (root): ERROR: Failed to take snapshot !!!
Oct  6 22:03:34 laptop backintime (root): INFO: [GnomePlugin.Systray.run] end loop
Oct  6 22:03:34 laptop backintime (root): INFO: Mountpoint /tmp/backintime/root/mnt/2A77923B is not mounted
Oct  6 22:03:34 laptop backintime (root): INFO: Unlock
Oct  6 22:15:01 laptop CRON[18894]: (root) CMD (test -x /usr/sbin/anacron && test -e /root/.config/backintime/anacrontab && /usr/sbin/anacron -s -t /root/.config/backintime/anacrontab -S /root/.local/share/backintime/anacron)
Oct  6 22:30:01 laptop CRON[19304]: (root) CMD (test -x /usr/sbin/anacron && test -e /root/.config/backintime/anacrontab && /usr/sbin/anacron -s -t /root/.config/backintime/anacrontab -S /root/.local/share/backintime/anacron)
simon@laptop:~$ sudo grep "^\[[IE]\]" /root/.local/share/backintime/takesnapshot_.log
[sudo] password for simon: 
simon@laptop:~$

Germar commented 9 years ago

(by germar) You're using profile id 2. So the 2nd command must be 'sudo grep "^[[IE]]" /root/.local/share/backintime/takesnapshot_2.log'

It looks like the remote sshd died completely during the second rsync command. Even 'find', 'rm' and 'chmod' didn't work anymore. Please check syslog and auth.log on your Raspberry for suspicious sshd messages.

Germar commented 9 years ago

(by simon-harhues) Ah, sry, I wasn't aware that the number corresponded to the profile (and not to some log rotate or so). But the output is empty as well:

simon@laptop:~$ sudo grep "^\[[IE]\]" /root/.local/share/backintime/takesnapshot_2.log
[sudo] password for simon: 
simon@laptop:~$

On the raspberry: In the syslog I found some of the following line (all and only for that time!), but I cannot interpret it:

Oct  6 14:40:59 raspberrypi kernel: [241893.650769] sshd: page allocation failure: order:0, mode:0x20

In the authlog I get lots of following lines, but that might be normal (as I said before I mounted one of the external hhd's via sshfs to my laptop)?

Oct  6 22:59:23 raspberrypi sshd[4173]: pam_unix(sshd:session): session closed for user pi
Oct  6 22:59:24 raspberrypi sshd[4184]: Accepted publickey for pi from 192.168.0.10 port 40296 ssh2
Oct  6 22:59:24 raspberrypi sshd[4184]: pam_unix(sshd:session): session opened for user pi by (uid=0)
Oct  6 23:07:16 raspberrypi sshd[3851]: pam_unix(sshd:session): session closed for user pi
Oct  6 23:40:58 raspberrypi sshd[4308]: Accepted publickey for pi from 192.168.0.10 port 40544 ssh2
Oct  6 23:40:59 raspberrypi sshd[4308]: pam_unix(sshd:session): session opened for user pi by (uid=0)

Germar commented 9 years ago

(by germar) 'page allocation failure' indicates a RAM problem. Did this happen only on Oct 6 14:40 or every time Backintime failed to take a snapshot?

Please increase swap on your Raspberry. I know it's not nice to have swap on an external USB drive. But if that will fix this we could try to minimize remote memory consumption in the next step.

Germar commented 9 years ago

(by simon-harhues) Only on that time. (But I have to admit that I lost a little the overview when snapshots were taken, specially as the caching of the ssh key passphrase does not work). I'll increase the swapfile later (still some space left on the sd memory card), but atm I'm still trying to take another snapshot over the cable (as back in time seems not to recognise that the files just were moved [due to a new mount point], it is like a full backup and takes some time). A memory issue sounds reasonable with a raspberry, but I have to say atm memory consumption looks quite small:

             total       used       free     shared    buffers     cached
Mem:          465M       414M        50M         0B        35M       287M
-/+ buffers/cache:        92M       372M
Swap:         511M        10M       501M
Total:        977M       425M       552M

Germar commented 9 years ago

(by germar) In #7 you mentioned that the error occur always on some big files. Can you please exclude them to test if BIT will correctly create a new snapshot without those and/or manually transfer those with:

rsync -rtDH --links --no-p --no-g --no-o --rsh="ssh -p 2222 " -v --chmod=Du+wx /path/to/big/file 'pi@192.168.0.254:"/mnt/backup/"'

Germar commented 9 years ago

(by simon-harhues) Tried again. First of all, forget the memory stats from yesterday, back in time seemed to have hang at that time already... My set up today:

backup of first profile (basically home and some stuff in /, in general no big multi media files)
raspberry addressed via wired LAN
deactivated the ownCloud sync-client (which lead to a constant load of 2 on the raspberry due to a bug I noticed yesterday [0])
second external hdd on raspberry was not mounted via sshfs to laptop (taking some sshd load of from the raspberry I guess)
resized swap file on sd card of the raspberry to 3GB

Result: snapshot completed without errors. hurray. During the backup the memory consumption on the raspberry was high (>450M of 465M, leaving only around 12M free), but swap was not used at all. Just when the intelligent removing started, around 10-20M of Swap was used. The load on the raspberry was constantly between 2 and 3 (normally it now idles with <0.05).

I believe the back in time log look okay:

simon@laptop:~$ sudo tail -n8 /root/.local/share/backintime/takesnapshot_.log | grep "^\[[IE]\]"
[I] Snapshot erstellen (rsync: sent 525630290 bytes  received 1542070 bytes  735760.45 bytes/sec)
[I] Snapshot erstellen (rsync: total size is 105675389875  speedup is 200.46)
[I] Einstellungen speichern ...
[I] Speichere Zugriffsrechte ...
[I] Alte Schnappschüsse entfernen
[I] intelligentes Löschen
[I] Versuche mindestens 2% freie inodes zu behalten.
[I] Finalisierung läuft
simon@laptop:~$ sudo grep "^\[[E]\]" /root/.local/share/backintime/takesnapshot_.log
simon@laptop:~$

Not sure about the attached syslog, some ssh calls contain error codes > 0.

It's great that the backup worked so far, but I want to try/achieve following backup situation in addition:

via wifi and LAN
via wifi and internet
while second hdd is mounted via sshfs on raspberry
second profile (containing photos and videos)
having ownCloud-client running Do you know if there is any algorithm implemented into back in time (or maybe the underlying technologies [e.g. sshfs, ssh, rsync]) yet to handle network problems user transparent? Or doesn't it make sense that I try a backup via wifi/wifi+internet at all?

Thank you for all the help so far!

[0] https://github.com/owncloud/mirall/issues/1078

Germar commented 9 years ago

(by germar) All ssh commands returned 256. Please post the output of 'ssh -vv -p 2222 pi@192.168.0.254 echo foobar'.

What system is running on the Raspberry? Is this a Debian?

It should be fine to use Wifi and Internet. If your dest. drive is ext you should use 'Full rsync mode' because it's lot faster and will add less load on your Raspberry. If it is NTFS you should consider reformating because Linux ntfs implementation will always take more resources than ext.

Germar commented 9 years ago

(by simon-harhues) Just saw your comment #12. I already started another snapshot, with profile two (including the big files), after mounting the folder via sshfs. Except from that, everything is like the earlier try #13 today.

Germar commented 9 years ago

(by simon-harhues) Regarding #14:

simon@laptop:~$ ssh -vv -p 2222 pi@192.168.0.254 echo foobar
OpenSSH_6.1p1 Debian-4, OpenSSL 1.0.1c 10 May 2012
debug1: Reading configuration data /home/simon/.ssh/config
debug1: Reading configuration data /etc/ssh/ssh_config
debug1: /etc/ssh/ssh_config line 19: Applying options for *
debug2: ssh_connect: needpriv 0
debug1: Connecting to 192.168.0.254 [192.168.0.254] port 2222.
debug1: Connection established.
debug1: identity file /home/simon/.ssh/id_rsa type 1
debug1: Checking blacklist file /usr/share/ssh/blacklist.RSA-2048
debug1: Checking blacklist file /etc/ssh/blacklist.RSA-2048
debug1: identity file /home/simon/.ssh/id_rsa-cert type -1
debug1: identity file /home/simon/.ssh/id_dsa type -1
debug1: identity file /home/simon/.ssh/id_dsa-cert type -1
debug1: identity file /home/simon/.ssh/id_ecdsa type -1
debug1: identity file /home/simon/.ssh/id_ecdsa-cert type -1
debug1: Remote protocol version 2.0, remote software version OpenSSH_6.0p1 Debian-4
debug1: match: OpenSSH_6.0p1 Debian-4 pat OpenSSH*
debug1: Enabling compatibility mode for protocol 2.0
debug1: Local version string SSH-2.0-OpenSSH_6.1p1 Debian-4
debug2: fd 3 setting O_NONBLOCK
debug1: SSH2_MSG_KEXINIT sent
debug1: SSH2_MSG_KEXINIT received
debug2: kex_parse_kexinit: ecdh-sha2-nistp256,ecdh-sha2-nistp384,ecdh-sha2-nistp521,diffie-hellman-group-exchange-sha256,diffie-hellman-group-exchange-sha1,diffie-hellman-group14-sha1,diffie-hellman-group1-sha1
debug2: kex_parse_kexinit: <email address hidden>,<email address hidden>,<email address hidden>,<email address hidden>,<email address hidden>,<email address hidden>,<email address hidden>,ecdsa-sha2-nistp256,ecdsa-sha2-nistp384,ecdsa-sha2-nistp521,ssh-rsa,ssh-dss
debug2: kex_parse_kexinit: aes128-ctr,aes192-ctr,aes256-ctr,arcfour256,arcfour128,aes128-cbc,3des-cbc,blowfish-cbc,cast128-cbc,aes192-cbc,aes256-cbc,arcfour,<email address hidden>
debug2: kex_parse_kexinit: aes128-ctr,aes192-ctr,aes256-ctr,arcfour256,arcfour128,aes128-cbc,3des-cbc,blowfish-cbc,cast128-cbc,aes192-cbc,aes256-cbc,arcfour,<email address hidden>
debug2: kex_parse_kexinit: hmac-md5,hmac-sha1,<email address hidden>,hmac-sha2-256,hmac-sha2-512,hmac-ripemd160,<email address hidden>,hmac-sha1-96,hmac-md5-96
debug2: kex_parse_kexinit: hmac-md5,hmac-sha1,<email address hidden>,hmac-sha2-256,hmac-sha2-512,hmac-ripemd160,<email address hidden>,hmac-sha1-96,hmac-md5-96
debug2: kex_parse_kexinit: none,<email address hidden>,zlib
debug2: kex_parse_kexinit: none,<email address hidden>,zlib
debug2: kex_parse_kexinit: 
debug2: kex_parse_kexinit: 
debug2: kex_parse_kexinit: first_kex_follows 0 
debug2: kex_parse_kexinit: reserved 0 
debug2: kex_parse_kexinit: ecdh-sha2-nistp256,ecdh-sha2-nistp384,ecdh-sha2-nistp521,diffie-hellman-group-exchange-sha256,diffie-hellman-group-exchange-sha1,diffie-hellman-group14-sha1,diffie-hellman-group1-sha1
debug2: kex_parse_kexinit: ssh-rsa,ssh-dss,ecdsa-sha2-nistp256
debug2: kex_parse_kexinit: aes128-ctr,aes192-ctr,aes256-ctr,arcfour256,arcfour128,aes128-cbc,3des-cbc,blowfish-cbc,cast128-cbc,aes192-cbc,aes256-cbc,arcfour,<email address hidden>
debug2: kex_parse_kexinit: aes128-ctr,aes192-ctr,aes256-ctr,arcfour256,arcfour128,aes128-cbc,3des-cbc,blowfish-cbc,cast128-cbc,aes192-cbc,aes256-cbc,arcfour,<email address hidden>
debug2: kex_parse_kexinit: hmac-md5,hmac-sha1,<email address hidden>,hmac-sha2-256,hmac-sha2-256-96,hmac-sha2-512,hmac-sha2-512-96,hmac-ripemd160,<email address hidden>,hmac-sha1-96,hmac-md5-96
debug2: kex_parse_kexinit: hmac-md5,hmac-sha1,<email address hidden>,hmac-sha2-256,hmac-sha2-256-96,hmac-sha2-512,hmac-sha2-512-96,hmac-ripemd160,<email address hidden>,hmac-sha1-96,hmac-md5-96
debug2: kex_parse_kexinit: none,<email address hidden>
debug2: kex_parse_kexinit: none,<email address hidden>
debug2: kex_parse_kexinit: 
debug2: kex_parse_kexinit: 
debug2: kex_parse_kexinit: first_kex_follows 0 
debug2: kex_parse_kexinit: reserved 0 
debug2: mac_setup: found hmac-md5
debug1: kex: server->client aes128-ctr hmac-md5 none
debug2: mac_setup: found hmac-md5
debug1: kex: client->server aes128-ctr hmac-md5 none
debug1: sending SSH2_MSG_KEX_ECDH_INIT
debug1: expecting SSH2_MSG_KEX_ECDH_REPLY
debug1: Server host key: ECDSA e4:03:4b:3c:e4:83:a8:fe:80:35:fc:11:d4:9a:13:b0
debug1: checking without port identifier
debug1: Host '192.168.0.254' is known and matches the ECDSA host key.
debug1: Found key in /home/simon/.ssh/known_hosts:16
debug1: found matching key w/out port
debug1: ssh_ecdsa_verify: signature correct
debug2: kex_derive_keys
debug2: set_newkeys: mode 1
debug1: SSH2_MSG_NEWKEYS sent
debug1: expecting SSH2_MSG_NEWKEYS
debug2: set_newkeys: mode 0
debug1: SSH2_MSG_NEWKEYS received
debug1: Roaming not allowed by server
debug1: SSH2_MSG_SERVICE_REQUEST sent
debug2: service_accept: ssh-userauth
debug1: SSH2_MSG_SERVICE_ACCEPT received
debug2: key: /home/simon/.ssh/id_rsa (0x7fcc9db42930)
debug2: key: /home/simon/.ssh/id_dsa ((nil))
debug2: key: /home/simon/.ssh/id_ecdsa ((nil))
debug1: Authentications that can continue: publickey
debug1: Next authentication method: publickey
debug1: Offering RSA public key: /home/simon/.ssh/id_rsa
debug2: we sent a publickey packet, wait for reply
debug1: Server accepts key: pkalg ssh-rsa blen 279
debug2: input_userauth_pk_ok: fp 9c:c3:dc:18:58:b0:0f:37:68:f2:f8:ce:d5:bd:ae:44
debug1: Authentication succeeded (publickey).
Authenticated to 192.168.0.254 ([192.168.0.254]:2222).
debug1: channel 0: new [client-session]
debug2: channel 0: send open
debug1: Requesting <email address hidden>
debug1: Entering interactive session.
debug2: callback start
debug2: fd 3 setting TCP_NODELAY
debug2: client_session2_setup: id 0
debug1: Sending environment.
debug1: Sending env LC_PAPER = de_DE.UTF-8
debug2: channel 0: request env confirm 0
debug1: Sending env LC_ADDRESS = de_DE.UTF-8
debug2: channel 0: request env confirm 0
debug1: Sending env LC_MONETARY = de_DE.UTF-8
debug2: channel 0: request env confirm 0
debug1: Sending env LC_NUMERIC = de_DE.UTF-8
debug2: channel 0: request env confirm 0
debug1: Sending env LC_TELEPHONE = de_DE.UTF-8
debug2: channel 0: request env confirm 0
debug1: Sending env LC_IDENTIFICATION = de_DE.UTF-8
debug2: channel 0: request env confirm 0
debug1: Sending env LANG = de_DE.UTF-8
debug2: channel 0: request env confirm 0
debug1: Sending env LC_MEASUREMENT = de_DE.UTF-8
debug2: channel 0: request env confirm 0
debug1: Sending env LC_TIME = de_DE.UTF-8
debug2: channel 0: request env confirm 0
debug1: Sending env LC_NAME = de_DE.UTF-8
debug2: channel 0: request env confirm 0
debug1: Sending command: echo foobar
debug2: channel 0: request exec confirm 1
debug2: callback done
debug2: channel 0: open confirm rwindow 0 rmax 32768
debug2: channel 0: rcvd adjust 2097152
debug2: channel_input_status_confirm: type 99 id 0
debug2: exec request accepted on channel 0
foobar
debug2: channel 0: rcvd eof
debug2: channel 0: output open -> drain
debug2: channel 0: obuf empty
debug2: channel 0: close_write
debug2: channel 0: output drain -> closed
debug1: client_input_channel_req: channel 0 rtype exit-status reply 0
debug1: client_input_channel_req: channel 0 rtype <email address hidden> reply 0
debug2: channel 0: rcvd eow
debug2: channel 0: close_read
debug2: channel 0: input open -> closed
debug2: channel 0: rcvd close
debug2: channel 0: almost dead
debug2: channel 0: gc: notify user
debug2: channel 0: gc: user detached
debug2: channel 0: send close
debug2: channel 0: is dead
debug2: channel 0: garbage collecting
debug1: channel 0: free: client-session, nchannels 1
Transferred: sent 3152, received 1920 bytes, in 0.2 seconds
Bytes per second: sent 18845.6, received 11479.5
debug1: Exit status 0
simon@laptop:~$

pi@raspberrypi ~ $ uname -a
Linux raspberrypi 3.6.11+ #538 PREEMPT Fri Aug 30 20:42:08 BST 2013 armv6l GNU/Linux

The hdd's are ext3 and ext4, I've changed the back in time settings according. Thanks for the hint.

Germar commented 9 years ago

(by germar) Hmm. ssh debug looks good. But this doesn't shed a light on why all ssh commands in Backintime fail with return codes > 0. It looks like they are doing their job but still return > 0 e.g. 'cp -alR' must have been successfully create new hard-links because otherwise rsync would have to transfer lot more data.

Can you please double check if permissions are correct for user 'pi' on Raspberry

Germar commented 9 years ago

(by simon-harhues) back in time also stated that the backup was successful, as written in #13. The snapshot looks good as well, I'd say, files seem to be all in place/linked. And the permissions look good as well. (as the backup now doesn't run with root anymore, I did a "chown -Rh pi" before the first backup run).

btw the other backup is (according to back in time) still running. In the status bar it shows:

In Bearbeitung: Snapshot erstellen (rsync: mnt/media/filme/2.avi)

if I open the log window, I see somewhere in the middle following lines:

[lots of more lines above...]
[C] *deleting   media/simon/media/filme/7.avi
[C] *deleting   media/simon/media/filme/3.avi
[C] *deleting   media/simon/media/filme/2.avi
[C] *deleting   media/simon/media/filme/
[C] *deleting   media/simon/media/
[C] *deleting   media/simon/
[C] *deleting   media/
[C] cd+++++++++ mnt/
[C] cd+++++++++ mnt/media/
[C] cd+++++++++ mnt/media/filme/
[C] <f+++++++++ mnt/media/filme/2.avi
[C] <f+++++++++ mnt/media/filme/3.avi
[C] <f+++++++++ mnt/media/filme/7.avi
[lots of more lines below...]

If I look on the raspberry in the backup folder "new_snapshot" I see the whole directory tree is already there, but no single file (no film, no photo). The raspberry seems to be not to busy, load of around 1, bur memory consumption is quite high: 374M (18M in swap).

pi@raspberrypi ~ $ ps aux | grep sshd
root     26851  0.0  0.0   6208   332 ?        Ss   16:39   0:00 /usr/sbin/sshd
root     27037  0.0  0.0   9768     0 ?        Ss   17:03   0:00 sshd: pi [priv]  
pi       27115  0.0  0.0   9768   316 ?        S    17:03   0:03 sshd: pi@pts/0   
root     27136  0.0  0.0   9768     0 ?        Ss   17:06   0:00 sshd: pi [priv]  
pi       27143  0.1  0.0   9768   316 ?        S    17:06   0:34 sshd: pi@pts/1   
root     27180  0.0  0.0   9768     0 ?        Ss   17:07   0:00 sshd: pi [priv]  
pi       27189  0.0  0.0  10068   364 ?        S    17:07   0:05 sshd: pi@notty   
root     27907  0.0  0.0   9768    76 ?        Ss   19:02   0:00 sshd: pi [priv]  
pi       27914  3.9  0.1   9908   880 ?        S    19:02   8:00 sshd: pi@notty   
root     27976  0.0  0.6   9768  3148 ?        Ss   19:06   0:00 sshd: pi [priv]  
pi       27984  0.6  0.4  10492  2208 ?        S    19:06   1:18 sshd: pi@notty   
root     28211  0.0  0.6   9768  3184 ?        Ss   20:49   0:00 sshd: pi [priv]  
pi       28218  0.0  0.3   9768  1516 ?        S    20:49   0:00 sshd: pi@pts/2   
pi       28646  0.0  0.1   4140   908 pts/2    S+   22:23   0:00 grep --color=auto sshd
pi@raspberrypi ~ $ ps aux | grep backintime
pi       27985  0.0  0.3  15940  1504 ?        Ss   19:06   0:09 rsync --server -vlHDtre.iLsf --delete-excluded . /mnt/backup/backintime/laptop/root/2/new_snapshot/backup/
pi       27986  0.2  0.2  16248  1328 ?        S    19:06   0:26 rsync --server -vlHDtre.iLsf --delete-excluded . /mnt/backup/backintime/laptop/root/2/new_snapshot/backup/
pi       28648  0.0  0.1   4136   856 pts/2    S+   22:23   0:00 grep --color=auto backintime

simon@laptop:~$ ps aux | grep ssh
simon     2571  0.0  0.0  12612   320 ?        Ss   13:36   0:00 /usr/bin/ssh-agent /usr/bin/dbus-launch --exit-with-session /usr/bin/im-launch gnome-session --session=ubuntu
simon     6478  0.0  0.0  41568  2912 pts/1    S+   17:03   0:00 ssh -p2222 pi@192.168.0.254
simon     6494  0.0  0.0  41568  2916 pts/2    S+   17:06   0:05 ssh -p2222 pi@192.168.0.254
root      6584  0.0  0.0  12612   768 ?        Ss   17:07   0:00 ssh-agent python /usr/share/backintime/gnome/app.py
root      6628  0.0  0.0  41732  3140 ?        S    17:07   0:01 ssh -x -a -oClearAllForwardings=yes -oPort=2222 -2 pi@192.168.0.254 -s sftp
root      6629  0.0  0.0 461612  1908 ?        Ssl  17:07   0:01 sshfs -p 2222 -o idmap=user pi@192.168.0.254:/mnt/backup /tmp/backintime/root/mnt/2A77923B/mountpoint
simon     7870  0.2  0.0  46148  3552 pts/3    S    19:02   0:31 ssh -x -a -oClearAllForwardings=yes -oport=2222 -ocompression=yes -2 <email address hidden> -s sftp
simon     7872  0.0  0.2 467872 18464 ?        Ssl  19:02   0:04 sshfs <email address hidden>:/mnt/media/ /mnt/media -o rw,noexec,nosuid,nodev,allow_other,port=2222,compression=yes,follow_symlinks
root      7889  0.0  0.0  12612   768 ?        Ss   19:04   0:00 ssh-agent python /usr/share/backintime/common/backintime.py --profile-id 2 --backup
root      7968  0.0  0.0   4440   628 ?        S    19:06   0:00 sh -c rsync -rtDH --links --no-p --no-g --no-o --rsh="ssh -p 2222 "  --delete --delete-excluded  -v  --chmod=Du+wx  --exclude="/tmp/backintime/root/2_7888" --exclude="/root/.local/share/backintime" --exclude="/tmp/backintime" --include="/mnt/media/" --include="/mnt/" --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="/tmp/backintime" --include="/mnt/media/**" --exclude="*" / 'pi@192.168.0.254:"/mnt/backup/backintime/laptop/root/2/new_snapshot/backup/"' 2>&1
root      7969  0.0  0.0  40456  1908 ?        D    19:06   0:04 rsync -rtDH --links --no-p --no-g --no-o --rsh=ssh -p 2222  --delete --delete-excluded -v --chmod=Du+wx --exclude=/tmp/backintime/root/2_7888 --exclude=/root/.local/share/backintime --exclude=/tmp/backintime --include=/mnt/media/ --include=/mnt/ --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=/tmp/backintime --include=/mnt/media/** --exclude=* / pi@192.168.0.254:"/mnt/backup/backintime/laptop/root/2/new_snapshot/backup/"
root      7970  0.1  0.0  42312  3436 ?        S    19:06   0:15 ssh -p 2222 -l pi 192.168.0.254 rsync --server -vlHDtre.iLsf --delete-excluded . "/mnt/backup/backintime/laptop/root/2/new_snapshot/backup/"
simon     8617  0.0  0.0  41568  2916 pts/4    S+   20:49   0:00 ssh -p2222 pi@192.168.0.254
simon     9351  0.0  0.0  13392   940 pts/5    S+   22:24   0:00 grep ssh
simon@laptop:~$ ps aux | grep backintime
simon     6576  0.1  0.2 514064 19000 ?        Sl   17:07   0:21 gksu backintime-gnome
root      6581  0.0  0.0 125664  4640 ?        Ss   17:07   0:00 /usr/bin/sudo -H -S -p GNOME_SUDO_PASS -u root -- backintime-gnome
root      6582  0.0  0.0   4440   624 ?        S    17:07   0:00 /bin/sh /usr/bin/backintime-gnome
root      6583  0.8  0.9 495236 76240 ?        S    17:07   2:50 python /usr/share/backintime/gnome/app.py
root      6584  0.0  0.0  12612   768 ?        Ss   17:07   0:00 ssh-agent python /usr/share/backintime/gnome/app.py
root      6629  0.0  0.0 461612  1908 ?        Ssl  17:07   0:01 sshfs -p 2222 -o idmap=user pi@192.168.0.254:/mnt/backup /tmp/backintime/root/mnt/2A77923B/mountpoint
root      7887  0.0  0.0   4440   624 ?        S    19:04   0:00 /bin/sh /usr/bin/backintime --profile-id 2 --backup
root      7888  0.2  0.3 508636 30492 ?        Sl   19:04   0:36 python /usr/share/backintime/common/backintime.py --profile-id 2 --backup
root      7889  0.0  0.0  12612   768 ?        Ss   19:04   0:00 ssh-agent python /usr/share/backintime/common/backintime.py --profile-id 2 --backup
root      7968  0.0  0.0   4440   628 ?        S    19:06   0:00 sh -c rsync -rtDH --links --no-p --no-g --no-o --rsh="ssh -p 2222 "  --delete --delete-excluded  -v  --chmod=Du+wx  --exclude="/tmp/backintime/root/2_7888" --exclude="/root/.local/share/backintime" --exclude="/tmp/backintime" --include="/mnt/media/" --include="/mnt/" --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="/tmp/backintime" --include="/mnt/media/**" --exclude="*" / 'pi@192.168.0.254:"/mnt/backup/backintime/laptop/root/2/new_snapshot/backup/"' 2>&1
root      7969  0.0  0.0  40456  1908 ?        D    19:06   0:04 rsync -rtDH --links --no-p --no-g --no-o --rsh=ssh -p 2222  --delete --delete-excluded -v --chmod=Du+wx --exclude=/tmp/backintime/root/2_7888 --exclude=/root/.local/share/backintime --exclude=/tmp/backintime --include=/mnt/media/ --include=/mnt/ --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=/tmp/backintime --include=/mnt/media/** --exclude=* / pi@192.168.0.254:"/mnt/backup/backintime/laptop/root/2/new_snapshot/backup/"
root      7970  0.1  0.0  42312  3436 ?        S    19:06   0:15 ssh -p 2222 -l pi 192.168.0.254 rsync --server -vlHDtre.iLsf --delete-excluded . "/mnt/backup/backintime/laptop/root/2/new_snapshot/backup/"
simon     9353  0.0  0.0  13392   940 pts/5    S+   22:25   0:00 grep backintime

The file sizes are about: 2.avi: 700M,B 3.avi:630MB, 7.avi:1.7GB I was wondering if something is still happening, but I might just have to be more patient... :)

Germar commented 9 years ago

(by simon-harhues) I just had another thought. The file "1.avi" is in really rather named "foo(bar).avi". Could the round bracket be a problem for rsync? I found a post suggesting that rsync has problems with brackets in file names and it was said that the parameter "-s", short for "--protect-args" should be used[0]. As far as I could see from the logs this parameter is not used by back in time. Could this be a problem? Would it be possible at all to use it or would the whole rsync call not work anymore (e.g. could it happen that it uses pattern?)?

[0] http://samba.2283325.n4.nabble.com/Bug-having-parentheses-in-filenames-causes-failure-td2509134.html

Germar commented 9 years ago

(by germar) Brackets should be fine. I just tested with a 1Gig "foo(bar).avi" and it didn't complain.

Germar commented 9 years ago

(by simon-harhues) I just checked for the last 15min and data seems still to be transferred (only one file atm). Unfortunately (I don't know why) it seems that speed is about 2MB/sec, a quick calculation revealed that it will take 1.25 days to complete the backup...

Germar commented 9 years ago

(by germar) The poor bandwidth is because of the weak processor in the Raspberry and strong encryption of the ssh cipher. If you are in a trusted network (wired network at home) you can use a weaker but faster cipher. I'm using 'arcfour' with my NAS (ARM 380MHz) which will make it to 3,6MB/s. The default cipher 'AES128-cbc' only makes 1,4MB/s. 'Blowfish' is quite fast (2,7MB/s), too. You can run 'backintime --benchmark-cipher' to see how fast each cipher is. But please read some security advices before using a non default cipher in untrusted networks (internet). 'Arcfour' and '3des' should be handled as not secure anymore.

Germar commented 9 years ago

(by simon-harhues) My fist guess was the small usb-host on the raspberry, as the load was "only" around 1-2 but around 50% WA. I run the benchmark, the results look all pretty slow (not sure why I get two numbers for each, if that is de-/encrypt or to prevent measurement errors):

3des-cbc:
tmpasY7EH                                     100%   40MB 819.2KB/s   00:50    
tmpasY7EH                                     100%   40MB 758.5KB/s   00:54    
aes128-cbc:
tmpasY7EH                                     100%   40MB 930.9KB/s   00:44    
tmpasY7EH                                     100%   40MB 772.8KB/s   00:53    
aes128-ctr:
tmpasY7EH                                     100%   40MB 787.7KB/s   00:52    
tmpasY7EH                                     100%   40MB 803.1KB/s   00:51    
aes192-cbc:
tmpasY7EH                                     100%   40MB 772.8KB/s   00:53    
tmpasY7EH                                     100%   40MB 853.3KB/s   00:48    
aes192-ctr:
tmpasY7EH                                     100%   40MB 772.8KB/s   00:53    
tmpasY7EH                                     100%   40MB 819.2KB/s   00:50    
aes256-cbc:
tmpasY7EH                                     100%   40MB 706.2KB/s   00:58    
tmpasY7EH                                     100%   40MB 731.4KB/s   00:56    
aes256-ctr:
tmpasY7EH                                     100%   40MB 660.6KB/s   01:02    
tmpasY7EH                                     100%   40MB 718.6KB/s   00:57    
arcfour:
tmpasY7EH                                     100%   40MB 819.2KB/s   00:50    
tmpasY7EH                                     100%   40MB 819.2KB/s   00:50    
arcfour128:
tmpasY7EH                                     100%   40MB 682.7KB/s   01:00    
tmpasY7EH                                     100%   40MB 772.8KB/s   00:53    
arcfour256:
tmpasY7EH                                     100%   40MB 602.4KB/s   01:08    
tmpasY7EH                                     100%   40MB 819.2KB/s   00:50    
blowfish-cbc:
tmpasY7EH                                     100%   40MB 718.6KB/s   00:57    
tmpasY7EH                                     100%   40MB   1.0MB/s   00:40    
cast128-cbc:
tmpasY7EH                                     100%   40MB 890.4KB/s   00:46    
tmpasY7EH                                     100%   40MB 744.7KB/s   00:55

The backups of profile 1 work (LAN, cable and wifi; via internet not tested yet). But for the profile 2 I will try to do the initial backup at the weekend with the disk attached to release half of the load of the raspberry. Hopefully incremental backups work better then afterwards.

Germar commented 9 years ago

(by simon-harhues) I just tested backing up via internet and it failed (I'll give it another try):

Oct 11 03:19:44 laptop backintime (root): INFO: mount ssh: <email address hidden>:/mnt/backup on /tmp/backintime/root/mnt/ABDD6A9D/mountpoint
Oct 11 03:19:44 laptop backintime (root): INFO: unmount ssh: <email address hidden>:/mnt/backup from /tmp/backintime/root/mnt/ABDD6A9D/mountpoint
Oct 11 03:19:44 laptop backintime (root): INFO: unmount ssh: pi@192.168.0.254:/mnt/backup from /tmp/backintime/root/mnt/2A77923B/mountpoint
Oct 11 03:19:56 laptop backintime (root): INFO: mount ssh: <email address hidden>:/mnt/backup on /tmp/backintime/root/mnt/ABDD6A9D/mountpoint
Oct 11 03:22:24 laptop backintime (root): INFO: Lock
Oct 11 03:22:30 laptop backintime (root): INFO: Mountpoint /tmp/backintime/root/mnt/ABDD6A9D/mountpoint is already mounted
Oct 11 03:22:30 laptop backintime (root): INFO: [GnomePlugin.Systray.run]
Oct 11 03:22:30 laptop backintime (root): INFO: on process begins
Oct 11 03:22:30 laptop backintime (root): INFO: [GnomePlugin.Systray.run] begin loop
Oct 11 03:22:30 laptop backintime (root): INFO: Profile_id: 1
Oct 11 03:22:30 laptop backintime (root): INFO: Call rsync to take the snapshot
Oct 11 03:26:06 laptop backintime (root): WARNING: Command "rsync -rtDH --links -pEgo --rsh="ssh -p 2222 "  --delete --delete-excluded  -v  --chmod=Du+wx  --exclude="/tmp/backintime/root/1_8943" --exclude="/root/.local/share/backintime" --exclude="/tmp/backintime" --include="/home/" --include="/etc/" --include="/var/" --include="/usr/local/" --include="/usr/" --include="/root/.config/backintime/" --include="/root/.config/" --include="/root/" --exclude="*.backup*" --exclude="*~" --exclude="/home/simon/privat/finanzen/hbcischluessel" --exclude=".gvfs" --exclude=".cache*" --exclude="[Cc]ache*" --exclude=".thumbnails*" --exclude="[Tt]rash*" --include="/home/**" --include="/etc/**" --include="/var/**" --include="/usr/local/**" --include="/root/.config/backintime/**" --exclude="*" / '<email address hidden>:"/mnt/backup/backintime/laptop/root/1/new_snapshot/backup/"' --link-dest="../../20131011-014455-106/backup" -i --out-format="BACKINTIME: %i %n%L" 2>&1" returns 65280
Oct 11 03:26:15 laptop backintime (root): INFO: Command "ssh -p 2222  <email address hidden> 'find "/mnt/backup/backintime/laptop/root/1/new_snapshot" -type d -exec chmod u+wx "{}" +'" returns 0
Oct 11 03:26:23 laptop backintime (root): INFO: Command "ssh -p 2222  <email address hidden> rm -rf "/mnt/backup/backintime/laptop/root/1/new_snapshot"" returns 0
Oct 11 03:26:23 laptop backintime (root): INFO: Command "rm -rf "/tmp/backintime/root/1_8943/backintime/laptop/root/1/20131011-032224-106"" returns 0
Oct 11 03:26:23 laptop backintime (root): ERROR: Failed to take snapshot !!!
Oct 11 03:26:28 laptop backintime (root): INFO: [GnomePlugin.Systray.run] end loop
Oct 11 03:26:28 laptop backintime (root): INFO: Mountpoint /tmp/backintime/root/mnt/ABDD6A9D/mountpoint still in use. Keep mounted
Oct 11 03:26:28 laptop backintime (root): INFO: Unlock
simon@laptop:~$ sudo grep "^\[[IE]\]" /root/.local/share/backintime/takesnapshot_.log
[E] Error: rsync: writefd_unbuffered failed to write 4 bytes to socket [sender]: Broken pipe (32)
[E] Konnte Snapshot 11.10.2013 03:22:24 nicht erstellen !!!
simon@laptop:~$

Germar commented 9 years ago

(by simon-harhues) Second try was successful. I checked on the raspberry again for errors from the try before, but couldn't find any. So I believe it was really a connection problem in the try before. Thus it maybe would help to just try n (n=3?) times to transfer a file if a broken pipe is detected, to make it more error tolerant?.

Germar commented 9 years ago

(by germar) Sorry, I'm a little confused by all these posts ;) So it is working right now except of some problems due to inconsistent network connection, is that correct? Can I mark this bug-report as a wishlist for more stable error-handling on unstable networks?

The benchmark looks like there is an other bottleneck than the cipher. Maybe the Raspberry is limited to USB1.0? I made two tests to make it more error-tolerant.

Germar commented 9 years ago

(by simon-harhues) Yeah, in general it works (very slowly). I think a more transparent way to handle network errors would be good (just again several backup attempts failed due to a broken pipe). Mark it as a feature request. :)

The raspberry has USB2, but has to share it with the ethernet port as both ports are connected via one usb hub to the CPU.[0] That's definitely not improving performance...

[0] https://en.wikipedia.org/wiki/Raspberry_Pi#Hardware

Germar commented 9 years ago

(by simon-harhues) just to have additional information, I just found this: https://answers.launchpad.net/backintime/+question/146883

Germar commented 9 years ago

(by germar) I'm not sure if question #146883 is related to your problem. Those problems occur always on the same file and excluding that file will fix the problem (I had this problem already by my self). But if I understood you correct your problems appears randomly.

Germar commented 9 years ago

(by simon-harhues) That's true. Just thought that the infos in the linked forums (about compression, size of rsync job, ...) could maybe be helpful.

emtiu commented 2 years ago

Closing as outdated.

major-mayer commented 1 year ago

Hi @emtiu I know this issue is pretty old and probably outdated, but is there acutally a fix for this? I am connecting to a NAS over the internet and the connection just isn't very stable. So an option to automatically retry the backup after a short interval, when it failed due to network errors, would be very nice for me to have.

emtiu commented 1 year ago

Hi @major-mayer, thanks for your comment. I don't think there is such a feature at the moment. How about we keep this old ticket closed, and you open one as a feature request? Ideally, you can describe your use case and how you would like backintime to handle aborts. Thanks :)