TKLBAM initial backup takes loooong time

Jacob - Wed, 2014/07/02 - 19:02

Cut & Paste from email with Liraz:

--------------------------------------

There's a trick you can use to throttle backup/restore speeds:

http://www.turnkeylinux.org/forum/support/20120327/throttle-backup-and-restore-bandwidth-speeds-tklbam

To debug what is going on at the network level I recommend trying out
nload, iftop or iptraf.

To stop the backup and try resuming it, just Ctrl-C and then rerun
whatever command you used - using exactly the same arguments.

Let me know how it goes.

You're welcome,
Liraz

PS: we should post your question and my answer to the forum so that
anyone that runs into the same problem (or has found a solution) can
chip in.

On 02/07/14 17:51, Jacob de Greef wrote:

Hi Liraz,
Sorry to bother you via mail. I searched the forums, but could not find any solution.
I installed the new version of the fileserver app, based on deb 7. Restored my old files. Started a fresh TKLBAM backup. This backup has been running for over 40 hrs (approx. 5 Gigabyte). My upload is normally between 1 and 3 Mbit/sec, so it should have finished by now. I cannot see any progress or errors, but I notice my entire bandwidth is clogged, even simple web browsing takes ages. On the Hub dashboard I see: 'Backup in progress… 0 bytes'

What can I do to check for status / progress / errors?
How can I safely pause / throttle the backup process and restart it at night?
Any other advice?

Thanks,
Jacob

Forum:

Support

Tags:

tklbam

fileserver

Add new comment

trickle only for new processes(?)

Jacob - Wed, 2014/07/02 - 19:08

I found out about trickle in the forums, but thought it only affects new started processes and will not in real time affect already running jobs.

So I gues I will Ctrl-C the currenct process, then install and run trickle, and then try to resume the backup.

One more question, what happens when after 24 hrs TKLBAM tries to initiated the incremental backup while the initial backup has not finished?

TKLBAM tries to pick up from

Liraz Siri - Wed, 2014/07/02 - 19:17

TKLBAM tries to pick up from where it left. It doesn't matter how much time has passed. Some things such as databases are only serialized (mysqldump'ed) once and are not reserialized when you resume. If new files have changed in between it won't pick up on that until the next backup.

Thanks Jacob. FWIW, in case

Liraz Siri - Wed, 2014/07/02 - 19:15

Thanks Jacob. FWIW, in case anyone finds it weird that we're pasting emails into the forum - the idea is to make it easier for others that run into a similar problem (or know the solution) to benefit or chip in.

log files

Jacob - Sun, 2014/07/20 - 18:39

