Release: 2.1.0.104 (Canary) 2024-12-31

kenkendk · December 31, 2024, 5:31pm

2.1.0.104_canary_2024-12-31

This release is a canary release intended to be used for testing.

Note that this build is using .NET8, unlike the 2.0.8.1 build

Note that this build has a redesigned restore flow
Should issues arise, the previous restore engine can be enabled with --restore-legacy=true.

Detailed list of changes:

Fixed issue with launchAgent for CLI server not taking an argument
Added simultaneous file processors, thanks @gpatel-fr
Updated translations, thansk to many contributors!
Added NOOP Daemon for FTP backend
Excluded Google Drive and GCS from timeout streams
Fixed an issue with the TrayIcon being disconnected after 15 minutes
Removed the captcha fro full backup removal
Reduced number of backend instances created
Removed Windows-only options on the File backend on non-Windows
Added option to log FTP messages to regular log

ollibraun · January 1, 2025, 4:10pm

Thank you for the new version, and a happy new year 2025. Unfortunately, the Windows service is not working for me. Version 2.1.0.102 works, but .103 and .104 do not.

MSIexec /i duplicati-2.1.0.104_canary_2024-12-31-win-x64-gui.msi FORSERVICE=true ADDLOCAL=ALL REMOVE=DuplicatiDesktopShortCutFeature,DuplicatiProgramMenuShortCutFeature,DuplicatiStartupShortCutFeature /Quiet

"C:\Program Files\Duplicati 2\Duplicati.WindowsService.exe" install --log-retention=1D --server-datafolder=%ALLUSERSPROFILE%\Duplicati --disable-db-encryption --webservice-password=password
Duplicati service installation failed. Exception: Win32 error 1073 during install service (CreateService)

In the event log, I have two entries:

Application: Duplicati.WindowsService.exe
CoreCLR Version: 8.0.624.26715
.NET Version: 8.0.6
Description: The process was terminated due to an unhandled exception.
Exception Info: System.ArgumentException: Log Duplicati 2 has already been registered as a source on the local computer.
   at System.Diagnostics.EventLog.CreateEventSource(EventSourceCreationData sourceData)
   at Duplicati.WindowsService.ServiceControl..ctor(String[] args, NamedExecutable executable)
   at Duplicati.WindowsService.Program.Main(String[] args)
   at Duplicati.WindowsService.Net8.Program.<>c__DisplayClass0_0.<Main>b__0()
   at Duplicati.Library.Crashlog.CrashlogHelper.WrapWithCrashLog[T](Func`1 method, String logdir, String applicationName)
   at Duplicati.WindowsService.Net8.Program.Main(String[] args)


Fehlerhafter Anwendungsname: Duplicati.WindowsService.exe, Version: 2.1.0.104, Zeitstempel: 0x66470000
Fehlerhafter Modulname: KERNELBASE.dll, Version: 10.0.27764.1000, Zeitstempel: 0xed180e69
Ausnahmecode: 0xe0434352
Fehleroffset: 0x00000000000ce2bc
Fehlerhafte Prozess-ID: 0x69D4
Fehlerhafte Anwendungsstartzeit: 0x1DB5C66AC127AF8
Fehlerhafter Anwendungspfad: C:\Program Files\Duplicati 2\Duplicati.WindowsService.exe
Fehlerhafter Modulpfad: C:\WINDOWS\System32\KERNELBASE.dll
Berichts-ID: 6775bbb0-bf54-4a1d-91b7-80a8e36d20db
Vollständiger Name des fehlerhaften Pakets: 
Fehlerhafte paketbezogene Anwendungs-ID:

Fehlerbucket 0, Typ 4
Ereignisname: APPCRASH
Antwort: Nicht verfügbar
CAB-Datei-ID: 0

Problemsignatur:
P1: Duplicati.WindowsService.exe
P2: 2.1.0.104
P3: 66470000
P4: KERNELBASE.dll
P5: 10.0.27764.1000
P6: ed180e69
P7: e0434352
P8: 00000000000ce2bc
P9: 
P10: 

Angefügte Dateien:
\\?\C:\ProgramData\Microsoft\Windows\WER\Temp\WER.c684a50c-a720-44b5-bcca-59c1d2b43f57.tmp.dmp
\\?\C:\ProgramData\Microsoft\Windows\WER\Temp\WER.757c7a6a-5abe-4715-bf75-775ada7f680d.tmp.WERInternalMetadata.xml
\\?\C:\ProgramData\Microsoft\Windows\WER\Temp\WER.68646407-7e0b-4dff-afc1-470061bcdc2a.tmp.csv
\\?\C:\ProgramData\Microsoft\Windows\WER\Temp\WER.fc70496e-c53a-41fd-8156-ea645371852b.tmp.txt
\\?\C:\ProgramData\Microsoft\Windows\WER\Temp\WER.abe2346b-6989-495d-825d-bae645877314.tmp.xml

Diese Dateien befinden sich möglicherweise hier:
\\?\C:\ProgramData\Microsoft\Windows\WER\ReportArchive\AppCrash_Duplicati.Window_735016c6443ba5c5fa473c7b1af57b2d9eea75_b0a7d6fe_486735d3-7c1d-497a-a393-b5caef6f75ba

Analysesymbol: 
Es wird erneut nach einer Lösung gesucht: 0
Berichts-ID: 6775bbb0-bf54-4a1d-91b7-80a8e36d20db
Berichtstatus: 268435456
Bucket mit Hash: b622e08f422e2c81acd6177930e9857e
CAB-Datei-Guid: 0

kenkendk · January 1, 2025, 4:14pm

I assume you have not created this source yourself?
Previous Duplicati would create a source named “Duplicati” and for that reason the new version uses a log named “Duplicati 2”.

The error indicates that there is a source named “Duplicati 2”, which I don’t understand the reason for.

You can manually work around it with Power Shell as Administrator:

Remove-EventLog -Source "Duplicati 2"

After this, you should be able to run the install command again.
If it works, could you please try to uninstall and install again, to see if it is a problem with Duplicati not detecting the existing log?

ollibraun · January 1, 2025, 6:02pm

Thank you very much for the quick feedback. This may be due to the installation of new Canary versions and also switching back in the last few months.

I deliberately didn’t create a source with any name, I don’t even know how to do that.

In a first test, the installation worked after the Powershell command. But I’ll have another look at it in the next few days.

Taomyn · January 2, 2025, 10:04am

Happy New Year. I upgraded all my .103 to .104 yesterday and all seemed fine. However, this morning one of my machines, 32bit RPi-4, was stuck on a job for over 9 hours and nothing seemed to be progressing.

It’s 10:58 at the moment I took the above screenshot and this is a very small backup normally. There are two other jobs that run just before it and they both ran without issue.

I tried the Stop button choosing terminate, and here’s something I’ve meant to query - why doesn’t this ever work, at least for me? Anyway, it doesn’t have any effect even after about 30min.

Other than a high load average which I cannot see the cause for, nothing else is looking bad:

Any ideas before I restart the service or the RPi itself?

ts678 · January 2, 2025, 5:50pm

This is more of a Linux topic, but your 24.6 wa is probably processes in D state, raising that.
Perhaps you can find some way to sort by state. If that fails, start with a ps -e -ostate,args

Taomyn · January 2, 2025, 6:09pm

I checked with htop as I worked out how to sort by state and it showed me that the Zabbix agent had many of those:

I stopped the service and they went away but nothing has changed, duplicati remains stuck

Although, it remains as the only D state now:

ts678 · January 2, 2025, 6:21pm

I don’t generally look at the state, but FWIW the duplicati-server I just started is in S state.
I don’t know if D might mean waiting for disk I/O. You could get its PID to fish with lsof -p.

# lsof -p12903 | grep -v /usr/lib

for example, assuming there’s nothing of interest in /usr/lib besides Duplicati executables.
The only sqlite, temp file, or destination I get is the server database and a nearby lock file.

Taomyn · January 2, 2025, 8:36pm

I ran lsof against the PID of the duplicati server and it comes back empty. I also checked the destination, a Windows SMB share, and there are no open file handles coming from the the machine. I then tried to dismount the SMB share and get this:

root@OTTO:/home/pi# umount //192.168.1.30/OTTO
umount: /srv/smb: target is busy.

This turned out to be the Zabbix agent as I have a check of the mount to alert me of any problems. I then stopped the agent and tried the umount again but it was still busy - lsof showed nothing. I tried a few different grep on lsof and nothing seemed to be using the SMB mount, yet the OS would not let me umount it.

So for now, I have restarted the machine - it never came back until I bounced the power. I reran the same backup job and it completed just fine. Very strange, but it’s not the first time as I’m sure this has happened before on another machine but it was a long time ago.

Taomyn · January 2, 2025, 8:39pm

Is this a bug? Running backups and repair updates the screen correctly, but the verify was stayed like this after it finished according to the log until I refreshed:

ts678 · January 2, 2025, 8:59pm

Assuming you mean the status bar still saying Verifying files, it’s similar to my report that:

and the conclusion seemed inconclusive. Next time, maybe you can look at the browser traffic.

is the last word for my report, so sounds like possibly the fixes so far have not resolved that bug.

kenkendk · January 3, 2025, 4:52pm

It has been broken for a long time, because it was originally implemented with thread interrupts, but this failed due to a lot of the code using tasks that are not bound to threads.

For 2.1.0.104 I have made most of the code use CancellationToken, so it should work better, but it is a cooperative stop. If the code hangs, it will never check for the stop.

My long-term plan to fix it is to have interprocess communication so we can run the backends in isolated processes and stop the process from the OS.

From the logs messages I can see that it has done CommitUpdateRemoteVolume and then it should do CommitAfterUpload, but that does not happen.

This indicates that it is stuck in FlushBackend which really just waits for the uploads to complete. But from the logs, it is obvious that the transfer is already completed, so there is nothing to wait for.

I will have a look.

It looks very much like there is a race somewhere in the server/UI where it does not get the last report in the correct state.

ts678 · January 4, 2025, 2:54pm

Got a red popup error titled “Error while running <job name>” with the popup contents saying:

Unable to find log in lookup table, this may be caused by attempting to transport call contexts between AppDomains (e.g. with remoting calls)

About → Show log → Stored

Jan 4, 2025 7:39 AM: Failed while executing Backup "<job name>" (id: 1)
System.Exception: Unable to find log in lookup table, this may be caused by attempting to transport call contexts between AppDomains (e.g. with remoting calls)
   at Duplicati.Library.Logging.Log.get_CurrentScope()
   at Duplicati.Library.Logging.Log.CloseScope(LogScope scope)
   at Duplicati.Library.Logging.LogScope.Dispose()
   at Duplicati.Server.Runner.Run(IRunnerData data, Boolean fromQueue)

Job log completed successfully, but time of error looks like when the run-script-after finished.

The run-script-after does some tests, leaving logs. The last file timestamps were at 7:39:15.

Profiling log shows usual end-of-backup-itself, but not the later error or end of full operation.

2025-01-04 07:25:05 -05 - [Profiling-Timer.Finished-Duplicati.Library.Main.Controller-RunBackup]: Running Backup took 0:00:05:02.550

Server log end:

2025-01-04 07:25:05 -05 - [Profiling-Timer.Finished-Duplicati.Library.Main.Controller-RunBackup]: Running Backup took 0:00:05:02.550

Status bar and Server state properties look like the backup operation has completed though.

Early morning weirdness on PC wake (or at least first Duplicati use) was a Connection lost

Connection to server was rejected due to invalid authentication.

Log in again, or re-open the page from the TrayIcon (if applicable)

If it’s relevant, this one (not yet fixed) is at http://localhost:8200/ngax/index.html#/log/1

Console which launched Duplicati kept nice and quiet yesterday, but now has this and more:

fail: Microsoft.AspNetCore.Server.Kestrel[13]
      Connection id "0HN9BVKTBTP75", Request id "0HN9BVKTBTP75:0000002F": An unhandled exception was thrown by the application.
      Duplicati.WebserverCore.Exceptions.UnauthorizedException: Token family not found
         at Duplicati.WebserverCore.Middlewares.JWTTokenProvider.ValidateAccessToken(TokenValidatedContext context, ITokenFamilyStore store)
         at Microsoft.AspNetCore.Authentication.JwtBearer.JwtBearerHandler.HandleAuthenticateAsync()
         at Microsoft.AspNetCore.Authentication.JwtBearer.JwtBearerHandler.HandleAuthenticateAsync()
         at Microsoft.AspNetCore.Authentication.AuthenticationHandler`1.AuthenticateAsync()
         at Microsoft.AspNetCore.Authentication.AuthenticationService.AuthenticateAsync(HttpContext context, String scheme)
         at Microsoft.AspNetCore.Authentication.AuthenticationMiddleware.Invoke(HttpContext context)
         at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.HttpProtocol.ProcessRequests[TContext](IHttpApplication`1 application)

These are in the Application event log, but whatever happened at 7:39 is not (that I could find).

EDIT:

The logout might just be the usual old problem still hanging around. I think I have four tabs, and

Release: 2.0.9.107 (Canary) 2024-09-11 talks about how Duplicati tends to do this around then.

A tab was http://localhost:8200/ngax/index.html#/log which is live log. I copied by Ctrl-A
Top entry was “Jan 3, 2025 8:17 PM: The operation List has completed”. In server log, it may be

2025-01-03 20:17:04 -05 - [Information-Duplicati.Library.Main.Controller-CompletedOperation]: The operation List has completed
2025-01-04 07:20:02 -05 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation Backup has started

where one also sees the scheduled backup starting. The above description says how that ended.
This TrayIcon started at 8:47:37 AM 1/3/2025. Not sure what else to add. I’ll leave it up for awhile.

kenkendk · January 6, 2025, 2:13pm

ts678:

About → Show log → Stored

Jan 4, 2025 7:39 AM: Failed while executing Backup "<job name>" (id: 1)
System.Exception: Unable to find log in lookup table, this may be caused by attempting to transport call contexts between AppDomains (e.g. with remoting calls)
   at Duplicati.Library.Logging.Log.get_CurrentScope()
   at Duplicati.Library.Logging.Log.CloseScope(LogScope scope)
   at Duplicati.Library.Logging.LogScope.Dispose()
   at Duplicati.Server.Runner.Run(IRunnerData data, Boolean fromQueue)

Job log completed successfully, but time of error looks like when the run-script-after finished.

It could be some kind of race in the shutdown. The error message indicates that the log itself has been removed (so there is no where the log messages can go). But the call stack looks like the call originates from the log dispose call, which is shutting it down .

ts678 · January 6, 2025, 2:27pm

I guess I can try to see if I can get it again. Which sort of logs are these? I’m probably running the automatic default log that the job log shows, and a server log, and a job log, and maybe old live…

kenkendk · January 6, 2025, 3:28pm

The logs here are (most likely) the backup job logs that are closed as the job is done.

ts678 · January 6, 2025, 7:37pm

It turned out I didn’t have to do anything, as my scheduled backups on Jan 5 and 6 failed too:

I think some of my tabs reconnected on their own, and I did Dismiss the red popup notification.
Maybe I’ll wait a little longer in case there’s something else that can be gleaned from this case.

EDIT 1:

Stacks are different. Original looks like on the way out. Next two on the way in. Nothing in logs, including the Application event log.

EDIT 2:

Since scheduled backups failed reliably, I tried one manually with breakpoint at StartScope.
	
Looking further got stack below, and it's about to throw new ArgumentNullException("entry");

>	Duplicati.Library.Logging.dll!Duplicati.Library.Logging.FunctionLogDestination.FunctionLogDestination(System.Action<Duplicati.Library.Logging.LogEntry> entry) (IL≈0x0016, Native=0x00007FFED807D280+0x83)
 	Duplicati.Library.Logging.dll!Duplicati.Library.Logging.Log.StartScope(System.Action<Duplicati.Library.Logging.LogEntry> log, System.Func<Duplicati.Library.Logging.LogEntry, bool> filter) (IL≈0x0000, Native=0x00007FFED807D160+0x4C)
 	Duplicati.Library.RestAPI.dll!Duplicati.Server.Runner.Run(Duplicati.Server.Runner.IRunnerData data, bool fromQueue) (IL≈0x016D, Native=0x00007FFED81398C0+0x78D)
 	Duplicati.Server.Implementation.dll!Duplicati.Server.Program.<>c.<SetWorkerThread>b__62_0(Duplicati.Server.Runner.IRunnerData x) (IL=epilog, Native=0x00007FFE66506300+0x21)
 	Duplicati.Library.Utility.dll!Duplicati.Library.Utility.WorkerThread<Duplicati.Server.Runner.IRunnerData>.Runner() (IL≈0x0191, Native=0x00007FFE664F24D0+0x503)
 	System.Private.CoreLib.dll!System.Threading.ExecutionContext.RunInternal(System.Threading.ExecutionContext executionContext, System.Threading.ContextCallback callback, object state) (IL≈0x0040, Native=0x00007FFEC1246420+0x7D)
 	[Native to Managed Transition]

kenkendk · January 10, 2025, 4:59pm

I managed to reproduce this by accident today. It seems to happen when two threads are setting up scopes. In this case, there can be cases where the log-scopes are not correctly following their parent scopes. When it is time to shut down, there is a single log statement (the “CompletedOperation” message) that is logged after the inner log scope is disposed.

For most cases this works fine, but there is something weird happening with multi-threaded scope usage that I have not been able to figure out.

I have added an issue with details of what I managed to figure out:

github.com/duplicati/duplicati

Multi-threaded log-scoping does not work correctly

opened 04:58PM - 10 Jan 25 UTC

kenkendk

bug

With the log scopes in Duplicati, the idea is to use the call context, to avoid …cluttering the code with references to the current log. This works with `AsyncLocal` keeping track of the current scope. When a new scope is created, it will reference the parent: ``` Current = RootScope CreateScope(): Scope = new Scope() Scope.Parent = Current Current = Scope CloseScope(): Current = Current.Parent ``` In normal cases this will create a chain: ``` Root -> Scope1 -> Scope2 -> Scope3 ``` Disposing the scope, jumps "up" one scope. But for multithreading, it is a bit different: ``` Root -> Scope1 -> Scope2 -> Scope3 -> Scope4 -> Scope5 ``` What seems to happen is that code such as this: ``` using (CreateScope()) // Scope1 { Log("1"); using (CreateScope()) // Scope2 { DoWorkAndLog(); } Log("2"); } ``` Here the log used for logging "1" and "2" should be Scope1, but for some reason, the closing of Scope2 fails in multi-threaded calls (at least that is how I can force it). Because of this, the statement `Log("2");` is done on the disposed `Scope2` which fails.

And a somewhat useable PR that fixes it, but probably still has an underlying issue.

github.com/duplicati/duplicati

Simplified logging

duplicati:master ← duplicati:feature/simplify-logging

opened 03:15PM - 10 Jan 25 UTC

kenkendk

+90 -102

This simplifies the logging by only keeping the object instance, not the key-dic…tionary that was needed in .NET4. It also allows writing logs directly to the desired scope. There appears to be some quirk with the logging and call context, when invoked by multiple threads in the same area. This commit fixes it, but most likely just masks the underlying issue.

ts678 · January 10, 2025, 5:14pm

Does that explain the sticky error I have, where backups fail repeatedly?
Mine’s still in StartScope in the debugger, but I might let it loose, for test.

kenkendk · January 10, 2025, 5:32pm

Not sure. The code has been there for at least 6 years, so no idea why it is suddenly causing trouble.