Logos crash with System.AccessViolationException

[tbleher]

Note: this bug is not specific to the installer, but this seems the best place to track it and collect infos on it.

Sometimes Logos can get into a situation where it reproducibly crashes with the following backtrace:

0118:err:eventlog:ReportEventW L"Application: Logos.exe\n"
0118:err:eventlog:ReportEventW L"CoreCLR Version: 8.0.524.21615\n"
0118:err:eventlog:ReportEventW L".NET Version: 8.0.5\n"
0118:err:eventlog:ReportEventW L"Description: The process was terminated due to an unhandled exception.\n"
0118:err:eventlog:ReportEventW L"Exception Info: System.AccessViolationException: Attempted to read or write protected memory. This is often an indication that other memory is corrupt.\n"
0118:err:eventlog:ReportEventW L"Stack:\n"
0118:err:eventlog:ReportEventW L"   at MS.Win32.PresentationCore.UnsafeNativeMethods+MILUnknown.Release(IntPtr)\n"
0118:err:eventlog:ReportEventW L"   at MS.Win32.PresentationCore.UnsafeNativeMethods+MILUnknown.Release(IntPtr)\n"
0118:err:eventlog:ReportEventW L"   at System.Windows.Media.Imaging.BitmapDecoder.SetupDecoderFromUriOrStream(System.Uri, System.IO.Stream, System.Windows.Media.Imaging.BitmapCacheOption, System.Guid ByRef, Boolean ByRef, System.IO.Stream ByRef, System.IO.UnmanagedMemoryStream ByRef, Microsoft.Win32.SafeHandles.SafeFileH"...
0118:err:eventlog:ReportEventW L"   at System.Windows.Media.Imaging.BitmapDecoder.CreateFromUriOrStream(System.Uri, System.Uri, System.IO.Stream, System.Windows.Media.Imaging.BitmapCreateOptions, System.Windows.Media.Imaging.BitmapCacheOption, System.Net.Cache.RequestCachePolicy, Boolean)\n"
0118:err:eventlog:ReportEventW L"   at System.Windows.Media.Imaging.BitmapImage.FinalizeCreation()\n"
0118:err:eventlog:ReportEventW L"   at System.Windows.Media.Imaging.BitmapImage.EndInit()\n"
0118:err:eventlog:ReportEventW L"   at Libronix.Utility.Windows.BitmapSourceUtility+<>c__DisplayClass7_0.<CreateFromStream>b__0()\n"
0118:err:eventlog:ReportEventW L"   at Libronix.Utility.Windows.BitmapSourceUtility.NullIfFailedCreation[[System.__Canon, System.Private.CoreLib, Version=8.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e]](System.Func`1<System.__Canon>, System.Exception ByRef)\n"
0118:err:eventlog:ReportEventW L"   at Libronix.Utility.Windows.BitmapSourceUtility.CreateFromByteArray(Byte[])\n"
0118:err:eventlog:ReportEventW L"   at LDLS4.NotificationsViewModel.CreateResourceUpdatePopupMessage(Libronix.DigitalLibrary.ResourceInfo, Boolean, System.Threading.CancellationToken)\n"
0118:err:eventlog:ReportEventW L"   at LDLS4.NotificationsViewModel+<>c__DisplayClass55_0.<RefreshResourceUpdatesNotification>b__3(Libronix.DigitalLibrary.ResourceInfo)\n"
0118:err:eventlog:ReportEventW L"   at System.Linq.Enumerable+SelectListIterator`2[[Libronix.DigitalLibrary.ResourceInfo, Libronix.DigitalLibrary, Version=59.8.5.0, Culture=neutral, PublicKeyToken=null],[System.__Canon, System.Private.CoreLib, Version=8.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e]].MoveNext()"
0118:err:eventlog:ReportEventW L"   at System.Collections.Generic.List`1[[System.__Canon, System.Private.CoreLib, Version=8.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e]].AddRange(System.Collections.Generic.IEnumerable`1<System.__Canon>)\n"
0118:err:eventlog:ReportEventW L"   at LDLS4.NotificationsViewModel+<RefreshResourceUpdatesNotification>d__55.MoveNext()\n"
0118:err:eventlog:ReportEventW L"   at System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1+AsyncStateMachineBox`1[[System.Threading.Tasks.VoidTaskResult, System.Private.CoreLib, Version=8.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e],[LDLS4.NotificationsViewModel+<RefreshResourceUpdatesNotification>d__55,"...
0118:err:eventlog:ReportEventW L"   at System.Threading.ExecutionContext.RunInternal(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object)\n"
0118:err:eventlog:ReportEventW L"   at System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1+AsyncStateMachineBox`1[[System.Threading.Tasks.VoidTaskResult, System.Private.CoreLib, Version=8.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e],[LDLS4.NotificationsViewModel+<RefreshResourceUpdatesNotification>d__55,"...
0118:err:eventlog:ReportEventW L"   at System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1+AsyncStateMachineBox`1[[System.Threading.Tasks.VoidTaskResult, System.Private.CoreLib, Version=8.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e],[LDLS4.NotificationsViewModel+<RefreshResourceUpdatesNotification>d__55,"...
0118:err:eventlog:ReportEventW L"   at System.Windows.Threading.ExceptionWrapper.InternalRealCall(System.Delegate, System.Object, Int32)\n"
0118:err:eventlog:ReportEventW L"   at System.Windows.Threading.ExceptionWrapper.TryCatchWhen(System.Object, System.Delegate, System.Object, Int32, System.Delegate)\n"
0118:err:eventlog:ReportEventW L"   at System.Windows.Threading.DispatcherOperation.InvokeImpl()\n"
0118:err:eventlog:ReportEventW L"   at MS.Internal.CulturePreservingExecutionContext.CallbackWrapper(System.Object)\n"
0118:err:eventlog:ReportEventW L"   at System.Threading.ExecutionContext.RunInternal(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object)\n"
0118:err:eventlog:ReportEventW L"   at MS.Internal.CulturePreservingExecutionContext.Run(MS.Internal.CulturePreservingExecutionContext, System.Threading.ContextCallback, System.Object)\n"
0118:err:eventlog:ReportEventW L"   at System.Windows.Threading.DispatcherOperation.Invoke()\n"
0118:err:eventlog:ReportEventW L"   at System.Windows.Threading.Dispatcher.ProcessQueue()\n"
0118:err:eventlog:ReportEventW L"   at System.Windows.Threading.Dispatcher.WndProcHook(IntPtr, Int32, IntPtr, IntPtr, Boolean ByRef)\n"
0118:err:eventlog:ReportEventW L"   at MS.Win32.HwndWrapper.WndProc(IntPtr, Int32, IntPtr, IntPtr, Boolean ByRef)\n"
0118:err:eventlog:ReportEventW L"   at System.Windows.Threading.ExceptionWrapper.InternalRealCall(System.Delegate, System.Object, Int32)\n"
0118:err:eventlog:ReportEventW L"   at System.Windows.Threading.ExceptionWrapper.TryCatchWhen(System.Object, System.Delegate, System.Object, Int32, System.Delegate)\n"
0118:err:eventlog:ReportEventW L"   at System.Windows.Threading.Dispatcher.LegacyInvokeImpl(System.Windows.Threading.DispatcherPriority, System.TimeSpan, System.Delegate, System.Object, Int32)\n"
0118:err:eventlog:ReportEventW L"   at MS.Win32.HwndSubclass.SubclassWndProc(IntPtr, Int32, IntPtr, IntPtr)\n"
0118:err:eventlog:ReportEventW L"   at MS.Win32.UnsafeNativeMethods.DispatchMessage(System.Windows.Interop.MSG ByRef)\n"
0118:err:eventlog:ReportEventW L"   at MS.Win32.UnsafeNativeMethods.DispatchMessage(System.Windows.Interop.MSG ByRef)\n"
0118:err:eventlog:ReportEventW L"   at System.Windows.Threading.Dispatcher.PushFrameImpl(System.Windows.Threading.DispatcherFrame)\n"
0118:err:eventlog:ReportEventW L"   at System.Windows.Threading.Dispatcher.PushFrame(System.Windows.Threading.DispatcherFrame)\n"
0118:err:eventlog:ReportEventW L"   at System.Windows.Threading.Dispatcher.Run()\n"
0118:err:eventlog:ReportEventW L"   at System.Windows.Application.RunDispatcher(System.Object)\n"
0118:err:eventlog:ReportEventW L"   at System.Windows.Application.RunInternal(System.Windows.Window)\n"
0118:err:eventlog:ReportEventW L"   at System.Windows.Application.Run(System.Windows.Window)\n"
0118:err:eventlog:ReportEventW L"   at System.Windows.Application.Run()\n"
0118:err:eventlog:ReportEventW L"   at LDLS4.OurApp.InitializeAndRun(System.Collections.ObjectModel.ReadOnlyCollection`1<System.String>, Libronix.Utility.Windows.Threading.SingleInstanceManager, Libronix.Utility.Scope)\n"
0118:err:eventlog:ReportEventW L"   at LDLS4.OurApp.Main(System.String[])\n"

