Getting timeouts/database locks on restore screen

zneumann · January 14, 2022, 6:55pm

Hello,
I am getting timeout errors on the restore screen and also database locks for a restore that is both off-prem SFTP (SSH) and on the same server just in different directories. The backups are fairly large between 1-2 TB as they are (mostly) whole server snapshots. I have repaired the remote database and even deleted and recreated the local databases. I have chmodded the files just in case but Duplicati is running from sytemd as a superuser so it should not matter. I pasted some logs below that I was able to locate related to the timeouts.

I updated to the canary build as I heard the most recent beta was having timeouts and it looks like the code may have been merged in the latest dev builds.
You are currently running Duplicati - 2.0.6.100_canary_2021-08-11

Operating system Ubuntu Linux 20.04.3
Kernel and CPU Linux 5.11.0-46-generic on x86_64
Processor information Intel(R) Xeon(R) CPU E5-2650 v2 @ 2.60GHz, 32 cores
CPU load averages 11.69 (1 min) 10.95 (5 mins) 10.76 (15 mins)
Real memory 51.88 GiB used / 193.05 GiB cached / 251.86 GiB total Virtual memory 11.44 GiB used / 11.99 GiB total
Local disk space 3.76 TiB used / 3.86 TiB free / 7.63 TiB total

mono -V
Mono JIT compiler version 6.12.0.122 (tarball Mon Feb 22 17:33:28 UTC 2021)
Copyright (C) 2002-2014 Novell, Inc, Xamarin Inc and Contributors. www.mono-project.com
        TLS:           __thread
        SIGSEGV:       altstack
        Notifications: epoll
        Architecture:  amd64
        Disabled:      none
        Misc:          softdebug 
        Interpreter:   yes
        LLVM:          yes(610)
        Suspend:       hybrid
        GC:            sgen (concurrent by default)

Jan 14, 2022 1:43 PM: Request for http://backups.hostingportal.net/api/v1/backup/12/files/*/var/lib/docker/volumes*?prefix-only=false&time=2022-01-10T07:00:01-05:00&filter=*%2Fvar%2Flib%2Fdocker%2Fvolumes* gave error
Mono.Data.Sqlite.SqliteException (0x80004005): The database file is locked
database is locked
  at Mono.Data.Sqlite.SQLite3.Step (Mono.Data.Sqlite.SqliteStatement stmt) [0x00089] in <83c72f6e53eb49f28420feee73a4aa07>:0 
  at Mono.Data.Sqlite.SqliteDataReader.NextResult () [0x00104] in <83c72f6e53eb49f28420feee73a4aa07>:0 
  at Mono.Data.Sqlite.SqliteDataReader..ctor (Mono.Data.Sqlite.SqliteCommand cmd, System.Data.CommandBehavior behave) [0x0004e] in <83c72f6e53eb49f28420feee73a4aa07>:0 
  at (wrapper remoting-invoke-with-check) Mono.Data.Sqlite.SqliteDataReader..ctor(Mono.Data.Sqlite.SqliteCommand,System.Data.CommandBehavior)
  at Mono.Data.Sqlite.SqliteCommand.ExecuteReader (System.Data.CommandBehavior behavior) [0x00006] in <83c72f6e53eb49f28420feee73a4aa07>:0 
  at Mono.Data.Sqlite.SqliteCommand.ExecuteDbDataReader (System.Data.CommandBehavior behavior) [0x00000] in <83c72f6e53eb49f28420feee73a4aa07>:0 
  at System.Data.Common.DbCommand.System.Data.IDbCommand.ExecuteReader () [0x00000] in <d3b33a5f75ba43539b447fcfaf55c885>:0 
  at Duplicati.Library.Main.Database.ExtensionMethods.ExecuteScalarInt64 (System.Data.IDbCommand self, System.Boolean writeLog, System.String cmd, System.Int64 defaultvalue, System.Object[] values) [0x00061] in <1d9349a5d6874088879a75d074c92b62>:0 
  at Duplicati.Library.Main.Database.ExtensionMethods.ExecuteScalarInt64 (System.Data.IDbCommand self, System.String cmd, System.Int64 defaultvalue, System.Object[] values) [0x00000] in <1d9349a5d6874088879a75d074c92b62>:0 
  at Duplicati.Library.Main.Database.LocalDatabase..ctor (System.Data.IDbConnection connection, System.String operation) [0x0005e] in <1d9349a5d6874088879a75d074c92b62>:0 
  at Duplicati.Library.Main.Database.LocalDatabase..ctor (System.String path, System.String operation, System.Boolean shouldclose) [0x00007] in <1d9349a5d6874088879a75d074c92b62>:0 
  at Duplicati.Library.Main.Database.LocalListDatabase..ctor (System.String path) [0x00000] in <1d9349a5d6874088879a75d074c92b62>:0 
  at Duplicati.Library.Main.Operation.ListFilesHandler.Run (System.Collections.Generic.IEnumerable`1[T] filterstrings, Duplicati.Library.Utility.IFilter compositefilter) [0x00075] in <1d9349a5d6874088879a75d074c92b62>:0 
  at Duplicati.Library.Main.Controller+<>c__DisplayClass21_0.<List>b__0 (Duplicati.Library.Main.ListResults result) [0x0001c] in <1d9349a5d6874088879a75d074c92b62>: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 <1d9349a5d6874088879a75d074c92b62>:0 
  at Duplicati.Library.Main.Controller.RunAction[T] (T result, Duplicati.Library.Utility.IFilter& filter, System.Action`1[T] method) [0x00007] in <1d9349a5d6874088879a75d074c92b62>:0 
  at Duplicati.Library.Main.Controller.List (System.Collections.Generic.IEnumerable`1[T] filterstrings, Duplicati.Library.Utility.IFilter filter) [0x00021] in <1d9349a5d6874088879a75d074c92b62>:0 
  at Duplicati.Server.Runner.Run (Duplicati.Server.Runner+IRunnerData data, System.Boolean fromQueue) [0x00668] in <3752ce5d8337471da6b77129cfa4bdbe>:0 
  at Duplicati.Server.WebServer.RESTMethods.Backup.SearchFiles (Duplicati.Server.Serialization.Interface.IBackup backup, System.String filterstring, Duplicati.Server.WebServer.RESTMethods.RequestInfo info) [0x000cb] in <3752ce5d8337471da6b77129cfa4bdbe>:0 
  at Duplicati.Server.WebServer.RESTMethods.Backup.GET (System.String key, Duplicati.Server.WebServer.RESTMethods.RequestInfo info) [0x001e0] in <3752ce5d8337471da6b77129cfa4bdbe>:0 
  at Duplicati.Server.WebServer.RESTHandler.DoProcess (Duplicati.Server.WebServer.RESTMethods.RequestInfo info, System.String method, System.String module, System.String key) [0x00146] in <3752ce5d8337471da6b77129cfa4bdbe>:0

Jan 14, 2022 1:43 PM: Request for http://backups.hostingportal.net/api/v1/backup/12/files/*/var/lib/docker/volumes*?prefix-only=false&time=2022-01-10T07:00:01-05:00&filter=*%2Fvar%2Flib%2Fdocker%2Fvolumes* gave error
Mono.Data.Sqlite.SqliteException (0x80004005): The database file is locked
database is locked
  at Mono.Data.Sqlite.SQLite3.Step (Mono.Data.Sqlite.SqliteStatement stmt) [0x00089] in <83c72f6e53eb49f28420feee73a4aa07>:0 
  at Mono.Data.Sqlite.SqliteDataReader.NextResult () [0x00104] in <83c72f6e53eb49f28420feee73a4aa07>:0 
  at Mono.Data.Sqlite.SqliteDataReader..ctor (Mono.Data.Sqlite.SqliteCommand cmd, System.Data.CommandBehavior behave) [0x0004e] in <83c72f6e53eb49f28420feee73a4aa07>:0 
  at (wrapper remoting-invoke-with-check) Mono.Data.Sqlite.SqliteDataReader..ctor(Mono.Data.Sqlite.SqliteCommand,System.Data.CommandBehavior)
  at Mono.Data.Sqlite.SqliteCommand.ExecuteReader (System.Data.CommandBehavior behavior) [0x00006] in <83c72f6e53eb49f28420feee73a4aa07>:0 
  at Mono.Data.Sqlite.SqliteCommand.ExecuteDbDataReader (System.Data.CommandBehavior behavior) [0x00000] in <83c72f6e53eb49f28420feee73a4aa07>:0 
  at System.Data.Common.DbCommand.System.Data.IDbCommand.ExecuteReader () [0x00000] in <d3b33a5f75ba43539b447fcfaf55c885>:0 
  at Duplicati.Library.Main.Database.ExtensionMethods.ExecuteScalarInt64 (System.Data.IDbCommand self, System.Boolean writeLog, System.String cmd, System.Int64 defaultvalue, System.Object[] values) [0x00061] in <1d9349a5d6874088879a75d074c92b62>:0 
  at Duplicati.Library.Main.Database.ExtensionMethods.ExecuteScalarInt64 (System.Data.IDbCommand self, System.String cmd, System.Int64 defaultvalue, System.Object[] values) [0x00000] in <1d9349a5d6874088879a75d074c92b62>:0 
  at Duplicati.Library.Main.Database.LocalDatabase..ctor (System.Data.IDbConnection connection, System.String operation) [0x0005e] in <1d9349a5d6874088879a75d074c92b62>:0 
  at Duplicati.Library.Main.Database.LocalDatabase..ctor (System.String path, System.String operation, System.Boolean shouldclose) [0x00007] in <1d9349a5d6874088879a75d074c92b62>:0 
  at Duplicati.Library.Main.Database.LocalListDatabase..ctor (System.String path) [0x00000] in <1d9349a5d6874088879a75d074c92b62>:0 
  at Duplicati.Library.Main.Operation.ListFilesHandler.Run (System.Collections.Generic.IEnumerable`1[T] filterstrings, Duplicati.Library.Utility.IFilter compositefilter) [0x00075] in <1d9349a5d6874088879a75d074c92b62>:0 
  at Duplicati.Library.Main.Controller+<>c__DisplayClass21_0.<List>b__0 (Duplicati.Library.Main.ListResults result) [0x0001c] in <1d9349a5d6874088879a75d074c92b62>: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 <1d9349a5d6874088879a75d074c92b62>:0 
  at Duplicati.Library.Main.Controller.RunAction[T] (T result, Duplicati.Library.Utility.IFilter& filter, System.Action`1[T] method) [0x00007] in <1d9349a5d6874088879a75d074c92b62>:0 
  at Duplicati.Library.Main.Controller.List (System.Collections.Generic.IEnumerable`1[T] filterstrings, Duplicati.Library.Utility.IFilter filter) [0x00021] in <1d9349a5d6874088879a75d074c92b62>:0 
  at Duplicati.Server.Runner.Run (Duplicati.Server.Runner+IRunnerData data, System.Boolean fromQueue) [0x00668] in <3752ce5d8337471da6b77129cfa4bdbe>:0 
  at Duplicati.Server.WebServer.RESTMethods.Backup.SearchFiles (Duplicati.Server.Serialization.Interface.IBackup backup, System.String filterstring, Duplicati.Server.WebServer.RESTMethods.RequestInfo info) [0x000cb] in <3752ce5d8337471da6b77129cfa4bdbe>:0 
  at Duplicati.Server.WebServer.RESTMethods.Backup.GET (System.String key, Duplicati.Server.WebServer.RESTMethods.RequestInfo info) [0x001e0] in <3752ce5d8337471da6b77129cfa4bdbe>:0 
  at Duplicati.Server.WebServer.RESTHandler.DoProcess (Duplicati.Server.WebServer.RESTMethods.RequestInfo info, System.String method, System.String module, System.String key) [0x00146] in <3752ce5d8337471da6b77129cfa4bdbe>:0

