Error while running first backup to Dropbox (several times!)

After some small tests I set up three Duplicati backups on two computers to a Dropbox-Account. Every first run ends with an error:
First computer:
[Error-Duplicati.Library.Main.Operation.TestHandler-FailedToProcessFile]: Failed to process file duplicati-bb…dblock.zip.aes
Second computer:
Detected non-empty blocksets with no associated blocks!
I do not found any tricks to avoid this. Help!

EPH

System: 2.0.5.1_beta_2020-01-18 on Windows 10 64bit Home

Welcome to the forum @eph

I don’t have Dropbox, but I think it can file sync. Is your destination Dropbox or Local folder or drive?

Regardless, FailedToProcessFile needs a look with About --> Show log --> Live --> Retry to see how that seeming download attempt to verify file’s contents failed. You might need to click on a failed get for detail.

Blocksets issue is hard to explain. What OS is this? If on Windows, snapshot-policy to use VSS may help avoid seeing some file change while being backed up, but issue with that “should” be largely fixed already.

Is this GUI or CLI backup? CLI is easy to stop hard, and that can cause problems. GUI “Stop now” can too.

EDIT:

If you want to test some files without trying the backup (which might fail), use backup’s “Verify files” button.

Thank you for the answer, although I did not understand everything.

Maschine 1: I post here a part of the logfile, perhaps that helps to see, what is going wrong:
Failed: Detected non-empty blocksets with no associated blocks!
Details: System.Exception: Detected non-empty blocksets with no associated blocks!
bei Duplicati.Library.Main.Database.LocalDatabase.VerifyConsistency(Int64 blocksize, Int64 hashsize, Boolean verifyfilelists, IDbTransaction transaction)
bei Duplicati.Library.Main.Operation.Backup.BackupDatabase.<>c__DisplayClass34_0.b__0()
bei Duplicati.Library.Main.Operation.Common.SingleRunner.<>c__DisplayClass3_0.b__0()
bei Duplicati.Library.Main.Operation.Common.SingleRunner.d__21.MoveNext() --- Ende der Stapelüberwachung vom vorhergehenden Ort, an dem die Ausnahme ausgelöst wurde --- bei System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw() bei System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task) bei Duplicati.Library.Main.Operation.BackupHandler.<RunAsync>d__20.MoveNext() --- Ende der Stapelüberwachung vom vorhergehenden Ort, an dem die Ausnahme ausgelöst wurde --- bei System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw() bei CoCoL.ChannelExtensions.WaitForTaskOrThrow(Task task) bei Duplicati.Library.Main.Controller.<>c__DisplayClass14_0.<Backup>b__0(BackupResults result) bei Duplicati.Library.Main.Controller.RunAction[T](T result, String[]& paths, IFilter& filter, Action1 method)

Machine 2: It is running unter Windows 10 Home (2004) as a service, controling via GUI. I do not switch the VSS to “on”, so it is off by default?

EPH

Yes. The snapshot-policy link that I posted says " --snapshot-policy = off", meaning it’s the default.

Assuming this is the default for a Windows service, running as SYSTEM has ample privilege to use VSS, however I wonder if two systems are being confused. Original post reports “First computer” “TestHandler” error, where you need to get a better look with a log. “Second computer” (now called Machine 1?) was the blocksets error, where I wondered if VSS would help, however once it’s this way it’s probably stuck at that.

TestHandler runs after backup. Verifying backend files, or you can push the “Verify files” button for the job.
Viewing the Duplicati Server Logs describes the live log, which is easiest. Start at main screen at About, then use the additional clicks on Show log and Live. On the dropdown, start with the level called Retry. Watch this screen while running a backup, and TestHandler should run near end. Or use Verify files.
Try clicking on anything that’s near TestHandler-FailedToProcessFile to see if any more is available.

Non-empty blocksets error is probably detected in the consistency checks before the backup itself starts. Does that seem to be the case? And the backup, while not the small test, has never actually succeeded? That would leave room for a fresh start by deleting backup files on Dropbox, and using Database Delete.

