2.0.5.108_canary_2020-07-09 has started hanging on backup to NAS

Support
1

hi all.
upgraded to the above version soon after it was released and have had no issues.
today however my backup to NAS has stalled and won’t get past a certain point.

here’s the log when it is stuck on 19.93 MB to go (i removed some AMD cache errors which have always been there and haven’t stopped the backup before). it never gets past this point today. have killed the process and restarted it. connection to the NAS is fine. cheers.

{
“DeletedFiles”: 316,
“DeletedFolders”: 167,
“ModifiedFiles”: 376,
“ExaminedFiles”: 78212,
“OpenedFiles”: 768,
“AddedFiles”: 392,
“SizeOfModifiedFiles”: 5021508732,
“SizeOfAddedFiles”: 163844837,
“SizeOfExaminedFiles”: 19724456953,
“SizeOfOpenedFiles”: 5194068037,
“NotProcessedFiles”: 0,
“AddedFolders”: 29,
“TooLargeFiles”: 0,
“FilesWithError”: 0,
“ModifiedFolders”: 0,
“ModifiedSymlinks”: 0,
“AddedSymlinks”: 0,
“DeletedSymlinks”: 0,
“PartialBackup”: false,
“Dryrun”: false,
“MainOperation”: “Backup”,
“CompactResults”: null,
“VacuumResults”: null,
“DeleteResults”: {
“DeletedSetsActualLength”: 0,
“DeletedSets”: ,
“Dryrun”: false,
“MainOperation”: “Delete”,
“CompactResults”: null,
“ParsedResult”: “Success”,
“Version”: “2.0.5.108 (2.0.5.108_canary_2020-07-09)”,
“EndTime”: “2020-07-18T15:00:30.0770733Z”,
“BeginTime”: “2020-07-18T15:00:20.3533655Z”,
“Duration”: “00:00:09.7237078”,
“MessagesActualLength”: 0,
“WarningsActualLength”: 0,
“ErrorsActualLength”: 0,
“Messages”: null,
“Warnings”: null,
“Errors”: null,
“BackendStatistics”: {
“RemoteCalls”: 24,
“BytesUploaded”: 2681190135,
“BytesDownloaded”: 321837655,
“FilesUploaded”: 19,
“FilesDownloaded”: 3,
“FilesDeleted”: 0,
“FoldersCreated”: 0,
“RetryAttempts”: 0,
“UnknownFileSize”: 0,
“UnknownFileCount”: 0,
“KnownFileCount”: 397,
“KnownFileSize”: 46087567609,
“LastBackupDate”: “2020-07-18T15:45:01+01:00”,
“BackupListCount”: 54,
“TotalQuotaSpace”: 3990861381632,
“FreeQuotaSpace”: 1742279270400,
“AssignedQuotaSpace”: -1,
“ReportedQuotaError”: false,
“ReportedQuotaWarning”: false,
“MainOperation”: “Backup”,
“ParsedResult”: “Success”,
“Version”: “2.0.5.108 (2.0.5.108_canary_2020-07-09)”,
“EndTime”: “0001-01-01T00:00:00”,
“BeginTime”: “2020-07-18T14:45:00.6001798Z”,
“Duration”: “00:00:00”,
“MessagesActualLength”: 0,
“WarningsActualLength”: 0,
“ErrorsActualLength”: 0,
“Messages”: null,
“Warnings”: null,
“Errors”: null
}
},
“RepairResults”: null,
“TestResults”: {
“MainOperation”: “Test”,
“VerificationsActualLength”: 3,
“Verifications”: [
{
“Key”: “duplicati-20200716T144508Z.dlist.zip.aes”,
“Value”:
},
{
“Key”: “duplicati-i7ca682464c0841f7ae45d185ef974d0f.dindex.zip.aes”,
“Value”:
},
{
“Key”: “duplicati-b37ff6ed1439441c5b9bf90c38d1576bc.dblock.zip.aes”,
“Value”:
}
],
“ParsedResult”: “Success”,
“Version”: “2.0.5.108 (2.0.5.108_canary_2020-07-09)”,
“EndTime”: “2020-07-18T15:01:29.6835655Z”,
“BeginTime”: “2020-07-18T15:00:38.1184401Z”,
“Duration”: “00:00:51.5651254”,
“MessagesActualLength”: 0,
“WarningsActualLength”: 0,
“ErrorsActualLength”: 0,
“Messages”: null,
“Warnings”: null,
“Errors”: null,
“BackendStatistics”: {
“RemoteCalls”: 24,
“BytesUploaded”: 2681190135,
“BytesDownloaded”: 321837655,
“FilesUploaded”: 19,
“FilesDownloaded”: 3,
“FilesDeleted”: 0,
“FoldersCreated”: 0,
“RetryAttempts”: 0,
“UnknownFileSize”: 0,
“UnknownFileCount”: 0,
“KnownFileCount”: 397,
“KnownFileSize”: 46087567609,
“LastBackupDate”: “2020-07-18T15:45:01+01:00”,
“BackupListCount”: 54,
“TotalQuotaSpace”: 3990861381632,
“FreeQuotaSpace”: 1742279270400,
“AssignedQuotaSpace”: -1,
“ReportedQuotaError”: false,
“ReportedQuotaWarning”: false,
“MainOperation”: “Backup”,
“ParsedResult”: “Success”,
“Version”: “2.0.5.108 (2.0.5.108_canary_2020-07-09)”,
“EndTime”: “0001-01-01T00:00:00”,
“BeginTime”: “2020-07-18T14:45:00.6001798Z”,
“Duration”: “00:00:00”,
“MessagesActualLength”: 0,
“WarningsActualLength”: 0,
“ErrorsActualLength”: 0,
“Messages”: null,
“Warnings”: null,
“Errors”: null
}
},
“ParsedResult”: “Warning”,
“Version”: “2.0.5.108 (2.0.5.108_canary_2020-07-09)”,
“EndTime”: “2020-07-18T15:01:29.7473257Z”,
“BeginTime”: “2020-07-18T14:45:00.5991972Z”,
“Duration”: “00:16:29.1481285”,
“MessagesActualLength”: 50,
“WarningsActualLength”: 24,
“ErrorsActualLength”: 0,
“Messages”: [
“2020-07-18 15:45:01 +01 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation Backup has started”,
“2020-07-18 15:47:15 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started: ()”,
“2020-07-18 15:47:36 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Completed: (378 bytes)”,
“2020-07-18 15:52:36 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-b7ad152d0f38247e1ab9ccd62666b65f4.dblock.zip.aes (299.90 MB)”,
“2020-07-18 15:52:37 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-b1f84068c0f5e4bcd952eab39dc0f7452.dblock.zip.aes (299.94 MB)”,
“2020-07-18 15:54:08 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-b1f84068c0f5e4bcd952eab39dc0f7452.dblock.zip.aes (299.94 MB)”,
“2020-07-18 15:54:08 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-i07cde9427b324d6bbb8712695c191c06.dindex.zip.aes (324.39 KB)”,
“2020-07-18 15:54:10 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-i07cde9427b324d6bbb8712695c191c06.dindex.zip.aes (324.39 KB)”,
“2020-07-18 15:54:12 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-b7ad152d0f38247e1ab9ccd62666b65f4.dblock.zip.aes (299.90 MB)”,
“2020-07-18 15:54:14 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-ifa21161030ad4a198fc4e9f9318c6013.dindex.zip.aes (318.98 KB)”,
“2020-07-18 15:54:14 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-ifa21161030ad4a198fc4e9f9318c6013.dindex.zip.aes (318.98 KB)”,
“2020-07-18 15:54:21 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-bc896202e1d45420c93381bd7fdc52df0.dblock.zip.aes (299.97 MB)”,
“2020-07-18 15:54:22 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-bf1a0a7264dc44db88f2d8c406911fea7.dblock.zip.aes (299.93 MB)”,
“2020-07-18 15:55:50 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-bc896202e1d45420c93381bd7fdc52df0.dblock.zip.aes (299.97 MB)”,
“2020-07-18 15:55:51 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-i68e51da257984eb099e32a28021798ad.dindex.zip.aes (356.79 KB)”,
“2020-07-18 15:55:52 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-i68e51da257984eb099e32a28021798ad.dindex.zip.aes (356.79 KB)”,
“2020-07-18 15:56:00 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-bdead671b0b7347f2b0f45e68c8f6e684.dblock.zip.aes (299.95 MB)”,
“2020-07-18 15:56:01 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-bf1a0a7264dc44db88f2d8c406911fea7.dblock.zip.aes (299.93 MB)”,
“2020-07-18 15:56:02 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-i4314e8847f6d4ea9afb56b81e46c104d.dindex.zip.aes (356.65 KB)”,
“2020-07-18 15:56:03 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-i4314e8847f6d4ea9afb56b81e46c104d.dindex.zip.aes (356.65 KB)”
],

],
“Errors”: ,
“BackendStatistics”: {
“RemoteCalls”: 24,
“BytesUploaded”: 2681190135,
“BytesDownloaded”: 321837655,
“FilesUploaded”: 19,
“FilesDownloaded”: 3,
“FilesDeleted”: 0,
“FoldersCreated”: 0,
“RetryAttempts”: 0,
“UnknownFileSize”: 0,
“UnknownFileCount”: 0,
“KnownFileCount”: 397,
“KnownFileSize”: 46087567609,
“LastBackupDate”: “2020-07-18T15:45:01+01:00”,
“BackupListCount”: 54,
“TotalQuotaSpace”: 3990861381632,
“FreeQuotaSpace”: 1742279270400,
“AssignedQuotaSpace”: -1,
“ReportedQuotaError”: false,
“ReportedQuotaWarning”: false,
“MainOperation”: “Backup”,
“ParsedResult”: “Success”,
“Version”: “2.0.5.108 (2.0.5.108_canary_2020-07-09)”,
“EndTime”: “0001-01-01T00:00:00”,
“BeginTime”: “2020-07-18T14:45:00.6001798Z”,
“Duration”: “00:00:00”,
“MessagesActualLength”: 0,
“WarningsActualLength”: 0,
“ErrorsActualLength”: 0,
“Messages”: null,
“Warnings”: null,
“Errors”: null
}
}

