DatabaseTarget - Added support for DbCommand Properties (#3839)

snakefoot · web-flow · commit 21d8239c5063 · 2020-03-15T23:26:46.000+01:00
diff --git a/src/NLog/Targets/DatabaseObjectPropertyInfo.cs b/src/NLog/Targets/DatabaseObjectPropertyInfo.cs
@@ -91,9 +91,9 @@ public DatabaseObjectPropertyInfo()
         [DefaultValue(null)]
         public CultureInfo Culture { get; set; }
 
-        internal bool SetPropertyValue(IDbConnection dbConnection, object propertyValue)
+        internal bool SetPropertyValue(object dbObject, object propertyValue)
         {
-            var dbConnectionType = dbConnection.GetType();
+            var dbConnectionType = dbObject.GetType();
             var propertySetterCache = _propertySetter;
             if (!propertySetterCache.Equals(Name, dbConnectionType))
             {
@@ -102,7 +102,7 @@ internal bool SetPropertyValue(IDbConnection dbConnection, object propertyValue)
                 _propertySetter = propertySetterCache;
             }
 
-            return propertySetterCache.PropertySetter?.SetPropertyValue(dbConnection, propertyValue) ?? false;
+            return propertySetterCache.PropertySetter?.SetPropertyValue(dbObject, propertyValue) ?? false;
         }
 
         private struct PropertySetterCacheItem
diff --git a/src/NLog/Targets/DatabaseTarget.cs b/src/NLog/Targets/DatabaseTarget.cs
@@ -280,6 +280,14 @@ public Layout DBPassword
         [ArrayParameter(typeof(DatabaseObjectPropertyInfo), "connectionproperty")]
         public IList<DatabaseObjectPropertyInfo> ConnectionProperties { get; } = new List<DatabaseObjectPropertyInfo>();
 
+        /// <summary>
+        /// Gets the collection of properties. Each item contains a mapping
+        /// between NLog layout and a property on the DbCommand instance
+        /// </summary>
+        /// <docgen category='Connection Options' order='10' />
+        [ArrayParameter(typeof(DatabaseObjectPropertyInfo), "commandproperty")]
+        public IList<DatabaseObjectPropertyInfo> CommandProperties { get; } = new List<DatabaseObjectPropertyInfo>();
+
         /// <summary>
         /// Configures isolated transaction batch writing. If supported by the database, then it will improve insert performance.
         /// </summary>
@@ -358,29 +366,29 @@ internal IDbConnection OpenConnection(string connectionString, LogEventInfo logE
             connection.ConnectionString = connectionString;
             if (ConnectionProperties?.Count > 0)
             {
-                ApplyConnectionProperties(connection, logEventInfo ?? LogEventInfo.CreateNullEvent());
+                ApplyDatabaseObjectProperties(connection, ConnectionProperties, logEventInfo ?? LogEventInfo.CreateNullEvent());
             }
 
             connection.Open();
             return connection;
         }
 
-        private void ApplyConnectionProperties(IDbConnection connection, LogEventInfo logEventInfo)
+        private void ApplyDatabaseObjectProperties(object databaseObject, IList<DatabaseObjectPropertyInfo> objectProperties, LogEventInfo logEventInfo)
         {
-            for (int i = 0; i < ConnectionProperties.Count; ++i)
+            for (int i = 0; i < objectProperties.Count; ++i)
             {
-                var propertyInfo = ConnectionProperties[i];
+                var propertyInfo = objectProperties[i];
                 try
                 {
-                    var propertyValue = GetDatabaseConnectionValue(logEventInfo, propertyInfo);
-                    if (!propertyInfo.SetPropertyValue(connection, propertyValue))
+                    var propertyValue = GetDatabaseObjectPropertyValue(logEventInfo, propertyInfo);
+                    if (!propertyInfo.SetPropertyValue(databaseObject, propertyValue))
                     {
-                        InternalLogger.Warn("DatabaseTarget(Name={0}): Failed to lookup property {1} on {2}", Name, propertyInfo.Name, connection.GetType());
+                        InternalLogger.Warn("DatabaseTarget(Name={0}): Failed to lookup property {1} on {2}", Name, propertyInfo.Name, databaseObject.GetType());
                     }
                 }
                 catch (Exception ex)
                 {
-                    InternalLogger.Error(ex, "DatabaseTarget(Name={0}): Failed to assign value for property {1} on {2}", Name, propertyInfo.Name, connection.GetType());
+                    InternalLogger.Error(ex, "DatabaseTarget(Name={0}): Failed to assign value for property {1} on {2}", Name, propertyInfo.Name, databaseObject.GetType());
                     if (ex.MustBeRethrown())
                         throw;
                 }
@@ -699,7 +707,7 @@ private void WriteLogEventBatchToDatabase(IList<AsyncLogEventInfo> logEvents, st
                     {
                         for (int i = 0; i < logEvents.Count; ++i)
                         {
-                            ExecuteDbCommandWithParameters(logEvents[i].LogEvent, dbTransaction);
+                            ExecuteDbCommandWithParameters(logEvents[i].LogEvent, _activeConnection, dbTransaction);
                         }
 
                         dbTransaction?.Commit();
@@ -767,7 +775,7 @@ private void WriteLogEventToDatabase(LogEventInfo logEvent, string connectionStr
                 {
                     EnsureConnectionOpen(connectionString, logEvent);
 
-                    ExecuteDbCommandWithParameters(logEvent, null);
+                    ExecuteDbCommandWithParameters(logEvent, _activeConnection, null);
 
                     transactionScope.Complete();    //not really needed as there is no transaction at all.
                 }
@@ -790,12 +798,9 @@ private void WriteLogEventToDatabase(LogEventInfo logEvent, string connectionStr
         /// <summary>
         /// Write logEvent to database
         /// </summary>
-        private void ExecuteDbCommandWithParameters(LogEventInfo logEvent, IDbTransaction dbTransaction)
+        private void ExecuteDbCommandWithParameters(LogEventInfo logEvent, IDbConnection dbConnection, IDbTransaction dbTransaction)
         {
-            var commandText = RenderLogEvent(CommandText, logEvent);
-            InternalLogger.Trace("DatabaseTarget(Name={0}): Executing {1}: {2}", Name, CommandType, commandText);
-
-            using (IDbCommand command = CreateDbCommandWithParameters(logEvent, CommandType, commandText, Parameters))
+            using (IDbCommand command = CreateDbCommand(logEvent, dbConnection))
             {
                 if (dbTransaction != null)
                     command.Transaction = dbTransaction;
@@ -805,11 +810,22 @@ private void ExecuteDbCommandWithParameters(LogEventInfo logEvent, IDbTransactio
             }
         }
 
+        internal IDbCommand CreateDbCommand(LogEventInfo logEvent, IDbConnection dbConnection)
+        {
+            var commandText = RenderLogEvent(CommandText, logEvent);
+            InternalLogger.Trace("DatabaseTarget(Name={0}): Executing {1}: {2}", Name, CommandType, commandText);
+            return CreateDbCommandWithParameters(logEvent, dbConnection, CommandType, commandText, Parameters);
+        }
+
         [System.Diagnostics.CodeAnalysis.SuppressMessage("Microsoft.Security", "CA2100:Review SQL queries for security vulnerabilities", Justification = "It's up to the user to ensure proper quoting.")]
-        private IDbCommand CreateDbCommandWithParameters(LogEventInfo logEvent, CommandType commandType, string dbCommandText, IList<DatabaseParameterInfo> databaseParameterInfos)
+        private IDbCommand CreateDbCommandWithParameters(LogEventInfo logEvent, IDbConnection dbConnection, CommandType commandType, string dbCommandText, IList<DatabaseParameterInfo> databaseParameterInfos)
         {
-            var dbCommand = _activeConnection.CreateCommand();
+            var dbCommand = dbConnection.CreateCommand();
             dbCommand.CommandType = commandType;
+            if (CommandProperties?.Count > 0)
+            {
+                ApplyDatabaseObjectProperties(dbCommand, CommandProperties, logEvent);
+            }
             dbCommand.CommandText = dbCommandText;
 
             for (int i = 0; i < databaseParameterInfos.Count; ++i)
@@ -965,7 +981,7 @@ private void RunInstallCommands(InstallationContext installationContext, IEnumer
 
                     installationContext.Trace("DatabaseTarget(Name={0}) - Executing {1} '{2}'", Name, commandInfo.CommandType, commandText);
 
-                    using (IDbCommand command = CreateDbCommandWithParameters(logEvent, commandInfo.CommandType, commandText, commandInfo.Parameters))
+                    using (IDbCommand command = CreateDbCommandWithParameters(logEvent, _activeConnection, commandInfo.CommandType, commandText, commandInfo.Parameters))
                     {
                         try
                         {
@@ -1081,7 +1097,7 @@ protected internal virtual object GetDatabaseParameterValue(LogEventInfo logEven
             return RenderObjectValue(logEvent, parameterInfo.Name, parameterInfo.Layout, parameterInfo.ParameterType, parameterInfo.Format, parameterInfo.Culture);
         }
 
-        private object GetDatabaseConnectionValue(LogEventInfo logEvent, DatabaseObjectPropertyInfo connectionInfo)
+        private object GetDatabaseObjectPropertyValue(LogEventInfo logEvent, DatabaseObjectPropertyInfo connectionInfo)
         {
             return RenderObjectValue(logEvent, connectionInfo.Name, connectionInfo.Layout, connectionInfo.PropertyType, connectionInfo.Format, connectionInfo.Culture);
         }
@@ -1163,7 +1179,7 @@ private static object CreateDefaultValue(Type dbParameterType)
         /// 
         /// Transactions aren't in .NET Core: https://github.com/dotnet/corefx/issues/2949
         /// </summary>
-        private class TransactionScope : IDisposable
+        private sealed class TransactionScope : IDisposable
         {
             private readonly TransactionScopeOption suppress;
 
diff --git a/tests/NLog.UnitTests/Targets/DatabaseTargetTests.cs b/tests/NLog.UnitTests/Targets/DatabaseTargetTests.cs
@@ -1203,6 +1203,32 @@ public void AccessTokenWithInvalidTypeCannotBeSet()
             Assert.Throws<FormatException>(() => databaseTarget.OpenConnection(".", null));
         }
 
+        [Fact]
+        public void CommandTimeoutShouldBeSet()
+        {
+            // Arrange
+            var commandTimeout = "123";
+            MockDbConnection.ClearLog();
+            var databaseTarget = new DatabaseTarget
+            {
+                DBProvider = typeof(MockDbConnection).AssemblyQualifiedName,
+                CommandText = "command1",
+            };
+            databaseTarget.CommandProperties.Add(new DatabaseObjectPropertyInfo() { Name = "CommandTimeout", Layout = commandTimeout, PropertyType = typeof(int) });
+            databaseTarget.Initialize(new LoggingConfiguration());
+
+            // Act
+            var connection = databaseTarget.OpenConnection(".", null);
+            var command1 = databaseTarget.CreateDbCommand(LogEventInfo.CreateNullEvent(), connection);
+            var command2 = databaseTarget.CreateDbCommand(LogEventInfo.CreateNullEvent(), connection);    // Twice because we use compiled method on 2nd attempt
+
+            // Assert
+            var sqlCommand1 = Assert.IsType<MockDbCommand>(command1);
+            Assert.Equal(commandTimeout, sqlCommand1.CommandTimeout.ToString());  // Verify dynamic setter method invoke assigns correctly
+            var sqlCommand2 = Assert.IsType<MockDbCommand>(command2);
+            Assert.Equal(commandTimeout, sqlCommand2.CommandTimeout.ToString());  // Verify compiled method also assigns correctly
+        }
+
         [Fact]
         public void SqlServerShorthandNotationTest()
         {

Original file line number	Diff line number	Diff line change
`@@ -91,9 +91,9 @@ public DatabaseObjectPropertyInfo()`
`91`	`91`	`[DefaultValue(null)]`
`92`	`92`	`public CultureInfo Culture { get; set; }`
`93`	`93`
`94`		`- internal bool SetPropertyValue(IDbConnection dbConnection, object propertyValue)`
	`94`	`+ internal bool SetPropertyValue(object dbObject, object propertyValue)`
`95`	`95`	`{`
`96`		`- var dbConnectionType = dbConnection.GetType();`
	`96`	`+ var dbConnectionType = dbObject.GetType();`
`97`	`97`	`var propertySetterCache = _propertySetter;`
`98`	`98`	`if (!propertySetterCache.Equals(Name, dbConnectionType))`
`99`	`99`	`{`
`@@ -102,7 +102,7 @@ internal bool SetPropertyValue(IDbConnection dbConnection, object propertyValue)`
`102`	`102`	`_propertySetter = propertySetterCache;`
`103`	`103`	`}`
`104`	`104`
`105`		`- return propertySetterCache.PropertySetter?.SetPropertyValue(dbConnection, propertyValue) ?? false;`
	`105`	`+ return propertySetterCache.PropertySetter?.SetPropertyValue(dbObject, propertyValue) ?? false;`
`106`	`106`	`}`
`107`	`107`
`108`	`108`	`private struct PropertySetterCacheItem`
Original file line number	Diff line number	Diff line change
`@@ -280,6 +280,14 @@ public Layout DBPassword`
`280`	`280`	`[ArrayParameter(typeof(DatabaseObjectPropertyInfo), "connectionproperty")]`
`281`	`281`	`public IList<DatabaseObjectPropertyInfo> ConnectionProperties { get; } = new List<DatabaseObjectPropertyInfo>();`
`282`	`282`
	`283`	`+ /// <summary>`
	`284`	`+ /// Gets the collection of properties. Each item contains a mapping`
	`285`	`+ /// between NLog layout and a property on the DbCommand instance`
	`286`	`+ /// </summary>`
	`287`	`+ /// <docgen category='Connection Options' order='10' />`
	`288`	`+ [ArrayParameter(typeof(DatabaseObjectPropertyInfo), "commandproperty")]`
	`289`	`+ public IList<DatabaseObjectPropertyInfo> CommandProperties { get; } = new List<DatabaseObjectPropertyInfo>();`
	`290`	`+`
`283`	`291`	`/// <summary>`
`284`	`292`	`/// Configures isolated transaction batch writing. If supported by the database, then it will improve insert performance.`
`285`	`293`	`/// </summary>`
`@@ -358,29 +366,29 @@ internal IDbConnection OpenConnection(string connectionString, LogEventInfo logE`
`358`	`366`	`connection.ConnectionString = connectionString;`
`359`	`367`	`if (ConnectionProperties?.Count > 0)`
`360`	`368`	`{`
`361`		`- ApplyConnectionProperties(connection, logEventInfo ?? LogEventInfo.CreateNullEvent());`
	`369`	`+ ApplyDatabaseObjectProperties(connection, ConnectionProperties, logEventInfo ?? LogEventInfo.CreateNullEvent());`
`362`	`370`	`}`
`363`	`371`
`364`	`372`	`connection.Open();`
`365`	`373`	`return connection;`
`366`	`374`	`}`
`367`	`375`
`368`		`- private void ApplyConnectionProperties(IDbConnection connection, LogEventInfo logEventInfo)`
	`376`	`+ private void ApplyDatabaseObjectProperties(object databaseObject, IList<DatabaseObjectPropertyInfo> objectProperties, LogEventInfo logEventInfo)`
`369`	`377`	`{`
`370`		`- for (int i = 0; i < ConnectionProperties.Count; ++i)`
	`378`	`+ for (int i = 0; i < objectProperties.Count; ++i)`
`371`	`379`	`{`
`372`		`- var propertyInfo = ConnectionProperties[i];`
	`380`	`+ var propertyInfo = objectProperties[i];`
`373`	`381`	`try`
`374`	`382`	`{`
`375`		`- var propertyValue = GetDatabaseConnectionValue(logEventInfo, propertyInfo);`
`376`		`- if (!propertyInfo.SetPropertyValue(connection, propertyValue))`
	`383`	`+ var propertyValue = GetDatabaseObjectPropertyValue(logEventInfo, propertyInfo);`
	`384`	`+ if (!propertyInfo.SetPropertyValue(databaseObject, propertyValue))`
`377`	`385`	`{`
`378`		`- InternalLogger.Warn("DatabaseTarget(Name={0}): Failed to lookup property {1} on {2}", Name, propertyInfo.Name, connection.GetType());`
	`386`	`+ InternalLogger.Warn("DatabaseTarget(Name={0}): Failed to lookup property {1} on {2}", Name, propertyInfo.Name, databaseObject.GetType());`
`379`	`387`	`}`
`380`	`388`	`}`
`381`	`389`	`catch (Exception ex)`
`382`	`390`	`{`
`383`		`- InternalLogger.Error(ex, "DatabaseTarget(Name={0}): Failed to assign value for property {1} on {2}", Name, propertyInfo.Name, connection.GetType());`
	`391`	`+ InternalLogger.Error(ex, "DatabaseTarget(Name={0}): Failed to assign value for property {1} on {2}", Name, propertyInfo.Name, databaseObject.GetType());`
`384`	`392`	`if (ex.MustBeRethrown())`
`385`	`393`	`throw;`
`386`	`394`	`}`
`@@ -699,7 +707,7 @@ private void WriteLogEventBatchToDatabase(IList<AsyncLogEventInfo> logEvents, st`
`699`	`707`	`{`
`700`	`708`	`for (int i = 0; i < logEvents.Count; ++i)`
`701`	`709`	`{`
`702`		`- ExecuteDbCommandWithParameters(logEvents[i].LogEvent, dbTransaction);`
	`710`	`+ ExecuteDbCommandWithParameters(logEvents[i].LogEvent, _activeConnection, dbTransaction);`
`703`	`711`	`}`
`704`	`712`
`705`	`713`	`dbTransaction?.Commit();`
`@@ -767,7 +775,7 @@ private void WriteLogEventToDatabase(LogEventInfo logEvent, string connectionStr`
`767`	`775`	`{`
`768`	`776`	`EnsureConnectionOpen(connectionString, logEvent);`
`769`	`777`
`770`		`- ExecuteDbCommandWithParameters(logEvent, null);`
	`778`	`+ ExecuteDbCommandWithParameters(logEvent, _activeConnection, null);`
`771`	`779`
`772`	`780`	`transactionScope.Complete(); //not really needed as there is no transaction at all.`
`773`	`781`	`}`
`@@ -790,12 +798,9 @@ private void WriteLogEventToDatabase(LogEventInfo logEvent, string connectionStr`
`790`	`798`	`/// <summary>`
`791`	`799`	`/// Write logEvent to database`
`792`	`800`	`/// </summary>`
`793`		`- private void ExecuteDbCommandWithParameters(LogEventInfo logEvent, IDbTransaction dbTransaction)`
	`801`	`+ private void ExecuteDbCommandWithParameters(LogEventInfo logEvent, IDbConnection dbConnection, IDbTransaction dbTransaction)`
`794`	`802`	`{`
`795`		`- var commandText = RenderLogEvent(CommandText, logEvent);`
`796`		`- InternalLogger.Trace("DatabaseTarget(Name={0}): Executing {1}: {2}", Name, CommandType, commandText);`
`797`		`-`
`798`		`- using (IDbCommand command = CreateDbCommandWithParameters(logEvent, CommandType, commandText, Parameters))`
	`803`	`+ using (IDbCommand command = CreateDbCommand(logEvent, dbConnection))`
`799`	`804`	`{`
`800`	`805`	`if (dbTransaction != null)`
`801`	`806`	`command.Transaction = dbTransaction;`
`@@ -805,11 +810,22 @@ private void ExecuteDbCommandWithParameters(LogEventInfo logEvent, IDbTransactio`
`805`	`810`	`}`
`806`	`811`	`}`
`807`	`812`
	`813`	`+ internal IDbCommand CreateDbCommand(LogEventInfo logEvent, IDbConnection dbConnection)`
	`814`	`+ {`
	`815`	`+ var commandText = RenderLogEvent(CommandText, logEvent);`
	`816`	`+ InternalLogger.Trace("DatabaseTarget(Name={0}): Executing {1}: {2}", Name, CommandType, commandText);`
	`817`	`+ return CreateDbCommandWithParameters(logEvent, dbConnection, CommandType, commandText, Parameters);`
	`818`	`+ }`
	`819`	`+`
`808`	`820`	`[System.Diagnostics.CodeAnalysis.SuppressMessage("Microsoft.Security", "CA2100:Review SQL queries for security vulnerabilities", Justification = "It's up to the user to ensure proper quoting.")]`
`809`		`- private IDbCommand CreateDbCommandWithParameters(LogEventInfo logEvent, CommandType commandType, string dbCommandText, IList<DatabaseParameterInfo> databaseParameterInfos)`
	`821`	`+ private IDbCommand CreateDbCommandWithParameters(LogEventInfo logEvent, IDbConnection dbConnection, CommandType commandType, string dbCommandText, IList<DatabaseParameterInfo> databaseParameterInfos)`
`810`	`822`	`{`
`811`		`- var dbCommand = _activeConnection.CreateCommand();`
	`823`	`+ var dbCommand = dbConnection.CreateCommand();`
`812`	`824`	`dbCommand.CommandType = commandType;`
	`825`	`+ if (CommandProperties?.Count > 0)`
	`826`	`+ {`
	`827`	`+ ApplyDatabaseObjectProperties(dbCommand, CommandProperties, logEvent);`
	`828`	`+ }`
`813`	`829`	`dbCommand.CommandText = dbCommandText;`
`814`	`830`
`815`	`831`	`for (int i = 0; i < databaseParameterInfos.Count; ++i)`
`@@ -965,7 +981,7 @@ private void RunInstallCommands(InstallationContext installationContext, IEnumer`
`965`	`981`
`966`	`982`	`installationContext.Trace("DatabaseTarget(Name={0}) - Executing {1} '{2}'", Name, commandInfo.CommandType, commandText);`
`967`	`983`
`968`		`- using (IDbCommand command = CreateDbCommandWithParameters(logEvent, commandInfo.CommandType, commandText, commandInfo.Parameters))`
	`984`	`+ using (IDbCommand command = CreateDbCommandWithParameters(logEvent, _activeConnection, commandInfo.CommandType, commandText, commandInfo.Parameters))`
`969`	`985`	`{`
`970`	`986`	`try`
`971`	`987`	`{`
`@@ -1081,7 +1097,7 @@ protected internal virtual object GetDatabaseParameterValue(LogEventInfo logEven`
`1081`	`1097`	`return RenderObjectValue(logEvent, parameterInfo.Name, parameterInfo.Layout, parameterInfo.ParameterType, parameterInfo.Format, parameterInfo.Culture);`
`1082`	`1098`	`}`
`1083`	`1099`
`1084`		`- private object GetDatabaseConnectionValue(LogEventInfo logEvent, DatabaseObjectPropertyInfo connectionInfo)`
	`1100`	`+ private object GetDatabaseObjectPropertyValue(LogEventInfo logEvent, DatabaseObjectPropertyInfo connectionInfo)`
`1085`	`1101`	`{`
`1086`	`1102`	`return RenderObjectValue(logEvent, connectionInfo.Name, connectionInfo.Layout, connectionInfo.PropertyType, connectionInfo.Format, connectionInfo.Culture);`
`1087`	`1103`	`}`
`@@ -1163,7 +1179,7 @@ private static object CreateDefaultValue(Type dbParameterType)`
`1163`	`1179`	`///`
`1164`	`1180`	`/// Transactions aren't in .NET Core: https://github.com/dotnet/corefx/issues/2949`
`1165`	`1181`	`/// </summary>`
`1166`		`- private class TransactionScope : IDisposable`
	`1182`	`+ private sealed class TransactionScope : IDisposable`
`1167`	`1183`	`{`
`1168`	`1184`	`private readonly TransactionScopeOption suppress;`
`1169`	`1185`