Can't create a new backup without errors


#1

I’m running Duplicati - 2.0.4.12_canary_2019-01-16.

A few months ago I put Duplicati on hold because I was getting “archive rot” - an increasing number of verification errors.

I did a clean install of Duplicati today and tried running a new backup, both to ssh/ftp and to a local disk.

Both cases ended with the following warning and errors:

Warnings 1

2019-01-17 12:30:04 -05 - [Warning-Duplicati.Library.Main.Operation.Backup.FileBlockProcessor.FileEntry-PathProcessingFailed]: Failed to process path: /home/sylerner/.config/Duplicati/68788278886971887374.sqlite-journal

Errors 2

2019-01-17 12:30:04 -05 - [Error-Duplicati.Library.Main.Database.LocalBackupDatabase-CheckingErrorsForIssue1400]: Checking errors, related to #1400. Unexpected result count: 0, expected 1, hash: 3Npnwl9b+qzIVDw2AKRvXlvkuW1IZF4lWJgfq/YYTFk=, size: 102400, blocksetid: 19106, ix: 7, fullhash: eyPnn/bAEL7/0BsuT6CZa6pOFcWZKQFQndpJJeTPp58=, fullsize: 2533568

2019-01-17 12:30:04 -05 - [Error-Duplicati.Library.Main.Database.LocalBackupDatabase-FoundIssue1400Error]: Found block with ID 1340383 and hash 3Npnwl9b+qzIVDw2AKRvXlvkuW1IZF4lWJgfq/YYTFk= and size 42952

Any idea what’s going on and the significance of these messages?


#2

FWIW, here is the full log:

