Connection Resiliency, Logging and Diagnostics in EF Core: Execution Strategies, Command Timeouts, TagWith, Events and Metrics

Version note: The code in this post was written and tested with EF Core 10, SQL Server 2025 and OpenTelemetry .NET 1.21.

Guess First

The API of Bookstore, the online bookstore used as the shared example across this site's series, has EnableRetryOnFailure() turned on. To imitate a failover, you take the database down with ALTER DATABASE ... SET OFFLINE WITH ROLLBACK IMMEDIATE, right after that you send an order with POST /orders, and seven seconds later you bring the database back with SET ONLINE. Is the order saved, and how many "retry" lines do you see in the log?

On my first attempt I got this: the order was saved with a 201 in 10.2 seconds, and there wasn't a single retry line in the log. EF Core's execution strategy never even kicked in. The reason is in the second section of this post.

This post is about the bad days of the Bookstore API's conversation with its database: dropped connections, long-running queries, and the question "which endpoint sent this SQL?". In post 13 we touched on the execution strategy as a pitfall, and in posts 17 and 21 we set up LogTo, TagWith and the slow query interceptor. Here we bring all of it together in a production-ready API.

EnableRetryOnFailure and the Execution Strategy

builder.Services.AddDbContext<BookstoreContext>(options =>
{
    options.UseSqlServer(builder.Configuration.GetConnectionString("Bookstore"), sql =>
    {
        sql.EnableRetryOnFailure(maxRetryCount: 5, maxRetryDelay: TimeSpan.FromSeconds(10), errorNumbersToAdd: null);
        sql.CommandTimeout(15);
    });
    options.ConfigureWarnings(w => w.Throw(CoreEventId.RowLimitingOperationWithoutOrderByWarning));
    if (builder.Environment.IsDevelopment())
    {
        options.EnableSensitiveDataLogging().EnableDetailedErrors();
    }
});

EnableRetryOnFailure() turns on the SQL Server provider's SqlServerRetryingExecutionStrategy. The defaults of the parameterless call, in the EF Core source code, are 6 attempts and a maximum delay of 30 seconds. I find 30 seconds long for an API request, so I limited it to 5 attempts and 10 seconds. The delay grows exponentially with each attempt and a random amount is added, as you'll see in the output below.

The strategy doesn't retry every error, only the SQL Server error numbers it knows to be transient. The list is in EF Core's SqlServerTransientExceptionDetector class: deadlocks (1205), "Cannot open database" (4060), dropped connections (10053, 10054, 10060), Azure SQL's "database currently unavailable" codes (40613, 40501…) and more. If your environment has an error number of its own, you add it with errorNumbersToAdd. One thing is not on the list: command timeout (-2). The comment in the source says why: when a timeout arrives the command may actually have completed, so retrying isn't safe.

With retries enabled, EF Core buffers query results in memory, because it needs to be able to restart a read that was cut off halfway. For queries that return very large result sets memory use goes up; turn it on knowing that.

Trying a Failover

The reason there were no retry logs on the first attempt is the connection resiliency of Microsoft.Data.SqlClient underneath EF Core. When a pooled connection breaks, SqlClient tries to rebuild it on its own (ConnectRetryCount defaults to 1, ConnectRetryInterval to 10 seconds); the request taking 10.2 seconds is exactly that wait. The error never reached EF Core. Microsoft's connection resiliency documentation also uses ConnectRetryCount=0 in its sample connection string; to avoid two layers doing the same job on top of each other, keep retries in one place. I added ConnectRetryCount=0 to the connection string and repeated the same test:

01:26:15  ALTER DATABASE ... SET OFFLINE WITH ROLLBACK IMMEDIATE
01:26:22  ALTER DATABASE ... SET ONLINE

info: Microsoft.EntityFrameworkCore.Infrastructure[10404]
      A transient exception occurred during execution. The operation will be retried after 0ms.
      Microsoft.Data.SqlClient.SqlException (0x80131904): Cannot open database "efseries_ext_33" requested by the login. The login failed.