The bug has been present for quite a while (see e.g. the report at https://community.logos.com/forums/t/121.aspx?PageIndex=67 from 2022). I could reproduce it with Logos v10.34 below Wine 9.9 devel and .NET 8 on Ubuntu 22.04.

This bug should be fixed.

[tbleher]

Notes and ideas (from someone quite new to .NET, so not everything might be correct):

• There are reports that the crash has something to do with a corrupted resource index. This matches the backtrace insofar as the code seems to be related to resource update (see CreateResourceUpdatePopupMessage)
• The functions starting with Libronix and LDLS4 seem to be Logos-specific functions (with Libronix being the technical core of Logos, according to https://www.logos.com/grow/so_do_i_call_it_logos_or_libro/ )
• The other functions are from .NET, though the code seems to be shipped with Logos, so not from the .NET install

The backtrace indicates that there might be heap corruption going on, but I could not verify this so far via WINEDEBUG=warn+heap, so this might be a different issue (needs another round of tests)

Ideas for further exploration:

• Catch the exception in a .NET debugger and look at which bitmap is being loaded (see call System.Windows.Media.Imaging.BitmapDecoder.CreateFromUriOrStream(System.Uri, System.Uri, System.IO.Stream, System.Windows.Media.Imaging.BitmapCreateOptions, System.Windows.Media.Imaging.BitmapCacheOption, System.Net.Cache.RequestCachePolicy, Boolean)). This might provide clues what is wrong.
• Look at Logos traces (see https://wiki.logos.com/diagnostic_logging) to see if there is any info related to corrupted data
• Try to run the corrupted database on Logos on Windows. If it crashes there, too, then this is a strong indication that the actual problem happened earlier

[thw26]

Note: this bug is not specific to the installer, but this seems the best place to track it and collect infos on it.

I do this on GitHub while I gather enough info to open a bug at WineHQ. I was doing that with this issue: https://github.com/ferion11/LogosLinuxInstaller/issues/105 until @jg00dman told me the issue was in wine 64bit having yet to implement error catching. My assumption was that in time Wine devs would fix it. I never found the PR or discussion associated with it.

Have you checked Wine's stuff to see if it's known or is that why you are thinking to test the corrupted DB on Windows, to rule things out?

Also, here's a link to our reported bugs:

https://appdb.winehq.org/objectManager.php?sClass=version&iId=41116

[thw26]

See also the attachment at:

https://bugs.winehq.org/show_bug.cgi?id=54870#c2

[tbleher]

Thanks @thw26 for the pointers! I searched generically for the backtrace, but did not yet look at the Wine bug database in particular. I think that's worth doing. I wanted to collect info here, since I don't know yet where the bug is, and I guessed that probably the Wine developers will only look at the bug if it is more specific (i.e. it is clear where the bug in Wine is). But I could be wrong of course.

I wanted to test the DBs on Windows to narrow down the problem space (since right now I only know that the exception causes the program to stop, but the real error (i.e. memory corruption) could have been much earlier). This could be very tricky to narrow down without the source code of the program, but I'll try at least :)

I think better understanding what the app is trying to load when the exception hits would be a good first step, but I'll need to get to know .NET debuggers first (having never debugged a .NET program before).

Regarding database corruption: most databases in Logos seem to be standard sqlite databases, so general file structure of .db files can be verified.