Release: 2.0.9.107 (Canary) 2024-09-11

[Taomyn]

@ts678

Some of this needs developer input, but here are some comments to try to cover some points.

@Taomyn

No idea how old the files are, I’d have to connect directly to the Wasabi S3 bucket to see.

Maybe this refers to the below, or some similar S3 client to access bucket over network?

Ok, back to this one now that I fixed the Win11 issue.

The referenced dindex file, duplicati-i1a38dada64b94dceb380c3a37b6d3125.dindex.zip.aes, was last changed back in August, so not very old:

So can this be fixed with the current version or do I need to wait for a fix to what you mentioned before?

[quote="ts678
Looks like one update of an SQL string from double-quoted (now illegal) to single got missed.

"Remotevolume"."State" = "Temporary"
[/quote]

[ts678]

@Taomyn

The referenced dindex file, duplicati-i1a38dada64b94dceb380c3a37b6d3125.dindex.zip.aes, was last changed back in August, so not very old:

But Aug 11 is old enough to pass 30 day default log-retention. It might not matter. It’s a Warning.

@Taomyn

"Warnings": [
    "2024-09-21 09:20:17 +02 - [Warning-Duplicati.Library.Main.Operation.RecreateDatabaseHandler-WrongBlocklistHashes]: duplicati-i1a38dada64b94dceb380c3a37b6d3125.dindex.zip.aes had invalid blocklists which could not be used. Consider deleting this index file and run repair to recreate it.",
    "2024-09-21 09:49:08 +02 - [Warning-Duplicati.Library.Main.Database.LocalRecreateDatabase-MissingVolumesDetected]: Found 5 missing volumes; attempting to replace blocks from existing volumes"
  ],
  "Errors": [
    "2024-09-21 09:19:55 +02 - [Error-Duplicati.Library.Main.Operation.RecreateDatabaseHandler-MissingFileDetected]: Remote file referenced as duplicati-b9e1f5e121479444d9fcc23ee8bd51872.dblock.zip.aes by duplicati-i16453320ee34465ca2e893331ee64171.dindex.zip.aes, but not found in list, registering a missing remote file",
    "2024-09-21 09:26:45 +02 - [Error-Duplicati.Library.Main.Operation.RecreateDatabaseHandler-MissingFileDetected]: Remote file referenced as duplicati-bc56973137cb642259676363069a849c5.dblock.zip.aes by duplicati-i6394beb6d51c496791743d885dd9d1b2.dindex.zip.aes, but not found in list, registering a missing remote file",
    "2024-09-21 09:30:21 +02 - [Error-Duplicati.Library.Main.Operation.RecreateDatabaseHandler-MissingFileDetected]: Remote file referenced as duplicati-b7a8359a5b95344d9b37675eab5fc4998.dblock.zip.aes by duplicati-i8ee561ff09f44db2887eca334055adaf.dindex.zip.aes, but not found in list, registering a missing remote file",
    "2024-09-21 09:31:40 +02 - [Error-Duplicati.Library.Main.Operation.RecreateDatabaseHandler-MissingFileDetected]: Remote file referenced as duplicati-bad2983f366a04e2c9bf3b3409182b286.dblock.zip.aes by duplicati-i9ea561cec92b4e4b8034b868cacd474f.dindex.zip.aes, but not found in list, registering a missing remote file",
    "2024-09-21 09:37:21 +02 - [Error-Duplicati.Library.Main.Operation.RecreateDatabaseHandler-MissingFileDetected]: Remote file referenced as duplicati-b600e2240b0984ce5b20c13a96c1a6181.dblock.zip.aes by duplicati-ie48cec5542ac490690ff70d0ef0d829c.dindex.zip.aes, but not found in list, registering a missing remote file",
    "2024-09-21 10:00:51 +02 - [Error-Duplicati.Library.Main.Controller-FailedOperation]: The operation Repair has failed with error: SQL logic error\r\nno such column: Temporary\r\nSQLiteException: SQL logic error\r\nno such column: Temporary"
  ],

@Taomyn

So can this be fixed with the current version or do I need to wait for a fix to what you mentioned before?

How old are the 5 dindex files in the Errors section? I think those are what trigger the SQL bug.
Is the size unusually small compared to the typical dindex file. I’m wondering if they’re relevant.

Sometimes Duplicati leaves bogus dindex files around that don’t hurt anything until a Recreate.

Did you happen to notice how far the progress bar moved? The final 30% (especially last 10%) involves reading dblock files (which are big) when the dindex files for the dblocks aren’t enough.

Do you now have a tool that can deal with Wasabi files? If so, test with rename or copy may be possible, however I’d want to not do extreme downloads because Wasabi might get upset at it.

Exotic option:

Have you looked in job databases before? We could also poke in there to search for file history.
Creating a bug report and posting a link to it would be a similar approach.

EDIT:

Viewed another way, I’m thinking the Errors dindex files can’t be helping to index dblock content because the dblock they reference isn’t there, I’d still prefer not to totally delete them though, but renaming so they don’t begin with duplicati-, or saving a copy just in case might be advisable.

[Taomyn]

Sorry, forgot about those, so checked again - I’m using the Wasabi console to browse the bucket the files are in:

duplicati-i16453320ee34465ca2e893331ee64171.dindex.zip.aes Mar 26, 2019, 7:06 AM
duplicati-i6394beb6d51c496791743d885dd9d1b2.dindex.zip.aes Apr 13, 2024, 7:20 AM
duplicati-i8ee561ff09f44db2887eca334055adaf.dindex.zip.aes Mar 26, 2019, 7:01 AM
duplicati-i9ea561cec92b4e4b8034b868cacd474f.dindex.zip.aes Mar 26, 2019, 7:01 AM
duplicati-ie48cec5542ac490690ff70d0ef0d829c.dindex.zip.aes Mar 26, 2019, 7:04 AM

Would renaming just one of them be a good enough test or should I do them all?

Going to sort out a different file browser for accessing Wasabi as the console is ok for basic things but I can’t filter on a substring of a file name to compare dindex file sizes

[ts678]

@Taomyn

Would renaming just one of them be a good enough test or should I do them all?

Renaming any one could certainly test whether the file-specific error shown clears.
I don’t see how it wouldn’t clear though, and SQL error will probably need all gone.

Seeing most files are 2019 makes me feel better, as dindex had more bugs earlier.
Seeing a 2024 file makes me feel worse. I’d like file details when you can get them.
Possibly I’ll even ask for a decrypt, unzip, and look, but let’s do the easier stuff first.

[ts678]

TrayIcon Quit is (again but worse) closing itself but not Duplicati. It’s been over an hour since Quit, whereas the delay used to be a few minutes. I’m not sure if this problem is reproducible.

TrayIcon is talking to itself just fine:

GET /api/v1/serverstate?longpoll=true&lastEventId=2486&duration=5m HTTP/1.1
Host: localhost:8200
Authorization: Bearer REDACTED
User-Agent: Duplicati-TrayIcon-Monitor/2.0.9.107


HTTP/1.1 200 OK
Content-Type: application/json; charset=utf-8
Date: Tue, 24 Sep 2024 22:28:02 GMT
Server: Kestrel
Transfer-Encoding: chunked

{"ActiveTask":null,"ProgramState":"Running","SchedulerQueueIds":[],"ProposedSchedule":[{"Item1":"1","Item2":"2024-09-25T09:20:00Z"}],"HasWarning":false,"HasError":true,"SuggestedStatusIcon":"ReadyError","EstimatedPauseEnd":"0001-01-01T00:00:00","LastEventID":2487,"LastDataUpdateID":142,"LastNotificationUpdateID":30,"UpdatedVersion":null,"UpdaterState":"Waiting","UpdateDownloadLink":null,"UpdateDownloadProgress":0}

and human Web UI seems fine, however I’d kind of like the Quit to quit so I can start up again.
I’ll leave it up for awhile before killing it, in case there’s something that I could look at to debug.

[Taomyn]

Ok, so I did a test by renaming one dindex file by prefixing it with bak. and trying the rebuild of the database, and it failed as expected but on the remaining files. As that took 1.5hrs I decided to try again after renaming the other 5 files as well.

This time it worked.

I’ve not done anything else, job is not scheduled, so should I simply try a backup now?

[ts678]

@Taomyn

so should I simply try a backup now?

The message from Recreate is what you want to see. Did you notice how far progress bar went? Ideally the dindex files were enough, so it didn’t need to linger beyond 70% reading any dblocks.

Now would be an easy point to look at <job> → Show log → Remote if you’re unsure what it did.
Top ideally is a dindex read, and if there’s a dblock read, hopefully there aren’t a huge number…

After that, might as well try a backup.

[Taomyn]

I didn’t notice as it takes 1.5hrs, but this is the log.

            {
  "MainOperation": "Repair",
  "RecreateDatabaseResults": {
    "MainOperation": "Repair",
    "ParsedResult": "Success",
    "Interrupted": false,
    "Version": "2.0.9.107 (2.0.9.107_canary_2024-09-11)",
    "EndTime": "2024-09-25T09:25:59.7091218Z",
    "BeginTime": "2024-09-25T08:02:03.0377537Z",
    "Duration": "01:23:56.6713681",
    "MessagesActualLength": 0,
    "WarningsActualLength": 0,
    "ErrorsActualLength": 0,
    "Messages": null,
    "Warnings": null,
    "Errors": null,
    "BackendStatistics": {
      "RemoteCalls": 12959,
      "BytesUploaded": 0,
      "BytesDownloaded": 684896342,
      "FilesUploaded": 0,
      "FilesDownloaded": 12958,
      "FilesDeleted": 0,
      "FoldersCreated": 0,
      "RetryAttempts": 0,
      "UnknownFileSize": 0,
      "UnknownFileCount": 0,
      "KnownFileCount": 0,
      "KnownFileSize": 0,
      "LastBackupDate": "0001-01-01T00:00:00",
      "BackupListCount": 0,
      "TotalQuotaSpace": 0,
      "FreeQuotaSpace": 0,
      "AssignedQuotaSpace": 0,
      "ReportedQuotaError": false,
      "ReportedQuotaWarning": false,
      "MainOperation": "Repair",
      "ParsedResult": "Success",
      "Interrupted": false,
      "Version": "2.0.9.107 (2.0.9.107_canary_2024-09-11)",
      "EndTime": "0001-01-01T00:00:00",
      "BeginTime": "2024-09-25T08:02:02.6265065Z",
      "Duration": "00:00:00",
      "MessagesActualLength": 0,
      "WarningsActualLength": 0,
      "ErrorsActualLength": 0,
      "Messages": null,
      "Warnings": null,
      "Errors": null
    }
  },
  "ParsedResult": "Success",
  "Interrupted": false,
  "Version": "2.0.9.107 (2.0.9.107_canary_2024-09-11)",
  "EndTime": "2024-09-25T09:26:00.6076895Z",
  "BeginTime": "2024-09-25T08:02:02.6265026Z",
  "Duration": "01:23:57.9811869",
  "MessagesActualLength": 25924,
  "WarningsActualLength": 0,
  "ErrorsActualLength": 0,
  "Messages": [
    "2024-09-25 10:02:03 +02 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation Repair has started",
    "2024-09-25 10:02:04 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started:  ()",
    "2024-09-25 10:02:06 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Completed:  (25.29 KB)",
    "2024-09-25 10:32:05 +02 - [Information-Duplicati.Library.Main.Operation.RecreateDatabaseHandler-RebuildStarted]: Rebuild database started, downloading 20 filelists",
    "2024-09-25 10:32:05 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Started: duplicati-20231029T094536Z.dlist.zip.aes (3.52 MB)",
    "2024-09-25 10:32:05 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Completed: duplicati-20231029T094536Z.dlist.zip.aes (3.52 MB)",
    "2024-09-25 10:32:05 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Started: duplicati-20231206T060635Z.dlist.zip.aes (3.62 MB)",
    "2024-09-25 10:32:05 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Completed: duplicati-20231206T060635Z.dlist.zip.aes (3.62 MB)",
    "2024-09-25 10:32:10 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Started: duplicati-20240115T051158Z.dlist.zip.aes (3.41 MB)",
    "2024-09-25 10:32:10 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Completed: duplicati-20240115T051158Z.dlist.zip.aes (3.41 MB)",
    "2024-09-25 10:32:14 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Started: duplicati-20240219T052413Z.dlist.zip.aes (3.96 MB)",
    "2024-09-25 10:32:14 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Completed: duplicati-20240219T052413Z.dlist.zip.aes (3.96 MB)",
    "2024-09-25 10:32:18 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Started: duplicati-20240322T051936Z.dlist.zip.aes (3.62 MB)",
    "2024-09-25 10:32:18 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Completed: duplicati-20240322T051936Z.dlist.zip.aes (3.62 MB)",
    "2024-09-25 10:32:23 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Started: duplicati-20240413T042638Z.dlist.zip.aes (3.64 MB)",
    "2024-09-25 10:32:23 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Completed: duplicati-20240413T042638Z.dlist.zip.aes (3.64 MB)",
    "2024-09-25 10:32:27 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Started: duplicati-20240429T041648Z.dlist.zip.aes (3.62 MB)",
    "2024-09-25 10:32:28 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Completed: duplicati-20240429T041648Z.dlist.zip.aes (3.62 MB)",
    "2024-09-25 10:32:32 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Started: duplicati-20240601T040259Z.dlist.zip.aes (3.48 MB)",
    "2024-09-25 10:32:32 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Completed: duplicati-20240601T040259Z.dlist.zip.aes (3.48 MB)"
  ],
  "Warnings": [],
  "Errors": [],
  "BackendStatistics": {
    "RemoteCalls": 12959,
    "BytesUploaded": 0,
    "BytesDownloaded": 684896342,
    "FilesUploaded": 0,
    "FilesDownloaded": 12958,
    "FilesDeleted": 0,
    "FoldersCreated": 0,
    "RetryAttempts": 0,
    "UnknownFileSize": 0,
    "UnknownFileCount": 0,
    "KnownFileCount": 0,
    "KnownFileSize": 0,
    "LastBackupDate": "0001-01-01T00:00:00",
    "BackupListCount": 0,
    "TotalQuotaSpace": 0,
    "FreeQuotaSpace": 0,
    "AssignedQuotaSpace": 0,
    "ReportedQuotaError": false,
    "ReportedQuotaWarning": false,
    "MainOperation": "Repair",
    "ParsedResult": "Success",
    "Interrupted": false,
    "Version": "2.0.9.107 (2.0.9.107_canary_2024-09-11)",
    "EndTime": "0001-01-01T00:00:00",
    "BeginTime": "2024-09-25T08:02:02.6265065Z",
    "Duration": "00:00:00",
    "MessagesActualLength": 0,
    "WarningsActualLength": 0,
    "ErrorsActualLength": 0,
    "Messages": null,
    "Warnings": null,
    "Errors": null
  }
}
        

I didn’t see any dblock reads so I will try a backup and see what happens.

[ts678]

@Taomyn

I didn’t see any dblock reads

That’s good, and consistent with

Backend event: List - Completed:  (25.29 KB)",
    

which for list is not really KB but destination file count. dblock and dindex are each about half.

@Taomyn

"FilesDownloaded": 12958

says you downloaded about half, so probably just the dlist and dindex like a good recreate does.

[Taomyn]

It failed

            {
  "DeletedFiles": 4415,
  "DeletedFolders": 214,
  "ModifiedFiles": 5053,
  "ExaminedFiles": 49184,
  "OpenedFiles": 36270,
  "AddedFiles": 6779,
  "SizeOfModifiedFiles": 2117669592,
  "SizeOfAddedFiles": 26967408195,
  "SizeOfExaminedFiles": 100818138264,
  "SizeOfOpenedFiles": 96896536860,
  "NotProcessedFiles": 0,
  "AddedFolders": 227,
  "TooLargeFiles": 0,
  "FilesWithError": 0,
  "ModifiedFolders": 0,
  "ModifiedSymlinks": 0,
  "AddedSymlinks": 362,
  "DeletedSymlinks": 155,
  "PartialBackup": false,
  "Dryrun": false,
  "MainOperation": "Backup",
  "CompactResults": {
    "DeletedFileCount": 0,
    "DownloadedFileCount": 0,
    "UploadedFileCount": 0,
    "DeletedFileSize": 0,
    "DownloadedFileSize": 0,
    "UploadedFileSize": 0,
    "Dryrun": false,
    "VacuumResults": null,
    "MainOperation": "Compact",
    "ParsedResult": "Success",
    "Interrupted": false,
    "Version": "2.0.9.107 (2.0.9.107_canary_2024-09-11)",
    "EndTime": "0001-01-01T00:00:00",
    "BeginTime": "2024-09-25T15:12:57.634111Z",
    "Duration": "00:00:00",
    "MessagesActualLength": 0,
    "WarningsActualLength": 0,
    "ErrorsActualLength": 0,
    "Messages": null,
    "Warnings": null,
    "Errors": null,
    "BackendStatistics": {
      "RemoteCalls": 1242,
      "BytesUploaded": 25829116604,
      "BytesDownloaded": 837622592,
      "FilesUploaded": 988,
      "FilesDownloaded": 16,
      "FilesDeleted": 237,
      "FoldersCreated": 0,
      "RetryAttempts": 0,
      "UnknownFileSize": 0,
      "UnknownFileCount": 0,
      "KnownFileCount": 25894,
      "KnownFileSize": 675683676350,
      "LastBackupDate": "2024-09-21T08:25:26+02:00",
      "BackupListCount": 20,
      "TotalQuotaSpace": 0,
      "FreeQuotaSpace": 0,
      "AssignedQuotaSpace": -1,
      "ReportedQuotaError": false,
      "ReportedQuotaWarning": false,
      "MainOperation": "Backup",
      "ParsedResult": "Success",
      "Interrupted": false,
      "Version": "2.0.9.107 (2.0.9.107_canary_2024-09-11)",
      "EndTime": "0001-01-01T00:00:00",
      "BeginTime": "2024-09-25T11:41:53.1073117Z",
      "Duration": "00:00:00",
      "MessagesActualLength": 0,
      "WarningsActualLength": 0,
      "ErrorsActualLength": 0,
      "Messages": null,
      "Warnings": null,
      "Errors": null
    }
  },
  "VacuumResults": null,
  "DeleteResults": {
    "DeletedSetsActualLength": 0,
    "DeletedSets": null,
    "Dryrun": false,
    "MainOperation": "Delete",
    "CompactResults": {
      "DeletedFileCount": 0,
      "DownloadedFileCount": 0,
      "UploadedFileCount": 0,
      "DeletedFileSize": 0,
      "DownloadedFileSize": 0,
      "UploadedFileSize": 0,
      "Dryrun": false,
      "VacuumResults": null,
      "MainOperation": "Compact",
      "ParsedResult": "Success",
      "Interrupted": false,
      "Version": "2.0.9.107 (2.0.9.107_canary_2024-09-11)",
      "EndTime": "0001-01-01T00:00:00",
      "BeginTime": "2024-09-25T15:12:57.634111Z",
      "Duration": "00:00:00",
      "MessagesActualLength": 0,
      "WarningsActualLength": 0,
      "ErrorsActualLength": 0,
      "Messages": null,
      "Warnings": null,
      "Errors": null,
      "BackendStatistics": {
        "RemoteCalls": 1242,
        "BytesUploaded": 25829116604,
        "BytesDownloaded": 837622592,
        "FilesUploaded": 988,
        "FilesDownloaded": 16,
        "FilesDeleted": 237,
        "FoldersCreated": 0,
        "RetryAttempts": 0,
        "UnknownFileSize": 0,
        "UnknownFileCount": 0,
        "KnownFileCount": 25894,
        "KnownFileSize": 675683676350,
        "LastBackupDate": "2024-09-21T08:25:26+02:00",
        "BackupListCount": 20,
        "TotalQuotaSpace": 0,
        "FreeQuotaSpace": 0,
        "AssignedQuotaSpace": -1,
        "ReportedQuotaError": false,
        "ReportedQuotaWarning": false,
        "MainOperation": "Backup",
        "ParsedResult": "Success",
        "Interrupted": false,
        "Version": "2.0.9.107 (2.0.9.107_canary_2024-09-11)",
        "EndTime": "0001-01-01T00:00:00",
        "BeginTime": "2024-09-25T11:41:53.1073117Z",
        "Duration": "00:00:00",
        "MessagesActualLength": 0,
        "WarningsActualLength": 0,
        "ErrorsActualLength": 0,
        "Messages": null,
        "Warnings": null,
        "Errors": null
      }
    },
    "ParsedResult": "Success",
    "Interrupted": false,
    "Version": "2.0.9.107 (2.0.9.107_canary_2024-09-11)",
    "EndTime": "0001-01-01T00:00:00",
    "BeginTime": "2024-09-25T14:53:35.7722874Z",
    "Duration": "00:00:00",
    "MessagesActualLength": 0,
    "WarningsActualLength": 0,
    "ErrorsActualLength": 0,
    "Messages": null,
    "Warnings": null,
    "Errors": null,
    "BackendStatistics": {
      "RemoteCalls": 1242,
      "BytesUploaded": 25829116604,
      "BytesDownloaded": 837622592,
      "FilesUploaded": 988,
      "FilesDownloaded": 16,
      "FilesDeleted": 237,
      "FoldersCreated": 0,
      "RetryAttempts": 0,
      "UnknownFileSize": 0,
      "UnknownFileCount": 0,
      "KnownFileCount": 25894,
      "KnownFileSize": 675683676350,
      "LastBackupDate": "2024-09-21T08:25:26+02:00",
      "BackupListCount": 20,
      "TotalQuotaSpace": 0,
      "FreeQuotaSpace": 0,
      "AssignedQuotaSpace": -1,
      "ReportedQuotaError": false,
      "ReportedQuotaWarning": false,
      "MainOperation": "Backup",
      "ParsedResult": "Success",
      "Interrupted": false,
      "Version": "2.0.9.107 (2.0.9.107_canary_2024-09-11)",
      "EndTime": "0001-01-01T00:00:00",
      "BeginTime": "2024-09-25T11:41:53.1073117Z",
      "Duration": "00:00:00",
      "MessagesActualLength": 0,
      "WarningsActualLength": 0,
      "ErrorsActualLength": 0,
      "Messages": null,
      "Warnings": null,
      "Errors": null
    }
  },
  "RepairResults": null,
  "TestResults": null,
  "ParsedResult": "Fatal",
  "Interrupted": false,
  "Version": "2.0.9.107 (2.0.9.107_canary_2024-09-11)",
  "EndTime": "2024-09-25T15:17:08.8432499Z",
  "BeginTime": "2024-09-25T11:41:53.1072613Z",
  "Duration": "03:35:15.7359886",
  "MessagesActualLength": 2496,
  "WarningsActualLength": 0,
  "ErrorsActualLength": 3,
  "Messages": [
    "2024-09-25 13:41:54 +02 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation Backup has started",
    "2024-09-25 13:42:02 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started:  ()",
    "2024-09-25 13:42:05 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Completed:  (25.29 KB)",
    "2024-09-25 13:42:15 +02 - [Information-Duplicati.Library.Main.Operation.Backup.RecreateMissingIndexFiles-RecreateMissingIndexFile]: Re-creating missing index file for duplicati-be90ad7b6839d4a2981d5274aee425c21.dblock.zip.aes",
    "2024-09-25 13:42:15 +02 - [Information-Duplicati.Library.Main.Operation.BackupHandler-SkipUsnForVolume]: Performing full scan for volume \"C:\\\": Previous backup did not record USN journal info",
    "2024-09-25 13:42:15 +02 - [Information-Duplicati.Library.Main.Operation.BackupHandler-SkipUsnForVolume]: Performing full scan for volume \"D:\\\": Previous backup did not record USN journal info",
    "2024-09-25 13:42:15 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-ie29f86e5ee4c4d84b796559f276e0305.dindex.zip.aes (66.34 KB)",
    "2024-09-25 13:42:15 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-ie29f86e5ee4c4d84b796559f276e0305.dindex.zip.aes (66.34 KB)",
    "2024-09-25 13:54:35 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-bd692489c0af14a0d9efeed236ccca88f.dblock.zip.aes (49.80 MB)",
    "2024-09-25 13:54:36 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-bd692489c0af14a0d9efeed236ccca88f.dblock.zip.aes (49.80 MB)",
    "2024-09-25 13:54:39 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-i9d5e40891cd0492cb5673e89861c9ea2.dindex.zip.aes (245.68 KB)",
    "2024-09-25 13:54:40 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-i9d5e40891cd0492cb5673e89861c9ea2.dindex.zip.aes (245.68 KB)",
    "2024-09-25 13:54:50 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-bc13182df6ab34ce4a27beb6770cc8787.dblock.zip.aes (49.81 MB)",
    "2024-09-25 13:54:53 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-bc13182df6ab34ce4a27beb6770cc8787.dblock.zip.aes (49.81 MB)",
    "2024-09-25 13:55:03 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-i857c6a6793dd4be0828d4b121d64a1d0.dindex.zip.aes (250.01 KB)",
    "2024-09-25 13:55:03 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-i857c6a6793dd4be0828d4b121d64a1d0.dindex.zip.aes (250.01 KB)",
    "2024-09-25 13:55:06 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-bb9179b78659b491a9caa34d64aea33c8.dblock.zip.aes (49.82 MB)",
    "2024-09-25 13:55:08 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-bb9179b78659b491a9caa34d64aea33c8.dblock.zip.aes (49.82 MB)",
    "2024-09-25 13:55:10 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-if58863fe863944c1b83ff306f37cb83c.dindex.zip.aes (238.47 KB)",
    "2024-09-25 13:55:10 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-if58863fe863944c1b83ff306f37cb83c.dindex.zip.aes (238.47 KB)"
  ],
  "Warnings": [],
  "Errors": [
    "2024-09-25 17:17:08 +02 - [Error-Duplicati.Library.Main.Operation.BackupHandler-FatalError]: Fatal error\r\nDataErrorException: Data Error",
    "2024-09-25 17:17:08 +02 - [Error-Duplicati.Library.Main.Operation.BackupHandler-RollbackError]: Rollback error: Cannot access a disposed object.\r\nObject name: 'SQLiteConnection'.\r\nObjectDisposedException: Cannot access a disposed object.\r\nObject name: 'SQLiteConnection'.",
    "2024-09-25 17:17:08 +02 - [Error-Duplicati.Library.Main.Controller-FailedOperation]: The operation Backup has failed with error: Data Error\r\nDataErrorException: Data Error"
  ],
  "BackendStatistics": {
    "RemoteCalls": 1242,
    "BytesUploaded": 25829116604,
    "BytesDownloaded": 837622592,
    "FilesUploaded": 988,
    "FilesDownloaded": 16,
    "FilesDeleted": 237,
    "FoldersCreated": 0,
    "RetryAttempts": 0,
    "UnknownFileSize": 0,
    "UnknownFileCount": 0,
    "KnownFileCount": 25894,
    "KnownFileSize": 675683676350,
    "LastBackupDate": "2024-09-21T08:25:26+02:00",
    "BackupListCount": 20,
    "TotalQuotaSpace": 0,
    "FreeQuotaSpace": 0,
    "AssignedQuotaSpace": -1,
    "ReportedQuotaError": false,
    "ReportedQuotaWarning": false,
    "MainOperation": "Backup",
    "ParsedResult": "Success",
    "Interrupted": false,
    "Version": "2.0.9.107 (2.0.9.107_canary_2024-09-11)",
    "EndTime": "0001-01-01T00:00:00",
    "BeginTime": "2024-09-25T11:41:53.1073117Z",
    "Duration": "00:00:00",
    "MessagesActualLength": 0,
    "WarningsActualLength": 0,
    "ErrorsActualLength": 0,
    "Messages": null,
    "Warnings": null,
    "Errors": null
  }
}
        

[ts678]

Google search can’t find any prior report of your first or second error lines, but code is likely at:

duplicati/duplicati/blob/2827be6bb81a5694a9d6750a4b737fbb1f486253/Duplicati/Library/Main/Operation/BackupHandler.cs#L650-L668

There have been changes in this file, including two the day before this release (in other areas).

Is there any stack trace to look over, possibly in the server log at About → Show log → Stored?

The one-liners in the job log are not as helpful, plus there are only a few before messages limit.

@Taomyn

"MessagesActualLength": 2496,

and most aren’t here. I don’t know if eventually this needs a log file set up to see pre-error action.

This could use developer input anyway.

[Taomyn]

There was this in the server log view:

SharpCompress.Compressors.LZMA.DataErrorException: Data Error
   at SharpCompress.Compressors.LZMA.LzmaStream.Read(Byte[] buffer, Int32 offset, Int32 count)
   at Duplicati.Library.Main.Volumes.BlockVolumeReader.ReadBlock(String hash, Byte[] blockbuffer)
   at Duplicati.Library.Main.Operation.CompactHandler.DoCompact(LocalDeleteDatabase db, Boolean hasVerifiedBackend, IDbTransaction& transaction, BackendManager sharedBackend)
   at Duplicati.Library.Main.Operation.DeleteHandler.DoRun(LocalDeleteDatabase db, IDbTransaction& transaction, Boolean hasVerifiedBackend, Boolean forceCompact, BackendManager sharedManager)
   at Duplicati.Library.Main.Operation.BackupHandler.CompactIfRequired(BackendManager backend, Int64 lastVolumeSize)
   at Duplicati.Library.Main.Operation.BackupHandler.RunAsync(String[] sources, IFilter filter, CancellationToken token)
   at CoCoL.ChannelExtensions.WaitForTaskOrThrow(Task task)
   at Duplicati.Library.Main.Operation.BackupHandler.Run(String[] sources, IFilter filter, CancellationToken token)
   at Duplicati.Library.Main.Controller.<>c__DisplayClass12_0.<Backup>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)

