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

ts678 · August 16, 2023, 3:19pm

I think I got one partway through the 50 MB to 250 MB compact. Prior upload was about an hour prior.
Looked with Process Explorer which gathers lots of stats, didn’t see anything going on. This can show threads, but the info isn’t the C# view. Attached dnSpy for that. Not all threads had info. The below did.
This is the C# view and the (more obscure to me) Windows native view for the three threads with data:

0x000076D8 "Main thread"
>	mscorlib.dll!System.Threading.WaitHandle.InternalWaitOne(System.Runtime.InteropServices.SafeHandle waitableSafeHandle, long millisecondsTimeout, bool hasThreadAffinity, bool exitContext) (IL≈0x0014, Native=0x00007FFCCDEEBE50+0x1C)
 	mscorlib.dll!System.Threading.WaitHandle.WaitOne(int millisecondsTimeout, bool exitContext) (IL≈0x0000, Native=0x00007FFCCDEEBE10+0x2F)
 	Duplicati.Library.Main.dll!Duplicati.Library.Main.BackendManager.FileEntryItem.Duplicati.Library.Main.BackendManager.IDownloadWaitHandle.Wait(out string hash, out long size) (IL=0x0006, Native=0x00007FFC71C599E0+0x1B)
 	Duplicati.Library.Main.dll!Duplicati.Library.Main.AsyncDownloader.AsyncDownloaderEnumerator.MoveNext() (IL≈0x0093, Native=0x00007FFC71C59350+0x188)
 	Duplicati.Library.Main.dll!Duplicati.Library.Main.Operation.CompactHandler.DoCompact(Duplicati.Library.Main.Database.LocalDeleteDatabase db, bool hasVerifiedBackend, ref System.Data.IDbTransaction transaction, Duplicati.Library.Main.BackendManager sharedBackend) (IL≈0x0482, Native=0x00007FFC71C21BC0+0xE3B)
 	Duplicati.Library.Main.dll!Duplicati.Library.Main.Operation.CompactHandler.Run() (IL≈0x0070, Native=0x00007FFC71BFE620+0x182)
 	Duplicati.Library.Main.dll!Duplicati.Library.Main.Controller.RunAction<System.__Canon>(System.__Canon result, ref string[] paths, ref Duplicati.Library.Utility.IFilter filter, System.Action<System.__Canon> method) (IL≈0x011C, Native=0x00007FFC70844E70+0x448)
 	Duplicati.Library.Main.dll!Duplicati.Library.Main.Controller.Compact() (IL=epilog, Native=0x00007FFC70843920+0xBC)
 	Duplicati.CommandLine.exe!Duplicati.CommandLine.Commands.Compact(System.IO.TextWriter outwriter, System.Action<Duplicati.Library.Main.Controller> setup, System.Collections.Generic.List<string> args, System.Collections.Generic.Dictionary<string, string> options, Duplicati.Library.Utility.IFilter filter) (IL≈0x0029, Native=0x00007FFC70842870+0xD6)
 	Duplicati.CommandLine.exe!Duplicati.CommandLine.Program.ParseCommandLine(System.IO.TextWriter outwriter, System.Action<Duplicati.Library.Main.Controller> setup, ref bool verboseErrors, string[] args) (IL≈0x031F, Native=0x00007FFC7083E4F0+0x79E)
 	Duplicati.CommandLine.exe!Duplicati.CommandLine.Program.RunCommandLine(System.IO.TextWriter outwriter, System.IO.TextWriter errwriter, System.Action<Duplicati.Library.Main.Controller> setup, string[] args) (IL≈0x0002, Native=0x00007FFC70839640+0x2D)
 	Duplicati.CommandLine.exe!Duplicati.CommandLine.Program.RealMain(string[] args) (IL=???, Native=0x00007FFC708266F0+0xB2)
 	[Native to Managed Transition]
 	mscorlib.dll!System.Reflection.RuntimeMethodInfo.UnsafeInvokeInternal(object obj, object[] parameters, object[] arguments) (IL≈0x0016, Native=0x00007FFCCDEBF9A0+0x84)
 	mscorlib.dll!System.Reflection.RuntimeMethodInfo.Invoke(object obj, System.Reflection.BindingFlags invokeAttr, System.Reflection.Binder binder, object[] parameters, System.Globalization.CultureInfo culture) (IL=epilog, Native=0x00007FFCCDED7300+0x92)
 	Duplicati.Library.AutoUpdater.exe!Duplicati.Library.AutoUpdater.UpdaterManager.RunMethod(System.Reflection.MethodInfo method, string[] args) (IL≈0x0000, Native=0x00007FFC70825F20+0x5C)
 	Duplicati.Library.AutoUpdater.exe!Duplicati.Library.AutoUpdater.UpdaterManager.<>c__DisplayClass58_0.<RunFromMostRecentSpawn>b__0() (IL≈0x0000, Native=0x00007FFC70825E30+0x15)
 	Duplicati.Library.AutoUpdater.exe!Duplicati.Library.AutoUpdater.UpdaterManager.WrapWithUpdater(Duplicati.Library.AutoUpdater.AutoUpdateStrategy defaultstrategy, System.Action wrappedFunction) (IL=0x015E, Native=0x00007FFC70825AA0+0x266)
 	Duplicati.Library.AutoUpdater.exe!Duplicati.Library.AutoUpdater.UpdaterManager.RunFromMostRecentSpawn(System.Reflection.MethodInfo method, string[] cmdargs, Duplicati.Library.AutoUpdater.AutoUpdateStrategy defaultstrategy) (IL=0x004D, Native=0x00007FFC708254A0+0xA4)
 	Duplicati.CommandLine.exe!Duplicati.CommandLine.Program.Main(string[] args) (IL=epilog, Native=0x00007FFC70800890+0x47)

win32u.dll!NtUserMsgWaitForMultipleObjectsEx+0x14
USER32.dll!MsgWaitForMultipleObjectsEx+0x9e
combase.dll!CoMarshalInterface+0x9b09
combase.dll!Ordinal87+0x13d5
combase.dll!CoWaitForMultipleHandles+0x76
clr.dll!CorExeMain+0x184f1
clr.dll!CorExeMain+0x18546
clr.dll!ClrCreateManagedInstance+0xeecd
clr.dll!ClrCreateManagedInstance+0xac61
[Managed to Unmanaged Transition]
C:\Windows\Microsoft.Net\assembly\GAC_64\mscorlib\v4.0_4.0.0.0__b77a5c561934e089\mscorlib.dll!System.Threading.WaitHandle.InternalWaitOne+0x1c
C:\Windows\Microsoft.Net\assembly\GAC_64\mscorlib\v4.0_4.0.0.0__b77a5c561934e089\mscorlib.dll!System.Threading.WaitHandle.WaitOne+0x2f
C:\Program Files\Duplicati 2\Duplicati.Library.Main.dll!FileEntryItem.Duplicati.Library.Main.BackendManager.IDownloadWaitHandle.Wait+0x1b
C:\Program Files\Duplicati 2\Duplicati.Library.Main.dll!AsyncDownloaderEnumerator.MoveNext+0x188
C:\Program Files\Duplicati 2\Duplicati.Library.Main.dll!Duplicati.Library.Main.Operation.CompactHandler.DoCompact+0xe3b
C:\Program Files\Duplicati 2\Duplicati.Library.Main.dll!Duplicati.Library.Main.Operation.CompactHandler.Run+0x182
C:\Program Files\Duplicati 2\Duplicati.Library.Main.dll!Duplicati.Library.Main.Controller.RunAction+0x448
C:\Program Files\Duplicati 2\Duplicati.Library.Main.dll!Duplicati.Library.Main.Controller.Compact+0xbc
C:\Program Files\Duplicati 2\Duplicati.CommandLine.exe!Duplicati.CommandLine.Commands.Compact+0xd6
C:\Program Files\Duplicati 2\Duplicati.CommandLine.exe!Duplicati.CommandLine.Program.ParseCommandLine+0x79e
C:\Program Files\Duplicati 2\Duplicati.CommandLine.exe!Duplicati.CommandLine.Program.RunCommandLine+0x2d
C:\Program Files\Duplicati 2\Duplicati.CommandLine.exe!Duplicati.CommandLine.Program.RealMain+0xb2
[Unmanaged to Managed Transition]
clr.dll!DllCanUnloadNowInternal+0x10f3
clr.dll!DllCanUnloadNowInternal+0x1000
clr.dll!DllUnregisterServerInternal+0x3958a
clr.dll!DllUnregisterServerInternal+0x39a45
[Managed to Unmanaged Transition]
C:\Windows\Microsoft.Net\assembly\GAC_64\mscorlib\v4.0_4.0.0.0__b77a5c561934e089\mscorlib.dll!System.Reflection.RuntimeMethodInfo.UnsafeInvokeInternal+0x84
C:\Windows\Microsoft.Net\assembly\GAC_64\mscorlib\v4.0_4.0.0.0__b77a5c561934e089\mscorlib.dll!System.Reflection.RuntimeMethodInfo.Invoke+0x92
C:\Program Files\Duplicati 2\Duplicati.Library.AutoUpdater.exe!Duplicati.Library.AutoUpdater.UpdaterManager.RunMethod+0x5c
C:\Program Files\Duplicati 2\Duplicati.Library.AutoUpdater.exe!<>c__DisplayClass58_0.<RunFromMostRecentSpawn>b__0+0x15
C:\Program Files\Duplicati 2\Duplicati.Library.AutoUpdater.exe!Duplicati.Library.AutoUpdater.UpdaterManager.WrapWithUpdater+0x266
C:\Program Files\Duplicati 2\Duplicati.Library.AutoUpdater.exe!Duplicati.Library.AutoUpdater.UpdaterManager.RunFromMostRecentSpawn+0xa4
C:\Program Files\Duplicati 2\Duplicati.CommandLine.exe!Duplicati.CommandLine.Program.Main+0x47
[Unmanaged to Managed Transition]
clr.dll!DllCanUnloadNowInternal+0x10f3
clr.dll!DllCanUnloadNowInternal+0x1000
clr.dll!DllCanUnloadNowInternal+0x18b0
clr.dll!SetRuntimeInfo+0x8fb
clr.dll!SetRuntimeInfo+0x119f
clr.dll!SetRuntimeInfo+0x1052
clr.dll!SetRuntimeInfo+0x998
clr.dll!SetRuntimeInfo+0x6f1
clr.dll!CorExeMain+0x14
mscoreei.dll!CorExeMain+0x71
MSCOREE.DLL!CorExeMain+0x72
KERNEL32.dll!BaseThreadInitThunk+0x14
ntdll.dll!RtlUserThreadStart+0x21


0x00000ED8 "Worker Thread" "Backend Async Worker"
>	mscorlib.dll!System.Threading.ManualResetEventSlim.Wait(int millisecondsTimeout, System.Threading.CancellationToken cancellationToken) (IL=???, Native=0x00007FFCCDF22BA0+0x364)
 	mscorlib.dll!System.Threading.Tasks.Task.SpinThenBlockingWait(int millisecondsTimeout, System.Threading.CancellationToken cancellationToken) (IL≈0x002D, Native=0x00007FFCCDF1D5A0+0xBB)
 	mscorlib.dll!System.Threading.Tasks.Task.InternalWait(int millisecondsTimeout, System.Threading.CancellationToken cancellationToken) (IL≈0x007F, Native=0x00007FFCCE88FA40+0x1B1)
 	mscorlib.dll!System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(System.Threading.Tasks.Task task) (IL≈0x0008, Native=0x00007FFCCDF1BC10+0x5A)
 	Duplicati.Library.Backend.OneDrive.dll!Duplicati.Library.Backend.MicrosoftGraphBackend.Get(string remotename, System.IO.Stream stream) (IL=???, Native=0x00007FFC71C5BA60+0xCD)
 	Duplicati.Library.Main.dll!Duplicati.Library.Main.BackendManager.coreDoGetPiping(Duplicati.Library.Main.BackendManager.FileEntryItem item, Duplicati.Library.Interface.IEncryption useDecrypter, out long retDownloadSize, out string retHashcode) (IL≈0x0193, Native=0x00007FFC71C5A890+0x4B0)
 	Duplicati.Library.Main.dll!Duplicati.Library.Main.BackendManager.DoGet(Duplicati.Library.Main.BackendManager.FileEntryItem item) (IL≈0x01B5, Native=0x00007FFC71C59E70+0x4C8)
 	Duplicati.Library.Main.dll!Duplicati.Library.Main.BackendManager.ThreadRun() (IL≈0x00FF, Native=0x00007FFC71C2C150+0x28D)
 	mscorlib.dll!System.Threading.ExecutionContext.RunInternal(System.Threading.ExecutionContext executionContext, System.Threading.ContextCallback callback, object state, bool preserveSyncCtx) (IL≈0x0079, Native=0x00007FFCCDEAFF40+0x172)
 	mscorlib.dll!System.Threading.ExecutionContext.Run(System.Threading.ExecutionContext executionContext, System.Threading.ContextCallback callback, object state, bool preserveSyncCtx) (IL=epilog, Native=0x00007FFCCDEAFF20+0x15)
 	mscorlib.dll!System.Threading.ExecutionContext.Run(System.Threading.ExecutionContext executionContext, System.Threading.ContextCallback callback, object state) (IL=epilog, Native=0x00007FFCCDEAFEB0+0x55)
 	mscorlib.dll!System.Threading.ThreadHelper.ThreadStart() (IL=epilog, Native=0x00007FFCCDF55FD0+0x55)
 	[Native to Managed Transition]

