Clean-up failing with "size was expected"

jshank · May 1, 2025, 6:03pm

I’m backing up from a Linux host (Docker image linuxserver/duplicati: (2.1.0.5_stable_2025-03-04) to a Win10 host via SMB mount. During the clean-up phase, Duplicati makes 5 attempts to download the dblock file and then crashes completely and restarts. Logs are lost and the signal to healthchecks.io is never sent. The only way I catch this is through profiling. I’m in the process of manually “identifying” each file and deleting it from the host, then running a purge-broken-files but this feels like a bug.

Live Profiling Logs

Operation Get with file duplicati-b73a3bf40330f4ce0bc32c2493f45b22c.dblock.zip attempt 3 of 5 failed with message: The file duplicati-b73a3bf40330f4ce0bc32c2493f45b22c.dblock.zip was downloaded and had size 52559872 but the size was expected to be 52524595
...
System.Exception: The file duplicati-b73a3bf40330f4ce0bc32c2493f45b22c.dblock.zip was downloaded and had size 52559872 but the size was expected to be 52524595 at Duplicati.Library.Main.BackendManager.DoGetAsync(FileEntryItem item, CancellationToken cancellationToken) at Duplicati.Library.Utility.Utility.Await(Task task) at Duplicati.Library.Main.BackendManager.ThreadRun()

Docker Logs

fail: Microsoft.AspNetCore.Server.Kestrel[13]
      Connection id "0HNC8R3OG5RO4", Request id "0HNC8R3OG5RO4:00000001": An unhandled exception was thrown by the application.
      System.NullReferenceException: Object reference not set to an instance of an object.
         at Duplicati.Server.Scheduler.get_WorkerQueue()
         at Duplicati.Server.Scheduler.GetSchedulerQueueIds()
         at WebserverCore.Services.SchedulerService.GetSchedulerQueueIds()
         at Duplicati.WebserverCore.Services.StatusService.GetStatus()
         at Duplicati.WebserverCore.Notifications.WebsocketAccessor.SendInitialStatus(WebSocket connection)
         at Duplicati.WebserverCore.Notifications.WebsocketAccessor.AddConnection(WebSocket newConnection)
         at Duplicati.WebserverCore.Middlewares.WebsocketExtensions.<>c__DisplayClass0_0.<<UseNotifications>b__0>d.MoveNext()
      --- End of stack trace from previous location ---
         at Microsoft.AspNetCore.Diagnostics.ExceptionHandlerMiddlewareImpl.<Invoke>g__Awaited|10_0(ExceptionHandlerMiddlewareImpl middleware, HttpContext context, Task task)
         at Microsoft.AspNetCore.Diagnostics.ExceptionHandlerMiddlewareImpl.HandleException(HttpContext context, ExceptionDispatchInfo edi)
         at Microsoft.AspNetCore.Diagnostics.ExceptionHandlerMiddlewareImpl.<Invoke>g__Awaited|10_0(ExceptionHandlerMiddlewareImpl middleware, HttpContext context, Task task)
         at Duplicati.WebserverCore.Middlewares.StaticFilesExtensions.<>c__DisplayClass5_0.<<UseDefaultStaticFiles>b__1>d.MoveNext()
      --- End of stack trace from previous location ---
         at Microsoft.AspNetCore.Authorization.AuthorizationMiddleware.Invoke(HttpContext context)
         at Microsoft.AspNetCore.Authentication.AuthenticationMiddleware.Invoke(HttpContext context)
         at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.HttpProtocol.ProcessRequests[TContext](IHttpApplication`1 application)
Unhandled exception. System.NullReferenceException: Object reference not set to an instance of an object.
   at Duplicati.Server.Scheduler.get_WorkerQueue()
   at Duplicati.Server.Scheduler.GetSchedulerQueueIds()
   at WebserverCore.Services.SchedulerService.GetSchedulerQueueIds()
   at Duplicati.WebserverCore.Services.StatusService.GetStatus()
   at Duplicati.WebserverCore.Notifications.WebsocketAccessor.<.ctor>b__4_0(Object _, EventArgs _)
   at System.Threading.Tasks.Task.<>c.<ThrowAsync>b__128_1(Object state)
   at System.Threading.QueueUserWorkItemCallback.Execute()
   at System.Threading.ThreadPoolWorkQueue.Dispatch()
   at System.Threading.PortableThreadPool.WorkerThread.WorkerThreadStart()
Connection to localhost (::1) 8200 port [tcp/*] succeeded!
Server has started and is listening on port 8200

ts678 · May 2, 2025, 9:34pm

Welcome to the forum @jshank

What’s interesting about the size is that in hexadecimal a 3217633 became 3220000.
Generally when wrong sizes are so even, I wonder if a filesystem or SMB has done it.

It would be interesting to see what the extra data is, for example if it’s NUL characters.
Linux has better built-in alternatives to a hex editor, e.g. dd or hexdump could show…

What does a .zip tool think about these files? Does trimming it to correct size help it?

The other interesting thing about the length error is Duplicati checks it numerous times.
What length shows using other tools? Might it list one length but give another to reads?

Checking from both Linux and Windows might also find something, as may timestamps. Possibly you’ll also see some pattern, e.g. is there a Windows restart anywhere nearby?

I don’t know if this is related to your unhandled exception, but the stack looks kind of like:

Duplicati crashing when starting backups
which seemed at first to be only on Linux backing up to Storj, but later reports vary more.

The developers are trying (although mostly on Storj), but I don’t think this one got solved,

or maybe I’m totally off here. Regardless, dev help would be helpful for both these issues.

The SMB unreliability problem is longstanding. The last attempt to handle it was with this:

  --disable-length-verification (Boolean): Disable length verification
    As an extra precaution the uploaded file length will be checked against the local source length.
    * default value: false

That’s supposed to check the length right after upload by default. So how’d it go wrong?
There are also length checks before and after backup, but actual downloads are heavy enough that one can’t download every file every time. One can certainly test as needed.

The TEST command

jshank · May 2, 2025, 10:52pm

Picking one today for example:

Operation Get with file duplicati-baf66a52f9fa44def8f85c60a1dc0fff6.dblock.zip attempt 1 of 5 failed with message: The file duplicati-baf66a52f9fa44def8f85c60a1dc0fff6.dblock.zip was downloaded and had size 42532864 but the size was expected to be 42498557

Everything except duplicati show this to be 42498557. So so weird.

Linux Docker Host

ls -al /mnt/zeussmb/hass-config/duplicati-baf66a52f9fa44def8f85c60a1dc0fff6.dblock.zip
-rwxr-xr-x 1 root root 42498557 Jun 19  2024 /mnt/zeussmb/hass-config/duplicati-baf66a52f9fa44def8f85c60a1dc0fff6.dblock.zip*

Duplicati Docker Container

root@8d724147d3b0:/# ls -al /source/mnt/zeussmb/hass-config/duplicati-baf66a52f9fa44def8f85c60a1dc0fff6.dblock.zip
-rwxr-xr-x 1 root root 42498557 Jun 19  2024 /source/mnt/zeussmb/hass-config/duplicati-baf66a52f9fa44def8f85c60a1dc0fff6.dblock.zip

Windows
Size: 40.5 MB (42,498,557 bytes)
Size on disk: 40.5 MB (42,500,096 bytes)

7-zip
Size: 46 580 080
Packed Size: 42 344 119
Folders: 0
Files: 942
CRC: 507CE5EB
------------------------:
Path: E:\Backups\hass-config\duplicati-baf66a52f9fa44def8f85c60a1dc0fff6.dblock.zip
Type: zip
Physical Size: 42 498 557

ts678 · May 2, 2025, 11:27pm

Maybe Duplicati shows it as that too, in its directory listing, but download gives more.
You can see what Duplicati found in its directory listing in job → Show log → Remote.
Find some list, click on it, look for the file of interest, and its size will be right there.

Same oddly even binary size holds. In hex, 28879FD got increased to even 2890000.
Previous question remains somewhat – what’s the extra data found at end of the file?

I don’t use Docker, Docker tends to have fewer debug tools. Do you only use Docker?

Although I’d prefer watching at a low level, a high-level way to work within Docker uses
BackendTool to get a file of interest. I think you can just use a path for the target URL.
There will probably still be too little low-level info, but you can see if simple test fails too.

If so, maybe you can run the test from something like a .zip install of Duplicati on host, where low-level tools are more available but still hard because that’s how such tools are.

IIRC there are some different ways to do SMB from within Docker. Can you test another?
You could also try a cp of the file inside docker exec to see what it gives when it’s read, getting back to the idea of a possible difference between directory listing size and reading.

Yes it would be weird, but that’s the situation. You probably have Duplicati thinking it uses local folder, while actually it’s SMB, with Docker thrown in to complicate the path further…

kenkendk · May 9, 2025, 12:51pm

Duplicati makes two checks:

When listing the directory
When reading the file

Since the error only happens when reading the file, what happens if you copy the file manually? What size does it have after being copied?

And I agree it looks super weird. As @ts678 suggests, it would be interesting to figure out what is in the extra data. It could be metadata, but given that the file listing shows it at the correct size, this indicates something even more strange.