ObjectDisposedException crashes out App Pool when used in ASP.NET

[jonasswiatek]

Hello and greetings!

I'm using gelf4net in an ASP.NET MVC application, hosted on AWS Elastic Beanstalk.

The App Pool crashes out almost immediately after the application starts running, with the following exception in the Windows Event Log:

Description: The process was terminated due to an unhandled exception.
Exception Info: System.ObjectDisposedException
Stack:
   at System.Net.Sockets.UdpClient.EndSend(System.IAsyncResult)
   at gelf4net.Appender.GelfUdpAppender.SendCallback(System.IAsyncResult)
   at System.Net.LazyAsyncResult.Complete(IntPtr)
   at System.Threading.ExecutionContext.RunInternal(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object, Boolean)
   at System.Threading.ExecutionContext.Run(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object, Boolean)
   at System.Threading.ExecutionContext.Run(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object)
   at System.Net.ContextAwareResult.Complete(IntPtr)
   at System.Net.Sockets.BaseOverlappedAsyncResult.CompletionPortCallback(UInt32, UInt32, System.Threading.NativeOverlapped*)
   at System.Threading._IOCompletionCallback.PerformIOCompletionCallback(UInt32, UInt32, System.Threading.NativeOverlapped*)

I'm fairly confident that the exception occurs on this line: https://github.com/jjchiw/gelf4net/blob/master/src/Gelf4net/Appender/GelfUdpAppender.cs#L100

I'm wondering why the exception occurs though, since if it was a network connection loss I'd not expect an ObjectDisposedException.

Edit: After having consulted MSDN, it seems this exception gets thrown when the connection is closed.

Since this exception occurs in a thread not directly managed by IIS, it crashes out the worker process, sending the server into a permanent 503 state, until it's restarted by some means.

This is my configuration:

  <log4net>
    <appender name="GelfUdpAppender" type="Gelf4net.Appender.GelfUdpAppender, Gelf4net">
      <remoteAddress value="172.31.41.121" />
      <remotePort value="12201" />
      <layout type="Gelf4net.Layout.GelfLayout, Gelf4net">
        <param name="AdditionalFields" value="app:bridge,version:1.0,Level:%level" />
        <param name="Facility" value="bridge" />
        <param name="IncludeLocationInformation" value="true" />
        <!-- Sets the full_message and short_message to the specified pattern-->
        <param name="ConversionPattern" value="[%t] %c{1} - %m" />
      </layout>
    </appender>
    <root>
      <level value="ALL" />
      <appender-ref ref="GelfUdpAppender" />
    </root>
  </log4net>

I call log4net.Config.XmlConfigurator.Configure(); once in Application_Start(), and then use the logger like this:

var gelfLog = LogManager.GetLogger("bridge");
ThreadContext.Properties["Application"] = "blabla";
ThreadContext.Properties["SubUserID"] = 33;
ThreadContext.Properties["UserID"] = 11;

gelfLog.Info("SomeLogmessage");

The logging works - I'm getting messages in greylog up to the point where it crashes out. Any input?

[jjchiw]

Hi

I've been trying to reproduce the error in a Simple Console Application creating tasks and cancelling the tasks even I try to call the base method Close of the Appender like this

var appender = LogManager.GetRepository().GetAppenders().FirstOrDefault();
var udpappender = appender as GelfUdpAppender;
udpappender.Close();

Changing the size of the MaxChunkSize message thinking that it was maybe the method that create the part of the messages.

I checked the base class of GelfUdpAppender that it's the UdpAppender https://svn.apache.org/repos/asf/logging/log4net/tags/log4net-1_2_9/src/Appender/UdpAppender.cs and the only place that the Close method is called is in OnClose() and that method is only called when I close the application.

I also tried to stop graylog in the middle of logging and started up

And I couldn't reproduce the exception ObjectDisposedException

This is the documentation of the exception in MSDN https://msdn.microsoft.com/en-us/library/system.net.sockets.udpclient.endreceive%28v=vs.110%29.aspx

ObjectDisposedException 
The underlying Socket has been closed. 

I'm sure that in the code the socket is never closed in GelfUdpAppender.

I created too a MVC project and added gelf4net, and it works....

Can you reproduce the exception in local?

[jonasswiatek]

Yeah I haven't been able to reproduce it locally either. I'm thinking maybe it's an issue with the Amazon Hosting Environment. Some sort of network error that cuts the connection, leaving it in a state like that.

I'm thinking though, that it's kinda nasty that the App Pool can be killed in case of something like that (if that is indeed the issue). Handling the exception and attempting recreate the connection might be a good idea? I don't mind trying to make a pull request that attempts something like that.

[jjchiw]

Hi!

Sure handling the exception and recreating the connection could be a good idea to avoid the crash in the AppPool but I'm not sure how will it behave with multiple threads, should we lock that part of the code endSend and wait to be initialized or create a sort of queue of the messages and when is connected reprocessed the messages, and what about the messages that are too big and are chunked and then throws the exception.....maybe I'm being paranoid. :)

I'll be glad with your PR that can handle that sort of exception and keep the integrity of the messages. Maybe another option more suited in the Amazon Hosting Environment could be to use the AmqpAppender instead of UdpAppender (yes, I know that's a very radical suggestion :/ )

By the way. I haven't tested AmqpAppender in a real environment... :/

[jjchiw]

Another thing just to know if it's the environment we can override void OnClose() and write in the EventLog and see when it's closing the connection maybe that will help to track the exception

something like this

protected override void OnClose()
{
    base.OnClose();

    string sSource;
    string sLog;
    string sEvent;

    sSource = "gelf4net";
    sLog = "Application";
    sEvent = "Closing event";

    if (!EventLog.SourceExists(sSource))
        EventLog.CreateEventSource(sSource, sLog);

    EventLog.WriteEntry(sSource, sEvent);
    EventLog.WriteEntry(sSource, sEvent,
        EventLogEntryType.Warning, 234);
}

[jonastelzio]

Hey! Sorry about the late response!

I just looked over more of our code, and it seems that log4net.Config.XmlConfigurator.Configure(); was actually called every time gelfLog.Info("SomeLogmessage"); was called in one section of our code.

Could that cause the socket to be closed and reopen, causing the ObjectDisposedException to occur?

[jjchiw]

Hi!

Yup, that's the cause of the exception. I ran some tests calling log4net.Config.XmlConfigurator.Configure(); before any log. and the it throwed the exception. I didn't dig more in the code of log4net to see if it's of how the appenders are managed, to know exactly when the Close method of the appender is called.

Ok, I'll close the issue, thanks for the info :)

[dtalas]

Hey all. I'm a bit confused if there is an actual resolution to this issue, or we should change the way we use log4net (call log first before Configure?). We are running into the same issue, as intermittently our console app that logs to graylog crashes with the same message in the EventLog as OP.

Thanks!

[jjchiw]

No, the original issue was that every time when gelfLog.Info("SomeLogmessage"); was called it seems the log4net.Config.XmlConfigurator.Configure(); was called, so every time log4net was configuring itself and GelfUdpAppender was called with the Close Method and that caused the System.ObjectDisposedException

The way it should be done is to call just once when the application start log4net.Config.XmlConfigurator.Configure();

[dtalas]

Thanks. So is there a workaround of any sort?

[jjchiw]

Yes, the library works, Do you have a project to reproduce the exception, so I can help you......