Duplicacy failing with Dropbox (0 byte files, restore impossible)

Bug
#1

Hi,
I usually backup to Google Drive or a local disk, but seeing that Duplicacy Web added Dropbox back, I tried to backup to Dropbox too, as redundancy.

Everything seemed to go well. Though Dropbox doesn’t seem to like multi threading, it still uploads fast with 1 thread, and it seems to be accepting 2 threads. (it was failing with 20 or 15 threads, with 2 seems to be working, I am not sure what the limit is.)

The problem started yesterday when I ran a check and got this error.

Running check command from C:\ProgramData\.duplicacy-web\repositories/localhost/all
Options: [-log check -storage Dropbox -a -tabular]
2020-05-20 19:55:24.858 INFO STORAGE_SET Storage set to dropbox://Duplicacy Backup Data
2020-05-20 19:55:26.570 INFO SNAPSHOT_CHECK Listing all chunks
2020-05-20 20:00:46.492 ERROR DOWNLOAD_DECRYPT Failed to decrypt the file snapshots/1-ONeill-C-Apps-Dropbox/1: No enough encrypted data (0 bytes) provided
Failed to decrypt the file snapshots/1-ONeill-C-Apps-Dropbox/1: No enough encrypted data (0 bytes) provided

So I looked at the forum. And read that some people had problems with 0 byte files, but those seem related to local storages and kernel panics. (Failed to decrypt the file snapshots)

I looked at the files in Dropbox, and sure enough, there were a few snapshot files with 0 bytes in multiple backup folders… I removed those, and run a new (simple) check. The check passed.

But I thought: if there are snapshots file with 0 bytes… are there any chunks files with 0 bytes? And sure enough, yes, there are… quite a bit actually. There are 40-51 0 byte file per folders, for a total of around 12k empty chunks out of 186k chunks.

Obviously restores fail:

