From e93783b614a4a674297fc0c40c8589dc2e45f459 Mon Sep 17 00:00:00 2001 From: Andrew Peters Date: Mon, 28 Sep 2015 14:03:02 -0700 Subject: [PATCH] Logging: All-up logging improvements: - New DbContextOption "LogSqlParameterValues()" replacing use of Debug log level to control sensitive data logging. - Use a wrapping ILogger in relational to transparently enforce sensitive data logging. - More consistentizing of logging usage, DI etc. - Better structured logging of DbCommands. - Use assembly scoped enums for event ids. - Use event ids everywhere. Fix #1374, #2490 --- src/EntityFramework.Core/DbContext.cs | 25 ++-- .../EntityFramework.Core.csproj | 2 + .../Internal/CoreLoggerExtensions.cs | 29 ++++ .../Infrastructure/CoreLoggingEventId.cs | 15 ++ .../Properties/CoreStrings.resx | 3 - .../Query/AsyncLinqOperatorProvider.cs | 15 +- .../Query/EntityQueryModelVisitor.cs | 35 +++-- .../QueryCompilationContextFactory.cs | 13 +- .../Query/LinqOperatorProvider.cs | 15 +- .../Storage/DatabaseProviderServices.cs | 3 +- .../EntityFramework.InMemory.csproj | 2 + .../Internal/InMemoryLoggerExtensions.cs | 21 +++ .../Infrastructure/InMemoryLoggingEventId.cs | 10 ++ .../Storage/Internal/InMemoryStore.cs | 7 +- .../EntityFramework.Relational.csproj | 6 +- .../Extensions/DbCommandLogData.cs | 30 ++++ .../Extensions/RelationalLoggerExtensions.cs | 131 ++++++------------ .../RelationalDbContextOptionsBuilder.cs | 3 + ...ntityFrameworkServicesBuilderExtensions.cs | 56 +++++++- .../RelationalLoggingEventId.cs | 16 +++ .../RelationalLoggingEventIds.cs | 16 --- .../RelationalOptionsExtension.cs | 10 ++ .../Internal/RelationalModelValidator.cs | 2 +- .../Properties/RelationalStrings.Designer.cs | 16 +++ .../Properties/RelationalStrings.resx | 6 + ...elationalQueryCompilationContextFactory.cs | 8 +- .../Storage/RelationalConnection.cs | 31 ++++- .../Storage/RelationalTransaction.cs | 31 +++-- .../Update/Internal/BatchExecutor.cs | 14 +- .../SqlServerDbContextOptionsExtensions.cs | 6 +- .../SqlServerCompositeMethodCallTranslator.cs | 1 + ...SqlServerQueryCompilationContextFactory.cs | 8 +- .../Storage/Internal/SqlServerConnection.cs | 2 +- src/Shared/LoggingExtensions.cs | 73 +--------- .../DbContextTest.cs | 2 +- .../LoggingModelValidatorTest.cs | 3 +- .../NonThrowingModelValidatorTest.cs | 5 +- .../ModelSourceTest.cs | 2 - .../TestSqlLoggerFactory.cs | 43 ++++-- .../RelationalModelValidatorTest.cs | 3 +- .../Update/BatchExecutorTest.cs | 9 +- .../DataAnnotationSqlServerFixture.cs | 2 +- .../DataAnnotationSqlServerTest.cs | 2 +- .../GearsOfWarQuerySqlServerFixture.cs | 7 +- .../InheritanceSqlServerFixture.cs | 6 +- .../NorthwindQuerySqlServerFixture.cs | 4 +- .../NorthwindSprocQuerySqlServerFixture.cs | 6 +- .../NullSemanticsQuerySqlServerFixture.cs | 2 + .../QueryBugsTest.cs | 4 +- .../QueryLoggingSqlServerTest.cs | 47 +++---- .../SqlServerEndToEndTest.cs | 13 +- .../SqlServerDatabaseCreatorTest.cs | 2 +- .../DataAnnotationSqliteFixture.cs | 5 +- .../DataAnnotationSqliteTest.cs | 2 +- 54 files changed, 493 insertions(+), 337 deletions(-) create mode 100644 src/EntityFramework.Core/Extensions/Internal/CoreLoggerExtensions.cs create mode 100644 src/EntityFramework.Core/Infrastructure/CoreLoggingEventId.cs create mode 100644 src/EntityFramework.InMemory/Extensions/Internal/InMemoryLoggerExtensions.cs create mode 100644 src/EntityFramework.InMemory/Infrastructure/InMemoryLoggingEventId.cs create mode 100644 src/EntityFramework.Relational/Extensions/DbCommandLogData.cs create mode 100644 src/EntityFramework.Relational/Infrastructure/RelationalLoggingEventId.cs delete mode 100644 src/EntityFramework.Relational/Infrastructure/RelationalLoggingEventIds.cs diff --git a/src/EntityFramework.Core/DbContext.cs b/src/EntityFramework.Core/DbContext.cs index 7cde878ef58..d21c62bcd61 100644 --- a/src/EntityFramework.Core/DbContext.cs +++ b/src/EntityFramework.Core/DbContext.cs @@ -9,6 +9,7 @@ using JetBrains.Annotations; using Microsoft.Data.Entity.ChangeTracking; using Microsoft.Data.Entity.ChangeTracking.Internal; +using Microsoft.Data.Entity.Extensions.Internal; using Microsoft.Data.Entity.Infrastructure; using Microsoft.Data.Entity.Internal; using Microsoft.Data.Entity.Metadata; @@ -191,14 +192,14 @@ private IDbContextServices InitializeServices(IServiceProvider serviceProvider, _initializing = true; var optionsBuilder = new DbContextOptionsBuilder(options); + OnConfiguring(optionsBuilder); var providerSource = serviceProvider != null ? ServiceProviderSource.Explicit : ServiceProviderSource.Implicit; serviceProvider = serviceProvider ?? ServiceProviderCache.Instance.GetOrAdd(optionsBuilder.Options); - _logger = serviceProvider.GetRequiredService().CreateLogger(); - _logger.LogDebug(CoreStrings.DebugLogWarning(nameof(LogLevel.Debug), nameof(ILoggerFactory) + "." + nameof(ILoggerFactory.MinimumLevel), nameof(LogLevel) + "." + nameof(LogLevel.Verbose))); + _logger = serviceProvider.GetRequiredService>(); _serviceScope = serviceProvider .GetRequiredService() @@ -304,13 +305,13 @@ public virtual int SaveChanges(bool acceptAllChangesOnSuccess) { return stateManager.SaveChanges(acceptAllChangesOnSuccess); } - catch (Exception ex) + catch (Exception exception) { _logger.LogError( - new DatabaseErrorLogState(GetType()), - ex, - (state, exception) => - CoreStrings.LogExceptionDuringSaveChanges(Environment.NewLine, exception)); + CoreLoggingEventId.DatabaseError, + () => new DatabaseErrorLogState(GetType()), + exception, + e => CoreStrings.LogExceptionDuringSaveChanges(Environment.NewLine, e)); throw; } @@ -384,13 +385,13 @@ public virtual async Task SaveChangesAsync(bool acceptAllChangesOnSuccess, { return await stateManager.SaveChangesAsync(acceptAllChangesOnSuccess, cancellationToken); } - catch (Exception ex) + catch (Exception exception) { _logger.LogError( - new DatabaseErrorLogState(GetType()), - ex, - (state, exception) => - CoreStrings.LogExceptionDuringSaveChanges(Environment.NewLine, exception)); + CoreLoggingEventId.DatabaseError, + () => new DatabaseErrorLogState(GetType()), + exception, + e => CoreStrings.LogExceptionDuringSaveChanges(Environment.NewLine, e)); throw; } diff --git a/src/EntityFramework.Core/EntityFramework.Core.csproj b/src/EntityFramework.Core/EntityFramework.Core.csproj index 30f3fc03042..c5b85df1dd4 100644 --- a/src/EntityFramework.Core/EntityFramework.Core.csproj +++ b/src/EntityFramework.Core/EntityFramework.Core.csproj @@ -66,6 +66,7 @@ + @@ -73,6 +74,7 @@ + diff --git a/src/EntityFramework.Core/Extensions/Internal/CoreLoggerExtensions.cs b/src/EntityFramework.Core/Extensions/Internal/CoreLoggerExtensions.cs new file mode 100644 index 00000000000..c55347a602c --- /dev/null +++ b/src/EntityFramework.Core/Extensions/Internal/CoreLoggerExtensions.cs @@ -0,0 +1,29 @@ +// Copyright (c) .NET Foundation. All rights reserved. +// Licensed under the Apache License, Version 2.0. See License.txt in the project root for license information. + +using System; +using Microsoft.Data.Entity.Infrastructure; +using Microsoft.Framework.Logging; + +namespace Microsoft.Data.Entity.Extensions.Internal +{ + internal static class CoreLoggerExtensions + { + public static void LogError( + this ILogger logger, CoreLoggingEventId eventId, Func state, Exception exception, Func formatter) + { + if (logger.IsEnabled(LogLevel.Error)) + { + logger.Log(LogLevel.Error, (int)eventId, state(), exception, (_, e) => formatter(e)); + } + } + + public static void LogVerbose(this ILogger logger, CoreLoggingEventId eventId, Func formatter) + { + if (logger.IsEnabled(LogLevel.Verbose)) + { + logger.Log(LogLevel.Verbose, (int)eventId, null, null, (_, __) => formatter()); + } + } + } +} diff --git a/src/EntityFramework.Core/Infrastructure/CoreLoggingEventId.cs b/src/EntityFramework.Core/Infrastructure/CoreLoggingEventId.cs new file mode 100644 index 00000000000..570312b6c40 --- /dev/null +++ b/src/EntityFramework.Core/Infrastructure/CoreLoggingEventId.cs @@ -0,0 +1,15 @@ +// Copyright (c) .NET Foundation. All rights reserved. +// Licensed under the Apache License, Version 2.0. See License.txt in the project root for license information. + +namespace Microsoft.Data.Entity.Infrastructure +{ + public enum CoreLoggingEventId + { + DatabaseError = 1, + CompilingQueryModel, + OptimizedQueryModel, + IncludingNavigation, + TrackingQuerySources, + QueryPlan + } +} diff --git a/src/EntityFramework.Core/Properties/CoreStrings.resx b/src/EntityFramework.Core/Properties/CoreStrings.resx index 3f6869d233b..5bae4c38491 100644 --- a/src/EntityFramework.Core/Properties/CoreStrings.resx +++ b/src/EntityFramework.Core/Properties/CoreStrings.resx @@ -462,9 +462,6 @@ The navigation for property '{navigation}' on entity type '{entityType}' cannot be associated with foreign key {targetFk} because it was created for foreign key {actualFk}. - - {debug} level logging is enabled. At this level, Entity Framework will log sensitive application data such as SQL parameter values. To hide this information configure {minimumLevel} to {recommendedLevel} - Property '{property}' on entity type '{entityType}' is of type '{actualType}' but the generic type provided is of type '{genericType}'. diff --git a/src/EntityFramework.Core/Query/AsyncLinqOperatorProvider.cs b/src/EntityFramework.Core/Query/AsyncLinqOperatorProvider.cs index a8d23b86f1c..2fdb5e7fa00 100644 --- a/src/EntityFramework.Core/Query/AsyncLinqOperatorProvider.cs +++ b/src/EntityFramework.Core/Query/AsyncLinqOperatorProvider.cs @@ -11,6 +11,8 @@ using System.Threading; using System.Threading.Tasks; using JetBrains.Annotations; +using Microsoft.Data.Entity.Extensions.Internal; +using Microsoft.Data.Entity.Infrastructure; using Microsoft.Data.Entity.Internal; using Microsoft.Data.Entity.Storage; using Microsoft.Data.Entity.Utilities; @@ -129,13 +131,14 @@ public async Task MoveNext(CancellationToken cancellationToken) return await _inner.MoveNext(cancellationToken); } - catch (Exception e) + catch (Exception exception) { - _exceptionInterceptor._logger.LogError( - new DatabaseErrorLogState(_exceptionInterceptor._contextType), - e, - (state, exception) => - CoreStrings.LogExceptionDuringQueryIteration(Environment.NewLine, exception)); + _exceptionInterceptor._logger + .LogError( + CoreLoggingEventId.DatabaseError, + () => new DatabaseErrorLogState(_exceptionInterceptor._contextType), + exception, + e => CoreStrings.LogExceptionDuringQueryIteration(Environment.NewLine, e)); throw; } diff --git a/src/EntityFramework.Core/Query/EntityQueryModelVisitor.cs b/src/EntityFramework.Core/Query/EntityQueryModelVisitor.cs index 23c5f73a8b2..27a2fdd89d7 100644 --- a/src/EntityFramework.Core/Query/EntityQueryModelVisitor.cs +++ b/src/EntityFramework.Core/Query/EntityQueryModelVisitor.cs @@ -8,6 +8,8 @@ using System.Reflection; using System.Threading.Tasks; using JetBrains.Annotations; +using Microsoft.Data.Entity.Extensions.Internal; +using Microsoft.Data.Entity.Infrastructure; using Microsoft.Data.Entity.Internal; using Microsoft.Data.Entity.Metadata; using Microsoft.Data.Entity.Metadata.Internal; @@ -136,7 +138,10 @@ public virtual Func> CreateQueryExecutor CoreStrings.LogCompilingQueryModel(queryModel)); _blockTaskExpressions = false; @@ -166,7 +171,10 @@ public virtual Func> CreateAsyncQueryExe using (QueryCompilationContext.Logger.BeginScopeImpl(this)) { - QueryCompilationContext.Logger.LogDebug(queryModel, CoreStrings.LogCompilingQueryModel); + QueryCompilationContext.Logger + .LogVerbose( + CoreLoggingEventId.CompilingQueryModel, + () => CoreStrings.LogCompilingQueryModel(queryModel)); _blockTaskExpressions = false; @@ -220,7 +228,10 @@ protected virtual void OptimizeQueryModel([NotNull] QueryModel queryModel) queryModel.TransformExpressions(_subQueryMemberPushDownExpressionVisitor.Visit); - QueryCompilationContext.Logger.LogDebug(queryModel, CoreStrings.LogOptimizedQueryModel); + QueryCompilationContext.Logger + .LogVerbose( + CoreLoggingEventId.OptimizedQueryModel, + () => CoreStrings.LogOptimizedQueryModel(queryModel)); } protected virtual void SingleResultToSequence([NotNull] QueryModel queryModel) @@ -333,9 +344,9 @@ var accessorLambda Expression.Parameter(queryModel.SelectClause.Selector.Type)); QueryCompilationContext.Logger - .LogDebug( - includeSpecification.NavigationPath.Join("."), - CoreStrings.LogIncludingNavigation); + .LogVerbose( + CoreLoggingEventId.IncludingNavigation, + () => CoreStrings.LogIncludingNavigation(includeSpecification.NavigationPath.Join("."))); IncludeNavigations( includeSpecification, @@ -404,10 +415,10 @@ var entityTrackingInfos if (entityTrackingInfos.Any()) { QueryCompilationContext.Logger - .LogDebug( - entityTrackingInfos, - etis => CoreStrings.LogTrackingQuerySources( - etis.Select(eti => eti.QuerySource.ItemName).Join())); + .LogVerbose( + CoreLoggingEventId.TrackingQuerySources, + () => CoreStrings.LogTrackingQuerySources( + entityTrackingInfos.Select(eti => eti.QuerySource.ItemName).Join())); var resultItemType = _expression.Type.GetSequenceType(); @@ -482,7 +493,9 @@ protected virtual Func CreateExecutorLambda() .Lambda>( _expression, QueryContextParameter, QueryResultScopeParameter); - QueryCompilationContext.Logger.LogDebug(() => + QueryCompilationContext.Logger.LogVerbose( + CoreLoggingEventId.QueryPlan, + () => { var queryPlan = _expressionPrinter.Print(queryExecutorExpression); diff --git a/src/EntityFramework.Core/Query/Internal/QueryCompilationContextFactory.cs b/src/EntityFramework.Core/Query/Internal/QueryCompilationContextFactory.cs index cd41d4a71d0..aa9820482e8 100644 --- a/src/EntityFramework.Core/Query/Internal/QueryCompilationContextFactory.cs +++ b/src/EntityFramework.Core/Query/Internal/QueryCompilationContextFactory.cs @@ -11,21 +11,20 @@ namespace Microsoft.Data.Entity.Query.Internal { public class QueryCompilationContextFactory : IQueryCompilationContextFactory { - private readonly ILoggerFactory _loggerFactory; private readonly DbContext _context; public QueryCompilationContextFactory( - [NotNull] ILoggerFactory loggerFactory, + [NotNull] ILogger logger, [NotNull] IEntityQueryModelVisitorFactory entityQueryModelVisitorFactory, [NotNull] IRequiresMaterializationExpressionVisitorFactory requiresMaterializationExpressionVisitorFactory, [NotNull] DbContext context) { - Check.NotNull(loggerFactory, nameof(loggerFactory)); + Check.NotNull(logger, nameof(logger)); Check.NotNull(entityQueryModelVisitorFactory, nameof(entityQueryModelVisitorFactory)); Check.NotNull(requiresMaterializationExpressionVisitorFactory, nameof(requiresMaterializationExpressionVisitorFactory)); Check.NotNull(context, nameof(context)); - _loggerFactory = loggerFactory; + Logger = logger; EntityQueryModelVisitorFactory = entityQueryModelVisitorFactory; RequiresMaterializationExpressionVisitorFactory = requiresMaterializationExpressionVisitorFactory; @@ -33,6 +32,7 @@ public QueryCompilationContextFactory( _context = context; } + protected virtual ILogger Logger { get; } protected virtual IEntityQueryModelVisitorFactory EntityQueryModelVisitorFactory { get; } protected virtual IRequiresMaterializationExpressionVisitorFactory RequiresMaterializationExpressionVisitorFactory { get; } @@ -40,13 +40,10 @@ public QueryCompilationContextFactory( public virtual QueryCompilationContext Create(bool async) => new QueryCompilationContext( - CreateLogger(), + Logger, EntityQueryModelVisitorFactory, RequiresMaterializationExpressionVisitorFactory, async ? (ILinqOperatorProvider)new AsyncLinqOperatorProvider() : new LinqOperatorProvider(), ContextType); - - protected virtual ILogger CreateLogger() - => _loggerFactory.CreateLogger(); } } diff --git a/src/EntityFramework.Core/Query/LinqOperatorProvider.cs b/src/EntityFramework.Core/Query/LinqOperatorProvider.cs index 3e9054133af..df8e6247778 100644 --- a/src/EntityFramework.Core/Query/LinqOperatorProvider.cs +++ b/src/EntityFramework.Core/Query/LinqOperatorProvider.cs @@ -9,6 +9,8 @@ using System.Linq.Expressions; using System.Reflection; using JetBrains.Annotations; +using Microsoft.Data.Entity.Extensions.Internal; +using Microsoft.Data.Entity.Infrastructure; using Microsoft.Data.Entity.Internal; using Microsoft.Data.Entity.Storage; using Microsoft.Data.Entity.Utilities; @@ -121,13 +123,14 @@ public bool MoveNext() return _inner.MoveNext(); } - catch (Exception e) + catch (Exception exception) { - _exceptionInterceptor._logger.LogError( - new DatabaseErrorLogState(_exceptionInterceptor._contextType), - e, - (state, exception) => - CoreStrings.LogExceptionDuringQueryIteration(Environment.NewLine, exception)); + _exceptionInterceptor._logger + .LogError( + CoreLoggingEventId.DatabaseError, + () => new DatabaseErrorLogState(_exceptionInterceptor._contextType), + exception, + e => CoreStrings.LogExceptionDuringQueryIteration(Environment.NewLine, e)); throw; } diff --git a/src/EntityFramework.Core/Storage/DatabaseProviderServices.cs b/src/EntityFramework.Core/Storage/DatabaseProviderServices.cs index 332a0b67345..e1f389b59e0 100644 --- a/src/EntityFramework.Core/Storage/DatabaseProviderServices.cs +++ b/src/EntityFramework.Core/Storage/DatabaseProviderServices.cs @@ -34,8 +34,7 @@ protected DatabaseProviderServices([NotNull] IServiceProvider services) public virtual IConventionSetBuilder ConventionSetBuilder => null; public virtual IValueGeneratorSelector ValueGeneratorSelector => GetService(); public virtual IModelValidator ModelValidator => GetService(); - public virtual ICompiledQueryCacheKeyGenerator CompiledQueryCacheKeyGenerator - => GetService(); + public virtual ICompiledQueryCacheKeyGenerator CompiledQueryCacheKeyGenerator => GetService(); public virtual IExpressionPrinter ExpressionPrinter => GetService(); public virtual IResultOperatorHandler ResultOperatorHandler => GetService(); public virtual IQueryCompilationContextFactory QueryCompilationContextFactory => GetService(); diff --git a/src/EntityFramework.InMemory/EntityFramework.InMemory.csproj b/src/EntityFramework.InMemory/EntityFramework.InMemory.csproj index 6d569f778eb..094e3abac57 100644 --- a/src/EntityFramework.InMemory/EntityFramework.InMemory.csproj +++ b/src/EntityFramework.InMemory/EntityFramework.InMemory.csproj @@ -45,8 +45,10 @@ Utilities\LoggingExtensions.cs + + diff --git a/src/EntityFramework.InMemory/Extensions/Internal/InMemoryLoggerExtensions.cs b/src/EntityFramework.InMemory/Extensions/Internal/InMemoryLoggerExtensions.cs new file mode 100644 index 00000000000..7f173b6e0b0 --- /dev/null +++ b/src/EntityFramework.InMemory/Extensions/Internal/InMemoryLoggerExtensions.cs @@ -0,0 +1,21 @@ +// Copyright (c) .NET Foundation. All rights reserved. +// Licensed under the Apache License, Version 2.0. See License.txt in the project root for license information. + +using System; +using Microsoft.Data.Entity.Infrastructure; +using Microsoft.Framework.Logging; + +namespace Microsoft.Data.Entity.Extensions.Internal +{ + internal static class CoreLoggerExtensions + { + public static void LogInformation( + this ILogger logger, InMemoryLoggingEventId eventId, TState state, Func formatter) + { + if (logger.IsEnabled(LogLevel.Information)) + { + logger.Log(LogLevel.Information, (int)eventId, state, null, (s, _) => formatter((TState)s)); + } + } + } +} diff --git a/src/EntityFramework.InMemory/Infrastructure/InMemoryLoggingEventId.cs b/src/EntityFramework.InMemory/Infrastructure/InMemoryLoggingEventId.cs new file mode 100644 index 00000000000..c00e5dd5633 --- /dev/null +++ b/src/EntityFramework.InMemory/Infrastructure/InMemoryLoggingEventId.cs @@ -0,0 +1,10 @@ +// Copyright (c) .NET Foundation. All rights reserved. +// Licensed under the Apache License, Version 2.0. See License.txt in the project root for license information. + +namespace Microsoft.Data.Entity.Infrastructure +{ + public enum InMemoryLoggingEventId + { + SavedChanges = 1 + } +} diff --git a/src/EntityFramework.InMemory/Storage/Internal/InMemoryStore.cs b/src/EntityFramework.InMemory/Storage/Internal/InMemoryStore.cs index e2ada4b9f69..2ad158802c7 100644 --- a/src/EntityFramework.InMemory/Storage/Internal/InMemoryStore.cs +++ b/src/EntityFramework.InMemory/Storage/Internal/InMemoryStore.cs @@ -7,7 +7,9 @@ using System.Diagnostics; using System.Linq; using JetBrains.Annotations; +using Microsoft.Data.Entity.Extensions.Internal; using Microsoft.Data.Entity.ChangeTracking.Internal; +using Microsoft.Data.Entity.Infrastructure; using Microsoft.Data.Entity.Internal; using Microsoft.Data.Entity.Metadata; using Microsoft.Data.Entity.Metadata.Internal; @@ -113,7 +115,10 @@ public virtual int ExecuteTransaction(IEnumerable entries) return ts; }); - _logger.LogInformation(rowsAffected, ra => InMemoryStrings.LogSavedChanges(ra)); + _logger.LogInformation( + InMemoryLoggingEventId.SavedChanges, + rowsAffected, + InMemoryStrings.LogSavedChanges); return rowsAffected; } diff --git a/src/EntityFramework.Relational/EntityFramework.Relational.csproj b/src/EntityFramework.Relational/EntityFramework.Relational.csproj index 46c362cdc47..3d8ab433a45 100644 --- a/src/EntityFramework.Relational/EntityFramework.Relational.csproj +++ b/src/EntityFramework.Relational/EntityFramework.Relational.csproj @@ -49,13 +49,11 @@ Extensions\AsyncEnumerableExtensions.cs - - Extensions\LoggingExtensions.cs - + - + diff --git a/src/EntityFramework.Relational/Extensions/DbCommandLogData.cs b/src/EntityFramework.Relational/Extensions/DbCommandLogData.cs new file mode 100644 index 00000000000..ccaa02565c7 --- /dev/null +++ b/src/EntityFramework.Relational/Extensions/DbCommandLogData.cs @@ -0,0 +1,30 @@ +// Copyright (c) .NET Foundation. All rights reserved. +// Licensed under the Apache License, Version 2.0. See License.txt in the project root for license information. + +using System.Collections.Generic; +using System.Data; +using JetBrains.Annotations; +// ReSharper disable once CheckNamespace + +namespace Microsoft.Data.Entity.Storage +{ + public class DbCommandLogData + { + public DbCommandLogData( + [NotNull] string commandText, + CommandType commandType, + int commandTimeout, + [NotNull] IReadOnlyDictionary parameters) + { + CommandText = commandText; + CommandType = commandType; + CommandTimeout = commandTimeout; + Parameters = parameters; + } + + public virtual string CommandText { get; } + public virtual CommandType CommandType { get; } + public virtual int CommandTimeout { get; } + public virtual IReadOnlyDictionary Parameters { get; } + } +} diff --git a/src/EntityFramework.Relational/Extensions/RelationalLoggerExtensions.cs b/src/EntityFramework.Relational/Extensions/RelationalLoggerExtensions.cs index e392ee207b2..b3f702aaaa3 100644 --- a/src/EntityFramework.Relational/Extensions/RelationalLoggerExtensions.cs +++ b/src/EntityFramework.Relational/Extensions/RelationalLoggerExtensions.cs @@ -2,10 +2,9 @@ // Licensed under the Apache License, Version 2.0. See License.txt in the project root for license information. using System; -using System.Data; using System.Data.Common; using System.Globalization; -using System.Text; +using System.Linq; using JetBrains.Annotations; using Microsoft.Data.Entity.Infrastructure; using Microsoft.Data.Entity.Internal; @@ -16,109 +15,65 @@ namespace Microsoft.Data.Entity.Storage { - public static class RelationalLoggerExtensions + internal static class RelationalLoggerExtensions { - public static void LogSql([NotNull] this ILogger logger, [NotNull] string sql) + public static void LogCommand([NotNull] this ILogger logger, [NotNull] DbCommand command) { Check.NotNull(logger, nameof(logger)); - Check.NotNull(sql, nameof(sql)); + Check.NotNull(command, nameof(command)); - logger.LogVerbose(RelationalLoggingEventIds.ExecutingSql, sql); + logger.LogInformation( + RelationalLoggingEventId.ExecutingCommand, + () => + { + var logParameterValues + = command.Parameters.Count > 0 + && (logger as ILogSqlParameterValuesAccessor)?.LogSqlParameterValues == true; + + return new DbCommandLogData( + command.CommandText.TrimEnd(), + command.CommandType, + command.CommandTimeout, + command.Parameters + .Cast() + .ToDictionary(p => p.ParameterName, p => logParameterValues ? p.Value : "?")); + }, + state => + RelationalStrings.RelationalLoggerExecutingCommand( + state.Parameters + .Select(kv => $"{kv.Key}='{Convert.ToString(kv.Value, CultureInfo.InvariantCulture)}'") + .Join(), + state.CommandType, + state.CommandTimeout, + Environment.NewLine, + state.CommandText)); } - public static void LogParameters([NotNull] this ILogger logger, [NotNull] DbParameterCollection parameters) + private static void LogInformation( + this ILogger logger, RelationalLoggingEventId eventId, Func state, Func formatter) { - Check.NotNull(logger, nameof(logger)); - Check.NotNull(parameters, nameof(parameters)); - - if (parameters.Count == 0) + if (logger.IsEnabled(LogLevel.Information)) { - return; + logger.Log(LogLevel.Information, (int)eventId, state(), null, (s, _) => formatter((TState)s)); } - var paramList = new StringBuilder(); - - paramList.AppendFormat("{0}: {1}", (parameters[0]).ParameterName, Convert.ToString((parameters[0]).Value, CultureInfo.InvariantCulture)); - for (var i = 1; i < parameters.Count; i++) - { - paramList.AppendLine(); - paramList.AppendFormat("{0}: {1}", (parameters[i]).ParameterName, Convert.ToString((parameters[i]).Value, CultureInfo.InvariantCulture)); - } - logger.LogDebug(RelationalLoggingEventIds.ExecutingSql, paramList.ToString()); } - public static void LogCommand([NotNull] this ILogger logger, [NotNull] DbCommand command) + public static void LogVerbose( + this ILogger logger, RelationalLoggingEventId eventId, Func formatter) { - Check.NotNull(logger, nameof(logger)); - Check.NotNull(command, nameof(command)); - - var scope = Guid.NewGuid(); - - using (logger.BeginScopeImpl(scope)) + if (logger.IsEnabled(LogLevel.Verbose)) { - logger.LogParameters(command.Parameters); - logger.LogSql(command.CommandText); + logger.Log(LogLevel.Verbose, (int)eventId, null, null, (_, __) => formatter()); } } - public static void CreatingDatabase([NotNull] this ILogger logger, [NotNull] string databaseName) + public static void LogVerbose( + this ILogger logger, RelationalLoggingEventId eventId, TState state, Func formatter) { - Check.NotNull(logger, nameof(logger)); - Check.NotNull(databaseName, nameof(databaseName)); - - logger.LogInformation( - RelationalLoggingEventIds.CreatingDatabase, - databaseName, - RelationalStrings.RelationalLoggerCreatingDatabase); - } - - public static void OpeningConnection([NotNull] this ILogger logger, [NotNull] string connectionString) - { - Check.NotNull(logger, nameof(logger)); - Check.NotNull(connectionString, nameof(connectionString)); - - logger.LogVerbose( - RelationalLoggingEventIds.OpeningConnection, - connectionString, - RelationalStrings.RelationalLoggerOpeningConnection); - } - - public static void ClosingConnection([NotNull] this ILogger logger, [NotNull] string connectionString) - { - Check.NotNull(logger, nameof(logger)); - Check.NotNull(connectionString, nameof(connectionString)); - - logger.LogVerbose( - RelationalLoggingEventIds.ClosingConnection, - connectionString, - RelationalStrings.RelationalLoggerClosingConnection); - } - - public static void BeginningTransaction([NotNull] this ILogger logger, IsolationLevel isolationLevel) - { - Check.NotNull(logger, nameof(logger)); - - logger.LogVerbose( - RelationalLoggingEventIds.BeginningTransaction, - isolationLevel, - il => RelationalStrings.RelationalLoggerBeginningTransaction(il.ToString("G"))); - } - - public static void CommittingTransaction([NotNull] this ILogger logger) - { - Check.NotNull(logger, nameof(logger)); - - logger.LogVerbose( - RelationalLoggingEventIds.CommittingTransaction, - RelationalStrings.RelationalLoggerCommittingTransaction); - } - - public static void RollingbackTransaction([NotNull] this ILogger logger) - { - Check.NotNull(logger, nameof(logger)); - - logger.LogVerbose( - RelationalLoggingEventIds.RollingbackTransaction, - RelationalStrings.RelationalLoggerRollingbackTransaction); + if (logger.IsEnabled(LogLevel.Verbose)) + { + logger.Log(LogLevel.Verbose, (int)eventId, state, null, (s, __) => formatter((TState)s)); + } } } } diff --git a/src/EntityFramework.Relational/Infrastructure/RelationalDbContextOptionsBuilder.cs b/src/EntityFramework.Relational/Infrastructure/RelationalDbContextOptionsBuilder.cs index 16d95477f2f..464f5e44c16 100644 --- a/src/EntityFramework.Relational/Infrastructure/RelationalDbContextOptionsBuilder.cs +++ b/src/EntityFramework.Relational/Infrastructure/RelationalDbContextOptionsBuilder.cs @@ -52,6 +52,9 @@ public virtual TBuilder UseRelationalNulls() public virtual TBuilder DisableQueryClientEvaluation() => SetOption(e => e.IsQueryClientEvaluationEnabled = false); + + public virtual TBuilder LogSqlParameterValues() + => SetOption(e => e.LogSqlParameterValues = true); protected virtual TBuilder SetOption([NotNull] Action setAction) { diff --git a/src/EntityFramework.Relational/Infrastructure/RelationalEntityFrameworkServicesBuilderExtensions.cs b/src/EntityFramework.Relational/Infrastructure/RelationalEntityFrameworkServicesBuilderExtensions.cs index 6ced2ad9f02..78c63167cf8 100644 --- a/src/EntityFramework.Relational/Infrastructure/RelationalEntityFrameworkServicesBuilderExtensions.cs +++ b/src/EntityFramework.Relational/Infrastructure/RelationalEntityFrameworkServicesBuilderExtensions.cs @@ -3,6 +3,7 @@ using System; using System.Collections.Generic; +using System.Linq; using JetBrains.Annotations; using Microsoft.Data.Entity.Internal; using Microsoft.Data.Entity.Migrations; @@ -20,6 +21,7 @@ using Microsoft.Data.Entity.ValueGeneration; using Microsoft.Framework.DependencyInjection; using Microsoft.Framework.DependencyInjection.Extensions; +using Microsoft.Framework.Logging; // Intentionally in this namespace since this is for use by other relational providers rather than // by top-level app developers. @@ -32,7 +34,9 @@ public static EntityFrameworkServicesBuilder AddRelational([NotNull] this Entity { Check.NotNull(builder, nameof(builder)); - builder.GetService().TryAdd(new ServiceCollection() + builder.GetService() + .Replace(new ServiceDescriptor(typeof(ILogger<>), typeof(SensitiveDataLogger<>), ServiceLifetime.Scoped)) + .TryAdd(new ServiceCollection() .AddSingleton() .AddSingleton, ModificationCommandComparer>() .AddSingleton() @@ -110,4 +114,54 @@ private static IRelationalDatabaseProviderServices GetProviderServices(IServiceP return providerServices; } } + + public interface ILogSqlParameterValuesAccessor + { + bool LogSqlParameterValues { get; } +} + + public class SensitiveDataLogger : ILogger, ILogSqlParameterValuesAccessor + { + private readonly ILogger _innerLogger; + private readonly RelationalOptionsExtension _relationalOptionsExtension; + + public SensitiveDataLogger( + [NotNull] ILoggerFactory loggerFactory, [CanBeNull] IDbContextOptions contextOptions) + { + _innerLogger = new Logger(loggerFactory); + + _relationalOptionsExtension + = contextOptions?.Extensions + .OfType() + .FirstOrDefault(); + } + + public virtual bool LogSqlParameterValues + { + get + { + if (_relationalOptionsExtension == null) + { + return false; + } + + if (_relationalOptionsExtension.LogSqlParameterValues + && !_relationalOptionsExtension.LogSqlParameterValuesWarned) + { + _innerLogger.LogWarning(RelationalStrings.ParameterLoggingEnabled); + + _relationalOptionsExtension.LogSqlParameterValuesWarned = true; + } + + return _relationalOptionsExtension.LogSqlParameterValues; + } + } + + void ILogger.Log(LogLevel logLevel, int eventId, object state, Exception exception, Func formatter) + => _innerLogger.Log(logLevel, eventId, state, exception, formatter); + + bool ILogger.IsEnabled(LogLevel logLevel) => _innerLogger.IsEnabled(logLevel); + + IDisposable ILogger.BeginScopeImpl(object state) => _innerLogger.BeginScopeImpl(state); + } } diff --git a/src/EntityFramework.Relational/Infrastructure/RelationalLoggingEventId.cs b/src/EntityFramework.Relational/Infrastructure/RelationalLoggingEventId.cs new file mode 100644 index 00000000000..dad7ffa5b3b --- /dev/null +++ b/src/EntityFramework.Relational/Infrastructure/RelationalLoggingEventId.cs @@ -0,0 +1,16 @@ +// Copyright (c) .NET Foundation. All rights reserved. +// Licensed under the Apache License, Version 2.0. See License.txt in the project root for license information. + +namespace Microsoft.Data.Entity.Infrastructure +{ + public enum RelationalLoggingEventId + { + ExecutingCommand = 1, + CreatingDatabase, + OpeningConnection, + ClosingConnection, + BeginningTransaction, + CommittingTransaction, + RollingbackTransaction + } +} diff --git a/src/EntityFramework.Relational/Infrastructure/RelationalLoggingEventIds.cs b/src/EntityFramework.Relational/Infrastructure/RelationalLoggingEventIds.cs deleted file mode 100644 index 45be7c28db3..00000000000 --- a/src/EntityFramework.Relational/Infrastructure/RelationalLoggingEventIds.cs +++ /dev/null @@ -1,16 +0,0 @@ -// Copyright (c) .NET Foundation. All rights reserved. -// Licensed under the Apache License, Version 2.0. See License.txt in the project root for license information. - -namespace Microsoft.Data.Entity.Infrastructure -{ - public static class RelationalLoggingEventIds - { - public const int ExecutingSql = 42; - public const int CreatingDatabase = 43; - public const int OpeningConnection = 44; - public const int ClosingConnection = 45; - public const int BeginningTransaction = 46; - public const int CommittingTransaction = 47; - public const int RollingbackTransaction = 48; - } -} diff --git a/src/EntityFramework.Relational/Infrastructure/RelationalOptionsExtension.cs b/src/EntityFramework.Relational/Infrastructure/RelationalOptionsExtension.cs index 37504663286..d0702b3cdf3 100644 --- a/src/EntityFramework.Relational/Infrastructure/RelationalOptionsExtension.cs +++ b/src/EntityFramework.Relational/Infrastructure/RelationalOptionsExtension.cs @@ -18,6 +18,7 @@ public abstract class RelationalOptionsExtension : IDbContextOptionsExtension private int? _maxBatchSize; private bool _useRelationalNulls; private bool _queryClientEvaluationEnabled = true; + private bool _logSqlParameterValues; private bool? _throwOnAmbientTransaction; private string _migrationsAssembly; private string _migrationsHistoryTableName; @@ -39,6 +40,7 @@ protected RelationalOptionsExtension([NotNull] RelationalOptionsExtension copyFr _maxBatchSize = copyFrom._maxBatchSize; _useRelationalNulls = copyFrom._useRelationalNulls; _queryClientEvaluationEnabled = copyFrom._queryClientEvaluationEnabled; + _logSqlParameterValues = copyFrom._logSqlParameterValues; _throwOnAmbientTransaction = copyFrom._throwOnAmbientTransaction; _migrationsAssembly = copyFrom._migrationsAssembly; _migrationsHistoryTableName = copyFrom._migrationsHistoryTableName; @@ -113,6 +115,14 @@ public virtual bool IsQueryClientEvaluationEnabled set { _queryClientEvaluationEnabled = value; } } + public virtual bool LogSqlParameterValues + { + get { return _logSqlParameterValues; } + set { _logSqlParameterValues = value; } + } + + internal bool LogSqlParameterValuesWarned { get; set; } + public virtual bool? ThrowOnAmbientTransaction { get { return _throwOnAmbientTransaction; } diff --git a/src/EntityFramework.Relational/Internal/RelationalModelValidator.cs b/src/EntityFramework.Relational/Internal/RelationalModelValidator.cs index 959119bcea8..fe478c19a19 100644 --- a/src/EntityFramework.Relational/Internal/RelationalModelValidator.cs +++ b/src/EntityFramework.Relational/Internal/RelationalModelValidator.cs @@ -15,7 +15,7 @@ public class RelationalModelValidator : LoggingModelValidator private readonly IRelationalAnnotationProvider _relationalExtensions; public RelationalModelValidator( - [NotNull] ILogger loggerFactory, // TODO: Fix covariance: Logging#253 + [NotNull] ILogger loggerFactory, [NotNull] IRelationalAnnotationProvider relationalExtensions) : base(loggerFactory) { diff --git a/src/EntityFramework.Relational/Properties/RelationalStrings.Designer.cs b/src/EntityFramework.Relational/Properties/RelationalStrings.Designer.cs index ce43475e102..dbdea650d18 100644 --- a/src/EntityFramework.Relational/Properties/RelationalStrings.Designer.cs +++ b/src/EntityFramework.Relational/Properties/RelationalStrings.Designer.cs @@ -468,6 +468,22 @@ public static string ClientEvalWarning([CanBeNull] object expression) return string.Format(CultureInfo.CurrentCulture, GetString("ClientEvalWarning", "expression"), expression); } + /// + /// SQL parameter value logging is enabled. As SQL parameter values may include sensitive application data, this mode should only be enabled during development. + /// + public static string ParameterLoggingEnabled + { + get { return GetString("ParameterLoggingEnabled"); } + } + + /// + /// Executing DbCommand: [Parameters=[{parameters}], CommandType='{commandType}', CommandTimeout='{commandTimeout}']{newLine}{newLine}{commandText}{newLine} + /// + public static string RelationalLoggerExecutingCommand([CanBeNull] object parameters, [CanBeNull] object commandType, [CanBeNull] object commandTimeout, [CanBeNull] object newLine, [CanBeNull] object commandText) + { + return string.Format(CultureInfo.CurrentCulture, GetString("RelationalLoggerExecutingCommand", "parameters", "commandType", "commandTimeout", "newLine", "commandText"), parameters, commandType, commandTimeout, newLine, commandText); + } + private static string GetString(string name, params string[] formatterNames) { var value = _resourceManager.GetString(name); diff --git a/src/EntityFramework.Relational/Properties/RelationalStrings.resx b/src/EntityFramework.Relational/Properties/RelationalStrings.resx index 713e0e87263..637c2ce247f 100644 --- a/src/EntityFramework.Relational/Properties/RelationalStrings.resx +++ b/src/EntityFramework.Relational/Properties/RelationalStrings.resx @@ -289,4 +289,10 @@ The LINQ expression '{expression}' could not be translated and will be evaluated locally. + + SQL parameter value logging is enabled. As SQL parameter values may include sensitive application data, this mode should only be enabled during development. + + + Executing DbCommand: [Parameters=[{parameters}], CommandType='{commandType}', CommandTimeout='{commandTimeout}']{newLine}{newLine}{commandText}{newLine} + \ No newline at end of file diff --git a/src/EntityFramework.Relational/Query/RelationalQueryCompilationContextFactory.cs b/src/EntityFramework.Relational/Query/RelationalQueryCompilationContextFactory.cs index afaf7ea74a9..e00f4be6606 100644 --- a/src/EntityFramework.Relational/Query/RelationalQueryCompilationContextFactory.cs +++ b/src/EntityFramework.Relational/Query/RelationalQueryCompilationContextFactory.cs @@ -12,12 +12,12 @@ namespace Microsoft.Data.Entity.Query public class RelationalQueryCompilationContextFactory : QueryCompilationContextFactory { public RelationalQueryCompilationContextFactory( - [NotNull] ILoggerFactory loggerFactory, + [NotNull] ILogger logger, [NotNull] IEntityQueryModelVisitorFactory entityQueryModelVisitorFactory, [NotNull] IRequiresMaterializationExpressionVisitorFactory requiresMaterializationExpressionVisitorFactory, [NotNull] DbContext context) : base( - Check.NotNull(loggerFactory, nameof(loggerFactory)), + Check.NotNull(logger, nameof(logger)), Check.NotNull(entityQueryModelVisitorFactory, nameof(entityQueryModelVisitorFactory)), Check.NotNull(requiresMaterializationExpressionVisitorFactory, nameof(requiresMaterializationExpressionVisitorFactory)), Check.NotNull(context, nameof(context))) @@ -27,14 +27,14 @@ public RelationalQueryCompilationContextFactory( public override QueryCompilationContext Create(bool async) => async ? new RelationalQueryCompilationContext( - CreateLogger(), + Logger, EntityQueryModelVisitorFactory, RequiresMaterializationExpressionVisitorFactory, new AsyncLinqOperatorProvider(), new AsyncQueryMethodProvider(), ContextType) : new RelationalQueryCompilationContext( - CreateLogger(), + Logger, EntityQueryModelVisitorFactory, RequiresMaterializationExpressionVisitorFactory, new LinqOperatorProvider(), diff --git a/src/EntityFramework.Relational/Storage/RelationalConnection.cs b/src/EntityFramework.Relational/Storage/RelationalConnection.cs index 4951951b0c6..cfc03e2f5e1 100644 --- a/src/EntityFramework.Relational/Storage/RelationalConnection.cs +++ b/src/EntityFramework.Relational/Storage/RelationalConnection.cs @@ -128,9 +128,19 @@ public virtual async Task BeginTransactionAsync( private IRelationalTransaction BeginTransactionWithNoPreconditions(IsolationLevel isolationLevel) { - _logger.BeginningTransaction(isolationLevel); + Check.NotNull(_logger, nameof(_logger)); - Transaction = new RelationalTransaction(this, DbConnection.BeginTransaction(isolationLevel), /*transactionOwned*/ true, _logger); + _logger.LogVerbose( + RelationalLoggingEventId.BeginningTransaction, + isolationLevel, + il => RelationalStrings.RelationalLoggerBeginningTransaction(il.ToString("G"))); + + Transaction + = new RelationalTransaction( + this, + DbConnection.BeginTransaction(isolationLevel), + _logger, + transactionOwned: true); return Transaction; } @@ -155,7 +165,7 @@ public virtual IRelationalTransaction UseTransaction(DbTransaction transaction) Open(); - Transaction = new RelationalTransaction(this, transaction, /*transactionOwned*/ false, _logger); + Transaction = new RelationalTransaction(this, transaction, _logger, transactionOwned: false); } return Transaction; @@ -169,7 +179,10 @@ public virtual void Open() #endif if (_openedCount == 0) { - _logger.OpeningConnection(ConnectionString); + _logger.LogVerbose( + RelationalLoggingEventId.OpeningConnection, + ConnectionString, + RelationalStrings.RelationalLoggerOpeningConnection); _connection.Value.Open(); } @@ -185,7 +198,10 @@ public virtual void Open() #endif if (_openedCount == 0) { - _logger.OpeningConnection(ConnectionString); + _logger.LogVerbose( + RelationalLoggingEventId.OpeningConnection, + ConnectionString, + RelationalStrings.RelationalLoggerOpeningConnection); await _connection.Value.OpenAsync(cancellationToken); } @@ -212,7 +228,10 @@ public virtual void Close() if (_openedCount > 0 && --_openedCount == 0) { - _logger.ClosingConnection(ConnectionString); + _logger.LogVerbose( + RelationalLoggingEventId.ClosingConnection, + ConnectionString, + RelationalStrings.RelationalLoggerClosingConnection); _connection.Value.Close(); } diff --git a/src/EntityFramework.Relational/Storage/RelationalTransaction.cs b/src/EntityFramework.Relational/Storage/RelationalTransaction.cs index 7030842ed20..8b99b5c904e 100644 --- a/src/EntityFramework.Relational/Storage/RelationalTransaction.cs +++ b/src/EntityFramework.Relational/Storage/RelationalTransaction.cs @@ -15,47 +15,54 @@ namespace Microsoft.Data.Entity.Storage public class RelationalTransaction : IRelationalTransaction { private readonly DbTransaction _transaction; + private readonly ILogger _logger; private readonly bool _transactionOwned; + private bool _disposed; public RelationalTransaction( [NotNull] IRelationalConnection connection, - [NotNull] DbTransaction dbTransaction, - bool transactionOwned, - [NotNull] ILogger logger) + [NotNull] DbTransaction transaction, + [NotNull] ILogger logger, + bool transactionOwned) { Check.NotNull(connection, nameof(connection)); - Check.NotNull(dbTransaction, nameof(dbTransaction)); + Check.NotNull(transaction, nameof(transaction)); Check.NotNull(logger, nameof(logger)); - if (connection.DbConnection != dbTransaction.Connection) + if (connection.DbConnection != transaction.Connection) { throw new InvalidOperationException(RelationalStrings.TransactionAssociatedWithDifferentConnection); } Connection = connection; - _transaction = dbTransaction; + + _transaction = transaction; + _logger = logger; _transactionOwned = transactionOwned; - Logger = logger; } - protected virtual ILogger Logger { get; } - public virtual IRelationalConnection Connection { get; } public virtual void Commit() { - Logger.CommittingTransaction(); + _logger.LogVerbose( + RelationalLoggingEventId.CommittingTransaction, + () => RelationalStrings.RelationalLoggerCommittingTransaction); _transaction.Commit(); + ClearTransaction(); } public virtual void Rollback() { - Logger.RollingbackTransaction(); + _logger.LogVerbose( + RelationalLoggingEventId.RollingbackTransaction, + () => RelationalStrings.RelationalLoggerRollingbackTransaction); _transaction.Rollback(); + ClearTransaction(); } @@ -64,10 +71,12 @@ public virtual void Dispose() if (!_disposed) { _disposed = true; + if (_transactionOwned) { _transaction.Dispose(); } + ClearTransaction(); } } diff --git a/src/EntityFramework.Relational/Update/Internal/BatchExecutor.cs b/src/EntityFramework.Relational/Update/Internal/BatchExecutor.cs index 110543aff7a..4f288d5f3fe 100644 --- a/src/EntityFramework.Relational/Update/Internal/BatchExecutor.cs +++ b/src/EntityFramework.Relational/Update/Internal/BatchExecutor.cs @@ -5,7 +5,6 @@ using System.Threading; using System.Threading.Tasks; using JetBrains.Annotations; -using Microsoft.Data.Entity.Internal; using Microsoft.Data.Entity.Storage; using Microsoft.Framework.Logging; @@ -13,15 +12,14 @@ namespace Microsoft.Data.Entity.Update.Internal { public class BatchExecutor : IBatchExecutor { - private readonly LazyRef _logger; + private readonly ILogger _logger; - public BatchExecutor([NotNull] ILoggerFactory loggerFactory) + // ReSharper disable once SuggestBaseTypeForParameter + public BatchExecutor([NotNull] ILogger logger) { - _logger = new LazyRef(() => (loggerFactory.CreateLogger())); + _logger = logger; } - protected virtual ILogger Logger => _logger.Value; - public virtual int Execute( IEnumerable commandBatches, IRelationalConnection connection) @@ -38,7 +36,7 @@ public virtual int Execute( foreach (var commandbatch in commandBatches) { - commandbatch.Execute(connection, Logger); + commandbatch.Execute(connection, _logger); rowsAffected += commandbatch.ModificationCommands.Count; } @@ -70,7 +68,7 @@ public virtual async Task ExecuteAsync( foreach (var commandbatch in commandBatches) { - await commandbatch.ExecuteAsync(connection, Logger, cancellationToken); + await commandbatch.ExecuteAsync(connection, _logger, cancellationToken); rowsAffected += commandbatch.ModificationCommands.Count; } diff --git a/src/EntityFramework.SqlServer/Extensions/SqlServerDbContextOptionsExtensions.cs b/src/EntityFramework.SqlServer/Extensions/SqlServerDbContextOptionsExtensions.cs index 969fd56a987..af934d9a154 100644 --- a/src/EntityFramework.SqlServer/Extensions/SqlServerDbContextOptionsExtensions.cs +++ b/src/EntityFramework.SqlServer/Extensions/SqlServerDbContextOptionsExtensions.cs @@ -13,7 +13,8 @@ namespace Microsoft.Data.Entity { public static class SqlServerDbContextOptionsExtensions { - public static SqlServerDbContextOptionsBuilder UseSqlServer([NotNull] this DbContextOptionsBuilder optionsBuilder, [NotNull] string connectionString) + public static SqlServerDbContextOptionsBuilder UseSqlServer( + [NotNull] this DbContextOptionsBuilder optionsBuilder, [NotNull] string connectionString) { Check.NotNull(optionsBuilder, nameof(optionsBuilder)); Check.NotEmpty(connectionString, nameof(connectionString)); @@ -26,7 +27,8 @@ public static SqlServerDbContextOptionsBuilder UseSqlServer([NotNull] this DbCon } // Note: Decision made to use DbConnection not SqlConnection: Issue #772 - public static SqlServerDbContextOptionsBuilder UseSqlServer([NotNull] this DbContextOptionsBuilder optionsBuilder, [NotNull] DbConnection connection) + public static SqlServerDbContextOptionsBuilder UseSqlServer( + [NotNull] this DbContextOptionsBuilder optionsBuilder, [NotNull] DbConnection connection) { Check.NotNull(optionsBuilder, nameof(optionsBuilder)); Check.NotNull(connection, nameof(connection)); diff --git a/src/EntityFramework.SqlServer/Query/ExpressionTranslators/Internal/SqlServerCompositeMethodCallTranslator.cs b/src/EntityFramework.SqlServer/Query/ExpressionTranslators/Internal/SqlServerCompositeMethodCallTranslator.cs index b7dc0d94908..8efcb227ba8 100644 --- a/src/EntityFramework.SqlServer/Query/ExpressionTranslators/Internal/SqlServerCompositeMethodCallTranslator.cs +++ b/src/EntityFramework.SqlServer/Query/ExpressionTranslators/Internal/SqlServerCompositeMethodCallTranslator.cs @@ -24,6 +24,7 @@ public class SqlServerCompositeMethodCallTranslator : RelationalCompositeMethodC new SqlServerConvertTranslator() }; + // ReSharper disable once SuggestBaseTypeForParameter public SqlServerCompositeMethodCallTranslator([NotNull] ILogger logger) : base(logger) { diff --git a/src/EntityFramework.SqlServer/Query/Internal/SqlServerQueryCompilationContextFactory.cs b/src/EntityFramework.SqlServer/Query/Internal/SqlServerQueryCompilationContextFactory.cs index 4ecf110885e..72d90804449 100644 --- a/src/EntityFramework.SqlServer/Query/Internal/SqlServerQueryCompilationContextFactory.cs +++ b/src/EntityFramework.SqlServer/Query/Internal/SqlServerQueryCompilationContextFactory.cs @@ -11,11 +11,11 @@ namespace Microsoft.Data.Entity.Query.Internal public class SqlServerQueryCompilationContextFactory : RelationalQueryCompilationContextFactory { public SqlServerQueryCompilationContextFactory( - [NotNull] ILoggerFactory loggerFactory, + [NotNull] ILogger logger, [NotNull] IEntityQueryModelVisitorFactory entityQueryModelVisitorFactory, [NotNull] IRequiresMaterializationExpressionVisitorFactory requiresMaterializationExpressionVisitorFactory, [NotNull] DbContext context) - : base(Check.NotNull(loggerFactory, nameof(loggerFactory)), + : base(Check.NotNull(logger, nameof(logger)), Check.NotNull(entityQueryModelVisitorFactory, nameof(entityQueryModelVisitorFactory)), Check.NotNull(requiresMaterializationExpressionVisitorFactory, nameof(requiresMaterializationExpressionVisitorFactory)), Check.NotNull(context, nameof(context))) @@ -25,14 +25,14 @@ public SqlServerQueryCompilationContextFactory( public override QueryCompilationContext Create(bool async) => async ? new SqlServerQueryCompilationContext( - CreateLogger(), + Logger, EntityQueryModelVisitorFactory, RequiresMaterializationExpressionVisitorFactory, new AsyncLinqOperatorProvider(), new AsyncQueryMethodProvider(), ContextType) : new SqlServerQueryCompilationContext( - CreateLogger(), + Logger, EntityQueryModelVisitorFactory, RequiresMaterializationExpressionVisitorFactory, new LinqOperatorProvider(), diff --git a/src/EntityFramework.SqlServer/Storage/Internal/SqlServerConnection.cs b/src/EntityFramework.SqlServer/Storage/Internal/SqlServerConnection.cs index fd51f71b21b..8886f31d9df 100644 --- a/src/EntityFramework.SqlServer/Storage/Internal/SqlServerConnection.cs +++ b/src/EntityFramework.SqlServer/Storage/Internal/SqlServerConnection.cs @@ -31,7 +31,7 @@ public virtual ISqlServerConnection CreateMasterConnection() { var builder = new SqlConnectionStringBuilder { ConnectionString = ConnectionString, InitialCatalog = "master" }; - // TODO use clone connection method once implimented see #1406 + // TODO use clone connection method once implemented see #1406 var optionsBuilder = new DbContextOptionsBuilder(); optionsBuilder.UseSqlServer(builder.ConnectionString).CommandTimeout(CommandTimeout); diff --git a/src/Shared/LoggingExtensions.cs b/src/Shared/LoggingExtensions.cs index 198019c1cc6..5b7ce384d51 100644 --- a/src/Shared/LoggingExtensions.cs +++ b/src/Shared/LoggingExtensions.cs @@ -1,9 +1,7 @@ // Copyright (c) .NET Foundation. All rights reserved. // Licensed under the Apache License, Version 2.0. See License.txt in the project root for license information. -using System; - -// ReSharper disable once CheckNamespace + // ReSharper disable once CheckNamespace namespace Microsoft.Framework.Logging { @@ -16,74 +14,5 @@ public static ILogger CreateCommandsLogger(this ILoggerFactory loggerFactory) public static ILogger CreateCommandsLogger(this ILoggerProvider loggerProvider) => loggerProvider.CreateLogger(CommandsLoggerName); - - public static void LogInformation(this ILogger logger, TState state, Func formatter) - => logger.LogInformation(0, state, formatter); - - public static void LogInformation( - this ILogger logger, int eventId, TState state, Func formatter) - { - if (logger.IsEnabled(LogLevel.Information)) - { - logger.Log(LogLevel.Information, eventId, state, null, (s, _) => formatter((TState)s)); - } - } - - public static void LogError( - this ILogger logger, Exception exception, Func formatter) - { - if (logger.IsEnabled(LogLevel.Error)) - { - logger.Log(LogLevel.Error, 0, null, exception, (s, e) => formatter((TState)s, e)); - } - } - - public static void LogError( - this ILogger logger, TState state, Exception exception, Func formatter) - { - if (logger.IsEnabled(LogLevel.Error)) - { - logger.Log(LogLevel.Error, 0, state, exception, (s, e) => formatter((TState)s, e)); - } - } - - public static void LogVerbose(this ILogger logger, int eventId, TState state) - => logger.LogVerbose(eventId, state, s => s != null ? s.ToString() : null); - - public static void LogVerbose( - this ILogger logger, TState state, Func formatter) - { - if (logger.IsEnabled(LogLevel.Verbose)) - { - logger.Log(LogLevel.Verbose, 0, state, null, (s, _) => formatter((TState)s)); - } - } - - public static void LogVerbose( - this ILogger logger, int eventId, TState state, Func formatter) - { - if (logger.IsEnabled(LogLevel.Verbose)) - { - logger.Log(LogLevel.Verbose, eventId, state, null, (s, _) => formatter((TState)s)); - } - } - - public static void LogDebug(this ILogger logger, Func formatter) - => logger.LogDebug(0, default(object), _ => formatter()); - - public static void LogDebug(this ILogger logger, TState state, Func formatter) - => logger.LogDebug(0, state, formatter); - - public static void LogDebug(this ILogger logger, int eventId, Func formatter) - => logger.LogDebug(eventId, default(object), _ => formatter()); - - public static void LogDebug( - this ILogger logger, int eventId, TState state, Func formatter) - { - if (logger.IsEnabled(LogLevel.Debug)) - { - logger.Log(LogLevel.Debug, eventId, state, null, (s, _) => formatter((TState)s)); - } - } } } diff --git a/test/EntityFramework.Core.Tests/DbContextTest.cs b/test/EntityFramework.Core.Tests/DbContextTest.cs index 572f5af30a2..e4f7950ef69 100644 --- a/test/EntityFramework.Core.Tests/DbContextTest.cs +++ b/test/EntityFramework.Core.Tests/DbContextTest.cs @@ -1765,9 +1765,9 @@ public void Can_start_with_custom_services_by_passing_in_base_service_provider() .AddSingleton() .AddSingleton() .AddSingleton() - .AddSingleton() .AddScoped() .AddScoped() + .AddLogging() .AddInstance(factory); var provider = serviceCollection.BuildServiceProvider(); diff --git a/test/EntityFramework.Core.Tests/Infrastructure/LoggingModelValidatorTest.cs b/test/EntityFramework.Core.Tests/Infrastructure/LoggingModelValidatorTest.cs index 200febd0b59..ab8a9e30bad 100644 --- a/test/EntityFramework.Core.Tests/Infrastructure/LoggingModelValidatorTest.cs +++ b/test/EntityFramework.Core.Tests/Infrastructure/LoggingModelValidatorTest.cs @@ -33,6 +33,7 @@ protected override void VerifyError(string expectedMessage, IModel model) protected override ModelValidator CreateModelValidator() => new LoggingModelValidator( - new Logger(new ListLoggerFactory(Log, l => l == typeof(LoggingModelValidator).FullName))); + new Logger( + new ListLoggerFactory(Log, l => l == typeof(LoggingModelValidator).FullName))); } } diff --git a/test/EntityFramework.Core.Tests/Infrastructure/NonThrowingModelValidatorTest.cs b/test/EntityFramework.Core.Tests/Infrastructure/NonThrowingModelValidatorTest.cs index 416dbdcd124..92915c6ec96 100644 --- a/test/EntityFramework.Core.Tests/Infrastructure/NonThrowingModelValidatorTest.cs +++ b/test/EntityFramework.Core.Tests/Infrastructure/NonThrowingModelValidatorTest.cs @@ -15,11 +15,12 @@ public class NonThrowingModelValidatorTest : LoggingModelValidatorTest protected override ModelValidator CreateModelValidator() => new NonThrowingModelValidator( - new Logger(new ListLoggerFactory(Log, l => l == typeof(LoggingModelValidator).FullName))); + new Logger( + new ListLoggerFactory(Log, l => l == typeof(NonThrowingModelValidator).FullName))); private class NonThrowingModelValidator : LoggingModelValidator { - public NonThrowingModelValidator([NotNull] ILogger logger) // TODO: Fix covariance: Logging#253 + public NonThrowingModelValidator([NotNull] ILogger logger) : base(logger) { } diff --git a/test/EntityFramework.Core.Tests/ModelSourceTest.cs b/test/EntityFramework.Core.Tests/ModelSourceTest.cs index 378fbfe4515..8eae1473011 100644 --- a/test/EntityFramework.Core.Tests/ModelSourceTest.cs +++ b/test/EntityFramework.Core.Tests/ModelSourceTest.cs @@ -59,7 +59,6 @@ public void Caches_model_by_context_type() { var modelSource = CreateDefaultModelSource(new DbSetFinder()); - // TODO: Fix covariance: Logging#253 var model1 = modelSource.GetModel(new Context1(), null, new LoggingModelValidator(new Logger(new LoggerFactory()))); var model2 = modelSource.GetModel(new Context2(), null, @@ -77,7 +76,6 @@ public void Stores_model_version_information_as_annotation_on_model() { var modelSource = CreateDefaultModelSource(new DbSetFinder()); - // TODO: Fix covariance: Logging#253 var model = modelSource.GetModel(new Context1(), null, new LoggingModelValidator(new Logger(new LoggerFactory()))); diff --git a/test/EntityFramework.Relational.FunctionalTests/TestSqlLoggerFactory.cs b/test/EntityFramework.Relational.FunctionalTests/TestSqlLoggerFactory.cs index df9af30b378..a9e3d0ffdab 100644 --- a/test/EntityFramework.Relational.FunctionalTests/TestSqlLoggerFactory.cs +++ b/test/EntityFramework.Relational.FunctionalTests/TestSqlLoggerFactory.cs @@ -3,9 +3,12 @@ using System; using System.Collections.Generic; +using System.Globalization; +using System.Linq; using System.Threading; using Microsoft.Data.Entity.Infrastructure; using Microsoft.Data.Entity.Internal; +using Microsoft.Data.Entity.Storage; using Microsoft.Framework.Logging; using Xunit.Abstractions; #if !DNXCORE50 @@ -37,7 +40,7 @@ public CancellationToken CancelQuery() return Logger.SqlLoggerData._cancellationTokenSource.Token; } - public static void Reset() => Logger.Reset(); + public static void Reset() => Logger.ResetLoggerData(); public static void CaptureOutput(ITestOutputHelper testOutputHelper) => Logger.SqlLoggerData._testOutputHelper = testOutputHelper; @@ -49,7 +52,7 @@ public void Dispose() public static string Log => Logger.SqlLoggerData._log.ToString(); public static string Sql - => string.Join(Environment.NewLine + Environment.NewLine, Logger.SqlLoggerData._sqlStatements); + => string.Join("\r\n\r\n", Logger.SqlLoggerData._sqlStatements); public static List SqlStatements => Logger.SqlLoggerData._sqlStatements; @@ -110,16 +113,32 @@ public void Log( { var sqlLoggerData = SqlLoggerData; - if (eventId == RelationalLoggingEventIds.ExecutingSql) + if (sqlLoggerData._cancellationTokenSource != null) { - if (sqlLoggerData._cancellationTokenSource != null) + sqlLoggerData._cancellationTokenSource.Cancel(); + sqlLoggerData._cancellationTokenSource = null; + } + + var commandLogData = state as DbCommandLogData; + + if (commandLogData != null) + { + var parameters = ""; + + if (commandLogData.Parameters.Any()) { - sqlLoggerData._cancellationTokenSource.Cancel(); - sqlLoggerData._cancellationTokenSource = null; + parameters + = string.Join( + "\r\n", + commandLogData.Parameters + .Select(kv => kv.Key + ": " + + Convert.ToString(kv.Value, CultureInfo.InvariantCulture))) + + "\r\n\r\n"; } - sqlLoggerData._sqlStatements.Add(format); + sqlLoggerData._sqlStatements.Add(parameters + commandLogData.CommandText); } + else { sqlLoggerData._log.AppendLine(format); @@ -133,14 +152,14 @@ public void Log( public IDisposable BeginScopeImpl(object state) => SqlLoggerData._log.Indent(); - public void Reset() - { + // ReSharper disable once MemberCanBeMadeStatic.Local + public void ResetLoggerData() + => #if DNXCORE50 - _loggerData.Value = null; + _loggerData.Value = null; #else - CallContext.LogicalSetData(ContextName, null); + CallContext.LogicalSetData(ContextName, null); #endif - } } } } diff --git a/test/EntityFramework.Relational.Tests/RelationalModelValidatorTest.cs b/test/EntityFramework.Relational.Tests/RelationalModelValidatorTest.cs index c91f20a8f09..483856c9a6a 100644 --- a/test/EntityFramework.Relational.Tests/RelationalModelValidatorTest.cs +++ b/test/EntityFramework.Relational.Tests/RelationalModelValidatorTest.cs @@ -154,7 +154,8 @@ protected class Generic : Abstract protected override ModelValidator CreateModelValidator() => new RelationalModelValidator( - new Logger(new ListLoggerFactory(Log, l => l == typeof(LoggingModelValidator).FullName)), + new Logger( + new ListLoggerFactory(Log, l => l == typeof(RelationalModelValidator).FullName)), new TestAnnotationProvider()); } } diff --git a/test/EntityFramework.Relational.Tests/Update/BatchExecutorTest.cs b/test/EntityFramework.Relational.Tests/Update/BatchExecutorTest.cs index b8ebefa72ee..ba4af07827a 100644 --- a/test/EntityFramework.Relational.Tests/Update/BatchExecutorTest.cs +++ b/test/EntityFramework.Relational.Tests/Update/BatchExecutorTest.cs @@ -36,9 +36,10 @@ public async Task ExecuteAsync_calls_Commit_if_no_transaction() mockRelationalConnection.Verify(rc => rc.OpenAsync(cancellationToken)); mockRelationalConnection.Verify(rc => rc.Close()); transactionMock.Verify(t => t.Commit()); + mockModificationCommandBatch.Verify(mcb => mcb.ExecuteAsync( It.IsAny(), - null, + It.IsAny(), cancellationToken)); } @@ -64,18 +65,16 @@ public async Task ExecuteAsync_does_not_call_Commit_if_existing_transaction() transactionMock.Verify(t => t.Commit(), Times.Never); mockModificationCommandBatch.Verify(mcb => mcb.ExecuteAsync( It.IsAny(), - null, + It.IsAny(), cancellationToken)); } private class BatchExecutorForTest : BatchExecutor { public BatchExecutorForTest() - : base(new LoggerFactory()) + : base(new Logger(new LoggerFactory())) { } - - protected override ILogger Logger => null; } } } diff --git a/test/EntityFramework.SqlServer.FunctionalTests/DataAnnotationSqlServerFixture.cs b/test/EntityFramework.SqlServer.FunctionalTests/DataAnnotationSqlServerFixture.cs index d2f3ca5bbfc..2ca4dff26d7 100644 --- a/test/EntityFramework.SqlServer.FunctionalTests/DataAnnotationSqlServerFixture.cs +++ b/test/EntityFramework.SqlServer.FunctionalTests/DataAnnotationSqlServerFixture.cs @@ -51,7 +51,7 @@ public override SqlServerTestStore CreateTestStore() public override DataAnnotationContext CreateContext(SqlServerTestStore testStore) { var optionsBuilder = new DbContextOptionsBuilder(); - optionsBuilder.UseSqlServer(testStore.Connection); + optionsBuilder.UseSqlServer(testStore.Connection).LogSqlParameterValues(); var context = new DataAnnotationContext(_serviceProvider, optionsBuilder.Options); context.Database.UseTransaction(testStore.Transaction); diff --git a/test/EntityFramework.SqlServer.FunctionalTests/DataAnnotationSqlServerTest.cs b/test/EntityFramework.SqlServer.FunctionalTests/DataAnnotationSqlServerTest.cs index 3439c21f8f0..1d4f641ec40 100644 --- a/test/EntityFramework.SqlServer.FunctionalTests/DataAnnotationSqlServerTest.cs +++ b/test/EntityFramework.SqlServer.FunctionalTests/DataAnnotationSqlServerTest.cs @@ -97,7 +97,7 @@ INSERT INTO [BookDetail] ([BookId]) OUTPUT INSERTED.[Id] VALUES (@p0); -@p0: +@p0: SET NOCOUNT OFF; INSERT INTO [BookDetail] ([BookId]) diff --git a/test/EntityFramework.SqlServer.FunctionalTests/GearsOfWarQuerySqlServerFixture.cs b/test/EntityFramework.SqlServer.FunctionalTests/GearsOfWarQuerySqlServerFixture.cs index b98de19ac3e..bfa8e780e5f 100644 --- a/test/EntityFramework.SqlServer.FunctionalTests/GearsOfWarQuerySqlServerFixture.cs +++ b/test/EntityFramework.SqlServer.FunctionalTests/GearsOfWarQuerySqlServerFixture.cs @@ -52,10 +52,15 @@ public override SqlServerTestStore CreateTestStore() public override GearsOfWarContext CreateContext(SqlServerTestStore testStore) { var optionsBuilder = new DbContextOptionsBuilder(); - optionsBuilder.UseSqlServer(testStore.Connection); + + optionsBuilder + .UseSqlServer(testStore.Connection) + .LogSqlParameterValues(); var context = new GearsOfWarContext(_serviceProvider, optionsBuilder.Options); + context.Database.UseTransaction(testStore.Transaction); + return context; } } diff --git a/test/EntityFramework.SqlServer.FunctionalTests/InheritanceSqlServerFixture.cs b/test/EntityFramework.SqlServer.FunctionalTests/InheritanceSqlServerFixture.cs index 571444cf05a..d83ba64a4ec 100644 --- a/test/EntityFramework.SqlServer.FunctionalTests/InheritanceSqlServerFixture.cs +++ b/test/EntityFramework.SqlServer.FunctionalTests/InheritanceSqlServerFixture.cs @@ -29,7 +29,11 @@ public InheritanceSqlServerFixture() var testStore = SqlServerTestStore.CreateScratch(); var optionsBuilder = new DbContextOptionsBuilder(); - optionsBuilder.UseSqlServer(testStore.Connection); + + optionsBuilder + .UseSqlServer(testStore.Connection) + .LogSqlParameterValues(); + _options = optionsBuilder.Options; // TODO: Do this via migrations diff --git a/test/EntityFramework.SqlServer.FunctionalTests/NorthwindQuerySqlServerFixture.cs b/test/EntityFramework.SqlServer.FunctionalTests/NorthwindQuerySqlServerFixture.cs index 6885bb2fb71..99059770d46 100644 --- a/test/EntityFramework.SqlServer.FunctionalTests/NorthwindQuerySqlServerFixture.cs +++ b/test/EntityFramework.SqlServer.FunctionalTests/NorthwindQuerySqlServerFixture.cs @@ -32,8 +32,6 @@ public NorthwindQuerySqlServerFixture() .BuildServiceProvider(); _options = BuildOptions(); - - _serviceProvider.GetRequiredService().MinimumLevel = LogLevel.Debug; } protected DbContextOptions BuildOptions() @@ -43,6 +41,8 @@ protected DbContextOptions BuildOptions() var sqlServerDbContextOptionsBuilder = optionsBuilder.UseSqlServer(_testStore.Connection.ConnectionString); + sqlServerDbContextOptionsBuilder.LogSqlParameterValues(); + ConfigureOptions(sqlServerDbContextOptionsBuilder); sqlServerDbContextOptionsBuilder.ApplyConfiguration(); diff --git a/test/EntityFramework.SqlServer.FunctionalTests/NorthwindSprocQuerySqlServerFixture.cs b/test/EntityFramework.SqlServer.FunctionalTests/NorthwindSprocQuerySqlServerFixture.cs index 77066e6bd78..970d7949ad0 100644 --- a/test/EntityFramework.SqlServer.FunctionalTests/NorthwindSprocQuerySqlServerFixture.cs +++ b/test/EntityFramework.SqlServer.FunctionalTests/NorthwindSprocQuerySqlServerFixture.cs @@ -30,7 +30,11 @@ public NorthwindSprocQuerySqlServerFixture() .BuildServiceProvider(); var optionsBuilder = new DbContextOptionsBuilder(); - optionsBuilder.UseSqlServer(_testStore.Connection.ConnectionString); + + optionsBuilder + .UseSqlServer(_testStore.Connection.ConnectionString) + .LogSqlParameterValues(); + _options = optionsBuilder.Options; _serviceProvider.GetRequiredService() diff --git a/test/EntityFramework.SqlServer.FunctionalTests/NullSemanticsQuerySqlServerFixture.cs b/test/EntityFramework.SqlServer.FunctionalTests/NullSemanticsQuerySqlServerFixture.cs index a98246e2ed4..9999bd73aad 100644 --- a/test/EntityFramework.SqlServer.FunctionalTests/NullSemanticsQuerySqlServerFixture.cs +++ b/test/EntityFramework.SqlServer.FunctionalTests/NullSemanticsQuerySqlServerFixture.cs @@ -56,6 +56,8 @@ public override NullSemanticsContext CreateContext(SqlServerTestStore testStore, var sqlServerOptions = optionsBuilder.UseSqlServer(testStore.Connection); + sqlServerOptions.LogSqlParameterValues(); + if (useRelationalNulls) { sqlServerOptions.UseRelationalNulls(); diff --git a/test/EntityFramework.SqlServer.FunctionalTests/QueryBugsTest.cs b/test/EntityFramework.SqlServer.FunctionalTests/QueryBugsTest.cs index 4ba9f2ca4e8..39679a0e357 100644 --- a/test/EntityFramework.SqlServer.FunctionalTests/QueryBugsTest.cs +++ b/test/EntityFramework.SqlServer.FunctionalTests/QueryBugsTest.cs @@ -259,7 +259,9 @@ public MyContext925(IServiceProvider serviceProvider) public DbSet Orders { get; set; } protected override void OnConfiguring(DbContextOptionsBuilder optionsBuilder) - => optionsBuilder.UseSqlServer(SqlServerTestStore.CreateConnectionString("Repro925")); + => optionsBuilder + .UseSqlServer(SqlServerTestStore.CreateConnectionString("Repro925")) + .LogSqlParameterValues(); protected override void OnModelCreating(ModelBuilder modelBuilder) { diff --git a/test/EntityFramework.SqlServer.FunctionalTests/QueryLoggingSqlServerTest.cs b/test/EntityFramework.SqlServer.FunctionalTests/QueryLoggingSqlServerTest.cs index 3854c0dcef7..bc0db8f431c 100644 --- a/test/EntityFramework.SqlServer.FunctionalTests/QueryLoggingSqlServerTest.cs +++ b/test/EntityFramework.SqlServer.FunctionalTests/QueryLoggingSqlServerTest.cs @@ -5,7 +5,6 @@ using Microsoft.Data.Entity.FunctionalTests; using Microsoft.Data.Entity.FunctionalTests.TestModels.Northwind; using Microsoft.Data.Entity.Internal; -using Microsoft.Framework.Logging; using Xunit; #if DNXCORE50 @@ -27,8 +26,7 @@ var customers Assert.NotNull(customers); Assert.StartsWith( - @"Debug level logging is enabled. At this level, Entity Framework will log sensitive application data such as SQL parameter values. To hide this information configure ILoggerFactory.MinimumLevel to LogLevel.Verbose - Compiling query model: 'value(Microsoft.Data.Entity.Query.EntityQueryable`1[Microsoft.Data.Entity.FunctionalTests.TestModels.Northwind.Customer])' + @" Compiling query model: 'value(Microsoft.Data.Entity.Query.EntityQueryable`1[Microsoft.Data.Entity.FunctionalTests.TestModels.Northwind.Customer])' Optimized query model: 'value(Microsoft.Data.Entity.Query.EntityQueryable`1[Microsoft.Data.Entity.FunctionalTests.TestModels.Northwind.Customer])' Tracking query sources: [_0] TRACKED: True @@ -44,7 +42,7 @@ var customers SELECT [c].[CustomerID], [c].[Address], [c].[City], [c].[CompanyName], [c].[ContactName], [c].[ContactTitle], [c].[Country], [c].[Fax], [c].[Phone], [c].[PostalCode], [c].[Region] FROM [Customers] AS [c] , - logger: SqlLogger, + logger: SensitiveDataLogger`1, shaper: (ValueBuffer prm2) => QueryResultScope CreateEntity( querySource: from Customer _0 in value(EntityQueryable`1[FunctionalTests.TestModels.Northwind.Customer]), queryContext: prm0, @@ -81,36 +79,26 @@ var var4 selector: (QueryResultScope prm1) => Customer prm1._GetResult( querySource: from Customer _0 in value(EntityQueryable`1[FunctionalTests.TestModels.Northwind.Customer]) ) -)", +)", TestSqlLoggerFactory.Log); } } [Fact] - public virtual void Queryable_with_parameter() + public virtual void Queryable_with_parameter_outputs_parameter_value_logging_warning() { using (var context = CreateContext()) { - var cities = new[] { "Seattle", "Redmond" }; + // ReSharper disable once ConvertToConstant.Local + var city = "Redmond"; - foreach (var city in cities) - { - var customers - = context.Customers.Where(c => c.City == city).ToList(); - } - Assert.Contains(CoreStrings.DebugLogWarning(nameof(LogLevel.Debug), nameof(ILoggerFactory) + "." + nameof(ILoggerFactory.MinimumLevel), nameof(LogLevel) + "." + nameof(LogLevel.Verbose)), TestSqlLoggerFactory.Log); - Assert.Equal(@"@__city_0: Seattle - -SELECT [c].[CustomerID], [c].[Address], [c].[City], [c].[CompanyName], [c].[ContactName], [c].[ContactTitle], [c].[Country], [c].[Fax], [c].[Phone], [c].[PostalCode], [c].[Region] -FROM [Customers] AS [c] -WHERE [c].[City] = @__city_0 - -@__city_0: Redmond + var customers + = context.Customers + .Where(c => c.City == city) + .ToList(); -SELECT [c].[CustomerID], [c].[Address], [c].[City], [c].[CompanyName], [c].[ContactName], [c].[ContactTitle], [c].[Country], [c].[Fax], [c].[Phone], [c].[PostalCode], [c].[Region] -FROM [Customers] AS [c] -WHERE [c].[City] = @__city_0", - TestSqlLoggerFactory.Sql); + Assert.NotNull(customers); + Assert.Contains(RelationalStrings.ParameterLoggingEnabled, TestSqlLoggerFactory.Log); } } @@ -125,8 +113,7 @@ var customers .ToList(); Assert.NotNull(customers); - Assert.StartsWith(@"Debug level logging is enabled. At this level, Entity Framework will log sensitive application data such as SQL parameter values. To hide this information configure ILoggerFactory.MinimumLevel to LogLevel.Verbose - Compiling query model: 'value(Microsoft.Data.Entity.Query.EntityQueryable`1[Microsoft.Data.Entity.FunctionalTests.TestModels.Northwind.Customer]) => AnnotateQuery(Include([c].Orders))' + Assert.StartsWith(@" Compiling query model: 'value(Microsoft.Data.Entity.Query.EntityQueryable`1[Microsoft.Data.Entity.FunctionalTests.TestModels.Northwind.Customer]) => AnnotateQuery(Include([c].Orders))' Optimized query model: 'value(Microsoft.Data.Entity.Query.EntityQueryable`1[Microsoft.Data.Entity.FunctionalTests.TestModels.Northwind.Customer])' Including navigation: 'Microsoft.Data.Entity.FunctionalTests.TestModels.Northwind.Customer.Orders' Tracking query sources: [c] @@ -146,7 +133,7 @@ var customers FROM [Customers] AS [c] ORDER BY [c].[CustomerID] , - logger: SqlLogger, + logger: SensitiveDataLogger`1, shaper: (ValueBuffer prm2) => QueryResultScope CreateEntity( querySource: from Customer c in value(EntityQueryable`1[FunctionalTests.TestModels.Northwind.Customer]), queryContext: prm0, @@ -193,7 +180,7 @@ FROM [Customers] AS [c] ) AS [c] ON [o].[CustomerID] = [c].[CustomerID] ORDER BY [c].[CustomerID] , - logger: SqlLogger, + logger: SensitiveDataLogger`1, queryIndex: 1 ) , @@ -217,8 +204,8 @@ var var6 selector: (QueryResultScope prm1) => Customer prm1._GetResult( querySource: from Customer c in value(EntityQueryable`1[FunctionalTests.TestModels.Northwind.Customer]) ) -)", - TestSqlLoggerFactory.Log); +)", + TestSqlLoggerFactory.Log); } } diff --git a/test/EntityFramework.SqlServer.FunctionalTests/SqlServerEndToEndTest.cs b/test/EntityFramework.SqlServer.FunctionalTests/SqlServerEndToEndTest.cs index 93576230526..519d0a4233c 100644 --- a/test/EntityFramework.SqlServer.FunctionalTests/SqlServerEndToEndTest.cs +++ b/test/EntityFramework.SqlServer.FunctionalTests/SqlServerEndToEndTest.cs @@ -111,7 +111,10 @@ public async Task Can_save_changes() using (var testDatabase = await SqlServerTestStore.CreateScratchAsync()) { var optionsBuilder = new DbContextOptionsBuilder(); - optionsBuilder.UseSqlServer(testDatabase.Connection.ConnectionString); + + optionsBuilder + .UseSqlServer(testDatabase.Connection.ConnectionString) + .LogSqlParameterValues(); using (var db = new BloggingContext(_fixture.ServiceProvider, optionsBuilder.Options)) { @@ -160,13 +163,13 @@ public async Task Can_save_changes() Assert.Equal(EntityState.Unchanged, db.Entry(toAdd).State); Assert.DoesNotContain(toDelete, db.ChangeTracker.Entries().Select(e => e.Entity)); - Assert.Equal(4, TestSqlLoggerFactory.SqlStatements.Count); + Assert.Equal(3, TestSqlLoggerFactory.SqlStatements.Count); Assert.Contains("SELECT", TestSqlLoggerFactory.SqlStatements[0]); Assert.Contains("SELECT", TestSqlLoggerFactory.SqlStatements[1]); Assert.Contains("@p0: " + deletedId, TestSqlLoggerFactory.SqlStatements[2]); - Assert.Contains("DELETE", TestSqlLoggerFactory.SqlStatements[3]); - Assert.Contains("UPDATE", TestSqlLoggerFactory.SqlStatements[3]); - Assert.Contains("INSERT", TestSqlLoggerFactory.SqlStatements[3]); + Assert.Contains("DELETE", TestSqlLoggerFactory.SqlStatements[2]); + Assert.Contains("UPDATE", TestSqlLoggerFactory.SqlStatements[2]); + Assert.Contains("INSERT", TestSqlLoggerFactory.SqlStatements[2]); var rows = await testDatabase.ExecuteScalarAsync( $@"SELECT Count(*) FROM [dbo].[Blog] WHERE Id = {updatedId} AND Name = 'Blog is Updated'", diff --git a/test/EntityFramework.SqlServer.Tests/SqlServerDatabaseCreatorTest.cs b/test/EntityFramework.SqlServer.Tests/SqlServerDatabaseCreatorTest.cs index 08d5427427b..c2ce89303a6 100644 --- a/test/EntityFramework.SqlServer.Tests/SqlServerDatabaseCreatorTest.cs +++ b/test/EntityFramework.SqlServer.Tests/SqlServerDatabaseCreatorTest.cs @@ -157,7 +157,7 @@ private class FakeSqlStatementExecutor : SqlStatementExecutor { public FakeSqlStatementExecutor( IRelationalCommandBuilderFactory commandBuilderFactory, - ILogger logger) + ILogger logger) : base(commandBuilderFactory, logger) { } diff --git a/test/EntityFramework.Sqlite.FunctionalTests/DataAnnotationSqliteFixture.cs b/test/EntityFramework.Sqlite.FunctionalTests/DataAnnotationSqliteFixture.cs index 20486e5f1bc..07a5b145442 100644 --- a/test/EntityFramework.Sqlite.FunctionalTests/DataAnnotationSqliteFixture.cs +++ b/test/EntityFramework.Sqlite.FunctionalTests/DataAnnotationSqliteFixture.cs @@ -51,7 +51,10 @@ public override SqliteTestStore CreateTestStore() public override DataAnnotationContext CreateContext(SqliteTestStore testStore) { var optionsBuilder = new DbContextOptionsBuilder(); - optionsBuilder.UseSqlite(testStore.Connection); + + optionsBuilder + .UseSqlite(testStore.Connection) + .LogSqlParameterValues(); var context = new DataAnnotationContext(_serviceProvider, optionsBuilder.Options); context.Database.UseTransaction(testStore.Transaction); diff --git a/test/EntityFramework.Sqlite.FunctionalTests/DataAnnotationSqliteTest.cs b/test/EntityFramework.Sqlite.FunctionalTests/DataAnnotationSqliteTest.cs index 296da4a09ed..f41c1d8e447 100644 --- a/test/EntityFramework.Sqlite.FunctionalTests/DataAnnotationSqliteTest.cs +++ b/test/EntityFramework.Sqlite.FunctionalTests/DataAnnotationSqliteTest.cs @@ -85,7 +85,7 @@ public override void RequiredAttribute_for_navigation_throws_while_inserting_nul FROM ""BookDetail"" WHERE changes() = 1 AND ""Id"" = last_insert_rowid(); -@p0: +@p0: INSERT INTO ""BookDetail"" (""BookId"") VALUES (@p0);