Mysterious Errors

Support
1

Hello , I am using Duplicati 2.0.4.23 Beta on Windows 10 Home to backup a folder with ca. 5 GB Data to Google Drive and a WebDAV destination with SSL. Both backups are with GPG encrypted and compressed with zip. The Backup using WebDAV always get three errors from Duplicati.Library.Main.Operation.TestHandler saying, it can’t process three files (one .dlist, one .dindex and one .dblock) because the sizes of the files aren’t the expected ones. I think this is the verification process. The files are always different. The other backup to Google Drive don’t get these errors, so I thought of a corrupt backup. I used the affected command to find out wich files are affected by the dblock file and tried to restore it(because only one was affected). It went successful! Then I downloaded the dindex file and compared the expected size with the downloaded file’s size, it was the same! I don’t have a clue what is happening. Disable the verification would be a workaround, but i want to have the verification. Here is the log(parts in german):

DeletedFiles: 0
DeletedFolders: 0
ModifiedFiles: 0
ExaminedFiles: 59841
OpenedFiles: 0
AddedFiles: 0
SizeOfModifiedFiles: 0
SizeOfAddedFiles: 0
SizeOfExaminedFiles: 5260878333
SizeOfOpenedFiles: 0
NotProcessedFiles: 0
AddedFolders: 0
TooLargeFiles: 0
FilesWithError: 0
ModifiedFolders: 0
ModifiedSymlinks: 0
AddedSymlinks: 0
DeletedSymlinks: 0
PartialBackup: False
Dryrun: False
MainOperation: Backup
CompactResults: null
DeleteResults:
    DeletedSets: []
    Dryrun: False
    MainOperation: Delete
    CompactResults: null
    ParsedResult: Error
    Version: 2.0.4.23 (2.0.4.23_beta_2019-07-14)
    EndTime: 30.08.2019 11:01:42 (1567155702)
    BeginTime: 30.08.2019 11:01:42 (1567155702)
    Duration: 00:00:00.4986623
    Messages: [
        2019-08-30 11:01:25 +02 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: Die Operation Backup wurde gestartet,
        2019-08-30 11:01:27 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started:  (),
        2019-08-30 11:01:28 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Completed:  (631 Bytes),
        2019-08-30 11:01:42 +02 - [Information-Duplicati.Library.Main.Operation.DeleteHandler:RetentionPolicy-StartCheck]: Start checking if backups can be removed,
        2019-08-30 11:01:42 +02 - [Information-Duplicati.Library.Main.Operation.DeleteHandler:RetentionPolicy-FramesAndIntervals]: Time frames and intervals pairs: 7.00:00:00 / 1.00:00:00, 28.00:00:00 / 7.00:00:00, 365.00:00:00 / 31.00:00:00,
...
    ]
    Warnings: []
    Errors: [
        2019-08-30 11:02:30 +02 - [Error-Duplicati.Library.Main.Operation.TestHandler-FailedToProcessFile]: Failed to process file duplicati-20190808T083941Z.dlist.zip.gpg,
        2019-08-30 11:03:16 +02 - [Error-Duplicati.Library.Main.Operation.TestHandler-FailedToProcessFile]: Failed to process file duplicati-i1b163e5e654a4f7e81106fefc5275185.dindex.zip.gpg,
        2019-08-30 11:04:04 +02 - [Error-Duplicati.Library.Main.Operation.TestHandler-FailedToProcessFile]: Failed to process file duplicati-b870fe3b452714c2e842d72055118acf5.dblock.zip.gpg
    ]
    BackendStatistics:
        RemoteCalls: 17
        BytesUploaded: 0
        BytesDownloaded: 7518465
        FilesUploaded: 0
        FilesDownloaded: 15
        FilesDeleted: 0
        FoldersCreated: 0
        RetryAttempts: 12
        UnknownFileSize: 0
        UnknownFileCount: 0
        KnownFileCount: 631
        KnownFileSize: 2994211846
        LastBackupDate: 28.08.2019 16:30:56 (1567002656)
        BackupListCount: 3
        TotalQuotaSpace: 0
        FreeQuotaSpace: 0
        AssignedQuotaSpace: -1
        ReportedQuotaError: False
        ReportedQuotaWarning: False
        ParsedResult: Error
        Version: 2.0.4.23 (2.0.4.23_beta_2019-07-14)
        Messages: [
            2019-08-30 11:01:25 +02 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: Die Operation Backup wurde gestartet,
            2019-08-30 11:01:27 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started:  (),
            2019-08-30 11:01:28 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Completed:  (631 Bytes),
            2019-08-30 11:01:42 +02 - [Information-Duplicati.Library.Main.Operation.DeleteHandler:RetentionPolicy-StartCheck]: Start checking if backups can be removed,
            2019-08-30 11:01:42 +02 - [Information-Duplicati.Library.Main.Operation.DeleteHandler:RetentionPolicy-FramesAndIntervals]: Time frames and intervals pairs: 7.00:00:00 / 1.00:00:00, 28.00:00:00 / 7.00:00:00, 365.00:00:00 / 31.00:00:00,
...
        ]
        Warnings: []
        Errors: [
            2019-08-30 11:02:30 +02 - [Error-Duplicati.Library.Main.Operation.TestHandler-FailedToProcessFile]: Failed to process file duplicati-20190808T083941Z.dlist.zip.gpg,
            2019-08-30 11:03:16 +02 - [Error-Duplicati.Library.Main.Operation.TestHandler-FailedToProcessFile]: Failed to process file duplicati-i1b163e5e654a4f7e81106fefc5275185.dindex.zip.gpg,
            2019-08-30 11:04:04 +02 - [Error-Duplicati.Library.Main.Operation.TestHandler-FailedToProcessFile]: Failed to process file duplicati-b870fe3b452714c2e842d72055118acf5.dblock.zip.gpg
        ]
