Log4Net Tutorial pt 5: Using Logger Objects

§ June 26, 2008 07:40 by beefarino |

We've done a lot log4net configuration in the last few tutorials; time to mix in some code and discuss loggers.  This post is meant to show you the most common pattern of logger use.

Crack open Visual Studio, create a new console project, and add a reference to the log4net assembly.

Add the following application configuration file to the project:

<configuration>
  <configSections>
    <section name="log4net"
      type="log4net.Config.Log4NetConfigurationSectionHandler, log4net"/>
  </configSections>

  <log4net>

    <appender name="ConsoleAppender" type="log4net.Appender.ConsoleAppender">
      <layout type="log4net.Layout.PatternLayout">
        <conversionPattern value="%logger [%level]- %message%newline" />
      </layout>
    </appender>

    <root>
      <level value="ALL" />
      <appender-ref ref="ConsoleAppender" />
    </root>
  </log4net>
</configuration>

Add the following code to your program.cs file:

namespace Tutorial5_Loggers
{
    class Program
     {
        private static log4net.ILog Log = log4net.LogManager.GetLogger( System.Reflection.MethodBase.GetCurrentMethod().DeclaringType );

        static void Main( string[] args )
        {
            log4net.Config.XmlConfigurator.Configure();
            Log.Info( "this is an info message" );
            Console.ReadLine();
        }
    }
}

The logger object is created on line 5 via a the call to LogManager.GetLogger.  Compile and run and check out the output; it'll be similar to the following:

Tutorial5_Loggers.Program [INFO]- this is an info message

The first item in the log entry printed to the console is the name of the logger object that issued the log entry.  Because GetLogger was passed a reference to my Program type, the logger name is the fully qualified type name of the Program object.

Add another class to the project:

namespace Tutorial5_Loggers
{
    class MyClass
    {
        private static log4net.ILog Log = log4net.LogManager.GetLogger( System.Reflection.MethodBase.GetCurrentMethod().DeclaringType );

        public static void WriteLog()
        {
            Log.Info( "this is an info message" );
        }
    }
}

and add a call to MyClass.WriteLog to your Main method (see line 7 below):

static void Main( string[] args )
{
    log4net.Config.XmlConfigurator.Configure();

    Log.Info( "this is an info message" );

    MyClass.WriteLog();
    Console.ReadLine();
}

Compile and run, and note the logger name in the second log statement matches the type name of MyClass:

Tutorial5_Loggers.Program [INFO]- this is an info message
Tutorial5_Loggers.MyClass [INFO]- this is an info message

Hierarchical Logger Configuration

You can use loggers this way to isolate logging concerns across your objects, and I wholly recommend you do so.  This will enable you to throttle and direct log output from individual loggers using log4net's hierarchical configuration mechanism.

Update your app.config to the following:

 
<configuration>
  <configSections>
    <section name="log4net" type="log4net.Config.Log4NetConfigurationSectionHandler, log4net"/>
  </configSections>

  <log4net>
    <appender name="ConsoleAppender" type="log4net.Appender.ConsoleAppender">
      <layout type="log4net.Layout.PatternLayout">
        <conversionPattern value="%logger [%level]- %message%newline" />
      </layout>
    </appender>
    <appender name="FileAppender" type="log4net.Appender.FileAppender">
      <file value="log-file.txt" />
      <appendToFile value="false"/>
      <layout type="log4net.Layout.PatternLayout">
        <conversionPattern value="%logger [%level]- %message%newline" />
      </layout>
    </appender>

    <root>
      <level value="ALL" />
    </root>
    <logger name="Tutorial5_Loggers">
      <level value="ALL" />
      <appender-ref ref="FileAppender" />
    </logger>
    <logger name="Tutorial5_Loggers.Program">
      <level value="ALL" />
      <appender-ref ref="ConsoleAppender" />
    </logger>
    <logger name="Tutorial5_Loggers.MyClass">
      <level value="ALL" />
    </logger>
  </log4net>
</configuration>

On line 12 we add a file appender to the mix; lines 23-33 provide configuration for specific logger objects.  Note that the logger names correspond directly to the namespace-qualified type names and namespaces from our project.  Specifically:

  • on line 23 a logger is configured specifically for the "Tutorial5_Loggers" namespace; this logger is configured to write logs to the file appender;
  • on line 27, a logger is configured for the Program class; this logger is configured to write logs to the console;
  • on line 31, a logger is configured for the MyClass class; this logger is not configured with an appender.

Compile and run, and you'll notice that:

  • the console output displays only the log statement from the Program class;
  • a "log-file.txt" file is written in the application folder, and this file contains the log statements from both the Program and MyClass types.

Now change the level value for the Tutorial5_Loggers.MyClass from ALL to OFF:

<logger name="Tutorial5_Loggers.MyClass">
  <level value="OFF" />
</logger>

Compile and run, and note that the log-file.txt file no longer contains the log statement from the MyClass object.  