{
“DeletedFiles”: 0,
“DeletedFolders”: 0,
“ModifiedFiles”: 0,
“ExaminedFiles”: 17593,
“OpenedFiles”: 17592,
“AddedFiles”: 17592,
“SizeOfModifiedFiles”: 0,
“SizeOfAddedFiles”: 142874369401,
“SizeOfExaminedFiles”: 142876579305,
“SizeOfOpenedFiles”: 142874369401,
“NotProcessedFiles”: 0,
“AddedFolders”: 1658,
“TooLargeFiles”: 0,
“FilesWithError”: 0,
“ModifiedFolders”: 0,
“ModifiedSymlinks”: 0,
“AddedSymlinks”: 121,
“DeletedSymlinks”: 0,
“PartialBackup”: false,
“Dryrun”: false,
“MainOperation”: “Backup”,
“CompactResults”: null,
“DeleteResults”: {
“DeletedSetsActualLength”: 0,
“DeletedSets”: ,
“Dryrun”: false,
“MainOperation”: “Delete”,
“CompactResults”: null,
“ParsedResult”: “Success”,
“Version”: “2.0.4.12 (2.0.4.12_canary_2019-01-16)”,
“EndTime”: “2019-01-17T17:30:48.068139Z”,
“BeginTime”: “2019-01-17T17:30:44.438521Z”,
“Duration”: “00:00:03.6296180”,
“MessagesActualLength”: 0,
“WarningsActualLength”: 0,
“ErrorsActualLength”: 0,
“Messages”: null,
“Warnings”: null,
“Errors”: null,
“BackendStatistics”: {
“RemoteCalls”: 8508,
“BytesUploaded”: 111408393097,
“BytesDownloaded”: 111408393097,
“FilesUploaded”: 4253,
“FilesDownloaded”: 4253,
“FilesDeleted”: 0,
“FoldersCreated”: 0,
“RetryAttempts”: 0,
“UnknownFileSize”: 0,
“UnknownFileCount”: 0,
“KnownFileCount”: 4253,
“KnownFileSize”: 111408393097,
“LastBackupDate”: “2019-01-17T10:31:58-05:00”,
“BackupListCount”: 1,
“TotalQuotaSpace”: 0,
“FreeQuotaSpace”: 0,
“AssignedQuotaSpace”: -1,
“ReportedQuotaError”: false,
“ReportedQuotaWarning”: false,
“MainOperation”: “Backup”,
“ParsedResult”: “Success”,
“Version”: “2.0.4.12 (2.0.4.12_canary_2019-01-16)”,
“EndTime”: “0001-01-01T00:00:00”,
“BeginTime”: “2019-01-17T15:31:58.562002Z”,
“Duration”: “00:00:00”,
“MessagesActualLength”: 0,
“WarningsActualLength”: 0,
“ErrorsActualLength”: 0,
“Messages”: null,
“Warnings”: null,
“Errors”: null
}
},
“RepairResults”: null,
“TestResults”: {
“MainOperation”: “Test”,
“VerificationsActualLength”: 4253,
“Verifications”: [
{
“Key”: “duplicati-20190117T153158Z.dlist.zip.aes”,
“Value”:
},
{
“Key”: “duplicati-ib3d1b1a621024f31890355dcac9e4259.dindex.zip.aes”,
“Value”:
},
{
“Key”: “duplicati-ib6cda9b004d84a5f945eea5fb47e196a.dindex.zip.aes”,
“Value”:
},
{
“Key”: “duplicati-i66859b9356c3429896ea011b6891b406.dindex.zip.aes”,
“Value”:
},
{
“Key”: “duplicati-iae411ad08a0145218001d97a12dd029c.dindex.zip.aes”,
“Value”:
},
{
“Key”: “duplicati-i95ac24e18e5b4fe789451cf8738a1f78.dindex.zip.aes”,
“Value”:
},
{
“Key”: “duplicati-ibe8697d118a340f28a04c852397828dd.dindex.zip.aes”,
“Value”:
},
{
“Key”: “duplicati-i0e80fa5d81be4f6cbdc02256cfc9afea.dindex.zip.aes”,
“Value”:
},
{
“Key”: “duplicati-i8fcb06cf6e50492b833fdf7835c1a4a2.dindex.zip.aes”,
“Value”:
},
{
“Key”: “duplicati-ib48d077591d5491f8029a6e023f031f4.dindex.zip.aes”,
“Value”:
},
{
“Key”: “duplicati-ia77ce3d9430c496a89ebb5db45a33d45.dindex.zip.aes”,
“Value”:
},
{
“Key”: “duplicati-ie31afef9d4394f1784ee4e582c492304.dindex.zip.aes”,
“Value”:
},
{
“Key”: “duplicati-ia347957ad1d0445d83f8736c34ec304d.dindex.zip.aes”,
“Value”:
},
{
“Key”: “duplicati-i014868acb59443c89341f953a468cfdb.dindex.zip.aes”,
“Value”:
},
{
“Key”: “duplicati-i3475ca1e9e1a459ba0bce9447559efc0.dindex.zip.aes”,
“Value”:
},
{
“Key”: “duplicati-ic8daa15f3ec040358a17849de6881952.dindex.zip.aes”,
“Value”:
},
{
“Key”: “duplicati-i5809cc91cd0d49e7b740167204389e02.dindex.zip.aes”,
“Value”:
},
{
“Key”: “duplicati-if3a773cdc48a4cffae5824ca9e1089bb.dindex.zip.aes”,
“Value”:
},
{
“Key”: “duplicati-i76e469b9f52c49ad8c3d9ef4d60e0462.dindex.zip.aes”,
“Value”:
},
{
“Key”: “duplicati-ibe9b34a431a64f86884622a246bc8e0c.dindex.zip.aes”,
“Value”:
}
],
“ParsedResult”: “Success”,
“Version”: “2.0.4.12 (2.0.4.12_canary_2019-01-16)”,
“EndTime”: “2019-01-17T19:03:02.691791Z”,
“BeginTime”: “2019-01-17T17:31:16.501891Z”,
“Duration”: “01:31:46.1899000”,
“MessagesActualLength”: 0,
“WarningsActualLength”: 0,
“ErrorsActualLength”: 0,
“Messages”: null,
“Warnings”: null,
“Errors”: null,
“BackendStatistics”: {
“RemoteCalls”: 8508,
“BytesUploaded”: 111408393097,
“BytesDownloaded”: 111408393097,
“FilesUploaded”: 4253,
“FilesDownloaded”: 4253,
“FilesDeleted”: 0,
“FoldersCreated”: 0,
“RetryAttempts”: 0,
“UnknownFileSize”: 0,
“UnknownFileCount”: 0,
“KnownFileCount”: 4253,
“KnownFileSize”: 111408393097,
“LastBackupDate”: “2019-01-17T10:31:58-05:00”,
“BackupListCount”: 1,
“TotalQuotaSpace”: 0,
“FreeQuotaSpace”: 0,
“AssignedQuotaSpace”: -1,
“ReportedQuotaError”: false,
“ReportedQuotaWarning”: false,
“MainOperation”: “Backup”,
“ParsedResult”: “Success”,
“Version”: “2.0.4.12 (2.0.4.12_canary_2019-01-16)”,
“EndTime”: “0001-01-01T00:00:00”,
“BeginTime”: “2019-01-17T15:31:58.562002Z”,
“Duration”: “00:00:00”,
“MessagesActualLength”: 0,
“WarningsActualLength”: 0,
“ErrorsActualLength”: 0,
“Messages”: null,
“Warnings”: null,
“Errors”: null
}
},
“ParsedResult”: “Error”,
“Version”: “2.0.4.12 (2.0.4.12_canary_2019-01-16)”,
“EndTime”: “2019-01-17T19:03:18.844791Z”,
“BeginTime”: “2019-01-17T15:31:58.56159Z”,
“Duration”: “03:31:20.2832010”,
“MessagesActualLength”: 17023,
“WarningsActualLength”: 1,
“ErrorsActualLength”: 2,
“Messages”: [
“2019-01-17 10:31:58 -05 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation Backup has started”,
“2019-01-17 10:31:59 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started: ()”,
“2019-01-17 10:32:09 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Completed: ()”,
“2019-01-17 10:32:32 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-b0fa97bc29a544da09540438aa90d0ce1.dblock.zip.aes (49.99 MB)”,
“2019-01-17 10:32:46 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-b0fa97bc29a544da09540438aa90d0ce1.dblock.zip.aes (49.99 MB)”,
“2019-01-17 10:32:46 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-ib3d1b1a621024f31890355dcac9e4259.dindex.zip.aes (33.70 KB)”,
“2019-01-17 10:32:46 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-ib3d1b1a621024f31890355dcac9e4259.dindex.zip.aes (33.70 KB)”,
“2019-01-17 10:32:46 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-b1a63f30e5f8d41cd92ef8e53420f96c3.dblock.zip.aes (49.93 MB)”,
“2019-01-17 10:32:48 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-b1a63f30e5f8d41cd92ef8e53420f96c3.dblock.zip.aes (49.93 MB)”,
“2019-01-17 10:32:48 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-ib6cda9b004d84a5f945eea5fb47e196a.dindex.zip.aes (33.92 KB)”,
“2019-01-17 10:32:48 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-ib6cda9b004d84a5f945eea5fb47e196a.dindex.zip.aes (33.92 KB)”,
“2019-01-17 10:32:48 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-bcb5fa4ce75bd4f9a8c3d1d9a42383ea5.dblock.zip.aes (49.95 MB)”,
“2019-01-17 10:32:51 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-bcb5fa4ce75bd4f9a8c3d1d9a42383ea5.dblock.zip.aes (49.95 MB)”,
“2019-01-17 10:32:51 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-i66859b9356c3429896ea011b6891b406.dindex.zip.aes (34.28 KB)”,
“2019-01-17 10:32:51 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-i66859b9356c3429896ea011b6891b406.dindex.zip.aes (34.28 KB)”,
“2019-01-17 10:32:51 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-b2674f51b8555465d8d43ca40e8f1d9a8.dblock.zip.aes (49.92 MB)”,
“2019-01-17 10:32:54 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-b2674f51b8555465d8d43ca40e8f1d9a8.dblock.zip.aes (49.92 MB)”,
“2019-01-17 10:32:54 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-iae411ad08a0145218001d97a12dd029c.dindex.zip.aes (134.15 KB)”,
“2019-01-17 10:32:54 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-iae411ad08a0145218001d97a12dd029c.dindex.zip.aes (134.15 KB)”,
“2019-01-17 10:32:54 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-b5cd48e0b85894ec38df5159549665dd7.dblock.zip.aes (50.00 MB)”
],
“Warnings”: [
“2019-01-17 12:30:04 -05 - [Warning-Duplicati.Library.Main.Operation.Backup.FileBlockProcessor.FileEntry-PathProcessingFailed]: Failed to process path: /home/sylerner/.config/Duplicati/68788278886971887374.sqlite-journal”
],
“Errors”: [
“2019-01-17 12:30:04 -05 - [Error-Duplicati.Library.Main.Database.LocalBackupDatabase-CheckingErrorsForIssue1400]: Checking errors, related to #1400. Unexpected result count: 0, expected 1, hash: 3Npnwl9b+qzIVDw2AKRvXlvkuW1IZF4lWJgfq/YYTFk=, size: 102400, blocksetid: 19106, ix: 7, fullhash: eyPnn/bAEL7/0BsuT6CZa6pOFcWZKQFQndpJJeTPp58=, fullsize: 2533568”,
“2019-01-17 12:30:04 -05 - [Error-Duplicati.Library.Main.Database.LocalBackupDatabase-FoundIssue1400Error]: Found block with ID 1340383 and hash 3Npnwl9b+qzIVDw2AKRvXlvkuW1IZF4lWJgfq/YYTFk= and size 42952”
],
“BackendStatistics”: {
“RemoteCalls”: 8508,
“BytesUploaded”: 111408393097,
“BytesDownloaded”: 111408393097,
“FilesUploaded”: 4253,
“FilesDownloaded”: 4253,
“FilesDeleted”: 0,
“FoldersCreated”: 0,
“RetryAttempts”: 0,
“UnknownFileSize”: 0,
“UnknownFileCount”: 0,
“KnownFileCount”: 4253,
“KnownFileSize”: 111408393097,
“LastBackupDate”: “2019-01-17T10:31:58-05:00”,
“BackupListCount”: 1,
“TotalQuotaSpace”: 0,
“FreeQuotaSpace”: 0,
“AssignedQuotaSpace”: -1,
“ReportedQuotaError”: false,
“ReportedQuotaWarning”: false,
“MainOperation”: “Backup”,
“ParsedResult”: “Success”,
“Version”: “2.0.4.12 (2.0.4.12_canary_2019-01-16)”,
“EndTime”: “0001-01-01T00:00:00”,
“BeginTime”: “2019-01-17T15:31:58.562002Z”,
“Duration”: “00:00:00”,
“MessagesActualLength”: 0,
“WarningsActualLength”: 0,
“ErrorsActualLength”: 0,
“Messages”: null,
“Warnings”: null,
“Errors”: null
}
}


#3

I don’t think this is well-understood (old issue came back), but the lead developer gave a comment here.

If you have Windows or Linux LVM (maybe in a recognized config…), you could try –snapshot-policy=on.

2.1. Rollback Journals explains the naming and use, and I’d guess it would be locked, which probably is causing the “Failed to process path”, but the detailed cause is on the line after the one in the summary. Emailing yourself a backup report, or setting up a –log-file will catch more error information, if you want.

If snapshots are not possible, not backing up that area would be another workaround. If you really want backup of the database (some people do, e.g. to avoid Recreate), see the later posts at top link above.


Repair and Rebuild database fails: Unexpected difference in fileset
New backup state Error: Checking errors, related to #1400