ntdll.dll!NtWaitForMultipleObjects+0x14
KERNELBASE.dll!WaitForMultipleObjectsEx+0xf0
clr.dll!ClrCreateManagedInstance+0xf2b7
clr.dll!ClrCreateManagedInstance+0xf140
clr.dll!ClrCreateManagedInstance+0xeecd
clr.dll!ClrCreateManagedInstance+0x30731
clr.dll!MetaDataGetDispenser+0xd1e4
clr.dll!MetaDataGetDispenser+0xd1ae
clr.dll!MetaDataGetDispenser+0xcef1
[Managed to Unmanaged Transition]
C:\Windows\Microsoft.Net\assembly\GAC_64\mscorlib\v4.0_4.0.0.0__b77a5c561934e089\mscorlib.dll!System.Threading.ManualResetEventSlim.Wait+0x364
C:\Windows\Microsoft.Net\assembly\GAC_64\mscorlib\v4.0_4.0.0.0__b77a5c561934e089\mscorlib.dll!System.Threading.Tasks.Task.SpinThenBlockingWait+0xbb
C:\Windows\Microsoft.Net\assembly\GAC_64\mscorlib\v4.0_4.0.0.0__b77a5c561934e089\mscorlib.dll!System.Threading.Tasks.Task.InternalWait+0x1b1
C:\Windows\Microsoft.Net\assembly\GAC_64\mscorlib\v4.0_4.0.0.0__b77a5c561934e089\mscorlib.dll!System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification+0x5a
C:\Program Files\Duplicati 2\Duplicati.Library.Backend.OneDrive.dll!Duplicati.Library.Backend.MicrosoftGraphBackend.Get+0xcd
C:\Program Files\Duplicati 2\Duplicati.Library.Main.dll!Duplicati.Library.Main.BackendManager.coreDoGetPiping+0x4b0
C:\Program Files\Duplicati 2\Duplicati.Library.Main.dll!Duplicati.Library.Main.BackendManager.DoGet+0x4c8
C:\Program Files\Duplicati 2\Duplicati.Library.Main.dll!Duplicati.Library.Main.BackendManager.ThreadRun+0x28d
C:\Windows\Microsoft.Net\assembly\GAC_64\mscorlib\v4.0_4.0.0.0__b77a5c561934e089\mscorlib.dll!System.Threading.ExecutionContext.RunInternal+0x172
C:\Windows\Microsoft.Net\assembly\GAC_64\mscorlib\v4.0_4.0.0.0__b77a5c561934e089\mscorlib.dll!System.Threading.ExecutionContext.Run+0x15
C:\Windows\Microsoft.Net\assembly\GAC_64\mscorlib\v4.0_4.0.0.0__b77a5c561934e089\mscorlib.dll!System.Threading.ExecutionContext.Run+0x55
C:\Windows\Microsoft.Net\assembly\GAC_64\mscorlib\v4.0_4.0.0.0__b77a5c561934e089\mscorlib.dll!System.Threading.ThreadHelper.ThreadStart+0x55
[Unmanaged to Managed Transition]
clr.dll!DllCanUnloadNowInternal+0x10f3
clr.dll!DllCanUnloadNowInternal+0x1000
clr.dll!DllCanUnloadNowInternal+0x18b0
clr.dll!MetaDataGetDispenser+0xcdaf
clr.dll!DllCanUnloadNowInternal+0x2498
clr.dll!DllCanUnloadNowInternal+0x2403
clr.dll!DllCanUnloadNowInternal+0x2342
clr.dll!DllCanUnloadNowInternal+0x2533
clr.dll!MetaDataGetDispenser+0xcc99
clr.dll!DllCanUnloadNowInternal+0x6015
KERNEL32.dll!BaseThreadInitThunk+0x14
ntdll.dll!RtlUserThreadStart+0x21


0x000044C0 "Thread Pool"
>	mscorlib.dll!System.Threading.ManualResetEventSlim.Wait(int millisecondsTimeout, System.Threading.CancellationToken cancellationToken) (IL=???, Native=0x00007FFCCDF22BA0+0x364)
 	Duplicati.Library.Utility.dll!Duplicati.Library.Utility.DirectStreamLink.read(byte[] buffer, int offset, int count) (IL≈0x00B5, Native=0x00007FFC71C5BF90+0x199)
 	mscorlib.dll!System.Security.Cryptography.HashAlgorithm.ComputeHash(System.IO.Stream inputStream) (IL≈0x001A, Native=0x00007FFCCDF0C610+0x46)
 	Duplicati.Library.Main.dll!Duplicati.Library.Main.BackendManager.CalculateFileHash(System.IO.Stream stream) (IL≈0x000B, Native=0x00007FFC71C5B970+0x3C)
 	Duplicati.Library.Main.dll!Duplicati.Library.Main.BackendManager.<>c__DisplayClass33_0.<coreDoGetPiping>b__1() (IL≈0x000C, Native=0x00007FFC71C5B8D0+0x29)
 	mscorlib.dll!System.Threading.Tasks.Task<string>.InnerInvoke() (IL≈0x000F, Native=0x00007FFCCDF1DFA0+0x4E)
 	mscorlib.dll!System.Threading.Tasks.Task.Execute() (IL≈0x0010, Native=0x00007FFCCDF1D080+0x47)
 	mscorlib.dll!System.Threading.ExecutionContext.RunInternal(System.Threading.ExecutionContext executionContext, System.Threading.ContextCallback callback, object state, bool preserveSyncCtx) (IL≈0x0079, Native=0x00007FFCCDEAFF40+0x172)
 	mscorlib.dll!System.Threading.ExecutionContext.Run(System.Threading.ExecutionContext executionContext, System.Threading.ContextCallback callback, object state, bool preserveSyncCtx) (IL=epilog, Native=0x00007FFCCDEAFF20+0x15)
 	mscorlib.dll!System.Threading.Tasks.Task.ExecuteWithThreadLocal(ref System.Threading.Tasks.Task currentTaskSlot) (IL=0x00E1, Native=0x00007FFCCDF1D150+0x231)
 	mscorlib.dll!System.Threading.Tasks.Task.ExecuteEntry(bool bPreventDoubleExecution) (IL=0x0096, Native=0x00007FFCCDF1C9C0+0xA1)
 	mscorlib.dll!System.Threading.ThreadPoolWorkQueue.Dispatch() (IL=0x00A4, Native=0x00007FFCCDE7ACF0+0x156)
 	[Native to Managed Transition]