RepairResults: null
TestResults:
    MainOperation: Test
    Verifications: [
        Key: duplicati-20190808T083941Z.dlist.zip.gpg
        Value: [
            Key: Error
            Value: Die Datei duplicati-20190808T083941Z.dlist.zip.gpg wurde heruntergeladen und hat die Größe 501051, erwartet war allerdings die Größe 5223626
        ],
        Key: duplicati-i1b163e5e654a4f7e81106fefc5275185.dindex.zip.gpg
        Value: [
            Key: Error
            Value: Die Datei duplicati-i1b163e5e654a4f7e81106fefc5275185.dindex.zip.gpg wurde heruntergeladen und hat die Größe 501321, erwartet war allerdings die Größe 14805
        ],
        Key: duplicati-b870fe3b452714c2e842d72055118acf5.dblock.zip.gpg
        Value: [
            Key: Error
            Value: Die Datei duplicati-b870fe3b452714c2e842d72055118acf5.dblock.zip.gpg wurde heruntergeladen und hat die Größe 501321, erwartet war allerdings die Größe 10361145
        ]
    ]
    ParsedResult: Error
    Version: 2.0.4.23 (2.0.4.23_beta_2019-07-14)
    EndTime: 30.08.2019 11:04:04 (1567155844)
    BeginTime: 30.08.2019 11:01:43 (1567155703)
    Duration: 00:02:21.0124141
    Messages: [
        2019-08-30 11:01:25 +02 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: Die Operation Backup wurde gestartet,
        2019-08-30 11:01:27 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started:  (),
        2019-08-30 11:01:28 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Completed:  (631 Bytes),
        2019-08-30 11:01:42 +02 - [Information-Duplicati.Library.Main.Operation.DeleteHandler:RetentionPolicy-StartCheck]: Start checking if backups can be removed,
        2019-08-30 11:01:42 +02 - [Information-Duplicati.Library.Main.Operation.DeleteHandler:RetentionPolicy-FramesAndIntervals]: Time frames and intervals pairs: 7.00:00:00 / 1.00:00:00, 28.00:00:00 / 7.00:00:00, 365.00:00:00 / 31.00:00:00,
...
    ]
    Warnings: []
    Errors: [
        2019-08-30 11:02:30 +02 - [Error-Duplicati.Library.Main.Operation.TestHandler-FailedToProcessFile]: Failed to process file duplicati-20190808T083941Z.dlist.zip.gpg,
        2019-08-30 11:03:16 +02 - [Error-Duplicati.Library.Main.Operation.TestHandler-FailedToProcessFile]: Failed to process file duplicati-i1b163e5e654a4f7e81106fefc5275185.dindex.zip.gpg,
        2019-08-30 11:04:04 +02 - [Error-Duplicati.Library.Main.Operation.TestHandler-FailedToProcessFile]: Failed to process file duplicati-b870fe3b452714c2e842d72055118acf5.dblock.zip.gpg
    ]