2020-05-20 20:20:52.356 INFO REPOSITORY_SET Repository set to E:/Downloads/STEAMDATATRY
2020-05-20 20:20:52.357 INFO STORAGE_SET Storage set to dropbox://Duplicacy Backup Data
2020-05-20 20:20:52.690 INFO SNAPSHOT_FILTER Loaded 0 include/exclude pattern(s)
2020-05-20 20:20:53.936 INFO RESTORE_INPLACE Forcing in-place mode with a non-default preference path
2020-05-20 20:20:57.685 INFO SNAPSHOT_FILTER Parsing filter file \\?\C:\ProgramData\.duplicacy-web\repositories\localhost\restore\.duplicacy\filters
2020-05-20 20:20:57.685 INFO SNAPSHOT_FILTER Loaded 0 include/exclude pattern(s)
2020-05-20 20:20:57.686 INFO RESTORE_START Restoring E:/Downloads/STEAMDATATRY to revision 7
2020-05-20 20:20:59.005 INFO DOWNLOAD_PROGRESS Downloaded chunk 1 size 7386268, 3.52MB/s 00:04:54 0.6%
2020-05-20 20:21:00.306 INFO DOWNLOAD_PROGRESS Downloaded chunk 2 size 10943095, 5.83MB/s 00:02:56 1.6%
2020-05-20 20:21:01.421 INFO DOWNLOAD_PROGRESS Downloaded chunk 3 size 1712419, 4.78MB/s 00:03:35 1.8%
2020-05-20 20:21:02.634 INFO DOWNLOAD_PROGRESS Downloaded chunk 4 size 8817520, 5.50MB/s 00:03:05 2.6%
2020-05-20 20:21:03.591 INFO DOWNLOAD_PROGRESS Downloaded chunk 5 size 1467067, 4.82MB/s 00:03:31 2.7%
2020-05-20 20:21:06.023 INFO DOWNLOAD_PROGRESS Downloaded chunk 6 size 4248262, 3.66MB/s 00:04:36 3.1%
2020-05-20 20:21:07.359 INFO DOWNLOAD_PROGRESS Downloaded chunk 7 size 14948645, 4.72MB/s 00:03:31 4.5%
2020-05-20 20:21:08.568 INFO DOWNLOAD_PROGRESS Downloaded chunk 8 size 2205739, 4.48MB/s 00:03:42 4.7%
2020-05-20 20:21:10.055 INFO DOWNLOAD_PROGRESS Downloaded chunk 9 size 5421870, 4.19MB/s 00:03:56 5.2%
2020-05-20 20:21:10.995 INFO DOWNLOAD_PROGRESS Downloaded chunk 10 size 1231103, 4.28MB/s 00:03:51 5.3%
2020-05-20 20:21:12.300 INFO DOWNLOAD_PROGRESS Downloaded chunk 11 size 8807356, 4.27MB/s 00:03:49 6.1%
2020-05-20 20:21:13.306 INFO DOWNLOAD_PROGRESS Downloaded chunk 12 size 1353351, 4.09MB/s 00:04:00 6.2%
2020-05-20 20:21:14.348 INFO DOWNLOAD_PROGRESS Downloaded chunk 13 size 4121631, 4.08MB/s 00:03:59 6.6%
2020-05-20 20:21:15.392 INFO DOWNLOAD_PROGRESS Downloaded chunk 14 size 2600031, 3.99MB/s 00:04:04 6.8%
2020-05-20 20:21:16.530 INFO DOWNLOAD_PROGRESS Downloaded chunk 15 size 3940249, 3.98MB/s 00:04:04 7.2%
2020-05-20 20:21:17.666 INFO DOWNLOAD_PROGRESS Downloaded chunk 16 size 3423140, 3.94MB/s 00:04:05 7.5%
2020-05-20 20:21:19.318 INFO DOWNLOAD_PROGRESS Downloaded chunk 17 size 4049257, 3.76MB/s 00:04:16 7.9%
2020-05-20 20:21:20.352 INFO DOWNLOAD_PROGRESS Downloaded chunk 18 size 2596369, 3.70MB/s 00:04:19 8.1%
2020-05-20 20:21:21.570 INFO DOWNLOAD_PROGRESS Downloaded chunk 19 size 4603831, 3.73MB/s 00:04:16 8.5%
2020-05-20 20:21:23.550 INFO DOWNLOAD_PROGRESS Downloaded chunk 20 size 10111327, 3.81MB/s 00:04:08 9.5%
2020-05-20 20:21:24.754 INFO DOWNLOAD_PROGRESS Downloaded chunk 21 size 5024691, 3.85MB/s 00:04:04 9.9%
2020-05-20 20:21:26.149 INFO DOWNLOAD_PROGRESS Downloaded chunk 22 size 8632825, 3.87MB/s 00:04:01 10.7%
2020-05-20 20:21:28.720 INFO DOWNLOAD_PROGRESS Downloaded chunk 23 size 7029082, 3.84MB/s 00:04:01 11.4%
2020-05-20 20:21:29.970 INFO DOWNLOAD_PROGRESS Downloaded chunk 24 size 10284976, 4.02MB/s 00:03:48 12.3%
2020-05-20 20:21:31.427 INFO DOWNLOAD_PROGRESS Downloaded chunk 25 size 3242205, 3.88MB/s 00:03:55 12.6%
2020-05-20 20:21:32.777 INFO DOWNLOAD_PROGRESS Downloaded chunk 26 size 6992485, 3.96MB/s 00:03:49 13.2%
2020-05-20 20:21:33.734 INFO DOWNLOAD_PROGRESS Downloaded chunk 27 size 1792496, 3.89MB/s 00:03:52 13.4%
2020-05-20 20:21:34.874 INFO DOWNLOAD_PROGRESS Downloaded chunk 28 size 6242933, 3.95MB/s 00:03:47 14.0%
2020-05-20 20:21:36.006 INFO DOWNLOAD_PROGRESS Downloaded chunk 29 size 1330391, 3.78MB/s 00:03:57 14.1%
2020-05-20 20:21:37.305 INFO DOWNLOAD_PROGRESS Downloaded chunk 30 size 11576750, 3.96MB/s 00:03:44 15.2%
2020-05-20 20:21:38.746 INFO DOWNLOAD_PROGRESS Downloaded chunk 31 size 13890309, 4.19MB/s 00:03:28 16.4%
2020-05-20 20:21:40.659 INFO DOWNLOAD_PROGRESS Downloaded chunk 32 size 3079634, 4.06MB/s 00:03:34 16.7%
2020-05-20 20:21:42.246 INFO DOWNLOAD_PROGRESS Downloaded chunk 33 size 6652926, 4.02MB/s 00:03:35 17.3%
2020-05-20 20:21:43.592 INFO DOWNLOAD_PROGRESS Downloaded chunk 34 size 6451200, 4.07MB/s 00:03:31 17.9%
2020-05-20 20:21:44.918 INFO DOWNLOAD_PROGRESS Downloaded chunk 35 size 8052440, 4.14MB/s 00:03:25 18.6%
2020-05-20 20:21:46.190 INFO DOWNLOAD_PROGRESS Downloaded chunk 36 size 3761826, 4.05MB/s 00:03:29 19.0%
2020-05-20 20:21:47.545 INFO DOWNLOAD_PROGRESS Downloaded chunk 37 size 6575515, 4.09MB/s 00:03:25 19.6%
2020-05-20 20:21:48.646 INFO DOWNLOAD_PROGRESS Downloaded chunk 38 size 1732652, 4.05MB/s 00:03:27 19.7%
2020-05-20 20:21:49.653 INFO DOWNLOAD_PROGRESS Downloaded chunk 39 size 3519646, 4.03MB/s 00:03:27 20.1%
2020-05-20 20:21:50.650 INFO DOWNLOAD_PROGRESS Downloaded chunk 40 size 3371762, 4.02MB/s 00:03:27 20.4%
2020-05-20 20:21:51.743 INFO DOWNLOAD_PROGRESS Downloaded chunk 41 size 4207443, 4.02MB/s 00:03:26 20.8%
2020-05-20 20:21:52.663 INFO DOWNLOAD_PROGRESS Downloaded chunk 42 size 1611095, 3.97MB/s 00:03:28 20.9%
2020-05-20 20:21:53.744 INFO DOWNLOAD_PROGRESS Downloaded chunk 43 size 3611368, 3.96MB/s 00:03:28 21.2%
2020-05-20 20:21:55.203 INFO DOWNLOAD_PROGRESS Downloaded chunk 44 size 16777216, 4.10MB/s 00:03:17 22.8%
2020-05-20 20:21:56.368 INFO DOWNLOAD_PROGRESS Downloaded chunk 45 size 3185636, 4.08MB/s 00:03:17 23.1%
2020-05-20 20:21:57.553 INFO DOWNLOAD_PROGRESS Downloaded chunk 46 size 3200839, 4.07MB/s 00:03:17 23.4%
2020-05-20 20:21:58.633 INFO DOWNLOAD_PROGRESS Downloaded chunk 47 size 3058232, 4.05MB/s 00:03:17 23.6%
2020-05-20 20:21:59.816 INFO DOWNLOAD_PROGRESS Downloaded chunk 48 size 3517093, 4.04MB/s 00:03:17 24.0%
2020-05-20 20:22:00.699 INFO DOWNLOAD_PROGRESS Downloaded chunk 49 size 1699390, 4.00MB/s 00:03:18 24.1%
2020-05-20 20:22:01.991 INFO DOWNLOAD_PROGRESS Downloaded chunk 50 size 3135185, 3.98MB/s 00:03:18 24.4%
2020-05-20 20:22:03.386 INFO DOWNLOAD_PROGRESS Downloaded chunk 51 size 3849612, 3.92MB/s 00:03:21 24.8%
2020-05-20 20:22:04.629 INFO DOWNLOAD_PROGRESS Downloaded chunk 52 size 13768760, 4.05MB/s 00:03:11 26.0%
2020-05-20 20:22:05.377 WARN DOWNLOAD_RETRY Failed to decrypt the chunk 72c0cd3e456bd53ea52da91d37742010f8da7f2fde28907a916c4d0400a2fa79: No enough encrypted data (0 bytes) provided; retrying
2020-05-20 20:22:06.271 WARN DOWNLOAD_RETRY Failed to decrypt the chunk 72c0cd3e456bd53ea52da91d37742010f8da7f2fde28907a916c4d0400a2fa79: No enough encrypted data (0 bytes) provided; retrying
2020-05-20 20:22:07.351 WARN DOWNLOAD_RETRY Failed to decrypt the chunk 72c0cd3e456bd53ea52da91d37742010f8da7f2fde28907a916c4d0400a2fa79: No enough encrypted data (0 bytes) provided; retrying
2020-05-20 20:22:08.218 ERROR DOWNLOAD_DECRYPT Failed to decrypt the chunk 72c0cd3e456bd53ea52da91d37742010f8da7f2fde28907a916c4d0400a2fa79: No enough encrypted data (0 bytes) provided