ntdll.dll!NtWaitForMultipleObjects+0x14
KERNELBASE.dll!WaitForMultipleObjectsEx+0xf0
clr.dll!ClrCreateManagedInstance+0xf2b7
clr.dll!ClrCreateManagedInstance+0xf140
clr.dll!ClrCreateManagedInstance+0xeecd
clr.dll!ClrCreateManagedInstance+0x30731
clr.dll!MetaDataGetDispenser+0xd1e4
clr.dll!MetaDataGetDispenser+0xd1ae
clr.dll!MetaDataGetDispenser+0xcef1
[Managed to Unmanaged Transition]
C:\Windows\Microsoft.Net\assembly\GAC_64\mscorlib\v4.0_4.0.0.0__b77a5c561934e089\mscorlib.dll!System.Threading.ManualResetEventSlim.Wait+0x364
C:\Program Files\Duplicati 2\Duplicati.Library.Utility.dll!Duplicati.Library.Utility.DirectStreamLink.read+0x199
C:\Windows\Microsoft.Net\assembly\GAC_64\mscorlib\v4.0_4.0.0.0__b77a5c561934e089\mscorlib.dll!System.Security.Cryptography.HashAlgorithm.ComputeHash+0x46
C:\Program Files\Duplicati 2\Duplicati.Library.Main.dll!Duplicati.Library.Main.BackendManager.CalculateFileHash+0x3c
C:\Program Files\Duplicati 2\Duplicati.Library.Main.dll!<>c__DisplayClass33_0.<coreDoGetPiping>b__1+0x29
C:\Windows\Microsoft.Net\assembly\GAC_64\mscorlib\v4.0_4.0.0.0__b77a5c561934e089\mscorlib.dll!System.Threading.Tasks.Task`1.InnerInvoke+0x4e
C:\Windows\Microsoft.Net\assembly\GAC_64\mscorlib\v4.0_4.0.0.0__b77a5c561934e089\mscorlib.dll!System.Threading.Tasks.Task.Execute+0x47
C:\Windows\Microsoft.Net\assembly\GAC_64\mscorlib\v4.0_4.0.0.0__b77a5c561934e089\mscorlib.dll!System.Threading.ExecutionContext.RunInternal+0x172
C:\Windows\Microsoft.Net\assembly\GAC_64\mscorlib\v4.0_4.0.0.0__b77a5c561934e089\mscorlib.dll!System.Threading.ExecutionContext.Run+0x15
C:\Windows\Microsoft.Net\assembly\GAC_64\mscorlib\v4.0_4.0.0.0__b77a5c561934e089\mscorlib.dll!System.Threading.Tasks.Task.ExecuteWithThreadLocal+0x231
C:\Windows\Microsoft.Net\assembly\GAC_64\mscorlib\v4.0_4.0.0.0__b77a5c561934e089\mscorlib.dll!System.Threading.Tasks.Task.ExecuteEntry+0xa1
C:\Windows\Microsoft.Net\assembly\GAC_64\mscorlib\v4.0_4.0.0.0__b77a5c561934e089\mscorlib.dll!System.Threading.ThreadPoolWorkQueue.Dispatch+0x156
[Unmanaged to Managed Transition]
clr.dll!DllCanUnloadNowInternal+0x10f3
clr.dll!DllCanUnloadNowInternal+0x1000
clr.dll!DllCanUnloadNowInternal+0x18b0
clr.dll!DllCanUnloadNowInternal+0x659a
clr.dll!DllCanUnloadNowInternal+0x2498
clr.dll!DllCanUnloadNowInternal+0x2403
clr.dll!DllCanUnloadNowInternal+0x2342
clr.dll!DllCanUnloadNowInternal+0x2533
clr.dll!DllCanUnloadNowInternal+0x64e7
clr.dll!DllCanUnloadNowInternal+0x204f
clr.dll!DllCanUnloadNowInternal+0x1f1f
clr.dll!DllCanUnloadNowInternal+0x6015
KERNEL32.dll!BaseThreadInitThunk+0x14
ntdll.dll!RtlUserThreadStart+0x21

C# debugger show another four threads, but there wasn’t a stack available. Here is the whole listing:

0x000076D8	0x00000001	Main Thread		mscorlib.dll!System.Threading.WaitHandle.InternalWaitOne(System.Runtime.InteropServices.SafeHandle waitableSafeHandle, long millisecondsTimeout, bool hasThreadAffinity, bool exitContext) (IL≈0x0014, Native=0x00007FFCCDEEBE50+0x1C)	Normal	0000000000001111	0x00000000	Duplicati.CommandLine.exe (id = 20472)	[1] Duplicati.CommandLine.exe	WaitSleepJoin, UnsafePoint
0x00008240	0x00000002	Finalizer		[Native to Managed Transition]	Highest	0000000000001111	0x00000000	Duplicati.CommandLine.exe (id = 20472)	[1] Duplicati.CommandLine.exe	Background, UnsafePoint
0x00008774	0x00000004	Thread Pool		<not available>	Normal	0000000000001111	0x00000000	Duplicati.CommandLine.exe (id = 20472)	[1] Duplicati.CommandLine.exe	Background, UnsafePoint, ThreadPool
0x00000ED8	0x00000006	Worker Thread	Backend Async Worker	mscorlib.dll!System.Threading.ManualResetEventSlim.Wait(int millisecondsTimeout, System.Threading.CancellationToken cancellationToken) (IL=???, Native=0x00007FFCCDF22BA0+0x364)	Normal	0000000000001111	0x00000000	Duplicati.CommandLine.exe (id = 20472)	[1] Duplicati.CommandLine.exe	Background, WaitSleepJoin, UnsafePoint
0x00006018	0x00000008	Thread Pool		<not available>	Normal	0000000000001111	0x00000000	Duplicati.CommandLine.exe (id = 20472)	[1] Duplicati.CommandLine.exe	Background, UnsafePoint, ThreadPool
0x00008470	0x00000010	Thread Pool		<not available>	Normal	0000000000001111	0x00000000	Duplicati.CommandLine.exe (id = 20472)	[1] Duplicati.CommandLine.exe	Background, UnsafePoint, ThreadPool
0x000044C0	0x00000012	Thread Pool		mscorlib.dll!System.Threading.ManualResetEventSlim.Wait(int millisecondsTimeout, System.Threading.CancellationToken cancellationToken) (IL=???, Native=0x00007FFCCDF22BA0+0x364)	Normal	0000000000001111	0x00000000	Duplicati.CommandLine.exe (id = 20472)	[1] Duplicati.CommandLine.exe	Background, WaitSleepJoin, UnsafePoint, ThreadPool

EDIT 1:

Process Explorer per-process network info just had one ESTABLISHED connection to 1drv.ms.
Wireshark on the local port and 1drv.ms didn’t show anything going on. Last output from test is:

Backend event: Put - Started: duplicati-bd5b495b6c0f34d1f8051ffaf6f40e311.dblock.zip (250.09 MB)
  Uploading file (250.09 MB) ...
Backend event: Put - Completed: duplicati-bd5b495b6c0f34d1f8051ffaf6f40e311.dblock.zip (250.09 MB)
Backend event: Put - Started: duplicati-if86c3a94aa194ffbad7e2ff746d80ef2.dindex.zip (186.22 KB)
  Uploading file (186.22 KB) ...
Backend event: Put - Completed: duplicati-if86c3a94aa194ffbad7e2ff746d80ef2.dindex.zip (186.22 KB)
Backend event: Delete - Started: duplicati-b33e0731510ab4100b3b2a14ea8e5b96d.dblock.zip (50.00 MB)
  Deleting file duplicati-b33e0731510ab4100b3b2a14ea8e5b96d.dblock.zip (50.00 MB) ...
Backend event: Delete - Completed: duplicati-b33e0731510ab4100b3b2a14ea8e5b96d.dblock.zip (50.00 MB)
Backend event: Delete - Started: duplicati-ie07e25c222b34afaa3ab4a38837c66fc.dindex.zip (117.84 KB)
  Deleting file duplicati-ie07e25c222b34afaa3ab4a38837c66fc.dindex.zip (117.84 KB) ...
Backend event: Delete - Completed: duplicati-ie07e25c222b34afaa3ab4a38837c66fc.dindex.zip (117.84 KB)
Backend event: Delete - Started: duplicati-b84b8acd395e245748d9ab88b42056113.dblock.zip (50.00 MB)
  Deleting file duplicati-b84b8acd395e245748d9ab88b42056113.dblock.zip (50.00 MB) ...
Backend event: Delete - Completed: duplicati-b84b8acd395e245748d9ab88b42056113.dblock.zip (50.00 MB)
Backend event: Delete - Started: duplicati-i8d791976388c4c50a8efba3ce39c71e4.dindex.zip (17.65 KB)
  Deleting file duplicati-i8d791976388c4c50a8efba3ce39c71e4.dindex.zip (17.65 KB) ...
Backend event: Delete - Completed: duplicati-i8d791976388c4c50a8efba3ce39c71e4.dindex.zip (17.65 KB)
Backend event: Delete - Started: duplicati-b941b456fa3334cdc8f092d7e6d80c5f4.dblock.zip (50.00 MB)
  Deleting file duplicati-b941b456fa3334cdc8f092d7e6d80c5f4.dblock.zip (50.00 MB) ...
Backend event: Delete - Completed: duplicati-b941b456fa3334cdc8f092d7e6d80c5f4.dblock.zip (50.00 MB)
Backend event: Delete - Started: duplicati-i17c675030b4f458b9749c94343c68c74.dindex.zip (17.67 KB)
  Deleting file duplicati-i17c675030b4f458b9749c94343c68c74.dindex.zip (17.67 KB) ...
Backend event: Delete - Completed: duplicati-i17c675030b4f458b9749c94343c68c74.dindex.zip (17.67 KB)
Backend event: Delete - Started: duplicati-b23d6059a1dd34094b0f69c78a672fb62.dblock.zip (50.00 MB)
  Deleting file duplicati-b23d6059a1dd34094b0f69c78a672fb62.dblock.zip (50.00 MB) ...
Backend event: Delete - Completed: duplicati-b23d6059a1dd34094b0f69c78a672fb62.dblock.zip (50.00 MB)
Backend event: Delete - Started: duplicati-i29b9fbe5f6354d1ba5216b4b67744c21.dindex.zip (17.65 KB)
  Deleting file duplicati-i29b9fbe5f6354d1ba5216b4b67744c21.dindex.zip (17.65 KB) ...
Backend event: Delete - Completed: duplicati-i29b9fbe5f6354d1ba5216b4b67744c21.dindex.zip (17.65 KB)
Backend event: Delete - Started: duplicati-b39d7d7ff11d44f87b7a7d7d2b4e42daa.dblock.zip (50.00 MB)
  Deleting file duplicati-b39d7d7ff11d44f87b7a7d7d2b4e42daa.dblock.zip (50.00 MB) ...
Backend event: Delete - Completed: duplicati-b39d7d7ff11d44f87b7a7d7d2b4e42daa.dblock.zip (50.00 MB)
Backend event: Delete - Started: duplicati-id3d98fba074047dea59abd321e0a07c0.dindex.zip (17.65 KB)
  Deleting file duplicati-id3d98fba074047dea59abd321e0a07c0.dindex.zip (17.65 KB) ...
Backend event: Delete - Completed: duplicati-id3d98fba074047dea59abd321e0a07c0.dindex.zip (17.65 KB)
Backend event: Get - Started: duplicati-b5dff5ec3f85d470aba7f4b45d6f59688.dblock.zip (50.00 MB)
  Downloading file (50.00 MB) ...

Some thoughts from any devs who can make more sense of all the above than I can would be helpful.

Jojo-1000 · August 16, 2023, 4:00pm

I tried a 3GB backup with 1MB → 6MB compact, but it did not get stuck.

The stack trace could be helpful.

ts678:

mscorlib.dll!System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(System.Threading.Tasks.Task task) (IL≈0x0008, Native=0x00007FFCCDF1BC10+0x5A)
Duplicati.Library.Backend.OneDrive.dll!Duplicati.Library.Backend.MicrosoftGraphBackend.Get(string remotename, System.IO.Stream stream) (IL=???, Native=0x00007FFC71C5BA60+0xCD)

This confirms that the Get() actually is stuck, and it is not some other deadlock. The Main thread is waiting for the download to finish, Thread Pool thread is waiting for the file to calculate the hash. That is both normal. The HandleNonSuccessAndDebugNotifications part means it is still waiting for an async task to finish.

It is interesting that it does not show any levels deeper than Get(), does this mean it was inlined, or do async tasks only show up where await is called in the stack trace?

There is also WaitForRetryAfter() in Get(), which is a blocking, potentially very long wait (depends on the Retry-After header returned) without a timeout (that should probably at least respect the operation timeout and have a sane default). This should log RetryAfterWait on the profiling level before waiting. Would that show up in your logs @ts678? They don’t look like profiling logs to me.

@arberg I see that you used --log-file for your backups. Can you also set --log-file-log-level=Profiling if you try to reproduce it again? Maybe that will give us some more clues.

ts678 · August 16, 2023, 4:34pm

I had a profiling log (also with --profile-all-database-queries) in the script. Retry mentions there were:

2023-08-15 15:35:36 -04 - [Retry-Duplicati.Library.Backend.MicrosoftGraphBackend-MicrosoftGraphFragmentRetryIn]: Uploading fragment 2/6 of remote file duplicati-b113cbcbb2f444e1a99d8c31f9d131a43.dblock.zip failed and will be retried in 00:00:01
2023-08-15 17:05:43 -04 - [Retry-Duplicati.Library.Main.BackendManager-RetryList]: Operation List with file  attempt 1 of 5 failed with message: BadGateway: Bad Gateway error from request https://graph.microsoft.com/v1.0/me/drive/root:/Duplicati Backups/onedrive_compact:/children
2023-08-15 17:05:43 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Retrying:  ()
2023-08-15 17:45:25 -04 - [Retry-Duplicati.Library.Backend.MicrosoftGraphBackend-MicrosoftGraphFragmentRetryIn]: Uploading fragment 0/1 of remote file duplicati-b9278fb42c77a49cea9e7b7fc6fba4647.dblock.zip failed and will be retried in 00:00:01
2023-08-15 18:46:37 -04 - [Retry-Duplicati.Library.Backend.MicrosoftGraphBackend-MicrosoftGraphFragmentRetryIn]: Uploading fragment 0/1 of remote file duplicati-bb79b33bbef5d476ba2ab9b4012d94b24.dblock.zip failed and will be retried in 00:00:01
2023-08-15 19:20:43 -04 - [Retry-Duplicati.Library.Backend.MicrosoftGraphBackend-MicrosoftGraphFragmentRetryIn]: Uploading fragment 0/2 of remote file duplicati-bd69ab1b10fab475d80bd371974ab13c4.dblock.zip failed and will be retried in 00:00:01
2023-08-15 19:53:56 -04 - [Retry-Duplicati.Library.Backend.MicrosoftGraphBackend-MicrosoftGraphFragmentRetryIn]: Uploading fragment 1/4 of remote file duplicati-bbc45cb406aa04672808b64a701d6ccf9.dblock.zip failed and will be retried in 00:00:01
2023-08-15 20:46:07 -04 - [Retry-Duplicati.Library.Main.BackendManager-RetryGet]: Operation Get with file duplicati-i83a7217ad93243829c65fbccb0f3aba7.dindex.zip attempt 1 of 5 failed with message: ServiceUnavailable: Service Unavailable error from request https://public.dm.files.1drv.com/y4mEWvuaH9n3q8n2hLRPwnV8X5fmapmKC0LT8M8Xx4a4MVp5xqt3aG5L33GL4YZJGHaKsVOZyr_pxmj_uDq52juIOgIy5pacr5EoWICy-ANwmrAh7coDW2NeQ6sB6DiASHRGgAiiA_Ffq-sgsZTd7dcAl6KpNdbPCxeJQbKXfEdPeKbrejKYQk7E9AvuZ1tK3gk_r3Yc504UJdTyLA8KIPM4ZjIDWpxWsen757sW_jjtIg/duplicati-i83a7217ad93243829c65fbccb0f3aba7.dindex.zip
2023-08-15 20:46:07 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Retrying: duplicati-i83a7217ad93243829c65fbccb0f3aba7.dindex.zip (175.57 KB)
2023-08-16 07:56:05 -04 - [Retry-Duplicati.Library.Main.Operation.Backup.BackendUploader-RetryPut]: Operation Put with file duplicati-be682ac2a34f940a1a7ec01310d9d4879.dblock.zip attempt 1 of 6 failed with message: BadGateway: Bad Gateway error from request https://graph.microsoft.com/v1.0/me/drive/root:/Duplicati Backups/onedrive_compact/duplicati-be682ac2a34f940a1a7ec01310d9d4879.dblock.zip:/createUploadSession
   at Duplicati.Library.Main.Operation.Backup.BackendUploader.<DoWithRetry>d__21.MoveNext()
2023-08-16 07:56:07 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Retrying: duplicati-be682ac2a34f940a1a7ec01310d9d4879.dblock.zip (50.00 MB)
2023-08-16 08:12:04 -04 - [Retry-Duplicati.Library.Backend.MicrosoftGraphBackend-MicrosoftGraphFragmentRetryIn]: Uploading fragment 0/5 of remote file duplicati-bd5a40a6538f34d8caa3c7d1595621ee7.dblock.zip failed and will be retried in 00:00:01
2023-08-16 08:12:15 -04 - [Retry-Duplicati.Library.Backend.MicrosoftGraphBackend-MicrosoftGraphFragmentRetryIn]: Uploading fragment 0/5 of remote file duplicati-b482aec36285547adbd96e26e78011c19.dblock.zip failed and will be retried in 00:00:01
2023-08-16 08:19:01 -04 - [Retry-Duplicati.Library.Backend.MicrosoftGraphBackend-MicrosoftGraphFragmentRetryIn]: Uploading fragment 1/5 of remote file duplicati-b0e536177e5b54ed0aabb35f3cbfff963.dblock.zip failed and will be retried in 00:00:01
2023-08-16 08:19:12 -04 - [Retry-Duplicati.Library.Backend.MicrosoftGraphBackend-MicrosoftGraphFragmentRetryIn]: Uploading fragment 1/5 of remote file duplicati-b7d6bd23311cc4ebb8363edb0cebe6ad2.dblock.zip failed and will be retried in 00:00:01
2023-08-16 08:19:32 -04 - [Retry-Duplicati.Library.Backend.MicrosoftGraphBackend-MicrosoftGraphFragmentRetryIn]: Uploading fragment 1/5 of remote file duplicati-b7d6bd23311cc4ebb8363edb0cebe6ad2.dblock.zip failed and will be retried in 00:00:02
2023-08-16 08:21:43 -04 - [Retry-Duplicati.Library.Backend.MicrosoftGraphBackend-MicrosoftGraphFragmentRetryIn]: Uploading fragment 4/5 of remote file duplicati-b1163ccf8aba7412cbc2766267cf3b244.dblock.zip failed and will be retried in 00:00:01

and possibly the high-level (entire operation) retries were some of the ones I noticed going by.
Unfortunately the compact command line used a simplified version, so I don’t have better logs.
Possibly @arberg was more consistent, but previously posted profiling data didn’t help much.

ts678 · August 16, 2023, 4:50pm

I’m not sure I’m doing this right, and getting local variables is a bit hit-or-miss, but I can see this:

-		m_retryAfter	{Duplicati.Library.RetryAfterHelper}	Duplicati.Library.RetryAfterHelper
		retryAfter	0x0000000000000000	long

Jojo-1000 · August 16, 2023, 5:33pm

That both suggests it is not the retry after that is blocking. Which is unfortunate, because in that case there are 2 different code paths for windows and linux (I assume the docker container uses mono, so no HttpClient is used by default). And you both get the same behavior, while using different methods for making the request (.NET HttpClient vs. our own OAuthHelper that uses the older HttpWebRequests). I don’t know why they both don’t time out.

I assume the other thread pool workers without stack trace have no work to do. There should be at least one thread somewhere running the actual Http request, if I understand the C# async model correctly. But there is none for some reason.

Can you get any more information out of the MicrosoftGraphBackend.Get() stackframe? It has IL=???, so I can’t compare it to the disassembled release build DLL to find out where that point is.

ts678 · August 16, 2023, 6:54pm

I’m not used to the way these look, especially when async, but a lot of stackoverflow articles say not to expect to see stack past the async spot. What I’d have liked is a little bit of the top portions before that:

I already fished around for locals (there are a lot), but didn’t find much of a clue in them as to situation.

At a native level, all I can say is that the native address on the line with the missing IL says it returns to

; C:\Program Files\Duplicati 2\Duplicati.Library.Backend.OneDrive.dll
; Void Get(System.String, System.IO.Stream) (0x06000012)
; Size: 769 (0x301)

; arg #0 (this) 00007FFC71C5BA60-00007FFC71C5BA94 rcx
; arg #0 (this) 00007FFC71C5BA94-00007FFC71C5BB35 rsi
; arg #0 (this) 00007FFC71C5BB98-00007FFC71C5BBB0 rsi
; arg #1 (remotename) 00007FFC71C5BA60-00007FFC71C5BA94 rdx
; arg #1 (remotename) 00007FFC71C5BA94-00007FFC71C5BAB8 rbx
; arg #2 (stream) 00007FFC71C5BA60-00007FFC71C5BA94 r8
; arg #2 (stream) 00007FFC71C5BA94-00007FFC71C5BB7A rdi
; arg #2 (stream) 00007FFC71C5BB98-00007FFC71C5BBD6 rdi
; local #0 (text) 00007FFC71C5BB98-00007FFC71C5BB9C rax
; local #1 (httpResponseMessage) 00007FFC71C5BB35-00007FFC71C5BB98 [rbp-50h]
; local #2 (stream2) 00007FFC71C5BB76-00007FFC71C5BB8E [rbp-58h]
; local #3 (responseWithoutException) 00007FFC71C5BBB0-00007FFC71C5BBF3 [rbp-60h]
; local #4 (responseStream) 00007FFC71C5BBD2-00007FFC71C5BBEA [rbp-68h]

00007FFC71C5BA60 55                   push    rbp
00007FFC71C5BA61 4157                 push    r15
00007FFC71C5BA63 4156                 push    r14
00007FFC71C5BA65 57                   push    rdi
00007FFC71C5BA66 56                   push    rsi
00007FFC71C5BA67 53                   push    rbx
00007FFC71C5BA68 4883EC68             sub     rsp,68h
00007FFC71C5BA6C 488DAC2490000000     lea     rbp,[rsp+90h]
00007FFC71C5BA74 488BF1               mov     rsi,rcx
00007FFC71C5BA77 488D7DA0             lea     rdi,[rbp-60h]
00007FFC71C5BA7B B90E000000           mov     ecx,0Eh
00007FFC71C5BA80 33C0                 xor     eax,eax
00007FFC71C5BA82 F3AB                 rep stosd
00007FFC71C5BA84 488BCE               mov     rcx,rsi
00007FFC71C5BA87 48896590             mov     [rbp-70h],rsp
00007FFC71C5BA8B 488BF1               mov     rsi,rcx
00007FFC71C5BA8E 488BDA               mov     rbx,rdx
00007FFC71C5BA91 498BF8               mov     rdi,r8

;         this.m_retryAfter.WaitForRetryAfter();
00007FFC71C5BA94 488B4E20             mov     rcx,[rsi+20h]
00007FFC71C5BA98 3909                 cmp     [rcx],ecx
00007FFC71C5BA9A E82181FDFF           call    Duplicati.Library.RetryAfterHelper.WaitForRetryAfter() (00007FFC71C33BC0h)
00007FFC71C5BA9F 488BCE               mov     rcx,rsi
00007FFC71C5BAA2 E8A975FDFF           call    Duplicati.Library.Backend.MicrosoftGraphBackend.get_DrivePrefix() (00007FFC71C33050h)
00007FFC71C5BAA7 4C8BF0               mov     r14,rax
00007FFC71C5BAAA 488B4E30             mov     rcx,[rsi+30h]
00007FFC71C5BAAE 3909                 cmp     [rcx],ecx
00007FFC71C5BAB0 E86B5B275C           call    System.Lazy`1[[System.__Canon, mscorlib]].get_Value() (00007FFCCDED1620h)
00007FFC71C5BAB5 4C8BF8               mov     r15,rax
00007FFC71C5BAB8 488BCB               mov     rcx,rbx
00007FFC71C5BABB E8D077FDFF           call    Duplicati.Library.Backend.MicrosoftGraphBackend.NormalizeSlashes(System.String) (00007FFC71C33290h)
00007FFC71C5BAC0 49B80813C2A733020000 mov     r8,233A7C21308h
00007FFC71C5BACA 4D8B00               mov     r8,[r8]
00007FFC71C5BACD 48BA50DEE5A733020000 mov     rdx,233A7E5DE50h
00007FFC71C5BAD7 488B12               mov     rdx,[rdx]
00007FFC71C5BADA 488D4DB8             lea     rcx,[rbp-48h]
00007FFC71C5BADE 4C8931               mov     [rcx],r14
00007FFC71C5BAE1 4C897908             mov     [rcx+8],r15
00007FFC71C5BAE5 48894110             mov     [rcx+10h],rax
00007FFC71C5BAE9 4C894118             mov     [rcx+18h],r8
00007FFC71C5BAED 4C8D45B8             lea     r8,[rbp-48h]
00007FFC71C5BAF1 33C9                 xor     ecx,ecx
00007FFC71C5BAF3 E8A8E02F5C           call    System.String.FormatHelper(System.IFormatProvider, System.String, System.ParamsArray) (00007FFCCDF59BA0h)

