My Custom Log4net Asynch Failover Appender Skips Messages

Question

I am trying to write an asynchronous Failover Appender for Log4net. i am nearly there, but have some slight issues.

The appender needs to try to log to our internal Web Service, then, if that fails, write to the file.

The Web Service works great...every time.
The fail-over into the file loses messages

This is where I need help...

SYMPTOMS:

My test console application displays all the messages (see attached photos below)
But when the fail-over activates, some or many of the messages dont get appended into the file

MY APPENDER CODE LOOKS LIKE:
Eventually, I will resolve the Client dynamically, but for now...

namespace Testing.Appenders
{
    using log4net.Appender;
    using log4net.Core;
    using System;
    using System.IO;
    using System.ServiceModel;
    using System.Threading.Tasks;
    using wsEventManager;

    public class AsynchWebServiceFailoverAppender : AppenderSkeleton
    {
        #region <Properties>

        public string ServiceUrl { get; set; }

        public string File { get; set; }

        #endregion

        #region <Methods>

        #region protected

        protected override void Append(LoggingEvent loggingEvent)
        {
            if (loggingEvent == null)
                throw new ArgumentNullException("LoggingEvent");

            if (string.IsNullOrEmpty(File))
                throw new ArgumentNullException("File");

            if (string.IsNullOrEmpty(ServiceUrl))
                throw new ArgumentNullException("ServiceUrl");

            Task.Factory.StartNew(() =>
            {
                var uri = new Uri(ServiceUrl);
                var myBinding = new BasicHttpBinding(BasicHttpSecurityMode.None);
                var endpoint = new EndpointAddress(uri);
                var client = new EventManagerSoapClient(myBinding, endpoint);

                var eventType = GetEventType(loggingEvent);
                var log = GetEvent(eventType);

                client.Log(log);
                client.Close();
                client = null;
            }) 
            .ContinueWith(task => 
            {    
                using (var streamWriter = new StreamWriter(File, true))
                {
                    using (var textWriter = TextWriter.Synchronized(streamWriter))
                    {
                        textWriter.WriteLine(base.RenderLoggingEvent(loggingEvent));
                        textWriter.FlushAsync();
                    }
                }
            }, TaskContinuationOptions.OnlyOnFaulted);
        }

        #endregion

        #endregion
    }
}

MY CONFIG WORKS, BUT HERE IT IS:

<?xml version="1.0"?>
<configuration>

  <configSections>
    <section name="log4net" type="log4net.Config.Log4NetConfigurationSectionHandler, log4net" />
  </configSections>

  <log4net>
    <appender name="WebServiceFailoverAppender" type="Testing.Appenders.AsynchWebServiceFailoverAppender , Testing">
      <ServiceUrl value="http://localhost/DiagnosticsWeb/BadUrl.asmx" />
      <file value="C:\Logs\Support\Diagnostics.Appender\log4net.log" />
      <layout type="log4net.Layout.PatternLayout">
        <conversionPattern value="&lt;%level date=&quot;%date{MM-dd-yyyy}&quot; time=&quot;%date{h:mm:ss tt}&quot; file=&quot;%class&quot; thread=&quot;%thread&quot;&gt;%message&lt;/%level&gt;%newline" />
      </layout>
    </appender>
    <root>
      <level value="ALL" />
      <appender-ref ref="WebServiceFailoverAppender" />
    </root>
  </log4net>

</configuration>

RESULTS:

5 Messages are sent to the console for logging
Only 2 messages get logged

Most likely you have race condition when you write to file. Your TextWriter.Synchronized has no effect because you create new writer every time. To verify try to lock over whole file writing block. — Evk, May 20 '16 at 18:22
No idea, only know that's not me. Did locking over file writing code helped? — Evk, May 20 '16 at 18:53

score 1 · Answer 1 · answered May 20 '16 at 18:18

If you are using asynchronous calls you should await them, otherwise, it might not be finished when you leave the scope. My guess is that flush does take any affect in this race condition you are having.

To fix the issue you should await for the flush. In your task continuation I would introduce await async architecture:

ContinueWith(async task => 
{    
    using (var streamWriter = new StreamWriter(File, true))
    {
       using (var textWriter = TextWriter.Synchronized(streamWriter))
       {
           textWriter.WriteLine(base.RenderLoggingEvent(loggingEvent));
           await textWriter.FlushAsync();
        }
     }
}, TaskContinuationOptions.OnlyOnFaulted);

Let me know if that worked.

score 1 · Accepted Answer · edited May 23 '17 at 12:31

You have race condition when you write to file. Your TextWriter.Synchronized has no effect because you create new writer every time, and this construct was created to synchronize writes to single instance of TextWriter. To verify try to lock over whole file writing block. If you want to write to single log file from multiple threads in fire-and-forget asynchronous manner - see my other answer here.

My Custom Log4net Asynch Failover Appender Skips Messages

2 Answers2