This hierarchical configuration system can be incredibly useful; a common practice is to disable logging of "verbose" objects by targeting their specific type with a logging level set to OFF; another is to provide a "specific-needs" logger configured with a special appender, such as a gateway to the windows event log or a remote log viewer.  However, the system has a few caveats you need to know about:

  • appenders accumulate through the hierarchy: if the Program class and Tutorial5_Logger namespace are each configured to append to the console, any log from the Program class will show up twice in the console (once for the class logger and once for the namespace logger);
  • logger levels deeper in the hierarchy trump the shallow ones: if the Program class logging level is set to ALL and the Tutorial5_Logger namespace logging level is set to OFF, logs from the program class are still written to the appenders configured for Tutorial5_Logger.

Coming Up

The first 5 tutorials have given you some pretty heavy-hitting abilities.  Next time I'll discuss associating context to log messages, which can provide invaluable debugging information. 



SVN Log Parsing with Powershell

§ June 20, 2008 07:47 by beefarino |

I absolutely love powershell.  I would estimate that over the past 6 months, powershell has saved me about two work weeks of time.

Case in point: next week we're entering a rather bulky merge phase across - count 'em now - four branches of the same project.  I needed a list of all of my commits for each branch to use as a cross-reference.  I thought about seeking out or coding up a SVN log parser, until I saw my powershell console and realized I didn't need to.  After a half-minute of hacking, I came up with this little diddy:

( [xml] ( svn log --xml | join-string -sep "" ) ).log.logentry |
 ? { $_.author -eq "jim christopher" } |
 format-list

In a nutshell, this one-liner requests the SVN log, filters log entries with my SVN username as the author, and formats them as a very readible list.

And that's the "power" in "powershell:" when I need a quick hack, powershell is there for me; but when I need the reliability and safety of objects, it's there for me too.

Enjoy! 

 



Log4Net Tutorial pt 4: Layouts and Patterns

§ June 20, 2008 04:32 by beefarino |

After that rather lengthy post about common appenders, this discussion of patterns and layouts should be short and sweet.

A layout is just a template for your log messages.  Layouts are specified per-appender, and you can specify only one layout for an appender:

<appender name="ColoredConsoleAppender" type="log4net.Appender.ColoredConsoleAppender">
    <layout type="log4net.Layout.SimpleLayout" />
</appender>

We've been using the SimpleLayout in the previous tutorials.  This is the easiest layout to use and yields rather a Spartan log:

DEBUG - this is a debug message
INFO - this is an info message
WARN - this is a warn message
ERROR - this is an error message
FATAL - this is a fatal message

The PatternLayout allows you to specify a printf-style template for your log entries using a "conversion pattern," and gives you the opportunity to decorate each entry with some valuable instance data.  For instance, this configuration:

<appender name="ColoredConsoleAppender" type="log4net.Appender.ColoredConsoleAppender">
    <layout type="log4net.Layout.PatternLayout">
        <conversionPattern value="%date [%thread] %-5level %logger - %message%newline" />
    </layout>
</appender>

produces a log that appears like so:

2008-06-20 12:29:03,541 [2684] DEBUG Tutorial4.Program - this is a debug message
2008-06-20 12:29:03,556 [2684] INFO  Tutorial4.Program - this is an info message
2008-06-20 12:29:03,556 [2684] WARN  Tutorial4.Program - this is a warn message
2008-06-20 12:29:03,556 [2684] ERROR Tutorial4.Program - this is an error message
2008-06-20 12:29:03,556 [2684] FATAL Tutorial4.Program - this is a fatal message

The conversion pattern string can include literal text and the following format expressions:

expressionvalue
%appdomain the friendly name of the appdomain from which the log entry was made
%date the local datetime when the log entry was made
%exception a formatted form of the exception object in the log entry, if the entry contains an exception; otherwise, this format expression adds nothing to the log entry
%file the file name from which the log entry was made; note that using %file has a significant performance impact and I don't recommend using it
%identity the user name of the active user logging the entry; this one is less reliable than %username; note that using %identity has a significant performance impact and I don't recommend using it
%level the severity level of the log entry (DEBUG,INFO, etc)
%line the source code line number from which the log entry was made; slow
%location some rudimentary call stack information, including file name and line number at which the log entry was made; using
%logger the name of the logger making the entry; more on this in a bit
%method the name of the method in which the log entry was made; also slow
%message the log message itself (don't forget this part!)
%newline the value of Environment.NewLine
%timestamp the milliseconds between the start of the application and the time the log entry was made
%type the full typename of the object from which the log entry was made
%username the Windows identity of user making the log entry; slow
%utcdate the UTC datetime when the log entry was made
%% a percent sign (%)

This sample output is from a single log entry using a conversion pattern containing all of the format expressions above:

%appdomain: Tutorial4_LayoutsAndPatterns.vshost.exe
%date: 2008-06-20 13:04:38,020
%exception:
%file: D:\Project\Log4NetTutorial\Log4NetTutorial\Tutorial4_LayoutsAndPatterns\Program.cs
%identity:
%level: INFO
%line: 14
%location: Tutorial4_LayoutsAndPatterns.Program.Main(D:\Project\Log4NetTutorial\Log4NetTutorial\Tutorial4_LayoutsAndPatterns\Program.cs:14)
%logger: Tutorial4_LayoutsAndPatterns.Program
%method: Main
%message: this is an info message
%timestamp: 1015
%type: Tutorial4_LayoutsAndPatterns.Program
%username: MYDOMAIN\username
%utcdate: 2008-06-20 17:04:38,020
%%: %

If you want a highly structured and queryable log, then XMLLayout is for you:

<appender name="ColoredConsoleAppender" type="log4net.Appender.ColoredConsoleAppender">
      <layout type="log4net.Layout.XMLLayout" />
    </appender>

The XMLLayout produces a stream of XML elements representing individual log entries:

<log4net:event logger="Tutorial4_LayoutsAndPatterns.Program" timestamp="2008-06-20T13:17:44.2863922-04:00" level="DEBUG" thread="2156" domain="Tutorial4_LayoutsAndPatterns.vshost.exe" username="POKERTEK\jchristopher">
    <log4net:message>this is a debug message</log4net:message>
    <log4net:global-properties>
        <log4net:data name="log4net:HostName" value="nc-jchri-l-3" />
    </log4net:global-properties>
</log4net:event>
<log4net:event logger="Tutorial4_LayoutsAndPatterns.Program" timestamp="2008-06-20T13:17:44.3176424-04:00" level="INFO" thread="2156" domain="Tutorial4_LayoutsAndPatterns.vshost.exe" username="POKERTEK\jchristopher">
    <log4net:message>this is an info message</log4net:message>
    <log4net:global-properties>
        <log4net:data name="log4net:HostName" value="nc-jchri-l-3" />
    </log4net:global-properties>
</log4net:event>

A few caveats you should note regarding the XMLLayout:

  • the log will contain a flat collection XML elements, but no containing root element; this means that you have to do some fernagling to read the XML as a document;
  • each log entry will contain the username and identity values (see the table above), which are expensive to read and may have a noticable impact on application performance.

Coming Up

That rounds out a lot of our configuration discussion.  Next time I'll jump back into code and discuss logger objects, which are simply sources of log messages.  I'll show you how to organize your logging activity by object types to provide a more tractable log.



Dependency Infection

§ June 17, 2008 07:27 by beefarino |

This post is about Dependency Injection frameworks.  It's not a survey, but you can find a good one here.

No, I'm afraid this is more of a rant.  You see, I'm a big fan of DI, and there's a pattern showing up in many of the frameworks that I don't care for: the frameworks want to infect my objects with dependencies in order to support the framework itself.  

In almost all cases the new requirements take the form of attributes on types, members, and parameters to "assist" the IoC container.  For example, if I choose Unity, I'm expected to pepper [Dependency] attributes on my object members.  If I use Ninject I need similar attributes to control activation behavior of my object.  Castle has a similar attribute serving the same purpose, but its use is optional.

I'm not picking on these frameworks specifically, they're just the examples that came to mind first.  A framework that forces me to use attributes like these leaves a bad taste in my mouth.  Why?  Because I don't think my objects should need to know anything about the framework managing their dependents and dependencies.  I see it as a Bad Thing™ for several reasons:

  1. The code behind my object must now manage its main purpose and how it will participate in the IoC container.  This violates the Single Responsibility principle I'm working so hard to uphold by using DI in the first place;
  2. Forcing my code to reference a specific DI library ties my object to that library.  If I end up using the object in another injection context (e.g., during unit tests, in another DI framework, or in a non-DI client), I have to drag the DI framework along for the ride.  This seems fishy when my goal is to decrease unnecessary coupling and isolate dependencies;
  3. Using attributes ties the DI context to the object's type definition, when the proper place for this context is the IoC container configuration.  For example, a type may be used as a singleton in one context, but as transient or pooled in another;
  4. These attributes don't appear to be necessary.  There are cleaner ways to communicate things like injection points, such as the CLR type model itself - e.g., public members and parameters are injectable, private members are not.

I want IoC to be a simple process of:

  1. Define types;
  2. Assemble them into a usable graph;
  3. There is nooooooooooooooooo step 3.

As I see it, the point of IoC is to get steps 1 and 2 to have as little to do with each other as possible.  When step 1 involves referencing the DI framework used in step 2 and decorating code, I hear a resounding "FAIL" in my head.

I've coined the phrase "dependency infection" to describe the proliferation of attributes and the addition of external dependencies mandated by some DI frameworks.  I plan to keep scoping out different IoC frameworks, but of late I keep coming back to Spring.NET and Castle and their complete acceptance of my bare naked and undecorated CLR objects.