efcore: Exception during IEnumerable param enumeration pretends to be a query problem

When EF receives an IEnumerable<T> query parameter, and an exception happens to be thrown during its deferred enumeration, EF logs an error as if something went wrong with the query. In actuality, the error had nothing to do with the query.

Let’s consider why one passes a deferred enumerable. At least not with the intent of making its enumeration a part of the query execution. 😃 Rather, say, because extra calls to ToList() reduce readability or are simply unnecessary.

For example:

var orderIds = inputModels.Select(model => model.OrderId);
// ToList() here would cause clutter - we are only enumerating once, after all

var orders = await dbContext.Orders
	.Where(order => orderIds.Contains(order.Id)
	.ToListAsync(cancellationToken);

Say that an exception is thrown during the enumeration of the IEnumerable<T>. A common use case for that is when we use DDD-style ValueObjects, such as an OrderId type. Perhaps OrderId is a string constrained to 50 alphanumeric characters. When the input does not satisfy the constraint, the OrderId constructor throws.

Suddenly, it matters way too much whether or not we add ToList() to the example’s first line:

  • If we add ToList(), the exception occurs normally. Our exception handler might kick in, blame the exception on caller error, and return BadRequest, without polluting the logs with any errors.
  • If we omit ToList(), the same things happen, but not before EF has logged an error!

Irrelevant error entries are the bane of any log’s usability, so the latter is quite undesirable. We could work around that by opting for the former, but how do we enforce that choice? Since the example was a natural way to write the code, spotting the “missing” ToList() would be an unreliable exercise.

Suggested solution

Exceptions caught during the enumeration of any IEnumerable query parameter should not cause EF to log. There is no difference of intent between the developer materializing the enumerable vs. letting EF enumerate it, so there should be no difference in the outcome either.

Implementation ideas

Some options:

  • Materialize any non-materialized enumerable parameters upfront, before entering the relevant try/catch block. (For example, if is not IReadOnlyCollection<T>, then we must materialize.)
  • Enumerate any enumerable parameters in their own try/catch block. Wrap potential exceptions in a custom exception type. At the existing outer catch that normally logs and rethrows, add a different catch for the new exception type. It simply unwraps the original exception and rethrows it.

Provider and version information

EF Core version: 7.0.0 Database provider: Microsoft.EntityFrameworkCore.SqlServer Target framework: .NET 7.0 Operating system: Windows 11 IDE: Visual Studio 2022 17.4.3

About this issue

  • Original URL
  • State: closed
  • Created a year ago
  • Comments: 15 (9 by maintainers)

Most upvoted comments

Yeah, I got really close with one of the new interceptors, IQueryExpressionInterceptor, but unfortunately it is called a fraction too late: after any captured variable expressions (like our IEnumerable<T>) have already been replaced by placeholders, e.g. __ids_0. The variable values themselves never pass through that interceptor, unfortunately.

I have to say I’m curious as to why this log message is bothersome enough for you to attempt such complex things to try to avoid it… It really doesn’t seem that bad to me personally.

Fair question. With regards to warnings and errors, we’ve worked hard to keep our logs clean of anything that does not require attention. In my experience in a consultant role, distractions like that accumulate and become velocity killers, so I’m pretty keen on optimizing that part of the workflow. I feel strongly about the scenario we’ve been discussing because it’s triggered by external API callers. I really want to prevent API callers from (inadvertently or maliciously) straining the development team. It truly works to have no boy who cries wolf!

Perhaps you can offer suggestions […]

Nothing comes to mind unfortunately; this particular enumeration happens for each query execution (i.e. it’s not part of the once-only compilation process), so there’s no interceptor for that. You can of course create a wrapper of your own for querying which would visit the query tree and do the enumeration, but that’s a very heavy hammer (and not great for perf, which is one reason we don’t have an interceptor here in the first place).

Is there a way I could filter out these log messages without filtering all query-related log messages?

If this is a specific exception which you can identify in a stack trace, you could have a logging filter that does this. But this doesn’t work in the general case where any exception may be thrown.

Any method that asks for IEnumerable<T> should only enumerate the input once.

That should be true in most cases, though there are exceptions. But in any case there’s no hard, visible guarantee around that.

I have to say I’m curious as to why this log message is bothersome enough for you to attempt such complex things to try to avoid it… It really doesn’t seem that bad to me personally.

Well the EF query fails to execute (because of an application-thrown exception)… I can see how maybe the log message could be different for that case, but I do think any EF query failure should be logged regardless of the source of the issue…