tags:

views:

115

answers:

2

This one really has me scratching my head....

I have been using log4net (currently version 1.2.10) in an application for some time. While adding a new option to the application, I noticed that even though the log4net Debug, Error, etc. methods were getting called items from that log source were not being seen by the console appender.

Having checked the obvious (like making sure there was no filtering involved), I noticed something else that was strange. If I have more than one appender (e.g. a log file appender and a UDP appender) then the appenders will sometimes see different subsets of the log messages. Which subset they see appears to be random, but typically when the problem occurs they will fail to see all messages from a given log source.

Why might this be happening, and what can I do about it since lost messages mean the log file cannot be trusted to show an accurate picture of remote failures?

[Additional information below added Jan 19th, 2010]

I finally took a good look at the ILog object getting passed back in response to the call

LogManager.GetLogger(typeof (MyTypeHere));

On some occasions, I am getting an ILog object with Debug, Info, Warning, Error etc set to false. On other occasions the ILog object has them correctly set to true. Since my code does nothing to manipulate those flags, on the occasions when my code is passed the "disabled" ILog object messages from my code (understandably) do not get propagated at all.

I still cannot explain the apparent discrepancy between the two appenders.

+1  A: 

We regularly use the logfile, console and smtp appenders together and we don't seem to have these issues. Under certain conditions, some appenders can lose messages because of their inherent nature. For example, the UDP appender, because of the transport mechanism, isn't guaranteed to transmit all messages. Same thing happens with the SMTP appender. If you are using a common log file but logging from several processes, sometimes the file is locked by another process (this usually throws an exception, but it might be getting caught somewhere in your code), so be sure to set the Minimal Lock property on it. Also, the appenders can be buffered, so if there is a process crash, log4net might not have a chance to flush out the buffered data.

In the end the most reliable appenders are those that log locally, such as the file and the event log appenders, but then you have to harvest all the logs. If you want to log centrally, you might want to consider logging to a database or a message queue.

TskTsk
Good point about the non-local appenders like the UDP one. The thing I found really odd was that the UDP appender was actually capturing more than the console one. As I also commented to Konrad the problem appears to be execution dependent. For a given run of the application items from event source X may or may not be logged... but their presence (or absence) is consistent for that run.
Richard J Foster
That is odd. Are you logging from the thread your app is running on or are you using the threadpool or some other threading mechanism when you write to the log?
TskTsk
Log entries are (or at least should be) coming from the application thread, or worker items processed using the ThreadPool via the QueueUserWorkItem mechanism. Log entries from both thread sources appear to be present in all of the test runs I did.
Richard J Foster
+1  A: 

Do I understand correctly that some messages which are normally logged successfully suddennly stop appearing (being logged) at some point? If that is the case, then I would suggest turning on the internal logging of log4net. Alternativly debug the issue with log4net code (with your problem I'd suggest breaking somewhere around CallAppenders method in Logger class. It will tell you which appenders will actually be called for a logging event).

If some messages are consistently are not being logged then I would look at the log4net configuration. Check for any levels/thresholds being set and more importantly, if you are using loggers check that their names and make sure that the prefix of whatever you put into LogManager.GetLogger(...) call matches the name loggers in your config.

I double what jvilalta said. I have been using log4net for years now with many types of appenders and I have not seen a situation where a message would be missing from only some of appenders but not all.

Konrad
It's the first time I've seen this problem too. I've had nothing but good results with log4net in the past (and have never had concerns about entries being lost - at least when going to local appenders like the file based one). The odd thing is it appears to be execution dependent. For a given run of the application items from event source X may or may not be logged... but their presence (or absence) is consistent for that execution of the application.
Richard J Foster