I have some good news:
The backup job completed 5h25min after starting it (start: 00.20 AM, end: 05.46 AM).
On the remote, one dindex and two dlist files have appeared at the very end of the backup process at 05.46 AM.
From the logs available I do not really understand what happened in most of the time (00.25 AM - 05.45 AM) because there are almost no entries, neither in the live log nor in the saved log file. The next messages after the ones copied in my previous posts are:
- New entries in live log (too much characters to post directly):
job_live_log_new_entries.zip (3.7 KB)
So for the live log, in the interval in which no visible progress happens, only the Hyper-V / MS SQL Server/ WMI provider messages appear twice but nothing else. - New entries in saved log file:
2024-04-27 05:45:45 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-bdd98b82632464cafaefb9ad65dff6c9f.dblock.zip.aes (39.88 MB)
2024-04-27 05:46:27 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-i94139bbd21cb408ca1bcced2d5bd664a.dindex.zip.aes (32.04 KB)
2024-04-27 05:46:27 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-i94139bbd21cb408ca1bcced2d5bd664a.dindex.zip.aes (32.04 KB)
2024-04-27 05:46:27 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-20240426T222037Z.dlist.zip.aes (2.28 MB)
2024-04-27 05:46:27 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-20240426T222037Z.dlist.zip.aes (2.28 MB)
2024-04-27 05:46:28 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-20240425T103610Z.dlist.zip.aes (62.84 MB)
2024-04-27 05:46:31 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-20240425T103610Z.dlist.zip.aes (62.84 MB)
2024-04-27 05:46:32 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started: ()
2024-04-27 05:46:32 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Completed: (2.82 KB)
2024-04-27 05:46:32 +02 - [Information-Duplicati.Library.Main.Operation.FilelistProcessor-RemoteUnwantedMissingFile]: removing file listed as Temporary: duplicati-20240425T103609Z.dlist.zip.aes
2024-04-27 05:46:33 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Started: duplicati-20240426T222037Z.dlist.zip.aes (2.28 MB)
2024-04-27 05:46:33 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Completed: duplicati-20240426T222037Z.dlist.zip.aes (2.28 MB)
2024-04-27 05:46:33 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Started: duplicati-ia41acd4ef57e4049ace8b09b5ca35509.dindex.zip.aes (14.56 KB)
2024-04-27 05:46:33 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Completed: duplicati-ia41acd4ef57e4049ace8b09b5ca35509.dindex.zip.aes (14.56 KB)
2024-04-27 05:46:33 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Started: duplicati-be550b9dfae8044cc9e24e6ffc689d1d5.dblock.zip.aes (99.95 MB)
2024-04-27 05:46:34 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Completed: duplicati-be550b9dfae8044cc9e24e6ffc689d1d5.dblock.zip.aes (99.95 MB)
- Now there is also available the general log of the job run (Expand job → Reporting → Show Log → General) which looks like a summary of the job log file:
Apr 27, 2024 5:46 AM - Operation: Backup
Time
Start 2024-04-27 00:20:37
End 2024-04-27 05:46:34
Duration 05:25:57
Source Files
Examined 18523 (33.61 GB)
Opened 2955 (9.91 GB)
Added 2681 (8.62 GB)
Modified 274 (1.29 GB)
Deleted 887041
Test Phase
Start 2024-04-27 05:46:33
End 2024-04-27 05:46:34
Duration 00:00:01
Verifications 3
Warnings 0
Errors 0
Warnings 0
Errors 0
Complete log
{
"DeletedFiles": 887041,
"DeletedFolders": 80747,
"ModifiedFiles": 274,
"ExaminedFiles": 18523,
"OpenedFiles": 2955,
"AddedFiles": 2681,
"SizeOfModifiedFiles": 1381506370,
"SizeOfAddedFiles": 9254360244,
"SizeOfExaminedFiles": 36087387660,
"SizeOfOpenedFiles": 10639404036,
"NotProcessedFiles": 0,
"AddedFolders": 1548,
"TooLargeFiles": 0,
"FilesWithError": 0,
"ModifiedFolders": 0,
"ModifiedSymlinks": 0,
"AddedSymlinks": 0,
"DeletedSymlinks": 0,
"PartialBackup": false,
"Dryrun": false,
"MainOperation": "Backup",
"CompactResults": null,
"VacuumResults": null,
"DeleteResults": null,
"RepairResults": null,
"TestResults": {
"MainOperation": "Test",
"VerificationsActualLength": 3,
"Verifications": [
{
"Key": "duplicati-20240426T222037Z.dlist.zip.aes",
"Value": []
},
{
"Key": "duplicati-ia41acd4ef57e4049ace8b09b5ca35509.dindex.zip.aes",
"Value": []
},
{
"Key": "duplicati-be550b9dfae8044cc9e24e6ffc689d1d5.dblock.zip.aes",
"Value": []
}
],
"ParsedResult": "Success",
"Version": "2.0.7.1 (2.0.7.1_beta_2023-05-25)",
"EndTime": "2024-04-27T03:46:34.6571012Z",
"BeginTime": "2024-04-27T03:46:33.7145473Z",
"Duration": "00:00:00.9425539",
"MessagesActualLength": 0,
"WarningsActualLength": 0,
"ErrorsActualLength": 0,
"Messages": null,
"Warnings": null,
"Errors": null,
"BackendStatistics": {
"RemoteCalls": 12,
"BytesUploaded": 214984043,
"BytesDownloaded": 107207767,
"FilesUploaded": 7,
"FilesDownloaded": 3,
"FilesDeleted": 0,
"FoldersCreated": 0,
"RetryAttempts": 0,
"UnknownFileSize": 0,
"UnknownFileCount": 0,
"KnownFileCount": 2891,
"KnownFileSize": 150696707391,
"LastBackupDate": "2024-04-27T00:20:37+02:00",
"BackupListCount": 9,
"TotalQuotaSpace": 322122280960,
"FreeQuotaSpace": 81383854080,
"AssignedQuotaSpace": -1,
"ReportedQuotaError": false,
"ReportedQuotaWarning": false,
"MainOperation": "Backup",
"ParsedResult": "Success",
"Version": "2.0.7.1 (2.0.7.1_beta_2023-05-25)",
"EndTime": "0001-01-01T00:00:00",
"BeginTime": "2024-04-26T22:20:37.5682708Z",
"Duration": "00:00:00",
"MessagesActualLength": 0,
"WarningsActualLength": 0,
"ErrorsActualLength": 0,
"Messages": null,
"Warnings": null,
"Errors": null
}
},
"ParsedResult": "Success",
"Version": "2.0.7.1 (2.0.7.1_beta_2023-05-25)",
"EndTime": "2024-04-27T03:46:34.665164Z",
"BeginTime": "2024-04-26T22:20:37.5682708Z",
"Duration": "05:25:57.0968932",
"MessagesActualLength": 32,
"WarningsActualLength": 0,
"ErrorsActualLength": 0,
"Messages": [
"2024-04-27 00:20:37 +02 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation Backup has started",
"2024-04-27 00:22:23 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started: ()",
"2024-04-27 00:22:27 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Completed: (2.82 KB)",
"2024-04-27 00:22:27 +02 - [Information-Duplicati.Library.Main.Operation.FilelistProcessor-RemoteUnwantedMissingFile]: removing file listed as Temporary: duplicati-20240424T134522Z.dlist.zip.aes",
"2024-04-27 00:22:27 +02 - [Information-Duplicati.Library.Main.Operation.FilelistProcessor-SchedulingMissingFileForDelete]: scheduling missing file for deletion, currently listed as Uploading: duplicati-20240424T134523Z.dlist.zip.aes",
"2024-04-27 00:22:27 +02 - [Information-Duplicati.Library.Main.Operation.FilelistProcessor-KeepIncompleteFile]: keeping protected incomplete remote file listed as Temporary: duplicati-20240425T103609Z.dlist.zip.aes",
"2024-04-27 00:22:36 +02 - [Information-Duplicati.Library.Main.Operation.Backup.UploadSyntheticFilelist-PreviousBackupFilelistUpload]: Uploading filelist from previous interrupted backup",
"2024-04-27 00:23:06 +02 - [Information-Duplicati.Library.Main.Operation.Backup.RecreateMissingIndexFiles-RecreateMissingIndexFile]: Re-creating missing index file for duplicati-ba8062607fee047ae8cbe4a9a9f8fe4e8.dblock.zip.aes",
"2024-04-27 00:23:09 +02 - [Information-Duplicati.Library.Main.Operation.BackupHandler-SkipUsnForVolume]: Performing full scan for volume \"C:\\\": Previous backup did not record USN journal info",
"2024-04-27 00:23:09 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-ifc87eb0863e74e57b90e65d36d8f510a.dindex.zip.aes (6.39 KB)",
"2024-04-27 00:23:09 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-ifc87eb0863e74e57b90e65d36d8f510a.dindex.zip.aes (6.39 KB)",
"2024-04-27 00:24:41 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-b89935303fcf54ceea825ae3fef3931f0.dblock.zip.aes (99.91 MB)",
"2024-04-27 00:24:46 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-b89935303fcf54ceea825ae3fef3931f0.dblock.zip.aes (99.91 MB)",
"2024-04-27 00:24:46 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-i034a63b4872d4dcd83dd136b906dac00.dindex.zip.aes (77.59 KB)",
"2024-04-27 00:24:46 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-i034a63b4872d4dcd83dd136b906dac00.dindex.zip.aes (77.59 KB)",
"2024-04-27 00:24:49 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-bdd98b82632464cafaefb9ad65dff6c9f.dblock.zip.aes (39.88 MB)",
"2024-04-27 05:45:45 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-bdd98b82632464cafaefb9ad65dff6c9f.dblock.zip.aes (39.88 MB)",
"2024-04-27 05:46:27 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-i94139bbd21cb408ca1bcced2d5bd664a.dindex.zip.aes (32.04 KB)",
"2024-04-27 05:46:27 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-i94139bbd21cb408ca1bcced2d5bd664a.dindex.zip.aes (32.04 KB)",
"2024-04-27 05:46:27 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-20240426T222037Z.dlist.zip.aes (2.28 MB)"
],
"Warnings": [],
"Errors": [],
"BackendStatistics": {
"RemoteCalls": 12,
"BytesUploaded": 214984043,
"BytesDownloaded": 107207767,
"FilesUploaded": 7,
"FilesDownloaded": 3,
"FilesDeleted": 0,
"FoldersCreated": 0,
"RetryAttempts": 0,
"UnknownFileSize": 0,
"UnknownFileCount": 0,
"KnownFileCount": 2891,
"KnownFileSize": 150696707391,
"LastBackupDate": "2024-04-27T00:20:37+02:00",
"BackupListCount": 9,
"TotalQuotaSpace": 322122280960,
"FreeQuotaSpace": 81383854080,
"AssignedQuotaSpace": -1,
"ReportedQuotaError": false,
"ReportedQuotaWarning": false,
"MainOperation": "Backup",
"ParsedResult": "Success",
"Version": "2.0.7.1 (2.0.7.1_beta_2023-05-25)",
"EndTime": "0001-01-01T00:00:00",
"BeginTime": "2024-04-26T22:20:37.5682708Z",
"Duration": "00:00:00",
"MessagesActualLength": 0,
"WarningsActualLength": 0,
"ErrorsActualLength": 0,
"Messages": null,
"Warnings": null,
"Errors": null
}
}
- And also a couple of entries exist in Expand job → Reporting → Show Log → Remote:
Apr 27, 2024 5:46 AM: get duplicati-be550b9dfae8044cc9e24e6ffc689d1d5.dblock.zip.aes
Apr 27, 2024 5:46 AM: get duplicati-ia41acd4ef57e4049ace8b09b5ca35509.dindex.zip.aes
Apr 27, 2024 5:46 AM: get duplicati-20240426T222037Z.dlist.zip.aes
Apr 27, 2024 5:46 AM: list
Apr 27, 2024 5:46 AM: put duplicati-20240425T103610Z.dlist.zip.aes
Apr 27, 2024 5:46 AM: put duplicati-20240426T222037Z.dlist.zip.aes
Apr 27, 2024 5:46 AM: put duplicati-i94139bbd21cb408ca1bcced2d5bd664a.dindex.zip.aes
Apr 27, 2024 12:24 AM: put duplicati-bdd98b82632464cafaefb9ad65dff6c9f.dblock.zip.aes
Apr 27, 2024 12:24 AM: put duplicati-i034a63b4872d4dcd83dd136b906dac00.dindex.zip.aes
Apr 27, 2024 12:24 AM: put duplicati-b89935303fcf54ceea825ae3fef3931f0.dblock.zip.aes
Apr 27, 2024 12:23 AM: put duplicati-ifc87eb0863e74e57b90e65d36d8f510a.dindex.zip.aes
Apr 27, 2024 12:22 AM: list
Do you have any ideas of what may have happened between 00.25 AM and 05.45 AM?
With compact disabled and full retention configured, we at least know that those process steps are not responsible for the delay observable this time.
Now that the job appears to have finished in a clean state, I may try to restart it and see how it behaves now (there should be barely any difference in source compared to the previous run). If you have any other suggestions of what to do next, I’m happy to hear them.
Also, if you need the full log in a single block for the live log or the log file, let me know. For the former, I can check whether my partial copies capture the whole job run interval.
EDIT, responding to the additional information you posted in the meantime:
Okay, that explanation is plausible. In fact, I remember going into “Edit” for the running job to check whether it has a snapshot-policy configured (it has not), then leaving without saving.
I can experiment a bit using those tools if you think restarting the job would be the most valuable option to proceed.
Is there an easy-to-follow way to check whether that is the case? The job details report (note that source is so small because I had removed source folders in previous partial job runs, it will be about 230 GB after re-adding them):
Source:33.61 GB
Backup:140.35 GB
Configured blocksize is 250 KB.