|
Well, that's a day of my life wasted. I've had the situation today that when I start my application 30% of the time it wouldn't make it through its initialisation and would deadlock deep in log4net code. Inspection of locked resources showed one thread had locked the RollingFileAppender and was waiting for a lock on the ConsoleAppender, and another thread the other way around, the classic deadly embrace.
How is this possible? It's hard, but can happen if one of the appenders itself attempts to do some logging while processing an existing logging call.
To cut a long story short, you need to make sure that any ToString() methods do not do any logging. I had exactly that, a ToString() method which presented different output depending on whether an object was valid or invalid, and where it was invalid it logged the fact. When you use something like ILog.DebugFormat, the arguments are evaluated late in the day, seemingly inside an appender, most likely so that the overhead is not present if logging levels don't require it. Thus one appender was trying to log to the other and the nasty outcome.
I was looking for this by inspecting the stack trace for flow out of our code, into log4net, and back into our code before going to log4net again and sure enough it was there. BUT, I couldn't see it for a long time as I was inspecting the call stack from the Threads window which doesn't show you the whole stack frame, just the top part of it. You need to switch to that thread and examine the stack trace window from there.
Nasty business, but quite interesting if you're as boring as I am.
Regards,
Rob Philpott.
|
|
|
|
General 
News 
Suggestion 
Question 
Bug 
Answer 
Joke 
Rant 
Admin 
Submit an article or tip
Post your Blog
