Do you know what my favorite quote from the log4net faq website is?

Is log4net a reliable logging system?

No. log4net is not reliable.

Ah yes, welcome back to hell!  I remember growing up watching one of the “Road Films”, with Bing Crosby and Bob Hope, where they were dealing with a Voodoo Witch Doctor.  Fast forward to today and it’s like the authors of the Log4Net logging framework took inspiration from the movie. I wouldn’t be surprised if there is a special dance you have to do, or sacrifice to some 486 in an office somewhere to get this thing working correctly.

So I come into the office this morning to “logging’s not working and we’re configuring it correctly”… I figured about half of that statement was true, and went to verify that loggng still worked on my local machine, and I would verify it was working on the staging environment.  After all, everything was working well on Friday.  Right??  Did the temperature suddenly get very hot?  After bit of cussing, I found this gem:

When should I log my first message?

The simple answer is as soon as possible. The long answer is more complex.

If you are configuring log4net programmatically, i.e. by calling the XmlConfigurator.Configure method then you should do so before you begin logging and it is reasonable to do this very soon after application start.

If you are configuring log4net by specifying assembly level attributes on your assembly then the configuration will be loaded once the first call to theLogManager.GetLogger is made. It is necessary that the first call to LogManager.GetLogger made during the process (or AppDomain) is made from the assembly that has the configuration attributes. Log4net will look only once and only on the first calling assembly for the configuration attributes.

Well that just makes perfect sense, right?  Whatever assembly happens to log first, that’s the configuration everyone is going to use.  I’m not going to bother asking why the guys felt that including configuration via assembly attribute was necessary, or even desired if this is the behavior.  So remember this little slice of code?

[assembly: log4net.Config.XmlConfigurator(ConfigFile = "log4net.config", Watch = true)]

Yeah that was fairly worthless.

So what I had to do, was create a global.asax which would make the appropriate calls for log4net to be configured correctly on the startup of my application:

protected static readonly log4net.ILog log =
log4net.LogManager.GetLogger(System.Reflection.MethodBase.GetCurrentMethod().DeclaringType);
    void Application_Start(object sender, EventArgs e)
    {
        String currentWebRootFilePath = System.Web.Hosting.HostingEnvironment.ApplicationPhysicalPath;
        String api4netConfigPath = System.IO.Path.Combine(currentWebRootFilePath, "log4net.config");
        log4net.Config.XmlConfigurator.Configure(new System.IO.FileInfo(api4netConfigPath));
        log.Info("Starting " + System.Reflection.Assembly.GetExecutingAssembly().FullName);
    }

    void Application_End(object sender, EventArgs e)
    {
        //  Code that runs on application shutdown
        log.Info("Stopping " + System.Reflection.Assembly.GetExecutingAssembly().FullName);
    }

After testing and verifying it worked… again, I checked it in.  I’m fully expecting to write a third post in this series, so stay tuned.

Parsnips