Add CommandInitialized interceptor (#27884)

src/EFCore.Relational/Diagnostics/CommandSource.cs

@@ -13,47 +13,53 @@ namespace Microsoft.EntityFrameworkCore.Diagnostics;
 public enum CommandSource
 {
     /// <summary>
-    ///     Unknown
+    ///     The command was generated from an unknown source. This usually indicates a database provider-generated command.
     /// </summary>
     Unknown,
 
     /// <summary>
-    ///     Linq Query
+    ///     The command was generated from a LINQ query on a <see cref="DbSet{TEntity}"/>.
     /// </summary>
     LinqQuery,
 
     /// <summary>
-    ///     Save Changes
+    ///     The command was generated from a call to <see cref="DbContext.SaveChanges()"/> or
+    ///     <see cref="DbContext.SaveChangesAsync(System.Threading.CancellationToken)"/>
     /// </summary>
     SaveChanges,
 
     /// <summary>
-    ///     Migrations
+    ///     The command was generated by EF Core Migrations.
     /// </summary>
     Migrations,
 
     /// <summary>
-    ///     FromSqlQuery
+    ///     The command was generated from a call to <see cref="RelationalQueryableExtensions.FromSqlRaw{TEntity}"/> or
+    ///     <see cref="RelationalQueryableExtensions.FromSqlInterpolated{TEntity}"/> 
     /// </summary>
     FromSqlQuery,
 
     /// <summary>
-    ///     ExecuteSqlRaw
+    ///     The command was generated from a call to
+    ///     <see cref="RelationalDatabaseFacadeExtensions.ExecuteSqlRaw(DatabaseFacade,string,object[])"/>,
+    ///     <see cref="RelationalDatabaseFacadeExtensions.ExecuteSqlRawAsync(DatabaseFacade,string,System.Threading.CancellationToken)"/>,
+    ///     <see cref="RelationalDatabaseFacadeExtensions.ExecuteSqlInterpolated"/>,
+    ///     or <see cref="RelationalDatabaseFacadeExtensions.ExecuteSqlInterpolatedAsync"/>.
     /// </summary>
     ExecuteSqlRaw,
 
     /// <summary>
-    ///     ValueGenerator
+    ///     The command was generated by a <see cref="ValueGenerator"/>.
     /// </summary>
     ValueGenerator,
 
     /// <summary>
-    ///     Scaffolding
+    ///     The command was generated as part of scaffolding (reverse-engineering) from an existing database.
     /// </summary>
     Scaffolding,
 
     /// <summary>
-    ///     BulkUpdate
+    ///     The command was generated as part of a bulk update.
     /// </summary>
     BulkUpdate
 }

src/EFCore.Relational/Diagnostics/IDbCommandInterceptor.cs

@@ -69,6 +69,21 @@ InterceptionResult<DbCommand> CommandCreating(CommandCorrelatedEventData eventDa
     DbCommand CommandCreated(CommandEndEventData eventData, DbCommand result)
         => result;
 
+    /// <summary>
+    ///     Called after EF has initialized <see cref="DbCommand.CommandText"/> and other command configuration.
+    /// </summary>
+    /// <param name="eventData">Contextual information about the command and execution.</param>
+    /// <param name="result">
+    ///     The command. This value is typically used as the return value for the implementation of this method.
+    /// </param>
+    /// <returns>
+    ///     The result that EF will use.
+    ///     A normal implementation of this method for any interceptor that is not attempting to change the result
+    ///     is to return the <paramref name="result" /> value passed in.
+    /// </returns>
+    DbCommand CommandInitialized(CommandEndEventData eventData, DbCommand result)
+        => result;
+
     /// <summary>
     ///     Called just before EF intends to call <see cref="DbCommand.ExecuteReader()" />.
     /// </summary>

src/EFCore.Relational/Diagnostics/IRelationalCommandDiagnosticsLogger.cs

@@ -64,6 +64,30 @@ DbCommand CommandCreated(
         TimeSpan duration,
         CommandSource commandSource);
 
+    /// <summary>
+    ///     Logs for the <see cref="RelationalEventId.CommandInitialized" /> event.
+    /// </summary>
+    /// <param name="connection">The connection.</param>
+    /// <param name="command">The database command object.</param>
+    /// <param name="commandMethod">The type of method that will be called on this command.</param>
+    /// <param name="context">The <see cref="DbContext" /> currently being used, to null if not known.</param>
+    /// <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 duration of the command creation.</param>
+    /// <param name="commandSource">Source of the command.</param>
+    /// <returns>An intercepted result.</returns>
+    DbCommand CommandInitialized(
+        IRelationalConnection connection,
+        DbCommand command,
+        DbCommandMethod commandMethod,
+        DbContext? context,
+        Guid commandId,
+        Guid connectionId,
+        DateTimeOffset startTime,
+        TimeSpan duration,
+        CommandSource commandSource);
+
     /// <summary>
     ///     Logs for the <see cref="RelationalEventId.CommandExecuting" /> event.
     /// </summary>

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

@@ -53,6 +53,18 @@ public DbCommand CommandCreated(
             return result;
         }
 
+        public DbCommand CommandInitialized(
+            CommandEndEventData eventData,
+            DbCommand result)
+        {
+            for (var i = 0; i < _interceptors.Length; i++)
+            {
+                result = _interceptors[i].CommandInitialized(eventData, result);
+            }
+
+            return result;
+        }
+
         public InterceptionResult<DbDataReader> ReaderExecuting(
             DbCommand command,
             CommandEventData eventData,

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

@@ -242,6 +242,107 @@ static string CommandCreated(EventDefinitionBase definition, EventData payload)
 
     #endregion CommandCreated
 
+    #region CommandInitialized
+
+    /// <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 DbCommand CommandInitialized(
+        IRelationalConnection connection,
+        DbCommand command,
+        DbCommandMethod commandMethod,
+        DbContext? context,
+        Guid commandId,
+        Guid connectionId,
+        DateTimeOffset startTime,
+        TimeSpan duration,
+        CommandSource commandSource)
+    {
+        var definition = RelationalResources.LogCommandInitialized(this);
+
+        if (ShouldLog(definition))
+        {
+            _suppressCommandCreateExpiration = default;
+
+            definition.Log(this, commandMethod.ToString(), (int)duration.TotalMilliseconds);
+        }
+
+        if (NeedsEventData<IDbCommandInterceptor>(
+                definition, out var interceptor, out var diagnosticSourceEnabled, out var simpleLogEnabled))
+        {
+            _suppressCommandCreateExpiration = default;
+
+            var eventData = BroadcastCommandInitialized(
+                connection.DbConnection,
+                command,
+                context,
+                commandMethod,
+                commandId,
+                connectionId,
+                async: false,
+                startTime,
+                duration,
+                definition,
+                diagnosticSourceEnabled,
+                simpleLogEnabled,
+                commandSource);
+
+            if (interceptor != null)
+            {
+                return interceptor.CommandInitialized(eventData, command);
+            }
+        }
+
+        return command;
+    }
+
+    private CommandEndEventData BroadcastCommandInitialized(
+        DbConnection connection,
+        DbCommand command,
+        DbContext? context,
+        DbCommandMethod executeMethod,
+        Guid commandId,
+        Guid connectionId,
+        bool async,
+        DateTimeOffset startTime,
+        TimeSpan duration,
+        EventDefinition<string, int> definition,
+        bool diagnosticSourceEnabled,
+        bool simpleLogEnabled,
+        CommandSource commandSource)
+    {
+        var eventData = new CommandEndEventData(
+            definition,
+            CommandInitialized,
+            connection,
+            command,
+            context,
+            executeMethod,
+            commandId,
+            connectionId,
+            async,
+            false,
+            startTime,
+            duration,
+            commandSource);
+
+        DispatchEventData(definition, eventData, diagnosticSourceEnabled, simpleLogEnabled);
+
+        return eventData;
+
+        static string CommandInitialized(EventDefinitionBase definition, EventData payload)
+        {
+            var d = (EventDefinition<string, int>)definition;
+            var p = (CommandEndEventData)payload;
+            return d.GenerateMessage(p.ExecuteMethod.ToString(), (int)p.Duration.TotalMilliseconds);
+        }
+    }
+
+    #endregion CommandInitialized
+
     #region CommandExecuting
 
     /// <summary>

src/EFCore.Relational/Diagnostics/RelationalEventId.cs

@@ -37,6 +37,7 @@ private enum Id
         CommandCreating,
         CommandCreated,
         CommandCanceled,
+        CommandInitialized,
 
         // Transaction events
         TransactionStarted = CoreEventId.RelationalBaseId + 200,
@@ -214,6 +215,19 @@ private static EventId MakeCommandId(Id id)
     /// </remarks>
     public static readonly EventId CommandCreated = MakeCommandId(Id.CommandCreated);
 
+    /// <summary>
+    ///     A <see cref="DbCommand" /> has been initialized with command text and other parameters.
+    /// </summary>
+    /// <remarks>
+    ///     <para>
+    ///         This event is in the <see cref="DbLoggerCategory.Database.Command" /> category.
+    ///     </para>
+    ///     <para>
+    ///         This event uses the <see cref="CommandEndEventData" /> payload when used with a <see cref="DiagnosticSource" />.
+    ///     </para>
+    /// </remarks>
+    public static readonly EventId CommandInitialized = MakeCommandId(Id.CommandInitialized);
+
     /// <summary>
     ///     A database command is executing.
     /// </summary>

src/EFCore.Relational/Diagnostics/RelationalLoggingDefinitions.cs

@@ -340,6 +340,15 @@ public abstract class RelationalLoggingDefinitions : LoggingDefinitions
     [EntityFrameworkInternal]
     public EventDefinitionBase? LogCommandCreated;
 
+    /// <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? LogCommandInitialized;
+
     /// <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.resx

@@ -495,6 +495,10 @@
     <value>Failed executing DbCommand ({elapsed}ms) [Parameters=[{parameters}], CommandType='{commandType}', CommandTimeout='{commandTimeout}']{newLine}{commandText}</value>
     <comment>Error RelationalEventId.CommandError string string System.Data.CommandType int string string</comment>
   </data>
+  <data name="LogCommandInitialized" xml:space="preserve">
+    <value>Initialized DbCommand for '{executionType}' ({elapsed}ms).</value>
+    <comment>Debug RelationalEventId.CommandInitialized string int</comment>
+  </data>
   <data name="LogCommittedTransaction" xml:space="preserve">
     <value>Committed transaction.</value>
     <comment>Debug RelationalEventId.TransactionCommitted</comment>

src/EFCore.Relational/Storage/RelationalCommand.cs

@@ -776,11 +776,12 @@ public virtual DbCommand CreateDbCommand(
 
         DbCommand command;
 
-        if (logger?.ShouldLogCommandCreate(startTime) == true)
+        var logCommandCreate = logger?.ShouldLogCommandCreate(startTime) == true;
+        if (logCommandCreate)
         {
             _stopwatch.Restart();
 
-            var interceptionResult = logger.CommandCreating(
+            var interceptionResult = logger!.CommandCreating(
                 connection, commandMethod, context, commandId, connectionId, startTime,
                 parameterObject.CommandSource);
 
@@ -832,6 +833,20 @@ public virtual DbCommand CreateDbCommand(
             }
         }
 
+        if (logCommandCreate)
+        {
+            command = logger!.CommandInitialized(
+                connection,
+                command,
+                commandMethod,
+                context,
+                commandId,
+                connectionId,
+                startTime,
+                _stopwatch.Elapsed,
+                parameterObject.CommandSource);
+        }
+
         return command;
     }