Would creating an MSSqlServerSink within a web request create a memory leak or similar type of problem?

Viewed 113

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 );
            }
        }
    }
}
1 Answers

Serilog sinks often need to be disposed in order to clean up eagerly. MSSqlServerSink is IDisposable, and while resources held by undisposed instances will eventually be cleaned up by the .NET finalizer thread, resources will be tied up for an unspecified amount of time before finalization kicks in, leading to leak-like behavior.

Your solution will need to be modified so that the sinks are disposed, or, you could use Serilog.Sinks.Map instead of this to route tenant-specific logs to the correct sink and get sink caching/disposing implemented for you.

Related