TrayIcon crashed during backup, with .NET runtime exception code c0000005

[ts678]

• I have searched open and closed issues for duplicates.
• I have searched the forum for related topics.

---

Environment info

• Duplicati version: 2.0.7.101 Canary (but it might just be a random .NET Framework failure)
• Operating system: Windows 10 Professional
• Backend: Microsoft OneDrive v2

Description

TrayIcon crashed during a routine backup, leaving its green icon which (as usual) vanished when moused over. Event log has:

Logged: 3/24/2024 12:59:32 PM Source: .NET Runtime Event ID: 1026 General:

Application: Duplicati.GUI.TrayIcon.exe
Framework Version: v4.0.30319
Description: The process was terminated due to an unhandled exception.
Exception Info: exception code c0000005, exception address 00007FFAAC888BED

Logged: 3/24/2024 12:59:39 PM Source: Application Error Event ID: 1000 General:

Faulting application name: Duplicati.GUI.TrayIcon.exe, version: 2.0.7.101, time stamp: 0x65eb0952
Faulting module name: ntdll.dll, version: 10.0.19041.3996, time stamp: 0x39215800
Exception code: 0xc0000005
Fault offset: 0x00000000000d8bed
Faulting process id: 0x5cc4
Faulting application start time: 0x01da77b40980d850
Faulting application path: C:\Duplicati\duplicati-2.0.7.101_canary_2024-03-08\Duplicati.GUI.TrayIcon.exe
Faulting module path: C:\Windows\SYSTEM32\ntdll.dll
Report Id: ab40d213-401d-461e-a670-48ac2c2441bc
Faulting package full name: 
Faulting package-relative application ID: 

Steps to reproduce

1. Unknown. I ran a GUI backup. No recent changes to Windows or Duplicati known. Reproduce on demand might not exist.

• Actual result:
  Crash partway through backup. It managed to upload 10 dblock and 10 dindex files to OneDrive before the crash though.
• Expected result:
  Backup

As you can see, my Duplicati folder path is a little non-standard. For years I've been installing Duplicati from .zip files into per-version folders, enabling easier start of whatever Duplicati I need for whatever purpose I'm aiming at. I also disable autoupdate notifications and the usual dual-procsss updater steps because I want to run exactly the version I need. I don't think this setup is related to crash though.

Some Google searching makes me think .NET Framework had a memory access violation. I don't know how Duplicati can fix that beyond moving to a newer platform (to possibly get a different set of bugs -- but hopefully fewer overall). See Battle plan for migrating to .Net8

Screenshots

Debug log

I do have a profiling log with --profile-all-database-queries, but I think there are intentional or accidental gaps in what that shows.
A slightly anonymized chunk at the end is:

