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.