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

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?

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

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

1 Like

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