Log4Net Hack: Customizing Log File Paths After Configuration

§ November 28, 2009 04:48 by beefarino |

I get a lot of log4net questions through my blog because of the tutorials I've written up.  One item that comes up frequently is how to configure a FileAppender to be able to write a single log file from multiple instances of the same application.  The truth is, you can't do it.  Or more precisely, there is no way to do it and expect not to lose log events and have your application performance suffer greatly.

First let me show you how to allow multiple applications access to a single log file.  It's actually quite easy:

 <?xml version="1.0" encoding="utf-8" ?>
 <configuration>
  <configSections>
    <section name="log4net" type="log4net.Config.Log4NetConfigurationSectionHandler, log4net"/>  
  </configSections>
  <log4net>
    <appender name="FileAppender" type="log4net.Appender.FileAppender">
      <file value="log-file.txt" />
      <appendToFile value="true" />
      <lockingModel type="log4net.Appender.FileAppender+MinimalLock" />
      <layout type="log4net.Layout.SimpleLayout" />         
    </appender>
    <root>
      <level value="DEBUG" />
      <appender-ref ref="FileAppender" />      
    </root>    
  </log4net>
  
</configuration> 

Since I discuss the parameters and pitfalls of the FileAppender elsewhere, I will leave it to you to read up on them more if you want to.  The locking mode being used here is causing log4net to acquire the file handle before each log event, then close the handle after the log event is written.  Doing this allows other applications to get write access to the file when no one else is currently logging, but the technique has a few serious flaws that should prevent you from using it:

  1. All of that file opening and closing seriously hampers performance;
  2. The log file will be shared, but access conflicts will still occur between applications attempting to log events at the same time, resulting in more performance degredation and "dropped" log events.

You may be able to address some of the performance issues using a BufferingForwardingAppender that sends large chunks of events to the minimally-locking FileAppender; however this will not resolve the contention over the single log file that is at the root of the issue.

The simplest solution to this problem is to use a different type of appender that is designed for concurrent use.  For instance, the EventLogAppender or AdoNetAppender use technologies that will manage concurrency issues for you.  If you're dead set on using the filesystem, the next simplest solution is to have each application log to a unique file, thus removing any log file contention at runtime.  The separate log files can be collated once the run is over using a tool like LogParser.  The drawback to this approach is that you have to hack it in: there is no direct way to modify the filename in the FileAppender based on the runtime environment.

That said, it's not hard.  Check out this simple console application:

using System;
using System.Collections.Generic;
using System.Linq;
using System.Text;
using log4net;
using log4net.Appender;
namespace log4netPostConfig
{
    class Program
    {       
        static void Main( string[] args )
        {
            log4net.Config.XmlConfigurator.Configure();
            var filePostfix = "_" + Guid.NewGuid().ToString( "N" );
            
            var fileAppenders = from appender in log4net.LogManager.GetRepository().GetAppenders()
                                where appender is FileAppender
                                select appender;
            fileAppenders.Cast<FileAppender>()
                .ToList()
                .ForEach(
                    fa =>
                    {
                        fa.File += filePostfix;
                        fa.ActivateOptions();
                    }
                );
            ILog Log = log4net.LogManager.GetLogger( System.Reflection.MethodBase.GetCurrentMethod().DeclaringType );
            Log.InfoFormat( "this process is using log file postfix [{0}]", filePostfix );
        }
    }
} 

This example loads the logging configuration from the app.config (line 14).  The log4net configuration is searched for instances of FileAppenders (line 16), which have their filename parameters handrolled with some process-specific information (line 25) - a GUID in this case, the current process identifier may be another good choice.  Calling the ActivateOptions on each modified appender is vital (line 26), as it recreates each file handle using the new filename configuration parameter set in the code.

The app.config for this example is just a plain vanilla logging configuration:

<?xml version="1.0" encoding="utf-8" ?>
 <configuration>
  <configSections>
    <section name="log4net" type="log4net.Config.Log4NetConfigurationSectionHandler, log4net"/>  
  </configSections>
  <log4net>
    <appender name="FileAppender" type="log4net.Appender.FileAppender">
      <file value="log-file.txt" />
      <appendToFile value="true" />
      <encoding value="utf-8" />
      <layout type="log4net.Layout.SimpleLayout" />         
    </appender>
    <root>
      <level value="DEBUG" />
      <appender-ref ref="FileAppender" />      
    </root>    
  </log4net>
  
</configuration>

Note that the log-file.txt specified in the app.config will be created when the XML logging configuration is loaded (line 13 in my code example above), but it will never be written to.

Edit Notes

I just noticed after publishing this that a very similar example was written almost 2 months ago by Wil Peck.



Twitter Appender for Log4Net

§ July 7, 2009 04:13 by beefarino |

Casey Watson just published a post describing how to create a Twitter appender for log4net!  Not only is the idea creative and fun, but it's also great sample code if you want to build your own custom appenders.

Please check it out here: http://caseywatson.com/2009/07/07/log4net-twitter-awesome/

NICE WORK CASEY!



Death by Logging Mantra #1 - Logs Consume Space

§ June 15, 2009 18:03 by beefarino |

As much as I love and lean on logging, it's not immune from problems.  In fact, it can be the source of some serious headaches.  A recent snafu at work prompted me to write about some situations where logging can bring your application performance to a screeching halt, or crash your application altogether. 

Here's what happened...

An incredibly complex system of hardware and software had been running smoothly for months; as part of an instrumentation layer we opted to change the rolling log strategy from 50 10MB text files:

