Changing log4net FileAppender whilst logging

Question

Hi guys, We're trying to configure a server process so that, each time it receives a request, it logs that request to a NEW filename.

The process is generally single threaded but we cannot guarantee that no other thread somewhere in the code won't sometimes try to write something to log4net.

What seemed to be working is:

The first time we get a request, we configure a "PerRequest" FileAppender as follows:

fileAppender = new FileAppender();
log.InfoFormat("Initializing log4net per request logging");
log4net.Layout.PatternLayout layout = new Layout.PatternLayout("%date %property{processid} %property{username} %-5level %logger - %message%newline");
fileAppender.Layout = layout;
layout.ActivateOptions();
fileAppender.AppendToFile = true;
fileAppender.Name = "PerRunLogger";
fileAppender.File = makeNewRequestLogName(); // Returns a unique filename (uses a Guid)
log.InfoFormat("Configured PerRequest logger to log to '{0}'", fileAppender.File);
fileAppender.ActivateOptions();
log4net.Config.BasicConfigurator.Configure(fileAppender);

Then each time we get a new request, we do the following:

fileAppender.File = makeNewRequestLogName();
log.InfoFormat("Configured PerRequest logger to log to '{0}'", fileAppender.File);
fileAppender.ActivateOptions();

At the end of the request, we "configure" the PerRequest logger to log to a single filename, as we couldn't find a satisfactory way to turn it off..

This was working pretty well... But under heavy load, we started noticing that the "PerRequest" log file would often have huge chunks of "missing" log lines. e.g. something like this:

2009-09-23 19:17:17,133 4332 hollingp DEBUG PostProcessInfrastructure.PostProcessRunner - Started post processing
* normal log lines here, omitted for brevity *
2009-09-23 19:17:36,414 4332 hollingp DEBUG PluginRegistry.PostProcessVersions.PostProcessPluginCacheVersion - About to run pub_GetPostProcessingVersion stored proc

*Normally lots of log lines here, but every now and then, NOTHING *

2009-09-23 19:17:37,742 4332 hollingp DEBUG PostProcessInfrastructure.PostProcessRunner - Finished post processing

There's no good explanation for what we see in the log file - there's no code path (even if an exception is thrown) that would explain the "missing" log lines - something (quite a lot of stuff actually) should have been logged on that thread between the line at 19:17:36 and the line at 19:17:37.

Admittedly this entire technique is all a bit dodgy but we couldn't think of another way to do this.

So the first question is: is there a better way to achieve what we want?

The second question is: Can anyone explain what might be happening? The suspicion is that there's some thread safety/locking that needs to be performed, but where? What needs to be locked, if that's the case?

There's no risk of another process attempting to log to the same file, because as the comment in the code indicates, we allocate the log filename using a GUID - there's no chance that another process is trying to log to the same file... But another thread? We can't rule that out.

Answer 1

So the first question is: is there a better way to achieve what we want?

Does it have to be a separate file per request?

If not, what about creating your own custom pattern layout and make the request details part of the log pattern? An example Google found.

If it does, how about extending RollingFileAppender and change the new file condition so that instead of being related to file size (or whatever), it's based on the request?

I presume you've already experimented with the LockingModel?

Answer 2

From the log4net FAQ:

Many developers are confronted with the problem of distinguishing the log output originating from the same class but different client requests. They come up with ingenious mechanisms to fan out the log output to different files. In most cases, this is not the right approach.

It is simpler to use a context property or stack (ThreadContext). Typically, one would ThreadContext.Properties["ID"] = "XXX" client specific information, such as the client's hostname, ID or any other distinguishing information when starting to handle the client's request. Thereafter, log output will automatically include the context data so that you can distinguish logs from different client requests even if they are output to the same file.

See the ThreadContext and the PatternLayout classes for more information.