Full Remote Verification

#1

I ran a full verification test on one of my main data stores because I am trying to make sure I don’t have any data rot in my backups. The results of the test show that there were a few errors that I I don’t understand. Below is the log of the test.

MainOperation: Test
Verifications: [
    Key: duplicati-20190329T051005Z.dlist.zip.aes
    Value: [],
    Key: duplicati-20190212T051414Z.dlist.zip.aes
    Value: [],
    Key: duplicati-20190316T051217Z.dlist.zip.aes
    Value: [],
    Key: duplicati-20190106T035227Z.dlist.zip.aes
    Value: [],
    Key: duplicati-20190331T234946Z.dlist.zip.aes
    Value: [],
...
]
ParsedResult: Error
Version: 2.0.4.5 (2.0.4.5_beta_2018-11-28)
EndTime: 04/02/2019 23:44:53 (1554248693)
BeginTime: 04/01/2019 17:35:30 (1554140130)
Duration: 1.06:09:23.9335940
Messages: [
    2019-04-01 17:35:30 +00 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation Test has started,
    2019-04-01 17:35:30 +00 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started:  (),
    2019-04-01 17:35:37 +00 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Completed:  (27.64 KB),
    2019-04-01 17:35:38 +00 - [Information-Duplicati.Library.Main.Operation.FilelistProcessor-IgnoreRemoteDeletedFile]: ignoring remote file listed as Deleted: duplicati-20190107T103457Z.dlist.zip.aes,
    2019-04-01 17:35:38 +00 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Started: duplicati-20190329T051005Z.dlist.zip.aes (104.92 KB),
...
]
Warnings: []
Errors: [
    2019-04-01 19:37:44 +00 - [Error-Duplicati.Library.Main.Operation.TestHandler-FailedToProcessFile]: Failed to process file duplicati-ba4569df9b37a4c01865506d9f7319503.dblock.zip.aes,
    2019-04-01 19:38:24 +00 - [Error-Duplicati.Library.Main.Operation.TestHandler-FailedToProcessFile]: Failed to process file duplicati-bd0a2b8430d444fd49a04511b12aea54a.dblock.zip.aes,
    2019-04-01 22:50:08 +00 - [Error-Duplicati.Library.Main.Operation.TestHandler-FailedToProcessFile]: Failed to process file duplicati-b682234a12bdc45fa99a9092dd9040054.dblock.zip.aes,
    2019-04-01 22:51:16 +00 - [Error-Duplicati.Library.Main.Operation.TestHandler-FailedToProcessFile]: Failed to process file duplicati-bb1d4e41e5f4c4d6b8709febb4a897d13.dblock.zip.aes,
    2019-04-01 22:52:56 +00 - [Error-Duplicati.Library.Main.Operation.TestHandler-FailedToProcessFile]: Failed to process file duplicati-be84140604fee46c886d376a998589994.dblock.zip.aes,
...
]
BackendStatistics:
    RemoteCalls: 29839
    BytesUploaded: 0
    BytesDownloaded: 1433960065698
    FilesUploaded: 0
    FilesDownloaded: 28186
    FilesDeleted: 0
    FoldersCreated: 0
    RetryAttempts: 1537
    UnknownFileSize: 0
    UnknownFileCount: 0
    KnownFileCount: 28302
    KnownFileSize: 1445755619958
    LastBackupDate: 03/31/2019 23:49:46 (1554076186)
    BackupListCount: 9
    TotalQuotaSpace: 0
    FreeQuotaSpace: 0
    AssignedQuotaSpace: -1
    ReportedQuotaError: False
    ReportedQuotaWarning: False
    ParsedResult: Error
    Version: 2.0.4.5 (2.0.4.5_beta_2018-11-28)
    Messages: [
        2019-04-01 17:35:30 +00 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation Test has started,
        2019-04-01 17:35:30 +00 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started:  (),
        2019-04-01 17:35:37 +00 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Completed:  (27.64 KB),
        2019-04-01 17:35:38 +00 - [Information-Duplicati.Library.Main.Operation.FilelistProcessor-IgnoreRemoteDeletedFile]: ignoring remote file listed as Deleted: duplicati-20190107T103457Z.dlist.zip.aes,
        2019-04-01 17:35:38 +00 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Started: duplicati-20190329T051005Z.dlist.zip.aes (104.92 KB),
...
    ]
    Warnings: []
    Errors: [
        2019-04-01 19:37:44 +00 - [Error-Duplicati.Library.Main.Operation.TestHandler-FailedToProcessFile]: Failed to process file duplicati-ba4569df9b37a4c01865506d9f7319503.dblock.zip.aes,
        2019-04-01 19:38:24 +00 - [Error-Duplicati.Library.Main.Operation.TestHandler-FailedToProcessFile]: Failed to process file duplicati-bd0a2b8430d444fd49a04511b12aea54a.dblock.zip.aes,
        2019-04-01 22:50:08 +00 - [Error-Duplicati.Library.Main.Operation.TestHandler-FailedToProcessFile]: Failed to process file duplicati-b682234a12bdc45fa99a9092dd9040054.dblock.zip.aes,
        2019-04-01 22:51:16 +00 - [Error-Duplicati.Library.Main.Operation.TestHandler-FailedToProcessFile]: Failed to process file duplicati-bb1d4e41e5f4c4d6b8709febb4a897d13.dblock.zip.aes,
        2019-04-01 22:52:56 +00 - [Error-Duplicati.Library.Main.Operation.TestHandler-FailedToProcessFile]: Failed to process file duplicati-be84140604fee46c886d376a998589994.dblock.zip.aes,
...
    ]