If somehow you’d rather leave the backup and make another with VSS on, and maybe a slow ramp from small test backup (which I assume worked) to full size, that would also tell if things hold, or when they fail. This particular problem might also be possible with hard stops, such as “Stop now”, or reboot on backup.

asks what you selected on the job’s screen 2, called Destination, for example which of these pictures?

image

image

I started once again after deleting the old backups: I set up a new backup:
OS: Windows 10 Home (2004)
Duplicati: Runs as service with system privileges and VSS=on
Backup destination: Dropbox
Sequence:

  • First run with a folder with 1,32 GB: no error, no warnung.
  • Second run with additional folder (5,5 GB in total): same error as before:
    [Error-Duplicati.Library.Main.Operation.TestHandler-FailedToProcessFile]: Failed to process file duplicati-bd9068f20025142d38020e7f0b4caf90b.dblock.zip.aes
  • Database repair: no error.
  • Third run with the same folders: same error.
    What can I do?

EPH

Did you do previous tests? I’m not seeing the result. You need to look at details of FailedToProcessFile.

It took some time to understand, what I have to do, as English is not my native language.
I started a verify with active Live log, but haven’t found the TestHandler. I attache the hole log, perhaps it helps.
Greetings EPH

  • 13 Aug 2020 20:14: The operation Test has completed
  • 13 Aug 2020 20:14: Failed to process file duplicati-bf8b4f51f35754fb98fc8b783849a1c3e.dblock.zip.aes
  • 13 Aug 2020 20:14: Backend event: Get - Failed: duplicati-bf8b4f51f35754fb98fc8b783849a1c3e.dblock.zip.aes (49.99 MB)
  • 13 Aug 2020 20:14: Operation Get with file duplicati-bf8b4f51f35754fb98fc8b783849a1c3e.dblock.zip.aes attempt 5 of 5 failed with message: Unerwartetes Dateiende oder 0 Bytes vom Transportstream erhalten.
  • 13 Aug 2020 19:57: Backend event: Get - Started: duplicati-bf8b4f51f35754fb98fc8b783849a1c3e.dblock.zip.aes (49.99 MB)
  • 13 Aug 2020 19:57: Backend event: Get - Retrying: duplicati-bf8b4f51f35754fb98fc8b783849a1c3e.dblock.zip.aes (49.99 MB)
  • 13 Aug 2020 19:57: Operation Get with file duplicati-bf8b4f51f35754fb98fc8b783849a1c3e.dblock.zip.aes attempt 4 of 5 failed with message: Unerwartetes Dateiende oder 0 Bytes vom Transportstream erhalten.
  • 13 Aug 2020 19:40: Backend event: Get - Started: duplicati-bf8b4f51f35754fb98fc8b783849a1c3e.dblock.zip.aes (49.99 MB)
  • 13 Aug 2020 19:40: Backend event: Get - Retrying: duplicati-bf8b4f51f35754fb98fc8b783849a1c3e.dblock.zip.aes (49.99 MB)
  • 13 Aug 2020 19:40: Operation Get with file duplicati-bf8b4f51f35754fb98fc8b783849a1c3e.dblock.zip.aes attempt 3 of 5 failed with message: File length is invalid
  • 13 Aug 2020 19:26: Backend event: Get - Started: duplicati-bf8b4f51f35754fb98fc8b783849a1c3e.dblock.zip.aes (49.99 MB)
  • 13 Aug 2020 19:26: Backend event: Get - Retrying: duplicati-bf8b4f51f35754fb98fc8b783849a1c3e.dblock.zip.aes (49.99 MB)
  • 13 Aug 2020 19:26: Operation Get with file duplicati-bf8b4f51f35754fb98fc8b783849a1c3e.dblock.zip.aes attempt 2 of 5 failed with message: Unerwartetes Dateiende oder 0 Bytes vom Transportstream erhalten.
  • 13 Aug 2020 19:09: Backend event: Get - Started: duplicati-bf8b4f51f35754fb98fc8b783849a1c3e.dblock.zip.aes (49.99 MB)
  • 13 Aug 2020 19:09: Backend event: Get - Retrying: duplicati-bf8b4f51f35754fb98fc8b783849a1c3e.dblock.zip.aes (49.99 MB)
  • 13 Aug 2020 19:09: Operation Get with file duplicati-bf8b4f51f35754fb98fc8b783849a1c3e.dblock.zip.aes attempt 1 of 5 failed with message: File length is invalid
  • 13 Aug 2020 18:52: Backend event: Get - Started: duplicati-bf8b4f51f35754fb98fc8b783849a1c3e.dblock.zip.aes (49.99 MB)
  • 13 Aug 2020 18:52: Backend event: Get - Completed: duplicati-i314fabda56b04871abdbc629194796eb.dindex.zip.aes (38.62 KB)
  • 13 Aug 2020 18:52: Backend event: Get - Started: duplicati-i314fabda56b04871abdbc629194796eb.dindex.zip.aes (38.62 KB)
  • 13 Aug 2020 18:52: Backend event: Get - Completed: duplicati-20200807T045649Z.dlist.zip.aes (1.14 MB)
  • 13 Aug 2020 18:52: Backend event: Get - Started: duplicati-20200807T045649Z.dlist.zip.aes (1.14 MB)
  • 13 Aug 2020 18:52: Backend event: List - Completed: (162 bytes)
  • 13 Aug 2020 18:52: Backend event: List - Started: ()

