For about a year, my debugging tool crashed the instant anyone pointed it at SQLite. I had no idea, because I only ever ran it against SQL Server. Nobody opened an issue either, which tells you roughly how many people were using it. Here's the bug, because it's an easy one to ship and I doubt I'm alone.
The tool records the SQL that EF Core runs (among other things) and shows it in a dashboard. To do that it uses a DbCommandInterceptor, and I wanted each query's execution time. The way I got it was bad enough that I'll just show you:
public override InterceptionResult<DbDataReader> ReaderExecuting(
DbCommand command, CommandEventData eventData, InterceptionResult<DbDataReader> result)
{
var id = Guid.NewGuid();
command.CommandText += $" /* {id}:{DateTime.UtcNow.Ticks} */";
return result;
}
On the way in, glue a comment with an id and a timestamp onto the SQL. On the way out, in ReaderExecuted, parse that comment back off the command text and subtract to get the elapsed time. A little correlation system, smuggled through the query string.
Yeah.
The first problem is that this changes the SQL you send to the database. Every query left with a /* ... */ tail on it. SQL Server shrugs and runs it, which is the whole reason I never noticed, but now the database's own query logging is full of my garbage and I'm writing to something that isn't mine to write to.
The second problem is the one that actually broke. Rewriting CommandText after the command has run, while its reader is still open, throws on SQLite:
System.InvalidOperationException: An open reader is associated with this
command. Close it before changing the CommandText property.
SQLite in local dev is completely normal. So instead of a dashboard, those people got an exception thrown from inside the tool that was supposed to be helping them debug. Great look.
Now the part that stings. I built that whole id-in-a-comment contraption to carry one number from ReaderExecuting to ReaderExecuted. I never needed to. ReaderExecuted already hands you the duration, and the command, and everything else:
public override DbDataReader ReaderExecuted(
DbCommand command, CommandExecutedEventData eventData, DbDataReader result)
{
Record(command.CommandText, eventData.Duration);
return result;
}
CommandExecutedEventData.Duration is a TimeSpan that EF measured for me. The command is right there too. There was nothing to correlate, because both halves of what I wanted live in the same callback. I'd written a solution to a problem the API had already solved, and that solution happened to corrupt SQL and crash SQLite on its way past.
If you genuinely do need to carry state from executing to executed (something that's only available before the command runs, say), there's a stable handle for that too. eventData.CommandId is the same Guid across both calls. Key your own dictionary off it and leave the SQL alone:
private readonly ConcurrentDictionary<Guid, MyState> _inflight = new();
public override InterceptionResult<DbDataReader> ReaderExecuting(
DbCommand command, CommandEventData eventData, InterceptionResult<DbDataReader> result)
{
_inflight[eventData.CommandId] = CaptureWhateverYouNeed();
return result;
}
public override DbDataReader ReaderExecuted(
DbCommand command, CommandExecutedEventData eventData, DbDataReader result)
{
_inflight.TryRemove(eventData.CommandId, out var state);
// use state + eventData.Duration here
return result;
}
The command object is for reading. Whatever you want to stash, stash it on your side.
I rebuilt the tool around the boring one-liner and shipped 2.0. MIT, .NET 8/9/10, two lines to wire up, then you open /_debug and get your requests, the SQL with real parameter values, logs, exceptions, and an N+1 nag when one request fires the same query over and over. Demo gif and setup in the readme: https://github.com/eladser/AspNetDebugDashboard
If you write interceptors, go look at yours and make sure they're not doing something clever to the command text. Mine looked fine for a year.