I’ve had two backups run since this test without error. Should I be concerned by these results? If so, do I need to do something? Or does Duplicati automatically correct any errors it finds when running a test.

Thanks for the assistance.

0 Likes

#2

Hey @fognar, good job considering testing your backups!

As of now Duplicati doesn’t automatically fix errors it finds while testing. My GUESS is that the errors about not testing some dblock files (where data blocks are stored) are related to the earlier message about ignoring a “deleted” dlist file.

I’d suggest running a compact (to clear out the “deleted” dlist file) and that may make the dblock errors go away.

If so, let us know as that’s a reporting but we can fix.

0 Likes

#3

I will give that a try, the backup is rather large though so it’s going to take at least 36 hours before another test will finish.

0 Likes

#4

I’m not in any hurry. :slight_smile:

I work by the Fast | Cheap | Good management triangle - you get to choose two. I’ve chosen Good & Cheap, so I don’t expect Fast. :wink:

1 Like

#5

So it looks like my most recent test had more errors, but for different files this time?

MainOperation: Test
Verifications: [
    Key: duplicati-20190404T050500Z.dlist.zip.aes
    Value: [],
    Key: duplicati-20190329T051005Z.dlist.zip.aes
    Value: [],
    Key: duplicati-20190402T234953Z.dlist.zip.aes
    Value: [],
    Key: duplicati-20190212T051414Z.dlist.zip.aes
    Value: [],
    Key: duplicati-20190331T234946Z.dlist.zip.aes
    Value: [],
...
]
ParsedResult: Error
Version: 2.0.4.5 (2.0.4.5_beta_2018-11-28)
EndTime: 04/05/2019 20:39:37 (1554496777)
BeginTime: 04/04/2019 16:12:20 (1554394340)
Duration: 1.04:27:16.4628240
Messages: [
    2019-04-04 16:12:21 +00 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation Test has started,
    2019-04-04 16:12:21 +00 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started:  (),
    2019-04-04 16:12:28 +00 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Completed:  (28.27 KB),
    2019-04-04 16:12:29 +00 - [Information-Duplicati.Library.Main.Operation.FilelistProcessor-IgnoreRemoteDeletedFile]: ignoring remote file listed as Deleted: duplicati-20190107T103457Z.dlist.zip.aes,
    2019-04-04 16:12:29 +00 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Started: duplicati-20190404T050500Z.dlist.zip.aes (107.09 KB),
...
]
Warnings: []
Errors: [
    2019-04-04 22:23:57 +00 - [Error-Duplicati.Library.Main.Operation.TestHandler-FailedToProcessFile]: Failed to process file duplicati-b166b4e1f8a074d5a975c93e0893881e6.dblock.zip.aes,
    2019-04-04 22:24:42 +00 - [Error-Duplicati.Library.Main.Operation.TestHandler-FailedToProcessFile]: Failed to process file duplicati-b4e04fee1a04842faac88f8d50cfbe9bf.dblock.zip.aes,
    2019-04-04 22:25:22 +00 - [Error-Duplicati.Library.Main.Operation.TestHandler-FailedToProcessFile]: Failed to process file duplicati-b57027c1bde9f4c479ce290bd9cfaa4d6.dblock.zip.aes,
    2019-04-04 22:26:46 +00 - [Error-Duplicati.Library.Main.Operation.TestHandler-FailedToProcessFile]: Failed to process file duplicati-b759bf2bc6675489f93bc8e7b1d25a185.dblock.zip.aes,
    2019-04-04 22:27:26 +00 - [Error-Duplicati.Library.Main.Operation.TestHandler-FailedToProcessFile]: Failed to process file duplicati-b20732571b5ae419cbf9ef602e194c55b.dblock.zip.aes,
...
]
BackendStatistics:
    RemoteCalls: 29838
    BytesUploaded: 0
    BytesDownloaded: 1475838442128
    FilesUploaded: 0
    FilesDownloaded: 28928
    FilesDeleted: 0
    FoldersCreated: 0
    RetryAttempts: 894
    UnknownFileSize: 0
    UnknownFileCount: 0
    KnownFileCount: 28944
    KnownFileSize: 1477275724800
    LastBackupDate: 04/04/2019 05:05:00 (1554354300)
    BackupListCount: 9
    TotalQuotaSpace: 0
    FreeQuotaSpace: 0
    AssignedQuotaSpace: -1
    ReportedQuotaError: False
    ReportedQuotaWarning: False
    ParsedResult: Error
    Version: 2.0.4.5 (2.0.4.5_beta_2018-11-28)
    Messages: [
        2019-04-04 16:12:21 +00 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation Test has started,
        2019-04-04 16:12:21 +00 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started:  (),
        2019-04-04 16:12:28 +00 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Completed:  (28.27 KB),
        2019-04-04 16:12:29 +00 - [Information-Duplicati.Library.Main.Operation.FilelistProcessor-IgnoreRemoteDeletedFile]: ignoring remote file listed as Deleted: duplicati-20190107T103457Z.dlist.zip.aes,
        2019-04-04 16:12:29 +00 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Started: duplicati-20190404T050500Z.dlist.zip.aes (107.09 KB),
...
    ]
    Warnings: []
    Errors: [
        2019-04-04 22:23:57 +00 - [Error-Duplicati.Library.Main.Operation.TestHandler-FailedToProcessFile]: Failed to process file duplicati-b166b4e1f8a074d5a975c93e0893881e6.dblock.zip.aes,
        2019-04-04 22:24:42 +00 - [Error-Duplicati.Library.Main.Operation.TestHandler-FailedToProcessFile]: Failed to process file duplicati-b4e04fee1a04842faac88f8d50cfbe9bf.dblock.zip.aes,
        2019-04-04 22:25:22 +00 - [Error-Duplicati.Library.Main.Operation.TestHandler-FailedToProcessFile]: Failed to process file duplicati-b57027c1bde9f4c479ce290bd9cfaa4d6.dblock.zip.aes,
        2019-04-04 22:26:46 +00 - [Error-Duplicati.Library.Main.Operation.TestHandler-FailedToProcessFile]: Failed to process file duplicati-b759bf2bc6675489f93bc8e7b1d25a185.dblock.zip.aes,
        2019-04-04 22:27:26 +00 - [Error-Duplicati.Library.Main.Operation.TestHandler-FailedToProcessFile]: Failed to process file duplicati-b20732571b5ae419cbf9ef602e194c55b.dblock.zip.aes,
...
    ]
