Skip to content

Commit 0373f57

Browse files
anpeteanpete
committed
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
1 parent 01f82b3 commit 0373f57

File tree

55 files changed

+495
-338
lines changed

Some content is hidden

Large Commits have some content hidden by default. Use the searchbox below for content that may be hidden.

55 files changed

+495
-338
lines changed

‎src/EntityFramework.Core/DbContext.cs‎

Lines changed: 13 additions & 12 deletions
Original file line numberDiff line numberDiff line change
@@ -9,6 +9,7 @@
99
using JetBrains.Annotations;
1010
using Microsoft.Data.Entity.ChangeTracking;
1111
using Microsoft.Data.Entity.ChangeTracking.Internal;
12+
using Microsoft.Data.Entity.Extensions.Internal;
1213
using Microsoft.Data.Entity.Infrastructure;
1314
using Microsoft.Data.Entity.Internal;
1415
using Microsoft.Data.Entity.Metadata;
@@ -191,14 +192,14 @@ private IDbContextServices InitializeServices(IServiceProvider serviceProvider,
191192
_initializing = true;
192193

193194
var optionsBuilder = new DbContextOptionsBuilder(options);
195+
194196
OnConfiguring(optionsBuilder);
195197

196198
var providerSource = serviceProvider != null ? ServiceProviderSource.Explicit : ServiceProviderSource.Implicit;
197199

198200
serviceProvider = serviceProvider ?? ServiceProviderCache.Instance.GetOrAdd(optionsBuilder.Options);
199201

200-
_logger = serviceProvider.GetRequiredService<ILoggerFactory>().CreateLogger<DbContext>();
201-
_logger.LogDebug(CoreStrings.DebugLogWarning(nameof(LogLevel.Debug), nameof(ILoggerFactory) + "." + nameof(ILoggerFactory.MinimumLevel), nameof(LogLevel) + "." + nameof(LogLevel.Verbose)));
202+
_logger = serviceProvider.GetRequiredService<ILogger<DbContext>>();
202203

203204
_serviceScope = serviceProvider
204205
.GetRequiredService<IServiceScopeFactory>()
@@ -304,13 +305,13 @@ public virtual int SaveChanges(bool acceptAllChangesOnSuccess)
304305
{
305306
return stateManager.SaveChanges(acceptAllChangesOnSuccess);
306307
}
307-
catch (Exception ex)
308+
catch (Exception exception)
308309
{
309310
_logger.LogError(
310-
new DatabaseErrorLogState(GetType()),
311-
ex,
312-
(state, exception) =>
313-
CoreStrings.LogExceptionDuringSaveChanges(Environment.NewLine, exception));
311+
CoreLoggingEventId.DatabaseError,
312+
() => new DatabaseErrorLogState(GetType()),
313+
exception,
314+
e => CoreStrings.LogExceptionDuringSaveChanges(Environment.NewLine, e));
314315

315316
throw;
316317
}
@@ -384,13 +385,13 @@ public virtual async Task<int> SaveChangesAsync(bool acceptAllChangesOnSuccess,
384385
{
385386
return await stateManager.SaveChangesAsync(acceptAllChangesOnSuccess, cancellationToken);
386387
}
387-
catch (Exception ex)
388+
catch (Exception exception)
388389
{
389390
_logger.LogError(
390-
new DatabaseErrorLogState(GetType()),
391-
ex,
392-
(state, exception) =>
393-
CoreStrings.LogExceptionDuringSaveChanges(Environment.NewLine, exception));
391+
CoreLoggingEventId.DatabaseError,
392+
() => new DatabaseErrorLogState(GetType()),
393+
exception,
394+
e => CoreStrings.LogExceptionDuringSaveChanges(Environment.NewLine, e));
394395

395396
throw;
396397
}

‎src/EntityFramework.Core/EntityFramework.Core.csproj‎

Lines changed: 2 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -66,13 +66,15 @@
6666
<Compile Include="ChangeTracking\Internal\ValueBufferSidecar.cs" />
6767
<Compile Include="DbUpdateConcurrencyException.cs" />
6868
<Compile Include="DbUpdateException.cs" />
69+
<Compile Include="Extensions\Internal\CoreLoggerExtensions.cs" />
6970
<Compile Include="Extensions\Internal\ExpressionExtensions.cs" />
7071
<Compile Include="Extensions\Internal\ListExtensions.cs" />
7172
<Compile Include="Extensions\Internal\PropertyInfoExtensions.cs" />
7273
<Compile Include="GraphBehavior.cs" />
7374
<Compile Include="Infrastructure\AccessorExtensions.cs" />
7475
<Compile Include="Infrastructure\DbContextAttribute.cs" />
7576
<Compile Include="Infrastructure\ModelSource.cs" />
77+
<Compile Include="Infrastructure\CoreLoggingEventId.cs" />
7678
<Compile Include="Internal\DatabaseProviderSelector.cs" />
7779
<Compile Include="Internal\EnumerableExtensions.cs" />
7880
<Compile Include="Internal\Graph.cs" />