;         if (this.m_client != null)
00007FFC71C5BAF8 488B4E10             mov     rcx,[rsi+10h]
00007FFC71C5BAFC 4885C9               test    rcx,rcx
00007FFC71C5BAFF 0F8493000000         je      near ptr LBL_2 (00007FFC71C5BB98h)
00007FFC71C5BB05 488BD0               mov     rdx,rax
00007FFC71C5BB08 3909                 cmp     [rcx],ecx
00007FFC71C5BB0A E899CC10FF           call    Duplicati.Library.OAuthHttpClient.GetAsync(System.String) (00007FFC70D687A8h)
00007FFC71C5BB0F 8B08                 mov     ecx,[rax]
00007FFC71C5BB11 488BD8               mov     rbx,rax
00007FFC71C5BB14 8B4B3C               mov     ecx,[rbx+3Ch]
00007FFC71C5BB17 81E100000011         and     ecx,11000000h
00007FFC71C5BB1D 81F900000001         cmp     ecx,1000000h
00007FFC71C5BB23 7408                 je      short LBL_0 (00007FFC71C5BB2Dh)

00007FFC71C5BB25 488BCB               mov     rcx,rbx
00007FFC71C5BB28 E8E3002C5C           call    System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(System.Threading.Tasks.Task) (00007FFCCDF1BC10h)

LBL_0:
00007FFC71C5BB2D 488B4B40             mov     rcx,[rbx+40h]

Return address is to the bottom line. Any idea how to get more information out of this? Do you have a favorite debugger that does well? Maybe either I can try yours or you can keep trying to get a repro…

EDIT:

Giving a little more (starting from return point) to see what’s up next after it gets back to this method…

00007FFC71C5BB2D 488B4B40             mov     rcx,[rbx+40h]
00007FFC71C5BB31 48894DB0             mov     [rbp-50h],rcx

;                 this.CheckResponse(httpResponseMessage);
00007FFC71C5BB35 488BCE               mov     rcx,rsi
00007FFC71C5BB38 488B55B0             mov     rdx,[rbp-50h]
00007FFC71C5BB3C E86FCAFDFF           call    Duplicati.Library.Backend.MicrosoftGraphBackend.CheckResponse(System.Net.Http.HttpResponseMessage) (00007FFC71C385B0h)
00007FFC71C5BB41 488B4DB0             mov     rcx,[rbp-50h]
00007FFC71C5BB45 488B4928             mov     rcx,[rcx+28h]
00007FFC71C5BB49 3909                 cmp     [rcx],ecx
00007FFC71C5BB4B E8B0F3C945           call    System.Net.Http.HttpContent.ReadAsStreamAsync() (00007FFCB78FAF00h)
00007FFC71C5BB50 8B08                 mov     ecx,[rax]
00007FFC71C5BB52 488BF0               mov     rsi,rax
00007FFC71C5BB55 8B4E3C               mov     ecx,[rsi+3Ch]
00007FFC71C5BB58 81E100000011         and     ecx,11000000h
00007FFC71C5BB5E 81F900000001         cmp     ecx,1000000h
00007FFC71C5BB64 7408                 je      short LBL_1 (00007FFC71C5BB6Eh)

00007FFC71C5BB66 488BCE               mov     rcx,rsi
00007FFC71C5BB69 E8A2002C5C           call    System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(System.Threading.Tasks.Task) (00007FFCCDF1BC10h)

LBL_1:
00007FFC71C5BB6E 488B4E40             mov     rcx,[rsi+40h]
00007FFC71C5BB72 48894DA8             mov     [rbp-58h],rcx

;                     stream2.CopyTo(stream);

Jojo-1000 · August 16, 2023, 7:26pm

Thank you for the disassembly. This means the block is directly in the HttpClient.GetAsync(). I looked for reasons why that might lock up, and most of the time it is because async Tasks want to continue on the same thread where await is called. Maybe there is a deadlock after all, but I don’t really know why it only happens for OneDrive (and it is so rare), and it doesn’t explain why the AsyncHttpRequest (that doesn’t use async tasks) also blocks.

One more thing, in the “Backend Async Worker” thread and “Thread Pool” thread the final stack frame is a wait on the ManualResetEventSlim. Can you see if the this pointer of those two belong to either linkForkHasher or linkForkDecryptor in BackendManager.coreDoGetPiping() (m_signalDataAvailable or m_signalBufferAvailable)? Maybe there is a deadlock with the signaling mechanism for stream forwarding. It might also be entirely unrelated and just be an internal wait, I don’t know.

arberg · August 16, 2023, 8:06pm

It’s late, and I don’t have time to reread all above, you’ve been busy Good to see some reproduction success.

