AuditTo uses shared DB Connection

[erviem99]

I am trying to use this sink with AuditTo but under heavy load I get errors

System.AggregateException: Failed to emit a log event. (Connection cannot be changed while async operation is in progress.)

This happens from within my logging call in audit.Save()

`
public void Log(string eventType, IDictionary<string, object> customFields = null, string comments = null)
{
using (var audit = auditScopeFactory.Create(new AuditScopeOptions { CreationPolicy = EventCreationPolicy.Manual }))
{
LogInternal(audit, eventType, customFields, comments);
audit.Save();
}
}

`

I think the issue arises because the underlying database connection is being reused inside Serilog and my Log function is called from a thread other than the main thread.

Can anyone confirm this or possibly suggest a fix?

[ckadluba]

Hi @erviem99!

Thank you for reporting this issue. Can you attach a complete exception info including call stack and all other stuff?

Thank you!

Christian

[erviem99]

Sure, I have an attribute on my controllers that handles the audit logging.

System.AggregateException: Failed to emit a log event. (Connection cannot be changed while async operation is in progress.)\n at void Serilog.Core.Sinks.AggregateSink.Emit(LogEvent logEvent)\n at void Serilog.Core.Logger.Write(LogEventLevel level, Exception exception, string messageTemplate, ReadOnlySpan<object> propertyValues)\n at void Serilog.Core.Logger.Information<T>(string messageTemplate, T propertyValue)\n at object Audit.Serilog.Providers.SerilogDataProvider.InsertEvent(AuditEvent auditEvent)\n at void SMDS.Logging.Services.AuditLoggerService.Log(string eventType, IDictionary<string, object> customFields, string comments)\n at void SMDS.Logging.Attributes.SmdsAuditFilterAttribute.SaveContext()\n at void SMDS.Logging.Attributes.SmdsAuditFilterAttribute.OnActionExecuted(ActionExecutedContext context)\n at async Task Microsoft.AspNetCore.Mvc.Filters.ActionFilterAttribute.OnActionExecutionAsync(ActionExecutingContext context, ActionExecutionDelegate next)\n at async Task Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.InvokeNextActionFilterAsync()+Awaited(?)\n at void Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.Rethrow(ActionExecutedContextSealed context)\n at Task Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.Next(ref State next, ref Scope scope, ref object state, ref bool isCompleted)\n at Task Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.InvokeInnerFilterAsync()\n at async Task Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.InvokeNextResourceFilter()+Awaited(?)\n at void Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.Rethrow(ResourceExecutedContextSealed context)\n at Task Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.Next(ref State next, ref Scope scope, ref object state, ref bool isCompleted)\n at Task Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.InvokeFilterPipelineAsync()\n at async Task Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.InvokeAsync()+Awaited(?) x 2\n at async Task Microsoft.AspNetCore.Authorization.AuthorizationMiddleware.Invoke(HttpContext context)\n at async Task Microsoft.AspNetCore.Authentication.AuthenticationMiddleware.Invoke(HttpContext context)\n at async Task WebReq3.Mini.Middleware.QueryStringSecurity.Invoke(HttpContext context) in /src/Api/WebReq3.Mini/Middleware/QueryStringSecurity.cs:line 29\n at async Task Swashbuckle.AspNetCore.SwaggerUI.SwaggerUIMiddleware.Invoke(HttpContext httpContext)\n at async Task Swashbuckle.AspNetCore.Swagger.SwaggerMiddleware.Invoke(HttpContext httpContext, ISwaggerProvider swaggerProvider)\n at async Task Microsoft.AspNetCore.Localization.RequestLocalizationMiddleware.Invoke(HttpContext context)\n at async Task Microsoft.AspNetCore.Diagnostics.ExceptionHandlerMiddlewareImpl.Invoke(HttpContext context)+Awaited(?) ---> System.InvalidOperationException: Connection cannot be changed while async operation is in progress.\n at void Microsoft.Data.SqlClient.SqlCommand.set_Connection(SqlConnection value)\n at void Serilog.Sinks.MSSqlServer.Platform.SqlInsertStatementWriter.InitializeSqlCommand(ISqlConnectionWrapper sqlConnection, IEnumerable<KeyValuePair<string, object>> logEventFields)\n at async Task Serilog.Sinks.MSSqlServer.Platform.SqlInsertStatementWriter.WriteEvents(IEnumerable<LogEvent> events)\n at void Serilog.Core.Sinks.AggregateSink.Emit(LogEvent logEvent)\n --- End of inner exception stack trace --- ---> System.InvalidOperationException: Connection cannot be changed while async operation is in progress.\n at void Microsoft.Data.SqlClient.SqlCommand.set_Connection(SqlConnection value)\n at void Serilog.Sinks.MSSqlServer.Platform.SqlInsertStatementWriter.InitializeSqlCommand(ISqlConnectionWrapper sqlConnection, IEnumerable<KeyValuePair<string, object>> logEventFields)\n at async Task Serilog.Sinks.MSSqlServer.Platform.SqlInsertStatementWriter.WriteEvents(IEnumerable<LogEvent> events)\n at void Serilog.Core.Sinks.AggregateSink.Emit(LogEvent logEvent)\n --- End of inner exception stack trace ---

[ckadluba]

We made some performance improvements in release 8.1.0 and i think this issue might have been introduced with that change.

2563b95

Perhaps it is caused because the sink now re-uses a single instance of SqlCommand but it turns out that SqlCommand seems not to be thread safe.

Do you have a change to verify this assumptions by downgrading to 8.0.0 in your scenario and let us know if the problem is not present in that version?

[erviem99]

This happened (unfortunately) to us in production so it is not easily reproducable. I will try and see what I can do but it will take a couple of weeks

[ckadluba]

No worries @erviem99. I think the part of the code causing the issue you reported is pretty clear. Therefore I created a release 8.1.1 which will most probably fix it.

https://github.com/serilog-mssql/serilog-sinks-mssqlserver/releases/tag/v8.1.1

If you could update your app to 8.1.1 and let us know in a while if you think the issue is gone, we would highly appreciate it. I will leave this issue open for a while so we can close it when you have some positive feedback.

[erviem99]

I can confirm that the problem has been fixed in 8.2.0.

As a side-note I did some performance testing between WriteTo and AuditTo and even with BatchPostingLimit of 1 using WriteTo is much faster.

I suspect this is because AuditTo is opening and closing the database connection much more frequent even in a very busy environment. For the same reason AuditTo is also using up a lot more database connections. This is something to be aware of (configure Max Pool Size).

[erviem99]

I'm sorry. It is not a lot faster. It was just falling behind with the writing to the database :-)

[ckadluba]

Thank you very much for the testing and feedback. I'm glad this issue is fixed now.

Regarding the connection count. How did you monitor the connection count used by the sink? I think network wise this should not be an issue since the SqlClient library internally does connection pooling and caching, so it should only open the TCP connection to the SQL Server once for multiple log calls in sequence. But it is an issue regarding memory allocation. Currently we create a new connection object for each log call. I wonder if this could be optimized without introducing a bug like this here, where we attempted to optimize performance by reusing SqlCommand instances.