Mild failure on B2: ERROR UPLOAD_CHUNK Failed to find the path for the chunk: http: read on closed response body

#1

Hi!

I’m doing a first-time upload of a ~678GB directory to a B2 bucket configured like so:

root@/home/plex # cat .duplicacy/preferences
[
    {
        "name": "default",
        "id": "salotto-plex",
        "storage": "b2://salotto-plex",
        "encrypted": true,
        "no_backup": false,
        "no_restore": false,
        "no_save_password": false,
        "keys": null
    }
]

with a filter like so:

root@/home/plex # cat .duplicacy/filter
+Cartoons/
+Movies/
+TV Shows/
-*

I invoke the backup as follows:

# cat /root/duplicacy.sh
#! /bin/bash

. $HOME/.duplicacy-setenv.sh

$DUP $@

. $HOME/.duplicacy-unsetenv.sh

# cat /root/.duplicacy-setenv.sh
export DUP=/usr/local/bin/duplicacy
export DUPLICACY_PASSWORD="***"
export DUPLICACY_B2_ID="***"
export DUPLICACY_B2_KEY="***"

# cat /root/.duplicacy-unsetenv.sh
unset DUPLICACY_PASSWORD
unset DUPLICACY_B2_ID
unset DUPLICACY_B2_KEY

Here’s the log of the first upload (BTW, not sure why it’s not ignoring .DS_Store, given the -* in the filters: anyways, not important):

root@salotto:/home/plex# /root/duplicacy.sh -log backup
2017-07-05 00:01:37.480 INFO STORAGE_SET Storage set to b2://salotto-plex
2017-07-05 00:01:40.340 INFO BACKUP_START No previous backup found
2017-07-05 00:01:40.340 INFO BACKUP_INDEXING Indexing /home/plex
2017-07-05 00:01:41.423 INFO BACKUP_LIST Listing all chunks
2017-07-05 00:01:41.621 INFO PACK_END Packed .DS_Store (12292)
2017-07-05 00:01:41.640 INFO PACK_END Packed ._.DS_Store (4096)
2017-07-05 00:01:41.640 INFO PACK_END Packed .smbcredentials (40)
2017-07-05 00:04:28.999 INFO PACK_END Packed Cartoons/cartoon1.webm (122006039)
2017-07-05 00:09:55.647 INFO PACK_END Packed Cartoons/cartoon2.mp4 (253974996)
2017-07-05 00:14:24.854 INFO BACKBLAZE_UPLOAD URL request 'https://pod-000-1043-12.backblaze.com/b2api/v1/b2_upload_file/c02ac2f6898f0ef955d2091c/c001_v0001043_t0033' returned status code 503
2017-07-05 00:19:28.898 INFO PACK_END Packed Cartoons/cartoon3.mp4 (463430930)
2017-07-05 00:32:15.094 INFO PACK_END Packed Cartoons/cartoon4.mp4 (738873175)
2017-07-05 00:45:24.893 INFO PACK_END Packed Cartoons/cartoon5.mp4 (755498815)
2017-07-05 01:04:23.553 INFO PACK_END Packed Movies/m1.avi (1056950272)
2017-07-05 06:28:03.959 INFO PACK_END Packed Movies/m2.mkv (16981988849)
2017-07-05 06:49:33.203 INFO PACK_END Packed Movies/m3.avi (1172026064)
2017-07-05 06:51:47.560 INFO PACK_END Packed Movies/m4.avi (106526720)
2017-07-05 08:20:52.368 INFO PACK_END Packed Movies/m5.mkv (4705937293)
2017-07-05 08:34:34.913 INFO PACK_END Packed Movies/m5.avi (734466048)
  [...]