[ts678]

There should be a timestamp above that which you can check, but it looks like

@Taomyn

SharpCompress.Compressors.LZMA.DataErrorException: Data Error

might explain

@Taomyn

  "Errors": [
    "2024-09-25 17:17:08 +02 - [Error-Duplicati.Library.Main.Operation.BackupHandler-FatalError]: Fatal error\r\nDataErrorException: Data Error",

however the new message talking about LZMA makes me wonder if you configured it with:

  --zip-compression-method (Enumeration): Set the ZIP compression method
    Use this option to set an alternative compressor method, such as LZMA. Note that using another value than Deflate will cause the option --zip-compression-level to be ignored.
    * values: None, Deflate, BZip2, LZMA, PPMd
    * default value: Deflate

Regardless, the new stack looks like it finished the backup, deleted a version due to retention, started a compact, and choked on a corrupted dblock file somehow LZMA rather than Deflate.

The easiest way to find the name of the bad file might be to run Compact manually for the job, while watching About → Show log → Live → Retry

[Taomyn]

@ts678

There should be a timestamp above that which you can check, but it looks like

Do you mean this because there’s nothing in the log text above that line:

@ts678

however the new message talking about LZMA makes me wonder if you configured it with:

  --zip-compression-method (Enumeration): Set the ZIP compression method
    Use this option to set an alternative compressor method, such as LZMA. Note that using another value than Deflate will cause the option --zip-compression-level to be ignored.
    * values: None, Deflate, BZip2, LZMA, PPMd
    * default value: Deflate

I have this set for all my jobs, but I don’t recall why and was for a good reason or so I thought:

@ts678

The easiest way to find the name of the bad file might be to run Compact manually for the job, while watching About → Show log → Live → Retry

I will try that and report back

[Taomyn]

26 Sep 2024 14:20: Backend event: Get - Completed: duplicati-b0eea475a30f1400790621f5b8d96fd1d.dblock.zip.aes (49.85 MB)
26 Sep 2024 14:20: Backend event: Get - Started: duplicati-b0eea475a30f1400790621f5b8d96fd1d.dblock.zip.aes (49.85 MB)
26 Sep 2024 14:19: Backend event: Get - Completed: duplicati-b0d7db3c279cf46c6a1bc4042bf347e0b.dblock.zip.aes (49.98 MB)
26 Sep 2024 14:19: Backend event: Get - Started: duplicati-b0d7db3c279cf46c6a1bc4042bf347e0b.dblock.zip.aes (49.98 MB)
26 Sep 2024 14:19: Backend event: Get - Completed: duplicati-b0d0fee3d1f784621834ad1e22e18ec47.dblock.zip.aes (49.92 MB)
26 Sep 2024 14:19: Backend event: Get - Started: duplicati-b0d0fee3d1f784621834ad1e22e18ec47.dblock.zip.aes (49.92 MB)
26 Sep 2024 14:19: removing file listed as Temporary: duplicati-i8206c127913c4e6296247b6e4886d6de.dindex.zip.aes
26 Sep 2024 14:19: removing file listed as Temporary: duplicati-b6827183af6e541bc964bc53c385b9f64.dblock.zip.aes
26 Sep 2024 14:19: removing file listed as Deleting: duplicati-ifa233b1fc9f046a19b9b655227ab90d9.dindex.zip.aes
26 Sep 2024 14:19: removing file listed as Deleting: duplicati-if88cffbb0bb34a7ca798a5582dab0046.dindex.zip.aes
26 Sep 2024 14:19: removing file listed as Deleting: duplicati-i913e8cc18c5f428dbddbd4d055f28ddb.dindex.zip.aes
26 Sep 2024 14:19: removing file listed as Deleting: duplicati-i54e68ce2fb1a4d03bb936b515de913f9.dindex.zip.aes
26 Sep 2024 14:19: removing file listed as Deleting: duplicati-i3c0d47662753441eb16a1aee740f6856.dindex.zip.aes
26 Sep 2024 14:19: removing file listed as Deleting: duplicati-b0b83e129871847c4a8f6934c2dda0de7.dblock.zip.aes
26 Sep 2024 14:19: removing file listed as Deleting: duplicati-b0b262a9f7eab47cc8b594b25fe2c9870.dblock.zip.aes
26 Sep 2024 14:19: removing file listed as Deleting: duplicati-b09f383a8abb149e88dda2b6f93be9518.dblock.zip.aes
26 Sep 2024 14:19: removing file listed as Deleting: duplicati-b08e27cd0a52347bbb08ad0d225c5aa19.dblock.zip.aes
26 Sep 2024 14:19: removing file listed as Deleting: duplicati-b08c6a5c7aaf74829a10411fed45d5c98.dblock.zip.aes
26 Sep 2024 14:19: Backend event: List - Completed: (26.03 KB)
26 Sep 2024 14:19: Backend event: List - Started: ()
26 Sep 2024 14:19: Compacting because there are 5 fully deletable volume(s)
26 Sep 2024 14:17: The operation Compact has started

            {
  "DeletedFileCount": 0,
  "DownloadedFileCount": 0,
  "UploadedFileCount": 0,
  "DeletedFileSize": 0,
  "DownloadedFileSize": 0,
  "UploadedFileSize": 0,
  "Dryrun": false,
  "VacuumResults": null,
  "MainOperation": "Compact",
  "ParsedResult": "Fatal",
  "Interrupted": false,
  "Version": "2.0.9.107 (2.0.9.107_canary_2024-09-11)",
  "EndTime": "2024-09-26T12:20:21.0887608Z",
  "BeginTime": "2024-09-26T12:17:05.312727Z",
  "Duration": "00:03:15.7760338",
  "MessagesActualLength": 22,
  "WarningsActualLength": 0,
  "ErrorsActualLength": 1,
  "Messages": [
    "2024-09-26 14:17:06 +02 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation Compact has started",
    "2024-09-26 14:19:17 +02 - [Information-Duplicati.Library.Main.Database.LocalDeleteDatabase-CompactReason]: Compacting because there are 5 fully deletable volume(s)",
    "2024-09-26 14:19:20 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started:  ()",
    "2024-09-26 14:19:22 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Completed:  (26.03 KB)",
    "2024-09-26 14:19:23 +02 - [Information-Duplicati.Library.Main.Operation.FilelistProcessor-RemoteUnwantedMissingFile]: removing file listed as Deleting: duplicati-b08c6a5c7aaf74829a10411fed45d5c98.dblock.zip.aes",
    "2024-09-26 14:19:23 +02 - [Information-Duplicati.Library.Main.Operation.FilelistProcessor-RemoteUnwantedMissingFile]: removing file listed as Deleting: duplicati-b08e27cd0a52347bbb08ad0d225c5aa19.dblock.zip.aes",
    "2024-09-26 14:19:23 +02 - [Information-Duplicati.Library.Main.Operation.FilelistProcessor-RemoteUnwantedMissingFile]: removing file listed as Deleting: duplicati-b09f383a8abb149e88dda2b6f93be9518.dblock.zip.aes",
    "2024-09-26 14:19:23 +02 - [Information-Duplicati.Library.Main.Operation.FilelistProcessor-RemoteUnwantedMissingFile]: removing file listed as Deleting: duplicati-b0b262a9f7eab47cc8b594b25fe2c9870.dblock.zip.aes",
    "2024-09-26 14:19:23 +02 - [Information-Duplicati.Library.Main.Operation.FilelistProcessor-RemoteUnwantedMissingFile]: removing file listed as Deleting: duplicati-b0b83e129871847c4a8f6934c2dda0de7.dblock.zip.aes",
    "2024-09-26 14:19:23 +02 - [Information-Duplicati.Library.Main.Operation.FilelistProcessor-RemoteUnwantedMissingFile]: removing file listed as Deleting: duplicati-i3c0d47662753441eb16a1aee740f6856.dindex.zip.aes",
    "2024-09-26 14:19:23 +02 - [Information-Duplicati.Library.Main.Operation.FilelistProcessor-RemoteUnwantedMissingFile]: removing file listed as Deleting: duplicati-i54e68ce2fb1a4d03bb936b515de913f9.dindex.zip.aes",
    "2024-09-26 14:19:23 +02 - [Information-Duplicati.Library.Main.Operation.FilelistProcessor-RemoteUnwantedMissingFile]: removing file listed as Deleting: duplicati-i913e8cc18c5f428dbddbd4d055f28ddb.dindex.zip.aes",
    "2024-09-26 14:19:23 +02 - [Information-Duplicati.Library.Main.Operation.FilelistProcessor-RemoteUnwantedMissingFile]: removing file listed as Deleting: duplicati-if88cffbb0bb34a7ca798a5582dab0046.dindex.zip.aes",
    "2024-09-26 14:19:23 +02 - [Information-Duplicati.Library.Main.Operation.FilelistProcessor-RemoteUnwantedMissingFile]: removing file listed as Deleting: duplicati-ifa233b1fc9f046a19b9b655227ab90d9.dindex.zip.aes",
    "2024-09-26 14:19:23 +02 - [Information-Duplicati.Library.Main.Operation.FilelistProcessor-RemoteUnwantedMissingFile]: removing file listed as Temporary: duplicati-b6827183af6e541bc964bc53c385b9f64.dblock.zip.aes",
    "2024-09-26 14:19:23 +02 - [Information-Duplicati.Library.Main.Operation.FilelistProcessor-RemoteUnwantedMissingFile]: removing file listed as Temporary: duplicati-i8206c127913c4e6296247b6e4886d6de.dindex.zip.aes",
    "2024-09-26 14:19:39 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Started: duplicati-b0d0fee3d1f784621834ad1e22e18ec47.dblock.zip.aes (49.92 MB)",
    "2024-09-26 14:19:40 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Completed: duplicati-b0d0fee3d1f784621834ad1e22e18ec47.dblock.zip.aes (49.92 MB)",
    "2024-09-26 14:19:40 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Started: duplicati-b0d7db3c279cf46c6a1bc4042bf347e0b.dblock.zip.aes (49.98 MB)",
    "2024-09-26 14:19:42 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Completed: duplicati-b0d7db3c279cf46c6a1bc4042bf347e0b.dblock.zip.aes (49.98 MB)"
  ],
  "Warnings": [],
  "Errors": [
    "2024-09-26 14:20:21 +02 - [Error-Duplicati.Library.Main.Controller-FailedOperation]: The operation Compact has failed with error: Data Error\r\nDataErrorException: Data Error"
  ],
  "BackendStatistics": {
    "RemoteCalls": 4,
    "BytesUploaded": 0,
    "BytesDownloaded": 157017447,
    "FilesUploaded": 0,
    "FilesDownloaded": 3,
    "FilesDeleted": 0,
    "FoldersCreated": 0,
    "RetryAttempts": 0,
    "UnknownFileSize": 0,
    "UnknownFileCount": 0,
    "KnownFileCount": 26645,
    "KnownFileSize": 695369782497,
    "LastBackupDate": "2024-09-25T13:41:54+02:00",
    "BackupListCount": 18,
    "TotalQuotaSpace": 0,
    "FreeQuotaSpace": 0,
    "AssignedQuotaSpace": -1,
    "ReportedQuotaError": false,
    "ReportedQuotaWarning": false,
    "MainOperation": "Compact",
    "ParsedResult": "Success",
    "Interrupted": false,
    "Version": "2.0.9.107 (2.0.9.107_canary_2024-09-11)",
    "EndTime": "0001-01-01T00:00:00",
    "BeginTime": "2024-09-26T12:17:05.3130139Z",
    "Duration": "00:00:00",
    "MessagesActualLength": 0,
    "WarningsActualLength": 0,
    "ErrorsActualLength": 0,
    "Messages": null,
    "Warnings": null,
    "Errors": null
  }
}
        

[ts678]

@Taomyn

Do you mean this

Yes. This confirms (at least to the minute) that this is the 17:17:08 (in other log) error.
Looking at wrong stack trace would have been a waste, and maybe even misleading.

@Taomyn

I have this set for all my jobs, but I don’t recall why and was for a good reason or so I thought

I think it compresses to a smaller file, but with slower speed, and less support in tools.
If this is a corrupted file (TBD), choice of compression probably isn’t the main concern.

@Taomyn

Completed: duplicati-b0eea475a30f1400790621f5b8d96fd1d.dblock.zip.aes (49.85 MB)

is probably the file having trouble, as otherwise it should have continued fetching more.
Sometimes the downloading is asynchronous, so it might also have been an earlier file.
With all three having reasonable length, it’s hard to know for sure without testing more.

Activity is probably below:

duplicati/duplicati/blob/2827be6bb81a5694a9d6750a4b737fbb1f486253/Duplicati/Library/Main/Operation/CompactHandler.cs#L150-L164

If there was no concern about time and download volume (but there probably is, if this is the backup on Wasabi S3), The TEST command could be made to download all files, and using --full-remote-verification would check the blocks (or fail trying). What’s odd is that there should have been either (or perhaps both) a hash check on the whole file, and a decryption.

Duplicati making bad file content would be a bad thing. Trying to manually study is awkward. Downloading is any way you can do it. Decrypt is either AES Crypt on Windows or Linux, or Duplicati.CommandLine.SharpAESCrypt.exe in Duplicati’s folder, if you prefer doing CLI.

Unzip runs into a possible tools problem with LZMA, but 7-Zip can do it, if regular tools cannot.

[ts678]

The Log out seems not to have an effect on other tabs until they do something and then discover.

Sometimes the behavior is reasonable messaging , but often times it’s some hang, or maybe this:

which was from trying to view job logs.
http://localhost:8200/api/v1/backup/4/log?pagesize=15
got 500 Internal Server Error response.

If I try About, the hang is

and the 500 is to http://localhost:8200/api/v1/acknowledgements

In contrast, 2.0.8.1 seems to notice Log off fairly fast on its 299 second long poll, for example:

http://localhost:8300/api/v1/serverstate/?lasteventid=2255&longpoll=true&duration=299s

gets 401 Not logged in, and up goes a notice:

I haven’t tested to see how it reacts if I try operations before that, but it’s a far shorter window.

[Taomyn]

@ts678

@Taomyn

Completed: duplicati-b0eea475a30f1400790621f5b8d96fd1d.dblock.zip.aes (49.85 MB)

is probably the file having trouble, as otherwise it should have continued fetching more.
Sometimes the downloading is asynchronous, so it might also have been an earlier file.
With all three having reasonable length, it’s hard to know for sure without testing more.

I downloaded the file, extracted the ZIP with AEScrypt then used WinRAR to test the archive and it was fine.

[ts678]

@Taomyn

the file

There were three suspects. Please check other two.

[Taomyn]

Sorry, I tested the other two and they both tested fine:

For good measure I extracted all three into folders without problems