How to recover from aborted/stuck/crashed backup run?

[redusr]

@ts678

We posted at almost the same time, so see my last post, but it’s a little late to catch the action live now.

Thanks, I have tried to incorporate your findings in the edit of my previous post.

@ts678

You might find something in a log (level varies) near start of backup talking about things like the following:

2024-04-20 06:51:45 -04 - [Profiling-Timer.Begin-Duplicati.Library.Main.Operation.Common.DatabaseCommon-CommitTransactionAsync]: Starting - PreSyntheticFilelist
2024-04-20 06:51:46 -04 - [Profiling-Timer.Finished-Duplicati.Library.Main.Operation.Common.DatabaseCommon-CommitTransactionAsync]: PreSyntheticFilelist took 0:00:00:00.452
2024-04-20 06:51:46 -04 - [Information-Duplicati.Library.Main.Operation.Backup.UploadSyntheticFilelist-PreviousBackupFilelistUpload]: Uploading filelist from previous interrupted backup

The synthetic file list is a recovery for an interrupted backup that reflects how far it had gotten by interrupt.
I’m not sure why it’s prepared at start of backup but its old dlist is uploaded at end, next to the current dlist.

That is correct, the chosen log level seems not to show it as detailed as in your example but I also have the UploadSyntheticFilelist-PreviousBackupFilelistUpload entry at the beginning of the job run:

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

@ts678

The sizes seem strange, unless you cut the backup down as you were thinking of, but I didn’t really advise.
You can look at your other dlist file sizes. Unless your backup shrank a lot, dlist sizes should be similar, but

@redusr

Deleted 887041

makes me think you might have cut back, unless there’s a huge amount of file removal on the source drive.

…

@redusr

note that source is so small because I had removed source folders in previous partial job runs

So that probably explains why the dlist got so small (comments above), but you can see if sizes look OK.

The dlist file size continuously increased up to 62.8 MB in March when the job was retired. Same size is observable for the interrupted backup dlist file. For the successful run afterwards, as you already noted, it decreased considerably to 2.28 MB.
To clarify modifications in the job configuration:

• I had removed source folders from the job two times: 1) Before un-retiring the job (that is, before the first partial job run). 2) Before the second partial job run, hoping for faster progress. Afterwards, I posted in this forum and following your advice, I did no more reduce the source folder list. I did also not re-add any source folders to keep the scenario constant and not add another variable for investigation.
  My interpretation of the dlist file sizes is that the change in source folder list is only reflected in the dlist if a run has completed successfully (that at least is what the data of my case suggests).
• The only modifications in job configuration after posting here in the forum are:

@redusr

I have added these options with log level verbose, compact disabled and all data now being retained.

Regarding the odd put:

@ts678

What I find odd (and again, input from a skilled developer would help) is how the logs got a little misaligned.

@redusr

Apr 27, 2024 12:24 AM: Backend event: Put - Started: duplicati-bdd98b82632464cafaefb9ad65dff6c9f.dblock.zip.aes (39.88 MB)

was the live log, and reading up finds a good looking progress message of almost certainly the same file:

@redusr

Apr 27, 2024 12:24 AM: Uploaded 39.88 MB in 00:00:00.0313744, 1.24 GB/s

plus you said you saw it. The question is why the log file had the Started message but not the Completed:

@redusr

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)

and hours later:

@redusr

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)

Well spotted! This is indeed also reflected in the log file (there are no other log messages in between those two):

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)

Correct, I saw that file and as you already referred to it by its file size in your previous post, I am also pretty sure that it already had a size of 39.88 MB. Even though Duplicati reports the Put to be completed at 05.45 AM, the file meta data (last modified date) is still 00.24 AM (but I can’t tell whether this really means that the file was no more changed at 05.45 AM on the remote).
I would also be interested in developers’ thoughts about that.

@ts678

I mentioned the worse reliability of logging via live log compared to log file.

If that helps, I can change log-file-log-level from verbose to profiling. Verbose level resulted in 85k lines in a 25 MB log file.

@ts678

You can’t change blocksize on an existing backup. Default is 100 KB, Is that 250 KB for job 1 or job 2?

Block size of both jobs are:

1. Job 1: 250 KB
2. Job 2: 400 KB
   I have set the size at the initial configuration before running the backup for the first time. When creating job 2, I decided to choose a larger block size (mainly because I read that too small block sizes may cause problems when the number of overall blocks grows large).

@ts678

SQLite’s default memory cache size is only 2 MB, and databases are almost always larger, so getting temporary file activity instead of memory activity is easy to induce – and I/O is far slower than memory.

Query Planning can also make bad choices, especially if PRAGMA optimize isn’t run often enough, and there’s some thought that its decisions aren’t always good, so PRAGMA analyze should be run directly.

I can test both but to be honest, I do not really know what I had to do specifically. If I understand correctly, for cache size there exists an environment variable I could modify. If I know its name and which value format it expects, I can test increasing the cache size.
For the PRAGMA analyze I am even more clueless. I recall having read about that pragma from time to time when browing in the forum but am not sure what to do precisely: Is this something I should use manually and if so, at which point in time? How can I run it (within the Duplicati GUI, as command-line option or even by directly accessing the SQLite database when Duplicati is not running)?

I think I will rerun the backup job one more time with log-file-log-level profiling and in case it appears stuck, check out whether SysInternals tools provide any clue about what is actually happening.

EDIT: Corrected reported log file size (it’s MB, not KB)

EDIT 2: The rerun has completed in 2 minutes, processing time was thus not suspicious this time. As expected, not that much of data had to be transferred to the remote (one dindex/dblock pair and a single dlist file). I think I may now gradually extend the source folder list to the configuration prior to the partial backup job runs and may also enable auto-compact again. I will report whether I am successful. If there is anything else I can do to help reproducing the original issue, let me know.