I’m running Duplicati 2.0.5.114_canary_2021-03-10 on macOS 10.15.7 on a PC that I haven’t interacted with much over the past many months.
I’m having several issues:
- I was getting an update notification (for the version I’m already running). Install > activate > (it never restarts duplicati automatically, so I have to manually launch it) > refresh browser page > login > it says an update is available (again, same one I’m already running). After numerous attempts to install/activate from the bottom notification, I finally dismissed the notification.
- Under About > Show Log > Stored I’m seeing numerous different errors getting logged as far back as this screen shows (back through April 30, 2021), including “Failed while executing “Backup”” many times.
One error is (and its first run timestamp):
Apr 30, 2021 3:11 PM: Error in updater
System.Exception: Found unexpected file: /Users/name/Library/Application Support/Duplicati/updates/2.0.5.103/OSXTrayHost/rumps.pyc
at Duplicati.Library.AutoUpdater.UpdaterManager.VerifyUnpackedFolder (System.String folder, Duplicati.Library.AutoUpdater.UpdateInfo version) [0x002a1] in <0a7cf6efd05d4a43aecfe52cee57a507>:0
I found a topic similar to this from 2017.
It has repeated a dozen+ times up through today.
The second error is:
Apr 30, 2021 3:11 PM: Failed while executing "Backup" with id: 2
Duplicati.Library.Interface.UserInformationException:
The database has version 11 but the largest supported version is 10.
This is likely caused by upgrading to a newer version and then downgrading.
If this is the case, there is likely a backup file of the previous database version in the folder /Users/name/.config/Duplicati.
at Duplicati.Library.SQLiteHelper.DatabaseUpgrader.UpgradeDatabase (System.Data.IDbConnection connection, System.String sourcefile, System.String schema, System.Collections.Generic.IList`1[T] versions) [0x000c0] in <27bb620d94b74930aa53f9be283b02a1>:0
at Duplicati.Library.SQLiteHelper.DatabaseUpgrader.UpgradeDatabase (System.Data.IDbConnection connection, System.String sourcefile, System.Type eltype) [0x00105] in <27bb620d94b74930aa53f9be283b02a1>:0
at Duplicati.Library.Main.Database.LocalDatabase.CreateConnection (System.String path) [0x00027] in <759bd83d98134a149cdf84e129a07d38>:0
at Duplicati.Library.Main.Database.LocalDatabase..ctor (System.String path, System.String operation, System.Boolean shouldclose) [0x00000] in <759bd83d98134a149cdf84e129a07d38>:0
at Duplicati.Library.Main.Database.LocalBackupDatabase..ctor (System.String path, Duplicati.Library.Main.Options options) [0x00000] in <759bd83d98134a149cdf84e129a07d38>:0
at Duplicati.Library.Main.Operation.BackupHandler.RunAsync (System.String[] sources, Duplicati.Library.Utility.IFilter filter, System.Threading.CancellationToken token) [0x00042] in <759bd83d98134a149cdf84e129a07d38>:0
at CoCoL.ChannelExtensions.WaitForTaskOrThrow (System.Threading.Tasks.Task task) [0x00050] in <9a758ff4db6c48d6b3d4d0e5c2adf6d1>:0
at Duplicati.Library.Main.Operation.BackupHandler.Run (System.String[] sources, Duplicati.Library.Utility.IFilter filter, System.Threading.CancellationToken token) [0x00009] in <759bd83d98134a149cdf84e129a07d38>:0
at Duplicati.Library.Main.Controller+<>c__DisplayClass14_0.<Backup>b__0 (Duplicati.Library.Main.BackupResults result) [0x0004b] in <759bd83d98134a149cdf84e129a07d38>:0
at Duplicati.Library.Main.Controller.RunAction[T] (T result, System.String[]& paths, Duplicati.Library.Utility.IFilter& filter, System.Action`1[T] method) [0x0026f] in <759bd83d98134a149cdf84e129a07d38>:0
at Duplicati.Library.Main.Controller.Backup (System.String[] inputsources, Duplicati.Library.Utility.IFilter filter) [0x00074] in <759bd83d98134a149cdf84e129a07d38>:0
at Duplicati.Server.Runner.Run (Duplicati.Server.Runner+IRunnerData data, System.Boolean fromQueue) [0x00349] in <63a01150aadd4a64a4d7c359bdc1e45d>:0
I installed canary on this PC and haven’t installed anything else, AFAICR. It repeats numerous times up through this morning.
The third error doesn’t show up until 5/13:
May 13, 2021 6:43 AM: Reporting error gave error
System.ObjectDisposedException: Can not write to a closed TextWriter.
at System.IO.StreamWriter.Flush (System.Boolean flushStream, System.Boolean flushEncoder) [0x00008] in <b814b509d4ad406fb40c6c93e38929e7>:0
at System.IO.StreamWriter.Flush () [0x00006] in <b814b509d4ad406fb40c6c93e38929e7>:0
at Duplicati.Server.WebServer.RESTHandler.DoProcess (Duplicati.Server.WebServer.RESTMethods.RequestInfo info, System.String method, System.String module, System.String key) [0x003bc] in <d38f460035ab4f3b9bab2fc91e2cec32>:0
…followed immediately by this error:
May 13, 2021 6:43 AM: Request for http://localhost:8200/api/v1/remoteoperation/test gave error
Duplicati.Library.Interface.UserInformationException: Failed to authorize using the OAuth service: Server error. If the problem persists, try generating a new authid token from: https://duplicati-oauth-handler.appspot.com?type=onedrivev2 ---> System.Net.WebException: The remote server returned an error: (500) Internal Server Error.
at System.Net.HttpWebRequest.GetResponseFromData (System.Net.WebResponseStream stream, System.Threading.CancellationToken cancellationToken) [0x00146] in <6aa0b19d109a447c94d1b43ec4471dc6>:0
at System.Net.HttpWebRequest.RunWithTimeoutWorker[T] (System.Threading.Tasks.Task`1[TResult] workerTask, System.Int32 timeout, System.Action abort, System.Func`1[TResult] aborted, System.Threading.CancellationTokenSource cts) [0x000f8] in <6aa0b19d109a447c94d1b43ec4471dc6>:0
at Duplicati.Library.Utility.AsyncHttpRequest+AsyncWrapper.GetResponseOrStream () [0x0004d] in <1b35de2536e5489e93307d4ad0240fd2>:0
at Duplicati.Library.Utility.AsyncHttpRequest.GetResponse () [0x00044] in <1b35de2536e5489e93307d4ad0240fd2>:0
at Duplicati.Library.JSONWebHelper.GetResponse (Duplicati.Library.Utility.AsyncHttpRequest req, System.Object requestdata) [0x000c9] in <f0d969e53b444e228a09a72d3769a5ee>:0
at Duplicati.Library.JSONWebHelper.ReadJSONResponse[T] (Duplicati.Library.Utility.AsyncHttpRequest req, System.Object requestdata) [0x00000] in <f0d969e53b444e228a09a72d3769a5ee>:0
at Duplicati.Library.JSONWebHelper.ReadJSONResponse[T] (System.Net.HttpWebRequest req, System.Object requestdata) [0x00007] in <f0d969e53b444e228a09a72d3769a5ee>:0
at Duplicati.Library.OAuthHelper.GetTokenResponse[T] () [0x00040] in <f0d969e53b444e228a09a72d3769a5ee>:0
at Duplicati.Library.OAuthHelper.get_AccessToken () [0x0002f] in <f0d969e53b444e228a09a72d3769a5ee>:0
--- End of inner exception stack trace ---
at Duplicati.Library.OAuthHelper.get_AccessToken () [0x00169] in <f0d969e53b444e228a09a72d3769a5ee>:0
at Duplicati.Library.OAuthHelper.CreateRequest (System.String url, System.String method, System.Boolean noAuthorization) [0x00027] in <f0d969e53b444e228a09a72d3769a5ee>:0
at Duplicati.Library.OAuthHelper.CreateRequest (System.String url, System.String method) [0x00000] in <f0d969e53b444e228a09a72d3769a5ee>:0
at Duplicati.Library.JSONWebHelper.GetResponseWithoutException (System.String url, System.Object requestdata, System.String method) [0x00020] in <f0d969e53b444e228a09a72d3769a5ee>:0
at Duplicati.Library.Backend.MicrosoftGraphBackend.SendRequest[T] (System.Net.Http.HttpMethod method, System.String url) [0x00032] in <22708b578dd647fbafbabbcba5b0fd68>:0
at Duplicati.Library.Backend.MicrosoftGraphBackend.Get[T] (System.String url) [0x00006] in <22708b578dd647fbafbabbcba5b0fd68>:0
at Duplicati.Library.Backend.MicrosoftGraphBackend.Test () [0x00017] in <22708b578dd647fbafbabbcba5b0fd68>:0
at Duplicati.Server.WebServer.RESTMethods.RemoteOperation.TestConnection (System.String url, Duplicati.Server.WebServer.RESTMethods.RequestInfo info) [0x000b7] in <d38f460035ab4f3b9bab2fc91e2cec32>:0
at Duplicati.Server.WebServer.RESTMethods.RemoteOperation.POST (System.String key, Duplicati.Server.WebServer.RESTMethods.RequestInfo info) [0x00094] in <d38f460035ab4f3b9bab2fc91e2cec32>:0
at Duplicati.Server.WebServer.RESTHandler.DoProcess (Duplicati.Server.WebServer.RESTMethods.RequestInfo info, System.String method, System.String module, System.String key) [0x00289] in <d38f460035ab4f3b9bab2fc91e2cec32>:0
I generated a new authid token shortly after that and the last successful backup shows “05/14/2021 (took 00:01:03)”. Strangely, there are numerous “Failed while executing “Backup” with id: 2” errors before and after the authid token update date.
Since the successful backup on 5/14, I’ve seen the “Error in updater” error 6 times; the “Failed while executing “Backup” with id: 2” 8 times; and the newest (different) errors:
May 25, 2021 10:09 AM: Reporting error gave error
System.InvalidOperationException
at (wrapper managed-to-native) System.Reflection.Emit.DynamicMethod.create_dynamic_method(System.Reflection.Emit.DynamicMethod)
at System.Reflection.Emit.DynamicMethod.CreateDynMethod () [0x000b9] in <b814b509d4ad406fb40c6c93e38929e7>:0
at System.Reflection.Emit.DynamicMethod.CreateDelegate (System.Type delegateType) [0x00023] in <b814b509d4ad406fb40c6c93e38929e7>:0
at Newtonsoft.Json.Utilities.DynamicReflectionDelegateFactory.CreateParameterizedConstructor (System.Reflection.MethodBase method) [0x0003e] in <d47de75a7e3f422ca4ca64a654c80495>:0
at Newtonsoft.Json.Serialization.DefaultContractResolver.CreateObjectContract (System.Type objectType) [0x0016a] in <d47de75a7e3f422ca4ca64a654c80495>:0
at Newtonsoft.Json.Serialization.DefaultContractResolver.CreateContract (System.Type objectType) [0x0010f] in <d47de75a7e3f422ca4ca64a654c80495>:0
at System.Collections.Concurrent.ConcurrentDictionary`2[TKey,TValue].GetOrAdd (TKey key, System.Func`2[T,TResult] valueFactory) [0x00034] in <b814b509d4ad406fb40c6c93e38929e7>:0
at Newtonsoft.Json.Utilities.ThreadSafeStore`2[TKey,TValue].Get (TKey key) [0x00000] in <d47de75a7e3f422ca4ca64a654c80495>:0
at Newtonsoft.Json.Serialization.DefaultContractResolver.ResolveContract (System.Type type) [0x0000b] in <d47de75a7e3f422ca4ca64a654c80495>:0
at Newtonsoft.Json.Serialization.JsonSerializerInternalWriter.GetContractSafe (System.Object value) [0x00016] in <d47de75a7e3f422ca4ca64a654c80495>:0
at Newtonsoft.Json.Serialization.JsonSerializerInternalWriter.Serialize (Newtonsoft.Json.JsonWriter jsonWriter, System.Object value, System.Type objectType) [0x00028] in <d47de75a7e3f422ca4ca64a654c80495>:0
at Newtonsoft.Json.JsonSerializer.SerializeInternal (Newtonsoft.Json.JsonWriter jsonWriter, System.Object value, System.Type objectType) [0x0023a] in <d47de75a7e3f422ca4ca64a654c80495>:0
at Newtonsoft.Json.JsonSerializer.Serialize (Newtonsoft.Json.JsonWriter jsonWriter, System.Object value) [0x00000] in <d47de75a7e3f422ca4ca64a654c80495>:0
at Duplicati.Server.Serialization.Serializer.SerializeJson (System.IO.TextWriter sw, System.Object o, System.Boolean preventDispose) [0x00025] in <b5a9229c590043f79d2dfbdb71fadb24>:0
at Duplicati.Server.WebServer.BodyWriter.WriteJsonObject (System.Object o) [0x00040] in <63a01150aadd4a64a4d7c359bdc1e45d>:0
at (wrapper remoting-invoke-with-check) Duplicati.Server.WebServer.BodyWriter.WriteJsonObject(object)
at Duplicati.Server.WebServer.RESTHandler.DoProcess (Duplicati.Server.WebServer.RESTMethods.RequestInfo info, System.String method, System.String module, System.String key) [0x003b1] in <63a01150aadd4a64a4d7c359bdc1e45d>:0
Followed by:
May 25, 2021 10:09 AM: Request for http://localhost:8200/api/v1/serverstate?longpoll=true&lasteventid=131&format=json&duration=5m gave error
System.Threading.ThreadAbortException: Thread was being aborted.
at (wrapper managed-to-native) System.Threading.WaitHandle.Wait_internal(intptr*,int,bool,int)
at System.Threading.WaitHandle.WaitOneNative (System.Runtime.InteropServices.SafeHandle waitableSafeHandle, System.UInt32 millisecondsTimeout, System.Boolean hasThreadAffinity, System.Boolean exitContext) [0x00044] in <b814b509d4ad406fb40c6c93e38929e7>:0
at System.Threading.WaitHandle.InternalWaitOne (System.Runtime.InteropServices.SafeHandle waitableSafeHandle, System.Int64 millisecondsTimeout, System.Boolean hasThreadAffinity, System.Boolean exitContext) [0x00014] in <b814b509d4ad406fb40c6c93e38929e7>:0
at System.Threading.WaitHandle.WaitOne (System.Int64 timeout, System.Boolean exitContext) [0x00000] in <b814b509d4ad406fb40c6c93e38929e7>:0
at System.Threading.WaitHandle.WaitOne (System.Int32 millisecondsTimeout, System.Boolean exitContext) [0x00019] in <b814b509d4ad406fb40c6c93e38929e7>:0
at Duplicati.Server.EventPollNotify.Wait (System.Int64 eventId, System.Int32 milliseconds) [0x00042] in <63a01150aadd4a64a4d7c359bdc1e45d>:0
at Duplicati.Server.WebServer.RESTMethods.RequestInfo.LongPollCheck (Duplicati.Server.EventPollNotify poller, System.Int64& id, System.Boolean& isError) [0x00119] in <63a01150aadd4a64a4d7c359bdc1e45d>:0
at Duplicati.Server.WebServer.RESTMethods.ServerState.GET (System.String key, Duplicati.Server.WebServer.RESTMethods.RequestInfo info) [0x0000c] in <63a01150aadd4a64a4d7c359bdc1e45d>:0
at Duplicati.Server.WebServer.RESTHandler.DoProcess (Duplicati.Server.WebServer.RESTMethods.RequestInfo info, System.String method, System.String module, System.String key) [0x00146] in <63a01150aadd4a64a4d7c359bdc1e45d>:0
Out of curiosity, I tried manually starting a backup. It took 26 seconds and in the live log ended with “The operation Backup has completed” and the dblock & dlist files are in the cloud as expected.
I didn’t expect the manually run backup to complete successfully when the scheduled backups apparently hadn’t worked in nearly 2 weeks.