Jan 14, 2022 1:43 PM: Failed while executing "List" with id: 12
Mono.Data.Sqlite.SqliteException (0x80004005): The database file is locked
database is locked
  at Mono.Data.Sqlite.SQLite3.Step (Mono.Data.Sqlite.SqliteStatement stmt) [0x00089] in <83c72f6e53eb49f28420feee73a4aa07>:0 
  at Mono.Data.Sqlite.SqliteDataReader.NextResult () [0x00104] in <83c72f6e53eb49f28420feee73a4aa07>:0 
  at Mono.Data.Sqlite.SqliteDataReader..ctor (Mono.Data.Sqlite.SqliteCommand cmd, System.Data.CommandBehavior behave) [0x0004e] in <83c72f6e53eb49f28420feee73a4aa07>:0 
  at (wrapper remoting-invoke-with-check) Mono.Data.Sqlite.SqliteDataReader..ctor(Mono.Data.Sqlite.SqliteCommand,System.Data.CommandBehavior)
  at Mono.Data.Sqlite.SqliteCommand.ExecuteReader (System.Data.CommandBehavior behavior) [0x00006] in <83c72f6e53eb49f28420feee73a4aa07>:0 
  at Mono.Data.Sqlite.SqliteCommand.ExecuteDbDataReader (System.Data.CommandBehavior behavior) [0x00000] in <83c72f6e53eb49f28420feee73a4aa07>:0 
  at System.Data.Common.DbCommand.System.Data.IDbCommand.ExecuteReader () [0x00000] in <d3b33a5f75ba43539b447fcfaf55c885>:0 
  at Duplicati.Library.Main.Database.ExtensionMethods.ExecuteScalarInt64 (System.Data.IDbCommand self, System.Boolean writeLog, System.String cmd, System.Int64 defaultvalue, System.Object[] values) [0x00061] in <1d9349a5d6874088879a75d074c92b62>:0 
  at Duplicati.Library.Main.Database.ExtensionMethods.ExecuteScalarInt64 (System.Data.IDbCommand self, System.String cmd, System.Int64 defaultvalue, System.Object[] values) [0x00000] in <1d9349a5d6874088879a75d074c92b62>:0 
  at Duplicati.Library.Main.Database.LocalDatabase..ctor (System.Data.IDbConnection connection, System.String operation) [0x0005e] in <1d9349a5d6874088879a75d074c92b62>:0 
  at Duplicati.Library.Main.Database.LocalDatabase..ctor (System.String path, System.String operation, System.Boolean shouldclose) [0x00007] in <1d9349a5d6874088879a75d074c92b62>:0 
  at Duplicati.Library.Main.Database.LocalListDatabase..ctor (System.String path) [0x00000] in <1d9349a5d6874088879a75d074c92b62>:0 
  at Duplicati.Library.Main.Operation.ListFilesHandler.Run (System.Collections.Generic.IEnumerable`1[T] filterstrings, Duplicati.Library.Utility.IFilter compositefilter) [0x00075] in <1d9349a5d6874088879a75d074c92b62>:0 
  at Duplicati.Library.Main.Controller+<>c__DisplayClass21_0.<List>b__0 (Duplicati.Library.Main.ListResults result) [0x0001c] in <1d9349a5d6874088879a75d074c92b62>: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 <1d9349a5d6874088879a75d074c92b62>:0 
  at Duplicati.Library.Main.Controller.RunAction[T] (T result, Duplicati.Library.Utility.IFilter& filter, System.Action`1[T] method) [0x00007] in <1d9349a5d6874088879a75d074c92b62>:0 
  at Duplicati.Library.Main.Controller.List (System.Collections.Generic.IEnumerable`1[T] filterstrings, Duplicati.Library.Utility.IFilter filter) [0x00021] in <1d9349a5d6874088879a75d074c92b62>:0 
  at Duplicati.Server.Runner.Run (Duplicati.Server.Runner+IRunnerData data, System.Boolean fromQueue) [0x00374] in <3752ce5d8337471da6b77129cfa4bdbe>:0

Jan 14, 2022 1:34 PM: Request for http://backups.hostingportal.net/api/v1/backup/12/files/*?prefix-only=true&folder-contents=false&time=2022-01-13T07:00:00-05:00 gave error
Mono.Data.Sqlite.SqliteException (0x80004005): The database file is locked
database is locked
  at Mono.Data.Sqlite.SQLite3.Step (Mono.Data.Sqlite.SqliteStatement stmt) [0x00089] in <83c72f6e53eb49f28420feee73a4aa07>:0 
  at Mono.Data.Sqlite.SqliteDataReader.NextResult () [0x00104] in <83c72f6e53eb49f28420feee73a4aa07>:0 
  at Mono.Data.Sqlite.SqliteDataReader..ctor (Mono.Data.Sqlite.SqliteCommand cmd, System.Data.CommandBehavior behave) [0x0004e] in <83c72f6e53eb49f28420feee73a4aa07>:0 
  at (wrapper remoting-invoke-with-check) Mono.Data.Sqlite.SqliteDataReader..ctor(Mono.Data.Sqlite.SqliteCommand,System.Data.CommandBehavior)
  at Mono.Data.Sqlite.SqliteCommand.ExecuteReader (System.Data.CommandBehavior behavior) [0x00006] in <83c72f6e53eb49f28420feee73a4aa07>:0 
  at Mono.Data.Sqlite.SqliteCommand.ExecuteNonQuery () [0x00000] in <83c72f6e53eb49f28420feee73a4aa07>:0 
  at Mono.Data.Sqlite.SqliteTransaction..ctor (Mono.Data.Sqlite.SqliteConnection connection, System.Boolean deferredLock) [0x000a2] in <83c72f6e53eb49f28420feee73a4aa07>:0 
  at (wrapper remoting-invoke-with-check) Mono.Data.Sqlite.SqliteTransaction..ctor(Mono.Data.Sqlite.SqliteConnection,bool)
  at Mono.Data.Sqlite.SqliteConnection.BeginDbTransaction (System.Data.IsolationLevel isolationLevel) [0x00036] in <83c72f6e53eb49f28420feee73a4aa07>:0 
  at System.Data.Common.DbConnection.System.Data.IDbConnection.BeginTransaction () [0x00000] in <d3b33a5f75ba43539b447fcfaf55c885>:0 
  at Duplicati.Library.Main.Database.LocalDatabase.Dispose () [0x0002e] in <1d9349a5d6874088879a75d074c92b62>:0 
  at Duplicati.Library.Main.Operation.ListFilesHandler.Run (System.Collections.Generic.IEnumerable`1[T] filterstrings, Duplicati.Library.Utility.IFilter compositefilter) [0x00206] in <1d9349a5d6874088879a75d074c92b62>:0 
  at Duplicati.Library.Main.Controller+<>c__DisplayClass21_0.<List>b__0 (Duplicati.Library.Main.ListResults result) [0x0001c] in <1d9349a5d6874088879a75d074c92b62>: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 <1d9349a5d6874088879a75d074c92b62>:0 
  at Duplicati.Library.Main.Controller.RunAction[T] (T result, Duplicati.Library.Utility.IFilter& filter, System.Action`1[T] method) [0x00007] in <1d9349a5d6874088879a75d074c92b62>:0 
  at Duplicati.Library.Main.Controller.List (System.Collections.Generic.IEnumerable`1[T] filterstrings, Duplicati.Library.Utility.IFilter filter) [0x00021] in <1d9349a5d6874088879a75d074c92b62>:0 
  at Duplicati.Server.Runner.Run (Duplicati.Server.Runner+IRunnerData data, System.Boolean fromQueue) [0x00668] in <3752ce5d8337471da6b77129cfa4bdbe>:0 
  at Duplicati.Server.WebServer.RESTMethods.Backup.SearchFiles (Duplicati.Server.Serialization.Interface.IBackup backup, System.String filterstring, Duplicati.Server.WebServer.RESTMethods.RequestInfo info) [0x000cb] in <3752ce5d8337471da6b77129cfa4bdbe>:0 
  at Duplicati.Server.WebServer.RESTMethods.Backup.GET (System.String key, Duplicati.Server.WebServer.RESTMethods.RequestInfo info) [0x001e0] in <3752ce5d8337471da6b77129cfa4bdbe>:0 
  at Duplicati.Server.WebServer.RESTHandler.DoProcess (Duplicati.Server.WebServer.RESTMethods.RequestInfo info, System.String method, System.String module, System.String key) [0x00146] in <3752ce5d8337471da6b77129cfa4bdbe>:0

drwtsn32 · January 14, 2022, 10:57pm

Is a backup in progress? If so you can get the “database is locked” error if you try to use the restore function at the same time. You’ll need to wait for the backup to finish before you kick off a restore.

If that’s not your issue, then I do think it’s a permission problem. Not only does Duplicati need write access to the sqlite file itself, but it needs to be able to create new files in that same directory. This is because when an operation is in progress, a sqlite-journal file is created and used temporarily.

zneumann · January 14, 2022, 11:15pm

Thank you for your reply.
So just for sanity and insanity, I chmod -R 777 the /home and /root/.config directories already. The database is in /root/.config/Duplicati/ and the backup files are in /home/BACKUP. Still getting the same errors. I will also clarify that this is definitely not a VPS and is a bare metal server so no virtualization (like Virtuozzo) disk locks are present. Also in my original post, I mentioned Duplicati is running as root from systemd so no permissions error should be present in theory.

drwtsn32 · January 14, 2022, 11:17pm

Ok yeah if it’s running as root then permissions shouldn’t be a problem.

Strange. Can you confirm that no other Duplicati operation is in progress when you try to do a restore?

zneumann · January 14, 2022, 11:35pm

