Memory leak when ES is not accesible

[lukas-lansky]

With a following code:

using log4net;
using log4net.Config;
using System;
using System.IO;

namespace EsLog4NetExperiment
{
    class Program
    {
        private static ILog log = LogManager.GetLogger(typeof(Program));

        static void Main(string[] args)
        {
            XmlConfigurator.Configure(new FileInfo("log4netconfig.xml"));

            while (true)
            {
                for (var i = 0; i < 10000; i++)
                {
                    log.Info("Test insert");
                }

                Console.WriteLine($"{DateTime.Now} 10000 logs inserted into ES");
            }
        }
    }
}

... and following configuration:

<?xml version="1.0" encoding="utf-8" ?>
<log4net>
  <appender name="ElasticSearchAppender" type="log4net.ElasticSearch.ElasticSearchAppender, log4net.ElasticSearch">
    <layout type="log4net.Layout.PatternLayout,log4net">
      <param name="ConversionPattern" value="%d{ABSOLUTE} InternalTrackingId[%property{InternalTrackingId}] ExternalTrackingId[%property{ExternalTrackingId}] %-5p %c{1}:%L - %m%n" />
    </layout>
    <connectionString value="Server=135.128.223.112;Index=elasticlogtest;Port=9200;Rolling=true" />
    <lossy value="false" />
    <bufferSize value="100" />
    <evaluator type="log4net.Core.LevelEvaluator">
      <threshold value="DEBUG"/>
    </evaluator>
    <Fix value="0" />
  </appender>

  <root>
    <level value="DEBUG" />
    <appender-ref ref="ElasticSearchAppender" />
  </root>
</log4net>

... and following packages:

<?xml version="1.0" encoding="utf-8"?>
<packages>
  <package id="log4net" version="2.0.5" targetFramework="net46" />
  <package id="log4net.ElasticSearch" version="2.3.3" targetFramework="net46" />
</packages>

Running this against non-responsing ElasticSearch (or non-existent, you can run configuration without modification to see this) causes following memory leak:

Making ES instance available will not result in freeing the memory. The same thing happen with or without debugger attached, in debug or release mode, with ES non-existent or crippled by out of memory condition.

I'll try to continue with more research or fix in the evening.

[michal-duda]

I am also looking into this issue and as it is visible from @lukas-lansky screenshot problem is that lib is registering non limited number callbacks for QueueUserWorkItem in appender.

protected virtual bool TryAsyncSend(IEnumerable<LoggingEvent> events)
{
        return ThreadPool.QueueUserWorkItem(SendBufferCallback, logEvent.CreateMany(events));
 }

Most straight forward solution is to use circuit breaker (as also @lukas-lansky proposed). I tried to quickly add Polly circuit breaker into Repository like this:

private static Policy policy = Policy.Handle<Exception>()
        .CircuitBreaker(2, TimeSpan.FromMinutes(1));

    public void Add(IEnumerable<logEvent> logEvents, int bufferSize)
    {
        policy.Execute(() =>
        {
                if (bufferSize <= 1)
                {
                    // Post the logEvents one at a time throught the ES insert API
                    logEvents.Do(logEvent => httpClient.Post(uri, logEvent));
                }
                else
                {
                    // Post the logEvents all at once using the ES _bulk API
                    httpClient.PostBulk(uri, logEvents);
                }
        });
    }

With this in place memory footprint stays on some constant value after two timeouts:

Also I think there should be some configurable timeout for http requests, .net HttpClient class should be used instead of WebRequest and number of queued background tasks should be limited 1.

@jptoto What are your thoughts on this? I am good to continue work on this more.