2024-03-24 12:59:08 -04 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: Starting - ExecuteNonQuery: INSERT INTO "FilesetEntry" ("FilesetID", "FileID", "Lastmodified") VALUES (654, 284798, 638465007362291830)
2024-03-24 12:59:08 -04 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: ExecuteNonQuery: INSERT INTO "FilesetEntry" ("FilesetID", "FileID", "Lastmodified") VALUES (654, 284798, 638465007362291830) took 0:00:00:00.218
2024-03-24 12:59:08 -04 - [Verbose-Duplicati.Library.Main.Operation.Backup.MetadataPreProcess.FileEntry-AddDirectory]: Adding directory C:\Users\Me\My Drive\CBB_HP4\C\Users\Me\AppData\Roaming\Mozilla\Firefox\Profiles\3w8afwwg.default\storage\default\http+++cas.ny.us.criteo.com\idb\12183338011.sqlite\20170505143037\
2024-03-24 12:59:08 -04 - [Verbose-Duplicati.Library.Main.Operation.Backup.FileEnumerationProcess-IncludingPath]: Including path as no filters matched: C:\Users\Me\My Drive\CBB_HP4\C\Users\Me\AppData\Roaming\Mozilla\Firefox\Profiles\3w8afwwg.default\storage\default\http+++cas.ny.us.criteo.com\idb\12183338011.sqlite\20170505143037\12183338011.sqlite
2024-03-24 12:59:09 -04 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteScalarInt64]: Starting - ExecuteScalarInt64: SELECT "ID" FROM "Block" WHERE "Hash" = "cMtrKp9+HXrBpyvPTv+EpjIoMuRHR/EUi4SfiCX0Rjk=" AND "Size" = 149
2024-03-24 12:59:18 -04 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteScalarInt64]: ExecuteScalarInt64: SELECT "ID" FROM "Block" WHERE "Hash" = "cMtrKp9+HXrBpyvPTv+EpjIoMuRHR/EUi4SfiCX0Rjk=" AND "Size" = 149 took 0:00:00:09.269
2024-03-24 12:59:18 -04 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteScalarInt64]: Starting - ExecuteScalarInt64: SELECT "ID" FROM "Blockset" WHERE "Fullhash" = "cMtrKp9+HXrBpyvPTv+EpjIoMuRHR/EUi4SfiCX0Rjk=" AND "Length" = 149
2024-03-24 12:59:18 -04 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteScalarInt64]: ExecuteScalarInt64: SELECT "ID" FROM "Blockset" WHERE "Fullhash" = "cMtrKp9+HXrBpyvPTv+EpjIoMuRHR/EUi4SfiCX0Rjk=" AND "Length" = 149 took 0:00:00:00.213
2024-03-24 12:59:18 -04 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteScalarInt64]: Starting - ExecuteScalarInt64: SELECT "A"."ID" FROM "Metadataset" A, "BlocksetEntry" B, "Block" C WHERE "A"."BlocksetID" = "B"."BlocksetID" AND "B"."BlockID" = "C"."ID" AND "C"."Hash" = "cMtrKp9+HXrBpyvPTv+EpjIoMuRHR/EUi4SfiCX0Rjk=" AND "C"."Size" = 149
2024-03-24 12:59:18 -04 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteScalarInt64]: ExecuteScalarInt64: SELECT "A"."ID" FROM "Metadataset" A, "BlocksetEntry" B, "Block" C WHERE "A"."BlocksetID" = "B"."BlocksetID" AND "B"."BlockID" = "C"."ID" AND "C"."Hash" = "cMtrKp9+HXrBpyvPTv+EpjIoMuRHR/EUi4SfiCX0Rjk=" AND "C"."Size" = 149 took 0:00:00:00.012
2024-03-24 12:59:18 -04 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteScalarInt64]: Starting - ExecuteScalarInt64: SELECT "ID" FROM "PathPrefix" WHERE "Prefix" = "C:\Users\Me\My Drive\CBB_HP4\C\Users\Me\AppData\Roaming\Mozilla\Firefox\Profiles\3w8afwwg.default\storage\default\http+++cas.ny.us.criteo.com\idb\12183338011.sqlite\"
2024-03-24 12:59:18 -04 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteScalarInt64]: ExecuteScalarInt64: SELECT "ID" FROM "PathPrefix" WHERE "Prefix" = "C:\Users\Me\My Drive\CBB_HP4\C\Users\Me\AppData\Roaming\Mozilla\Firefox\Profiles\3w8afwwg.default\storage\default\http+++cas.ny.us.criteo.com\idb\12183338011.sqlite\" took 0:00:00:00.000
2024-03-24 12:59:18 -04 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteScalarInt64]: Starting - ExecuteScalarInt64: SELECT "ID" FROM "FileLookup" WHERE "BlocksetID" = -100 AND "MetadataID" = 283921 AND "Path" = "20170505143037\" AND "PrefixID" = 5405
2024-03-24 12:59:19 -04 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteScalarInt64]: ExecuteScalarInt64: SELECT "ID" FROM "FileLookup" WHERE "BlocksetID" = -100 AND "MetadataID" = 283921 AND "Path" = "20170505143037\" AND "PrefixID" = 5405 took 0:00:00:00.522
2024-03-24 12:59:19 -04 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: Starting - ExecuteNonQuery: INSERT INTO "FilesetEntry" ("FilesetID", "FileID", "Lastmodified") VALUES (654, 284799, 638465008401123377)
2024-03-24 12:59:19 -04 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: ExecuteNonQuery: INSERT INTO "FilesetEntry" ("FilesetID", "FileID", "Lastmodified") VALUES (654, 284799, 638465008401123377) took 0:00:00:00.000
2024-03-24 12:59:35 -04 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteScalarInt64]: Starting - ExecuteScalarInt64: SELECT "ID" FROM "PathPrefix" WHERE "Prefix" = "C:\Users\Me\My Drive\CBB_HP4\C\Users\Me\AppData\Roaming\Mozilla\Firefox\Profiles\3w8afwwg.default\storage\default\http+++cas.ny.us.criteo.com\idb\12183338011.sqlite\20170505143037\"
2024-03-24 12:59:35 -04 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteScalarInt64]: ExecuteScalarInt64: SELECT "ID" FROM "PathPrefix" WHERE "Prefix" = "C:\Users\Me\My Drive\CBB_HP4\C\Users\Me\AppData\Roaming\Mozilla\Firefox\Profiles\3w8afwwg.default\storage\default\http+++cas.ny.us.criteo.com\idb\12183338011.sqlite\20170505143037\" took 0:00:00:00.635
2024-03-24 12:59:36 -04 - [Verbose-Duplicati.Library.Main.Operation.Backup.FilePreFilterProcess.FileEntry-SkipCheckNoMetadataChange]: Skipped checking file, because no metadata was updated C:\Users\Me\My Drive\CBB_HP4\C\Users\Me\AppData\Roaming\Mozilla\Firefox\Profiles\3w8afwwg.default\storage\default\http+++cas.ny.us.criteo.com\idb\12183338011.sqlite\20170505143037\12183338011.sqlite
2024-03-24 12:59:36 -04 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: Starting - ExecuteNonQuery: INSERT INTO "FilesetEntry" ("FilesetID", "FileID", "Lastmodified") VALUES (654, 11457, 636398010525420000)
2024-03-24 12:59:37 -04 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: ExecuteNonQuery: INSERT INTO "FilesetEntry" ("FilesetID", "FileID", "Lastmodified") VALUES (654, 11457, 636398010525420000) took 0:00:00:00.394
2024-03-24 12:59:36 -04 - [Verbose-Duplicati.Library.Main.Operation.Backup.MetadataPreProcess.FileEntry-AddDirectory]: Adding directory C:\Users\Me\My Drive\CBB_HP4\C\Users\Me\AppData\Roaming\Mozilla\Firefox\Profiles\3w8afwwg.default\storage\default\http+++cas.ny.us.criteo.com\.metadata-v2\
2024-03-24 12:59:36 -04 - [Verbose-Duplicati.Library.Main.Operation.Backup.FileEnumerationProcess-IncludingPath]: Including path as no filters matched: C:\Users\Me\My Drive\CBB_HP4\C\Users\Me\AppData\Roaming\Mozilla\Firefox\Profiles\3w8afwwg.default\storage\default\http+++cas.ny.us.criteo.com\.metadata-v2\20170805232928\