My theory is that I am hitting some sort of timeout because of how long it takes for the directory contents to be retrieved and then it also locks the DB temporarily or it’s just a secondary warning caused by the timeout (I will note I do in fact SSL proxy through Nginx) but I was also getting the error when loading from localhost as well bypassing the SSL proxy. Currently, I am trying to do the same restore by importing the config file on my local machine (and grabbing the files remotely) and even that was throwing the same errors for a while. So far this time if I click one arrow and wait for it to load it seems fine but I was trying to expand multiple directories earlier. Almost feels like normal tech stuff where you could replicate it all day and now all of a sudden it’s mostly behaving (on the local fresh instance with the imported config). The server instance is verifying the offsite database at the moment so I can’t test that instance currently as that is gonna take a while (usually several hours to verify from experience).

zneumann · January 15, 2022, 4:43am

Yeah, it is still happening even just looking at the interface.
No pending tasks:

Jan 14, 2022 11:41 PM: Request for http://backups.hostingportal.net/api/v1/backup/12/filesets gave error
Mono.Data.Sqlite.SqliteException (0x80004005): The database file is locked
database is locked
  at Mono.Data.Sqlite.SQLite3.Step (Mono.Data.Sqlite.SqliteStatement stmt) [0x00089] in <83c72f6e53eb49f28420feee73a4aa07>:0 
  at Mono.Data.Sqlite.SqliteDataReader.NextResult () [0x00104] in <83c72f6e53eb49f28420feee73a4aa07>:0 
  at Mono.Data.Sqlite.SqliteDataReader..ctor (Mono.Data.Sqlite.SqliteCommand cmd, System.Data.CommandBehavior behave) [0x0004e] in <83c72f6e53eb49f28420feee73a4aa07>:0 
  at (wrapper remoting-invoke-with-check) Mono.Data.Sqlite.SqliteDataReader..ctor(Mono.Data.Sqlite.SqliteCommand,System.Data.CommandBehavior)
  at Mono.Data.Sqlite.SqliteCommand.ExecuteReader (System.Data.CommandBehavior behavior) [0x00006] in <83c72f6e53eb49f28420feee73a4aa07>:0 
  at Mono.Data.Sqlite.SqliteCommand.ExecuteDbDataReader (System.Data.CommandBehavior behavior) [0x00000] in <83c72f6e53eb49f28420feee73a4aa07>:0 
  at System.Data.Common.DbCommand.System.Data.IDbCommand.ExecuteReader () [0x00000] in <d3b33a5f75ba43539b447fcfaf55c885>:0 
  at Duplicati.Library.Main.Database.ExtensionMethods.ExecuteScalarInt64 (System.Data.IDbCommand self, System.Boolean writeLog, System.String cmd, System.Int64 defaultvalue, System.Object[] values) [0x00061] in <1d9349a5d6874088879a75d074c92b62>:0 
  at Duplicati.Library.Main.Database.ExtensionMethods.ExecuteScalarInt64 (System.Data.IDbCommand self, System.String cmd, System.Int64 defaultvalue, System.Object[] values) [0x00000] in <1d9349a5d6874088879a75d074c92b62>:0 
  at Duplicati.Library.Main.Database.LocalDatabase..ctor (System.Data.IDbConnection connection, System.String operation) [0x0005e] in <1d9349a5d6874088879a75d074c92b62>:0 
  at Duplicati.Library.Main.Database.LocalDatabase..ctor (System.String path, System.String operation, System.Boolean shouldclose) [0x00007] in <1d9349a5d6874088879a75d074c92b62>:0 
  at Duplicati.Library.Main.Database.LocalListDatabase..ctor (System.String path) [0x00000] in <1d9349a5d6874088879a75d074c92b62>:0 
  at Duplicati.Library.Main.Operation.ListFilesHandler.Run (System.Collections.Generic.IEnumerable`1[T] filterstrings, Duplicati.Library.Utility.IFilter compositefilter) [0x00075] in <1d9349a5d6874088879a75d074c92b62>:0 
  at Duplicati.Library.Main.Controller+<>c__DisplayClass21_0.<List>b__0 (Duplicati.Library.Main.ListResults result) [0x0001c] in <1d9349a5d6874088879a75d074c92b62>: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 <1d9349a5d6874088879a75d074c92b62>:0 
  at Duplicati.Library.Main.Controller.RunAction[T] (T result, Duplicati.Library.Utility.IFilter& filter, System.Action`1[T] method) [0x00007] in <1d9349a5d6874088879a75d074c92b62>:0 
  at Duplicati.Library.Main.Controller.List (System.Collections.Generic.IEnumerable`1[T] filterstrings, Duplicati.Library.Utility.IFilter filter) [0x00021] in <1d9349a5d6874088879a75d074c92b62>:0 
  at Duplicati.Server.Runner.Run (Duplicati.Server.Runner+IRunnerData data, System.Boolean fromQueue) [0x00668] in <3752ce5d8337471da6b77129cfa4bdbe>:0 
  at Duplicati.Server.WebServer.RESTMethods.Backup.ListFileSets (Duplicati.Server.Serialization.Interface.IBackup backup, Duplicati.Server.WebServer.RESTMethods.RequestInfo info) [0x000a4] in <3752ce5d8337471da6b77129cfa4bdbe>:0 
  at Duplicati.Server.WebServer.RESTMethods.Backup.GET (System.String key, Duplicati.Server.WebServer.RESTMethods.RequestInfo info) [0x001fd] in <3752ce5d8337471da6b77129cfa4bdbe>:0 
  at Duplicati.Server.WebServer.RESTHandler.DoProcess (Duplicati.Server.WebServer.RESTMethods.RequestInfo info, System.String method, System.String module, System.String key) [0x00146] in <3752ce5d8337471da6b77129cfa4bdbe>:0

Jan 14, 2022 11:41 PM: 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 <533173d24dae460899d2b10975534bb0>:0 
  at System.IO.StreamWriter.Flush () [0x00006] in <533173d24dae460899d2b10975534bb0>:0 
  at Duplicati.Server.WebServer.RESTHandler.DoProcess (Duplicati.Server.WebServer.RESTMethods.RequestInfo info, System.String method, System.String module, System.String key) [0x003bc] in <3752ce5d8337471da6b77129cfa4bdbe>:0

drwtsn32 · January 15, 2022, 3:38pm

Are you running Duplicati in docker, or is it installed right on the host. (I’m guessing the latter based on your previous messages but just want to be sure.)

Is there anything special about the location where databases are stored? eg, is it a regular directory on a fixed local disk or is it an NFS mount?

ts678 · January 15, 2022, 5:04pm

While we’re asking questions, can you elaborate on the timeout? I wasn’t able to find the details posted.

Also, what is the browser? Most have some developer tools to look at the queries, if you’re comfortable.

On the Duplicati side, there’s quite a bit of logging available to see whether SQL is getting overly slow…

zneumann · January 15, 2022, 9:03pm

Duplicati is installed bare metal and not running in a container so a memory constraint is not the issue. The drives are soft raided (0) EXT4 and there are no NFS mounts. I have monitoring for SMART and RAID in Webmin and no alerts are currently being set off. The browser is Chrome but I’m not sure if it’s going to provide much more useful information than the logs Duplicati is throwing at the time of the error. I will reply back with console logs and network info from Chrome.

zneumann · January 15, 2022, 9:16pm

Here are the Chrome errors:

zneumann · January 15, 2022, 9:18pm

I appreciate everyone’s assistance with trying to dig further into the issue. This is a weird one for sure and I was not finding many previous issues of it.

ts678 · January 15, 2022, 10:09pm

Failed to connect: Gateway Time-out issue when restoring was me on how to increase the NGINX timeout, however in that topic it turned into a different error. For awhile though you weren’t on NGINX. Are you back?

The network status code image with the 504 is gateway timeout. Is that what you’ve always been getting? Talking about timeout in a generic way leaves too much guessing, so I was trying to get timeouts clarified.

I am not certain that the Duplicati web server can’t 504, but I doubt it. I don’t see a 504 or GatewayTimeout from a source search. I do see it returning a lot of its errors using the names from HttpStatusCode Enum.

You can watch the SQL go by in About → Show log → Live → Profiling (if that web report stays .working).
More certain (and more setup) is log-file=<path> and log-file-log-level=profiling, then tail -f your log file, while also watching for a 504. Possibly you’ll see it still in the query when NGINX gets tired of waiting on it.

If the problem is really that the response can’t meet the timeout, the only short-term fix is to raise timeout.
Note that this theory doesn’t hold too well if you’re on a direct network path to localhost:8200 (if you were).

zneumann · January 15, 2022, 10:31pm

Unfortunately, I get it on localhost as well even bypassing the Nginx proxy. The error changes from a 504 to a 500 error.

ts678 · January 15, 2022, 10:42pm

Can you see if there’s any more description on that 500 status? Maybe on Response tab. I don’t know.
At least the 500 is something I see in the web server code, and I see some attempts to send details…

zneumann · January 15, 2022, 10:44pm

It’s a JSON reply:
Message: "The database file is locked\r\ndatabase is locked.
Type: “SqliteException”

That is all it provides in the response tab.

ts678 · January 15, 2022, 10:48pm

I was wondering (still am, but less) whether that database issue was a follow-on to some other glitch.
So it looks like the files query to the server went straight to 500. Was there a timing value on reply?
This might also be a good time to try the profiling log (probably to log file) to see what the DB is doing.

zneumann · January 15, 2022, 10:52pm

The profiling log is blank. All it has is the last time I tried restarting the Duplicati service.

The best logs I got are the stored ones I have been embedding.

Jan 15, 2022 5:39 PM: 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 <533173d24dae460899d2b10975534bb0>:0 
  at System.IO.StreamWriter.Flush () [0x00006] in <533173d24dae460899d2b10975534bb0>:0 
  at Duplicati.Server.WebServer.RESTHandler.DoProcess (Duplicati.Server.WebServer.RESTMethods.RequestInfo info, System.String method, System.String module, System.String key) [0x003bc] in <3752ce5d8337471da6b77129cfa4bdbe>:0 
Jan 15, 2022 5:39 PM: Request for http://127.0.0.1:8196/api/v1/backup/12/filesets gave error
Mono.Data.Sqlite.SqliteException (0x80004005): The database file is locked
database is locked
  at Mono.Data.Sqlite.SQLite3.Step (Mono.Data.Sqlite.SqliteStatement stmt) [0x00089] in <83c72f6e53eb49f28420feee73a4aa07>:0 
  at Mono.Data.Sqlite.SqliteDataReader.NextResult () [0x00104] in <83c72f6e53eb49f28420feee73a4aa07>:0 
  at Mono.Data.Sqlite.SqliteDataReader..ctor (Mono.Data.Sqlite.SqliteCommand cmd, System.Data.CommandBehavior behave) [0x0004e] in <83c72f6e53eb49f28420feee73a4aa07>:0 
  at (wrapper remoting-invoke-with-check) Mono.Data.Sqlite.SqliteDataReader..ctor(Mono.Data.Sqlite.SqliteCommand,System.Data.CommandBehavior)
  at Mono.Data.Sqlite.SqliteCommand.ExecuteReader (System.Data.CommandBehavior behavior) [0x00006] in <83c72f6e53eb49f28420feee73a4aa07>:0 
  at Mono.Data.Sqlite.SqliteCommand.ExecuteDbDataReader (System.Data.CommandBehavior behavior) [0x00000] in <83c72f6e53eb49f28420feee73a4aa07>:0 
  at System.Data.Common.DbCommand.System.Data.IDbCommand.ExecuteReader () [0x00000] in <d3b33a5f75ba43539b447fcfaf55c885>:0 
  at Duplicati.Library.Main.Database.ExtensionMethods.ExecuteScalarInt64 (System.Data.IDbCommand self, System.Boolean writeLog, System.String cmd, System.Int64 defaultvalue, System.Object[] values) [0x00061] in <1d9349a5d6874088879a75d074c92b62>:0 
  at Duplicati.Library.Main.Database.ExtensionMethods.ExecuteScalarInt64 (System.Data.IDbCommand self, System.String cmd, System.Int64 defaultvalue, System.Object[] values) [0x00000] in <1d9349a5d6874088879a75d074c92b62>:0 
  at Duplicati.Library.Main.Database.LocalDatabase..ctor (System.Data.IDbConnection connection, System.String operation) [0x0005e] in <1d9349a5d6874088879a75d074c92b62>:0 
  at Duplicati.Library.Main.Database.LocalDatabase..ctor (System.String path, System.String operation, System.Boolean shouldclose) [0x00007] in <1d9349a5d6874088879a75d074c92b62>:0 
  at Duplicati.Library.Main.Database.LocalListDatabase..ctor (System.String path) [0x00000] in <1d9349a5d6874088879a75d074c92b62>:0 
  at Duplicati.Library.Main.Operation.ListFilesHandler.Run (System.Collections.Generic.IEnumerable`1[T] filterstrings, Duplicati.Library.Utility.IFilter compositefilter) [0x00075] in <1d9349a5d6874088879a75d074c92b62>:0 
  at Duplicati.Library.Main.Controller+<>c__DisplayClass21_0.<List>b__0 (Duplicati.Library.Main.ListResults result) [0x0001c] in <1d9349a5d6874088879a75d074c92b62>: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 <1d9349a5d6874088879a75d074c92b62>:0 
  at Duplicati.Library.Main.Controller.RunAction[T] (T result, Duplicati.Library.Utility.IFilter& filter, System.Action`1[T] method) [0x00007] in <1d9349a5d6874088879a75d074c92b62>:0 
  at Duplicati.Library.Main.Controller.List (System.Collections.Generic.IEnumerable`1[T] filterstrings, Duplicati.Library.Utility.IFilter filter) [0x00021] in <1d9349a5d6874088879a75d074c92b62>:0 
  at Duplicati.Server.Runner.Run (Duplicati.Server.Runner+IRunnerData data, System.Boolean fromQueue) [0x00668] in <3752ce5d8337471da6b77129cfa4bdbe>:0 
  at Duplicati.Server.WebServer.RESTMethods.Backup.ListFileSets (Duplicati.Server.Serialization.Interface.IBackup backup, Duplicati.Server.WebServer.RESTMethods.RequestInfo info) [0x000a4] in <3752ce5d8337471da6b77129cfa4bdbe>:0 
  at Duplicati.Server.WebServer.RESTMethods.Backup.GET (System.String key, Duplicati.Server.WebServer.RESTMethods.RequestInfo info) [0x001fd] in <3752ce5d8337471da6b77129cfa4bdbe>:0 
  at Duplicati.Server.WebServer.RESTHandler.DoProcess (Duplicati.Server.WebServer.RESTMethods.RequestInfo info, System.String method, System.String module, System.String key) [0x00146] in <3752ce5d8337471da6b77129cfa4bdbe>:0 
