I have a fairly unique multi-tenant application where each client gets their own database. I'm currently using Serilog with an MSSqlServerSink to log everything to a single database. I just got the request/requirement to also log to the individual tenant databases.
I created a new ILogEventSink implementation that uses a ConcurrentDictionary and look for an existing sink, then creates a new one if it doesn't exist.
Since deploying, we've been getting some 503 errors and the only symptoms being observed by our admins are a number of connections to the web server seem to be staying open in a CLOSE_WAIT state. I'm searching for more info on what causes CLOSE_WAIT, but the only big change was the deployment of this new logging sink.
Since the only reference to the new sink is maintained in my sink object (and that object is created during app_start), I would think this would work, but is it possible that this new sink is somehow getting tied to the thread that's handling the current request and keeping that request/connection alive?
using Serilog.Core;
using Serilog.Events;
using Serilog.Sinks.MSSqlServer;
using System;
using System.Collections.Concurrent;
using System.Linq;
using Context = Logging.Constants.Context;
namespace Web.Logging
{
public class CustomerSink : ILogEventSink
{
private readonly ConcurrentDictionary<string, SinkCache> Sinks;
private readonly ICustomerProvider CustomerProvider;
public CustomerSink( ICustomerProvider customerProvider = null )
{
CustomerProvider = customerProvider ?? Customer.GetProvider();
Sinks = new ConcurrentDictionary<string, SinkCache>();
}
private ILogEventSink CreateSink( Customer customer )
{
var columnOptions = SqlServerOptions.DefaultColumnOptions();
var remove = columnOptions.AdditionalColumns.Where( column => column.ColumnName == Context.ApplicationName || column.ColumnName == Context.CustomerId ).ToList();
foreach( var column in remove )
columnOptions.AdditionalColumns.Remove( column );
columnOptions.Store.Remove( StandardColumn.MessageTemplate );
columnOptions.LogEvent.ExcludeAdditionalProperties = true;
columnOptions.LogEvent.ExcludeStandardColumns = true;
return new MSSqlServerSink(
connectionString: customer.ConnectionString,
tableName: "Event",
batchPostingLimit: 50,
period: TimeSpan.FromSeconds( 5 ),
formatProvider: null,
autoCreateSqlTable: true,
columnOptions: columnOptions,
schemaName: "log"
);
}
private SinkCache CreateSink( string customerId )
{
if( CustomerProvider.GetCustomer( customerId, out var customer ) )
return new SinkCache( customer.ConnectionString, CreateSink( customer ) );
return new SinkCache( null, null );
}
public void Emit( LogEvent logEvent )
{
if( logEvent.Properties.TryGetValue( Context.CustomerId, out var value ) && value is ScalarValue scalar && scalar.Value != null )
{
var cache = Sinks.AddOrUpdate( scalar.Value.ToString(), CreateSink,
( customerId, existing ) =>
{
if( existing.Expiration < DateTime.UtcNow )
{
if( CustomerProvider.GetCustomer( customerId, out var customer ) )
{
if( customer.ConnectionString == existing.ConnectionString )
return new SinkCache( existing.ConnectionString, existing.Sink ); //Just refresh the expiration
if( existing.Sink is IDisposable disposable )
disposable.Dispose();
return new SinkCache( customer.ConnectionString, CreateSink( customer ) );
}
else if( existing.Sink is IDisposable disposable )
disposable.Dispose();
return new SinkCache( null, null );
}
//No change
return existing;
} );
cache.Sink?.Emit( logEvent );
}
}
private class SinkCache
{
public string ConnectionString { get; }
public DateTime Expiration { get; }
public ILogEventSink Sink { get; }
public SinkCache( string connectionString, ILogEventSink sink )
{
ConnectionString = connectionString;
Sink = sink;
Expiration = DateTime.UtcNow.AddMinutes( 2 );
}
}
}
}