...
<appender name="TextFile" type="log4net.Appender.RollingFileAppender">
    <file value="logs\log.txt" />
    <appendToFile value="true" />
    <rollingStyle value="Size" />
    <maxSizeRollBackups value="50" />
    <maximumFileSize value="10MB" />
    <layout type="log4net.Layout.XMLLayout">
      <prefix value="" />
    </layout>
</appender>
... 

to 500 1MB xml files:

...
<appender name="XmlFile" type="log4net.Appender.RollingFileAppender">
    <file value="logs\log.xml" />
    <appendToFile value="true" />
    <rollingStyle value="Size" />
    <maxSizeRollBackups value="500" />
    <maximumFileSize value="1MB" />
    <staticLogFileName value="false" />
    <countDirection value="1" />
    <layout type="log4net.Layout.XMLLayout">
      <prefix value="" />
    </layout>
</appender>
... 

As an ardent log4net user, I am aware of the performance impact of rolling a large number of files - if the CountDirection setting of the RollingFileAppender is less than 0 (which it is by default), the system will rename every log file each time the log rolls over.  This is costly, and in our product configuration that would mean up to 500 file renames on each roll. 

"Good thing I know what I'm doing...."

Several hours after firing up the new configuration a college asked me to come look at the device.  It had slowed to a wounded crawl.   I went to dig into the logs - I popped over to the log drive and started to find the most recent one.

... but there were 2000 log files, not 500.  The 2GB drive dedicated to the log was completely full.  And the application was still trying to write new log entries, which meant a slew of IO Exceptions were being continuously thrown by multiple threads.

"Um, I think I may have found the problem..."

I removed the oldest 1999 log files and the device immediately recovered.

So what happened?

The configuration XML is 100% correct.  The problem was that I accidentally deployed the software to the device with an old beta version of log4net 1.2.9; that particular version contains a bug in the RollingFileAppender code that prevents the MaxSizeRollBackups from being honored when CountDirection was >= 0.  Without the logs being limited in number, the software eventually filled up the hard disk with log entries.

Which bring me to my first death-by-logging mantra...

Logs Consume Space

It sounds silly I know, but this is the single most prevalent antipattern I see with any logging implementation.  There is a finite amount of storage space, and you need to make sure your logging activity doesn't consume more than its share.

I frequently see this when apps use FileAppender - this beast has no chains and, as I've stated elsewhere, you should never ever use it.  Ever.  Even in "little" applications it can cause massive trouble because the log accumulates over process time or application runs with no checks.  I've seen a 1KB application with 3GB of logs spanning almost a year of activity.

But don't think the problem is limited to the file-based appenders.  Remember....

  • memory is finite...
  • event logs fill up more often than you think...
  • a database can be configured to boundlessly expand as needed...
  • mail servers generally put caps on the size of an inbox...

Whichever appender strategies you choose, you should carefully consider the following:

... How much persistent storage are you allocating to the log?  Your answer should be a firm number, like "500MB", and not "the rest of the disk".  If you can, base this on the amount of information you need to have access to.  If a typical run of your application results in 10MB of logs, you can base the allocated size on the number of runs you want to persist.  If your application runs continuously - like a web site or windows service - you can plot out the logging activity over time, then gauge the allocation size from the time span of activity you want to persist.

... How will you cope when the allocated storage is used up?  Some appenders, like the RollingFileAppender, can handle this for you by freeing up space used by old log entries.  Others, like the EventLogAppender or the AdoNetAppender, blithely log without regard to the amount of space being consumed, and it's up to you to manage the size of the log in other ways.  E.g., I've seen SQL jobs dedicated to removing log records older than N hours, or truncating the log table to the N newest records.

... What happens when you log to a full repository?  Plan for success, but understand the causes of failure.  As I recently learned, our application slows down significantly when the log drive is full, so now checking the free space of the log drive is now included in our troubleshooting guide as a checklist item under "Application Performance Issues".  Test your application under limited logging resources to understand how it will behave.

The most important thing to remember is that logging, like any other subsystem of your application, needs to be planned, tested, and verified.



Log4Net Tutorials and Resources

§ June 7, 2009 03:57 by beefarino |

I've been meaning to create a landing page for all the log4net traffic on my blog.  A friend of mine recently told me how difficult it is to drill through all the tutorials, so I decided to organize access to all the log4net stuff in one place.  I'll keep this page updated as the blog grows. 

If there are any log4net resources you think I should add to this list or blog about, please add them in the comments or send them to me via the contact link.

Log4Net Tutorials

If you've never used log4net before, you should begin with the getting started and configuration topics.  You'll want to review the appender, layout, and patterns tutorials next, and use the others as you see fit.

  • Getting Started with Log4Net - never used log4net before, but need to get running quickly?
  • Basic XML Configuration - describes how to isolate log4net configuration to an XML file for easier modification.
  • Appenders - a discussion of the catalog of appenders available in the log4net distribution. Need to figure out how to log to the console? Or a text file? Or a database? This tutorial is for you.
  • Layouts and Patterns - want more control over the way your log looks?
  • Using Logger Objects - learn to use logger objects to organize your logging code into independently configurable parts.
  • Log Event Context - need some extra data in that log message? Maybe a call stack label, user identifier, or session moniker?
  • Filters - learn how to tame that log output and filter out the stuff you don't want or need.
  • Lossy Logging - learn about an advanced technique of optimizing your logging activity. Lossy logging gives you the benefit of a verbose log with the performance of a minimal logging scenario.

Recomended Practices

  • Your Code - learn what you should do in your code to make the most of logging.
  • Isolating Bugs - see how logging can be used to isolate production bugs.

Death by Logging Mantras

These mantras discuss specific scenarios where logging can cripple your application or its performance.  These are in-process and links will become available as I write the posts.

Resources