Report debug log for connection cancellation (#35793)

Fixes #35708

Author: roji

src/EFCore.Relational/Diagnostics/DbConnectionInterceptor.cs

@@ -97,4 +97,16 @@ public virtual Task ConnectionFailedAsync(
         ConnectionErrorEventData eventData,
         CancellationToken cancellationToken = default)
         => Task.CompletedTask;
+
+    /// <inheritdoc />
+    public virtual void ConnectionCanceled(DbConnection connection, ConnectionEndEventData eventData)
+    {
+    }
+
+    /// <inheritdoc />
+    public virtual Task ConnectionCanceledAsync(
+        DbConnection connection,
+        ConnectionEndEventData eventData,
+        CancellationToken cancellationToken = default)
+        => Task.CompletedTask;
 }

src/EFCore.Relational/Diagnostics/IDbConnectionInterceptor.cs

@@ -261,7 +261,7 @@ Task ConnectionDisposedAsync(DbConnection connection, ConnectionEndEventData eve
         => Task.CompletedTask;
 
     /// <summary>
-    ///     Called when closing of a connection has failed with an exception.
+    ///     Called when a connection operation (e.g. open) has failed with an exception.
     /// </summary>
     /// <param name="connection">The connection.</param>
     /// <param name="eventData">Contextual information about the connection.</param>
@@ -270,7 +270,7 @@ void ConnectionFailed(DbConnection connection, ConnectionErrorEventData eventDat
     }
 
     /// <summary>
-    ///     Called when closing of a connection has failed with an exception.
+    ///     Called when a connection operation (e.g. open) has failed with an exception.
     /// </summary>
     /// <param name="connection">The connection.</param>
     /// <param name="eventData">Contextual information about the connection.</param>
@@ -279,4 +279,24 @@ void ConnectionFailed(DbConnection connection, ConnectionErrorEventData eventDat
     /// <exception cref="OperationCanceledException">If the <see cref="CancellationToken" /> is canceled.</exception>
     Task ConnectionFailedAsync(DbConnection connection, ConnectionErrorEventData eventData, CancellationToken cancellationToken = default)
         => Task.CompletedTask;
+
+    /// <summary>
+    ///     Called when the opening of a connection was canceled.
+    /// </summary>
+    /// <param name="connection">The connection.</param>
+    /// <param name="eventData">Contextual information about the connection.</param>
+    void ConnectionCanceled(DbConnection connection, ConnectionEndEventData eventData)
+    {
+    }
+
+    /// <summary>
+    ///     Called when the opening of a connection was canceled.
+    /// </summary>
+    /// <param name="connection">The connection.</param>
+    /// <param name="eventData">Contextual information about the connection.</param>
+    /// <param name="cancellationToken">A <see cref="CancellationToken" /> to observe while waiting for the task to complete.</param>
+    /// <returns>A <see cref="Task" /> representing the asynchronous operation.</returns>
+    /// <exception cref="OperationCanceledException">If the <see cref="CancellationToken" /> is canceled.</exception>
+    Task ConnectionCanceledAsync(DbConnection connection, ConnectionEndEventData eventData, CancellationToken cancellationToken = default)
+        => Task.CompletedTask;
 }

src/EFCore.Relational/Diagnostics/IRelationalCommandDiagnosticsLogger.cs

@@ -463,7 +463,7 @@ Task CommandErrorAsync(
     /// <param name="commandId">The correlation ID associated with the given <see cref="DbCommand" />.</param>
     /// <param name="connectionId">The correlation ID associated with the <see cref="DbConnection" /> being used.</param>
     /// <param name="startTime">The time that execution began.</param>
-    /// <param name="duration">The amount of time that passed until the exception was raised.</param>
+    /// <param name="duration">The amount of time that passed until the command was canceled.</param>
     /// <param name="commandSource">Source of the command.</param>
     void CommandCanceled(
         IRelationalConnection connection,
@@ -488,7 +488,7 @@ void CommandCanceled(
     /// <param name="commandId">The correlation ID associated with the given <see cref="DbCommand" />.</param>
     /// <param name="connectionId">The correlation ID associated with the <see cref="DbConnection" /> being used.</param>
     /// <param name="startTime">The time that execution began.</param>
-    /// <param name="duration">The amount of time that passed until the exception was raised.</param>
+    /// <param name="duration">The amount of time that passed until the command was canceled.</param>
     /// <param name="commandSource">Source of the command.</param>
     /// <param name="cancellationToken">A <see cref="CancellationToken" /> to observe while waiting for the task to complete.</param>
     /// <returns>A <see cref="Task" /> representing the async operation.</returns>

src/EFCore.Relational/Diagnostics/IRelationalConnectionDiagnosticsLogger.cs

@@ -210,6 +210,32 @@ Task ConnectionErrorAsync(
         bool logErrorAsDebug,
         CancellationToken cancellationToken = default);
 
+    /// <summary>
+    ///     Logs for the <see cref="RelationalEventId.ConnectionCanceled" /> event.
+    /// </summary>
+    /// <param name="connection">The connection.</param>
+    /// <param name="startTime">The time that the operation was started.</param>
+    /// <param name="duration">The amount of time that passed until the command was canceled.</param>
+    void ConnectionCanceled(
+        IRelationalConnection connection,
+        DateTimeOffset startTime,
+        TimeSpan duration);
+
+    /// <summary>
+    ///     Logs for the <see cref="RelationalEventId.ConnectionCanceled" /> event.
+    /// </summary>
+    /// <param name="connection">The connection.</param>
+    /// <param name="startTime">The time that the operation was started.</param>
+    /// <param name="duration">The amount of time that passed until the command was canceled.</param>
+    /// <param name="cancellationToken">A <see cref="CancellationToken" /> to observe while waiting for the task to complete.</param>
+    /// <returns>A <see cref="Task" /> representing the async operation.</returns>
+    /// <exception cref="OperationCanceledException">If the <see cref="CancellationToken" /> is canceled.</exception>
+    Task ConnectionCanceledAsync(
+        IRelationalConnection connection,
+        DateTimeOffset startTime,
+        TimeSpan duration,
+        CancellationToken cancellationToken = default);
+
     /// <summary>
     ///     Whether <see cref="RelationalEventId.ConnectionCreating" /> or <see cref="RelationalEventId.ConnectionCreated" /> need
     ///     to be logged.

src/EFCore.Relational/Diagnostics/Internal/RelationalConnectionDiagnosticsLogger.cs

@@ -892,6 +892,121 @@ private void LogConnectionError(
 
     #endregion ConnectionError
 
+    #region ConnectionCanceled
+
+    /// <summary>
+    ///     This is an internal API that supports the Entity Framework Core infrastructure and not subject to
+    ///     the same compatibility standards as public APIs. It may be changed or removed without notice in
+    ///     any release. You should only use it directly in your code with extreme caution and knowing that
+    ///     doing so can result in application failures when updating to a new Entity Framework Core release.
+    /// </summary>
+    public virtual void ConnectionCanceled(
+        IRelationalConnection connection,
+        DateTimeOffset startTime,
+        TimeSpan duration)
+    {
+        var definition = RelationalResources.LogConnectionCanceled(this);
+
+        LogConnectionCanceled(connection, definition);
+
+        if (NeedsEventData<IDbConnectionInterceptor>(
+                definition, out var interceptor, out var diagnosticSourceEnabled, out var simpleLogEnabled))
+        {
+            var eventData = BroadcastConnectionCanceled(
+                connection,
+                startTime,
+                duration,
+                async: false,
+                definition,
+                diagnosticSourceEnabled,
+                simpleLogEnabled);
+
+            interceptor?.ConnectionCanceled(connection.DbConnection, eventData);
+        }
+    }
+
+    /// <summary>
+    ///     This is an internal API that supports the Entity Framework Core infrastructure and not subject to
+    ///     the same compatibility standards as public APIs. It may be changed or removed without notice in
+    ///     any release. You should only use it directly in your code with extreme caution and knowing that
+    ///     doing so can result in application failures when updating to a new Entity Framework Core release.
+    /// </summary>
+    public virtual Task ConnectionCanceledAsync(
+        IRelationalConnection connection,
+        DateTimeOffset startTime,
+        TimeSpan duration,
+        CancellationToken cancellationToken = default)
+    {
+        var definition = RelationalResources.LogConnectionCanceled(this);
+
+        LogConnectionCanceled(connection, definition);
+
+        if (NeedsEventData<IDbConnectionInterceptor>(
+                definition, out var interceptor, out var diagnosticSourceEnabled, out var simpleLogEnabled))
+        {
+            var eventData = BroadcastConnectionCanceled(
+                connection,
+                startTime,
+                duration,
+                async: true,
+                definition,
+                diagnosticSourceEnabled,
+                simpleLogEnabled);
+
+            interceptor?.ConnectionCanceled(connection.DbConnection, eventData);
+        }
+
+        return Task.CompletedTask;
+    }
+
+    private ConnectionEndEventData BroadcastConnectionCanceled(
+        IRelationalConnection connection,
+        DateTimeOffset startTime,
+        TimeSpan duration,
+        bool async,
+        EventDefinition<string, string> definition,
+        bool diagnosticSourceEnabled,
+        bool simpleLogEnabled)
+    {
+        var eventData = new ConnectionEndEventData(
+            definition,
+            ConnectionCanceled,
+            connection.DbConnection,
+            connection.Context,
+            connection.ConnectionId,
+            async,
+            startTime,
+            duration);
+
+        DispatchEventData(definition, eventData, diagnosticSourceEnabled, simpleLogEnabled);
+
+        return eventData;
+
+        static string ConnectionCanceled(EventDefinitionBase definition, EventData payload)
+        {
+            var d = (EventDefinition<string, string>)definition;
+            var p = (ConnectionEndEventData)payload;
+            return d.GenerateMessage(
+                p.Connection.Database,
+                p.Connection.DataSource);
+        }
+    }
+
+    private void LogConnectionCanceled(
+        IRelationalConnection connection,
+        EventDefinition<string, string> definition)
+    {
+        if (ShouldLog(definition))
+        {
+            definition.Log(
+                this,
+                connection.DbConnection.Database,
+                connection.DbConnection.DataSource);
+        }
+    }
+
+    #endregion ConnectionCanceled
+
     #region ConnectionCreating
 
     /// <summary>

src/EFCore.Relational/Diagnostics/RelationalEventId.cs

@@ -33,6 +33,7 @@ private enum Id
         ConnectionCreated,
         ConnectionDisposing,
         ConnectionDisposed,
+        ConnectionCanceled,
 
         // Command events
         CommandExecuting = CoreEventId.RelationalBaseId + 100,
@@ -217,6 +218,19 @@ private static EventId MakeConnectionId(Id id)
     /// </remarks>
     public static readonly EventId ConnectionError = MakeConnectionId(Id.ConnectionError);
 
+    /// <summary>
+    ///     A <see cref="DbConnection" /> open operation has been canceled.
+    /// </summary>
+    /// <remarks>
+    ///     <para>
+    ///         This event is in the <see cref="DbLoggerCategory.Database.Connection" /> category.
+    ///     </para>
+    ///     <para>
+    ///         This event uses the <see cref="ConnectionEndEventData" /> payload when used with a <see cref="DiagnosticSource" />.
+    ///     </para>
+    /// </remarks>
+    public static readonly EventId ConnectionCanceled = MakeConnectionId(Id.ConnectionCanceled);
+
     /// <summary>
     ///     A <see cref="DbConnection" /> is about to be created by EF.
     /// </summary>

src/EFCore.Relational/Diagnostics/RelationalLoggingDefinitions.cs

@@ -133,6 +133,15 @@ public abstract class RelationalLoggingDefinitions : LoggingDefinitions
     [EntityFrameworkInternal]
     public EventDefinitionBase? LogConnectionError;
 
+    /// <summary>
+    ///     This is an internal API that supports the Entity Framework Core infrastructure and not subject to
+    ///     the same compatibility standards as public APIs. It may be changed or removed without notice in
+    ///     any release. You should only use it directly in your code with extreme caution and knowing that
+    ///     doing so can result in application failures when updating to a new Entity Framework Core release.
+    /// </summary>
+    [EntityFrameworkInternal]
+    public EventDefinitionBase? LogConnectionCanceled;
+
     /// <summary>
     ///     This is an internal API that supports the Entity Framework Core infrastructure and not subject to
     ///     the same compatibility standards as public APIs. It may be changed or removed without notice in

src/EFCore.Relational/Properties/RelationalStrings.Designer.cs

@@ -716,6 +716,10 @@
     <value>An error occurred using the connection to database '{database}' on server '{server}'.</value>
     <comment>Debug RelationalEventId.ConnectionError string string</comment>
   </data>
+  <data name="LogConnectionCanceled" xml:space="preserve">
+    <value>A connection open was canceled to database '{database}' on server '{server}'.</value>
+    <comment>Debug RelationalEventId.ConnectionCanceled string string string</comment>
+  </data>
   <data name="LogCreatedTransactionSavepoint" xml:space="preserve">
     <value>Created transaction savepoint.</value>
     <comment>Debug RelationalEventId.CreatedTransactionSavepoint</comment>

src/EFCore.Relational/Properties/RelationalStrings.resx

@@ -42,6 +42,7 @@ public abstract class RelationalConnection : IRelationalConnection, ITransaction
     private readonly ConcurrentStack<Transaction> _ambientTransactions = new();
     private DbConnection? _connection;
     private readonly IRelationalCommandBuilder _relationalCommandBuilder;
+    private readonly IExceptionDetector _exceptionDetector;
     private IRelationalCommand? _cachedRelationalCommand;
 
     /// <summary>
@@ -74,6 +75,8 @@ protected RelationalConnection(RelationalConnectionDependencies dependencies)
         {
             _connectionOwned = true;
         }
+
+        _exceptionDetector = dependencies.ExceptionDetector;
     }
 
     /// <summary>
@@ -726,7 +729,14 @@ private void OpenInternal(bool errorsExpected)
         }
         catch (Exception e)
         {
-            logger.ConnectionError(this, e, startTime, stopwatch.Elapsed, errorsExpected);
+            if (_exceptionDetector.IsCancellation(e, CancellationToken.None))
+            {
+                logger.ConnectionCanceled(this, startTime, stopwatch.Elapsed);
+            }
+            else
+            {
+                logger.ConnectionError(this, e, startTime, stopwatch.Elapsed, errorsExpected);
+            }
 
             throw;
         }
@@ -773,14 +783,16 @@ await logger.ConnectionOpenedAsync(this, startTime, stopwatch.Elapsed, cancellat
         }
         catch (Exception e)
         {
-            await logger.ConnectionErrorAsync(
-                    this,
-                    e,
-                    startTime,
-                    stopwatch.Elapsed,
-                    errorsExpected,
-                    cancellationToken)
-                .ConfigureAwait(false);
+            if (_exceptionDetector.IsCancellation(e, CancellationToken.None))
+            {
+                await logger.ConnectionCanceledAsync(this, startTime, stopwatch.Elapsed, cancellationToken)
+                    .ConfigureAwait(false);
+            }
+            else
+            {
+                await logger.ConnectionErrorAsync(this, e, startTime, stopwatch.Elapsed, errorsExpected, cancellationToken)
+                    .ConfigureAwait(false);
+            }
 
             throw;
         }