IIS Application pool Crashed During APP Pool Recycle and apparently Gelf was the culprit

[fm-gawdeprasad]

We use Graylog to log all the Database calls in our application. We had the IIS App Pool recycle scheduled at 3AM in the morning. During the Recycle, the IIS failed to start with following logs in System Event log

An unhandled exception occurred and the process was terminated. Application ID: /LM/W3SVC/2/ROOT Process ID: 4924 Exception: System.ObjectDisposedException Message: Cannot access a disposed object. Object name: 'System.Net.Sockets.Socket'. StackTrace: at System.Net.Sockets.Socket.EndSendTo(IAsyncResult asyncResult) at System.Net.Sockets.UdpClient.EndSend(IAsyncResult asyncResult) at gelf4net.Appender.GelfUdpAppender.SendCallback(IAsyncResult ar) at System.Net.LazyAsyncResult.Complete(IntPtr userToken) at System.Net.ContextAwareResult.CompleteCallback(Object state) at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state, Boolean preserveSyncCtx) at System.Threading.ExecutionContext.Run(ExecutionContext executionContext, ContextCallback callback, Object state, Boolean preserveSyncCtx) at System.Threading.ExecutionContext.Run(ExecutionContext executionContext, ContextCallback callback, Object state) at System.Net.ContextAwareResult.Complete(IntPtr userToken) at System.Net.LazyAsyncResult.ProtectedInvokeCallback(Object result, IntPtr userToken) at System.Net.LazyAsyncResult.InvokeCallback(Object result) at System.Net.Sockets.BaseOverlappedAsyncResult.CompletionPortCallback(UInt32 errorCode, UInt32 numBytes, NativeOverlapped* nativeOverlapped) at System.Threading._IOCompletionCallback.PerformIOCompletionCallback(UInt32 errorCode, UInt32 numBytes, NativeOverlapped* pOVERLAP)

An unhandled exception occurred and the process was terminated.

Application ID: /LM/W3SVC/2/ROOT

Process ID: 4924

Exception: System.ObjectDisposedException

Message: Cannot access a disposed object.
Object name: 'System.Net.Sockets.Socket'.

StackTrace:    at System.Net.Sockets.Socket.EndSendTo(IAsyncResult asyncResult)
   at System.Net.Sockets.UdpClient.EndSend(IAsyncResult asyncResult)
   at gelf4net.Appender.GelfUdpAppender.SendCallback(IAsyncResult ar)
   at System.Net.LazyAsyncResult.Complete(IntPtr userToken)
   at System.Net.ContextAwareResult.CompleteCallback(Object state)
   at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state, Boolean preserveSyncCtx)
   at System.Threading.ExecutionContext.Run(ExecutionContext executionContext, ContextCallback callback, Object state, Boolean preserveSyncCtx)
   at System.Threading.ExecutionContext.Run(ExecutionContext executionContext, ContextCallback callback, Object state)
   at System.Net.ContextAwareResult.Complete(IntPtr userToken)
   at System.Net.LazyAsyncResult.ProtectedInvokeCallback(Object result, IntPtr userToken)
   at System.Net.LazyAsyncResult.InvokeCallback(Object result)
   at System.Net.Sockets.BaseOverlappedAsyncResult.CompletionPortCallback(UInt32 errorCode, UInt32 numBytes, NativeOverlapped* nativeOverlapped)
   at System.Threading._IOCompletionCallback.PerformIOCompletionCallback(UInt32 errorCode, UInt32 numBytes, NativeOverlapped* pOVERLAP)

The number of message being sent to Graylog was pretty high as it sent 20lac messages in the span of 17 hours (which is too much). When I looked at GelfUdpAppender, I think what might have happened is the client object was recycled before the EndSend() is called. But I am not sure about it.

Following is how we are creating logger. We created the static instance of the logger

 static readonly ILog log = LogManager.GetLogger(typeof(LogLiveSps));

And I am logging the error as below

log.Error(sb.ToString());

Do let me know if my assumption is correct. With this effort we have memached most of the DB calls, but my worry is that, if I enable graylog again, it should not crash the app pool on live site during recycle.

[jjchiw]

Hi I think it's very similar to this issue https://github.com/jjchiw/gelf4net/issues/18

And the exception was triggered because log4net.Config.XmlConfigurator.Configure(); was called every time as explained in this comment https://github.com/jjchiw/gelf4net/issues/18#issuecomment-97927767

I'll try to reproduce the exception Recycling the App pool and will let you know if I could reproduce it

[JBJamesBrownJB]

Did you confirm that was the issue?

[jjchiw]

Hi!

No I couldn't reproduce it or confirmed it, do you have the same issue?

[JBJamesBrownJB]

Yes I have an WCF service which seems to crash like this when app pool recycles and we are logging a high frequency.

[jjchiw]

I can't reproduce it, I created a simple nancy application hosted in iis, and I had various thread pointing to the endpoint and logging the time via http and udp, and in the iis console I go to the application pool and recycle it, and all the messages kept going to graylog and didn't experience any crash....

test-gelf4net.zip

[JBJamesBrownJB]

So I also had WCF tracing turned on at the time. Maybe this is a contributor. I will also attempt to reproduce in a simpler example than our production system. Thanks for your attempts.