Jojo, I don’t think we know its only OneDrive. I have only tested OneDrive, local files, and ssh on local network, and of those three, only oneDrive gave issues. And actually I don’t think I have compacted large quantities over ssh. And obviously local files don’t use HttpClient. So it could be on others as well. It could be other cloud drives as well. After all it wasn’t THAT easy to reproduce.

If its easy to add lots of log statements around that code, we might learn more. I don’t know how much you control of the code, whether you can see if the getAsync actually is started or not via logging.

ts678 · August 16, 2023, 8:18pm

I suspect not, but let me confirm the request after looking some things up to get a general idea of this.

github.com

duplicati/duplicati/blob/d0f1498bd41b151d8512fd2acb57739f6a05587f/Duplicati/Library/Utility/DirectStreamLink.cs#L30-L49


      
          /// <summary>
          /// A link connecting a streaming writer to a streaming reader through a buffer.
          /// Should be used to enable multithreading by linking sequential processes avoiding tempfiles (piping).
          /// Safe for a single reader and writer to be in different threads. It is possible to pass the written
          /// data on to an underlying stream. Use another DirectLinkStream as passthrough to feed multiple spawned
          /// threads processing data.
          /// </summary>
          public class DirectStreamLink : IDisposable
          {
              /// <summary>
              /// Main lock to synchronize operations between reader and writer.
              /// Used to protect accesses to all state vars and making decisions
              /// on blocking thereon.
              /// </summary>
              private readonly object m_lock = new object();
          
              /// <summary> An event to wake reader. </summary>
              private readonly ManualResetEventSlim m_signalDataAvailable = new ManualResetEventSlim(false);
              /// <summary> An event to wake writer. </summary>
              private readonly ManualResetEventSlim m_signalBufferAvailable = new ManualResetEventSlim(true);

github.com

duplicati/duplicati/blob/d0f1498bd41b151d8512fd2acb57739f6a05587f/Duplicati/Library/Main/BackendManager.cs#L761-L766


      
          private TempFile coreDoGetPiping(FileEntryItem item, Interface.IEncryption useDecrypter, out long retDownloadSize, out string retHashcode)

          {

              // With piping allowed, we will parallelize the operation with buffered pipes to maximize throughput:

              // Separated: Download (only for streaming) - Hashing - Decryption

              // The idea is to use DirectStreamLink's that are inserted in the stream stack, creating a fork to run

              // the crypto operations on.

github.com

duplicati/duplicati/blob/d0f1498bd41b151d8512fd2acb57739f6a05587f/Duplicati/Library/Main/BackendManager.cs#L793-L796


      
          // setup decryption: fork off a StreamLink from stack, and setup decryptor task

          if (useDecrypter != null)

          {

              linkForkDecryptor = new DirectStreamLink(1 << 16, false, false, nextTierWriter);

github.com

duplicati/duplicati/blob/d0f1498bd41b151d8512fd2acb57739f6a05587f/Duplicati/Library/Main/BackendManager.cs#L810-L811


      
          // setup hashing: fork off a StreamLink from stack, then task computes hash

          linkForkHasher = new DirectStreamLink(1 << 16, false, false, nextTierWriter);

Wait(Int32, CancellationToken)

Blocks the current thread until the current ManualResetEventSlim is set, using a 32-bit signed integer to measure the time interval, while observing a CancellationToken.

So you want me to try tracing the ManualResetEventSlim to a DirectStreamLink to one of the linkFork variables? The C# data doesn’t go that far that I can find, and I don’t think I have registers to go lower.

I’m starting to think some sort of crude logging and a custom build for you (can you keep it isolated so interference with production doesn’t occur if something breaks?) might be easier than this deep diving.

I could “maybe” get something out of .NET Tracing. I could also just release the debugger and see if it continues sitting or blows up our theories by continuing. I was running another backup on OneDrive at same time with same AuthID, so if OneDrive did some throttling it must have been at connection level.

I counted 250 MB files (compact results) and found 22, so it took about 5.5 GB before the get hang…

arberg · August 17, 2023, 8:54am

In rclone I could see the Retry-After header OneDrive sends, and at most it sent 24h (maybe most was 8h), and that was when dowloading 700 GB. So its highly unlikely that is the problem. But Duplicati definitely should log the Retry-After before sleeping to the profile log. It is rather important to have that infomation for debugging and just for understanding why its hanging. It drove me insane why rclone was so freaking slow, until I learned it was just because OneDrive throttled me

Sure, somehow. I think I can install it on my windows. Probably also on a debug docker image.

Is the code easy to set up with the environment? Do I need Visual Code? If you add some logs and push to a debug branch, I might have a look and add more. I’m not sure I have the time, but it wouldn’t hurt to try if its easy.

Jojo-1000 · August 17, 2023, 12:38pm

This older post also had similar behavior when downloading from Jottacloud (hangs on Get), so maybe it is a more general problem (Jottacloud also uses OAuthHelper):

ts678 · August 17, 2023, 1:59pm

It looks like it does, although I didn’t find one above. Do you see anything like below in profiling logs?

github.com

duplicati/duplicati/blob/d0f1498bd41b151d8512fd2acb57739f6a05587f/Duplicati/Library/Backend/OAuthHelper/RetryAfterHelper.cs#L80-L99


      
          public void WaitForRetryAfter()

          {

              this.WaitForRetryAfterAsync(CancellationToken.None).Await();

          }

          

          public async Task WaitForRetryAfterAsync(CancellationToken cancelToken)

          {

              TimeSpan delay = this.GetDelayTime();

          

              if (delay > TimeSpan.Zero)

              {

                  Log.WriteProfilingMessage(

                      LOGTAG,

                      "RetryAfterWait",

                      "Waiting for {0} to respect Retry-After header",

                      delay);

          

                  await Task.Delay(delay).ConfigureAwait(false);

              }

          }

What I found, such as the below, looks like a different sort of exponential backoff done by Duplicati:

ts678:

2023-08-16 08:19:32 -04 - [Retry-Duplicati.Library.Backend.MicrosoftGraphBackend-MicrosoftGraphFragmentRetryIn]: Uploading fragment 1/5 of remote file duplicati-b7d6bd23311cc4ebb8363edb0cebe6ad2.dblock.zip failed and will be retried in 00:00:02

github.com

duplicati/duplicati/blob/d0f1498bd41b151d8512fd2acb57739f6a05587f/Duplicati/Library/Backend/OneDrive/MicrosoftGraphBackend.cs#L551-L566


      
          else if ((int)ex.StatusCode >= 500 && (int)ex.StatusCode < 600)

          {

              // If a 5xx error code is hit, we should use an exponential backoff strategy before retrying.

              // To make things simpler, we just use the current attempt number as the exponential factor.

              // If there was a Retry-After header, we'll wait for that right before sending the next request as well.

              TimeSpan delay = TimeSpan.FromMilliseconds((int)Math.Pow(2, attempt) * this.fragmentRetryDelay);

          

              Log.WriteRetryMessage(

                  LOGTAG,

                  "MicrosoftGraphFragmentRetryIn",

                  ex,

                  "Uploading fragment {0}/{1} of remote file {2} failed and will be retried in {3}",

                  fragmentNumber,

                  fragmentCount,

                  remotename,

                  delay);

and this format seems to apply only to put, whereas the Retry-After covers many operation types.

arberg · August 18, 2023, 9:41am

Ahh, that is good to see. None of my logs contain this ‘RetryAfterWait’ log, but I also only enabled profiling in some of them. It’s quite likely I never got such a retry, since it hang way before down/uploading 200 GB, which is the point where rclone start reporting those Retry-After-headers from OneDrive.

I wonder if the code is correctly handles http-requests that never respond? I would assume that’s what hte http-timeout was for, so I also doubt that is the issue.

That exponential backoff seems crazy, in that it does not have an upper limit. However I’m pretty sure that is not the problem we are facing as nothing is logged even with profiling on, from between successful deletes to the hanging get/put. However I think I’ll try to reproduce the problem again on the smaller compact test i made, this time with profiling enabled, just to be sure.

ts678 · August 18, 2023, 3:01pm

Disagree but haven’t tested:

C:\Duplicati\duplicati-2.0.7.2_canary_2023-05-25>Duplicati.CommandLine.exe help fragment-retry-count
  --fragment-retry-count (Integer): Number of retries for each fragment
    Number of retry attempts made for each fragment before failing the overall
    file upload
    * default value: 5

github.com

duplicati/duplicati/blob/d0f1498bd41b151d8512fd2acb57739f6a05587f/Duplicati/Library/Backend/OneDrive/MicrosoftGraphBackend.cs#L483-L484


      
          int retryCount = this.fragmentRetryCount;

          for (int attempt = 0; attempt < retryCount; attempt++)

In other new, my connection is still hanging around, but I’m going to detach the debugger soon unless somebody thinks of something else I can fish for. I might try testing other parameters or just download.

Without network logs of some sort (or more magic in the debugger than I have – maybe others do), figuring out if the request actually went out isn’t obvious. Without studying much code, I’ll reference:

HttpClient.GetAsync Method (Microsoft)

Send a GET request to the specified Uri as an asynchronous operation.

and if it’s in something like that, where exactly is it? There’s both a send and a receive aspect to this.

ts678 · August 19, 2023, 12:52pm

I got one without compact, doing downloads with test ... all. First one was a false alarm though.

2023-08-18 21:28:45 -04 - [Profiling-Timer.Begin-Duplicati.Library.Main.BackendManager-RemoteOperationGet]: Starting - RemoteOperationGet
2023-08-18 21:28:45 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Started: duplicati-b96dec70ea42a41029aea26991b47f29c.dblock.zip (50.00 MB)
2023-08-18 21:28:45 -04 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: Starting - ExecuteNonQuery: CREATE TEMPORARY TABLE "Blocklist-6E8BBA148806FC49A768376774405E79" ("Hash" TEXT NOT NULL, "Size" INTEGER NOT NULL)
2023-08-18 21:28:45 -04 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: ExecuteNonQuery: CREATE TEMPORARY TABLE "Blocklist-6E8BBA148806FC49A768376774405E79" ("Hash" TEXT NOT NULL, "Size" INTEGER NOT NULL) took 0:00:00:00.000
2023-08-18 21:28:45 -04 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: Starting - ExecuteNonQuery: CREATE TEMPORARY TABLE "CmpTable-14B4948DCCF0BF42B01FB1ECDC2157AF" AS SELECT DISTINCT "Hash" AS "Hash", "Size" AS "Size" FROM (SELECT "Block"."Hash" AS "Hash", "Block"."Size" AS "Size" FROM "Remotevolume", "Block" WHERE "Remotevolume"."Name" = "duplicati-b2d698c48c7394ea8b5d8bfadb78b444b.dblock.zip" AND "Remotevolume"."ID" = "Block"."VolumeID" UNION SELECT "DeletedBlock"."Hash" AS "Hash", "DeletedBlock"."Size" AS "Size" FROM "DeletedBlock", "RemoteVolume" WHERE "RemoteVolume"."Name" = "duplicati-b2d698c48c7394ea8b5d8bfadb78b444b.dblock.zip" AND "RemoteVolume"."ID" = "DeletedBlock"."VolumeID")
2023-08-18 21:28:45 -04 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: ExecuteNonQuery: CREATE TEMPORARY TABLE "CmpTable-14B4948DCCF0BF42B01FB1ECDC2157AF" AS SELECT DISTINCT "Hash" AS "Hash", "Size" AS "Size" FROM (SELECT "Block"."Hash" AS "Hash", "Block"."Size" AS "Size" FROM "Remotevolume", "Block" WHERE "Remotevolume"."Name" = "duplicati-b2d698c48c7394ea8b5d8bfadb78b444b.dblock.zip" AND "Remotevolume"."ID" = "Block"."VolumeID" UNION SELECT "DeletedBlock"."Hash" AS "Hash", "DeletedBlock"."Size" AS "Size" FROM "DeletedBlock", "RemoteVolume" WHERE "RemoteVolume"."Name" = "duplicati-b2d698c48c7394ea8b5d8bfadb78b444b.dblock.zip" AND "RemoteVolume"."ID" = "DeletedBlock"."VolumeID") took 0:00:00:00.002
2023-08-18 21:28:45 -04 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteReader]: Starting - ExecuteReader: SELECT 1 AS "Type", "Blocklist-6E8BBA148806FC49A768376774405E79"."Hash" AS "Hash" FROM "Blocklist-6E8BBA148806FC49A768376774405E79" WHERE "Blocklist-6E8BBA148806FC49A768376774405E79"."Hash" NOT IN ( SELECT "Hash" FROM "CmpTable-14B4948DCCF0BF42B01FB1ECDC2157AF" ) UNION SELECT 0 AS "Type", "Hash" AS "Hash" FROM "CmpTable-14B4948DCCF0BF42B01FB1ECDC2157AF" WHERE "Hash" NOT IN (SELECT "Hash" FROM "Blocklist-6E8BBA148806FC49A768376774405E79") UNION SELECT 2 AS "Type", "E"."Hash" AS "Hash" FROM "Blocklist-6E8BBA148806FC49A768376774405E79" E, "CmpTable-14B4948DCCF0BF42B01FB1ECDC2157AF" D WHERE "D"."Hash" = "E"."Hash" AND "D"."Size" != "E"."Size"  
2023-08-18 21:28:45 -04 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteReader]: ExecuteReader: SELECT 1 AS "Type", "Blocklist-6E8BBA148806FC49A768376774405E79"."Hash" AS "Hash" FROM "Blocklist-6E8BBA148806FC49A768376774405E79" WHERE "Blocklist-6E8BBA148806FC49A768376774405E79"."Hash" NOT IN ( SELECT "Hash" FROM "CmpTable-14B4948DCCF0BF42B01FB1ECDC2157AF" ) UNION SELECT 0 AS "Type", "Hash" AS "Hash" FROM "CmpTable-14B4948DCCF0BF42B01FB1ECDC2157AF" WHERE "Hash" NOT IN (SELECT "Hash" FROM "Blocklist-6E8BBA148806FC49A768376774405E79") UNION SELECT 2 AS "Type", "E"."Hash" AS "Hash" FROM "Blocklist-6E8BBA148806FC49A768376774405E79" E, "CmpTable-14B4948DCCF0BF42B01FB1ECDC2157AF" D WHERE "D"."Hash" = "E"."Hash" AND "D"."Size" != "E"."Size"   took 0:00:00:00.002
2023-08-18 21:28:45 -04 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: Starting - ExecuteNonQuery: DROP TABLE IF EXISTS "CmpTable-14B4948DCCF0BF42B01FB1ECDC2157AF" 
2023-08-18 21:28:45 -04 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: ExecuteNonQuery: DROP TABLE IF EXISTS "CmpTable-14B4948DCCF0BF42B01FB1ECDC2157AF"  took 0:00:00:00.000
2023-08-18 21:28:45 -04 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: Starting - ExecuteNonQuery: DROP TABLE IF EXISTS "Blocklist-6E8BBA148806FC49A768376774405E79"
2023-08-18 21:28:45 -04 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: ExecuteNonQuery: DROP TABLE IF EXISTS "Blocklist-6E8BBA148806FC49A768376774405E79" took 0:00:00:00.000
2023-08-18 21:28:45 -04 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: Starting - ExecuteNonQuery: UPDATE "RemoteVolume" SET "VerificationCount" = MAX(1, CASE WHEN "VerificationCount" <= 0 THEN (SELECT MAX("VerificationCount") FROM "RemoteVolume") ELSE "VerificationCount" + 1 END) WHERE "Name" = "duplicati-b2d698c48c7394ea8b5d8bfadb78b444b.dblock.zip"
2023-08-18 21:28:45 -04 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: ExecuteNonQuery: UPDATE "RemoteVolume" SET "VerificationCount" = MAX(1, CASE WHEN "VerificationCount" <= 0 THEN (SELECT MAX("VerificationCount") FROM "RemoteVolume") ELSE "VerificationCount" + 1 END) WHERE "Name" = "duplicati-b2d698c48c7394ea8b5d8bfadb78b444b.dblock.zip" took 0:00:00:00.310
2023-08-18 21:31:34 -04 - [Profiling-Timer.Finished-Duplicati.Library.Main.BackendManager-RemoteOperationGet]: RemoteOperationGet took 0:00:02:48.866
2023-08-18 21:31:34 -04 - [Retry-Duplicati.Library.Main.BackendManager-RetryGet]: Operation Get with file duplicati-b96dec70ea42a41029aea26991b47f29c.dblock.zip attempt 1 of 5 failed with message: Error while copying content to a stream.
System.Net.Http.HttpRequestException: Error while copying content to a stream. ---> System.IO.IOException: Unable to read data from the transport connection: An existing connection was forcibly closed by the remote host. ---> System.Net.Sockets.SocketException: An existing connection was forcibly closed by the remote host
   at System.Net.Sockets.Socket.EndReceive(IAsyncResult asyncResult)
   at System.Net.Sockets.NetworkStream.EndRead(IAsyncResult asyncResult)
   --- End of inner exception stack trace ---
   at System.Net.ConnectStream.EndRead(IAsyncResult asyncResult)
   at System.Net.Http.HttpClientHandler.WebExceptionWrapperStream.EndRead(IAsyncResult asyncResult)
   at System.Net.Http.StreamToStreamCopy.BufferReadCallback(IAsyncResult ar)
   --- End of inner exception stack trace ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at Duplicati.Library.OAuthHttpClient.<GetAsync>d__5.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at Duplicati.Library.Backend.MicrosoftGraphBackend.Get(String remotename, Stream stream)
   at Duplicati.Library.Main.BackendManager.coreDoGetPiping(FileEntryItem item, IEncryption useDecrypter, Int64& retDownloadSize, String& retHashcode)
   at Duplicati.Library.Main.BackendManager.DoGet(FileEntryItem item)
   at Duplicati.Library.Main.BackendManager.ThreadRun()
2023-08-18 21:31:34 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Retrying: duplicati-b96dec70ea42a41029aea26991b47f29c.dblock.zip (50.00 MB)
2023-08-18 21:31:44 -04 - [Profiling-Timer.Begin-Duplicati.Library.Main.BackendManager-RemoteOperationGet]: Starting - RemoteOperationGet
2023-08-18 21:31:44 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Started: duplicati-b96dec70ea42a41029aea26991b47f29c.dblock.zip (50.00 MB)
2023-08-18 21:32:52 -04 - [Profiling-Duplicati.Library.Main.BackendManager-DownloadSpeed]: Downloaded 50.00 MB in 00:01:07.7951080, 755.21 KB/s
2023-08-18 21:32:52 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Completed: duplicati-b96dec70ea42a41029aea26991b47f29c.dblock.zip (50.00 MB)
2023-08-18 21:32:52 -04 - [Profiling-Timer.Finished-Duplicati.Library.Main.BackendManager-RemoteOperationGet]: RemoteOperationGet took 0:00:01:07.796

Second one looks like it’s more stuck. It’s been sitting for around 10 hours with a 1drv.ms connection.

2023-08-18 22:17:45 -04 - [Profiling-Timer.Begin-Duplicati.Library.Main.BackendManager-RemoteOperationGet]: Starting - RemoteOperationGet
2023-08-18 22:17:45 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Started: duplicati-b911d41fae406498eaac7d1d8a053e0e8.dblock.zip (50.00 MB)
2023-08-18 22:17:45 -04 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: Starting - ExecuteNonQuery: CREATE TEMPORARY TABLE "Blocklist-8F1C4DC173E13B43A3436188928F2D84" ("Hash" TEXT NOT NULL, "Size" INTEGER NOT NULL)
2023-08-18 22:17:45 -04 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: ExecuteNonQuery: CREATE TEMPORARY TABLE "Blocklist-8F1C4DC173E13B43A3436188928F2D84" ("Hash" TEXT NOT NULL, "Size" INTEGER NOT NULL) took 0:00:00:00.000
2023-08-18 22:17:46 -04 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: Starting - ExecuteNonQuery: CREATE TEMPORARY TABLE "CmpTable-5B6A84CBBB6CCE47988836BE6E0C05B0" AS SELECT DISTINCT "Hash" AS "Hash", "Size" AS "Size" FROM (SELECT "Block"."Hash" AS "Hash", "Block"."Size" AS "Size" FROM "Remotevolume", "Block" WHERE "Remotevolume"."Name" = "duplicati-bb8e417fdea554f3bbb920eaadc98a79b.dblock.zip" AND "Remotevolume"."ID" = "Block"."VolumeID" UNION SELECT "DeletedBlock"."Hash" AS "Hash", "DeletedBlock"."Size" AS "Size" FROM "DeletedBlock", "RemoteVolume" WHERE "RemoteVolume"."Name" = "duplicati-bb8e417fdea554f3bbb920eaadc98a79b.dblock.zip" AND "RemoteVolume"."ID" = "DeletedBlock"."VolumeID")
2023-08-18 22:17:46 -04 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: ExecuteNonQuery: CREATE TEMPORARY TABLE "CmpTable-5B6A84CBBB6CCE47988836BE6E0C05B0" AS SELECT DISTINCT "Hash" AS "Hash", "Size" AS "Size" FROM (SELECT "Block"."Hash" AS "Hash", "Block"."Size" AS "Size" FROM "Remotevolume", "Block" WHERE "Remotevolume"."Name" = "duplicati-bb8e417fdea554f3bbb920eaadc98a79b.dblock.zip" AND "Remotevolume"."ID" = "Block"."VolumeID" UNION SELECT "DeletedBlock"."Hash" AS "Hash", "DeletedBlock"."Size" AS "Size" FROM "DeletedBlock", "RemoteVolume" WHERE "RemoteVolume"."Name" = "duplicati-bb8e417fdea554f3bbb920eaadc98a79b.dblock.zip" AND "RemoteVolume"."ID" = "DeletedBlock"."VolumeID") took 0:00:00:00.000
2023-08-18 22:17:46 -04 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteReader]: Starting - ExecuteReader: SELECT 1 AS "Type", "Blocklist-8F1C4DC173E13B43A3436188928F2D84"."Hash" AS "Hash" FROM "Blocklist-8F1C4DC173E13B43A3436188928F2D84" WHERE "Blocklist-8F1C4DC173E13B43A3436188928F2D84"."Hash" NOT IN ( SELECT "Hash" FROM "CmpTable-5B6A84CBBB6CCE47988836BE6E0C05B0" ) UNION SELECT 0 AS "Type", "Hash" AS "Hash" FROM "CmpTable-5B6A84CBBB6CCE47988836BE6E0C05B0" WHERE "Hash" NOT IN (SELECT "Hash" FROM "Blocklist-8F1C4DC173E13B43A3436188928F2D84") UNION SELECT 2 AS "Type", "E"."Hash" AS "Hash" FROM "Blocklist-8F1C4DC173E13B43A3436188928F2D84" E, "CmpTable-5B6A84CBBB6CCE47988836BE6E0C05B0" D WHERE "D"."Hash" = "E"."Hash" AND "D"."Size" != "E"."Size"  
2023-08-18 22:17:46 -04 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteReader]: ExecuteReader: SELECT 1 AS "Type", "Blocklist-8F1C4DC173E13B43A3436188928F2D84"."Hash" AS "Hash" FROM "Blocklist-8F1C4DC173E13B43A3436188928F2D84" WHERE "Blocklist-8F1C4DC173E13B43A3436188928F2D84"."Hash" NOT IN ( SELECT "Hash" FROM "CmpTable-5B6A84CBBB6CCE47988836BE6E0C05B0" ) UNION SELECT 0 AS "Type", "Hash" AS "Hash" FROM "CmpTable-5B6A84CBBB6CCE47988836BE6E0C05B0" WHERE "Hash" NOT IN (SELECT "Hash" FROM "Blocklist-8F1C4DC173E13B43A3436188928F2D84") UNION SELECT 2 AS "Type", "E"."Hash" AS "Hash" FROM "Blocklist-8F1C4DC173E13B43A3436188928F2D84" E, "CmpTable-5B6A84CBBB6CCE47988836BE6E0C05B0" D WHERE "D"."Hash" = "E"."Hash" AND "D"."Size" != "E"."Size"   took 0:00:00:00.001
2023-08-18 22:17:46 -04 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: Starting - ExecuteNonQuery: DROP TABLE IF EXISTS "CmpTable-5B6A84CBBB6CCE47988836BE6E0C05B0" 
2023-08-18 22:17:46 -04 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: ExecuteNonQuery: DROP TABLE IF EXISTS "CmpTable-5B6A84CBBB6CCE47988836BE6E0C05B0"  took 0:00:00:00.000
2023-08-18 22:17:46 -04 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: Starting - ExecuteNonQuery: DROP TABLE IF EXISTS "Blocklist-8F1C4DC173E13B43A3436188928F2D84"
2023-08-18 22:17:46 -04 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: ExecuteNonQuery: DROP TABLE IF EXISTS "Blocklist-8F1C4DC173E13B43A3436188928F2D84" took 0:00:00:00.000
2023-08-18 22:17:46 -04 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: Starting - ExecuteNonQuery: UPDATE "RemoteVolume" SET "VerificationCount" = MAX(1, CASE WHEN "VerificationCount" <= 0 THEN (SELECT MAX("VerificationCount") FROM "RemoteVolume") ELSE "VerificationCount" + 1 END) WHERE "Name" = "duplicati-bb8e417fdea554f3bbb920eaadc98a79b.dblock.zip"
2023-08-18 22:17:46 -04 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: ExecuteNonQuery: UPDATE "RemoteVolume" SET "VerificationCount" = MAX(1, CASE WHEN "VerificationCount" <= 0 THEN (SELECT MAX("VerificationCount") FROM "RemoteVolume") ELSE "VerificationCount" + 1 END) WHERE "Name" = "duplicati-bb8e417fdea554f3bbb920eaadc98a79b.dblock.zip" took 0:00:00:00.138