Jan 15, 2022 5:39 PM: Failed while executing "List" with id: 12
Mono.Data.Sqlite.SqliteException (0x80004005): The database file is locked
database is locked
  at Mono.Data.Sqlite.SQLite3.Step (Mono.Data.Sqlite.SqliteStatement stmt) [0x00089] in <83c72f6e53eb49f28420feee73a4aa07>:0 
  at Mono.Data.Sqlite.SqliteDataReader.NextResult () [0x00104] in <83c72f6e53eb49f28420feee73a4aa07>:0 
  at Mono.Data.Sqlite.SqliteDataReader..ctor (Mono.Data.Sqlite.SqliteCommand cmd, System.Data.CommandBehavior behave) [0x0004e] in <83c72f6e53eb49f28420feee73a4aa07>:0 
  at (wrapper remoting-invoke-with-check) Mono.Data.Sqlite.SqliteDataReader..ctor(Mono.Data.Sqlite.SqliteCommand,System.Data.CommandBehavior)
  at Mono.Data.Sqlite.SqliteCommand.ExecuteReader (System.Data.CommandBehavior behavior) [0x00006] in <83c72f6e53eb49f28420feee73a4aa07>:0 
  at Mono.Data.Sqlite.SqliteCommand.ExecuteDbDataReader (System.Data.CommandBehavior behavior) [0x00000] in <83c72f6e53eb49f28420feee73a4aa07>:0 
  at System.Data.Common.DbCommand.System.Data.IDbCommand.ExecuteReader () [0x00000] in <d3b33a5f75ba43539b447fcfaf55c885>:0 
  at Duplicati.Library.Main.Database.ExtensionMethods.ExecuteScalarInt64 (System.Data.IDbCommand self, System.Boolean writeLog, System.String cmd, System.Int64 defaultvalue, System.Object[] values) [0x00061] in <1d9349a5d6874088879a75d074c92b62>:0 
  at Duplicati.Library.Main.Database.ExtensionMethods.ExecuteScalarInt64 (System.Data.IDbCommand self, System.String cmd, System.Int64 defaultvalue, System.Object[] values) [0x00000] in <1d9349a5d6874088879a75d074c92b62>:0 
  at Duplicati.Library.Main.Database.LocalDatabase..ctor (System.Data.IDbConnection connection, System.String operation) [0x0005e] in <1d9349a5d6874088879a75d074c92b62>:0 
  at Duplicati.Library.Main.Database.LocalDatabase..ctor (System.String path, System.String operation, System.Boolean shouldclose) [0x00007] in <1d9349a5d6874088879a75d074c92b62>:0 
  at Duplicati.Library.Main.Database.LocalListDatabase..ctor (System.String path) [0x00000] in <1d9349a5d6874088879a75d074c92b62>:0 
  at Duplicati.Library.Main.Operation.ListFilesHandler.Run (System.Collections.Generic.IEnumerable`1[T] filterstrings, Duplicati.Library.Utility.IFilter compositefilter) [0x00075] in <1d9349a5d6874088879a75d074c92b62>:0 
  at Duplicati.Library.Main.Controller+<>c__DisplayClass21_0.<List>b__0 (Duplicati.Library.Main.ListResults result) [0x0001c] in <1d9349a5d6874088879a75d074c92b62>: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 <1d9349a5d6874088879a75d074c92b62>:0 
  at Duplicati.Library.Main.Controller.RunAction[T] (T result, Duplicati.Library.Utility.IFilter& filter, System.Action`1[T] method) [0x00007] in <1d9349a5d6874088879a75d074c92b62>:0 
  at Duplicati.Library.Main.Controller.List (System.Collections.Generic.IEnumerable`1[T] filterstrings, Duplicati.Library.Utility.IFilter filter) [0x00021] in <1d9349a5d6874088879a75d074c92b62>:0 
  at Duplicati.Server.Runner.Run (Duplicati.Server.Runner+IRunnerData data, System.Boolean fromQueue) [0x00374] in <3752ce5d8337471da6b77129cfa4bdbe>:0 
Jan 15, 2022 5:38 PM: Request for http://127.0.0.1:8196/api/v1/backup/12/files/*?prefix-only=true&folder-contents=false&time=2022-01-13T07:00:00-05:00 gave error
Mono.Data.Sqlite.SqliteException (0x80004005): The database file is locked
database is locked
  at Mono.Data.Sqlite.SQLite3.Step (Mono.Data.Sqlite.SqliteStatement stmt) [0x00089] in <83c72f6e53eb49f28420feee73a4aa07>:0 
  at Mono.Data.Sqlite.SqliteDataReader.NextResult () [0x00104] in <83c72f6e53eb49f28420feee73a4aa07>:0 
  at Mono.Data.Sqlite.SqliteDataReader..ctor (Mono.Data.Sqlite.SqliteCommand cmd, System.Data.CommandBehavior behave) [0x0004e] in <83c72f6e53eb49f28420feee73a4aa07>:0 
  at (wrapper remoting-invoke-with-check) Mono.Data.Sqlite.SqliteDataReader..ctor(Mono.Data.Sqlite.SqliteCommand,System.Data.CommandBehavior)
  at Mono.Data.Sqlite.SqliteCommand.ExecuteReader (System.Data.CommandBehavior behavior) [0x00006] in <83c72f6e53eb49f28420feee73a4aa07>:0 
  at Mono.Data.Sqlite.SqliteCommand.ExecuteNonQuery () [0x00000] in <83c72f6e53eb49f28420feee73a4aa07>:0 
  at Mono.Data.Sqlite.SqliteTransaction..ctor (Mono.Data.Sqlite.SqliteConnection connection, System.Boolean deferredLock) [0x000a2] in <83c72f6e53eb49f28420feee73a4aa07>:0 
  at (wrapper remoting-invoke-with-check) Mono.Data.Sqlite.SqliteTransaction..ctor(Mono.Data.Sqlite.SqliteConnection,bool)
  at Mono.Data.Sqlite.SqliteConnection.BeginDbTransaction (System.Data.IsolationLevel isolationLevel) [0x00036] in <83c72f6e53eb49f28420feee73a4aa07>:0 
  at System.Data.Common.DbConnection.System.Data.IDbConnection.BeginTransaction () [0x00000] in <d3b33a5f75ba43539b447fcfaf55c885>:0 
  at Duplicati.Library.Main.Database.LocalDatabase.Dispose () [0x0002e] in <1d9349a5d6874088879a75d074c92b62>:0 
  at Duplicati.Library.Main.Operation.ListFilesHandler.Run (System.Collections.Generic.IEnumerable`1[T] filterstrings, Duplicati.Library.Utility.IFilter compositefilter) [0x00206] in <1d9349a5d6874088879a75d074c92b62>:0 
  at Duplicati.Library.Main.Controller+<>c__DisplayClass21_0.<List>b__0 (Duplicati.Library.Main.ListResults result) [0x0001c] in <1d9349a5d6874088879a75d074c92b62>: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 <1d9349a5d6874088879a75d074c92b62>:0 
  at Duplicati.Library.Main.Controller.RunAction[T] (T result, Duplicati.Library.Utility.IFilter& filter, System.Action`1[T] method) [0x00007] in <1d9349a5d6874088879a75d074c92b62>:0 
  at Duplicati.Library.Main.Controller.List (System.Collections.Generic.IEnumerable`1[T] filterstrings, Duplicati.Library.Utility.IFilter filter) [0x00021] in <1d9349a5d6874088879a75d074c92b62>:0 
  at Duplicati.Server.Runner.Run (Duplicati.Server.Runner+IRunnerData data, System.Boolean fromQueue) [0x00668] in <3752ce5d8337471da6b77129cfa4bdbe>:0 
  at Duplicati.Server.WebServer.RESTMethods.Backup.SearchFiles (Duplicati.Server.Serialization.Interface.IBackup backup, System.String filterstring, Duplicati.Server.WebServer.RESTMethods.RequestInfo info) [0x000cb] in <3752ce5d8337471da6b77129cfa4bdbe>:0 
  at Duplicati.Server.WebServer.RESTMethods.Backup.GET (System.String key, Duplicati.Server.WebServer.RESTMethods.RequestInfo info) [0x001e0] in <3752ce5d8337471da6b77129cfa4bdbe>:0 
  at Duplicati.Server.WebServer.RESTHandler.DoProcess (Duplicati.Server.WebServer.RESTMethods.RequestInfo info, System.String method, System.String module, System.String key) [0x00146] in <3752ce5d8337471da6b77129cfa4bdbe>:0 