2017-07-05 19:46:17.551 INFO BACKBLAZE_UPLOAD URL request 'https://pod-000-1040-19.backblaze.com/b2api/v1/b2_upload_file/c02ac2f6898f0ef955d2091c/c001_v0001040_t0035' returned status code 500
2017-07-05 19:46:40.735 INFO BACKBLAZE_UPLOAD URL request 'https://pod-000-1042-12.backblaze.com/b2api/v1/b2_upload_file/c02ac2f6898f0ef955d2091c/c001_v0001042_t0014' returned status code 503
2017-07-05 19:57:32.139 INFO PACK_END Packed Movies/m6.avi (1475145728)
2017-07-05 20:14:15.943 INFO BACKBLAZE_UPLOAD URL request 'https://pod-000-1026-16.backblaze.com/b2api/v1/b2_upload_file/c02ac2f6898f0ef955d2091c/c001_v0001026_t0006' returned status code 503
2017-07-05 20:35:17.172 INFO BACKBLAZE_UPLOAD URL request 'https://pod-000-1043-07.backblaze.com/b2api/v1/b2_upload_file/c02ac2f6898f0ef955d2091c/c001_v0001043_t0058' returned status code 503
2017-07-05 20:35:43.546 INFO BACKBLAZE_UPLOAD URL request 'https://pod-000-1041-01.backblaze.com/b2api/v1/b2_upload_file/c02ac2f6898f0ef955d2091c/c001_v0001041_t0052' returned status code 503
2017-07-05 21:34:45.695 INFO PACK_END Packed Movies/m7.mkv (4701326613)
2017-07-05 23:25:10.641 INFO BACKBLAZE_UPLOAD URL request 'https://pod-000-1043-00.backblaze.com/b2api/v1/b2_upload_file/c02ac2f6898f0ef955d2091c/c001_v0001043_t0020' returned status code 503
2017-07-06 00:05:01.648 INFO PACK_END Packed Movies/m8.mkv (7046113481)
2017-07-06 00:09:34.559 INFO BACKBLAZE_UPLOAD URL request 'https://pod-000-1043-16.backblaze.com/b2api/v1/b2_upload_file/c02ac2f6898f0ef955d2091c/c001_v0001043_t0014' returned status code 503
2017-07-06 00:22:01.487 INFO PACK_END Packed Movies/m9.avi (932515840)
2017-07-06 01:45:27.328 INFO PACK_END Packed Movies/m10.mkv (4702021133)
2017-07-06 01:59:13.525 INFO BACKBLAZE_UPLOAD URL request 'https://pod-000-1033-05.backblaze.com/b2api/v1/b2_upload_file/c02ac2f6898f0ef955d2091c/c001_v0001033_t0004' returned status code 503
2017-07-06 02:07:55.453 INFO BACKBLAZE_UPLOAD URL request 'https://pod-000-1043-17.backblaze.com/b2api/v1/b2_upload_file/c02ac2f6898f0ef955d2091c/c001_v0001043_t0047' returned status code 503
2017-07-06 03:17:00.855 INFO BACKBLAZE_UPLOAD URL request 'https://pod-000-1041-17.backblaze.com/b2api/v1/b2_upload_file/c02ac2f6898f0ef955d2091c/c001_v0001041_t0001' returned status code 503
2017-07-06 03:35:27.563 INFO BACKBLAZE_UPLOAD URL request 'https://pod-000-1025-09.backblaze.com/b2api/v1/b2_upload_file/c02ac2f6898f0ef955d2091c/c001_v0001025_t0018' returned status code 503
2017-07-06 04:58:20.958 INFO PACK_END Packed Movies/m11.mkv (9805278563)
2017-07-06 08:15:15.523 INFO PACK_END Packed Movies/m12.mkv (9928928289)
2017-07-06 10:29:03.026 INFO BACKBLAZE_UPLOAD URL request 'https://pod-000-1040-06.backblaze.com/b2api/v1/b2_upload_file/c02ac2f6898f0ef955d2091c/c001_v0001040_t0027' returned status code 503
2017-07-06 11:26:14.162 INFO PACK_END Packed Movies/m13.mkv (9731726298)
2017-07-06 12:31:38.603 INFO BACKBLAZE_UPLOAD URL request 'https://pod-000-1043-08.backblaze.com/b2api/v1/b2_upload_file/c02ac2f6898f0ef955d2091c/c001_v0001043_t0058' returned status code 503
2017-07-06 12:33:09.218 INFO BACKBLAZE_UPLOAD URL request 'https://pod-000-1043-11.backblaze.com/b2api/v1/b2_upload_file/c02ac2f6898f0ef955d2091c/c001_v0001043_t0028' returned status code 503
2017-07-06 14:39:08.875 INFO PACK_END Packed Movies/m14.mkv (10314004027)
2017-07-06 14:44:07.128 INFO BACKBLAZE_UPLOAD URL request 'https://pod-000-1018-06.backblaze.com/b2api/v1/b2_upload_file/c02ac2f6898f0ef955d2091c/c001_v0001018_t0018' returned status code 503
2017-07-06 16:44:03.352 INFO BACKBLAZE_UPLOAD URL request 'https://pod-000-1043-00.backblaze.com/b2api/v1/b2_upload_file/c02ac2f6898f0ef955d2091c/c001_v0001043_t0007' returned status code 503
2017-07-06 17:29:54.098 INFO BACKBLAZE_UPLOAD URL request 'https://pod-000-1043-12.backblaze.com/b2api/v1/b2_upload_file/c02ac2f6898f0ef955d2091c/c001_v0001043_t0023' returned status code 503
2017-07-06 18:07:28.343 INFO PACK_END Packed Movies/m15.mkv (9738444669)
2017-07-06 19:50:00.558 INFO BACKBLAZE_UPLOAD URL request 'https://pod-000-1043-17.backblaze.com/b2api/v1/b2_upload_file/c02ac2f6898f0ef955d2091c/c001_v0001043_t0036' returned status code 503
2017-07-06 22:17:27.880 INFO PACK_END Packed Movies/m16.mkv (12439262823)
2017-07-06 23:12:59.915 INFO BACKBLAZE_UPLOAD URL request 'https://pod-000-1011-15.backblaze.com/b2api/v1/b2_upload_file/c02ac2f6898f0ef955d2091c/c001_v0001011_t0042' returned status code 503
2017-07-06 23:16:53.808 ERROR UPLOAD_CHUNK Failed to find the path for the chunk aeef2ea477ae36c164e9e227cbdeb29e0f92630df90e5e046100ec4a09ad9fad: http: read on closed response body
root@salotto:/home/plex#