info: Microsoft.EntityFrameworkCore.Infrastructure[10404]
      A transient exception occurred during execution. The operation will be retried after 1048ms.
info: Microsoft.EntityFrameworkCore.Infrastructure[10404]
      A transient exception occurred during execution. The operation will be retried after 3078ms.
info: Microsoft.EntityFrameworkCore.Infrastructure[10404]
      A transient exception occurred during execution. The operation will be retried after 7615ms.
info: Bookstore.Api.Orders.PlaceOrderRequest[0]
      Order 100009 placed for request 6f1d2c3a-0000-4000-8000-000000000003

{"id":9,"orderNumber":100009,"totalAmount":14.89} http=201 t=12.172230s

For readability I converted the output from the JSON log to plain text and cut each retry's stack trace. Four attempts failed, on the fifth the database was up and the order was saved; the customer didn't see an error, they just waited 12 seconds. The delays are 0, 1, 3 and 7.6 seconds: exponential backoff plus a random amount. We covered a real failover (such as an availability group switching to another replica) in the Database Performance and Scaling series post on high availability and failover; whether the application survives it depends on exactly this setting.

Your Own Transaction and Idempotency

The rule from post 13 applies here too: with retries on, if you open your own transaction with BeginTransactionAsync and call SaveChanges, EF Core throws an InvalidOperationException saying "The configured execution strategy 'SqlServerRetryingExecutionStrategy' does not support user-initiated transactions"; I got exactly the same message in this setup. The fix is to hand the whole unit of work to the strategy. But there's one more hard case: if the connection drops right during COMMIT, you can't know whether the transaction committed. The strategy assumes it didn't and tries again; if it did, the order is written twice.

In Bookstore I took two measures against this. First, the client gives every order a RequestId (a GUID), and the table has a unique index on that column; if the same order is written a second time, the database rejects it. Second, EF Core's ExecuteInTransactionAsync: if a transient error occurs during the commit, it calls the verifySucceeded function to ask whether the work actually happened:

// Same RequestId again (client retry): return the existing order.
var existing = await db.Orders
    .TagWith("POST /orders: idempotency check")
    .Where(o => o.RequestId == request.RequestId)
    .Select(o => new { o.Id, o.OrderNumber, o.TotalAmount })
    .FirstOrDefaultAsync(ct);
if (existing is not null)
{
    return Results.Ok(existing);
}

// ... read prices, build Order and OrderItems, db.Orders.Add(order)

var strategy = db.Database.CreateExecutionStrategy();
await strategy.ExecuteInTransactionAsync(
    db,
    operation: (context, token) => context.SaveChangesAsync(acceptAllChangesOnSuccess: false, token),
    verifySucceeded: (context, token) => context.Orders.AsNoTracking().AnyAsync(o => o.RequestId == request.RequestId, token),
    ct);
db.ChangeTracker.AcceptAllChanges();

acceptAllChangesOnSuccess: false matters: if the operation is retried, the entities in the change tracker must still be in the Added state. Once everything is done, AcceptAllChanges closes the state. The request I sent a second time with the same RequestId didn't create a new order; it returned the first one:

{"id":7,"orderNumber":100007,"totalAmount":41.99}
{"id":7,"orderNumber":100007,"totalAmount":41.99}

I couldn't reliably reproduce a drop at commit time locally, so I'm not showing the moment verifySucceeded is called. But the logic is simple: the check itself is a query, and it also runs inside the strategy; when the database comes back, it asks "does this RequestId exist?". This is the EF Core counterpart of the approach whose design we discussed in the Solution Patterns series post on idempotency keys.

Command Timeout

In the SQL Server provider the command timeout is 30 seconds by default. A user waiting 30 seconds on a web request is long gone, so I reduced it to 15 in the API with sql.CommandTimeout(15); the CommandTimeout='15' in the log lines shows it. For a single operation you can use db.Database.SetCommandTimeout(...). In a report job I lowered the timeout to 2 seconds and ran a command that takes 5 seconds:

