Logging: All-up logging improvements:

- New DbContextOption "LogSqlParameterValues()" replacing use of Debug log level to control sensitive data logging. - Use a wrapping ILogger<T> 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
dotnet · Oct 1, 2015 · e93783b · e93783b
1 parent 8b50592
commit e93783b
Show file tree

Hide file tree

Showing 54 changed files with 493 additions and 337 deletions.
diff --git 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<ILoggerFactory>().CreateLogger<DbContext>();
-                _logger.LogDebug(CoreStrings.DebugLogWarning(nameof(LogLevel.Debug), nameof(ILoggerFactory) + "." + nameof(ILoggerFactory.MinimumLevel), nameof(LogLevel) + "." + nameof(LogLevel.Verbose)));
+                _logger = serviceProvider.GetRequiredService<ILogger<DbContext>>();
 
                 _serviceScope = serviceProvider
                     .GetRequiredService<IServiceScopeFactory>()
@@ -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<int> 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
@@ -66,13 +66,15 @@
     <Compile Include="ChangeTracking\Internal\ValueBufferSidecar.cs" />
     <Compile Include="DbUpdateConcurrencyException.cs" />
     <Compile Include="DbUpdateException.cs" />
+    <Compile Include="Extensions\Internal\CoreLoggerExtensions.cs" />
     <Compile Include="Extensions\Internal\ExpressionExtensions.cs" />
     <Compile Include="Extensions\Internal\ListExtensions.cs" />
     <Compile Include="Extensions\Internal\PropertyInfoExtensions.cs" />
     <Compile Include="GraphBehavior.cs" />
     <Compile Include="Infrastructure\AccessorExtensions.cs" />
     <Compile Include="Infrastructure\DbContextAttribute.cs" />
     <Compile Include="Infrastructure\ModelSource.cs" />
+    <Compile Include="Infrastructure\CoreLoggingEventId.cs" />
     <Compile Include="Internal\DatabaseProviderSelector.cs" />
     <Compile Include="Internal\EnumerableExtensions.cs" />
     <Compile Include="Internal\Graph.cs" />

diff --git a/src/EntityFramework.Core/Extensions/Internal/CoreLoggerExtensions.cs 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<TState>(
+            this ILogger logger, CoreLoggingEventId eventId, Func<TState> state, Exception exception, Func<Exception, string> 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<string> 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
@@ -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
@@ -462,9 +462,6 @@
   <data name="NavigationForWrongForeignKey" xml:space="preserve">
     <value>The navigation for property '{navigation}' on entity type '{entityType}' cannot be associated with foreign key {targetFk} because it was created for foreign key {actualFk}.</value>
   </data>
-  <data name="DebugLogWarning" xml:space="preserve">
-    <value>{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}</value>
-  </data>
   <data name="WrongGenericPropertyType" xml:space="preserve">
     <value>Property '{property}' on entity type '{entityType}' is of type '{actualType}' but the generic type provided is of type '{genericType}'.</value>
   </data>

diff --git 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<bool> 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
@@ -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<QueryContext, IEnumerable<TResult>> CreateQueryExecutor<TRes
 
             using (QueryCompilationContext.Logger.BeginScopeImpl(this))
             {
-                QueryCompilationContext.Logger.LogDebug(queryModel, CoreStrings.LogCompilingQueryModel);
+                QueryCompilationContext.Logger
+                    .LogVerbose(
+                        CoreLoggingEventId.CompilingQueryModel,
+                        () => CoreStrings.LogCompilingQueryModel(queryModel));
 
                 _blockTaskExpressions = false;
 
@@ -166,7 +171,10 @@ public virtual Func<QueryContext, IAsyncEnumerable<TResult>> 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<QueryContext, TResults> CreateExecutorLambda<TResults>()
                     .Lambda<Func<QueryContext, QueryResultScope, TResults>>(
                         _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
@@ -11,42 +11,39 @@ 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<QueryCompilationContextFactory> 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;
 
             _context = context;
         }
 
+        protected virtual ILogger Logger { get; }
         protected virtual IEntityQueryModelVisitorFactory EntityQueryModelVisitorFactory { get; }
         protected virtual IRequiresMaterializationExpressionVisitorFactory RequiresMaterializationExpressionVisitorFactory { get; }
 
         protected virtual Type ContextType => _context.GetType();
 
         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<QueryCompilationContext>();
     }
 }
diff --git 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
@@ -34,8 +34,7 @@ protected DatabaseProviderServices([NotNull] IServiceProvider services)
         public virtual IConventionSetBuilder ConventionSetBuilder => null;
         public virtual IValueGeneratorSelector ValueGeneratorSelector => GetService<ValueGeneratorSelector>();
         public virtual IModelValidator ModelValidator => GetService<LoggingModelValidator>();
-        public virtual ICompiledQueryCacheKeyGenerator CompiledQueryCacheKeyGenerator
-            => GetService<CompiledQueryCacheKeyGenerator>();
+        public virtual ICompiledQueryCacheKeyGenerator CompiledQueryCacheKeyGenerator => GetService<CompiledQueryCacheKeyGenerator>();
         public virtual IExpressionPrinter ExpressionPrinter => GetService<ExpressionPrinter>();
         public virtual IResultOperatorHandler ResultOperatorHandler => GetService<ResultOperatorHandler>();
         public virtual IQueryCompilationContextFactory QueryCompilationContextFactory => GetService<QueryCompilationContextFactory>();

diff --git a/src/EntityFramework.InMemory/EntityFramework.InMemory.csproj b/src/EntityFramework.InMemory/EntityFramework.InMemory.csproj
@@ -45,8 +45,10 @@
     <Compile Include="..\Shared\LoggingExtensions.cs">
       <Link>Utilities\LoggingExtensions.cs</Link>
     </Compile>
+    <Compile Include="Extensions\Internal\InMemoryLoggerExtensions.cs" />
     <Compile Include="Infrastructure\Internal\InMemoryModelSource.cs" />
     <Compile Include="Infrastructure\Internal\InMemoryOptionsExtension.cs" />
+    <Compile Include="Infrastructure\InMemoryLoggingEventId.cs" />
     <Compile Include="Metadata\Internal\EntityTypeNameEqualityComparer.cs" />
     <Compile Include="Query\ExpressionVisitors\Internal\InMemoryEntityQueryableExpressionVisitor.cs" />
     <Compile Include="Query\ExpressionVisitors\Internal\InMemoryEntityQueryableExpressionVisitorFactory.cs" />

diff --git a/src/EntityFramework.InMemory/Extensions/Internal/InMemoryLoggerExtensions.cs 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<TState>(
+            this ILogger logger, InMemoryLoggingEventId eventId, TState state, Func<TState, string> 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
@@ -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
+    }
+}