Any idea of why this may be happening? (Maybe I should never use the multi-thread option with Dropbox?)
Any quick and easy way to remove the 0 byte files so I can check if the non-0 byte chunks are fine?

Receiving Failed to decrypt the chunk messages
#2

I can confirm that this appears to be related to the use of multiple threads. Even -threads 2 would produce some 0-size chunks although it happens less frequently than -threads 4 and -threads 8.

Looking at the code I found that we didn’t pass the chunk length in the Content-Length header when uploading a chunk. I’ll run some test to see if this header makes a difference.

3 Likes
#3

Setting Content-Length didn’t help. I’ll file a bug report with Dropbox.

1 Like
#4

It turned out that this is a bug caused by retrying without resetting the chunk reader: when the dropbox server returns an error like 429 (which happens more frequently if there are multiple uploading threads), we wait a small delay and resend the request. However, the chunk reader may have already reached the end of the buffer during the first attempt, so the server will only receive a 0-byte chunk.

This has been fixed by Fixed a bug where 0-byte file is upload after retrying · gilbertchen/go-dropbox@0baa901 · GitHub.

@HailAlistair I can send you a new binary for you to test the fix.

4 Likes
#5

Sure! I will test it.

#6

Which OS version do you need?

#7

Win64. (I use the web GUI.)