I'm also preserving the database at the time of crash (including -journal), and I also have the DB before (I keep a rolling history).
Some things in the crash DB look less than perfect, so I will probably bring this back up carefully, so any Duplicati goof gets found.
Sometimes all this care winds up being wasted, but I'd rather err on the side of caution because there are still unsolved corruptions around, which typically stay unsolved due to lack of information. If any developer experts want to advise on my analysis, please do.

Bad cleanups at backup time from a previous backup that failed were a suspected backup-breaker in the forum, but data is scarce...
Unexpected difference in fileset; unable to delete broken version. Crash here has lots of Duplicati info, but little on .NET Framework.

One thing I'll be looking at is what happens to a dblock/dindex pair that were uploaded but aren't currently in IndexBlockLink data.

[ts678]

Where we left off from above, these were not linked in IndexBlockLink:
5275 duplicati-i3d50ab7aa9384ceb8593fe0c8733150e.dindex.zip.aes
5268 duplicati-b0a036e8f4a4d413887a64aa2e8e0119d.dblock.zip.aes
Looking in dindex shows it goes with the above, but DB doesn't know.

Moving in smaller steps while collecting, inspecting, predicting, I ran Verify files, Repair, list-broken-files, Compact now, and backup which already had after-backup tests including dlist/dindex block check, Remotevolume/IndexBlockLink sanity, and test of recreate,

Interestingly the repair below is not in repair, so only ran upon backup:

duplicati/Duplicati/Library/Main/Operation/BackupHandler.cs

Lines 484 to 485 in 6f2f8c5

	// Rebuild any index files that are missing
	await Backup.RecreateMissingIndexFiles.Run(db, m_options, m_result.TaskReader);

2024-03-29 17:16:56 -04 - [Information-Duplicati.Library.Main.Operation.Backup.RecreateMissingIndexFiles-RecreateMissingIndexFile]: Re-creating missing index file for duplicati-b0a036e8f4a4d413887a64aa2e8e0119d.dblock.zip.aes

