Logging Query Parameters

Using the new 'debug' level in logging, this adds the ability to EF to log query parameters

src/EntityFramework.Core/DbContext.cs

@@ -47,9 +47,10 @@ public class DbContext : IDisposable, IAccessor<IServiceProvider>
         private static readonly ThreadSafeDictionaryCache<Type, Type> _optionsTypes = new ThreadSafeDictionaryCache<Type, Type>();
 
         private LazyRef<IDbContextServices> _contextServices;
-        private LazyRef<ILogger> _logger;
         private LazyRef<IDbSetInitializer> _setInitializer;
         private LazyRef<Database> _database;
+        private ILogger _logger;
+        private ILoggerFactory _loggerFactory;
 
         private bool _initializing;
 
@@ -143,7 +144,6 @@ private void Initialize(IServiceProvider serviceProvider, DbContextOptions optio
         {
             InitializeSets(serviceProvider, options);
             _contextServices = new LazyRef<IDbContextServices>(() => InitializeServices(serviceProvider, options));
-            _logger = new LazyRef<ILogger>(CreateLogger);
             _setInitializer = new LazyRef<IDbSetInitializer>(GetSetInitializer);
             _database = new LazyRef<Database>(GetDatabase);
         }
@@ -169,7 +169,7 @@ private DbContextOptions GetOptions(IServiceProvider serviceProvider)
             return options ?? new DbContextOptions<DbContext>();
         }
 
-        private ILogger CreateLogger() => _contextServices.Value.ServiceProvider.GetRequiredService<ILoggerFactory>().CreateLogger<DbContext>();
+        private ILogger CreateLogger() => _loggerFactory.CreateLogger<DbContext>();
 
         private IDbSetInitializer GetSetInitializer() => _contextServices.Value.ServiceProvider.GetRequiredService<IDbSetInitializer>();
 