‎src/EntityFramework.Core/Extensions/Internal/CoreLoggerExtensions.cs‎

Lines changed: 29 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,29 @@
1+
// Copyright (c) .NET Foundation. All rights reserved.
2+
// Licensed under the Apache License, Version 2.0. See License.txt in the project root for license information.
3+
4+
using System;
5+
using Microsoft.Data.Entity.Infrastructure;
6+
using Microsoft.Framework.Logging;
7+
8+
namespace Microsoft.Data.Entity.Extensions.Internal
9+
{
10+
internal static class CoreLoggerExtensions
11+
{
12+
public static void LogError<TState>(
13+
this ILogger logger, CoreLoggingEventId eventId, Func<TState> state, Exception exception, Func<Exception, string> formatter)
14+
{
15+
if (logger.IsEnabled(LogLevel.Error))
16+
{
17+
logger.Log(LogLevel.Error, (int)eventId, state(), exception, (_, e) => formatter(e));
18+
}
19+
}
20+
21+
public static void LogVerbose(this ILogger logger, CoreLoggingEventId eventId, Func<string> formatter)
22+
{
23+
if (logger.IsEnabled(LogLevel.Verbose))
24+
{
25+
logger.Log(LogLevel.Verbose, (int)eventId, null, null, (_, __) => formatter());
26+
}
27+
}
28+
}
29+
}

‎src/EntityFramework.Core/Infrastructure/CoreLoggingEventId.cs‎

Lines changed: 15 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,15 @@
1+
// Copyright (c) .NET Foundation. All rights reserved.
2+
// Licensed under the Apache License, Version 2.0. See License.txt in the project root for license information.
3+
4+
namespace Microsoft.Data.Entity.Infrastructure
5+
{
6+
public enum CoreLoggingEventId
7+
{
8+
DatabaseError = 1,
9+
CompilingQueryModel,
10+
OptimizedQueryModel,
11+
IncludingNavigation,
12+
TrackingQuerySources,
13+
QueryPlan
14+
}
15+
}

‎src/EntityFramework.Core/Properties/CoreStrings.resx‎

Lines changed: 0 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -462,9 +462,6 @@
462462
<data name="NavigationForWrongForeignKey" xml:space="preserve">
463463
<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>
464464
</data>
465-
<data name="DebugLogWarning" xml:space="preserve">
466-
<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>
467-
</data>
468465
<data name="WrongGenericPropertyType" xml:space="preserve">
469466
<value>Property '{property}' on entity type '{entityType}' is of type '{actualType}' but the generic type provided is of type '{genericType}'.</value>
470467
</data>

‎src/EntityFramework.Core/Query/AsyncLinqOperatorProvider.cs‎

Lines changed: 9 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -11,6 +11,8 @@
1111
using System.Threading;
1212
using System.Threading.Tasks;
1313
using JetBrains.Annotations;
14+
using Microsoft.Data.Entity.Extensions.Internal;
15+
using Microsoft.Data.Entity.Infrastructure;
1416
using Microsoft.Data.Entity.Internal;
1517
using Microsoft.Data.Entity.Storage;
1618
using Microsoft.Data.Entity.Utilities;
@@ -129,13 +131,14 @@ public async Task<bool> MoveNext(CancellationToken cancellationToken)
129131

130132
return await _inner.MoveNext(cancellationToken);
131133
}
132-
catch (Exception e)
134+
catch (Exception exception)
133135
{
134-
_exceptionInterceptor._logger.LogError(
135-
new DatabaseErrorLogState(_exceptionInterceptor._contextType),
136-
e,
137-
(state, exception) =>
138-
CoreStrings.LogExceptionDuringQueryIteration(Environment.NewLine, exception));
136+
_exceptionInterceptor._logger
137+
.LogError(
138+
CoreLoggingEventId.DatabaseError,
139+
() => new DatabaseErrorLogState(_exceptionInterceptor._contextType),
140+
exception,
141+
e => CoreStrings.LogExceptionDuringQueryIteration(Environment.NewLine, e));
139142

140143
throw;
141144
}

‎src/EntityFramework.Core/Query/EntityQueryModelVisitor.cs‎

