From c2f69ab26675c4cc50814be27bfb2e678e7fe0b6 Mon Sep 17 00:00:00 2001 From: Arthur Vickers Date: Tue, 21 Jun 2022 21:20:12 +0100 Subject: [PATCH] Add interception for DbDataReader.Close Part of #626 Fixes #23535 Also added tests to: - Show that this can be used to get statistics from a query, as requested in #23535. - Show that Close and/or Dispose can be suppressed, as requested in #24295. --- .../Diagnostics/DataReaderClosingEventData.cs | 50 +++++ .../DataReaderDisposingEventData.cs | 57 +----- .../Diagnostics/DataReaderEventData.cs | 83 ++++++++ .../Diagnostics/IDbCommandInterceptor.cs | 42 ++++ .../IRelationalCommandDiagnosticsLogger.cs | 48 ++++- .../DbCommandInterceptorAggregator.cs | 24 +++ .../RelationalCommandDiagnosticsLogger.cs | 148 +++++++++++++- .../Diagnostics/RelationalEventId.cs | 14 ++ .../RelationalLoggingDefinitions.cs | 9 + .../Properties/RelationalStrings.Designer.cs | 35 +++- .../Properties/RelationalStrings.resx | 10 +- .../Storage/RelationalDataReader.cs | 46 ++++- .../CommandInterceptionTestBase.cs | 192 +++++++++++++++++- .../RelationalEventIdTest.cs | 2 +- .../Storage/RelationalCommandTest.cs | 22 +- .../FakeRelationalCommandDiagnosticsLogger.cs | 23 +++ .../CommandInterceptionSqlServerTest.cs | 109 ++++++++++ .../Query/BadDataSqliteTest.cs | 3 +- 18 files changed, 837 insertions(+), 80 deletions(-) create mode 100644 src/EFCore.Relational/Diagnostics/DataReaderClosingEventData.cs create mode 100644 src/EFCore.Relational/Diagnostics/DataReaderEventData.cs diff --git a/src/EFCore.Relational/Diagnostics/DataReaderClosingEventData.cs b/src/EFCore.Relational/Diagnostics/DataReaderClosingEventData.cs new file mode 100644 index 00000000000..fee023e23bf --- /dev/null +++ b/src/EFCore.Relational/Diagnostics/DataReaderClosingEventData.cs @@ -0,0 +1,50 @@ +// Licensed to the .NET Foundation under one or more agreements. +// The .NET Foundation licenses this file to you under the MIT license. + +namespace Microsoft.EntityFrameworkCore.Diagnostics; + +/// +/// event payload for . +/// +/// +/// See Logging, events, and diagnostics for more information and examples. +/// +public class DataReaderClosingEventData : DataReaderEventData +{ + /// + /// Constructs a event payload for . + /// + /// The event definition. + /// A delegate that generates a log message for this event. + /// The that created the reader. + /// The that is being disposed. + /// The currently being used, to null if not known. + /// A correlation ID that identifies the instance being used. + /// A correlation ID that identifies the instance being used. + /// Indicates whether or not the command was executed asynchronously. + /// Gets the number of rows changed, inserted, or deleted by execution of the SQL statement. + /// Gets the number of read operations performed by this reader. + /// The time when the data reader was created. + public DataReaderClosingEventData( + EventDefinitionBase eventDefinition, + Func messageGenerator, + DbCommand command, + DbDataReader dataReader, + DbContext? context, + Guid commandId, + Guid connectionId, + bool async, + int recordsAffected, + int readCount, + DateTimeOffset startTime) + : base( + eventDefinition, messageGenerator, command, dataReader, context, commandId, connectionId, recordsAffected, readCount, startTime) + { + IsAsync = async; + } + + /// + /// Indicates whether or not the operation is being executed asynchronously. + /// + public virtual bool IsAsync { get; } +} diff --git a/src/EFCore.Relational/Diagnostics/DataReaderDisposingEventData.cs b/src/EFCore.Relational/Diagnostics/DataReaderDisposingEventData.cs index e46d6da77bf..c61a67c3f95 100644 --- a/src/EFCore.Relational/Diagnostics/DataReaderDisposingEventData.cs +++ b/src/EFCore.Relational/Diagnostics/DataReaderDisposingEventData.cs @@ -9,7 +9,7 @@ namespace Microsoft.EntityFrameworkCore.Diagnostics; /// /// See Logging, events, and diagnostics for more information and examples. /// -public class DataReaderDisposingEventData : DbContextEventData +public class DataReaderDisposingEventData : DataReaderEventData { /// /// Constructs a event payload for . @@ -23,8 +23,11 @@ public class DataReaderDisposingEventData : DbContextEventData /// A correlation ID that identifies the instance being used. /// Gets the number of rows changed, inserted, or deleted by execution of the SQL statement. /// Gets the number of read operations performed by this reader. - /// The start time of this event. - /// The duration this event. + /// The time when the data reader was created. + /// + /// The duration from the time the data reader is created until it is disposed. This corresponds to the time reading + /// for reading results of a query. + /// public DataReaderDisposingEventData( EventDefinitionBase eventDefinition, Func messageGenerator, @@ -37,55 +40,15 @@ public DataReaderDisposingEventData( int readCount, DateTimeOffset startTime, TimeSpan duration) - : base(eventDefinition, messageGenerator, context) + : base( + eventDefinition, messageGenerator, command, dataReader, context, commandId, connectionId, recordsAffected, readCount, startTime) { - Command = command; - DataReader = dataReader; - CommandId = commandId; - ConnectionId = connectionId; - RecordsAffected = recordsAffected; - ReadCount = readCount; - StartTime = startTime; Duration = duration; } /// - /// The that created the reader. - /// - public virtual DbCommand Command { get; } - - /// - /// The that is being disposed. - /// - public virtual DbDataReader DataReader { get; } - - /// - /// A correlation ID that identifies the instance being used. - /// - public virtual Guid CommandId { get; } - - /// - /// A correlation ID that identifies the instance being used. - /// - public virtual Guid ConnectionId { get; } - - /// - /// Gets the number of rows changed, inserted, or deleted by execution of the SQL statement. - /// - public virtual int RecordsAffected { get; } - - /// - /// Gets the number of read operations performed by this reader. - /// - public virtual int ReadCount { get; } - - /// - /// The start time of this event. - /// - public virtual DateTimeOffset StartTime { get; } - - /// - /// The duration this event. + /// The duration from the time the data reader is created until it is disposed. This corresponds to the time reading + /// for reading results of a query. /// public virtual TimeSpan Duration { get; } } diff --git a/src/EFCore.Relational/Diagnostics/DataReaderEventData.cs b/src/EFCore.Relational/Diagnostics/DataReaderEventData.cs new file mode 100644 index 00000000000..3f328491000 --- /dev/null +++ b/src/EFCore.Relational/Diagnostics/DataReaderEventData.cs @@ -0,0 +1,83 @@ +// Licensed to the .NET Foundation under one or more agreements. +// The .NET Foundation licenses this file to you under the MIT license. + +namespace Microsoft.EntityFrameworkCore.Diagnostics; + +/// +/// event payload for . +/// +/// +/// See Logging, events, and diagnostics for more information and examples. +/// +public class DataReaderEventData : DbContextEventData +{ + /// + /// Constructs a event payload for . + /// + /// The event definition. + /// A delegate that generates a log message for this event. + /// The that created the reader. + /// The that is being disposed. + /// The currently being used, to null if not known. + /// A correlation ID that identifies the instance being used. + /// A correlation ID that identifies the instance being used. + /// Gets the number of rows changed, inserted, or deleted by execution of the SQL statement. + /// Gets the number of read operations performed by this reader. + /// The start time of this event. + public DataReaderEventData( + EventDefinitionBase eventDefinition, + Func messageGenerator, + DbCommand command, + DbDataReader dataReader, + DbContext? context, + Guid commandId, + Guid connectionId, + int recordsAffected, + int readCount, + DateTimeOffset startTime) + : base(eventDefinition, messageGenerator, context) + { + Command = command; + DataReader = dataReader; + CommandId = commandId; + ConnectionId = connectionId; + RecordsAffected = recordsAffected; + ReadCount = readCount; + StartTime = startTime; + } + + /// + /// The that created the reader. + /// + public virtual DbCommand Command { get; } + + /// + /// The that is being disposed. + /// + public virtual DbDataReader DataReader { get; } + + /// + /// A correlation ID that identifies the instance being used. + /// + public virtual Guid CommandId { get; } + + /// + /// A correlation ID that identifies the instance being used. + /// + public virtual Guid ConnectionId { get; } + + /// + /// Gets the number of rows changed, inserted, or deleted by execution of the SQL statement. + /// + public virtual int RecordsAffected { get; } + + /// + /// Gets the number of read operations performed by this reader. + /// + public virtual int ReadCount { get; } + + /// + /// The start time of this event. + /// + public virtual DateTimeOffset StartTime { get; } +} diff --git a/src/EFCore.Relational/Diagnostics/IDbCommandInterceptor.cs b/src/EFCore.Relational/Diagnostics/IDbCommandInterceptor.cs index 2d10f232a9e..d71b33eb940 100644 --- a/src/EFCore.Relational/Diagnostics/IDbCommandInterceptor.cs +++ b/src/EFCore.Relational/Diagnostics/IDbCommandInterceptor.cs @@ -412,6 +412,48 @@ void CommandFailed(DbCommand command, CommandErrorEventData eventData) Task CommandFailedAsync(DbCommand command, CommandErrorEventData eventData, CancellationToken cancellationToken = default) => Task.CompletedTask; + /// + /// Called just before EF intends to call . + /// + /// The command. + /// Contextual information about the command. + /// + /// Represents the current result if one exists. + /// This value will have set to if some previous + /// interceptor suppressed execution by calling . + /// This value is typically used as the return value for the implementation of this method. + /// + /// + /// If is , then EF will continue as normal. + /// If is , then EF will suppress the operation + /// it was about to perform. + /// An implementation of this method for any interceptor that is not attempting to suppress + /// the operation is to return the value passed in. + /// + InterceptionResult DataReaderClosing(DbCommand command, DataReaderClosingEventData eventData, InterceptionResult result) + => result; + + /// + /// Called just before EF intends to call in an async context. + /// + /// The command. + /// Contextual information about the command. + /// + /// Represents the current result if one exists. + /// This value will have set to if some previous + /// interceptor suppressed execution by calling . + /// This value is typically used as the return value for the implementation of this method. + /// + /// + /// If is , then EF will continue as normal. + /// If is , then EF will suppress the operation + /// it was about to perform. + /// An implementation of this method for any interceptor that is not attempting to suppress + /// the operation is to return the value passed in. + /// + ValueTask DataReaderClosingAsync(DbCommand command, DataReaderClosingEventData eventData, InterceptionResult result) + => new(result); + /// /// Called when execution of a is about to be disposed. /// diff --git a/src/EFCore.Relational/Diagnostics/IRelationalCommandDiagnosticsLogger.cs b/src/EFCore.Relational/Diagnostics/IRelationalCommandDiagnosticsLogger.cs index 305db4cb744..f30162bce74 100644 --- a/src/EFCore.Relational/Diagnostics/IRelationalCommandDiagnosticsLogger.cs +++ b/src/EFCore.Relational/Diagnostics/IRelationalCommandDiagnosticsLogger.cs @@ -496,6 +496,46 @@ InterceptionResult DataReaderDisposing( DateTimeOffset startTime, TimeSpan duration); + /// + /// Logs for the event. + /// + /// The connection. + /// The database command object. + /// The data reader. + /// The correlation ID associated with the given . + /// The number of records in the database that were affected. + /// The number of records that were read. + /// The time that the operation was started. + /// The result of execution, which may have been modified by an interceptor. + InterceptionResult DataReaderClosing( + IRelationalConnection connection, + DbCommand command, + DbDataReader dataReader, + Guid commandId, + int recordsAffected, + int readCount, + DateTimeOffset startTime); + + /// + /// Logs for the event. + /// + /// The connection. + /// The database command object. + /// The data reader. + /// The correlation ID associated with the given . + /// The number of records in the database that were affected. + /// The number of records that were read. + /// The time that the operation was started. + /// The result of execution, which may have been modified by an interceptor. + ValueTask DataReaderClosingAsync( + IRelationalConnection connection, + DbCommand command, + DbDataReader dataReader, + Guid commandId, + int recordsAffected, + int readCount, + DateTimeOffset startTime); + /// /// Whether or need /// to be logged. @@ -508,11 +548,13 @@ InterceptionResult DataReaderDisposing( /// bool ShouldLogCommandExecute(DateTimeOffset now); + /// + /// Whether needs to be logged. + /// + bool ShouldLogDataReaderClose(DateTimeOffset now); + /// /// Whether needs to be logged. /// bool ShouldLogDataReaderDispose(DateTimeOffset now); - - private bool ShouldLogParameterValues(DbCommand command) - => command.Parameters.Count > 0 && ShouldLogSensitiveData(); } diff --git a/src/EFCore.Relational/Diagnostics/Internal/DbCommandInterceptorAggregator.cs b/src/EFCore.Relational/Diagnostics/Internal/DbCommandInterceptorAggregator.cs index bb74a7cd62a..fd5e8fc1cc8 100644 --- a/src/EFCore.Relational/Diagnostics/Internal/DbCommandInterceptorAggregator.cs +++ b/src/EFCore.Relational/Diagnostics/Internal/DbCommandInterceptorAggregator.cs @@ -273,6 +273,30 @@ await _interceptors[i].CommandFailedAsync(command, eventData, cancellationToken) } } + public InterceptionResult DataReaderClosing(DbCommand command, DataReaderClosingEventData eventData, InterceptionResult result) + { + for (var i = 0; i < _interceptors.Length; i++) + { + result = _interceptors[i].DataReaderClosing(command, eventData, result); + } + + return result; + } + + public async ValueTask DataReaderClosingAsync( + DbCommand command, + DataReaderClosingEventData eventData, + InterceptionResult result) + { + for (var i = 0; i < _interceptors.Length; i++) + { + result = await _interceptors[i].DataReaderClosingAsync(command, eventData, result) + .ConfigureAwait(false); + } + + return result; + } + public InterceptionResult DataReaderDisposing( DbCommand command, DataReaderDisposingEventData eventData, diff --git a/src/EFCore.Relational/Diagnostics/Internal/RelationalCommandDiagnosticsLogger.cs b/src/EFCore.Relational/Diagnostics/Internal/RelationalCommandDiagnosticsLogger.cs index ac193c8ab61..d77715fbd2b 100644 --- a/src/EFCore.Relational/Diagnostics/Internal/RelationalCommandDiagnosticsLogger.cs +++ b/src/EFCore.Relational/Diagnostics/Internal/RelationalCommandDiagnosticsLogger.cs @@ -20,6 +20,7 @@ public class RelationalCommandDiagnosticsLogger { private DateTimeOffset _suppressCommandCreateExpiration; private DateTimeOffset _suppressCommandExecuteExpiration; + private DateTimeOffset _suppressDataReaderClosingExpiration; private DateTimeOffset _suppressDataReaderDisposingExpiration; private readonly TimeSpan _loggingCacheTime; @@ -1510,7 +1511,127 @@ static string CommandCanceled(EventDefinitionBase definition, EventData payload) #endregion CommandCanceled - #region DataReaderDisposing + #region DataReader + + /// + /// 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. + /// + public virtual InterceptionResult DataReaderClosing( + IRelationalConnection connection, + DbCommand command, + DbDataReader dataReader, + Guid commandId, + int recordsAffected, + int readCount, + DateTimeOffset startTime) + { + _suppressDataReaderClosingExpiration = startTime + _loggingCacheTime; + + var definition = RelationalResources.LogClosingDataReader(this); + + if (ShouldLog(definition)) + { + _suppressDataReaderClosingExpiration = default; + + definition.Log(this, connection.DbConnection.Database, connection.DbConnection.DataSource); + } + + if (NeedsEventData( + definition, out var interceptor, out var diagnosticSourceEnabled, out var simpleLogEnabled)) + { + _suppressDataReaderClosingExpiration = default; + + var eventData = new DataReaderClosingEventData( + definition, + CreateDataReaderClosingString, + command, + dataReader, + connection.Context, + commandId, + connection.ConnectionId, + async: false, + recordsAffected, + readCount, + startTime); + + DispatchEventData(definition, eventData, diagnosticSourceEnabled, simpleLogEnabled); + + if (interceptor != null) + { + return interceptor.DataReaderClosing(command, eventData, default); + } + } + + return default; + } + + /// + /// 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. + /// + public virtual ValueTask DataReaderClosingAsync( + IRelationalConnection connection, + DbCommand command, + DbDataReader dataReader, + Guid commandId, + int recordsAffected, + int readCount, + DateTimeOffset startTime) + { + _suppressDataReaderClosingExpiration = startTime + _loggingCacheTime; + + var definition = RelationalResources.LogClosingDataReader(this); + + if (ShouldLog(definition)) + { + _suppressDataReaderClosingExpiration = default; + + definition.Log(this, connection.DbConnection.Database, connection.DbConnection.DataSource); + } + + if (NeedsEventData( + definition, out var interceptor, out var diagnosticSourceEnabled, out var simpleLogEnabled)) + { + _suppressDataReaderClosingExpiration = default; + + var eventData = new DataReaderClosingEventData( + definition, + CreateDataReaderClosingString, + command, + dataReader, + connection.Context, + commandId, + connection.ConnectionId, + async: true, + recordsAffected, + readCount, + startTime); + + DispatchEventData(definition, eventData, diagnosticSourceEnabled, simpleLogEnabled); + + if (interceptor != null) + { + return interceptor.DataReaderClosingAsync(command, eventData, default); + } + } + + return default; + } + + + private static string CreateDataReaderClosingString(EventDefinitionBase definition, EventData payload) + { + var d = (EventDefinition)definition; + var p = (DataReaderClosingEventData)payload; + return d.GenerateMessage( + p.Command.Connection?.Database ?? "", + p.Command.Connection?.DataSource ?? ""); + } /// /// This is an internal API that supports the Entity Framework Core infrastructure and not subject to @@ -1536,7 +1657,7 @@ public virtual InterceptionResult DataReaderDisposing( { _suppressDataReaderDisposingExpiration = default; - definition.Log(this); + definition.Log(this, connection.DbConnection.Database, connection.DbConnection.DataSource, (int)duration.TotalMilliseconds); } if (NeedsEventData( @@ -1546,7 +1667,7 @@ public virtual InterceptionResult DataReaderDisposing( var eventData = new DataReaderDisposingEventData( definition, - (d, _) => ((EventDefinition)d).GenerateMessage(), + CreateDataReaderDisposingString, command, dataReader, connection.Context, @@ -1568,7 +1689,17 @@ public virtual InterceptionResult DataReaderDisposing( return default; } - #endregion DataReaderDisposing + private static string CreateDataReaderDisposingString(EventDefinitionBase definition, EventData payload) + { + var d = (EventDefinition)definition; + var p = (DataReaderDisposingEventData)payload; + return d.GenerateMessage( + p.Command.Connection?.Database ?? "", + p.Command.Connection?.DataSource ?? "", + (int)p.Duration.TotalMilliseconds); + } + + #endregion DataReader #region ShouldLog checks @@ -1590,6 +1721,15 @@ public virtual bool ShouldLogCommandCreate(DateTimeOffset now) public virtual bool ShouldLogCommandExecute(DateTimeOffset now) => now > _suppressCommandExecuteExpiration; + /// + /// 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. + /// + public virtual bool ShouldLogDataReaderClose(DateTimeOffset now) + => now > _suppressDataReaderClosingExpiration; + /// /// 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 diff --git a/src/EFCore.Relational/Diagnostics/RelationalEventId.cs b/src/EFCore.Relational/Diagnostics/RelationalEventId.cs index 614e687e199..82a7da2fa21 100644 --- a/src/EFCore.Relational/Diagnostics/RelationalEventId.cs +++ b/src/EFCore.Relational/Diagnostics/RelationalEventId.cs @@ -65,6 +65,7 @@ private enum Id // DataReader events DataReaderDisposing = CoreEventId.RelationalBaseId + 300, + DataReaderClosing, // Migrations events MigrateUsingConnection = CoreEventId.RelationalBaseId + 400, @@ -577,6 +578,19 @@ private static EventId MakeTransactionId(Id id) /// public static readonly EventId DataReaderDisposing = MakeCommandId(Id.DataReaderDisposing); + /// + /// A database data reader is about to be closed. + /// + /// + /// + /// This event is in the category. + /// + /// + /// This event uses the payload when used with a . + /// + /// + public static readonly EventId DataReaderClosing = MakeCommandId(Id.DataReaderClosing); + private static readonly string _migrationsPrefix = DbLoggerCategory.Migrations.Name + "."; private static EventId MakeMigrationsId(Id id) diff --git a/src/EFCore.Relational/Diagnostics/RelationalLoggingDefinitions.cs b/src/EFCore.Relational/Diagnostics/RelationalLoggingDefinitions.cs index d77e753cadf..1e116b46339 100644 --- a/src/EFCore.Relational/Diagnostics/RelationalLoggingDefinitions.cs +++ b/src/EFCore.Relational/Diagnostics/RelationalLoggingDefinitions.cs @@ -106,6 +106,15 @@ public abstract class RelationalLoggingDefinitions : LoggingDefinitions [EntityFrameworkInternal] public EventDefinitionBase? LogClosingConnection; + /// + /// 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. + /// + [EntityFrameworkInternal] + public EventDefinitionBase? LogClosingDataReader; + /// /// 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 diff --git a/src/EFCore.Relational/Properties/RelationalStrings.Designer.cs b/src/EFCore.Relational/Properties/RelationalStrings.Designer.cs index 6fefaeab639..78647c4e82b 100644 --- a/src/EFCore.Relational/Properties/RelationalStrings.Designer.cs +++ b/src/EFCore.Relational/Properties/RelationalStrings.Designer.cs @@ -1801,6 +1801,31 @@ public static EventDefinition LogClosingConnection(IDiagnosticsL return (EventDefinition)definition; } + /// + /// Closing data reader to '{database}' on server '{server}'. + /// + public static EventDefinition LogClosingDataReader(IDiagnosticsLogger logger) + { + var definition = ((RelationalLoggingDefinitions)logger.Definitions).LogClosingDataReader; + if (definition == null) + { + definition = NonCapturingLazyInitializer.EnsureInitialized( + ref ((RelationalLoggingDefinitions)logger.Definitions).LogClosingDataReader, + logger, + static logger => new EventDefinition( + logger.Options, + RelationalEventId.DataReaderClosing, + LogLevel.Debug, + "RelationalEventId.DataReaderClosing", + level => LoggerMessage.Define( + level, + RelationalEventId.DataReaderClosing, + _resourceManager.GetString("LogClosingDataReader")!))); + } + + return (EventDefinition)definition; + } + /// /// The order of column '{table}.{column}' was ignored. Column orders are only used when the table is first created. /// @@ -2202,9 +2227,9 @@ public static EventDefinition LogCreatingTransactionSavepoint(IDiagnosticsLogger } /// - /// A data reader was disposed. + /// A data reader for '{database}' on server '{server}' is being disposed after spending {elapsed}ms reading results. /// - public static EventDefinition LogDisposingDataReader(IDiagnosticsLogger logger) + public static EventDefinition LogDisposingDataReader(IDiagnosticsLogger logger) { var definition = ((RelationalLoggingDefinitions)logger.Definitions).LogDisposingDataReader; if (definition == null) @@ -2212,18 +2237,18 @@ public static EventDefinition LogDisposingDataReader(IDiagnosticsLogger logger) definition = NonCapturingLazyInitializer.EnsureInitialized( ref ((RelationalLoggingDefinitions)logger.Definitions).LogDisposingDataReader, logger, - static logger => new EventDefinition( + static logger => new EventDefinition( logger.Options, RelationalEventId.DataReaderDisposing, LogLevel.Debug, "RelationalEventId.DataReaderDisposing", - level => LoggerMessage.Define( + level => LoggerMessage.Define( level, RelationalEventId.DataReaderDisposing, _resourceManager.GetString("LogDisposingDataReader")!))); } - return (EventDefinition)definition; + return (EventDefinition)definition; } /// diff --git a/src/EFCore.Relational/Properties/RelationalStrings.resx b/src/EFCore.Relational/Properties/RelationalStrings.resx index 472df3e9f01..46b8c5d2ccb 100644 --- a/src/EFCore.Relational/Properties/RelationalStrings.resx +++ b/src/EFCore.Relational/Properties/RelationalStrings.resx @@ -508,6 +508,10 @@ Closing connection to database '{database}' on server '{server}'. Debug RelationalEventId.ConnectionClosing string string + + Closing data reader to '{database}' on server '{server}'. + Debug RelationalEventId.DataReaderClosing string string + The order of column '{table}.{column}' was ignored. Column orders are only used when the table is first created. Warning RelationalEventId.ColumnOrderIgnoredWarning string string @@ -573,8 +577,8 @@ Debug RelationalEventId.CreatingTransactionSavepoint - A data reader was disposed. - Debug RelationalEventId.DataReaderDisposing + A data reader for '{database}' on server '{server}' is being disposed after spending {elapsed}ms reading results. + Debug RelationalEventId.DataReaderDisposing string string int Disposing transaction. @@ -949,4 +953,4 @@ 'VisitChildren' must be overridden in the class deriving from 'SqlExpression'. - \ No newline at end of file + diff --git a/src/EFCore.Relational/Storage/RelationalDataReader.cs b/src/EFCore.Relational/Storage/RelationalDataReader.cs index 22f5fd87e0e..c38cc5b491c 100644 --- a/src/EFCore.Relational/Storage/RelationalDataReader.cs +++ b/src/EFCore.Relational/Storage/RelationalDataReader.cs @@ -103,7 +103,28 @@ public virtual void Dispose() var interceptionResult = default(InterceptionResult); try { - _reader.Close(); // can throw + var closeInterceptionResult = default(InterceptionResult); + try + { + if (_logger?.ShouldLogDataReaderClose(DateTimeOffset.UtcNow) == true) + { + closeInterceptionResult = _logger.DataReaderClosing( + _relationalConnection, + _command, + _reader, + _commandId, + _reader.RecordsAffected, + _readCount, + _startTime); // can throw + } + } + finally + { + if (!closeInterceptionResult.IsSuppressed) + { + _reader.Close(); // can throw + } + } if (_logger?.ShouldLogDataReaderDispose(DateTimeOffset.UtcNow) == true) { @@ -143,7 +164,28 @@ public virtual async ValueTask DisposeAsync() var interceptionResult = default(InterceptionResult); try { - await _reader.CloseAsync().ConfigureAwait(false); // can throw + var closeInterceptionResult = default(InterceptionResult); + try + { + if (_logger?.ShouldLogDataReaderClose(DateTimeOffset.UtcNow) == true) + { + closeInterceptionResult = await _logger.DataReaderClosingAsync( + _relationalConnection, + _command, + _reader, + _commandId, + _reader.RecordsAffected, + _readCount, + _startTime).ConfigureAwait(false); // can throw + } + } + finally + { + if (!closeInterceptionResult.IsSuppressed) + { + await _reader.CloseAsync().ConfigureAwait(false); // can throw + } + } if (_logger?.ShouldLogDataReaderDispose(DateTimeOffset.UtcNow) == true) { diff --git a/test/EFCore.Relational.Specification.Tests/CommandInterceptionTestBase.cs b/test/EFCore.Relational.Specification.Tests/CommandInterceptionTestBase.cs index e8e1be5b789..8111507ebaa 100644 --- a/test/EFCore.Relational.Specification.Tests/CommandInterceptionTestBase.cs +++ b/test/EFCore.Relational.Specification.Tests/CommandInterceptionTestBase.cs @@ -37,6 +37,9 @@ public virtual async Task Intercept_query_passively(bool async, bool inj AssertNormalOutcome(context, interceptor, async, CommandSource.LinqQuery); + Assert.True(interceptor.DataReaderClosingCalled); + Assert.True(interceptor.DataReaderDisposingCalled); + AssertExecutedEvents(listener); } @@ -156,6 +159,9 @@ public virtual async Task Intercept_query_to_suppress_execution(bool asy AssertNormalOutcome(context, interceptor, async, CommandSource.LinqQuery); + Assert.True(interceptor.DataReaderClosingCalled); + Assert.True(interceptor.DataReaderDisposingCalled); + AssertExecutedEvents(listener); } @@ -214,6 +220,9 @@ public virtual async Task Intercept_query_to_suppress_command_creation(bool asyn AssertNormalOutcome(context, interceptor, async, CommandSource.LinqQuery); + Assert.True(interceptor.DataReaderClosingCalled); + Assert.True(interceptor.DataReaderDisposingCalled); + AssertExecutedEvents(listener); } } @@ -417,6 +426,9 @@ protected virtual async Task QueryMutationTest(bool async, AssertNormalOutcome(context, interceptor, async, CommandSource.LinqQuery); + Assert.True(interceptor.DataReaderClosingCalled); + Assert.True(interceptor.DataReaderDisposingCalled); + AssertExecutedEvents(listener); } @@ -649,6 +661,9 @@ public virtual async Task Intercept_query_to_replace_execution(bool asyn AssertNormalOutcome(context, interceptor, async, CommandSource.LinqQuery); + Assert.True(interceptor.DataReaderClosingCalled); + Assert.True(interceptor.DataReaderDisposingCalled); + AssertExecutedEvents(listener); } @@ -871,6 +886,9 @@ public virtual async Task Intercept_query_to_replace_result(bool async, AssertNormalOutcome(context, interceptor, async, CommandSource.LinqQuery); + Assert.True(interceptor.DataReaderClosingCalled); + Assert.True(interceptor.DataReaderDisposingCalled); + AssertExecutedEvents(listener); } @@ -1480,6 +1498,124 @@ public virtual async Task Intercept_non_query_with_explicitly_composed_app_inter await TestCompositeNonQueryInterceptors(context, async); } + [ConditionalTheory] + [InlineData(false, false)] + [InlineData(true, false)] + [InlineData(false, true)] + [InlineData(true, true)] + public virtual async Task Intercept_query_to_call_DataReader_NextResult(bool async, bool inject) + { + var (context, interceptor) = CreateContext(inject); + using (context) + { + using var listener = Fixture.SubscribeToDiagnosticListener(context.ContextId); + _ = async + ? await context.Set().ToListAsync() + : context.Set().ToList(); + + AssertNormalOutcome(context, interceptor, async, CommandSource.LinqQuery); + + Assert.True(interceptor.DataReaderClosingCalled); + Assert.True(interceptor.DataReaderDisposingCalled); + + AssertExecutedEvents(listener); + } + + return interceptor.CommandText; + } + + protected class NextResultCommandInterceptor : CommandInterceptorBase + { + public NextResultCommandInterceptor() + : base(DbCommandMethod.ExecuteReader) + { + } + + public override InterceptionResult DataReaderClosing( + DbCommand command, + DataReaderClosingEventData eventData, + InterceptionResult result) + { + eventData.DataReader.NextResult(); + + return base.DataReaderClosing(command, eventData, result); + } + + public override async ValueTask DataReaderClosingAsync( + DbCommand command, + DataReaderClosingEventData eventData, + InterceptionResult result) + { + await eventData.DataReader.NextResultAsync(); + + return await base.DataReaderClosingAsync(command, eventData, result); + } + } + + [ConditionalTheory] + [InlineData(false, false)] + [InlineData(true, false)] + [InlineData(false, true)] + [InlineData(true, true)] + public virtual async Task Intercept_query_to_suppress_close_of_reader(bool async, bool inject) + { + var (context, interceptor) = CreateContext(inject); + using (context) + { + using var listener = Fixture.SubscribeToDiagnosticListener(context.ContextId); + _ = async + ? await context.Set().ToListAsync() + : context.Set().ToList(); + + AssertNormalOutcome(context, interceptor, async, CommandSource.LinqQuery); + + Assert.True(interceptor.DataReaderClosingCalled); + Assert.True(interceptor.DataReaderDisposingCalled); + + AssertExecutedEvents(listener); + } + + return interceptor.CommandText; + } + + protected class SuppressReaderCloseCommandInterceptor : CommandInterceptorBase + { + public SuppressReaderCloseCommandInterceptor() + : base(DbCommandMethod.ExecuteReader) + { + } + + public override InterceptionResult DataReaderDisposing( + DbCommand command, + DataReaderDisposingEventData eventData, + InterceptionResult result) + { + eventData.DataReader.NextResult(); + + return base.DataReaderDisposing(command, eventData, result); + } + + public override InterceptionResult DataReaderClosing( + DbCommand command, + DataReaderClosingEventData eventData, + InterceptionResult result) + { + base.DataReaderClosing(command, eventData, result); + + return InterceptionResult.Suppress(); + } + + public override async ValueTask DataReaderClosingAsync( + DbCommand command, + DataReaderClosingEventData eventData, + InterceptionResult result) + { + await base.DataReaderClosingAsync(command, eventData, result); + + return InterceptionResult.Suppress(); + } + } + private class WrappingDbCommand : DbCommand { private readonly DbCommand _command; @@ -1645,7 +1781,7 @@ public override IEnumerator GetEnumerator() => throw new NotImplementedException(); } - private static void AssertNormalOutcome(DbContext context, CommandInterceptorBase interceptor, bool async, CommandSource commandSource) + protected static void AssertNormalOutcome(DbContext context, CommandInterceptorBase interceptor, bool async, CommandSource commandSource) { Assert.Equal(async, interceptor.AsyncCalled); Assert.NotEqual(async, interceptor.SyncCalled); @@ -1658,7 +1794,7 @@ private static void AssertNormalOutcome(DbContext context, CommandInterceptorBas Assert.Equal(commandSource, interceptor.CommandSource); } - private static void AssertErrorOutcome(DbContext context, CommandInterceptorBase interceptor, bool async, CommandSource commandSource) + protected static void AssertErrorOutcome(DbContext context, CommandInterceptorBase interceptor, bool async, CommandSource commandSource) { Assert.Equal(async, interceptor.AsyncCalled); Assert.NotEqual(async, interceptor.SyncCalled); @@ -1671,7 +1807,7 @@ private static void AssertErrorOutcome(DbContext context, CommandInterceptorBase Assert.Equal(commandSource, interceptor.CommandSource); } - private static void AssertExecutedEvents(ITestDiagnosticListener listener) + protected static void AssertExecutedEvents(ITestDiagnosticListener listener) => listener.AssertEventsInOrder( RelationalEventId.CommandExecuting.Name, RelationalEventId.CommandExecuted.Name); @@ -1705,6 +1841,8 @@ protected CommandInterceptorBase(DbCommandMethod commandMethod) public bool CreatingCalled { get; set; } public bool CreatedCalled { get; set; } public bool InitializedCalled { get; set; } + public bool DataReaderClosingCalled { get; set; } + public bool DataReaderDisposingCalled { get; set; } public virtual InterceptionResult CommandCreating( CommandCorrelatedEventData eventData, @@ -1883,7 +2021,7 @@ public virtual ValueTask NonQueryExecutedAsync( return new ValueTask(result); } - public void CommandFailed( + public virtual void CommandFailed( DbCommand command, CommandErrorEventData eventData) { @@ -1892,7 +2030,7 @@ public void CommandFailed( AssertFailed(command, eventData); } - public Task CommandFailedAsync( + public virtual Task CommandFailedAsync( DbCommand command, CommandErrorEventData eventData, CancellationToken cancellationToken = default) @@ -1904,7 +2042,7 @@ public Task CommandFailedAsync( return Task.CompletedTask; } - public void CommandCanceled( + public virtual void CommandCanceled( DbCommand command, CommandEndEventData eventData) { @@ -1913,7 +2051,7 @@ public void CommandCanceled( AssertCanceled(command, eventData); } - public Task CommandCanceledAsync( + public virtual Task CommandCanceledAsync( DbCommand command, CommandEndEventData eventData, CancellationToken cancellationToken = default) @@ -1925,11 +2063,49 @@ public Task CommandCanceledAsync( return Task.CompletedTask; } - public InterceptionResult DataReaderDisposing( + public virtual InterceptionResult DataReaderClosing( + DbCommand command, + DataReaderClosingEventData eventData, + InterceptionResult result) + { + Assert.False(eventData.IsAsync); + SyncCalled = true; + DataReaderClosingCalled = true; + + Assert.NotNull(eventData.DataReader); + Assert.Same(Context, eventData.Context); + Assert.Equal(CommandText, command.CommandText); + Assert.Equal(CommandId, eventData.CommandId); + Assert.Equal(ConnectionId, eventData.ConnectionId); + + return result; + } + + public virtual ValueTask DataReaderClosingAsync( + DbCommand command, + DataReaderClosingEventData eventData, + InterceptionResult result) + { + Assert.True(eventData.IsAsync); + AsyncCalled = true; + DataReaderClosingCalled = true; + + Assert.NotNull(eventData.DataReader); + Assert.Same(Context, eventData.Context); + Assert.Equal(CommandText, command.CommandText); + Assert.Equal(CommandId, eventData.CommandId); + Assert.Equal(ConnectionId, eventData.ConnectionId); + + return new(result); + } + + public virtual InterceptionResult DataReaderDisposing( DbCommand command, DataReaderDisposingEventData eventData, InterceptionResult result) { + DataReaderDisposingCalled = true; + Assert.NotNull(eventData.DataReader); Assert.Same(Context, eventData.Context); Assert.Equal(CommandText, command.CommandText); diff --git a/test/EFCore.Relational.Tests/RelationalEventIdTest.cs b/test/EFCore.Relational.Tests/RelationalEventIdTest.cs index d513999fcd5..6dd8397a957 100644 --- a/test/EFCore.Relational.Tests/RelationalEventIdTest.cs +++ b/test/EFCore.Relational.Tests/RelationalEventIdTest.cs @@ -303,7 +303,7 @@ public override string CommandText public override CommandType CommandType { get; set; } public override bool DesignTimeVisible { get; set; } public override UpdateRowSource UpdatedRowSource { get; set; } - protected override DbConnection DbConnection { get; set; } + protected override DbConnection DbConnection { get; set; } = new FakeDbConnection(); protected override DbParameterCollection DbParameterCollection => new FakeDbParameterCollection(); diff --git a/test/EFCore.Relational.Tests/Storage/RelationalCommandTest.cs b/test/EFCore.Relational.Tests/Storage/RelationalCommandTest.cs index 72c34fc6515..51d5828c2c4 100644 --- a/test/EFCore.Relational.Tests/Storage/RelationalCommandTest.cs +++ b/test/EFCore.Relational.Tests/Storage/RelationalCommandTest.cs @@ -391,9 +391,14 @@ DbDataReader CreateDbDataReader() diagnosticEvents.Clear(); } - var diagnostic = diagnosticEvents.Single(); - Assert.Equal(RelationalEventId.DataReaderDisposing.Name, diagnostic.Item1); - var dataReaderDisposingEventData = (DataReaderDisposingEventData)diagnostic.Item2; + Assert.Equal(2, diagnosticEvents.Count); + + Assert.Equal(RelationalEventId.DataReaderClosing.Name, diagnosticEvents[0].Item1); + var dataReaderClosingEventData = (DataReaderClosingEventData)diagnosticEvents[0].Item2; + Assert.Equal(3, dataReaderClosingEventData.ReadCount); + + Assert.Equal(RelationalEventId.DataReaderDisposing.Name, diagnosticEvents[1].Item1); + var dataReaderDisposingEventData = (DataReaderDisposingEventData)diagnosticEvents[1].Item2; Assert.Equal(3, dataReaderDisposingEventData.ReadCount); diagnosticEvents.Clear(); @@ -417,9 +422,14 @@ DbDataReader CreateDbDataReader() diagnosticEvents.Clear(); } - diagnostic = diagnosticEvents.Single(); - Assert.Equal(RelationalEventId.DataReaderDisposing.Name, diagnostic.Item1); - dataReaderDisposingEventData = (DataReaderDisposingEventData)diagnostic.Item2; + Assert.Equal(2, diagnosticEvents.Count); + + Assert.Equal(RelationalEventId.DataReaderClosing.Name, diagnosticEvents[0].Item1); + dataReaderClosingEventData = (DataReaderClosingEventData)diagnosticEvents[0].Item2; + Assert.Equal(3, dataReaderClosingEventData.ReadCount); + + Assert.Equal(RelationalEventId.DataReaderDisposing.Name, diagnosticEvents[1].Item1); + dataReaderDisposingEventData = (DataReaderDisposingEventData)diagnosticEvents[1].Item2; Assert.Equal(3, dataReaderDisposingEventData.ReadCount); } diff --git a/test/EFCore.Relational.Tests/TestUtilities/FakeRelationalCommandDiagnosticsLogger.cs b/test/EFCore.Relational.Tests/TestUtilities/FakeRelationalCommandDiagnosticsLogger.cs index ada428a9b3a..ae25c3e5158 100644 --- a/test/EFCore.Relational.Tests/TestUtilities/FakeRelationalCommandDiagnosticsLogger.cs +++ b/test/EFCore.Relational.Tests/TestUtilities/FakeRelationalCommandDiagnosticsLogger.cs @@ -273,12 +273,35 @@ public InterceptionResult DataReaderDisposing( TimeSpan duration) => default; + public InterceptionResult DataReaderClosing( + IRelationalConnection connection, + DbCommand command, + DbDataReader dataReader, + Guid commandId, + int recordsAffected, + int readCount, + DateTimeOffset startTime) + => default; + + public ValueTask DataReaderClosingAsync( + IRelationalConnection connection, + DbCommand command, + DbDataReader dataReader, + Guid commandId, + int recordsAffected, + int readCount, + DateTimeOffset startTime) + => default; + public bool ShouldLogCommandCreate(DateTimeOffset now) => true; public bool ShouldLogCommandExecute(DateTimeOffset now) => true; + public bool ShouldLogDataReaderClose(DateTimeOffset now) + => true; + public bool ShouldLogDataReaderDispose(DateTimeOffset now) => true; } diff --git a/test/EFCore.SqlServer.FunctionalTests/CommandInterceptionSqlServerTest.cs b/test/EFCore.SqlServer.FunctionalTests/CommandInterceptionSqlServerTest.cs index 5e23046370c..2ed3e99f4eb 100644 --- a/test/EFCore.SqlServer.FunctionalTests/CommandInterceptionSqlServerTest.cs +++ b/test/EFCore.SqlServer.FunctionalTests/CommandInterceptionSqlServerTest.cs @@ -1,6 +1,7 @@ // Licensed to the .NET Foundation under one or more agreements. // The .NET Foundation licenses this file to you under the MIT license. +using Microsoft.Data.SqlClient; using Microsoft.EntityFrameworkCore.SqlServer.Storage.Internal; namespace Microsoft.EntityFrameworkCore; @@ -39,6 +40,114 @@ public override async Task Intercept_query_to_replace_execution(bool asy return null; } + [ConditionalTheory] + [InlineData(false, false)] + [InlineData(true, false)] + [InlineData(false, true)] + [InlineData(true, true)] + public virtual async Task Intercept_query_to_get_statistics(bool async, bool inject) // Issue #23535 + { + var (context, interceptor) = CreateContext(inject); + using (context) + { + using (async + ? await context.Database.BeginTransactionAsync() + : context.Database.BeginTransaction()) + { + var connection = (SqlConnection)context.Database.GetDbConnection(); + var message = ""; + + connection.InfoMessage += ConnectionOnInfoMessage; + + using var listener = Fixture.SubscribeToDiagnosticListener(context.ContextId); + + var results = async + ? await context.Set().ToListAsync() + : context.Set().ToList(); + + AssertNormalOutcome(context, interceptor, async, CommandSource.LinqQuery); + Assert.True(interceptor.DataReaderClosingCalled); + Assert.True(interceptor.DataReaderDisposingCalled); + + Assert.Contains("Scan count", message); + + results[0].Type = "Big Hole Bang"; + + _ = async + ? await context.SaveChangesAsync() + : context.SaveChanges(); + + AssertNormalOutcome(context, interceptor, async, CommandSource.SaveChanges); + Assert.True(interceptor.DataReaderClosingCalled); + Assert.True(interceptor.DataReaderDisposingCalled); + + Assert.Contains("Scan count", message); + + AssertExecutedEvents(listener); + + connection.InfoMessage -= ConnectionOnInfoMessage; + + void ConnectionOnInfoMessage(object sender, SqlInfoMessageEventArgs args) + { + Assert.Same(connection, sender); + message = args.Message; + } + } + } + + return interceptor.CommandText; + } + + + protected class StatisticsCommandInterceptor : CommandInterceptorBase + { + public StatisticsCommandInterceptor() + : base(DbCommandMethod.ExecuteReader) + { + } + + public override InterceptionResult ReaderExecuting( + DbCommand command, + CommandEventData eventData, + InterceptionResult result) + { + command.CommandText = "SET STATISTICS IO ON;" + command.CommandText; + + return base.ReaderExecuting(command, eventData, result); + } + + public override ValueTask> ReaderExecutingAsync( + DbCommand command, + CommandEventData eventData, + InterceptionResult result, + CancellationToken cancellationToken = default) + { + command.CommandText = "SET STATISTICS IO ON;" + command.CommandText; + + return base.ReaderExecutingAsync(command, eventData, result, cancellationToken); + } + + public override InterceptionResult DataReaderClosing( + DbCommand command, + DataReaderClosingEventData eventData, + InterceptionResult result) + { + eventData.DataReader.NextResult(); + + return base.DataReaderClosing(command, eventData, result); + } + + public override async ValueTask DataReaderClosingAsync( + DbCommand command, + DataReaderClosingEventData eventData, + InterceptionResult result) + { + await eventData.DataReader.NextResultAsync(); + + return await base.DataReaderClosingAsync(command, eventData, result); + } + } + public abstract class InterceptionSqlServerFixtureBase : InterceptionFixtureBase { protected override string StoreName diff --git a/test/EFCore.Sqlite.FunctionalTests/Query/BadDataSqliteTest.cs b/test/EFCore.Sqlite.FunctionalTests/Query/BadDataSqliteTest.cs index cf3d38eb359..ff233ab658b 100644 --- a/test/EFCore.Sqlite.FunctionalTests/Query/BadDataSqliteTest.cs +++ b/test/EFCore.Sqlite.FunctionalTests/Query/BadDataSqliteTest.cs @@ -3,6 +3,7 @@ using System.Collections; using System.Data; +using Microsoft.Data.Sqlite; using Microsoft.EntityFrameworkCore.TestModels.Northwind; // ReSharper disable InconsistentNaming @@ -337,7 +338,7 @@ public IDbContextTransaction CurrentTransaction public SemaphoreSlim Semaphore { get; } public string ConnectionString { get; set; } - public DbConnection DbConnection { get; set; } + public DbConnection DbConnection { get; set; } = new SqliteConnection(); public DbContext Context => null;