0 Likes

#6

The web log only shows the first 5 or so messages in a block (hence the “…” before the closing bracket for the Warnings and Errors) so it’s possible the same files are erroring but in a different order.

For a complete log you could use the --log-file parameter - though that can get pretty big unless you also play with --log-file-log-level and --log-file-log-filter.


In paying closer attention to your provided log I see the BackendStatistics reports 894 retry attempts for the 29,838 downloaded files. That’s almost a 3% retry (failure?) rate - it’s possible (likely?) that the “failed to process file” errors are related to those files.

Can you check how many files are actually in the destination? If it’s around 29,838 then my guess is that you’re running into connectivity issue making some of the downloads fail (and thus not get tested).

    ParsedResult: Error
    Version: 2.0.4.5 (2.0.4.5_beta_2018-11-28)
    EndTime: 04/05/2019 20:39:37 (1554496777)
    BeginTime: 04/04/2019 16:12:20 (1554394340)
    Duration: 1.04:27:16.4628240
    Messages: [
        2019-04-04 16:12:21 +00 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation Test has started,
        2019-04-04 16:12:21 +00 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started:  (),
        2019-04-04 16:12:28 +00 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Completed:  (28.27 KB),
        2019-04-04 16:12:29 +00 - [Information-Duplicati.Library.Main.Operation.FilelistProcessor-IgnoreRemoteDeletedFile]: ignoring remote file listed as Deleted: duplicati-20190107T103457Z.dlist.zip.aes,
        2019-04-04 16:12:29 +00 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Started: duplicati-20190404T050500Z.dlist.zip.aes (107.09 KB),
    ...
    ]
    Warnings: []
    Errors: [
        2019-04-04 22:23:57 +00 - [Error-Duplicati.Library.Main.Operation.TestHandler-FailedToProcessFile]: Failed to process file duplicati-b166b4e1f8a074d5a975c93e0893881e6.dblock.zip.aes,
        2019-04-04 22:24:42 +00 - [Error-Duplicati.Library.Main.Operation.TestHandler-FailedToProcessFile]: Failed to process file duplicati-b4e04fee1a04842faac88f8d50cfbe9bf.dblock.zip.aes,
        2019-04-04 22:25:22 +00 - [Error-Duplicati.Library.Main.Operation.TestHandler-FailedToProcessFile]: Failed to process file duplicati-b57027c1bde9f4c479ce290bd9cfaa4d6.dblock.zip.aes,
        2019-04-04 22:26:46 +00 - [Error-Duplicati.Library.Main.Operation.TestHandler-FailedToProcessFile]: Failed to process file duplicati-b759bf2bc6675489f93bc8e7b1d25a185.dblock.zip.aes,
        2019-04-04 22:27:26 +00 - [Error-Duplicati.Library.Main.Operation.TestHandler-FailedToProcessFile]: Failed to process file duplicati-b20732571b5ae419cbf9ef602e194c55b.dblock.zip.aes,
    ...
    ]
    BackendStatistics:
        RemoteCalls: 29838
        BytesUploaded: 0
        BytesDownloaded: 1475838442128
        FilesUploaded: 0
        FilesDownloaded: 28928
        FilesDeleted: 0
        FoldersCreated: 0
        RetryAttempts: 894
        UnknownFileSize: 0
        UnknownFileCount: 0
        KnownFileCount: 28944
        KnownFileSize: 1477275724800
        LastBackupDate: 04/04/2019 05:05:00 (1554354300)
        BackupListCount: 9
        TotalQuotaSpace: 0
        FreeQuotaSpace: 0
        AssignedQuotaSpace: -1
        ReportedQuotaError: False
        ReportedQuotaWarning: False
        ParsedResult: Error
        Version: 2.0.4.5 (2.0.4.5_beta_2018-11-28)
0 Likes

#7

I was going to say that connectivity issues are unlikely since I currently have the backup box hooked directly to the same router as my main server, but then I remembered that I still have it going through the same SSH tunnel that I have setup when it’s away. Then on top of that my ssh connection that I opened to check the file count died on me after only a few seconds 3 times in a row.

So I guess I need to sort out some SSH tunnel issues before I can do a proper check. That or change the destination to reflect that it’s here in the house right now.

The remote did have a few more files than whats listed here but it also is 6 days older so I guess that is probably to be expected.

0 Likes