ParsedResult: Error
Version: 2.0.4.23 (2.0.4.23_beta_2019-07-14)
EndTime: 30.08.2019 11:04:04 (1567155844)
BeginTime: 30.08.2019 11:01:25 (1567155685)
Duration: 00:02:38.9476090
Messages: [
    2019-08-30 11:01:25 +02 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: Die Operation Backup wurde gestartet,
    2019-08-30 11:01:27 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started:  (),
    2019-08-30 11:01:28 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Completed:  (631 Bytes),
    2019-08-30 11:01:42 +02 - [Information-Duplicati.Library.Main.Operation.DeleteHandler:RetentionPolicy-StartCheck]: Start checking if backups can be removed,
    2019-08-30 11:01:42 +02 - [Information-Duplicati.Library.Main.Operation.DeleteHandler:RetentionPolicy-FramesAndIntervals]: Time frames and intervals pairs: 7.00:00:00 / 1.00:00:00, 28.00:00:00 / 7.00:00:00, 365.00:00:00 / 31.00:00:00,
...
]
Warnings: []
Errors: [
    2019-08-30 11:02:30 +02 - [Error-Duplicati.Library.Main.Operation.TestHandler-FailedToProcessFile]: Failed to process file duplicati-20190808T083941Z.dlist.zip.gpg,
    2019-08-30 11:03:16 +02 - [Error-Duplicati.Library.Main.Operation.TestHandler-FailedToProcessFile]: Failed to process file duplicati-i1b163e5e654a4f7e81106fefc5275185.dindex.zip.gpg,
    2019-08-30 11:04:04 +02 - [Error-Duplicati.Library.Main.Operation.TestHandler-FailedToProcessFile]: Failed to process file duplicati-b870fe3b452714c2e842d72055118acf5.dblock.zip.gpg
]

Here are the details of the downloaded dindex file:

(translation)
Key: duplicati-i1b163e5e654a4f7e81106fefc5275185.dindex.zip.gpg
        Value: [
            Key: Error
            Value: The file duplicati-i1b163e5e654a4f7e81106fefc5275185.dindex.zip.gpg was downloaded and has got the size 501321, expected, however, was the size 14805
        ]

Anmerkung%202019-08-19%20120523
Anmerkung 2019-08-19 120523.jpg365×510 99 KB

2

I’ve had similar mistakes, too. Because of broken backup archives
I think you have a broken archive.

which message shows the affected dblock file
duplicati-b870fe3b452714c2e842d72055118acf5.dblock.zip

3

I don’t really understand what you want to say. The command? Because I could restore the file, that is depended on this file.

4

I use affected to see what files were affected. On the screenshot I demonstrated it

image
image.png1364×665 39.4 KB

5

By the way, I don’t use gpg encryption using the standard method of specifying a passphrase password. Try to check this.

I have also noticed that magic strange errors appear while working through the webdav protocol and they also disappear. Apparently, the webdav protocol is a very capricious child

I advise you to check not a few services with webdav support. Try the Russian service Yandex disk there is free 10 gigabytes of storage space

6

It shows me a file of a backup version. I could restore the file.

7

What WebDAV is this? I tried a different translator to check which number is which, and looked at English version too. The number on the right is expected size. The one on the left is download. Is it always 501321 regardless of which file Duplicati asks for? As a side note, the GUI verification, like CLI, does sets of three:

The TEST command

This is a rolling check, i.e. when executed another time different samples are verified than in the first run. A sample consists of 1 dlist, 1 dindex, 1 dblock.

What’s odd in the WebDAV downloads is the size is 501321 regardless of whether the original was larger or smaller. It makes me wonder whether you’re just getting some constant data regardless of the request.

Copying the file out of your –tempdir folder is possible, but takes some work (e.g. a copy loop) to catch it. Looking in file to see what actually downloaded (using a text editor, hex viewer, etc.) might be enlightening. Alternatively (as suggested) maybe you just need to use a different destination than this troublesome one.

Using what? Duplicati.CommandLine.BackendTool.exe can do it, but not everyone is aware of this tool. Another useful command line tool would be Duplicati.CommandLine.BackendTester.exe where you can provide an empty folder at WebDAV server, then find whether this tester thinks it’s working as it should. Getting a Target URL can be tricky, but the Commandline screen or Export As Command-line can help.

For best certainty when testing restores of source files, put –no-local-blocks in job Advanced options, so Duplicati can’t optimize and get blocks from your original file on disk. You want to force using the remote.

1 Like
8
  1. I downloaded the file with the webinterface of my storageprovider.
  2. I tried to restore it with --no-local-blocks. It failed, with the same messages size don’t match. The dblock files are now always the size 501322
  3. Then I downloaded the dlist file (I think the dlist file wasn’t needed when using the database, because in the log the file isn’t mentioned) and all “corrupt” dblock files using the webinterface again and tried to restore the file without my database from the downloaded files. This went successful!
  4. The blocks in the dblock file duplicati-b870fe3b452714c2e842d72055118acf5.dblock.zip are now moved, but this doesn’t matter, because every file is making errors. (Because after this time I used affected command the file isn’t depended on the dblock file.)

There is the log from the try failed:

3 files need to be restored (452,92 MB) // (duplicated files)
  Downloading file (9,91 MB) ...
  Downloading file (9,91 MB) ...
  Downloading file (9,91 MB) ...
  Downloading file (9,91 MB) ...
  Downloading file (9,91 MB) ...
Failed to patch with remote file: "duplicati-b33bb3fac81da49b7a99cf09076e00d59.dblock.zip.gpg", message: Die Datei duplicati-b33bb3fac81da49b7a99cf09076e00d59.dblock.zip.gpg wurde heruntergeladen und hat die Größe 501322, erwartet war allerdings die Größe 10393295 => Die Datei duplicati-b33bb3fac81da49b7a99cf09076e00d59.dblock.zip.gpg wurde heruntergeladen und hat die Größe 501322, erwartet war allerdings die Größe 10393295
  Downloading file (9,89 MB) ...
  Downloading file (9,89 MB) ...
  Downloading file (9,89 MB) ...
  Downloading file (9,89 MB) ...
  Downloading file (9,89 MB) ...
Failed to patch with remote file: "duplicati-b73b03ec3e28f4c8ab1a16aa120f18e25.dblock.zip.gpg", message: Die Datei duplicati-b73b03ec3e28f4c8ab1a16aa120f18e25.dblock.zip.gpg wurde heruntergeladen und hat die Größe 501322, erwartet war allerdings die Größe 10370137 => Die Datei duplicati-b73b03ec3e28f4c8ab1a16aa120f18e25.dblock.zip.gpg wurde heruntergeladen und hat die Größe 501322, erwartet war allerdings die Größe 10370137
  Downloading file (9,92 MB) ...
  Downloading file (9,92 MB) ...
  Downloading file (9,92 MB) ...
  Downloading file (9,92 MB) ...
  Downloading file (9,92 MB) ...