@@ -206,6 +206,10 @@ private IDbContextServices InitializeServices(IServiceProvider serviceProvider,
 
                 serviceProvider = serviceProvider ?? ServiceProviderCache.Instance.GetOrAdd(optionsBuilder.Options);
 
+                _loggerFactory = serviceProvider.GetRequiredService<ILoggerFactory>();
+                _logger = _loggerFactory.CreateLogger<DbContext>();
+                _logger.LogDebug(Strings.DebugLogWarning(nameof(LogLevel.Debug), nameof(ILoggerFactory) + "." + nameof(ILoggerFactory.MinimumLevel), nameof(LogLevel) + "." + nameof(LogLevel.Verbose)));
+
                 var scopedServiceProvider = serviceProvider
                     .GetRequiredService<IServiceScopeFactory>()
                     .CreateScope()
@@ -296,7 +300,7 @@ public virtual int SaveChanges()
             }
             catch (Exception ex)
             {
-                _logger.Value.LogError(
+                _logger.LogError(
                     new DataStoreErrorLogState(GetType()),
                     ex,
                     (state, exception) =>
@@ -348,7 +352,7 @@ private void TryDetectChanges(IStateManager stateManager)
             }
             catch (Exception ex)
             {
-                _logger.Value.LogError(
+                _logger.LogError(
                     new DataStoreErrorLogState(GetType()),
                     ex,
                     (state, exception) =>

src/EntityFramework.Core/Properties/Strings.resx

@@ -468,6 +468,9 @@
   <data name="NavigationToSelfDuplicate" xml:space="preserve">
     <value>The navigation property '{navigation}' cannot be used for both ends of the relationship. Either specify it on the principal side or the dependent side.</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 '{propertyName}' on entity type '{entityType}' is of type '{actualType}' but the generic type provided is of type '{genericType}'.</value>
   </data>

src/EntityFramework.Relational/Query/AsyncQueryingEnumerable.cs

@@ -81,7 +81,7 @@ await _enumerable._relationalQueryContext.Connection
                             _enumerable._relationalQueryContext.Connection,
                             _enumerable._relationalQueryContext.ParameterValues))
                 {
-                    _enumerable._logger.WriteSql(command.CommandText);
+                    _enumerable._logger.LogCommand(command);
 
                     _reader = await command.ExecuteReaderAsync(cancellationToken).WithCurrentCulture();
                 }

src/EntityFramework.Relational/Query/QueryingEnumerable.cs

@@ -69,7 +69,7 @@ public bool MoveNext()
                                 _enumerable._relationalQueryContext.Connection,
                                 _enumerable._relationalQueryContext.ParameterValues))
                     {
-                        _enumerable._logger.WriteSql(command.CommandText);
+                        _enumerable._logger.LogCommand(command);
 
                         _reader = command.ExecuteReader();
                     }

src/EntityFramework.Relational/RelationalLoggerExtensions.cs

@@ -1,7 +1,10 @@
 // Copyright (c) Microsoft Open Technologies, Inc. All rights reserved.
 // 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.Text;
 using JetBrains.Annotations;
 using Microsoft.Data.Entity.Relational;
 using Microsoft.Data.Entity.Utilities;
@@ -12,14 +15,45 @@ namespace Microsoft.Framework.Logging
 {
     internal static class RelationalLoggerExtensions
     {
-        public static void WriteSql([NotNull] this ILogger logger, [NotNull] string sql)
+        public static void LogSql([NotNull] this ILogger logger, [NotNull] string sql)
         {
             Check.NotNull(logger, nameof(logger));
             Check.NotEmpty(sql, nameof(sql));
 
             logger.LogVerbose(RelationalLoggingEventIds.Sql, sql);
         }
 
+        public static void LogParameters([NotNull] this ILogger logger, [NotNull] DbParameterCollection parameters)
+        {
+            if (parameters.Count == 0)
+            {
+                return;
+            }
+            StringBuilder paramList = new StringBuilder();
+
+            paramList.AppendFormat("{0}: {1}", (parameters[0]).ParameterName, (parameters[0]).Value);
+            for (int i = 1; i < parameters.Count; i++)
+            {
+                paramList.AppendLine();
+                paramList.AppendFormat("{0}: {1}", (parameters[i]).ParameterName, (parameters[i]).Value);
+            }
+            logger.LogDebug(RelationalLoggingEventIds.Sql, paramList.ToString());
+        }
+
+        public static void LogCommand([NotNull] this ILogger logger, [NotNull] DbCommand command)
+        {
+            Check.NotNull(logger, nameof(logger));
+            Check.NotNull(command, nameof(command));
+
+            var scope = Guid.NewGuid();
+
+            using (logger.BeginScope(scope))
+            {
+                logger.LogParameters(command.Parameters);
+                logger.LogSql(command.CommandText);
+            }
+        }
+
         public static void CreatingDatabase([NotNull] this ILogger logger, [NotNull] string databaseName)
         {
             Check.NotNull(logger, nameof(logger));

src/EntityFramework.Relational/SqlStatementExecutor.cs

@@ -41,9 +41,10 @@ public virtual Task ExecuteNonQueryAsync(
                     {
                         foreach (var sqlBatch in sqlBatches)
                         {
-                            Logger.WriteSql(sqlBatch.Sql);
+                            var command = CreateCommand(connection, transaction, sqlBatch.Sql);
+                            Logger.LogCommand(command);
 
-                            await CreateCommand(connection, transaction, sqlBatch.Sql).ExecuteNonQueryAsync(cancellationToken)
+                            await command.ExecuteNonQueryAsync(cancellationToken)
                                 .WithCurrentCulture();
                         }
                         return Task.FromResult<object>(null);
@@ -64,9 +65,10 @@ public virtual Task<object> ExecuteScalarAsync(
                 connection,
                 () =>
                     {
-                        Logger.WriteSql(sql);
+                        var command = CreateCommand(connection, transaction, sql);
+                        Logger.LogCommand(command);
 
-                        return CreateCommand(connection, transaction, sql).ExecuteScalarAsync(cancellationToken);
+                        return command.ExecuteScalarAsync(cancellationToken);
                     },
                 cancellationToken);
         }
@@ -117,9 +119,10 @@ public virtual void ExecuteNonQuery(
                     {
                         foreach (var sqlBatch in sqlBatches)
                         {
-                            Logger.WriteSql(sqlBatch.Sql);
+                            var command = CreateCommand(connection, transaction, sqlBatch.Sql);
+                            Logger.LogCommand(command);
 
-                            CreateCommand(connection, transaction, sqlBatch.Sql).ExecuteNonQuery();
+                            command.ExecuteNonQuery();
                         }
                         return null;
                     });
@@ -137,9 +140,10 @@ public virtual object ExecuteScalar(
                 connection,
                 () =>
                     {
-                        Logger.WriteSql(sql);
+                        var command = CreateCommand(connection, transaction, sql);
+                        Logger.LogCommand(command);
 
-                        return CreateCommand(connection, transaction, sql).ExecuteScalar();
+                        return command.ExecuteScalar();
                     });
         }
 

src/EntityFramework.Relational/Update/ReaderModificationCommandBatch.cs

@@ -158,17 +158,17 @@ public override int Execute(
             Check.NotNull(logger, nameof(logger));
 
             var commandText = GetCommandText();
-            if (logger.IsEnabled(LogLevel.Verbose))
-            {
-                // TODO: Write parameter values
-                logger.WriteSql(commandText);
-            }
 
             Debug.Assert(ResultSetEnds.Count == ModificationCommands.Count);
 
             var commandIndex = 0;
             using (var storeCommand = CreateStoreCommand(commandText, transaction.DbTransaction, typeMapper, transaction.Connection?.CommandTimeout))
             {
+                if (logger.IsEnabled(LogLevel.Verbose))
+                {
+                    logger.LogCommand(storeCommand);
+                }
+
                 try
                 {
                     using (var reader = storeCommand.ExecuteReader())
@@ -223,17 +223,17 @@ public override async Task<int> ExecuteAsync(
             Check.NotNull(logger, nameof(logger));
 
             var commandText = GetCommandText();
-            if (logger.IsEnabled(LogLevel.Verbose))
-            {
-                // TODO: Write parameter values
-                logger.WriteSql(commandText);
-            }
 
             Debug.Assert(ResultSetEnds.Count == ModificationCommands.Count);
 
             var commandIndex = 0;
             using (var storeCommand = CreateStoreCommand(commandText, transaction.DbTransaction, typeMapper, transaction.Connection?.CommandTimeout))
             {
+                if (logger.IsEnabled(LogLevel.Verbose))
+                {
+                    logger.LogCommand(storeCommand);
+                }
+
                 try
                 {
                     using (var reader = await storeCommand.ExecuteReaderAsync(cancellationToken).WithCurrentCulture())

test/EntityFramework.Core.Tests/DbContextTest.cs

@@ -1657,6 +1657,7 @@ public void Can_start_with_custom_services_by_passing_in_base_service_provider()
                 .AddSingleton<IMemberMapper, MemberMapper>()
                 .AddSingleton<IFieldMatcher, FieldMatcher>()
                 .AddSingleton<DataStoreSelector>()
+                .AddSingleton<ILoggerFactory, LoggerFactory>()
                 .AddScoped<IDbSetInitializer, DbSetInitializer>()
                 .AddScoped<IDbContextServices, DbContextServices>()
                 .AddInstance(factory);

test/EntityFramework.SqlServer.FunctionalTests/FromSqlQuerySqlServerTest.cs

@@ -53,12 +53,16 @@ public override void From_sql_queryable_where_simple_closure_via_query_cache()
             base.From_sql_queryable_where_simple_closure_via_query_cache();
 
             Assert.Equal(
-                @"SELECT [c].[Address], [c].[City], [c].[CompanyName], [c].[ContactName], [c].[ContactTitle], [c].[Country], [c].[CustomerID], [c].[Fax], [c].[Phone], [c].[PostalCode], [c].[Region]
+                @"__title_0: Sales Associate
+
+SELECT [c].[Address], [c].[City], [c].[CompanyName], [c].[ContactName], [c].[ContactTitle], [c].[Country], [c].[CustomerID], [c].[Fax], [c].[Phone], [c].[PostalCode], [c].[Region]
 FROM (
     SELECT * FROM Customers WHERE Customers.ContactName LIKE '%o%'
 ) AS [c]
 WHERE [c].[ContactTitle] = @__title_0
 
+__title_0: Sales Manager
+
 SELECT [c].[Address], [c].[City], [c].[CompanyName], [c].[ContactName], [c].[ContactTitle], [c].[Country], [c].[CustomerID], [c].[Fax], [c].[Phone], [c].[PostalCode], [c].[Region]
 FROM (
     SELECT * FROM Customers WHERE Customers.ContactName LIKE '%o%'
@@ -86,7 +90,10 @@ public override void From_sql_queryable_with_params_parameters()
             base.From_sql_queryable_with_params_parameters();
 
             Assert.Equal(
-                @"SELECT [c].[Address], [c].[City], [c].[CompanyName], [c].[ContactName], [c].[ContactTitle], [c].[Country], [c].[CustomerID], [c].[Fax], [c].[Phone], [c].[PostalCode], [c].[Region]
+                @"p0: London
+p1: Sales Representative
+
+SELECT [c].[Address], [c].[City], [c].[CompanyName], [c].[ContactName], [c].[ContactTitle], [c].[Country], [c].[CustomerID], [c].[Fax], [c].[Phone], [c].[PostalCode], [c].[Region]
 FROM (
     SELECT * FROM Customers WHERE City = @p0 AND ContactTitle = @p1
 ) AS [c]",
@@ -98,11 +105,17 @@ public override void From_sql_queryable_with_params_parameters_does_not_collide_
             base.From_sql_queryable_with_params_parameters_does_not_collide_with_cache();
 
             Assert.Equal(
-                @"SELECT [c].[Address], [c].[City], [c].[CompanyName], [c].[ContactName], [c].[ContactTitle], [c].[Country], [c].[CustomerID], [c].[Fax], [c].[Phone], [c].[PostalCode], [c].[Region]
+                @"p0: London
+p1: Sales Representative
+
+SELECT [c].[Address], [c].[City], [c].[CompanyName], [c].[ContactName], [c].[ContactTitle], [c].[Country], [c].[CustomerID], [c].[Fax], [c].[Phone], [c].[PostalCode], [c].[Region]
 FROM (
     SELECT * FROM Customers WHERE City = @p0 AND ContactTitle = @p1
 ) AS [c]
 
+p0: Madrid
+p1: Accounting Manager
+
 SELECT [c].[Address], [c].[City], [c].[CompanyName], [c].[ContactName], [c].[ContactTitle], [c].[Country], [c].[CustomerID], [c].[Fax], [c].[Phone], [c].[PostalCode], [c].[Region]
 FROM (
     SELECT * FROM Customers WHERE City = @p0 AND ContactTitle = @p1

test/EntityFramework.SqlServer.FunctionalTests/NorthwindQuerySqlServerFixture.cs

@@ -33,6 +33,9 @@ public NorthwindQuerySqlServerFixture()
             var optionsBuilder = new DbContextOptionsBuilder();
             optionsBuilder.UseSqlServer(_testStore.Connection.ConnectionString);
             _options = optionsBuilder.Options;
+
+            _serviceProvider.GetRequiredService<ILoggerFactory>()
+                .MinimumLevel = LogLevel.Debug;
         }
 
         public override NorthwindContext CreateContext()

test/EntityFramework.SqlServer.FunctionalTests/PropertyEntrySqlServerTest.cs

@@ -17,15 +17,17 @@ public override void Property_entry_original_value_is_set()
         {
             base.Property_entry_original_value_is_set();
 
-            Assert.Equal(
+            Assert.Contains(
                 @"SELECT TOP(1) [e].[EngineSupplierId], [e].[Id], [e].[Name]
-FROM [Engines] AS [e]
+FROM [Engines] AS [e]", 
+                Sql);
 
-SET NOCOUNT OFF;
+            Assert.Contains(
+                @"SET NOCOUNT OFF;
 UPDATE [Engines] SET [Name] = @p2
 WHERE [EngineSupplierId] = @p0 AND [Id] = @p1 AND [Name] = @p3;
-SELECT @@ROWCOUNT;
-", Sql);
+SELECT @@ROWCOUNT;", 
+                Sql);
         }
 
         private static string Sql