I guess the live log doesn’t show the log tag (e.g. TestHandler) the same way as log-file or default log.

Try clicking on any error, such as “Get – Failed” or maybe “Failed to process file” to expand to details.

I expand some of the errors:

  • 13 Aug 2020 20:14: The operation Test has completed

  • 13 Aug 2020 20:14: Failed to process file duplicati-bf8b4f51f35754fb98fc8b783849a1c3e.dblock.zip.aes

{“ClassName”:“System.IO.IOException”,“Message”:“Unerwartetes Dateiende oder 0 Bytes vom Transportstream erhalten.”,“Data”:null,“InnerException”:null,“HelpURL”:null,“StackTraceString”:" bei Duplicati.Library.Main.AsyncDownloader.AsyncDownloaderEnumerator.AsyncDownloadedFile.get_TempFile()\r\n bei Duplicati.Library.Main.Operation.TestHandler.DoRun(Int64 samples, LocalTestDatabase db, BackendManager backend)",“RemoteStackTraceString”:null,“RemoteStackIndex”:0,“ExceptionMethod”:“8\nget_TempFile\nDuplicati.Library.Main, Version=2.0.5.1, Culture=neutral, PublicKeyToken=null\nDuplicati.Library.Main.AsyncDownloader+AsyncDownloaderEnumerator+AsyncDownloadedFile\nDuplicati.Library.Utility.TempFile get_TempFile()”,“HResult”:-2146232800,“Source”:“Duplicati.Library.Main”,“WatsonBuckets”:null}

  • 13 Aug 2020 20:14: Backend event: Get - Failed: duplicati-bf8b4f51f35754fb98fc8b783849a1c3e.dblock.zip.aes (49.99 MB)

  • 13 Aug 2020 20:14: Operation Get with file duplicati-bf8b4f51f35754fb98fc8b783849a1c3e.dblock.zip.aes attempt 5 of 5 failed with message: Unerwartetes Dateiende oder 0 Bytes vom Transportstream erhalten.