#8

This is the new CLI with the fix: http://acrosync.com/duplicacy/duplicacy_win_x64_2.5.3.exe

Download this file to C:\Users\username\.duplicacy-web\bin, stop the web GUI, edit C:\Users\username\.duplicacy-web\duplicacy.json to set the cli_version key:

"cli_version": "2.5.3",

and then restart the web GUI.

It should say Duplicacy CLI 2.5.3 in the log file ``C:\Users\username.duplicacy-web\logs\duplicacy_web.log `.

You can also run a check job first against your existing storage which should report 0-byte chunks without extra options.

#9

I’m testing it now. It took me a while to delete all the 0 byte files… as I used the Dropbox app to sync the Duplicacy folder (the files were set to only only, but it was a lot of files, Dropbox struggles with huge numbers of files), searched with File Explorer “size:0”, and then deleted all results.
I’m sure that there must be some quicker way… maybe using rclone or something like that to avoid having to use the Dropbox app?

Anyway, I then run a check with 2.5.3 to make sure that there were no 0-byte chunks. It obviously reported missing chunks, but no 0 byte files.

I’m restarting the backups now to see if new 0-byte files get created.
How do I ask Duplicacy to re-upload the 0-byte (now missing) chunks? Do I just delete all the snapshots files (in Dropbox, the ones named with the revision number)? Does that result in Duplicacy trying to start the backup as if it was a brand new backup?

#10

You’ve got a couple of options.

Delete (or preferably move out of the way) the snapshot files (all of them per snapshot ID; i.e. the whole snapshot ID folder) as you said - but that obviously means those old snapshots are gone, and it may only be that some of the snapshots are missing chunks.

Or you can set up another backup job for the same repository but with a different ID.

I’d recommend the second option as it’s easier to deal with.

In both cases, subsequent backups may upload the missing chunks and in turn fix those old snapshots. If so, you could in theory ‘undelete’ (move back) the deleted snapshots as per #1, or delete the temporary snapshot ID as per #2 - and continue running backups.

Obviously, you’ll want to see how much of your previous snaphots are in tact after this (check) and you could manually delete any snapshot revisions that are definitely missing chunks. You may prefer to continue using the new repository ID, depending how corrupt your snapshot history is. The key is making sure your latest revision for each repository isn’t missing any chunks, coz then you can resume backups and without re-uploading the whole shebang.

Edit: Just to clarify - going with option #2 should always allow you to have a backup chain with no missing chunks, as it’s a fresh backup. And it’ll do so without re-uploading everything. It’s just that if you want to keep as much historic backups as possible, you’ll want to run a ‘fresh’ backup to fill those missing chunks and then run a check to weed out any definately-broken snapshots. If it was me, I’d probably stay with the different IDs and allow the older ‘good’ snapshots to be pruned during the normal course.

#11

Any updates on this. I’ve got a macOS WebGUI install suffering from the similar behavior with -threads greater than 1.

#12

This should have been fixed by the latest CLI release 2.6.1. By default the web GUI will automatically update the CLI to the latest version on startup. Check the log file ~/.duplicacy-web/logs/duplicacy_web.log to see if it has a line that says Duplicacy CLI 2.6.1.