Lines changed: 24 additions & 11 deletions
Original file line numberDiff line numberDiff line change
@@ -8,6 +8,8 @@
88
using System.Reflection;
99
using System.Threading.Tasks;
1010
using JetBrains.Annotations;
11+
using Microsoft.Data.Entity.Extensions.Internal;
12+
using Microsoft.Data.Entity.Infrastructure;
1113
using Microsoft.Data.Entity.Internal;
1214
using Microsoft.Data.Entity.Metadata;
1315
using Microsoft.Data.Entity.Metadata.Internal;
@@ -136,7 +138,10 @@ public virtual Func<QueryContext, IEnumerable<TResult>> CreateQueryExecutor<TRes
136138

137139
using (QueryCompilationContext.Logger.BeginScopeImpl(this))
138140
{
139-
QueryCompilationContext.Logger.LogDebug(queryModel, CoreStrings.LogCompilingQueryModel);
141+
QueryCompilationContext.Logger
142+
.LogVerbose(
143+
CoreLoggingEventId.CompilingQueryModel,
144+
() => CoreStrings.LogCompilingQueryModel(queryModel));
140145

141146
_blockTaskExpressions = false;
142147

@@ -166,7 +171,10 @@ public virtual Func<QueryContext, IAsyncEnumerable<TResult>> CreateAsyncQueryExe
166171

167172
using (QueryCompilationContext.Logger.BeginScopeImpl(this))
168173
{
169-
QueryCompilationContext.Logger.LogDebug(queryModel, CoreStrings.LogCompilingQueryModel);
174+
QueryCompilationContext.Logger
175+
.LogVerbose(
176+
CoreLoggingEventId.CompilingQueryModel,
177+
() => CoreStrings.LogCompilingQueryModel(queryModel));
170178

171179
_blockTaskExpressions = false;
172180

@@ -220,7 +228,10 @@ protected virtual void OptimizeQueryModel([NotNull] QueryModel queryModel)
220228

221229
queryModel.TransformExpressions(_subQueryMemberPushDownExpressionVisitor.Visit);
222230

223-
QueryCompilationContext.Logger.LogDebug(queryModel, CoreStrings.LogOptimizedQueryModel);
231+
QueryCompilationContext.Logger
232+
.LogVerbose(
233+
CoreLoggingEventId.OptimizedQueryModel,
234+
() => CoreStrings.LogOptimizedQueryModel(queryModel));
224235
}
225236

226237
protected virtual void SingleResultToSequence([NotNull] QueryModel queryModel)
@@ -333,9 +344,9 @@ var accessorLambda
333344
Expression.Parameter(queryModel.SelectClause.Selector.Type));
334345

335346
QueryCompilationContext.Logger
336-
.LogDebug(
337-
includeSpecification.NavigationPath.Join("."),
338-
CoreStrings.LogIncludingNavigation);
347+
.LogVerbose(
348+
CoreLoggingEventId.IncludingNavigation,
349+
() => CoreStrings.LogIncludingNavigation(includeSpecification.NavigationPath.Join(".")));
339350