2

reintalled the same version. ran backup and this time it’s

with the following in the log

code = Unknown (-1), message = System.Data.SQLite.SQLiteException (0x80004005): unknown error

No transaction is active on this connection

at System.Data.SQLite.SQLiteTransactionBase.IsValid(Boolean throwError)

at System.Data.SQLite.SQLiteTransaction.Commit()

at Duplicati.Library.Main.Operation.Common.DatabaseCommon.Dispose(Boolean isDisposing)

at Duplicati.Library.Main.Operation.BackupHandler.d__20.MoveNext()

— End of stack trace from previous location where exception was thrown —

at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()

at CoCoL.ChannelExtensions.WaitForTaskOrThrow(Task task)

at Duplicati.Library.Main.Controller.<>c__DisplayClass14_0.b__0(BackupResults result)

at Duplicati.Library.Main.Controller.RunAction[T](T result, String& paths, IFilter& filter, Action`1 method)

at Duplicati.Library.Main.Controller.Backup(String inputsources, IFilter filter)

at Duplicati.Server.Runner.Run(IRunnerData data, Boolean fromQueue)

3

Right away or after doing enough (e.g. as seen in the GUI) that it looked like it was near end of backup?

Was the system restarted before that run, or was Task Manager checked for any old leftover Duplicati?

I assume you didn’t also start-fresh backup. Does the Database screen’s Local database path say

image

(the Current file in original post, without the -journal suffix) If so, and if you can get back to original problem, then excluding that sqlite file and any suffixed versions (* can be used as a wildcard) may help.

There’s no point in backing up the database for a given job while the job is running – it’ll be stale instantly. Possibly attempting to read it for backup interferes with Duplicati trying to write data to it. Might deadlock.

1 Like
4

thanks for the reply and info.
the backup never got to the end of the run even after leaving it for an hour.
i killed all duplicati instances in task manager (2 of them). restarted the laptop. deleted and recreated the database.
i had never thought that the *.sqlite files would be an issue in the backup. i’m only really backing them up because they’re in AppData (which i exclude lots of files from) and they’d never caused issues before. am trying a run now with them excluded.

5

completed 2 backup runs without them hanging or throwing any errors after excluding the sqlite files.
unsure why the same backups ran for 2 months without there being a problem with the duplicati databases being included but i’m not complaining right now.
appreciate your input on this and send my thanks.

1 Like