2024-03-29 17:16:57 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-ic0594262095a4474b7f5bc3be68732c0.dindex.zip.aes (5.36 KB)
2024-03-29 17:16:59 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-ic0594262095a4474b7f5bc3be68732c0.dindex.zip.aes (5.36 KB)

At this point, that was probably the second dindex for duplicati-b0a036e8f4a4d413887a64aa2e8e0119d.dblock.zip.aes, but it's uncertain because the old dblock and its new dindex got deleted in compact after deletes, because the dblock had excess waste.

Regardless, the original dindex is still hanging around without a dblock, so recreate notices this. I also have a job to test recreate on the rclone sync of the actual destination, and can run it without bothering the production DB. On the GUI, it pops a red error which then can show me the job log (thanks to changes in Canary to make one rather than making me look into the server log).

2024-03-29 18:45:25 -04 - [Error-Duplicati.Library.Main.Operation.RecreateDatabaseHandler-MissingFileDetected]: Remote file referenced as duplicati-b0a036e8f4a4d413887a64aa2e8e0119d.dblock.zip.aes by duplicati-i3d50ab7aa9384ceb8593fe0c8733150e.dindex.zip.aes, but not found in list, registering a missing remote file

2024-03-29 18:45:55 -04 - [Warning-Duplicati.Library.Main.Database.LocalRecreateDatabase-MissingVolumesDetected]: Found 1 missing volumes; attempting to replace blocks from existing volumes
2024-03-29 18:46:45 -04 - [Warning-Duplicati.Library.Main.Database.LocalRecreateDatabase-MissingVolumesDetected]: Found 1 missing volumes; attempting to replace blocks from existing volumes

GUI Commandline version shows the same thing in a different format:

Downloading file duplicati-i3d75c08ac5b64a08945d17b7f3420698.dindex.zip.aes (28.00 KB) ...
Remote file referenced as duplicati-b0a036e8f4a4d413887a64aa2e8e0119d.dblock.zip.aes by duplicati-i3d50ab7aa9384ceb8593fe0c8733150e.dindex.zip.aes, but not found in list, registering a missing remote file
Downloading file duplicati-i3ff3e01d7bec45b89e62227cb6203330.dindex.zip.aes (541 bytes) ...
...
Downloading file duplicati-iff1da9bcca884968bc301392329cd5d6.dindex.zip.aes (124.98 KB) ...
Found 1 missing volumes; attempting to replace blocks from existing volumes
Found 1 missing volumes; attempting to replace blocks from existing volumes
Return code: 0

I'm not sure I like the return code 0 after the error, but maybe it had other reasons to declare success despite logging an error.

Because my IndexBlockLink checker was sounding an alarm, I looked at the recreated database, and found the orphaned dindex linked to a State Temporary dblock file, and had its blocks in the Block table. Is this a safe view? The dblock file is gone, and any backup that deduplicates it based on the Block table is going to be referencing a block that doesn't actually exist in the backup.

My own Python script dlist/dindex checker would fall into the same trap, as it assumes the dindex blocks are actually in backup.

Arguably this is a secondary issue to the original crash, but I didn't feel like opening another issue without any developer input.

[kenkendk]

Is this a safe view? The dblock file is gone, and any backup that deduplicates it based on the Block table is going to be referencing a block that doesn't actually exist in the backup.

No it sounds like it will lead to bad things going forward.

I'm not sure I like the return code 0 after the error, but maybe it had other reasons to declare success despite logging an error.

That is because the messages are classified as warnings. I think the logic here is a bit weird, because those dblock files should not really exist, just because the dindex files mention them. If the dblock files are not actually used, they should not be re-introduced, but rather the dindex files should be deleted (assuming they have no additional information).

[ts678]

No it sounds like it will lead to bad things going forward.

It did look like State Temporary files get deleted typically (maybe subject to options like no-backup-verification), to save things.
I'm actually still running this backup to see what breaks (because I've got lots of logging, and a time series of older databases).

Before finding you were here after the "Unexpected differences" forum work, I almost pointed out there that this issue causes:

2024-04-03 19:49:40 -04 - [Error-Duplicati.Library.Main.Operation.RecreateDatabaseHandler-MissingFileDetected]: Remote file referenced as duplicati-b0a036e8f4a4d413887a64aa2e8e0119d.dblock.zip.aes by duplicati-i3d50ab7aa9384ceb8593fe0c8733150e.dindex.zip.aes, but not found in list, registering a missing remote file

and it's not because of a recently interrupted compact in a backup. Anyway, back to forum to keep catch up on recent actions.