Duplicati stuck on Compact when Getting/Putting from OneDrive and results in missing files

ts678 · August 19, 2023, 6:50pm

Network tracing typically prints 1024 byte dump chunk. Here’s how the last good download finished:

System.Net.Sockets Verbose: 0 : [2740] 000003F0 : E7 32 4E 63 15 0B CA 42-3E 6B EF C8 09 78 54 A3 : .2Nc...B>k...xT.
    ProcessId=22936
    DateTime=2023-08-19T14:12:55.9381193Z
System.Net.Sockets Verbose: 0 : [2740] Entering Socket#25690090::EndReceive(OverlappedAsyncResult#43574417)
    ProcessId=22936
    DateTime=2023-08-19T14:12:55.9381193Z
System.Net.Sockets Verbose: 0 : [2740] Exiting Socket#25690090::EndReceive() 	-> Int32#4492
    ProcessId=22936
    DateTime=2023-08-19T14:12:55.9381193Z
System.Net Verbose: 0 : [2740] Entering ConnectStream#65537674::EndRead()
    ProcessId=22936
    DateTime=2023-08-19T14:12:55.9381193Z
System.Net Verbose: 0 : [2740] Exiting ConnectStream#65537674::EndRead() 	-> Int32#4096
    ProcessId=22936
    DateTime=2023-08-19T14:12:55.9381193Z
System.Net Verbose: 0 : [2740] Entering ConnectStream#65537674::BeginRead()
    ProcessId=22936
    DateTime=2023-08-19T14:12:55.9381193Z
System.Net Verbose: 0 : [2740] Exiting ConnectStream#65537674::BeginRead() 	-> BufferAsyncResult#60284321
    ProcessId=22936
    DateTime=2023-08-19T14:12:55.9381193Z
System.Net Verbose: 0 : [2740] Entering ConnectStream#65537674::EndRead()
    ProcessId=22936
    DateTime=2023-08-19T14:12:55.9381193Z
System.Net Verbose: 0 : [2740] Exiting ConnectStream#65537674::EndRead() 	-> Int32#372
    ProcessId=22936
    DateTime=2023-08-19T14:12:55.9381193Z
System.Net Verbose: 0 : [2740] Entering ConnectStream#65537674::BeginRead()
    ProcessId=22936
    DateTime=2023-08-19T14:12:55.9390955Z
System.Net Verbose: 0 : [2740] Exiting ConnectStream#65537674::BeginRead() 	-> NestedSingleAsyncResult#26166769
    ProcessId=22936
    DateTime=2023-08-19T14:12:55.9390955Z
System.Net Verbose: 0 : [2740] Entering ConnectStream#65537674::EndRead()
    ProcessId=22936
    DateTime=2023-08-19T14:12:55.9390955Z
System.Net Verbose: 0 : [2740] Exiting ConnectStream#65537674::EndRead() 	-> Int32#0
    ProcessId=22936
    DateTime=2023-08-19T14:12:55.9390955Z
System.Net Verbose: 0 : [2740] Entering ConnectStream#65537674::Close()
    ProcessId=22936
    DateTime=2023-08-19T14:12:55.9390955Z
System.Net Verbose: 0 : [2740] Exiting ConnectStream#65537674::Close() 
    ProcessId=22936
    DateTime=2023-08-19T14:12:55.9390955Z
System.Net.Http Warning: 0 : [2740] Value for header 'ETag' has invalid format. Value: 'aN0RGRUU0NjkwRDlGNDcxMSEzODM5Ni4x'.
    ProcessId=22936
    DateTime=2023-08-19T14:12:55.9390955Z
System.Net.Http Information: 0 : [2740] OAuthHttpClient#54778057 - Request for HttpRequestMessage#31002743 completed successfully. Returning response HttpResponseMessage#12551126: StatusCode: 200, ReasonPhrase: 'OK', Version: 1.1, Content: System.Net.Http.StreamContent, Headers:

The ‘ETag’ warning is extremely common. The hung one below lacks it, but adds a rarer Closed as idle:

System.Net.Sockets Verbose: 0 : [2740] 000003F0 : 15 1D BF F9 24 95 DE E0-7E B7 E6 15 36 62 C8 91 : ....$...~...6b..
    ProcessId=22936
    DateTime=2023-08-19T14:13:07.4038668Z
System.Net.Sockets Verbose: 0 : [2740] Entering Socket#25690090::EndReceive(OverlappedAsyncResult#34016546)
    ProcessId=22936
    DateTime=2023-08-19T14:13:07.4038668Z
System.Net.Sockets Verbose: 0 : [2740] Exiting Socket#25690090::EndReceive() 	-> Int32#16408
    ProcessId=22936
    DateTime=2023-08-19T14:13:07.4038668Z
