No logging into DB after upgrade to 2.X

[gl2007]

I upgraded last week to this new version 2.X including upgrade to log4net 1.2.13 from nuget. The issue started yesterday and no logs in the DB at all.

I see tons of these exceptions in the internal log of log4net.

"log4net:ERROR Subscriber task was aborted. System.Threading.ThreadAbortException: Thread was being aborted. at System.Threading.Monitor.ObjWait(Boolean exitContext, Int32 millisecondsTimeout, Object obj) at System.Threading.SemaphoreSlim.WaitUntilCountOrTimeout(Int32 millisecondsTimeout, UInt32 startTime, CancellationToken cancellationToken) at System.Threading.SemaphoreSlim.Wait(Int32 millisecondsTimeout, CancellationToken cancellationToken) at System.Collections.Concurrent.BlockingCollection1.TryTakeWithNoTimeValidation(T& item, Int32 millisecondsTimeout, CancellationToken cancellationToken, CancellationTokenSource combinedTokenSource) at System.Collections.Concurrent.BlockingCollection1.d__68.MoveNext() at Log4Net.Async.ParallelForwardingAppender.SubscriberLoop() log4net:ERROR Exception while logging System.Threading.LockRecursionException: Recursive read lock acquisitions not allowed in this mode. at System.Threading.ReaderWriterLockSlim.TryEnterReadLockCore(TimeoutTracker timeout) at System.Threading.ReaderWriterLockSlim.TryEnterReadLock(TimeoutTracker timeout) at log4net.Repository.Hierarchy.Logger.CallAppenders(LoggingEvent loggingEvent) at log4net.Repository.Hierarchy.Logger.Log(Type callerStackBoundaryDeclaringType, Level level, Object message, Exception exception)"

My setup hasn't changed.

<appender name="AsyncParallelForwarder" type="Log4Net.Async.ParallelForwardingAppender, Log4Net.Async">
      <appender-ref ref="RollingLogFileAppender" />
      <appender-ref ref="AdoNetAppender_SqlServer" />
</appender>
<root>
     <level value="ALL" />
     <appender-ref ref="AsyncParallelForwarder" />
</root>

Any help to resolve this would really help.

[gl2007]

Seems to be happening in all log4net versions 1.2.13+ till latest but the custom appender should take steps to prevent this as per Apache's thread here: https://issues.apache.org/jira/plugins/servlet/mobile#issue/LOG4NET-418

I am using .Net 4.0, not sure if it is specific to this version.

[rcollette]

Something to try would be to create two async parallel forwarders and put sql server appender in one and the rolling log file appender in the other. If that doesn't solve the problem, try to isolate the problem by using only one of the physical appenders at a time and see if the problem still exists.

The problem seems to be that the forwarder is aborting due to a rentrant lock but given that the type of locking done in the ParallelForwardingAppender and in Log4net has been around for a long time, I'm inclined to think the issue lies in one of the physical appenders. ParallelForwardingAppender appears to be in wait state and thus having already established its lock, at the time the exception occurs.

By splitting into two separate forwarding appenders, each appender will be able to write at its own pace and exceptions in one logger should not affect the other.

[rcollette]

What type of application is this? Is LogManager.Shutdown() being called when the application ends such as in the Application_End event handler of an ASP.NET application?

I received a response from the Log4net thread you mentioned and they too seem to indicate that the thread abort is happening elsewhere, a recycling app pool perhaps?

[gl2007]

Tried both now:

1. Separating out the file/db loggers. Same result.
2. I do have the LogManager.Shutdown in the Application_End event. I know my app is not crashing as it is working and I do see file logs, but not Db logs. I did comment out and test it. Still the same.

Verified DB credentials, parameters etc, just to check out.

Still nothing.

I see this error (saw this also in DB log when it had worked for a brief moment) in the file log: [NAOU11395][AsyncParallelForwarder_File ParallelForwardingAppender Subscriber Task][ERROR] 21:04:22,591 [(null)] [(null)] [] [ParallelForwardingAppender] - Subscriber task was canceled before completion. System.OperationCanceledException: The operation was canceled. at System.Collections.Concurrent.BlockingCollection1.TryTakeWithNoTimeValidation(T& item, Int32 millisecondsTimeout, CancellationToken cancellationToken, CancellationTokenSource combinedTokenSource) at System.Collections.Concurrent.BlockingCollection1.d__68.MoveNext() at Log4Net.Async.ParallelForwardingAppender.SubscriberLoop()

Thinking of downgrading...but its a big change, decompile all dependent, update recompile...Ughh.

[gl2007]

Finally, logs appeared! It seems that after I truncated my db logs tables, new logs started appearing. Need to see what happened there.

Thanks for the patience!

[gl2007]

It would be great if the log4net can dump the actual exception in the internal debug file. In my case, maybe my Db was full, so the insert failing reason could have saved so much of my time figuring out what was going on. Funny part is that I was seeing 400+ mb space as available.

[rcollette]

For this reason, I would definitely use separate forwarders. This way if one of the threads gets canceled, at least your other appender won't be affected.

The forwarder cannot do anything when it's own thread gets canceled this way. It's essentially an abort. I'll follow up with Log4Net and see if there is any way we can have some sense of what the original error is rather than just getting a thread abort in the appender.

The issue with messaging around the db appender should be addressed with the authors. At a minimum it should write to the log4net debug log but you're not really going to have that on in production normally. Perhaps they have some advice.

[gl2007]

Yes, that's a good takeaway from this thread for me! Thanks!

Even in production, it would be good to see this in the internal file (maybe filtered by count or any other logic to restrict how many times it dumps it).

[rcollette]

Closing since this was a system issue.