I attempted to list the snapshots and the files, but there were none. So, despite no .duplicacy/incomplete was there, I decided to restart the backup anyways:

root@salotto:/home/plex# /root/duplicacy.sh -log backup
2017-07-08 16:18:32.551 INFO STORAGE_SET Storage set to b2://salotto-plex
2017-07-08 16:18:36.085 INFO BACKUP_START No previous backup found
2017-07-08 16:18:36.085 INFO BACKUP_INDEXING Indexing /home/plex
2017-07-08 16:18:37.364 INFO BACKUP_LIST Listing all chunks
2017-07-08 16:18:50.109 INFO PACK_END Packed .DS_Store (12292)
2017-07-08 16:18:50.128 INFO PACK_END Packed ._.DS_Store (4096)
2017-07-08 16:18:50.137 INFO PACK_END Packed .smbcredentials (40)
2017-07-08 16:18:52.495 INFO PACK_END Packed Cartoons/cartoon1.webm (122006039)
2017-07-08 16:18:57.855 INFO PACK_END Packed Cartoons/cartoon2.mp4 (253974996)
2017-07-08 16:19:07.177 INFO PACK_END Packed Cartoons/cartoon3.mp4 (463430930)
2017-07-08 16:19:21.686 INFO PACK_END Packed Cartoons/cartoon4.mp4 (738873175)
2017-07-08 16:19:39.682 INFO PACK_END Packed Cartoons/cartoon5.mp4 (755498815)
2017-07-08 16:19:59.738 INFO PACK_END Packed Movies/m1.avi (1056950272)
2017-07-08 16:25:25.467 INFO PACK_END Packed Movies/m2.mkv (16981988849)
2017-07-08 16:25:48.933 INFO PACK_END Packed Movies/m3.avi (1172026064)
2017-07-08 16:25:51.157 INFO PACK_END Packed Movies/m4.avi (106526720)
2017-07-08 16:27:28.623 INFO PACK_END Packed Movies/m5.mkv (4705937293)
  [...]

I changed the file names for privacy reasons, but you can still compare the timing: it’s way faster now! For instance, this time it took ~6’ to upload Movies/m1.avi, whereas the first time it took ~5 hours. Is it because it’s not actually uploading, but just checking the files with the remote chunks?

#2

Right, the first time it was uploading all chunks that composed Movies/m1.avi while the second time detected that all chunks existed in the storage so 6 minutes was just the scanning time.

Which version are you running? The fast resuming feature was introduced in 2.0.4 but there was a bug that has been fixed in 2.0.5. So if you run 2.0.5 then you don’t even need to spend 6 minutes to rescan Movies/m1.avi.

In 2.0.5 there was also a change that I think would fix this read on closed response body error. I suspected that this error is always accompanied by a http 3xx status code, so by retrying on a 3xx status code it can avoid reading the closed response body.

One last thing, you can use the -threads option to increase the backup speed if you think it didn’t saturate your uplink.

#3

I’m on 2.0.3, but if upgrading won’t break the chunk/package format, I’ll do that right away.

Thanks!

#4

There hasn’t been any change to the chunk/package format since 2.0.0. Even if there is a change in the future we’ll always promise backward compatibility.