System.Net Verbose: 0 : [2740] Entering ConnectStream#65575460::EndRead()
    ProcessId=22936
    DateTime=2023-08-19T14:13:07.4038668Z
System.Net Verbose: 0 : [2740] Exiting ConnectStream#65575460::EndRead() 	-> Int32#4096
    ProcessId=22936
    DateTime=2023-08-19T14:13:07.4038668Z
System.Net Verbose: 0 : [2740] Entering ConnectStream#65575460::BeginRead()
    ProcessId=22936
    DateTime=2023-08-19T14:13:07.4038668Z
System.Net Verbose: 0 : [2740] Exiting ConnectStream#65575460::BeginRead() 	-> BufferAsyncResult#13582308
    ProcessId=22936
    DateTime=2023-08-19T14:13:07.4038668Z
System.Net Verbose: 0 : [2740] Entering ConnectStream#65575460::EndRead()
    ProcessId=22936
    DateTime=2023-08-19T14:13:07.4038668Z
System.Net Verbose: 0 : [2740] Exiting ConnectStream#65575460::EndRead() 	-> Int32#4096
    ProcessId=22936
    DateTime=2023-08-19T14:13:07.4038668Z
System.Net Verbose: 0 : [2740] Entering ConnectStream#65575460::BeginRead()
    ProcessId=22936
    DateTime=2023-08-19T14:13:07.4038668Z
System.Net Verbose: 0 : [2740] Exiting ConnectStream#65575460::BeginRead() 	-> BufferAsyncResult#10434822
    ProcessId=22936
    DateTime=2023-08-19T14:13:07.4038668Z
System.Net Verbose: 0 : [2740] Entering ConnectStream#65575460::EndRead()
    ProcessId=22936
    DateTime=2023-08-19T14:13:07.4038668Z
System.Net Verbose: 0 : [2740] Exiting ConnectStream#65575460::EndRead() 	-> Int32#4096
    ProcessId=22936
    DateTime=2023-08-19T14:13:07.4038668Z
System.Net Verbose: 0 : [2740] Entering ConnectStream#65575460::BeginRead()
    ProcessId=22936
    DateTime=2023-08-19T14:13:07.4038668Z
System.Net Verbose: 0 : [2740] Exiting ConnectStream#65575460::BeginRead() 	-> BufferAsyncResult#7174825
    ProcessId=22936
    DateTime=2023-08-19T14:13:07.4048431Z
System.Net Verbose: 0 : [2740] Entering ConnectStream#65575460::EndRead()
    ProcessId=22936
    DateTime=2023-08-19T14:13:07.4048431Z
System.Net Verbose: 0 : [2740] Exiting ConnectStream#65575460::EndRead() 	-> Int32#4096
    ProcessId=22936
    DateTime=2023-08-19T14:13:07.4048431Z
System.Net Verbose: 0 : [2740] Entering ConnectStream#65575460::BeginRead()
    ProcessId=22936
    DateTime=2023-08-19T14:13:07.4048431Z
System.Net.Sockets Verbose: 0 : [2740] Entering Socket#25690090::BeginReceive()
    ProcessId=22936
    DateTime=2023-08-19T14:13:07.4048431Z
System.Net.Sockets Verbose: 0 : [2740] Exiting Socket#25690090::BeginReceive() 	-> OverlappedAsyncResult#63710477
    ProcessId=22936
    DateTime=2023-08-19T14:13:07.4048431Z
System.Net Verbose: 0 : [2740] Exiting ConnectStream#65575460::BeginRead() 	-> BufferAsyncResult#47540338
    ProcessId=22936
    DateTime=2023-08-19T14:13:07.4048431Z
System.Net Information: 0 : [19000] ServicePoint#4032828 - Closed as idle.
    ProcessId=22936
    DateTime=2023-08-19T14:14:36.3845683Z
System.Net.Sockets Verbose: 0 : [19000] Entering Socket#37489757::Dispose()
    ProcessId=22936
    DateTime=2023-08-19T14:14:36.3845683Z
System.Net Information: 0 : [19000] ServicePoint#4032828 - ConnectionGroup#28379535 - Closed as idle.
    ProcessId=22936
    DateTime=2023-08-19T14:14:36.3845683Z
System.Net Information: 0 : [19000] ServicePoint#4032828::ReleaseConnectionGroup(35912612S>I>)
    ProcessId=22936
    DateTime=2023-08-19T14:14:36.3845683Z
System.Net Information: 0 : [19000] ServicePoint#4032828::ReleaseConnectionGroup, returning(false)
    ProcessId=22936
    DateTime=2023-08-19T14:14:36.3845683Z

I can test this more on 2.0.6.3 (got one OK run). I just need to edit the database Version down to 11.
I can also test intermediate Canary versions. Beyond that (and short of debug code), low on ideas…