Tried to post the tklbam-backup logfile here. But the mod system regards it as spam :( Too many s3 hyperlinks I guess. Any way to get aroud that?

Try attaching them to your OP

Jeremy Davis - Tue, 2014/07/22 - 13:08

You can only do that with the first post of a thread, so you'll need to edit that. But that shouldn't be an issue for the spam filter (although following the tweaks that Liraz did recently; when logged in you should be able to avoid the spam filter altogether now... Not sure why that isn't working...?!)

There was a bug, I think I squashed it

Liraz Siri - Fri, 2014/07/25 - 01:49

Jacob, thanks for reporting the issue with TKLBAM and the issue you ran into with the forum. Could you try again (with the forum) I think I squashed the issue.

exerpt log file

Jacob - Fri, 2014/07/25 - 18:21

Trying to copy-paste a snippet of /var/log/tklbam-backup

I have a mobile broadband connection. The ISP is NATting the connection, so I don't have a public IP address. The quality of the connection varies :( sometimes it seems to drop and reconnects after a couple of minutes. I cannot get a decent log out of the MiFi device, and Huawei doesn't give information on how to put it in bridge mode.

Anyway, here's the snippet. Please shoot if you see any indication what may cause the interupted backups.



Executing Duplicity to backup system changes to encrypted, incremental archives
===============================================================================

# export PASSPHRASE=$(cat /var/lib/tklbam/secret)
# duplicity --verbosity=5 --archive-dir=/var/cache/duplicity cleanup --force s3://s3.amazonaws.com/tklbam-qqnfbgn26sfi3f6e
Listing s3://s3.amazonaws.com/tklbam-qqnfbgn26sfi3f6e
Local and Remote metadata are synchronized, no sync needed.
Listing s3://s3.amazonaws.com/tklbam-qqnfbgn26sfi3f6e
Added incremental Backupset (start_time: Mon Jun 30 16:47:34 2014 / end_time: Wed Jul  9 01:11:53 2014)
Added incremental Backupset (start_time: Wed Jul  9 01:11:53 2014 / end_time: Thu Jul 10 00:38:51 2014)
Added incremental Backupset (start_time: Thu Jul 10 00:38:51 2014 / end_time: Fri Jul 11 01:05:32 2014)
Added incremental Backupset (start_time: Fri Jul 11 01:05:32 2014 / end_time: Sat Jul 12 00:38:57 2014)
Added incremental Backupset (start_time: Sat Jul 12 00:38:57 2014 / end_time: Sun Jul 13 00:50:18 2014)
Added incremental Backupset (start_time: Sun Jul 13 00:50:18 2014 / end_time: Mon Jul 14 00:44:21 2014)
Added incremental Backupset (start_time: Mon Jul 14 00:44:21 2014 / end_time: Thu Jul 17 01:15:36 2014)
Added incremental Backupset (start_time: Thu Jul 17 01:15:36 2014 / end_time: Sat Jul 19 00:59:45 2014)
Added incremental Backupset (start_time: Sat Jul 19 00:59:45 2014 / end_time: Sun Jul 20 01:21:41 2014)
Added incremental Backupset (start_time: Sun Jul 20 01:21:41 2014 / end_time: Mon Jul 21 01:04:22 2014)
Last full backup date: Mon Jun 30 16:47:34 2014
No extraneous files found, nothing deleted in cleanup.

# duplicity --verbosity=5 --volsize=5 --full-if-older-than=1M --gpg-options=--cipher-algo=aes --include=/TKLBAM --include-filelist=/TKLBAM/fsdelta-olist --exclude=** --archive-dir=/var/cache/duplicity --s3-unencrypted-connection --allow-source-mismatch / s3://s3.amazonaws.com/tklbam-qqnfbgn26sfi3f6e
Listing s3://s3.amazonaws.com/tklbam-qqnfbgn26sfi3f6e
Local and Remote metadata are synchronized, no sync needed.
Listing s3://s3.amazonaws.com/tklbam-qqnfbgn26sfi3f6e
Added incremental Backupset (start_time: Mon Jun 30 16:47:34 2014 / end_time: Wed Jul  9 01:11:53 2014)
Added incremental Backupset (start_time: Wed Jul  9 01:11:53 2014 / end_time: Thu Jul 10 00:38:51 2014)
Added incremental Backupset (start_time: Thu Jul 10 00:38:51 2014 / end_time: Fri Jul 11 01:05:32 2014)
Added incremental Backupset (start_time: Fri Jul 11 01:05:32 2014 / end_time: Sat Jul 12 00:38:57 2014)
Added incremental Backupset (start_time: Sat Jul 12 00:38:57 2014 / end_time: Sun Jul 13 00:50:18 2014)
Added incremental Backupset (start_time: Sun Jul 13 00:50:18 2014 / end_time: Mon Jul 14 00:44:21 2014)
Added incremental Backupset (start_time: Mon Jul 14 00:44:21 2014 / end_time: Thu Jul 17 01:15:36 2014)
Added incremental Backupset (start_time: Thu Jul 17 01:15:36 2014 / end_time: Sat Jul 19 00:59:45 2014)
Added incremental Backupset (start_time: Sat Jul 19 00:59:45 2014 / end_time: Sun Jul 20 01:21:41 2014)
Added incremental Backupset (start_time: Sun Jul 20 01:21:41 2014 / end_time: Mon Jul 21 01:04:22 2014)
Last full backup date: Mon Jun 30 16:47:34 2014
Downloading s3://s3.amazonaws.com/tklbam-qqnfbgn26sfi3f6e/duplicity-inc.20140720T052141Z.to.20140721T050422Z.manifest.gpg
A .
A TKLBAM
M TKLBAM/backup-conf
A TKLBAM/etc
M TKLBAM/etc/group
M TKLBAM/etc/passwd
M TKLBAM/fsdelta
M TKLBAM/fsdelta-olist
M TKLBAM/newpkgs
[…]
Uploading s3://s3.amazonaws.com/tklbam-qqnfbgn26sfi3f6e/duplicity-inc.20140721T050422Z.to.20140722T051612Z.vol1.difftar.gpg to STANDARD Storage
Upload 's3://s3.amazonaws.com/tklbam-qqnfbgn26sfi3f6e/duplicity-inc.20140721T050422Z.to.20140722T051612Z.vol1.difftar.gpg' failed (attempt #1, reason: error: [Errno 104] Connection reset by peer)
Uploading s3://s3.amazonaws.com/tklbam-qqnfbgn26sfi3f6e/duplicity-inc.20140721T050422Z.to.20140722T051612Z.vol1.difftar.gpg to STANDARD Storage
Upload 's3://s3.amazonaws.com/tklbam-qqnfbgn26sfi3f6e/duplicity-inc.20140721T050422Z.to.20140722T051612Z.vol1.difftar.gpg' failed (attempt #2, reason: timeout: timed out)
Uploading s3://s3.amazonaws.com/tklbam-qqnfbgn26sfi3f6e/duplicity-inc.20140721T050422Z.to.20140722T051612Z.vol1.difftar.gpg to STANDARD Storage
Upload 's3://s3.amazonaws.com/tklbam-qqnfbgn26sfi3f6e/duplicity-inc.20140721T050422Z.to.20140722T051612Z.vol1.difftar.gpg' failed (attempt #3, reason: error: [Errno 104] Connection reset by peer)
Uploading s3://s3.amazonaws.com/tklbam-qqnfbgn26sfi3f6e/duplicity-inc.20140721T050422Z.to.20140722T051612Z.vol1.difftar.gpg to STANDARD Storage
Upload 's3://s3.amazonaws.com/tklbam-qqnfbgn26sfi3f6e/duplicity-inc.20140721T050422Z.to.20140722T051612Z.vol1.difftar.gpg' failed (attempt #4, reason: timeout: timed out)
Uploading s3://s3.amazonaws.com/tklbam-qqnfbgn26sfi3f6e/duplicity-inc.20140721T050422Z.to.20140722T051612Z.vol1.difftar.gpg to STANDARD Storage
Upload 's3://s3.amazonaws.com/tklbam-qqnfbgn26sfi3f6e/duplicity-inc.20140721T050422Z.to.20140722T051612Z.vol1.difftar.gpg' failed (attempt #5, reason: timeout: timed out)
Giving up trying to upload s3://s3.amazonaws.com/tklbam-qqnfbgn26sfi3f6e/duplicity-inc.20140721T050422Z.to.20140722T051612Z.vol1.difftar.gpg after 5 attempts
Backend error detail: Traceback (most recent call last):
  File "/usr/lib/tklbam/deps/bin/duplicity", line 1405, in <module>
    with_tempdir(main)
  File "/usr/lib/tklbam/deps/bin/duplicity", line 1398, in with_tempdir
    fn()
  File "/usr/lib/tklbam/deps/bin/duplicity", line 1380, in main
    incremental_backup(sig_chain)
  File "/usr/lib/tklbam/deps/bin/duplicity", line 586, in incremental_backup
    globals.backend)
  File "/usr/lib/tklbam/deps/bin/duplicity", line 412, in write_multivol
    (tdp, dest_filename, vol_num)))
  File "/usr/lib/tklbam/deps/lib/python2.7/dist-packages/duplicity/asyncscheduler.py", line 145, in schedule_task
    return self.__run_synchronously(fn, params)
  File "/usr/lib/tklbam/deps/lib/python2.7/dist-packages/duplicity/asyncscheduler.py", line 172, in __run_synchronously
    ret = fn(*params)
  File "/usr/lib/tklbam/deps/bin/duplicity", line 411, in <lambda>
    async_waiters.append(io_scheduler.schedule_task(lambda tdp, dest_filename, vol_num: put(tdp, dest_filename, vol_num),
  File "/usr/lib/tklbam/deps/bin/duplicity", line 309, in put
    backend.put(tdp, dest_filename)
  File "/usr/lib/tklbam/deps/lib/python2.7/dist-packages/duplicity/backends/_boto_single.py", line 230, in put
    raise BackendException("Error uploading %s/%s" % (self.straight_url, remote_filename))
BackendException: Error uploading s3://s3.amazonaws.com/tklbam-qqnfbgn26sfi3f6e/duplicity-inc.20140721T050422Z.to.20140722T051612Z.vol1.difftar.gpg

BackendException: Error uploading s3://s3.amazonaws.com/tklbam-qqnfbgn26sfi3f6e/duplicity-inc.20140721T050422Z.to.20140722T051612Z.vol1.difftar.gpg
warning: can't update Hub of backup completed: error(65, 'GnuTLS recv error (-9): A TLS packet with unexpected length was received.')

Traceback (most recent call last):
  File "/usr/bin/tklbam-backup", line 467, in main
    log=_print)
  File "/usr/lib/tklbam/duplicity.py", line 253, in __call__
    backup_command.run(target.secret, target.credentials, debug=debug)
  File "/usr/lib/tklbam/duplicity.py", line 101, in run
    raise Error("non-zero exitcode (%d) from backup command: %s" % (exitcode, str(self)))
Error: non-zero exitcode (23) from backup command: duplicity --verbosity=5 --volsize=5 --full-if-older-than=1M --gpg-options=--cipher-algo=aes --include=/TKLBAM --include-filelist=/TKLBAM/fsdelta-olist --exclude=** --archive-dir=/var/cache/duplicity --s3-unencrypted-connection --allow-source-mismatch / s3://s3.amazonaws.com/tklbam-qqnfbgn26sfi3f6e

################################
### Wed Jul 23 00:33:39 2014 ###
################################

ATTEMPTING TO RESUME ABORTED BACKUP SESSION

UNCOMPRESSED BACKUP SIZE: 5.43 GB in 12996 files

Executing Duplicity to backup system changes to encrypted, incremental archives
===============================================================================

# export PASSPHRASE=$(cat /var/lib/tklbam/secret)
# duplicity --verbosity=5 --volsize=5 --full-if-older-than=1M --gpg-options=--cipher-algo=aes --include=/TKLBAM --include-filelist=/TKLBAM/fsdelta-olist --exclude=** --archive-dir=/var/cache/duplicity --s3-unencrypted-connection --allow-source-mismatch / s3://s3.amazonaws.com/tklbam-qqnfbgn26sfi3f6e
Listing s3://s3.amazonaws.com/tklbam-qqnfbgn26sfi3f6e
Local and Remote metadata are synchronized, no sync needed.
Listing s3://s3.amazonaws.com/tklbam-qqnfbgn26sfi3f6e
Added incremental Backupset (start_time: Mon Jun 30 16:47:34 2014 / end_time: Wed Jul  9 01:11:53 2014)
Added incremental Backupset (start_time: Wed Jul  9 01:11:53 2014 / end_time: Thu Jul 10 00:38:51 2014)
Added incremental Backupset (start_time: Thu Jul 10 00:38:51 2014 / end_time: Fri Jul 11 01:05:32 2014)
Added incremental Backupset (start_time: Fri Jul 11 01:05:32 2014 / end_time: Sat Jul 12 00:38:57 2014)
Added incremental Backupset (start_time: Sat Jul 12 00:38:57 2014 / end_time: Sun Jul 13 00:50:18 2014)
Added incremental Backupset (start_time: Sun Jul 13 00:50:18 2014 / end_time: Mon Jul 14 00:44:21 2014)
Added incremental Backupset (start_time: Mon Jul 14 00:44:21 2014 / end_time: Thu Jul 17 01:15:36 2014)
Added incremental Backupset (start_time: Thu Jul 17 01:15:36 2014 / end_time: Sat Jul 19 00:59:45 2014)
Added incremental Backupset (start_time: Sat Jul 19 00:59:45 2014 / end_time: Sun Jul 20 01:21:41 2014)
Added incremental Backupset (start_time: Sun Jul 20 01:21:41 2014 / end_time: Mon Jul 21 01:04:22 2014)
Added incremental Backupset (start_time: Mon Jul 21 01:04:22 2014 / end_time: Tue Jul 22 01:16:12 2014)
Last inc backup left a partial set, restarting.
Last full backup date: Mon Jun 30 16:47:34 2014
RESTART: The first volume failed to upload before termination.
         Restart is impossible...starting backup from beginning.
Listing s3://s3.amazonaws.com/tklbam-qqnfbgn26sfi3f6e
Local and Remote metadata are synchronized, no sync needed.
Listing s3://s3.amazonaws.com/tklbam-qqnfbgn26sfi3f6e
Added incremental Backupset (start_time: Mon Jun 30 16:47:34 2014 / end_time: Wed Jul  9 01:11:53 2014)
Added incremental Backupset (start_time: Wed Jul  9 01:11:53 2014 / end_time: Thu Jul 10 00:38:51 2014)
Added incremental Backupset (start_time: Thu Jul 10 00:38:51 2014 / end_time: Fri Jul 11 01:05:32 2014)
Added incremental Backupset (start_time: Fri Jul 11 01:05:32 2014 / end_time: Sat Jul 12 00:38:57 2014)
Added incremental Backupset (start_time: Sat Jul 12 00:38:57 2014 / end_time: Sun Jul 13 00:50:18 2014)
Added incremental Backupset (start_time: Sun Jul 13 00:50:18 2014 / end_time: Mon Jul 14 00:44:21 2014)
Added incremental Backupset (start_time: Mon Jul 14 00:44:21 2014 / end_time: Thu Jul 17 01:15:36 2014)
Added incremental Backupset (start_time: Thu Jul 17 01:15:36 2014 / end_time: Sat Jul 19 00:59:45 2014)
Added incremental Backupset (start_time: Sat Jul 19 00:59:45 2014 / end_time: Sun Jul 20 01:21:41 2014)
Added incremental Backupset (start_time: Sun Jul 20 01:21:41 2014 / end_time: Mon Jul 21 01:04:22 2014)
Last full backup date: Mon Jun 30 16:47:34 2014
Downloading s3://s3.amazonaws.com/tklbam-qqnfbgn26sfi3f6e/duplicity-inc.20140720T052141Z.to.20140721T050422Z.manifest.gpg
A .
A TKLBAM
M TKLBAM/backup-conf
A TKLBAM/etc
M TKLBAM/etc/group
M TKLBAM/etc/passwd
M TKLBAM/fsdelta
M TKLBAM/fsdelta-olist
M TKLBAM/newpkgs
M etc/.etckeeper
A etc/.git
M etc/.git/COMMIT_EDITMSG
M etc/.git/index
A etc/.git/info
M etc/.git/info/refs
A etc/.git/logs
M etc/.git/logs/HEAD
A etc/.git/logs/refs/heads
M etc/.git/logs/refs/heads/master
A etc/.git/objects
D etc/.git/objects/00
D etc/.git/objects/00/139bef7a671ff8ccb8a549d1a4d0d8821b844d
D etc/.git/objects/0c
D etc/.git/objects/0c/3429e1a9a703d93b95430240ef1c4813ea1417
D etc/.git/objects/0d
D etc/.git/objects/0d/ea6f54525673ab48ac9e88003c7b4d81b9d8df
D etc/.git/objects/11
D etc/.git/objects/11/859a510501e2a2cc91d07e27503ba9e0ad0a32
D etc/.git/objects/19
D etc/.git/objects/19/3d2ca3f53c08736d206c2d7985c5f149bda545
D etc/.git/objects/21
D etc/.git/objects/21/3c6706a8f73e09141f8ef4440554cd9f733492
D etc/.git/objects/22
D etc/.git/objects/22/f158049536409608e5d1d0d4980e5e56f952a7
D etc/.git/objects/2e
D etc/.git/objects/2e/93720ed122d48b30edc1e8fd354ceb36a18b56
D etc/.git/objects/37
D etc/.git/objects/37/52855ec52880e864b0f2ada50d52c6e761ffc2
D etc/.git/objects/3e
D etc/.git/objects/3e/77b2c1091606d72f2ef96690523fced364708a
D etc/.git/objects/52
D etc/.git/objects/52/e581a868c58b57e66449aae95f08bfc3db8c45
D etc/.git/objects/53
D etc/.git/objects/53/df1e3971ed0944661b25e0b472cae5c376db97
D etc/.git/objects/59
D etc/.git/objects/59/a20d6b82a92ead67efcbf29e053991b5cf9b7d
D etc/.git/objects/60
D etc/.git/objects/60/7bdabac13fbfb54d87f81c5fb8e9863c55d9a8
D etc/.git/objects/6d
D etc/.git/objects/6d/846cd1fdaf360025e49f48990fa629469b96d9
D etc/.git/objects/71
D etc/.git/objects/71/9dbcce2935144b0af8069f164b197eb8a7884a
D etc/.git/objects/9e
D etc/.git/objects/9e/aa734b4c1576effaf68062b65ba45ecd4d0309
D etc/.git/objects/a2
D etc/.git/objects/a2/d078cfb63babaaec08bd6e9eca946ac8390fbf
D etc/.git/objects/a3
D etc/.git/objects/a3/19e5d7cf233d985f572c76b99150e011489121
D etc/.git/objects/a4
D etc/.git/objects/a4/7152285d0d5503a72da70385827e283214f9ca
D etc/.git/objects/a6
D etc/.git/objects/a6/9049a46146d24042f8656b6b18656ede56ae39
D etc/.git/objects/ad
D etc/.git/objects/ad/e59ac4fcc53de8fa808dbdfbc60f08fc3d6754
D etc/.git/objects/b2
D etc/.git/objects/b2/604e56369b1208542f2aa50639aa44150545bf
D etc/.git/objects/c2
D etc/.git/objects/c2/65227752d2dc122ef710188480ff520076a957
D etc/.git/objects/ca
D etc/.git/objects/ca/066ba57ee5d82dd0ae506df3ed5fddba1e7756
D etc/.git/objects/d5
D etc/.git/objects/d5/1aac2ba749e266e9a81af57f2c763eb8e2420d
D etc/.git/objects/d6
D etc/.git/objects/d6/35bd27fb5825cb7e6436bad62c755c0dfaea9b
A etc/.git/objects/dc
D etc/.git/objects/dc/df673bb812aa13a158cf9cc81ddeba64d88bb0
D etc/.git/objects/e3
D etc/.git/objects/e3/0c72cec6425d212f9d07d251bd8ec8f720a94f
D etc/.git/objects/f3
D etc/.git/objects/f3/d3c6e7fb4a0b63719cb526f71d477d680e7325
A etc/.git/objects/info
M etc/.git/objects/info/packs
A etc/.git/objects/pack
D etc/.git/objects/pack/pack-ab254fe495c80fad20579c31bad136d65c956510.idx
D etc/.git/objects/pack/pack-ab254fe495c80fad20579c31bad136d65c956510.pack
M etc/.git/packed-refs
A etc/.git/refs/heads
M etc/.git/refs/heads/master
A etc/webmin/system-status
M etc/webmin/system-status/info
M root/.gnupg/random_seed
A srv/storage/[…]
[…]
Uploading s3://s3.amazonaws.com/tklbam-qqnfbgn26sfi3f6e/duplicity-inc.20140721T050422Z.to.20140723T043406Z.vol1.difftar.gpg to STANDARD Storage
Upload 's3://s3.amazonaws.com/tklbam-qqnfbgn26sfi3f6e/duplicity-inc.20140721T050422Z.to.20140723T043406Z.vol1.difftar.gpg' failed (attempt #1, reason: error: [Errno 104] Connection reset by peer)
Uploading s3://s3.amazonaws.com/tklbam-qqnfbgn26sfi3f6e/duplicity-inc.20140721T050422Z.to.20140723T043406Z.vol1.difftar.gpg to STANDARD Storage
Upload 's3://s3.amazonaws.com/tklbam-qqnfbgn26sfi3f6e/duplicity-inc.20140721T050422Z.to.20140723T043406Z.vol1.difftar.gpg' failed (attempt #2, reason: error: [Errno 104] Connection reset by peer)
Uploading s3://s3.amazonaws.com/tklbam-qqnfbgn26sfi3f6e/duplicity-inc.20140721T050422Z.to.20140723T043406Z.vol1.difftar.gpg to STANDARD Storage
Upload 's3://s3.amazonaws.com/tklbam-qqnfbgn26sfi3f6e/duplicity-inc.20140721T050422Z.to.20140723T043406Z.vol1.difftar.gpg' failed (attempt #3, reason: error: [Errno 104] Connection reset by peer)
Uploading s3://s3.amazonaws.com/tklbam-qqnfbgn26sfi3f6e/duplicity-inc.20140721T050422Z.to.20140723T043406Z.vol1.difftar.gpg to STANDARD Storage
Upload 's3://s3.amazonaws.com/tklbam-qqnfbgn26sfi3f6e/duplicity-inc.20140721T050422Z.to.20140723T043406Z.vol1.difftar.gpg' failed (attempt #4, reason: error: [Errno 104] Connection reset by peer)
Uploading s3://s3.amazonaws.com/tklbam-qqnfbgn26sfi3f6e/duplicity-inc.20140721T050422Z.to.20140723T043406Z.vol1.difftar.gpg to STANDARD Storage
Upload 's3://s3.amazonaws.com/tklbam-qqnfbgn26sfi3f6e/duplicity-inc.20140721T050422Z.to.20140723T043406Z.vol1.difftar.gpg' failed (attempt #5, reason: error: [Errno 104] Connection reset by peer)
Giving up trying to upload s3://s3.amazonaws.com/tklbam-qqnfbgn26sfi3f6e/duplicity-inc.20140721T050422Z.to.20140723T043406Z.vol1.difftar.gpg after 5 attempts
Backend error detail: Traceback (most recent call last):
  File "/usr/lib/tklbam/deps/bin/duplicity", line 1405, in <module>
    with_tempdir(main)
  File "/usr/lib/tklbam/deps/bin/duplicity", line 1398, in with_tempdir
    fn()
  File "/usr/lib/tklbam/deps/bin/duplicity", line 1380, in main
    incremental_backup(sig_chain)
  File "/usr/lib/tklbam/deps/bin/duplicity", line 586, in incremental_backup
    globals.backend)
  File "/usr/lib/tklbam/deps/bin/duplicity", line 412, in write_multivol
    (tdp, dest_filename, vol_num)))
  File "/usr/lib/tklbam/deps/lib/python2.7/dist-packages/duplicity/asyncscheduler.py", line 145, in schedule_task
    return self.__run_synchronously(fn, params)
  File "/usr/lib/tklbam/deps/lib/python2.7/dist-packages/duplicity/asyncscheduler.py", line 172, in __run_synchronously
    ret = fn(*params)
  File "/usr/lib/tklbam/deps/bin/duplicity", line 411, in <lambda>
    async_waiters.append(io_scheduler.schedule_task(lambda tdp, dest_filename, vol_num: put(tdp, dest_filename, vol_num),
  File "/usr/lib/tklbam/deps/bin/duplicity", line 309, in put
    backend.put(tdp, dest_filename)
  File "/usr/lib/tklbam/deps/lib/python2.7/dist-packages/duplicity/backends/_boto_single.py", line 230, in put
    raise BackendException("Error uploading %s/%s" % (self.straight_url, remote_filename))
BackendException: Error uploading s3://s3.amazonaws.com/tklbam-qqnfbgn26sfi3f6e/duplicity-inc.20140721T050422Z.to.20140723T043406Z.vol1.difftar.gpg

BackendException: Error uploading s3://s3.amazonaws.com/tklbam-qqnfbgn26sfi3f6e/duplicity-inc.20140721T050422Z.to.20140723T043406Z.vol1.difftar.gpg
warning: can't update Hub of backup completed: error(65, 'GnuTLS recv error (-9): A TLS packet with unexpected length was received.')

Traceback (most recent call last):
  File "/usr/bin/tklbam-backup", line 467, in main
    log=_print)
  File "/usr/lib/tklbam/duplicity.py", line 253, in __call__
    backup_command.run(target.secret, target.credentials, debug=debug)
  File "/usr/lib/tklbam/duplicity.py", line 101, in run
    raise Error("non-zero exitcode (%d) from backup command: %s" % (exitcode, str(self)))
Error: non-zero exitcode (23) from backup command: duplicity --verbosity=5 --volsize=5 --full-if-older-than=1M --gpg-options=--cipher-algo=aes --include=/TKLBAM --include-filelist=/TKLBAM/fsdelta-olist --exclude=** --archive-dir=/var/cache/duplicity --s3-unencrypted-connection --allow-source-mismatch / s3://s3.amazonaws.com/tklbam-qqnfbgn26sfi3f6e

################################
### Thu Jul 24 00:57:20 2014 ###
################################

ATTEMPTING TO RESUME ABORTED BACKUP SESSION

UNCOMPRESSED BACKUP SIZE: 5.43 GB in 12984 files

Executing Duplicity to backup system changes to encrypted, incremental archives
===============================================================================

# export PASSPHRASE=$(cat /var/lib/tklbam/secret)
# duplicity --verbosity=5 --volsize=5 --full-if-older-than=1M --gpg-options=--cipher-algo=aes --include=/TKLBAM --include-filelist=/TKLBAM/fsdelta-olist --exclude=** --archive-dir=/var/cache/duplicity --s3-unencrypted-connection --allow-source-mismatch / s3://s3.amazonaws.com/tklbam-qqnfbgn26sfi3f6e
Listing s3://s3.amazonaws.com/tklbam-qqnfbgn26sfi3f6e
Local and Remote metadata are synchronized, no sync needed.
Listing s3://s3.amazonaws.com/tklbam-qqnfbgn26sfi3f6e
Added incremental Backupset (start_time: Mon Jun 30 16:47:34 2014 / end_time: Wed Jul  9 01:11:53 2014)
Added incremental Backupset (start_time: Wed Jul  9 01:11:53 2014 / end_time: Thu Jul 10 00:38:51 2014)
Added incremental Backupset (start_time: Thu Jul 10 00:38:51 2014 / end_time: Fri Jul 11 01:05:32 2014)
Added incremental Backupset (start_time: Fri Jul 11 01:05:32 2014 / end_time: Sat Jul 12 00:38:57 2014)
Added incremental Backupset (start_time: Sat Jul 12 00:38:57 2014 / end_time: Sun Jul 13 00:50:18 2014)
Added incremental Backupset (start_time: Sun Jul 13 00:50:18 2014 / end_time: Mon Jul 14 00:44:21 2014)
Added incremental Backupset (start_time: Mon Jul 14 00:44:21 2014 / end_time: Thu Jul 17 01:15:36 2014)
Added incremental Backupset (start_time: Thu Jul 17 01:15:36 2014 / end_time: Sat Jul 19 00:59:45 2014)
Added incremental Backupset (start_time: Sat Jul 19 00:59:45 2014 / end_time: Sun Jul 20 01:21:41 2014)
Added incremental Backupset (start_time: Sun Jul 20 01:21:41 2014 / end_time: Mon Jul 21 01:04:22 2014)
Added incremental Backupset (start_time: Mon Jul 21 01:04:22 2014 / end_time: Wed Jul 23 00:34:06 2014)
Last inc backup left a partial set, restarting.
Last full backup date: Mon Jun 30 16:47:34 2014
RESTART: The first volume failed to upload before termination.
         Restart is impossible...starting backup from beginning.
Listing s3://s3.amazonaws.com/tklbam-qqnfbgn26sfi3f6e
Local and Remote metadata are synchronized, no sync needed.
Listing s3://s3.amazonaws.com/tklbam-qqnfbgn26sfi3f6e
Added incremental Backupset (start_time: Mon Jun 30 16:47:34 2014 / end_time: Wed Jul  9 01:11:53 2014)
Added incremental Backupset (start_time: Wed Jul  9 01:11:53 2014 / end_time: Thu Jul 10 00:38:51 2014)
Added incremental Backupset (start_time: Thu Jul 10 00:38:51 2014 / end_time: Fri Jul 11 01:05:32 2014)
Added incremental Backupset (start_time: Fri Jul 11 01:05:32 2014 / end_time: Sat Jul 12 00:38:57 2014)
Added incremental Backupset (start_time: Sat Jul 12 00:38:57 2014 / end_time: Sun Jul 13 00:50:18 2014)
Added incremental Backupset (start_time: Sun Jul 13 00:50:18 2014 / end_time: Mon Jul 14 00:44:21 2014)
Added incremental Backupset (start_time: Mon Jul 14 00:44:21 2014 / end_time: Thu Jul 17 01:15:36 2014)
Added incremental Backupset (start_time: Thu Jul 17 01:15:36 2014 / end_time: Sat Jul 19 00:59:45 2014)
Added incremental Backupset (start_time: Sat Jul 19 00:59:45 2014 / end_time: Sun Jul 20 01:21:41 2014)
Added incremental Backupset (start_time: Sun Jul 20 01:21:41 2014 / end_time: Mon Jul 21 01:04:22 2014)
Last full backup date: Mon Jun 30 16:47:34 2014
Downloading s3://s3.amazonaws.com/tklbam-qqnfbgn26sfi3f6e/duplicity-inc.20140720T052141Z.to.20140721T050422Z.manifest.gpg
A .
A TKLBAM
M TKLBAM/backup-conf
A TKLBAM/etc
M TKLBAM/etc/group
M TKLBAM/etc/passwd
M TKLBAM/fsdelta
M TKLBAM/fsdelta-olist
M TKLBAM/newpkgs
[ . . . ]
Uploading s3://s3.amazonaws.com/tklbam-qqnfbgn26sfi3f6e/duplicity-inc.20140721T050422Z.to.20140724T045741Z.vol1.difftar.gpg to STANDARD Storage
Upload 's3://s3.amazonaws.com/tklbam-qqnfbgn26sfi3f6e/duplicity-inc.20140721T050422Z.to.20140724T045741Z.vol1.difftar.gpg' failed (attempt #1, reason: timeout: timed out)
Uploading s3://s3.amazonaws.com/tklbam-qqnfbgn26sfi3f6e/duplicity-inc.20140721T050422Z.to.20140724T045741Z.vol1.difftar.gpg to STANDARD Storage
Upload 's3://s3.amazonaws.com/tklbam-qqnfbgn26sfi3f6e/duplicity-inc.20140721T050422Z.to.20140724T045741Z.vol1.difftar.gpg' failed (attempt #2, reason: timeout: timed out)
Uploading s3://s3.amazonaws.com/tklbam-qqnfbgn26sfi3f6e/duplicity-inc.20140721T050422Z.to.20140724T045741Z.vol1.difftar.gpg to STANDARD Storage
Upload 's3://s3.amazonaws.com/tklbam-qqnfbgn26sfi3f6e/duplicity-inc.20140721T050422Z.to.20140724T045741Z.vol1.difftar.gpg' failed (attempt #3, reason: error: [Errno 104] Connection reset by peer)
Uploading s3://s3.amazonaws.com/tklbam-qqnfbgn26sfi3f6e/duplicity-inc.20140721T050422Z.to.20140724T045741Z.vol1.difftar.gpg to STANDARD Storage
Upload 's3://s3.amazonaws.com/tklbam-qqnfbgn26sfi3f6e/duplicity-inc.20140721T050422Z.to.20140724T045741Z.vol1.difftar.gpg' failed (attempt #4, reason: error: [Errno 104] Connection reset by peer)
Uploading s3://s3.amazonaws.com/tklbam-qqnfbgn26sfi3f6e/duplicity-inc.20140721T050422Z.to.20140724T045741Z.vol1.difftar.gpg to STANDARD Storage
Upload 's3://s3.amazonaws.com/tklbam-qqnfbgn26sfi3f6e/duplicity-inc.20140721T050422Z.to.20140724T045741Z.vol1.difftar.gpg' failed (attempt #5, reason: error: [Errno 104] Connection reset by peer)
Giving up trying to upload s3://s3.amazonaws.com/tklbam-qqnfbgn26sfi3f6e/duplicity-inc.20140721T050422Z.to.20140724T045741Z.vol1.difftar.gpg after 5 attempts
Backend error detail: Traceback (most recent call last):
  File "/usr/lib/tklbam/deps/bin/duplicity", line 1405, in <module>
    with_tempdir(main)
  File "/usr/lib/tklbam/deps/bin/duplicity", line 1398, in with_tempdir
    fn()
  File "/usr/lib/tklbam/deps/bin/duplicity", line 1380, in main
    incremental_backup(sig_chain)
  File "/usr/lib/tklbam/deps/bin/duplicity", line 586, in incremental_backup
    globals.backend)
  File "/usr/lib/tklbam/deps/bin/duplicity", line 412, in write_multivol
    (tdp, dest_filename, vol_num)))
  File "/usr/lib/tklbam/deps/lib/python2.7/dist-packages/duplicity/asyncscheduler.py", line 145, in schedule_task
    return self.__run_synchronously(fn, params)
  File "/usr/lib/tklbam/deps/lib/python2.7/dist-packages/duplicity/asyncscheduler.py", line 172, in __run_synchronously
    ret = fn(*params)
  File "/usr/lib/tklbam/deps/bin/duplicity", line 411, in <lambda>
    async_waiters.append(io_scheduler.schedule_task(lambda tdp, dest_filename, vol_num: put(tdp, dest_filename, vol_num),
  File "/usr/lib/tklbam/deps/bin/duplicity", line 309, in put
    backend.put(tdp, dest_filename)
  File "/usr/lib/tklbam/deps/lib/python2.7/dist-packages/duplicity/backends/_boto_single.py", line 230, in put
    raise BackendException("Error uploading %s/%s" % (self.straight_url, remote_filename))
BackendException: Error uploading s3://s3.amazonaws.com/tklbam-qqnfbgn26sfi3f6e/duplicity-inc.20140721T050422Z.to.20140724T045741Z.vol1.difftar.gpg

BackendException: Error uploading s3://s3.amazonaws.com/tklbam-qqnfbgn26sfi3f6e/duplicity-inc.20140721T050422Z.to.20140724T045741Z.vol1.difftar.gpg
warning: can't update Hub of backup completed: error(65, 'GnuTLS recv error (-9): A TLS packet with unexpected length was received.')

Traceback (most recent call last):
  File "/usr/bin/tklbam-backup", line 467, in main
    log=_print)
  File "/usr/lib/tklbam/duplicity.py", line 253, in __call__
    backup_command.run(target.secret, target.credentials, debug=debug)
  File "/usr/lib/tklbam/duplicity.py", line 101, in run
    raise Error("non-zero exitcode (%d) from backup command: %s" % (exitcode, str(self)))
Error: non-zero exitcode (23) from backup command: duplicity --verbosity=5 --volsize=5 --full-if-older-than=1M --gpg-options=--cipher-algo=aes --include=/TKLBAM --include-filelist=/TKLBAM/fsdelta-olist --exclude=** --archive-dir=/var/cache/duplicity --s3-unencrypted-connection --allow-source-mismatch / s3://s3.amazonaws.com/tklbam-qqnfbgn26sfi3f6e

################################
### Fri Jul 25 01:01:54 2014 ###
################################

ATTEMPTING TO RESUME ABORTED BACKUP SESSION

UNCOMPRESSED BACKUP SIZE: 5.42 GB in 12966 files

Executing Duplicity to backup system changes to encrypted, incremental archives
===============================================================================

# export PASSPHRASE=$(cat /var/lib/tklbam/secret)
# duplicity --verbosity=5 --volsize=5 --full-if-older-than=1M --gpg-options=--cipher-algo=aes --include=/TKLBAM --include-filelist=/TKLBAM/fsdelta-olist --exclude=** --archive-dir=/var/cache/duplicity --s3-unencrypted-connection --allow-source-mismatch / s3://s3.amazonaws.com/tklbam-qqnfbgn26sfi3f6e
Listing s3://s3.amazonaws.com/tklbam-qqnfbgn26sfi3f6e
Local and Remote metadata are synchronized, no sync needed.
Listing s3://s3.amazonaws.com/tklbam-qqnfbgn26sfi3f6e
Added incremental Backupset (start_time: Mon Jun 30 16:47:34 2014 / end_time: Wed Jul  9 01:11:53 2014)
Added incremental Backupset (start_time: Wed Jul  9 01:11:53 2014 / end_time: Thu Jul 10 00:38:51 2014)
Added incremental Backupset (start_time: Thu Jul 10 00:38:51 2014 / end_time: Fri Jul 11 01:05:32 2014)
Added incremental Backupset (start_time: Fri Jul 11 01:05:32 2014 / end_time: Sat Jul 12 00:38:57 2014)
Added incremental Backupset (start_time: Sat Jul 12 00:38:57 2014 / end_time: Sun Jul 13 00:50:18 2014)
Added incremental Backupset (start_time: Sun Jul 13 00:50:18 2014 / end_time: Mon Jul 14 00:44:21 2014)
Added incremental Backupset (start_time: Mon Jul 14 00:44:21 2014 / end_time: Thu Jul 17 01:15:36 2014)
Added incremental Backupset (start_time: Thu Jul 17 01:15:36 2014 / end_time: Sat Jul 19 00:59:45 2014)
Added incremental Backupset (start_time: Sat Jul 19 00:59:45 2014 / end_time: Sun Jul 20 01:21:41 2014)
Added incremental Backupset (start_time: Sun Jul 20 01:21:41 2014 / end_time: Mon Jul 21 01:04:22 2014)
Added incremental Backupset (start_time: Mon Jul 21 01:04:22 2014 / end_time: Thu Jul 24 00:57:41 2014)
Last inc backup left a partial set, restarting.
Last full backup date: Mon Jun 30 16:47:34 2014
RESTART: The first volume failed to upload before termination.
         Restart is impossible...starting backup from beginning.
Listing s3://s3.amazonaws.com/tklbam-qqnfbgn26sfi3f6e
Local and Remote metadata are synchronized, no sync needed.
Listing s3://s3.amazonaws.com/tklbam-qqnfbgn26sfi3f6e
Added incremental Backupset (start_time: Mon Jun 30 16:47:34 2014 / end_time: Wed Jul  9 01:11:53 2014)
Added incremental Backupset (start_time: Wed Jul  9 01:11:53 2014 / end_time: Thu Jul 10 00:38:51 2014)
Added incremental Backupset (start_time: Thu Jul 10 00:38:51 2014 / end_time: Fri Jul 11 01:05:32 2014)
Added incremental Backupset (start_time: Fri Jul 11 01:05:32 2014 / end_time: Sat Jul 12 00:38:57 2014)
Added incremental Backupset (start_time: Sat Jul 12 00:38:57 2014 / end_time: Sun Jul 13 00:50:18 2014)
Added incremental Backupset (start_time: Sun Jul 13 00:50:18 2014 / end_time: Mon Jul 14 00:44:21 2014)
Added incremental Backupset (start_time: Mon Jul 14 00:44:21 2014 / end_time: Thu Jul 17 01:15:36 2014)
Added incremental Backupset (start_time: Thu Jul 17 01:15:36 2014 / end_time: Sat Jul 19 00:59:45 2014)
Added incremental Backupset (start_time: Sat Jul 19 00:59:45 2014 / end_time: Sun Jul 20 01:21:41 2014)
Added incremental Backupset (start_time: Sun Jul 20 01:21:41 2014 / end_time: Mon Jul 21 01:04:22 2014)
Last full backup date: Mon Jun 30 16:47:34 2014
Downloading s3://s3.amazonaws.com/tklbam-qqnfbgn26sfi3f6e/duplicity-inc.20140720T052141Z.to.20140721T050422Z.manifest.gpg
A .
A TKLBAM
M TKLBAM/backup-conf
A TKLBAM/etc
M TKLBAM/etc/group
M TKLBAM/etc/passwd
M TKLBAM/fsdelta
M TKLBAM/fsdelta-olist
M TKLBAM/newpkgs
[…]
A var/spool/cron/crontabs
M var/spool/cron/crontabs/root
Uploading s3://s3.amazonaws.com/tklbam-qqnfbgn26sfi3f6e/duplicity-inc.20140721T050422Z.to.20140725T050212Z.vol10.difftar.gpg to STANDARD Storage
Processed volume 10
Uploading s3://s3.amazonaws.com/tklbam-qqnfbgn26sfi3f6e/duplicity-new-signatures.20140721T050422Z.to.20140725T050212Z.sigtar.gpg to STANDARD Storage
Uploading s3://s3.amazonaws.com/tklbam-qqnfbgn26sfi3f6e/duplicity-inc.20140721T050422Z.to.20140725T050212Z.manifest.gpg to STANDARD Storage

--------------[ Backup Statistics ]--------------
StartTime 1406264539.59 (Fri Jul 25 01:02:19 2014)
EndTime 1406265493.29 (Fri Jul 25 01:18:13 2014)
ElapsedTime 953.70 (15 minutes 53.70 seconds)
SourceFiles 14709
SourceFileSize 5830352582 (5.43 GB)
NewFiles 202
NewFileSize 53572806 (51.1 MB)
DeletedFiles 140
ChangedFiles 36
ChangedFileSize 21150814 (20.2 MB)
ChangedDeltaSize 0 (0 bytes)
DeltaEntries 378
RawDeltaSize 56630956 (54.0 MB)
TotalDestinationSizeChange 50054947 (47.7 MB)
Errors 0
-------------------------------------------------

TKLBAM is Liraz's baby and I'm not really much of a programmer

Jeremy Davis - Sun, 2014/07/27 - 05:17

So his perspective will no doubt be much more enlightening than mine...

From my casual glance through your log (plus the other info that you have mentioned) it seems pretty clear to me that it is a connection issue. One thing that you may be able to try is reducing the volume size. Smaller volumes may have a better chance of getting through without being timed out? Probably worth a try...

[Edit]: Oops I just realised that it looks like you have already tweaked the volume size down to 5MB (from the default of 50MB).

Yes, this looks like a connection issue

Liraz Siri - Sun, 2014/07/27 - 21:29

I tried looking in the logs for anything that might indicate a TKLBAM specific problem but it just looks like a bad connection.

Sometimes the Hub can be slow to update

Jeremy Davis - Tue, 2014/12/23 - 23:12

Although it is strange that the Sun & Mon incrementals aren't there...

Have you checked your TKLBAM logs (on your server) to see what they say? I.e. check that the backups ran and what if any errors may have been raised. IIRC log should be /var/log/tklbam (or similar).

You could use 'tklbam-list' from your server to double check the Hub's backup records. It shouldn't make any difference as the 'tklbam-list' command gets it's info from the same dataset as the Hub UI but perhaps it's worth a try anyway...?!

If you can confirm that the backup definitely ran successfully (from your logs - copy/paste the relevant bit into a new comment) and that it doesn't show up in the Hub UI (perhaps copy/paste from hub-list) then we should lodge a pretty convincing bug report (to the TKL Issue Tracker).

Add new comment

form.antibot { display: none !important; } You must have JavaScript enabled to use this form.

Main menu

User menu

You are here

trickle only for new processes(?)

TKLBAM tries to pick up from

Thanks Jacob. FWIW, in case

log files

Try attaching them to your OP

There was a bug, I think I squashed it

exerpt log file

TKLBAM is Liraz's baby and I'm not really much of a programmer

Yes, this looks like a connection issue

Sometimes the Hub can be slow to update

Add new comment

Plain text

Search form

You are here

Add new comment

Plain text