Jan 15, 2022 5:38 PM: 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 <533173d24dae460899d2b10975534bb0>:0 
  at System.IO.StreamWriter.Flush () [0x00006] in <533173d24dae460899d2b10975534bb0>:0 
  at Duplicati.Server.WebServer.RESTHandler.DoProcess (Duplicati.Server.WebServer.RESTMethods.RequestInfo info, System.String method, System.String module, System.String key) [0x003bc] in <3752ce5d8337471da6b77129cfa4bdbe>:0 
Jan 15, 2022 5:38 PM: Failed while executing "List" with id: 12
Mono.Data.Sqlite.SqliteException (0x80004005): The database file is locked
database is locked
  at Mono.Data.Sqlite.SQLite3.Step (Mono.Data.Sqlite.SqliteStatement stmt) [0x00089] in <83c72f6e53eb49f28420feee73a4aa07>:0 
  at Mono.Data.Sqlite.SqliteDataReader.NextResult () [0x00104] in <83c72f6e53eb49f28420feee73a4aa07>:0 
  at Mono.Data.Sqlite.SqliteDataReader..ctor (Mono.Data.Sqlite.SqliteCommand cmd, System.Data.CommandBehavior behave) [0x0004e] in <83c72f6e53eb49f28420feee73a4aa07>:0 
  at (wrapper remoting-invoke-with-check) Mono.Data.Sqlite.SqliteDataReader..ctor(Mono.Data.Sqlite.SqliteCommand,System.Data.CommandBehavior)
  at Mono.Data.Sqlite.SqliteCommand.ExecuteReader (System.Data.CommandBehavior behavior) [0x00006] in <83c72f6e53eb49f28420feee73a4aa07>:0 
  at Mono.Data.Sqlite.SqliteCommand.ExecuteNonQuery () [0x00000] in <83c72f6e53eb49f28420feee73a4aa07>:0 
  at Mono.Data.Sqlite.SqliteTransaction..ctor (Mono.Data.Sqlite.SqliteConnection connection, System.Boolean deferredLock) [0x000a2] in <83c72f6e53eb49f28420feee73a4aa07>:0 
  at (wrapper remoting-invoke-with-check) Mono.Data.Sqlite.SqliteTransaction..ctor(Mono.Data.Sqlite.SqliteConnection,bool)
  at Mono.Data.Sqlite.SqliteConnection.BeginDbTransaction (System.Data.IsolationLevel isolationLevel) [0x00036] in <83c72f6e53eb49f28420feee73a4aa07>:0 
  at System.Data.Common.DbConnection.System.Data.IDbConnection.BeginTransaction () [0x00000] in <d3b33a5f75ba43539b447fcfaf55c885>:0 
  at Duplicati.Library.Main.Database.LocalDatabase.Dispose () [0x0002e] in <1d9349a5d6874088879a75d074c92b62>:0 
  at Duplicati.Library.Main.Operation.ListFilesHandler.Run (System.Collections.Generic.IEnumerable`1[T] filterstrings, Duplicati.Library.Utility.IFilter compositefilter) [0x00206] in <1d9349a5d6874088879a75d074c92b62>:0 
  at Duplicati.Library.Main.Controller+<>c__DisplayClass21_0.<List>b__0 (Duplicati.Library.Main.ListResults result) [0x0001c] in <1d9349a5d6874088879a75d074c92b62>: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 <1d9349a5d6874088879a75d074c92b62>:0 
  at Duplicati.Library.Main.Controller.RunAction[T] (T result, Duplicati.Library.Utility.IFilter& filter, System.Action`1[T] method) [0x00007] in <1d9349a5d6874088879a75d074c92b62>:0 
  at Duplicati.Library.Main.Controller.List (System.Collections.Generic.IEnumerable`1[T] filterstrings, Duplicati.Library.Utility.IFilter filter) [0x00021] in <1d9349a5d6874088879a75d074c92b62>:0 
  at Duplicati.Server.Runner.Run (Duplicati.Server.Runner+IRunnerData data, System.Boolean fromQueue) [0x00374] in <3752ce5d8337471da6b77129cfa4bdbe>:0 
Jan 15, 2022 5:27 PM: Failed while executing "List" with id: 12
Mono.Data.Sqlite.SqliteException (0x80004005): The database file is locked
database is locked
  at Mono.Data.Sqlite.SQLite3.Step (Mono.Data.Sqlite.SqliteStatement stmt) [0x00089] in <83c72f6e53eb49f28420feee73a4aa07>:0 
  at Mono.Data.Sqlite.SqliteDataReader.NextResult () [0x00104] in <83c72f6e53eb49f28420feee73a4aa07>:0 
  at Mono.Data.Sqlite.SqliteDataReader..ctor (Mono.Data.Sqlite.SqliteCommand cmd, System.Data.CommandBehavior behave) [0x0004e] in <83c72f6e53eb49f28420feee73a4aa07>:0 
  at (wrapper remoting-invoke-with-check) Mono.Data.Sqlite.SqliteDataReader..ctor(Mono.Data.Sqlite.SqliteCommand,System.Data.CommandBehavior)
  at Mono.Data.Sqlite.SqliteCommand.ExecuteReader (System.Data.CommandBehavior behavior) [0x00006] in <83c72f6e53eb49f28420feee73a4aa07>:0 
  at Mono.Data.Sqlite.SqliteCommand.ExecuteDbDataReader (System.Data.CommandBehavior behavior) [0x00000] in <83c72f6e53eb49f28420feee73a4aa07>:0 
  at System.Data.Common.DbCommand.System.Data.IDbCommand.ExecuteReader () [0x00000] in <d3b33a5f75ba43539b447fcfaf55c885>:0 
  at Duplicati.Library.Main.Database.ExtensionMethods.ExecuteScalarInt64 (System.Data.IDbCommand self, System.Boolean writeLog, System.String cmd, System.Int64 defaultvalue, System.Object[] values) [0x00061] in <1d9349a5d6874088879a75d074c92b62>:0 
  at Duplicati.Library.Main.Database.ExtensionMethods.ExecuteScalarInt64 (System.Data.IDbCommand self, System.String cmd, System.Int64 defaultvalue, System.Object[] values) [0x00000] in <1d9349a5d6874088879a75d074c92b62>:0 
  at Duplicati.Library.Main.Database.LocalDatabase..ctor (System.Data.IDbConnection connection, System.String operation) [0x0005e] in <1d9349a5d6874088879a75d074c92b62>:0 
  at Duplicati.Library.Main.Database.LocalDatabase..ctor (System.String path, System.String operation, System.Boolean shouldclose) [0x00007] in <1d9349a5d6874088879a75d074c92b62>:0 
  at Duplicati.Library.Main.Database.LocalListDatabase..ctor (System.String path) [0x00000] in <1d9349a5d6874088879a75d074c92b62>:0 
  at Duplicati.Library.Main.Operation.ListFilesHandler.Run (System.Collections.Generic.IEnumerable`1[T] filterstrings, Duplicati.Library.Utility.IFilter compositefilter) [0x00075] in <1d9349a5d6874088879a75d074c92b62>:0 
  at Duplicati.Library.Main.Controller+<>c__DisplayClass21_0.<List>b__0 (Duplicati.Library.Main.ListResults result) [0x0001c] in <1d9349a5d6874088879a75d074c92b62>: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 <1d9349a5d6874088879a75d074c92b62>:0 
  at Duplicati.Library.Main.Controller.RunAction[T] (T result, Duplicati.Library.Utility.IFilter& filter, System.Action`1[T] method) [0x00007] in <1d9349a5d6874088879a75d074c92b62>:0 
  at Duplicati.Library.Main.Controller.List (System.Collections.Generic.IEnumerable`1[T] filterstrings, Duplicati.Library.Utility.IFilter filter) [0x00021] in <1d9349a5d6874088879a75d074c92b62>:0 
  at Duplicati.Server.Runner.Run (Duplicati.Server.Runner+IRunnerData data, System.Boolean fromQueue) [0x00374] in <3752ce5d8337471da6b77129cfa4bdbe>:0 