db.Database.SetCommandTimeout(TimeSpan.FromSeconds(2));
await db.Database.ExecuteSqlRawAsync("WAITFOR DELAY '00:00:05'");

fail: 11/15/2026 01:26:59.596 RelationalEventId.CommandError[20102] (Microsoft.EntityFrameworkCore.Database.Command)
      Failed executing DbCommand (2,014ms) [Parameters=[], CommandType='Text', CommandTimeout='2']
      WAITFOR DELAY '00:00:05'
SqlException: Execution Timeout Expired.  The timeout period elapsed prior to completion of the operation or the server is not responding.
Number: -2

Even though retries are on, there isn't a single retry line; as we said above, -2 isn't retried. Raising the timeout doesn't fix a slow query; first examine the query and the index, as in posts 17 and 30.

Logging: Categories, Environments and Turning Warnings into Errors

In ASP.NET Core, a context registered with AddDbContext uses the application's ILoggerFactory on its own; there's no need for LogTo. LogTo is for console apps, tests and a quick look. You choose what gets logged by category. EF Core's most useful category is Microsoft.EntityFrameworkCore.Database.Command, which writes every SQL statement that runs:

// appsettings.json
"Microsoft.EntityFrameworkCore.Database.Command": "Warning"

// appsettings.Development.json
"Microsoft.EntityFrameworkCore.Database.Command": "Information"

I ran the same request in both environments and counted: 0 command logs in Production, 1 in Development. At Warning level, Production still writes failed commands (CommandError). If you want to target specific events, you can pass a list of EventIds as in LogTo(Console.WriteLine, [RelationalEventId.CommandExecuted]); in the timeout example above I selected only the ExecutionStrategyRetrying and CommandError events this way.

EnableSensitiveDataLogging writes parameter values to the log (@q_contains='%emma%'); EnableDetailedErrors adds more expensive checks that tell you which column caused a problem on read errors. I turned both on only in Development. EF Core reminds you of it with a warning on the first request: "Sensitive data logging is enabled. Log entries and exception messages may include sensitive application data; this mode should only be enabled during development."

With ConfigureWarnings you can turn a warning into an error. In post 09 we saw that Take without OrderBy only produces a warning; in the API I made it an error, and a test endpoint without OrderBy returned 500:

System.InvalidOperationException: An error was generated for warning 'Microsoft.EntityFrameworkCore.Query.RowLimitingOperationWithoutOrderByWarning': The query uses a row limiting operator ('Skip'/'Take') without an 'OrderBy' operator. This may lead to unpredictable results. ...

Warnings get lost in the log; exceptions get caught in tests. Turning the warnings your team says it never wants to see again into errors is a cheap quality gate.

TagWith and TagWithCallSite: Linking SQL to Code

In post 17 we put a tag on a query by hand with TagWith. TagWithCallSite(), introduced in EF Core 6, generates the tag itself: file name and line number. I added it to the search endpoint in the API and had the log written as JSON, with its scopes (builder.Logging.AddJsonConsole(o => o.IncludeScopes = true)). Shortened:

{
  "EventId": 20101,
  "LogLevel": "Information",
  "Category": "Microsoft.EntityFrameworkCore.Database.Command",
  "Message": "Executed DbCommand (15ms) [Parameters=[@p='20', @q_contains='%emma%' (Size = 200), @q_contains0='%emma%' (Size = 100)], CommandType='Text', CommandTimeout='15']\n-- File: .../src/Bookstore.Api/Program.cs:51\n\nSELECT TOP(@p) [b].[Id], [b].[Title], [a].[Name] AS [Author], [b].[Price]\nFROM [catalog].[Books] AS [b]\n...",
  "Scopes": [
    {
      "Message": "SpanId:70a6f028ddcc0098, TraceId:dde5b2c6ccb84fe2df3821ca90f320d0, ParentId:0000000000000000",
      "TraceId": "dde5b2c6ccb84fe2df3821ca90f320d0"
    },
    {
      "Message": "RequestPath:/books/search RequestId:0HNQ2JQJT12MV:00000001",
      "RequestPath": "/books/search"
    }
  ]
}