Failed to patch with remote file: "duplicati-ba4820639434a47b4b8d79b5c073e6c6f.dblock.zip.gpg", message: Die Datei duplicati-ba4820639434a47b4b8d79b5c073e6c6f.dblock.zip.gpg wurde heruntergeladen und hat die Größe 501322, erwartet war allerdings die Größe 10403086 => Die Datei duplicati-ba4820639434a47b4b8d79b5c073e6c6f.dblock.zip.gpg wurde heruntergeladen und hat die Größe 501322, erwartet war allerdings die Größe 10403086
  Downloading file (9,91 MB) ...
  Downloading file (9,91 MB) ...
  Downloading file (9,91 MB) ...
  Downloading file (9,91 MB) ...
  Downloading file (9,91 MB) ...
Failed to patch with remote file: "duplicati-b22e306c42f474bb09c0645d0568ca762.dblock.zip.gpg", message: Die Datei duplicati-b22e306c42f474bb09c0645d0568ca762.dblock.zip.gpg wurde heruntergeladen und hat die Größe 501322, erwartet war allerdings die Größe 10389414 => Die Datei duplicati-b22e306c42f474bb09c0645d0568ca762.dblock.zip.gpg wurde heruntergeladen und hat die Größe 501322, erwartet war allerdings die Größe 10389414
  Downloading file (9,92 MB) ...
  Downloading file (9,92 MB) ...
  Downloading file (9,92 MB) ...
  Downloading file (9,92 MB) ...
  Downloading file (9,92 MB) ...
Failed to patch with remote file: "duplicati-bf306049435c34f9786e68c50c47f100e.dblock.zip.gpg", message: Die Datei duplicati-bf306049435c34f9786e68c50c47f100e.dblock.zip.gpg wurde heruntergeladen und hat die Größe 501322, erwartet war allerdings die Größe 10399897 => Die Datei duplicati-bf306049435c34f9786e68c50c47f100e.dblock.zip.gpg wurde heruntergeladen und hat die Größe 501322, erwartet war allerdings die Größe 10399897
  Downloading file (9,89 MB) ...
  Downloading file (9,89 MB) ...
  Downloading file (9,89 MB) ...
  Downloading file (9,89 MB) ...
  Downloading file (9,89 MB) ...
Failed to patch with remote file: "duplicati-b261929003d8b4c01b7034f1f3e3b52b6.dblock.zip.gpg", message: Die Datei duplicati-b261929003d8b4c01b7034f1f3e3b52b6.dblock.zip.gpg wurde heruntergeladen und hat die Größe 501322, erwartet war allerdings die Größe 10372306 => Die Datei duplicati-b261929003d8b4c01b7034f1f3e3b52b6.dblock.zip.gpg wurde heruntergeladen und hat die Größe 501322, erwartet war allerdings die Größe 10372306
  Downloading file (9,94 MB) ...
  Downloading file (9,94 MB) ...
  Downloading file (9,94 MB) ...
  Downloading file (9,94 MB) ...
  Downloading file (9,94 MB) ...
Failed to patch with remote file: "duplicati-b2243db79c853422b9b5b3f42a2ec1fbb.dblock.zip.gpg", message: Die Datei duplicati-b2243db79c853422b9b5b3f42a2ec1fbb.dblock.zip.gpg wurde heruntergeladen und hat die Größe 501322, erwartet war allerdings die Größe 10428003 => Die Datei duplicati-b2243db79c853422b9b5b3f42a2ec1fbb.dblock.zip.gpg wurde heruntergeladen und hat die Größe 501322, erwartet war allerdings die Größe 10428003
  0 files need to be restored (0 Bytes)
Verifying restored files ...
Ein Teil des Pfades "E:\xxxxx" konnte nicht gefunden werden. => Ein Teil des Pfades "E:\xxxxx" konnte nicht gefunden werden.
Ein Teil des Pfades "E:\xxxxx" konnte nicht gefunden werden. => Ein Teil des Pfades "E:\xxxxx" konnte nicht gefunden werden.
Ein Teil des Pfades "E:\xxxxx" konnte nicht gefunden werden. => Ein Teil des Pfades "E:\xxxxx" konnte nicht gefunden werden.
Restored 0 (0 Bytes) files to E:\
Duration of restore: 00:05:22
Return code: 0