Jan 15, 2022 5:27 PM: Request for http://127.0.0.1:8196/api/v1/backup/12/files/*?prefix-only=true&folder-contents=false&time=2022-01-10T07:00:01-05:00 gave error
Mono.Data.Sqlite.SqliteException (0x80004005): The database file is locked
database is locked
  at Mono.Data.Sqlite.SQLite3.Step (Mono.Data.Sqlite.SqliteStatement stmt) [0x00089] in <83c72f6e53eb49f28420feee73a4aa07>:0 
  at Mono.Data.Sqlite.SqliteDataReader.NextResult () [0x00104] in <83c72f6e53eb49f28420feee73a4aa07>:0 
  at Mono.Data.Sqlite.SqliteDataReader..ctor (Mono.Data.Sqlite.SqliteCommand cmd, System.Data.CommandBehavior behave) [0x0004e] in <83c72f6e53eb49f28420feee73a4aa07>:0 
  at (wrapper remoting-invoke-with-check) Mono.Data.Sqlite.SqliteDataReader..ctor(Mono.Data.Sqlite.SqliteCommand,System.Data.CommandBehavior)
  at Mono.Data.Sqlite.SqliteCommand.ExecuteReader (System.Data.CommandBehavior behavior) [0x00006] in <83c72f6e53eb49f28420feee73a4aa07>:0 
  at Mono.Data.Sqlite.SqliteCommand.ExecuteDbDataReader (System.Data.CommandBehavior behavior) [0x00000] in <83c72f6e53eb49f28420feee73a4aa07>:0 
  at System.Data.Common.DbCommand.System.Data.IDbCommand.ExecuteReader () [0x00000] in <d3b33a5f75ba43539b447fcfaf55c885>:0 
  at Duplicati.Library.Main.Database.ExtensionMethods.ExecuteScalarInt64 (System.Data.IDbCommand self, System.Boolean writeLog, System.String cmd, System.Int64 defaultvalue, System.Object[] values) [0x00061] in <1d9349a5d6874088879a75d074c92b62>:0 
  at Duplicati.Library.Main.Database.ExtensionMethods.ExecuteScalarInt64 (System.Data.IDbCommand self, System.String cmd, System.Int64 defaultvalue, System.Object[] values) [0x00000] in <1d9349a5d6874088879a75d074c92b62>:0 
  at Duplicati.Library.Main.Database.LocalDatabase..ctor (System.Data.IDbConnection connection, System.String operation) [0x0005e] in <1d9349a5d6874088879a75d074c92b62>:0 
  at Duplicati.Library.Main.Database.LocalDatabase..ctor (System.String path, System.String operation, System.Boolean shouldclose) [0x00007] in <1d9349a5d6874088879a75d074c92b62>:0 
  at Duplicati.Library.Main.Database.LocalListDatabase..ctor (System.String path) [0x00000] in <1d9349a5d6874088879a75d074c92b62>:0 
  at Duplicati.Library.Main.Operation.ListFilesHandler.Run (System.Collections.Generic.IEnumerable`1[T] filterstrings, Duplicati.Library.Utility.IFilter compositefilter) [0x00075] in <1d9349a5d6874088879a75d074c92b62>:0 
  at Duplicati.Library.Main.Controller+<>c__DisplayClass21_0.<List>b__0 (Duplicati.Library.Main.ListResults result) [0x0001c] in <1d9349a5d6874088879a75d074c92b62>: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 <1d9349a5d6874088879a75d074c92b62>:0 
  at Duplicati.Library.Main.Controller.RunAction[T] (T result, Duplicati.Library.Utility.IFilter& filter, System.Action`1[T] method) [0x00007] in <1d9349a5d6874088879a75d074c92b62>:0 
  at Duplicati.Library.Main.Controller.List (System.Collections.Generic.IEnumerable`1[T] filterstrings, Duplicati.Library.Utility.IFilter filter) [0x00021] in <1d9349a5d6874088879a75d074c92b62>:0 
  at Duplicati.Server.Runner.Run (Duplicati.Server.Runner+IRunnerData data, System.Boolean fromQueue) [0x00668] in <3752ce5d8337471da6b77129cfa4bdbe>:0 
  at Duplicati.Server.WebServer.RESTMethods.Backup.SearchFiles (Duplicati.Server.Serialization.Interface.IBackup backup, System.String filterstring, Duplicati.Server.WebServer.RESTMethods.RequestInfo info) [0x000cb] in <3752ce5d8337471da6b77129cfa4bdbe>:0 
  at Duplicati.Server.WebServer.RESTMethods.Backup.GET (System.String key, Duplicati.Server.WebServer.RESTMethods.RequestInfo info) [0x001e0] in <3752ce5d8337471da6b77129cfa4bdbe>:0 
  at Duplicati.Server.WebServer.RESTHandler.DoProcess (Duplicati.Server.WebServer.RESTMethods.RequestInfo info, System.String method, System.String module, System.String key) [0x00146] in <3752ce5d8337471da6b77129cfa4bdbe>:0

zneumann · January 15, 2022, 11:09pm

It looks like Duplicati is using a longpoll=true&duration=299s as well.

These are the service startup settings the only flag passed is the webserver port to not conflict with other services (IceCast).

service duplicati status
● duplicati.service - Duplicati web-server
     Loaded: loaded (/lib/systemd/system/duplicati.service; enabled; vendor preset: enabled)
     Active: active (running) since Sat 2022-01-15 16:30:02 EST; 1h 38min ago
   Main PID: 3051497 (mono)
      Tasks: 29 (limit: 629145)
     Memory: 138.7M
     CGroup: /system.slice/duplicati.service
             ├─3051497 DuplicatiServer /usr/lib/duplicati/Duplicati.Server.exe --webservice-port=8196
             └─3053717 /usr/bin/mono-sgen /usr/share/Duplicati/updates/2.0.6.100/Duplicati.Server.exe --webservice-port=8196

ts678 · January 15, 2022, 11:13pm

That’s live log. Generally you have to start it and then do something. Log file setup is on Options screen.

This (like any stack trace) is good to see the path to the failure, but it doesn’t show what else is going on which potentially caused the failure, for example database work from some other thread. For even more

Restore fails with “Failed to connect: The database file is locked database is locked” links to a GitHub issue talking about threads, but stack trace is not like yours is, and I don’t know if you ever press Stop as in issue.

I’m not sure what action that causes. There’s a fair amount of simultaneous web work going into the server.
Running Wireshark on unencrypted localhost would catch it, but then you’d spend awhile trying to sort it out.

ts678 · January 15, 2022, 11:16pm

Sometimes it’s helpful to find the smallest backup that can show an issue. If nothing else, log is smaller.
I’m not sure if current path will succeed without more developer help, and developers are very scarce…

EDIT:

For comparison to yours, here’s my maximal profiling log file when I hit Restore button and it works OK:

2022-01-15 20:11:20 -05 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation List has started
2022-01-15 20:11:20 -05 - [Profiling-Timer.Begin-Duplicati.Library.Main.Controller-RunList]: Starting - Running List
2022-01-15 20:11:20 -05 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteScalarInt64]: Starting - ExecuteScalarInt64: INSERT INTO "Operation" ("Description", "Timestamp") VALUES ("List", 1642295480); SELECT last_insert_rowid();
2022-01-15 20:11:20 -05 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteScalarInt64]: ExecuteScalarInt64: INSERT INTO "Operation" ("Description", "Timestamp") VALUES ("List", 1642295480); SELECT last_insert_rowid(); took 0:00:00:00.075
2022-01-15 20:11:20 -05 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteReader]: Starting - ExecuteReader: SELECT "ID", "Timestamp" FROM "Fileset" ORDER BY "Timestamp" DESC
2022-01-15 20:11:20 -05 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteReader]: ExecuteReader: SELECT "ID", "Timestamp" FROM "Fileset" ORDER BY "Timestamp" DESC took 0:00:00:00.000
2022-01-15 20:11:20 -05 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: Starting - ExecuteNonQuery: CREATE TEMPORARY TABLE "Filesets-2B71CA0705475D459B2123BF74462B40" AS SELECT DISTINCT "ID" AS "FilesetID", "IsFullBackup" AS "IsFullBackup" , "Timestamp" AS "Timestamp" FROM "Fileset" 
2022-01-15 20:11:20 -05 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: ExecuteNonQuery: CREATE TEMPORARY TABLE "Filesets-2B71CA0705475D459B2123BF74462B40" AS SELECT DISTINCT "ID" AS "FilesetID", "IsFullBackup" AS "IsFullBackup" , "Timestamp" AS "Timestamp" FROM "Fileset"  took 0:00:00:00.000
2022-01-15 20:11:20 -05 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: Starting - ExecuteNonQuery: CREATE INDEX "Filesets-2B71CA0705475D459B2123BF74462B40_FilesetIDTimestampIndex" ON "Filesets-2B71CA0705475D459B2123BF74462B40" ("FilesetID", "Timestamp" DESC)
2022-01-15 20:11:20 -05 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: ExecuteNonQuery: CREATE INDEX "Filesets-2B71CA0705475D459B2123BF74462B40_FilesetIDTimestampIndex" ON "Filesets-2B71CA0705475D459B2123BF74462B40" ("FilesetID", "Timestamp" DESC) took 0:00:00:00.000
2022-01-15 20:11:20 -05 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteReader]: Starting - ExecuteReader: SELECT DISTINCT "ID", "IsFullBackup" FROM "Fileset" ORDER BY "Timestamp" DESC 
2022-01-15 20:11:20 -05 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteReader]: ExecuteReader: SELECT DISTINCT "ID", "IsFullBackup" FROM "Fileset" ORDER BY "Timestamp" DESC  took 0:00:00:00.000
2022-01-15 20:11:20 -05 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: Starting - ExecuteNonQuery: DROP TABLE IF EXISTS "Filesets-2B71CA0705475D459B2123BF74462B40" 
2022-01-15 20:11:20 -05 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: ExecuteNonQuery: DROP TABLE IF EXISTS "Filesets-2B71CA0705475D459B2123BF74462B40"  took 0:00:00:00.000
2022-01-15 20:11:20 -05 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: Starting - ExecuteNonQuery: PRAGMA optimize
2022-01-15 20:11:20 -05 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: ExecuteNonQuery: PRAGMA optimize took 0:00:00:00.000
2022-01-15 20:11:20 -05 - [Profiling-Timer.Finished-Duplicati.Library.Main.Controller-RunList]: Running List took 0:00:00:00.084
2022-01-15 20:11:20 -05 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation List has started
2022-01-15 20:11:20 -05 - [Profiling-Timer.Begin-Duplicati.Library.Main.Controller-RunList]: Starting - Running List
2022-01-15 20:11:20 -05 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteScalarInt64]: Starting - ExecuteScalarInt64: INSERT INTO "Operation" ("Description", "Timestamp") VALUES ("List", 1642295480); SELECT last_insert_rowid();
2022-01-15 20:11:20 -05 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteScalarInt64]: ExecuteScalarInt64: INSERT INTO "Operation" ("Description", "Timestamp") VALUES ("List", 1642295480); SELECT last_insert_rowid(); took 0:00:00:00.084
2022-01-15 20:11:20 -05 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteReader]: Starting - ExecuteReader: SELECT "ID", "Timestamp" FROM "Fileset" ORDER BY "Timestamp" DESC
2022-01-15 20:11:20 -05 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteReader]: ExecuteReader: SELECT "ID", "Timestamp" FROM "Fileset" ORDER BY "Timestamp" DESC took 0:00:00:00.000
2022-01-15 20:11:20 -05 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: Starting - ExecuteNonQuery: CREATE TEMPORARY TABLE "Filesets-0CD3B441684AD545A7B348B8F9B54714" AS SELECT DISTINCT "ID" AS "FilesetID", "IsFullBackup" AS "IsFullBackup" , "Timestamp" AS "Timestamp" FROM "Fileset"  WHERE  "Timestamp" <= 1639969879
2022-01-15 20:11:20 -05 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: ExecuteNonQuery: CREATE TEMPORARY TABLE "Filesets-0CD3B441684AD545A7B348B8F9B54714" AS SELECT DISTINCT "ID" AS "FilesetID", "IsFullBackup" AS "IsFullBackup" , "Timestamp" AS "Timestamp" FROM "Fileset"  WHERE  "Timestamp" <= 1639969879 took 0:00:00:00.000
2022-01-15 20:11:20 -05 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: Starting - ExecuteNonQuery: CREATE INDEX "Filesets-0CD3B441684AD545A7B348B8F9B54714_FilesetIDTimestampIndex" ON "Filesets-0CD3B441684AD545A7B348B8F9B54714" ("FilesetID", "Timestamp" DESC)
2022-01-15 20:11:20 -05 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: ExecuteNonQuery: CREATE INDEX "Filesets-0CD3B441684AD545A7B348B8F9B54714_FilesetIDTimestampIndex" ON "Filesets-0CD3B441684AD545A7B348B8F9B54714" ("FilesetID", "Timestamp" DESC) took 0:00:00:00.000
2022-01-15 20:11:20 -05 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: Starting - ExecuteNonQuery: DELETE FROM "Filesets-0CD3B441684AD545A7B348B8F9B54714" WHERE "FilesetID" NOT IN (SELECT "FilesetID" FROM "Filesets-0CD3B441684AD545A7B348B8F9B54714" ORDER BY "Timestamp" DESC LIMIT 1 )
2022-01-15 20:11:20 -05 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: ExecuteNonQuery: DELETE FROM "Filesets-0CD3B441684AD545A7B348B8F9B54714" WHERE "FilesetID" NOT IN (SELECT "FilesetID" FROM "Filesets-0CD3B441684AD545A7B348B8F9B54714" ORDER BY "Timestamp" DESC LIMIT 1 ) took 0:00:00:00.000
2022-01-15 20:11:20 -05 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: Starting - ExecuteNonQuery: CREATE TEMPORARY TABLE "Filenames-FB912B459B475A4DB189B19D714D3C56" ("Path" TEXT NOT NULL)
2022-01-15 20:11:20 -05 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: ExecuteNonQuery: CREATE TEMPORARY TABLE "Filenames-FB912B459B475A4DB189B19D714D3C56" ("Path" TEXT NOT NULL) took 0:00:00:00.000
2022-01-15 20:11:20 -05 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: Starting - ExecuteNonQuery: INSERT INTO "Filenames-FB912B459B475A4DB189B19D714D3C56" SELECT DISTINCT "Path" FROM "File" WHERE "Path" LIKE "%"
2022-01-15 20:11:20 -05 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: ExecuteNonQuery: INSERT INTO "Filenames-FB912B459B475A4DB189B19D714D3C56" SELECT DISTINCT "Path" FROM "File" WHERE "Path" LIKE "%" took 0:00:00:00.000
2022-01-15 20:11:20 -05 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: Starting - ExecuteNonQuery: DELETE FROM "Filenames-FB912B459B475A4DB189B19D714D3C56" WHERE "Path" NOT IN (SELECT DISTINCT "Path" FROM "File", "FilesetEntry" WHERE "FilesetEntry"."FileID" = "File"."ID" AND "FilesetEntry"."FilesetID" IN (SELECT "FilesetID" FROM "Filesets-0CD3B441684AD545A7B348B8F9B54714") ) 
2022-01-15 20:11:20 -05 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: ExecuteNonQuery: DELETE FROM "Filenames-FB912B459B475A4DB189B19D714D3C56" WHERE "Path" NOT IN (SELECT DISTINCT "Path" FROM "File", "FilesetEntry" WHERE "FilesetEntry"."FileID" = "File"."ID" AND "FilesetEntry"."FilesetID" IN (SELECT "FilesetID" FROM "Filesets-0CD3B441684AD545A7B348B8F9B54714") )  took 0:00:00:00.000
2022-01-15 20:11:20 -05 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteScalarInt64]: Starting - ExecuteScalarInt64: SELECT COUNT(*) FROM "Filenames-FB912B459B475A4DB189B19D714D3C56"
2022-01-15 20:11:20 -05 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteScalarInt64]: ExecuteScalarInt64: SELECT COUNT(*) FROM "Filenames-FB912B459B475A4DB189B19D714D3C56" took 0:00:00:00.000
2022-01-15 20:11:20 -05 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteScalarInt64]: Starting - ExecuteScalarInt64: SELECT COUNT(*) FROM "Filenames-FB912B459B475A4DB189B19D714D3C56" WHERE SUBSTR("Path", 1, 23) = "C:\backup source\A.txt\"
2022-01-15 20:11:20 -05 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteScalarInt64]: ExecuteScalarInt64: SELECT COUNT(*) FROM "Filenames-FB912B459B475A4DB189B19D714D3C56" WHERE SUBSTR("Path", 1, 23) = "C:\backup source\A.txt\" took 0:00:00:00.000
2022-01-15 20:11:20 -05 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteScalarInt64]: Starting - ExecuteScalarInt64: SELECT COUNT(*) FROM "Filenames-FB912B459B475A4DB189B19D714D3C56" WHERE SUBSTR("Path", 1, 17) = "C:\backup source\"
2022-01-15 20:11:20 -05 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteScalarInt64]: ExecuteScalarInt64: SELECT COUNT(*) FROM "Filenames-FB912B459B475A4DB189B19D714D3C56" WHERE SUBSTR("Path", 1, 17) = "C:\backup source\" took 0:00:00:00.000
2022-01-15 20:11:20 -05 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: Starting - ExecuteNonQuery: DROP TABLE IF EXISTS "Filenames-FB912B459B475A4DB189B19D714D3C56" 
2022-01-15 20:11:20 -05 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: ExecuteNonQuery: DROP TABLE IF EXISTS "Filenames-FB912B459B475A4DB189B19D714D3C56"  took 0:00:00:00.000
2022-01-15 20:11:20 -05 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteReader]: Starting - ExecuteReader: SELECT DISTINCT "A"."FilesetID", "A"."IsFullBackup", "B"."FileCount", "B"."FileSizes" FROM "Filesets-0CD3B441684AD545A7B348B8F9B54714" A LEFT OUTER JOIN ( SELECT "A"."FilesetID" AS "FilesetID", COUNT(*) AS "FileCount", SUM("C"."Length") AS "FileSizes" FROM "FilesetEntry" A, "File" B, "Blockset" C WHERE "A"."FileID" = "B"."ID" AND "B"."BlocksetID" = "C"."ID" AND "A"."FilesetID" IN (SELECT DISTINCT "FilesetID" FROM "Filesets-0CD3B441684AD545A7B348B8F9B54714") GROUP BY "A"."FilesetID"  ) B ON "A"."FilesetID" = "B"."FilesetID" ORDER BY "A"."Timestamp" DESC 
2022-01-15 20:11:20 -05 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteReader]: ExecuteReader: SELECT DISTINCT "A"."FilesetID", "A"."IsFullBackup", "B"."FileCount", "B"."FileSizes" FROM "Filesets-0CD3B441684AD545A7B348B8F9B54714" A LEFT OUTER JOIN ( SELECT "A"."FilesetID" AS "FilesetID", COUNT(*) AS "FileCount", SUM("C"."Length") AS "FileSizes" FROM "FilesetEntry" A, "File" B, "Blockset" C WHERE "A"."FileID" = "B"."ID" AND "B"."BlocksetID" = "C"."ID" AND "A"."FilesetID" IN (SELECT DISTINCT "FilesetID" FROM "Filesets-0CD3B441684AD545A7B348B8F9B54714") GROUP BY "A"."FilesetID"  ) B ON "A"."FilesetID" = "B"."FilesetID" ORDER BY "A"."Timestamp" DESC  took 0:00:00:00.000
2022-01-15 20:11:20 -05 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: Starting - ExecuteNonQuery: DROP TABLE IF EXISTS "Filesets-0CD3B441684AD545A7B348B8F9B54714" 
2022-01-15 20:11:20 -05 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: ExecuteNonQuery: DROP TABLE IF EXISTS "Filesets-0CD3B441684AD545A7B348B8F9B54714"  took 0:00:00:00.000
2022-01-15 20:11:20 -05 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: Starting - ExecuteNonQuery: PRAGMA optimize
2022-01-15 20:11:20 -05 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: ExecuteNonQuery: PRAGMA optimize took 0:00:00:00.000
2022-01-15 20:11:20 -05 - [Profiling-Timer.Finished-Duplicati.Library.Main.Controller-RunList]: Running List took 0:00:00:00.090
2022-01-15 20:11:20 -05 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation List has started
2022-01-15 20:11:20 -05 - [Profiling-Timer.Begin-Duplicati.Library.Main.Controller-RunList]: Starting - Running List
2022-01-15 20:11:20 -05 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteScalarInt64]: Starting - ExecuteScalarInt64: INSERT INTO "Operation" ("Description", "Timestamp") VALUES ("List", 1642295480); SELECT last_insert_rowid();
2022-01-15 20:11:21 -05 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteScalarInt64]: ExecuteScalarInt64: INSERT INTO "Operation" ("Description", "Timestamp") VALUES ("List", 1642295480); SELECT last_insert_rowid(); took 0:00:00:00.110
2022-01-15 20:11:21 -05 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteReader]: Starting - ExecuteReader: SELECT "ID", "Timestamp" FROM "Fileset" ORDER BY "Timestamp" DESC
2022-01-15 20:11:21 -05 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteReader]: ExecuteReader: SELECT "ID", "Timestamp" FROM "Fileset" ORDER BY "Timestamp" DESC took 0:00:00:00.000
2022-01-15 20:11:21 -05 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: Starting - ExecuteNonQuery: CREATE TEMPORARY TABLE "Filesets-43B68CC1AE30DE4ABD3A626B94D57F2E" AS SELECT DISTINCT "ID" AS "FilesetID", "IsFullBackup" AS "IsFullBackup" , "Timestamp" AS "Timestamp" FROM "Fileset"  WHERE  "Timestamp" <= 1639969879
2022-01-15 20:11:21 -05 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: ExecuteNonQuery: CREATE TEMPORARY TABLE "Filesets-43B68CC1AE30DE4ABD3A626B94D57F2E" AS SELECT DISTINCT "ID" AS "FilesetID", "IsFullBackup" AS "IsFullBackup" , "Timestamp" AS "Timestamp" FROM "Fileset"  WHERE  "Timestamp" <= 1639969879 took 0:00:00:00.000
2022-01-15 20:11:21 -05 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: Starting - ExecuteNonQuery: CREATE INDEX "Filesets-43B68CC1AE30DE4ABD3A626B94D57F2E_FilesetIDTimestampIndex" ON "Filesets-43B68CC1AE30DE4ABD3A626B94D57F2E" ("FilesetID", "Timestamp" DESC)
2022-01-15 20:11:21 -05 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: ExecuteNonQuery: CREATE INDEX "Filesets-43B68CC1AE30DE4ABD3A626B94D57F2E_FilesetIDTimestampIndex" ON "Filesets-43B68CC1AE30DE4ABD3A626B94D57F2E" ("FilesetID", "Timestamp" DESC) took 0:00:00:00.000
2022-01-15 20:11:21 -05 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: Starting - ExecuteNonQuery: DELETE FROM "Filesets-43B68CC1AE30DE4ABD3A626B94D57F2E" WHERE "FilesetID" NOT IN (SELECT "FilesetID" FROM "Filesets-43B68CC1AE30DE4ABD3A626B94D57F2E" ORDER BY "Timestamp" DESC LIMIT 1 )
2022-01-15 20:11:21 -05 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: ExecuteNonQuery: DELETE FROM "Filesets-43B68CC1AE30DE4ABD3A626B94D57F2E" WHERE "FilesetID" NOT IN (SELECT "FilesetID" FROM "Filesets-43B68CC1AE30DE4ABD3A626B94D57F2E" ORDER BY "Timestamp" DESC LIMIT 1 ) took 0:00:00:00.000
2022-01-15 20:11:21 -05 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteReader]: Starting - ExecuteReader: SELECT DISTINCT "A"."FilesetID", "A"."IsFullBackup", "B"."FileCount", "B"."FileSizes" FROM "Filesets-43B68CC1AE30DE4ABD3A626B94D57F2E" A LEFT OUTER JOIN ( SELECT "A"."FilesetID" AS "FilesetID", COUNT(*) AS "FileCount", SUM("C"."Length") AS "FileSizes" FROM "FilesetEntry" A, "File" B, "Blockset" C WHERE "A"."FileID" = "B"."ID" AND "B"."BlocksetID" = "C"."ID" AND "A"."FilesetID" IN (SELECT DISTINCT "FilesetID" FROM "Filesets-43B68CC1AE30DE4ABD3A626B94D57F2E") GROUP BY "A"."FilesetID"  ) B ON "A"."FilesetID" = "B"."FilesetID" ORDER BY "A"."Timestamp" DESC 
2022-01-15 20:11:21 -05 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteReader]: ExecuteReader: SELECT DISTINCT "A"."FilesetID", "A"."IsFullBackup", "B"."FileCount", "B"."FileSizes" FROM "Filesets-43B68CC1AE30DE4ABD3A626B94D57F2E" A LEFT OUTER JOIN ( SELECT "A"."FilesetID" AS "FilesetID", COUNT(*) AS "FileCount", SUM("C"."Length") AS "FileSizes" FROM "FilesetEntry" A, "File" B, "Blockset" C WHERE "A"."FileID" = "B"."ID" AND "B"."BlocksetID" = "C"."ID" AND "A"."FilesetID" IN (SELECT DISTINCT "FilesetID" FROM "Filesets-43B68CC1AE30DE4ABD3A626B94D57F2E") GROUP BY "A"."FilesetID"  ) B ON "A"."FilesetID" = "B"."FilesetID" ORDER BY "A"."Timestamp" DESC  took 0:00:00:00.000
2022-01-15 20:11:21 -05 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: Starting - ExecuteNonQuery: CREATE TEMPORARY TABLE "Filenames-558391EFCE46544098E69EDFF4871BE3" ("Path" TEXT NOT NULL)
2022-01-15 20:11:21 -05 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: ExecuteNonQuery: CREATE TEMPORARY TABLE "Filenames-558391EFCE46544098E69EDFF4871BE3" ("Path" TEXT NOT NULL) took 0:00:00:00.000
2022-01-15 20:11:21 -05 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: Starting - ExecuteNonQuery: INSERT INTO "Filenames-558391EFCE46544098E69EDFF4871BE3" SELECT DISTINCT "Path" FROM "File" WHERE "Path" LIKE "C:\BACKUP SOURCE\%"
2022-01-15 20:11:21 -05 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: ExecuteNonQuery: INSERT INTO "Filenames-558391EFCE46544098E69EDFF4871BE3" SELECT DISTINCT "Path" FROM "File" WHERE "Path" LIKE "C:\BACKUP SOURCE\%" took 0:00:00:00.000
2022-01-15 20:11:21 -05 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: Starting - ExecuteNonQuery: DELETE FROM "Filenames-558391EFCE46544098E69EDFF4871BE3" WHERE "Path" NOT IN (SELECT DISTINCT "Path" FROM "File", "FilesetEntry" WHERE "FilesetEntry"."FileID" = "File"."ID" AND "FilesetEntry"."FilesetID" IN (SELECT "FilesetID" FROM "Filesets-43B68CC1AE30DE4ABD3A626B94D57F2E") ) 
2022-01-15 20:11:21 -05 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: ExecuteNonQuery: DELETE FROM "Filenames-558391EFCE46544098E69EDFF4871BE3" WHERE "Path" NOT IN (SELECT DISTINCT "Path" FROM "File", "FilesetEntry" WHERE "FilesetEntry"."FileID" = "File"."ID" AND "FilesetEntry"."FilesetID" IN (SELECT "FilesetID" FROM "Filesets-43B68CC1AE30DE4ABD3A626B94D57F2E") )  took 0:00:00:00.000
2022-01-15 20:11:21 -05 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: Starting - ExecuteNonQuery: CREATE TEMPORARY TABLE "Filenames-1BFE49F5FB7587409B162638F350F20E" ("Path" TEXT NOT NULL)
2022-01-15 20:11:21 -05 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: ExecuteNonQuery: CREATE TEMPORARY TABLE "Filenames-1BFE49F5FB7587409B162638F350F20E" ("Path" TEXT NOT NULL) took 0:00:00:00.000
2022-01-15 20:11:21 -05 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteReader]: Starting - ExecuteReader: SELECT DISTINCT "Path" FROM "Filenames-558391EFCE46544098E69EDFF4871BE3" 
2022-01-15 20:11:21 -05 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteReader]: ExecuteReader: SELECT DISTINCT "Path" FROM "Filenames-558391EFCE46544098E69EDFF4871BE3"  took 0:00:00:00.000
2022-01-15 20:11:21 -05 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: Starting - ExecuteNonQuery: CREATE INDEX "Filenames-1BFE49F5FB7587409B162638F350F20E_PathIndex" ON "Filenames-1BFE49F5FB7587409B162638F350F20E" ("Path")
2022-01-15 20:11:21 -05 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: ExecuteNonQuery: CREATE INDEX "Filenames-1BFE49F5FB7587409B162638F350F20E_PathIndex" ON "Filenames-1BFE49F5FB7587409B162638F350F20E" ("Path") took 0:00:00:00.000
2022-01-15 20:11:21 -05 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteReader]: Starting - ExecuteReader: SELECT "C"."Path", "D"."Length", "C"."FilesetID" FROM (SELECT "A"."Path", "B"."FilesetID" FROM "Filenames-1BFE49F5FB7587409B162638F350F20E" A, (SELECT "FilesetID", "Timestamp" FROM "Filesets-43B68CC1AE30DE4ABD3A626B94D57F2E" ORDER BY "Timestamp" DESC) B ORDER BY "A"."Path" ASC, "B"."Timestamp" DESC) C LEFT OUTER JOIN (SELECT "Length", "FilesetEntry"."FilesetID", "File"."Path" FROM "Blockset", "FilesetEntry", "File" WHERE "File"."BlocksetID" = "Blockset"."ID" AND "FilesetEntry"."FileID" = "File"."ID" AND FilesetEntry."FilesetID" IN (SELECT DISTINCT "FilesetID" FROM "Filesets-43B68CC1AE30DE4ABD3A626B94D57F2E") ) D ON "C"."FilesetID" = "D"."FilesetID" AND "C"."Path" = "D"."Path"
2022-01-15 20:11:21 -05 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteReader]: ExecuteReader: SELECT "C"."Path", "D"."Length", "C"."FilesetID" FROM (SELECT "A"."Path", "B"."FilesetID" FROM "Filenames-1BFE49F5FB7587409B162638F350F20E" A, (SELECT "FilesetID", "Timestamp" FROM "Filesets-43B68CC1AE30DE4ABD3A626B94D57F2E" ORDER BY "Timestamp" DESC) B ORDER BY "A"."Path" ASC, "B"."Timestamp" DESC) C LEFT OUTER JOIN (SELECT "Length", "FilesetEntry"."FilesetID", "File"."Path" FROM "Blockset", "FilesetEntry", "File" WHERE "File"."BlocksetID" = "Blockset"."ID" AND "FilesetEntry"."FileID" = "File"."ID" AND FilesetEntry."FilesetID" IN (SELECT DISTINCT "FilesetID" FROM "Filesets-43B68CC1AE30DE4ABD3A626B94D57F2E") ) D ON "C"."FilesetID" = "D"."FilesetID" AND "C"."Path" = "D"."Path" took 0:00:00:00.000
2022-01-15 20:11:21 -05 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: Starting - ExecuteNonQuery: DROP TABLE IF EXISTS "Filenames-558391EFCE46544098E69EDFF4871BE3" 
2022-01-15 20:11:21 -05 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: ExecuteNonQuery: DROP TABLE IF EXISTS "Filenames-558391EFCE46544098E69EDFF4871BE3"  took 0:00:00:00.000
2022-01-15 20:11:21 -05 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: Starting - ExecuteNonQuery: DROP TABLE IF EXISTS "Filenames-1BFE49F5FB7587409B162638F350F20E"
2022-01-15 20:11:21 -05 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: ExecuteNonQuery: DROP TABLE IF EXISTS "Filenames-1BFE49F5FB7587409B162638F350F20E" took 0:00:00:00.000
2022-01-15 20:11:21 -05 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: Starting - ExecuteNonQuery: DROP TABLE IF EXISTS "Filesets-43B68CC1AE30DE4ABD3A626B94D57F2E" 
2022-01-15 20:11:21 -05 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: ExecuteNonQuery: DROP TABLE IF EXISTS "Filesets-43B68CC1AE30DE4ABD3A626B94D57F2E"  took 0:00:00:00.000
2022-01-15 20:11:21 -05 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: Starting - ExecuteNonQuery: PRAGMA optimize
2022-01-15 20:11:21 -05 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: ExecuteNonQuery: PRAGMA optimize took 0:00:00:00.000
2022-01-15 20:11:21 -05 - [Profiling-Timer.Finished-Duplicati.Library.Main.Controller-RunList]: Running List took 0:00:00:00.117