Fixed concurrency issue #607

Do not reuse SqlCommand because apparently it is not threadsafe. Set connection on command leads to a exception in audit sink under heavy load.

Author: ckadluba

src/Serilog.Sinks.MSSqlServer/Sinks/MSSqlServer/MSSqlServerAuditSink.cs

@@ -26,12 +26,10 @@ namespace Serilog.Sinks.MSSqlServer
     /// Writes log events as rows in a table of MSSqlServer database using Audit logic, meaning that each row is synchronously committed
     /// and any errors that occur are propagated to the caller.
     /// </summary>
-    public class MSSqlServerAuditSink : ILogEventSink, IDisposable
+    public class MSSqlServerAuditSink : ILogEventSink
     {
         private readonly ISqlLogEventWriter _sqlLogEventWriter;
 
-        private bool _disposedValue;
-
         /// <summary>
         /// Construct a sink posting to the specified database.
         ///
@@ -99,33 +97,6 @@ internal MSSqlServerAuditSink(
         public void Emit(LogEvent logEvent) =>
             _sqlLogEventWriter.WriteEvent(logEvent);
 
-        /// <summary>
-        /// Performs application-defined tasks associated with freeing, releasing, or resetting unmanaged resources.
-        /// </summary>
-        public void Dispose()
-        {
-            Dispose(true);
-            GC.SuppressFinalize(this);
-        }
-
-        /// <summary>
-        /// Releases the unmanaged resources used by the Serilog.Sinks.MSSqlServer.MSSqlServerAuditSink and optionally
-        /// releases the managed resources.
-        /// </summary>
-        /// <param name="disposing">True to release both managed and unmanaged resources; false to release only unmanaged resources.</param>
-        protected virtual void Dispose(bool disposing)
-        {
-            if (!_disposedValue)
-            {
-                if (disposing)
-                {
-                    _sqlLogEventWriter.Dispose();
-                }
-
-                _disposedValue = true;
-            }
-        }
-
         private static void ValidateParameters(MSSqlServerSinkOptions sinkOptions, ColumnOptions columnOptions)
         {
             if (sinkOptions?.TableName == null)

src/Serilog.Sinks.MSSqlServer/Sinks/MSSqlServer/MSSqlServerSink.cs

@@ -152,7 +152,6 @@ protected virtual void Dispose(bool disposing)
                 if (disposing)
                 {
                     _sqlBulkBatchWriter.Dispose();
-                    _sqlLogEventWriter.Dispose();
                 }
 
                 _disposedValue = true;

src/Serilog.Sinks.MSSqlServer/Sinks/MSSqlServer/Platform/ISqlCommandFactory.cs

@@ -4,7 +4,6 @@ namespace Serilog.Sinks.MSSqlServer.Platform
 {
     internal interface ISqlCommandFactory
     {
-        ISqlCommandWrapper CreateCommand(ISqlConnectionWrapper sqlConnection);
         ISqlCommandWrapper CreateCommand(string cmdText, ISqlConnectionWrapper sqlConnection);
     }
 }

src/Serilog.Sinks.MSSqlServer/Sinks/MSSqlServer/Platform/ISqlLogEventWriter.cs

@@ -1,11 +1,10 @@
-using System;
-using System.Collections.Generic;
+using System.Collections.Generic;
 using System.Threading.Tasks;
 using Serilog.Events;
 
 namespace Serilog.Sinks.MSSqlServer.Platform
 {
-    internal interface ISqlLogEventWriter : IDisposable
+    internal interface ISqlLogEventWriter
     {
         void WriteEvent(LogEvent logEvent);
 

src/Serilog.Sinks.MSSqlServer/Sinks/MSSqlServer/Platform/SqlBulkBatchWriter.cs

@@ -1,9 +1,7 @@
 using System;
 using System.Collections.Generic;
 using System.Data;
-using System.Linq;
 using System.Threading.Tasks;
-using Serilog.Debugging;
 using Serilog.Events;
 using Serilog.Sinks.MSSqlServer.Output;
 
@@ -45,10 +43,10 @@ public async Task WriteBatch(IEnumerable<LogEvent> events)
             {
                 FillDataTable(events);
 
-                using (var cn = _sqlConnectionFactory.Create())
+                using (var sqlConnection = _sqlConnectionFactory.Create())
                 {
-                    await cn.OpenAsync().ConfigureAwait(false);
-                    using (var copy = cn.CreateSqlBulkCopy(_disableTriggers, _schemaAndTableName))
+                    await sqlConnection.OpenAsync().ConfigureAwait(false);
+                    using (var copy = sqlConnection.CreateSqlBulkCopy(_disableTriggers, _schemaAndTableName))
                     {
                         for (var i = 0; i < _dataTable.Columns.Count; i++)
                         {

src/Serilog.Sinks.MSSqlServer/Sinks/MSSqlServer/Platform/SqlClient/ISqlCommandWrapper.cs

@@ -1,17 +1,10 @@
 using System;
-using System.Data;
 using System.Threading.Tasks;
-using Microsoft.Data.SqlClient;
 
 namespace Serilog.Sinks.MSSqlServer.Platform.SqlClient
 {
     internal interface ISqlCommandWrapper : IDisposable
     {
-        CommandType CommandType { get; set; }
-        string CommandText { get; set; }
-
-        void SetConnection(ISqlConnectionWrapper sqlConnectionWrapper);
-        void ClearParameters();
         void AddParameter(string parameterName, object value);
         int ExecuteNonQuery();
         Task<int> ExecuteNonQueryAsync();

src/Serilog.Sinks.MSSqlServer/Sinks/MSSqlServer/Platform/SqlClient/SqlCommandWrapper.cs

@@ -10,32 +10,9 @@ internal class SqlCommandWrapper : ISqlCommandWrapper
         private readonly SqlCommand _sqlCommand;
         private bool _disposedValue;
 
-        public SqlCommandWrapper(SqlCommand sqlCommand, SqlConnection sqlConnection)
+        public SqlCommandWrapper(SqlCommand sqlCommand)
         {
             _sqlCommand = sqlCommand ?? throw new ArgumentNullException(nameof(sqlCommand));
-            _sqlCommand.Connection = sqlConnection ?? throw new ArgumentNullException(nameof(sqlConnection));
-        }
-
-        public CommandType CommandType
-        {
-            get => _sqlCommand.CommandType;
-            set => _sqlCommand.CommandType = value;
-        }
-
-        public string CommandText
-        {
-            get => _sqlCommand.CommandText;
-            set => _sqlCommand.CommandText = value;
-        }
-
-        public void SetConnection(ISqlConnectionWrapper sqlConnectionWrapper)
-        {
-            _sqlCommand.Connection = sqlConnectionWrapper.SqlConnection;
-        }
-
-        public void ClearParameters()
-        {
-            _sqlCommand.Parameters.Clear();
         }
 
         public void AddParameter(string parameterName, object value)

src/Serilog.Sinks.MSSqlServer/Sinks/MSSqlServer/Platform/SqlCommandFactory.cs

@@ -5,16 +5,10 @@ namespace Serilog.Sinks.MSSqlServer.Platform
 {
     internal class SqlCommandFactory : ISqlCommandFactory
     {
-        public ISqlCommandWrapper CreateCommand(ISqlConnectionWrapper sqlConnection)
-        {
-            var sqlCommand = new SqlCommand();
-            return new SqlCommandWrapper(sqlCommand, sqlConnection.SqlConnection);
-        }
-
         public ISqlCommandWrapper CreateCommand(string cmdText, ISqlConnectionWrapper sqlConnection)
         {
-            var sqlCommand = new SqlCommand(cmdText);
-            return new SqlCommandWrapper(sqlCommand, sqlConnection.SqlConnection);
+            var sqlCommand = new SqlCommand(cmdText, sqlConnection.SqlConnection);
+            return new SqlCommandWrapper(sqlCommand);
         }
     }
 }

src/Serilog.Sinks.MSSqlServer/Sinks/MSSqlServer/Platform/SqlInsertStatementWriter.cs

@@ -1,10 +1,8 @@
 using System;
 using System.Collections.Generic;
-using System.Data;
 using System.Linq;
 using System.Text;
 using System.Threading.Tasks;
-using Serilog.Debugging;
 using Serilog.Events;
 using Serilog.Sinks.MSSqlServer.Output;
 using Serilog.Sinks.MSSqlServer.Platform.SqlClient;
@@ -20,8 +18,7 @@ internal class SqlInsertStatementWriter : ISqlLogEventWriter
         private readonly ISqlCommandFactory _sqlCommandFactory;
         private readonly ILogEventDataGenerator _logEventDataGenerator;
 
-        private ISqlCommandWrapper _sqlCommand;
-        private bool _disposedValue;
+        private string _sqlCommandText;
 
         public SqlInsertStatementWriter(
             string tableName,
@@ -43,92 +40,68 @@ public SqlInsertStatementWriter(
 
         public async Task WriteEvents(IEnumerable<LogEvent> events)
         {
-            using (var cn = _sqlConnectionFactory.Create())
+            using (var sqlConnection = _sqlConnectionFactory.Create())
             {
-                await cn.OpenAsync().ConfigureAwait(false);
+                await sqlConnection.OpenAsync().ConfigureAwait(false);
 
                 foreach (var logEvent in events)
                 {
                     var fields = _logEventDataGenerator.GetColumnsAndValues(logEvent).ToList();
-                    InitializeSqlCommand(cn, fields);
-
-                    var index = 0;
-                    _sqlCommand.ClearParameters();
-                    foreach (var field in fields)
+                    using (var sqlCommand = InitializeSqlCommand(sqlConnection, fields))
                     {
-                        _sqlCommand.AddParameter(Invariant($"@P{index}"), field.Value);
-                        index++;
+                        await sqlCommand.ExecuteNonQueryAsync().ConfigureAwait(false);
                     }
-
-                    await _sqlCommand.ExecuteNonQueryAsync().ConfigureAwait(false);
                 }
             }
         }
 
-        /// <summary>
-        /// Performs application-defined tasks associated with freeing, releasing, or resetting unmanaged resources.
-        /// </summary>
-        public void Dispose()
+        private ISqlCommandWrapper InitializeSqlCommand(
+            ISqlConnectionWrapper sqlConnection,
+            IEnumerable<KeyValuePair<string, object>> logEventFields)
         {
-            Dispose(disposing: true);
-            GC.SuppressFinalize(this);
-        }
+            InitializeSqlCommandText(logEventFields);
 
-        /// <summary>
-        /// Releases the unmanaged resources used by the Serilog.Sinks.MSSqlServer.Platform.SqlInsertStatementWriter and optionally
-        /// releases the managed resources.
-        /// </summary>
-        /// <param name="disposing">True to release both managed and unmanaged resources; false to release only unmanaged resources.</param>
-        protected virtual void Dispose(bool disposing)
-        {
-            if (!_disposedValue)
+            var sqlCommand = _sqlCommandFactory.CreateCommand(_sqlCommandText, sqlConnection);
+            var index = 0;
+            foreach (var field in logEventFields)
             {
-                if (disposing)
-                {
-                    _sqlCommand?.Dispose();
-                }
-
-                _disposedValue = true;
+                sqlCommand.AddParameter(Invariant($"@P{index}"), field.Value);
+                index++;
             }
+
+            return sqlCommand;
         }
 
-        private void InitializeSqlCommand(ISqlConnectionWrapper sqlConnection,
-            IEnumerable<KeyValuePair<string, object>> logEventFields)
+        private void InitializeSqlCommandText(IEnumerable<KeyValuePair<string, object>> logEventFields)
         {
-            // Optimization: generate INSERT statement and SqlCommand only once
-            // and reuse it with different values and SqlConnections because
-            // the structure does not change.
-            if (_sqlCommand == null)
+            if (_sqlCommandText != null)
             {
-                _sqlCommand = _sqlCommandFactory.CreateCommand(sqlConnection);
-                _sqlCommand.CommandType = CommandType.Text;
+                return;
+            }
 
-                var fieldList = new StringBuilder(Invariant($"INSERT INTO [{_schemaName}].[{_tableName}] ("));
-                var parameterList = new StringBuilder(") VALUES (");
+            var fieldList = new StringBuilder(Invariant($"INSERT INTO [{_schemaName}].[{_tableName}] ("));
+            var parameterList = new StringBuilder(") VALUES (");
 
-                var index = 0;
-                foreach (var field in logEventFields)
+            var index = 0;
+            foreach (var field in logEventFields)
+            {
+                if (index != 0)
                 {
-                    if (index != 0)
-                    {
-                        fieldList.Append(',');
-                        parameterList.Append(',');
-                    }
-
-                    fieldList.Append(Invariant($"[{field.Key}]"));
-                    parameterList.Append("@P");
-                    parameterList.Append(index);
-
-                    index++;
+                    fieldList.Append(',');
+                    parameterList.Append(',');
                 }
 
-                parameterList.Append(')');
-                fieldList.Append(parameterList);
+                fieldList.Append(Invariant($"[{field.Key}]"));
+                parameterList.Append("@P");
+                parameterList.Append(index);
 
-                _sqlCommand.CommandText = fieldList.ToString();
+                index++;
             }
 
-            _sqlCommand.SetConnection(sqlConnection);
+            parameterList.Append(')');
+            fieldList.Append(parameterList);
+
+            _sqlCommandText = fieldList.ToString();
         }
     }
 }

test/Serilog.Sinks.MSSqlServer.PerformanceTests/Sinks/MSSqlServer/Platform/SqlInsertStatementWriterBenchmarks.cs

@@ -13,7 +13,7 @@ namespace Serilog.Sinks.MSSqlServer.PerformanceTests.Platform;
 
 [MemoryDiagnoser]
 [MaxIterationCount(16)]
-public class SqlInsertStatementWriterBenchmarks : IDisposable
+public class SqlInsertStatementWriterBenchmarks
 {
     private const string _tableName = "TestTableName";
     private const string _schemaName = "TestSchemaName";
@@ -35,7 +35,7 @@ public void Setup()
         _sqlCommandWrapperMock = new Mock<ISqlCommandWrapper>();
 
         _sqlConnectionFactoryMock.Setup(f => f.Create()).Returns(_sqlConnectionWrapperMock.Object);
-        _sqlCommandFactoryMock.Setup(f => f.CreateCommand(It.IsAny<ISqlConnectionWrapper>()))
+        _sqlCommandFactoryMock.Setup(f => f.CreateCommand(It.IsAny<string>(), It.IsAny<ISqlConnectionWrapper>()))
             .Returns(_sqlCommandWrapperMock.Object);
 
         CreateLogEvents();
@@ -67,10 +67,4 @@ private void CreateLogEvents()
             _logEvents.Add(CreateLogEvent());
         }
     }
-
-    public void Dispose()
-    {
-        GC.SuppressFinalize(this);
-        _sut.Dispose();
-    }
 }