There is the log from the try went successful:

Restore started at 31.08.2019 15:58:44
  Listing remote folder ...
  Downloading file (4,98 MB) ...
  Downloading file (9,94 MB) ...
  Downloading file (9,91 MB) ...
  Downloading file (9,89 MB) ...
  Downloading file (9,91 MB) ...
  Downloading file (9,89 MB) ...
  Downloading file (9,92 MB) ...
  Downloading file (9,92 MB) ...
Checking remote backup ...
  Listing remote folder ...
Skipping invalid version: 1 // I wasn't sure the version is depended on the dlist file
Skipping invalid version: 2
Skipping invalid version: 3
Skipping invalid version: 4
Skipping invalid version: 5
Skipping invalid version: 6
Skipping invalid version: 7
Skipping invalid version: 8
Skipping invalid version: 9
Skipping invalid version: 10
Checking existing target files ...
  Downloading file (9,91 MB) ...
  3 files need to be restored (452,92 MB) // duplicated files again
  Downloading file (9,89 MB) ...
  Downloading file (9,92 MB) ...
Creating missing folder E:\xxx for  file E:\xxx\xxxxx.xxx
Creating missing folder E:\xxx for  file E:\xxx\xxxxx.xxx
Creating missing folder E:\xxx for  file E:\xxx\xxxxx.xxx
  Downloading file (9,91 MB) ...
  Downloading file (9,92 MB) ...
  Downloading file (9,89 MB) ...
  Downloading file (9,94 MB) ...
  0 files need to be restored (0 Bytes)
Verifying restored files ...
Restored 3 (452,92 MB) files to E:\
Duration of restore: 00:00:31
***********************************************
Did we help save your files? If so, please support Duplicati with a donation. We suggest 10€ for private use and 100€ for commercial use.
https://www.duplicati.com/donate/
***********************************************
Return code: 2
9

and if the dlist and dindex files also download at that size, every time, it says your WebDAV provider isn’t returning the file properly, unless somehow Duplicati is stuck asking for the wrong one – any that size on WebDAV provider that might be accidentally downloaded? Something is coming down from somewhere.

What bad something is isn’t possible to know without looking at the file, but file size may be an easy clue.
Pursuing file size theory is easier if you add –upload-verification-file=true to get duplicati-verification.json which you can then look at with a text editor to see if any file in the backup legitimately has a 501322 size.

Alternatively see if you can get the BackendTool to get file, then at least it won’t be deleted after download, which is the challenge of trying to copy the temp file. Name is unknown, so just copy all the dup-* files…

If you mean you did something like a restore from files manually downloaded into a folder, using “Restore” → “Direct restore from backup files” with --no-local-blocks added (maybe on second screen), then great! Your problem seems to be on the download side, not the upload, so possibly all your backup files are fine, however you can’t actually use them for restore without such manual workarounds, which is not so fine…

If you want to download all your destination files for checking, the Duplicati utility-scripts folder has Python and PowerShell scripts you can use to prove (or disprove) that all the remote files agree with DB records.

You could also get an opinion using some totally non-Duplicati WebDAV client on how well files download.
WinSCP and Cyberduck are two possible clients, but there are quite a few others, maybe Windows itself.

10

The documentation is very good!
https://duplicati.readthedocs.io/en/latest/07-other-command-line-utilities/#duplicaticommandlinebackendtoolexe
I looked into the code of the BackendTool and saw, that --tempdir is working(not mentioned in the documentation) so I don’t have to search for the file. I’m going to try the command!

11

After a long time I’ve found out more crazy things:

  1. The backendtool always downloads the website of my storage provider. I know a bit HTML so I recognised it, after gpg4win failed to decipher the file…
  2. The backendtool always downloads a file with the name of the file I wanted, if the file doesn’t exist, too.
  3. Windows fails with logging in to my storage (with 401 unauthorized). But if I click a second time on the network drive, my files appear(I saved the password).
  4. WinSCP hasn’t got any problems with WebDAV. Everything works fine.

I still don’t know why the backendtool gets those files.