I shortened the file path; in reality it contains the full path on the build machine. A single log record brings three things together: the SQL itself, the line of code that produced it (Program.cs:51), and the request path (RequestPath) with its TraceId. When these events go to Seq with the setup from the Seq post in the Logging in .NET series, a RequestPath = '/books/search' filter brings up every query that endpoint sent, and the TraceId every query of a single request. Because the tag is part of the SQL text, it also travels in the batch sent to the database; on SQL Server it shows up in tools that capture the batch text, such as Extended Events. A hand-written tag (TagWith("GET /books/bestsellers")) doesn't change during refactoring; TagWithCallSite always names the right line, but it changes as lines move. I prefer hand-written tags that carry the endpoint name.

DiagnosticListener, OpenTelemetry and Metrics

In post 21 we caught slow queries with a DbCommandInterceptor. An interceptor is tied to a context; to listen to all contexts from one place, EF Core also has a DiagnosticListener. Unlike an interceptor, it can't intervene in the flow; it only observes:

// Listens to EF Core's DiagnosticListener and logs commands slower than the threshold.
public sealed class SlowCommandObserver(ILogger<SlowCommandObserver> logger, TimeSpan threshold)
    : IObserver<DiagnosticListener>, IObserver<KeyValuePair<string, object?>>
{
    public void OnNext(DiagnosticListener listener)
    {
        if (listener.Name == DbLoggerCategory.Name)
        {
            listener.Subscribe(this);
        }
    }

    public void OnNext(KeyValuePair<string, object?> e)
    {
        if (e.Key == RelationalEventId.CommandExecuted.Name
            && e.Value is CommandExecutedEventData data
            && data.Duration > threshold)
        {
            logger.LogWarning("Slow command ({ElapsedMs} ms): {CommandText}", (long)data.Duration.TotalMilliseconds, data.Command.CommandText);
        }
    }

    public void OnCompleted() { }
    public void OnError(Exception error) { }
}

The threshold defaults to 200 ms; to try it I lowered it to 5 ms with the Diagnostics:SlowCommandMs setting, and the best seller endpoint produced this warning, with RequestPath /books/bestsellers in the log's scope:

Slow command (15 ms): -- GET /books/bestsellers

SELECT TOP(@p2) [b].[Title], [f].[Units]
FROM [dbo].[fn_BestSellers](@since) AS [f]
INNER JOIN [catalog].[Books] AS [b] ON [f].[BookId] = [b].[Id]
ORDER BY [f].[Units] DESC

One step beyond logs is tracing. OpenTelemetry's EF Core instrumentation package (OpenTelemetry.Instrumentation.EntityFrameworkCore, still in beta: 1.21.0-beta.1) opens a span for each command. To try it, I put the console exporter behind a setting:

builder.Services.AddOpenTelemetry()
    .ConfigureResource(r => r.AddService("Bookstore.Api"))
    .WithTracing(t => t.AddAspNetCoreInstrumentation().AddEntityFrameworkCoreInstrumentation().AddConsoleExporter())
    .WithMetrics(m => m.AddMeter("Microsoft.EntityFrameworkCore").AddConsoleExporter());

Activity.TraceId:            75d4a2db6b18ff367b0b7f5d1ecf5f18
Activity.SpanId:             af8e5718de7239d0
Activity.ParentSpanId:       3aaff3aab184699a
Activity.DisplayName:        efseries_ext_33
Activity.Kind:               Client
Activity.Duration:           00:00:00.0288600
Activity.Tags:
    db.system: mssql
    db.name: efseries_ext_33
    db.statement:

SELECT TOP(@p2) [b].[Title], [f].[Units]
FROM [dbo].[fn_BestSellers](@since) AS [f]
...

The parent of the SQL span is the ASP.NET Core span named GET /books/bestsellers; both carry the same TraceId. One detail caught my eye: db.statement didn't contain the TagWith comment, just empty lines in its place, while the same command appeared with its tag in the log and in the DiagnosticListener. If you plan to look at tags from traces, try it in your own setup first. Sending traces to Jaeger or Tempo and building dashboards is the subject of the Observability series.

Since EF Core 9 there is also a meter named Microsoft.EntityFrameworkCore: active context count, query count, compiled query cache hits/misses, SaveChanges count, execution strategy failures and concurrency failures. You can see it with dotnet-counters without touching the application; I collected it while putting load on the API:

dotnet-counters collect -p <PID> --counters Microsoft.EntityFrameworkCore --duration 00:00:00:06 --format csv

Microsoft.EntityFrameworkCore,microsoft.entityframeworkcore.queries ({query} / 1 sec),Rate,14
Microsoft.EntityFrameworkCore,microsoft.entityframeworkcore.compiled_query_cache_hits ({hits} / 1 sec),Rate,14
Microsoft.EntityFrameworkCore,microsoft.entityframeworkcore.compiled_query_cache_misses ({misses} / 1 sec),Rate,0
Microsoft.EntityFrameworkCore,microsoft.entityframeworkcore.execution_strategy_operation_failures ({failure} / 1 sec),Rate,0
Microsoft.EntityFrameworkCore,microsoft.entityframeworkcore.active_dbcontexts ({dbcontext}),Metric,0

14 queries per second, all 14 from the compiled query cache: after the first time, each query isn't compiled again. Cache misses staying above zero is a sign of dynamic queries that produce a different expression tree every time. According to the documentation, execution_strategy_operation_failures counts every failed attempt in a retried operation; when it rises above zero, it tells you the infrastructure is having transient problems. General use of dotnet-counters is covered in the Profiling and Diagnostics in .NET series post on dotnet-counters and built-in metrics.

Common Pitfalls

First, opening a BeginTransaction by hand while retries are on. The error comes immediately, and it's good that it does; but the fix isn't to turn retries off, it's to wrap the transaction in CreateExecutionStrategy().ExecuteAsync or ExecuteInTransactionAsync.

Second, a retry performing a non-idempotent write twice. After a connection drops during commit, the strategy runs the work from the start. An INSERT that relies on store-generated keys (identity) is written a second time with a different Id, without any error. Without a client-generated identifier (RequestId) with a unique index on it, or a verifySucceeded, retries can duplicate data. Don't put work that must not be repeated, such as sending e-mails or calling a payment service, inside the strategy block either.

Third, EnableSensitiveDataLogging in production. Customer names, e-mail addresses and search terms land in the log and from there in your log system. Keep it behind an IsDevelopment() check.

Fourth, retries in two layers. When SqlClient's ConnectRetryCount and EF Core's execution strategy stack up, as we saw, one hides the other and the total wait is longer than you expect. Decide which one you'll use, and see it in the log.

A Small Experiment

★☆☆ Run the API with EnableRetryOnFailure set to maxRetryCount: 2 and repeat the failover test. This time keep the database down for 20 seconds; note the error the client gets and the last message in the log.

★★☆ Send POST /orders twice at the same time with the same RequestId (two terminals). Examine which one hits the unique index and what the client gets back, and make the endpoint return the existing order in this case too.

★★★ Turn SlowCommandObserver into a DbCommandInterceptor and compare the two approaches: which one also sees the queries of ReportingContext, and which one can stop a command before it runs?

That wraps up the "EF Core in Practice" block: generating a model from the database, the LINQ translation catalog, the Fluent API, the daily life of migrations, and now resilience and observation in production. The series will continue with what EF Core 11 brings.