{“ClassName”:“System.IO.IOException”,“Message”:“Unerwartetes Dateiende oder 0 Bytes vom Transportstream erhalten.”,“Data”:null,“InnerException”:null,“HelpURL”:null,“StackTraceString”:" bei Duplicati.Library.Main.AsyncDownloader.AsyncDownloaderEnumerator.AsyncDownloadedFile.get_TempFile()\r\n bei Duplicati.Library.Main.Operation.TestHandler.DoRun(Int64 samples, LocalTestDatabase db, BackendManager backend)",“RemoteStackTraceString”:null,“RemoteStackIndex”:0,“ExceptionMethod”:“8\nget_TempFile\nDuplicati.Library.Main, Version=2.0.5.1, Culture=neutral, PublicKeyToken=null\nDuplicati.Library.Main.AsyncDownloader+AsyncDownloaderEnumerator+AsyncDownloadedFile\nDuplicati.Library.Utility.TempFile get_TempFile()”,“HResult”:-2146232800,“Source”:“Duplicati.Library.Main”,“WatsonBuckets”:null}

  • 13 Aug 2020 19:57: Backend event: Get - Started: duplicati-bf8b4f51f35754fb98fc8b783849a1c3e.dblock.zip.aes (49.99 MB)

  • 13 Aug 2020 19:57: Backend event: Get - Retrying: duplicati-bf8b4f51f35754fb98fc8b783849a1c3e.dblock.zip.aes (49.99 MB)

  • 13 Aug 2020 19:57: Operation Get with file duplicati-bf8b4f51f35754fb98fc8b783849a1c3e.dblock.zip.aes attempt 4 of 5 failed with message: Unerwartetes Dateiende oder 0 Bytes vom Transportstream erhalten.

{“ClassName”:“System.IO.IOException”,“Message”:“Unerwartetes Dateiende oder 0 Bytes vom Transportstream erhalten.”,“Data”:null,“InnerException”:null,“HelpURL”:null,“StackTraceString”:" bei System.Net.ConnectStream.Read(Byte buffer, Int32 offset, Int32 size)\r\n bei Duplicati.Library.Utility.Utility.CopyStream(Stream source, Stream target, Boolean tryRewindSource, Byte buf)\r\n bei Duplicati.Library.Backend.DropboxHelper.DownloadFile(String path, Stream fs)\r\n bei Duplicati.Library.Backend.Dropbox.Get(String remotename, Stream stream)\r\n bei Duplicati.Library.Main.BackendManager.coreDoGetPiping(FileEntryItem item, IEncryption useDecrypter, Int64& retDownloadSize, String& retHashcode)\r\n bei Duplicati.Library.Main.BackendManager.DoGet(FileEntryItem item)\r\n bei Duplicati.Library.Main.BackendManager.ThreadRun()",“RemoteStackTraceString”:null,“RemoteStackIndex”:0,“ExceptionMethod”:“8\nRead\nSystem, Version=4.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089\nSystem.Net.ConnectStream\nInt32 Read(Byte, Int32, Int32)”,“HResult”:-2146232800,“Source”:“System”,“WatsonBuckets”:null}

  • 13 Aug 2020 19:40: Backend event: Get - Started: duplicati-bf8b4f51f35754fb98fc8b783849a1c3e.dblock.zip.aes (49.99 MB)

  • 13 Aug 2020 19:40: Backend event: Get - Retrying: duplicati-bf8b4f51f35754fb98fc8b783849a1c3e.dblock.zip.aes (49.99 MB)

  • 13 Aug 2020 19:40: Operation Get with file duplicati-bf8b4f51f35754fb98fc8b783849a1c3e.dblock.zip.aes attempt 3 of 5 failed with message: File length is invalid

  • 13 Aug 2020 19:26: Backend event: Get - Started: duplicati-bf8b4f51f35754fb98fc8b783849a1c3e.dblock.zip.aes (49.99 MB)

  • 13 Aug 2020 19:26: Backend event: Get - Retrying: duplicati-bf8b4f51f35754fb98fc8b783849a1c3e.dblock.zip.aes (49.99 MB)

  • 13 Aug 2020 19:26: Operation Get with file duplicati-bf8b4f51f35754fb98fc8b783849a1c3e.dblock.zip.aes attempt 2 of 5 failed with message: Unerwartetes Dateiende oder 0 Bytes vom Transportstream erhalten.