Profiling log continues to not help hugely, but I suppose a next step is to try to set up network tracing.

ts678 · August 19, 2023, 3:14pm

I got one with network tracing added. Tracing log is huge, and I could use assist with OneDrive API.
Original developer of that work seems to not follow forum much, but if need be we could invite help.

gpatel-fr · August 19, 2023, 6:01pm

One… what ? a compact or a test ? Your trace with test (Duplicati stuck on Compact when Getting/Putting from OneDrive and results in missing files - #35 by ts678) does not seem to be ‘stuck’ (full test is very looong) so I’m not sure I see the point.

ts678 · August 19, 2023, 6:06pm

One new stuck test run – basically another repro case, except with the addition of the following:

EDIT 1:

With the download-only approach I can just backup once then go to downloads. It ran 18 minutes.
Made about 2 GB of network log, whose format I find hard to read. Not sure if we have any expert.

Early results show the last request going out, data (maybe encrypted – can’t match any of it) back.
Ordinarily the server declares completion. This time the data just ended without the completion, so whether it was a shorter-than-should-have-been download is not clear from the file of logging lines.

EDIT 2:

Information level on console, showing the last successful download, and then the one that got stuck:

Backend event: Get - Started: duplicati-b4570bef2dce040e0b9caa767bb26e68b.dblock.zip (50.00 MB)
  Downloading file (50.00 MB) ...
Backend event: Get - Completed: duplicati-b4570bef2dce040e0b9caa767bb26e68b.dblock.zip (50.00 MB)
Backend event: Get - Started: duplicati-bd4a6e4f3c82c4537a4a8572863200439.dblock.zip (50.00 MB)
  Downloading file (50.00 MB) ...

Network tracing view (only a little sanitized) of the last good one and then the one that didn’t complete.
The file is too big to go through manually, so I summarized in glogg with search for regular expression

HttpWebRequest|HttpResponseMessage

System.Net Verbose: 0 : [25300] Entering HttpWebRequest#26664328::HttpWebRequest(https://graph.microsoft.com/v1.0/me/drive/root:/Duplicati Backups/onedrive_compact/duplicati-b4570bef2dce040e0b9caa767bb26e68b.dblock.zip:/content#794160182)
System.Net Verbose: 0 : [25300] Exiting HttpWebRequest#26664328::HttpWebRequest() 
System.Net Verbose: 0 : [25300] Entering HttpWebRequest#26664328::HttpWebRequest(uri: 'https://graph.microsoft.com/v1.0/me/drive/root:/Duplicati Backups/onedrive_compact/duplicati-b4570bef2dce040e0b9caa767bb26e68b.dblock.zip:/content', connectionGroupName: '35912612')
System.Net Verbose: 0 : [25300] Exiting HttpWebRequest#26664328::HttpWebRequest() 
System.Net.Http Information: 0 : [25300] Associating HttpRequestMessage#31002743 with HttpWebRequest#26664328
System.Net Verbose: 0 : [38064] Entering HttpWebRequest#26664328::BeginGetResponse()
System.Net Information: 0 : [38064] Associating HttpWebRequest#26664328 with ServicePoint#4032828
System.Net Information: 0 : [38064] Associating Connection#33711845 with HttpWebRequest#26664328
System.Net Information: 0 : [38064] Associating HttpWebRequest#26664328 with ConnectStream#22953427
System.Net Information: 0 : [38064] HttpWebRequest#26664328 - Request: GET /v1.0/me/drive/root:/Duplicati%20Backups/onedrive_compact/duplicati-b4570bef2dce040e0b9caa767bb26e68b.dblock.zip:/content HTTP/1.1
System.Net Verbose: 0 : [38064] Exiting HttpWebRequest#26664328::BeginGetResponse() 	-> ContextAwareResult#5145064
System.Net Information: 0 : [5092] Associating HttpWebRequest#26664328 with ConnectStream#14597200
System.Net Information: 0 : [5092] Associating HttpWebRequest#26664328 with HttpWebResponse#50242601
System.Net Warning: 0 : [5092] HttpWebRequest#26664328::() - Error code 302 was received from server response.
System.Net Warning: 0 : [5092] HttpWebRequest#26664328::() - Resubmitting request.
System.Net Information: 0 : [5092] Associating HttpWebRequest#26664328 with ServicePoint#10286142
System.Net Information: 0 : [5092] Associating Connection#60223214 with HttpWebRequest#26664328
System.Net Information: 0 : [5092] Associating HttpWebRequest#26664328 with ConnectStream#43475050
System.Net Information: 0 : [5092] HttpWebRequest#26664328 - Request: GET /.../duplicati-b4570bef2dce040e0b9caa767bb26e68b.dblock.zip HTTP/1.1
System.Net Information: 0 : [5092] Associating HttpWebRequest#26664328 with ConnectStream#65537674
System.Net Information: 0 : [5092] Associating HttpWebRequest#26664328 with HttpWebResponse#13236156
System.Net Verbose: 0 : [5092] Entering HttpWebRequest#26664328::EndGetResponse()
System.Net Verbose: 0 : [5092] Exiting HttpWebRequest#26664328::EndGetResponse() 	-> HttpWebResponse#13236156
2023-08-19T13:56:18.4078862Z System.Net.Http Verbose: 0 : [5092] Entering HttpResponseMessage#12551126::.ctor(StatusCode: 200, ReasonPhrase: '')
2023-08-19T14:12:41.4932814Z System.Net.Http Verbose: 0 : [5092] Exiting HttpResponseMessage#12551126::.ctor() 
2023-08-19T14:12:41.4932814Z System.Net.Http Information: 0 : [5092] Associating HttpResponseMessage#12551126 with HttpRequestMessage#31002743
2023-08-19T14:12:41.4932814Z System.Net.Http Information: 0 : [5092] Associating HttpResponseMessage#12551126 with StreamContent#26912652
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:

Times manually added when it started to get interesting. Lots of data on a socket prior to last line.
Hung one looked similar except never got to the last line – the server completed successfully.

System.Net Verbose: 0 : [25300] Entering HttpWebRequest#31418307::HttpWebRequest(https://graph.microsoft.com/v1.0/me/drive/root:/Duplicati Backups/onedrive_compact/duplicati-bd4a6e4f3c82c4537a4a8572863200439.dblock.zip:/content#-695925059)
System.Net Verbose: 0 : [25300] Exiting HttpWebRequest#31418307::HttpWebRequest() 
System.Net Verbose: 0 : [25300] Entering HttpWebRequest#31418307::HttpWebRequest(uri: 'https://graph.microsoft.com/v1.0/me/drive/root:/Duplicati Backups/onedrive_compact/duplicati-bd4a6e4f3c82c4537a4a8572863200439.dblock.zip:/content', connectionGroupName: '35912612')
System.Net Verbose: 0 : [25300] Exiting HttpWebRequest#31418307::HttpWebRequest() 
System.Net.Http Information: 0 : [25300] Associating HttpRequestMessage#10339784 with HttpWebRequest#31418307
System.Net Verbose: 0 : [26524] Entering HttpWebRequest#31418307::BeginGetResponse()
System.Net Information: 0 : [26524] Associating HttpWebRequest#31418307 with ServicePoint#4032828
System.Net Information: 0 : [26524] Associating Connection#33711845 with HttpWebRequest#31418307
System.Net Information: 0 : [26524] Associating HttpWebRequest#31418307 with ConnectStream#38126477
System.Net Information: 0 : [26524] HttpWebRequest#31418307 - Request: GET /v1.0/me/drive/root:/Duplicati%20Backups/onedrive_compact/duplicati-bd4a6e4f3c82c4537a4a8572863200439.dblock.zip:/content HTTP/1.1
System.Net Verbose: 0 : [26524] Exiting HttpWebRequest#31418307::BeginGetResponse() 	-> ContextAwareResult#5181569
System.Net Information: 0 : [33500] Associating HttpWebRequest#31418307 with ConnectStream#41720639
System.Net Information: 0 : [33500] Associating HttpWebRequest#31418307 with HttpWebResponse#32824616
System.Net Warning: 0 : [33500] HttpWebRequest#31418307::() - Error code 302 was received from server response.
System.Net Warning: 0 : [33500] HttpWebRequest#31418307::() - Resubmitting request.
System.Net Information: 0 : [33500] Associating HttpWebRequest#31418307 with ServicePoint#10286142
System.Net Information: 0 : [33500] Associating Connection#60223214 with HttpWebRequest#31418307
System.Net Information: 0 : [33500] Associating HttpWebRequest#31418307 with ConnectStream#3631988
System.Net Information: 0 : [33500] HttpWebRequest#31418307 - Request: GET /.../duplicati-bd4a6e4f3c82c4537a4a8572863200439.dblock.zip HTTP/1.1
System.Net Information: 0 : [33500] Associating HttpWebRequest#31418307 with ConnectStream#65575460
System.Net Information: 0 : [33500] Associating HttpWebRequest#31418307 with HttpWebResponse#4239330
System.Net Verbose: 0 : [33500] Entering HttpWebRequest#31418307::EndGetResponse()
System.Net Verbose: 0 : [33500] Exiting HttpWebRequest#31418307::EndGetResponse() 	-> HttpWebResponse#4239330
System.Net.Http Verbose: 0 : [33500] Entering HttpResponseMessage#39594807::.ctor(StatusCode: 200, ReasonPhrase: '')
System.Net.Http Verbose: 0 : [33500] Exiting HttpResponseMessage#39594807::.ctor() 
System.Net.Http Information: 0 : [33500] Associating HttpResponseMessage#39594807 with HttpRequestMessage#10339784
System.Net.Http Information: 0 : [33500] Associating HttpResponseMessage#39594807 with StreamContent#12774356

Profiling log continues to not provided any additional insights, but here’s how this test run ended:

2023-08-19 10:12:35 -04 - [Profiling-Timer.Begin-Duplicati.Library.Main.BackendManager-RemoteOperationGet]: Starting - RemoteOperationGet
2023-08-19 10:12:35 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Started: duplicati-b4570bef2dce040e0b9caa767bb26e68b.dblock.zip (50.00 MB)
2023-08-19 10:12:35 -04 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: Starting - ExecuteNonQuery: CREATE TEMPORARY TABLE "Blocklist-5EB8686F3E849640B0B35526A3E27D1A" ("Hash" TEXT NOT NULL, "Size" INTEGER NOT NULL)
2023-08-19 10:12:35 -04 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: ExecuteNonQuery: CREATE TEMPORARY TABLE "Blocklist-5EB8686F3E849640B0B35526A3E27D1A" ("Hash" TEXT NOT NULL, "Size" INTEGER NOT NULL) took 0:00:00:00.000
2023-08-19 10:12:36 -04 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: Starting - ExecuteNonQuery: CREATE TEMPORARY TABLE "CmpTable-A2BF75B10546C34F9D1B214D86A48315" AS SELECT DISTINCT "Hash" AS "Hash", "Size" AS "Size" FROM (SELECT "Block"."Hash" AS "Hash", "Block"."Size" AS "Size" FROM "Remotevolume", "Block" WHERE "Remotevolume"."Name" = "duplicati-bc696e9aaaed14c70ad63a59890516a9c.dblock.zip" AND "Remotevolume"."ID" = "Block"."VolumeID" UNION SELECT "DeletedBlock"."Hash" AS "Hash", "DeletedBlock"."Size" AS "Size" FROM "DeletedBlock", "RemoteVolume" WHERE "RemoteVolume"."Name" = "duplicati-bc696e9aaaed14c70ad63a59890516a9c.dblock.zip" AND "RemoteVolume"."ID" = "DeletedBlock"."VolumeID")
2023-08-19 10:12:36 -04 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: ExecuteNonQuery: CREATE TEMPORARY TABLE "CmpTable-A2BF75B10546C34F9D1B214D86A48315" AS SELECT DISTINCT "Hash" AS "Hash", "Size" AS "Size" FROM (SELECT "Block"."Hash" AS "Hash", "Block"."Size" AS "Size" FROM "Remotevolume", "Block" WHERE "Remotevolume"."Name" = "duplicati-bc696e9aaaed14c70ad63a59890516a9c.dblock.zip" AND "Remotevolume"."ID" = "Block"."VolumeID" UNION SELECT "DeletedBlock"."Hash" AS "Hash", "DeletedBlock"."Size" AS "Size" FROM "DeletedBlock", "RemoteVolume" WHERE "RemoteVolume"."Name" = "duplicati-bc696e9aaaed14c70ad63a59890516a9c.dblock.zip" AND "RemoteVolume"."ID" = "DeletedBlock"."VolumeID") took 0:00:00:00.000
2023-08-19 10:12:36 -04 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteReader]: Starting - ExecuteReader: SELECT 1 AS "Type", "Blocklist-5EB8686F3E849640B0B35526A3E27D1A"."Hash" AS "Hash" FROM "Blocklist-5EB8686F3E849640B0B35526A3E27D1A" WHERE "Blocklist-5EB8686F3E849640B0B35526A3E27D1A"."Hash" NOT IN ( SELECT "Hash" FROM "CmpTable-A2BF75B10546C34F9D1B214D86A48315" ) UNION SELECT 0 AS "Type", "Hash" AS "Hash" FROM "CmpTable-A2BF75B10546C34F9D1B214D86A48315" WHERE "Hash" NOT IN (SELECT "Hash" FROM "Blocklist-5EB8686F3E849640B0B35526A3E27D1A") UNION SELECT 2 AS "Type", "E"."Hash" AS "Hash" FROM "Blocklist-5EB8686F3E849640B0B35526A3E27D1A" E, "CmpTable-A2BF75B10546C34F9D1B214D86A48315" D WHERE "D"."Hash" = "E"."Hash" AND "D"."Size" != "E"."Size"  
2023-08-19 10:12:36 -04 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteReader]: ExecuteReader: SELECT 1 AS "Type", "Blocklist-5EB8686F3E849640B0B35526A3E27D1A"."Hash" AS "Hash" FROM "Blocklist-5EB8686F3E849640B0B35526A3E27D1A" WHERE "Blocklist-5EB8686F3E849640B0B35526A3E27D1A"."Hash" NOT IN ( SELECT "Hash" FROM "CmpTable-A2BF75B10546C34F9D1B214D86A48315" ) UNION SELECT 0 AS "Type", "Hash" AS "Hash" FROM "CmpTable-A2BF75B10546C34F9D1B214D86A48315" WHERE "Hash" NOT IN (SELECT "Hash" FROM "Blocklist-5EB8686F3E849640B0B35526A3E27D1A") UNION SELECT 2 AS "Type", "E"."Hash" AS "Hash" FROM "Blocklist-5EB8686F3E849640B0B35526A3E27D1A" E, "CmpTable-A2BF75B10546C34F9D1B214D86A48315" D WHERE "D"."Hash" = "E"."Hash" AND "D"."Size" != "E"."Size"   took 0:00:00:00.002
2023-08-19 10:12:36 -04 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: Starting - ExecuteNonQuery: DROP TABLE IF EXISTS "CmpTable-A2BF75B10546C34F9D1B214D86A48315" 
2023-08-19 10:12:36 -04 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: ExecuteNonQuery: DROP TABLE IF EXISTS "CmpTable-A2BF75B10546C34F9D1B214D86A48315"  took 0:00:00:00.000
2023-08-19 10:12:36 -04 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: Starting - ExecuteNonQuery: DROP TABLE IF EXISTS "Blocklist-5EB8686F3E849640B0B35526A3E27D1A"
2023-08-19 10:12:36 -04 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: ExecuteNonQuery: DROP TABLE IF EXISTS "Blocklist-5EB8686F3E849640B0B35526A3E27D1A" took 0:00:00:00.000
2023-08-19 10:12:36 -04 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: Starting - ExecuteNonQuery: UPDATE "RemoteVolume" SET "VerificationCount" = MAX(1, CASE WHEN "VerificationCount" <= 0 THEN (SELECT MAX("VerificationCount") FROM "RemoteVolume") ELSE "VerificationCount" + 1 END) WHERE "Name" = "duplicati-bc696e9aaaed14c70ad63a59890516a9c.dblock.zip"
2023-08-19 10:12:36 -04 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: ExecuteNonQuery: UPDATE "RemoteVolume" SET "VerificationCount" = MAX(1, CASE WHEN "VerificationCount" <= 0 THEN (SELECT MAX("VerificationCount") FROM "RemoteVolume") ELSE "VerificationCount" + 1 END) WHERE "Name" = "duplicati-bc696e9aaaed14c70ad63a59890516a9c.dblock.zip" took 0:00:00:00.069
2023-08-19 10:12:56 -04 - [Profiling-Duplicati.Library.Main.BackendManager-DownloadSpeed]: Downloaded 50.00 MB in 00:00:20.2557447, 2.47 MB/s
2023-08-19 10:12:56 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Completed: duplicati-b4570bef2dce040e0b9caa767bb26e68b.dblock.zip (50.00 MB)
2023-08-19 10:12:56 -04 - [Profiling-Timer.Finished-Duplicati.Library.Main.BackendManager-RemoteOperationGet]: RemoteOperationGet took 0:00:00:20.255
2023-08-19 10:12:56 -04 - [Profiling-Timer.Begin-Duplicati.Library.Main.BackendManager-RemoteOperationGet]: Starting - RemoteOperationGet
2023-08-19 10:12:56 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Started: duplicati-bd4a6e4f3c82c4537a4a8572863200439.dblock.zip (50.00 MB)
2023-08-19 10:12:56 -04 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: Starting - ExecuteNonQuery: CREATE TEMPORARY TABLE "Blocklist-337E9547AF02DB4BB06B9594D50DE694" ("Hash" TEXT NOT NULL, "Size" INTEGER NOT NULL)
2023-08-19 10:12:56 -04 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: ExecuteNonQuery: CREATE TEMPORARY TABLE "Blocklist-337E9547AF02DB4BB06B9594D50DE694" ("Hash" TEXT NOT NULL, "Size" INTEGER NOT NULL) took 0:00:00:00.000
2023-08-19 10:12:56 -04 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: Starting - ExecuteNonQuery: CREATE TEMPORARY TABLE "CmpTable-C7958754B9D50742B31D54BA5AE849C8" AS SELECT DISTINCT "Hash" AS "Hash", "Size" AS "Size" FROM (SELECT "Block"."Hash" AS "Hash", "Block"."Size" AS "Size" FROM "Remotevolume", "Block" WHERE "Remotevolume"."Name" = "duplicati-b4570bef2dce040e0b9caa767bb26e68b.dblock.zip" AND "Remotevolume"."ID" = "Block"."VolumeID" UNION SELECT "DeletedBlock"."Hash" AS "Hash", "DeletedBlock"."Size" AS "Size" FROM "DeletedBlock", "RemoteVolume" WHERE "RemoteVolume"."Name" = "duplicati-b4570bef2dce040e0b9caa767bb26e68b.dblock.zip" AND "RemoteVolume"."ID" = "DeletedBlock"."VolumeID")
2023-08-19 10:12:56 -04 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: ExecuteNonQuery: CREATE TEMPORARY TABLE "CmpTable-C7958754B9D50742B31D54BA5AE849C8" AS SELECT DISTINCT "Hash" AS "Hash", "Size" AS "Size" FROM (SELECT "Block"."Hash" AS "Hash", "Block"."Size" AS "Size" FROM "Remotevolume", "Block" WHERE "Remotevolume"."Name" = "duplicati-b4570bef2dce040e0b9caa767bb26e68b.dblock.zip" AND "Remotevolume"."ID" = "Block"."VolumeID" UNION SELECT "DeletedBlock"."Hash" AS "Hash", "DeletedBlock"."Size" AS "Size" FROM "DeletedBlock", "RemoteVolume" WHERE "RemoteVolume"."Name" = "duplicati-b4570bef2dce040e0b9caa767bb26e68b.dblock.zip" AND "RemoteVolume"."ID" = "DeletedBlock"."VolumeID") took 0:00:00:00.001
2023-08-19 10:12:56 -04 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteReader]: Starting - ExecuteReader: SELECT 1 AS "Type", "Blocklist-337E9547AF02DB4BB06B9594D50DE694"."Hash" AS "Hash" FROM "Blocklist-337E9547AF02DB4BB06B9594D50DE694" WHERE "Blocklist-337E9547AF02DB4BB06B9594D50DE694"."Hash" NOT IN ( SELECT "Hash" FROM "CmpTable-C7958754B9D50742B31D54BA5AE849C8" ) UNION SELECT 0 AS "Type", "Hash" AS "Hash" FROM "CmpTable-C7958754B9D50742B31D54BA5AE849C8" WHERE "Hash" NOT IN (SELECT "Hash" FROM "Blocklist-337E9547AF02DB4BB06B9594D50DE694") UNION SELECT 2 AS "Type", "E"."Hash" AS "Hash" FROM "Blocklist-337E9547AF02DB4BB06B9594D50DE694" E, "CmpTable-C7958754B9D50742B31D54BA5AE849C8" D WHERE "D"."Hash" = "E"."Hash" AND "D"."Size" != "E"."Size"  
2023-08-19 10:12:56 -04 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteReader]: ExecuteReader: SELECT 1 AS "Type", "Blocklist-337E9547AF02DB4BB06B9594D50DE694"."Hash" AS "Hash" FROM "Blocklist-337E9547AF02DB4BB06B9594D50DE694" WHERE "Blocklist-337E9547AF02DB4BB06B9594D50DE694"."Hash" NOT IN ( SELECT "Hash" FROM "CmpTable-C7958754B9D50742B31D54BA5AE849C8" ) UNION SELECT 0 AS "Type", "Hash" AS "Hash" FROM "CmpTable-C7958754B9D50742B31D54BA5AE849C8" WHERE "Hash" NOT IN (SELECT "Hash" FROM "Blocklist-337E9547AF02DB4BB06B9594D50DE694") UNION SELECT 2 AS "Type", "E"."Hash" AS "Hash" FROM "Blocklist-337E9547AF02DB4BB06B9594D50DE694" E, "CmpTable-C7958754B9D50742B31D54BA5AE849C8" D WHERE "D"."Hash" = "E"."Hash" AND "D"."Size" != "E"."Size"   took 0:00:00:00.001
2023-08-19 10:12:56 -04 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: Starting - ExecuteNonQuery: DROP TABLE IF EXISTS "CmpTable-C7958754B9D50742B31D54BA5AE849C8" 
2023-08-19 10:12:56 -04 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: ExecuteNonQuery: DROP TABLE IF EXISTS "CmpTable-C7958754B9D50742B31D54BA5AE849C8"  took 0:00:00:00.000
2023-08-19 10:12:56 -04 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: Starting - ExecuteNonQuery: DROP TABLE IF EXISTS "Blocklist-337E9547AF02DB4BB06B9594D50DE694"
2023-08-19 10:12:56 -04 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: ExecuteNonQuery: DROP TABLE IF EXISTS "Blocklist-337E9547AF02DB4BB06B9594D50DE694" took 0:00:00:00.000
2023-08-19 10:12:56 -04 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: Starting - ExecuteNonQuery: UPDATE "RemoteVolume" SET "VerificationCount" = MAX(1, CASE WHEN "VerificationCount" <= 0 THEN (SELECT MAX("VerificationCount") FROM "RemoteVolume") ELSE "VerificationCount" + 1 END) WHERE "Name" = "duplicati-b4570bef2dce040e0b9caa767bb26e68b.dblock.zip"
2023-08-19 10:12:56 -04 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: ExecuteNonQuery: UPDATE "RemoteVolume" SET "VerificationCount" = MAX(1, CASE WHEN "VerificationCount" <= 0 THEN (SELECT MAX("VerificationCount") FROM "RemoteVolume") ELSE "VerificationCount" + 1 END) WHERE "Name" = "duplicati-b4570bef2dce040e0b9caa767bb26e68b.dblock.zip" took 0:00:00:00.088

gpatel-fr · August 19, 2023, 6:45pm

If it ended just like that, it is hanging in a Get indeed:

2023-08-19 10:12:56 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Started: duplicati-bd4a6e4f3c82c4537a4a8572863200439.dblock.zip (50.00 MB)

strange that there is no timeout. I suspect that OAuth could be a problem here (I see 302 redirects in your traces). If the OP switched from a Beta to the last one, there were a few changes in OAuth. AFAIK there was no change at all in OneDrive library.

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…