Exception from SQLite provider when application is shutting down

[dataweasel]

I hope I'm posting this in the right location. I have been running this problem down for several days now and I'm not sure what is going on. I've checked all my various libraries and 3rd party packages to see if there might be an issue there. The problem is that the issue is happening when my code is no longer running.

In a nutshell, my issue is happening here:

using System;
using System.Windows.Forms;
using System.Collections.Generic;
using System.Linq;
using System.Threading.Tasks;

namespace WeatherWire_Personal
{
    internal static class Program
    {
        /// <summary>
        ///  The main entry point for the application.
        /// </summary>
        [STAThread]
        static void Main()
        {
            Application.SetHighDpiMode(HighDpiMode.SystemAware);
            Application.EnableVisualStyles();
            Application.SetCompatibleTextRenderingDefault(false);
            Application.Run(new WWMonitor());
        }   **//-   <------ Exception is thrown HERE**
    }
}

It's at the point above that a "System.InvalidOperationException: 'Collection was modified; enumeration operation may not execute." exception is thrown. No tasks show in the debugger. I'm not sure what collection it is talking about since no collections in my code are being iterated at this point.

So...I disable "Enable Just My Code" in the debugger options, then set a breakpoint for that curly bracket. I kick off a debugging session again, then close down the application. When I hit the breakpoint there are no "Tasks" and no "Locals" shown. With "Source Link" enabled I the debugger I get:

	Name	Value	Type
	Message	"Collection was modified; enumeration operation may not execute."	string
	Source	"System.Private.CoreLib"	string
	StackTrace	" at System.ThrowHelper.ThrowInvalidOperationException_InvalidOperation_EnumFailedVersion() in /_/src/libraries/System.Private.CoreLib/src/System/ThrowHelper.cs:line 361"	string

Yesterday I ran the application from OUTSIDE Visual Studio 2022 from the DEBUG directory. When I clicked the close button the application appeared to shut down without issue, but looking in the Windows Application Log I saw:

Application: WeatherWire_Personal.exe
CoreCLR Version: 5.0.1221.52207
.NET Version: 5.0.12
Description: The process was terminated due to an unhandled exception.
Exception Info: System.InvalidOperationException: Collection was modified; enumeration operation may not execute.
   at System.Collections.Generic.List`1.Enumerator.MoveNextRare()
   at Microsoft.Data.Sqlite.SqliteConnectionPool.ReclaimLeakedConnections()
   at Microsoft.Data.Sqlite.SqliteConnectionPool.Clear()
   at Microsoft.Data.Sqlite.SqliteConnectionFactory.ReleasePool(SqliteConnectionPool pool, Boolean clearing)
   at Microsoft.Data.Sqlite.SqliteConnectionPoolGroup.Clear()
   at Microsoft.Data.Sqlite.SqliteConnectionFactory.ClearPools()
   at Microsoft.Data.Sqlite.SqliteConnectionFactory.<.ctor>b__7_1(Object _, EventArgs _)
   at System.AppContext.OnProcessExit()

...then immediately after...

Faulting application name: WeatherWire_Personal.exe, version: 0.1.1.0, time stamp: 0x61732c02
Faulting module name: KERNELBASE.dll, version: 10.0.19041.1387, time stamp: 0x0b9a844a
Exception code: 0xe0434352
Fault offset: 0x0000000000034f69
Faulting process id: 0xa208
Faulting application start time: 0x01d802880e12fd2f
Faulting application path: P:\Development\WeatherWire\WeatherWire_Personal\bin\Debug\net5.0-windows\WeatherWire_Personal.exe
Faulting module path: C:\WINDOWS\System32\KERNELBASE.dll
Report Id: d9c0925c-d9ae-40aa-b747-62bb35d2d0ea
Faulting package full name: 
Faulting package-relative application ID: 

I checked that I closed and even DISPOSE() my Sqlite Database connections.

I'm totally at a loss if this is something with Visual Studio, .Net 5, or what. It doesn't appear to be code that I'm running, although I haven't ruled it out. It's just that the exception is being thrown after all my code stops running.

I'd appreciate any guidance on where to look next that anyone has.

-Joe

[dataweasel]

Some more investigation...

I started working on commenting anything out that I thought might be an issue, working my way back up the main program loop...so to speak. Something strange:

//- Check the command line arguments to see if we need to process anything
                string[]? args = Environment.GetCommandLineArgs();
                if (args.Length > 0)
                {
                    CheckCommandLine(args, applog, _configDBPath, _msgDBPath, _nwwsClient);
                }
                else
                {
                    applog.Debug("No command line options present when app was started.");
                }

                Application.Exit();

                //- Display Splash Screen
                SplashScreen frmSplash = new SplashScreen(applog, _cfgHelper, _nwwsClient, _AssemblyVersion, _configDBPath, _msgDBPath, true);
                frmSplash.ShowDialog();

After the "Application.Exit()" statement, the application continues on running the SplashScreen. I was under the impression that Application.Exit is supposed to close down all the forms and then exit the application from the "Main()" method. In other words, anything after "Application.Exit();" is just unreachable code. If I use:

Application.Exit();
Environment.Exit(0);

...the program shuts down there, as expected.

Looking at the documentation for Application.Exit() I see:

Informs all message pumps that they must terminate, and then closes all application windows after the messages have been processed.

I'm no expert but am I to understand that "Application.Exit()" will kill off all message pumps, close all forms, but then the application continues to anything following it?

-Joe

[dataweasel]

Same thing happens if I use:

Application.Exit();
this.Close();

I know that the Application.Exit() closes the form that is currently running the code....but I would have expected the "this.Close()" would at least throw an exception.

[roji]

@dataweasel Application.Exit() is a Winforms API which terminates the Winforms application/resources (e.g. closing windows), but the .NET program itself continues running. Environment.Exit is the thing that actually terminates the .NET process, and also triggers the Sqlite connection pool clearing code which you see above. Microsoft.Data.Sqlite and Winforms are oblivious of each other.

Regardless, the stack trace you posted above does seem to indicate a bug. A few questions:

• Which version of Microsoft.Data.Sqlite are you using?
• Does the exception happen reliably every time? Or only from time to time? If it's the former, can you submit a minimal code repro which reproduces it?

From a cursory look at SqliteConnectionPool nothing obvious pops up. We do access _connections.Count without locking, but that shouldn't cause any exceptions (we may want to consider locking around it just in case though).

/cc @bricelam

[dataweasel]

@roji - I am using the latest Microsoft.Data.Sqlite from Nuget (so...6.0.1?). It does happen reliably every time...but I think I might have figured out my problem.

I think I had a stray Sqlite connection still open when the program went to exit. I did a full code review and found a class where I had opened a Sqlite connection and did not have a close at the end of the method. When the close wasn't there I would get this exception 100% of the time. When I added the close, the problem went away. I then commented out the close and the exception returned.

I will try to get a minimal code repro for you. I'm looking at the following:

1. Program Start
2. Open connection to Sqlite DB.
3. Instance a class that also opens a connection to a different Sqlite database but does not close it.
4. Exit main program

I'll let you know if this repros.

-Joe

[roji]

@dataweasel thanks for the additional. Even if you forgot the Close, I'm still very interested in looking into this, as it may indicate an internal bug which could have other effects. So a repro would be much appreciated.

[vonzshik]

That's an interesting bug, Whenever the pool attempts to reclaim a connection, while enumerating the list, it might call Return on a leaked connection. While returning the connection to the pool, in some cases it might dispose them. And while disposing the connection, it's removed from the _connections list. That way, the list is changed while it's already enumerated.

[dataweasel]

I quickly tried this with a Console Application and leaving the connection open didn't cause an issue. I'm not doing much work with the DB connections (just opening the connection to a file with no tables or data) so I'm not sure if that has anything to do with it. My application where this was failing was a Windows Form app (.Net 5).

Still working on it.

[vonzshik]

Managed to reproduce in a console app.

using Microsoft.Data.Sqlite;

Test();

GC.Collect();
GC.WaitForPendingFinalizers();
GC.Collect();

static void Test()
{
    var connection = new SqliteConnection("Data Source=hello.db");
    connection.Open();
}

[dataweasel]

This works:

using System;
using Microsoft.Data.Sqlite;

namespace SqliteDbTest
{
    internal class Program
    {
        private static SqliteConnection dbConn01 = null;

        static void Main(string[] args)
        {
            DBOpen();
            GC.Collect();
            GC.WaitForPendingFinalizers();
            GC.Collect();

        }

        static void DBOpen()
        {
            string strDB01File = @"c:\temp\db01.sqlite";

            dbConn01 = new SqliteConnection($"Data Source={strDB01File};");
            dbConn01.Open();
        }
    }
}

This breaks:

using System;
using Microsoft.Data.Sqlite;

namespace SqliteDbTest
{
    internal class Program
    {

        static void Main(string[] args)
        {
            DBOpen();
            GC.Collect();
            GC.WaitForPendingFinalizers();
            GC.Collect();

        }

        static void DBOpen()
        {
            string strDB01File = @"c:\temp\db01.sqlite";

            var dbConn01 = new SqliteConnection($"Data Source={strDB01File};");
            dbConn01.Open();
        }
    }
}

Changing to var instead of a declaration is the difference?

-Joe

[vonzshik]

Changing to var instead of a declaration is the difference?

Kind of, in your case it's the static field - the point is for the GC to collect SqliteConnection.

[dataweasel]

Kind of, in your case it's the static field - the point is for the GC to collect SqliteConnection.

Okay...I am starting to see it now. It's now how it is being used or even that it is "open" when the program is ending. When GC attempts to dispose of it (from a pool or something) it's disposing of the connection object, which changes the collection of connections while it is being enumerated. Did I get that right? That's why the stack trace has the "ReclaimLeakedConnections()" and such.

I'm still learning. Thanks for the insights.

[vonzshik]

When GC attempts to dispose of it (from a pool or something) it's disposing of the connection object, which changes the collection of connections while it is being enumerated.

Not exactly. SQLite has a mechanism to detect leaked connections, which is mostly determined by WeakReference<SqliteConnection?> going 'stale' (which does happen whenever SqliteConnection is GC'ed), Also, SQLite has a mechanism to clear the pool whenever an app is closing. Combining both of them leads to the issue you've encountered.

[roji]

Thanks for looking into this @vonzshik - yeah, ReclaimLeakedConnections iterates over _connections, but calls return inside which mutates them. So not a concurrency issue - just a plain old mutate-within-iteration bug.

Should be fixable by copying _connections before iterating.