{“ClassName”:“System.IO.IOException”,“Message”:“Unerwartetes Dateiende oder 0 Bytes vom Transportstream erhalten.”,“Data”:null,“InnerException”:null,“HelpURL”:null,“StackTraceString”:" bei System.Net.ConnectStream.Read(Byte buffer, Int32 offset, Int32 size)\r\n bei Duplicati.Library.Utility.Utility.CopyStream(Stream source, Stream target, Boolean tryRewindSource, Byte buf)\r\n bei Duplicati.Library.Backend.DropboxHelper.DownloadFile(String path, Stream fs)\r\n bei Duplicati.Library.Backend.Dropbox.Get(String remotename, Stream stream)\r\n bei Duplicati.Library.Main.BackendManager.coreDoGetPiping(FileEntryItem item, IEncryption useDecrypter, Int64& retDownloadSize, String& retHashcode)\r\n bei Duplicati.Library.Main.BackendManager.DoGet(FileEntryItem item)\r\n bei Duplicati.Library.Main.BackendManager.ThreadRun()",“RemoteStackTraceString”:null,“RemoteStackIndex”:0,“ExceptionMethod”:“8\nRead\nSystem, Version=4.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089\nSystem.Net.ConnectStream\nInt32 Read(Byte, Int32, Int32)”,“HResult”:-2146232800,“Source”:“System”,“WatsonBuckets”:null}

  • 13 Aug 2020 19:09: Backend event: Get - Started: duplicati-bf8b4f51f35754fb98fc8b783849a1c3e.dblock.zip.aes (49.99 MB)

  • 13 Aug 2020 19:09: Backend event: Get - Retrying: duplicati-bf8b4f51f35754fb98fc8b783849a1c3e.dblock.zip.aes (49.99 MB)

  • 13 Aug 2020 19:09: Operation Get with file duplicati-bf8b4f51f35754fb98fc8b783849a1c3e.dblock.zip.aes attempt 1 of 5 failed with message: File length is invalid

  • 13 Aug 2020 18:52: Backend event: Get - Started: duplicati-bf8b4f51f35754fb98fc8b783849a1c3e.dblock.zip.aes (49.99 MB)

  • 13 Aug 2020 18:52: Backend event: Get - Completed: duplicati-i314fabda56b04871abdbc629194796eb.dindex.zip.aes (38.62 KB)

  • 13 Aug 2020 18:52: Backend event: Get - Started: duplicati-i314fabda56b04871abdbc629194796eb.dindex.zip.aes (38.62 KB)

  • 13 Aug 2020 18:52: Backend event: Get - Completed: duplicati-20200807T045649Z.dlist.zip.aes (1.14 MB)

  • 13 Aug 2020 18:52: Backend event: Get - Started: duplicati-20200807T045649Z.dlist.zip.aes (1.14 MB)

  • 13 Aug 2020 18:52: Backend event: List - Completed: (162 bytes)

  • 13 Aug 2020 18:52: Backend event: List - Started: ()

per translate.google.com is

Unexpected end of file or 0 bytes received from transport stream.

Searching the Internet for variations on that make me think the official English error message is actually:

Received an unexpected EOF or 0 bytes from the transport stream.

Received an unexpected EOF or 0 bytes from the transport stream when create .zip file using ZipFile in c# points out several errors that DropBox might return, and that the error value should be checked before use.

Improved error messages for non-json errors #4195 was a Duplicati change to handle such errors better, however the error being avoided there is not the one that you’re seeing. Still, 2.0.5.106 Canary might help.

If it does not, then this probably needs to become a GitHub issue, so that developers can debug it further, unless you want to carefully use network tracing to look over what Dropbox is returning to Duplicati there.

2.0.5.106_canary_2020-05-11