340351
IncludeNavigations(
341352
includeSpecification,
@@ -404,10 +415,10 @@ var entityTrackingInfos
404415
if (entityTrackingInfos.Any())
405416
{
406417
QueryCompilationContext.Logger
407-
.LogDebug(
408-
entityTrackingInfos,
409-
etis => CoreStrings.LogTrackingQuerySources(
410-
etis.Select(eti => eti.QuerySource.ItemName).Join()));
418+
.LogVerbose(
419+
CoreLoggingEventId.TrackingQuerySources,
420+
() => CoreStrings.LogTrackingQuerySources(
421+
entityTrackingInfos.Select(eti => eti.QuerySource.ItemName).Join()));
411422

412423
var resultItemType
413424
= _expression.Type.GetSequenceType();
@@ -482,7 +493,9 @@ protected virtual Func<QueryContext, TResults> CreateExecutorLambda<TResults>()
482493
.Lambda<Func<QueryContext, QueryResultScope, TResults>>(
483494
_expression, QueryContextParameter, QueryResultScopeParameter);
484495

485-
QueryCompilationContext.Logger.LogDebug(() =>
496+
QueryCompilationContext.Logger.LogVerbose(
497+
CoreLoggingEventId.QueryPlan,
498+
() =>
486499
{
487500
var queryPlan = _expressionPrinter.Print(queryExecutorExpression);
488501

‎src/EntityFramework.Core/Query/Internal/QueryCompilationContextFactory.cs‎

Lines changed: 5 additions & 8 deletions
Original file line numberDiff line numberDiff line change
@@ -11,42 +11,39 @@ namespace Microsoft.Data.Entity.Query.Internal
1111
{
1212
public class QueryCompilationContextFactory : IQueryCompilationContextFactory
1313
{
14-
private readonly ILoggerFactory _loggerFactory;
1514
private readonly DbContext _context;
1615

1716
public QueryCompilationContextFactory(
18-
[NotNull] ILoggerFactory loggerFactory,
17+
[NotNull] ILogger<QueryCompilationContextFactory> logger,
1918
[NotNull] IEntityQueryModelVisitorFactory entityQueryModelVisitorFactory,
2019
[NotNull] IRequiresMaterializationExpressionVisitorFactory requiresMaterializationExpressionVisitorFactory,
2120
[NotNull] DbContext context)
2221
{
23-
Check.NotNull(loggerFactory, nameof(loggerFactory));
22+
Check.NotNull(logger, nameof(logger));
2423
Check.NotNull(entityQueryModelVisitorFactory, nameof(entityQueryModelVisitorFactory));
2524
Check.NotNull(requiresMaterializationExpressionVisitorFactory, nameof(requiresMaterializationExpressionVisitorFactory));
2625
Check.NotNull(context, nameof(context));
2726

28-
_loggerFactory = loggerFactory;
27+
Logger = logger;
2928

3029
EntityQueryModelVisitorFactory = entityQueryModelVisitorFactory;
3130
RequiresMaterializationExpressionVisitorFactory = requiresMaterializationExpressionVisitorFactory;
3231

3332
_context = context;
3433
}
3534

35+
protected virtual ILogger Logger { get; }
3636
protected virtual IEntityQueryModelVisitorFactory EntityQueryModelVisitorFactory { get; }
3737
protected virtual IRequiresMaterializationExpressionVisitorFactory RequiresMaterializationExpressionVisitorFactory { get; }
3838

3939
protected virtual Type ContextType => _context.GetType();
4040

4141
public virtual QueryCompilationContext Create(bool async)
4242
=> new QueryCompilationContext(
43-
CreateLogger(),
43+
Logger,
4444
EntityQueryModelVisitorFactory,
4545
RequiresMaterializationExpressionVisitorFactory,
4646
async ? (ILinqOperatorProvider)new AsyncLinqOperatorProvider() : new LinqOperatorProvider(),
4747
ContextType);
48-
49-
protected virtual ILogger CreateLogger()
50-
=> _loggerFactory.CreateLogger<QueryCompilationContext>();
5148
}
5249
}

‎src/EntityFramework.Core/Query/LinqOperatorProvider.cs‎

Lines changed: 9 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -9,6 +9,8 @@
99
using System.Linq.Expressions;
1010
using System.Reflection;
1111
using JetBrains.Annotations;
12+
using Microsoft.Data.Entity.Extensions.Internal;
13+
using Microsoft.Data.Entity.Infrastructure;
1214
using Microsoft.Data.Entity.Internal;
1315
using Microsoft.Data.Entity.Storage;
1416
using Microsoft.Data.Entity.Utilities;
@@ -121,13 +123,14 @@ public bool MoveNext()
121123

122124
return _inner.MoveNext();
123125
}
124-
catch (Exception e)
126+
catch (Exception exception)
125127
{
126-
_exceptionInterceptor._logger.LogError(
127-
new DatabaseErrorLogState(_exceptionInterceptor._contextType),
128-
e,
129-
(state, exception) =>
130-
CoreStrings.LogExceptionDuringQueryIteration(Environment.NewLine, exception));
128+
_exceptionInterceptor._logger
129+
.LogError(
130+
CoreLoggingEventId.DatabaseError,
131+
() => new DatabaseErrorLogState(_exceptionInterceptor._contextType),
132+
exception,
133+
e => CoreStrings.LogExceptionDuringQueryIteration(Environment.NewLine, e));
131134

132135
throw;
133136
}

‎src/EntityFramework.Core/Storage/DatabaseProviderServices.cs‎

Lines changed: 1 addition & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -34,8 +34,7 @@ protected DatabaseProviderServices([NotNull] IServiceProvider services)
3434
public virtual IConventionSetBuilder ConventionSetBuilder => null;
3535
public virtual IValueGeneratorSelector ValueGeneratorSelector => GetService<ValueGeneratorSelector>();
3636
public virtual IModelValidator ModelValidator => GetService<LoggingModelValidator>();
37-
public virtual ICompiledQueryCacheKeyGenerator CompiledQueryCacheKeyGenerator
38-
=> GetService<CompiledQueryCacheKeyGenerator>();
37+
public virtual ICompiledQueryCacheKeyGenerator CompiledQueryCacheKeyGenerator => GetService<CompiledQueryCacheKeyGenerator>();
3938
public virtual IExpressionPrinter ExpressionPrinter => GetService<ExpressionPrinter>();
4039
public virtual IResultOperatorHandler ResultOperatorHandler => GetService<ResultOperatorHandler>();
4140
public virtual IQueryCompilationContextFactory QueryCompilationContextFactory => GetService<QueryCompilationContextFactory>();

0 commit comments

Comments
 (0)