Improved errors from Json source, thanks @kenkendk

Canary is always a bit risky. On average it usually gets better than Beta, but can have unexpected breaks.
Going back to Beta is, at the moment, difficult, because the database version will be upgraded by Canary.

Thank you. I will try Canary in the next days.

I have installed 2.0.5.110_canary_2020-08-10 and got no errors until now after a lot more of data than before.

Next try was with MS OneDrive. On the run I received this message (live-log-retry):
6 of 6 failed with message: Eine Aufgabe wurde abgebrochen.
{“ClassName”:“System.Threading.Tasks.TaskCanceledException”,“Message”:“Eine Aufgabe wurde abgebrochen.”,“Data”:null,“InnerException”:null,“HelpURL”:null,“StackTraceString”:" bei System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)\r\n bei System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)\r\n bei Duplicati.Library.OAuthHttpClient.d__6.MoveNext()\r\n— Ende der Stapelüberwachung vom vorhergehenden Ort, an dem die Ausnahme ausgelöst wurde —\r\n bei System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()\r\n bei System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)\r\n bei Duplicati.Library.Backend.MicrosoftGraphBackend.d__58.MoveNext()\r\n— Ende der Stapelüberwachung vom vorhergehenden Ort, an dem die Ausnahme ausgelöst wurde —\r\n bei System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()\r\n bei System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)\r\n bei System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)\r\n bei Duplicati.Library.Main.Operation.Backup.BackendUploader.d__21.MoveNext()\r\n— Ende der Stapelüberwachung vom vorhergehenden Ort, an dem die Ausnahme ausgelöst wurde —\r\n bei System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()\r\n bei System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)\r\n bei System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)\r\n bei Duplicati.Library.Main.Operation.Backup.BackendUploader.<>c__DisplayClass17_0.<b__0>d.MoveNext()\r\n— Ende der Stapelüberwachung vom vorhergehenden Ort, an dem die Ausnahme ausgelöst wurde —\r\n bei System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()\r\n bei System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)\r\n bei Duplicati.Library.Main.Operation.Backup.BackendUploader.d__18.MoveNext()",“RemoteStackTraceString”:null,“RemoteStackIndex”:0,“ExceptionMethod”:“8\nThrowForNonSuccess\nmscorlib, Version=4.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089\nSystem.Runtime.CompilerServices.TaskAwaiter\nVoid ThrowForNonSuccess(System.Threading.Tasks.Task)”,“HResult”:-2146233029,“Source”:“mscorlib”,“WatsonBuckets”:null}

Translates to A task was canceled (which doesn’t really say anything about the original issue).
Was there a better error message on an earlier try of this series, where 6 of 6 is shown here?

You might also consider doing an Export As Command-line to get the remote URL for backup.
Edit the URL for a different empty folder, and you can test you backend connection using CLI.
Sometimes the error messages are shown differently. You’re clearly having issues somehow.

Duplicati.CommandLine.BackendTester.exe (automatic)
Duplicati.CommandLine.BackendTool.exe (manual)

I tried the Backend-Tester, which produces errors with bigger files (see attached log).

log for Duplicati.CommandLine.BackendTester.exe onedrivev2__DuplicatiTest.zip (8.6 KB) log for Duplicati.CommandLine.BackendTester.exe onedrivev2__DuplicatiTest.zip (8.6 KB)

Try adding option http-operation-timeout. The default of 100 seconds (1:40) is apparently low for your upload speed. I didn’t study the logs closely, but the varying sizes used will let you guess at what you need for your likely-largest files which (unless you changed the default Remote Volume Size, a.k.a. dblock-size) are 50MB.

If I add the “–http-operation-timeout”-option to the backendtester command line I receive the message with the supported options. The backendtester does not support the timeout, I’m afraid.

Sorry, that was for the backup. The test tools are very small programs with few options.

With a http-timeout of 10 minutes it works with a small amount of data. The bigger one I will test after my holiday.