Log4Net Tutorial pt 2: Basic XML Configuration

§ June 6, 2008 06:07 by beefarino |

Previously, I offered a quick overview of using log4net.

In this post, I'll show you how to use an XML file to configure log4net, and demonstrate some of the basic ways you can control the verbosity of your log.

Using the XML Configurator

Open Visual Studio, create a new console application, and add a reference to the log4net assembly.  Add the following code to your Main() method:

using System;

namespace Tutorial2_BasicXmlConfiguration
{
    class Program
    {
        static void Main( string[] args )
        {
            log4net.Config.XmlConfigurator.Configure();
            log4net.ILog log = log4net.LogManager.GetLogger( typeof( Program ) );

            log.Info( "beginning loop" );

            for( int c = 0; c < 100; ++c )
            {
                log.DebugFormat( "iteration #{0}", c );
            }

            log.Info( "loop has completed" );

            Console.ReadLine();            
        }
    }
}

On line 9, log4net is bootstrapped using the XmlConfigurator.  This configuration strategy relies on an XML document to supply configuration for log4net.  The static Configure method is overloaded to accept the configuration XML from a file, stream, URI, or an XmlElement object; the parameterless form of the method used here instructs log4net to load the XML from the application's configuration file.  

In addition to the Configure method, the XmlConfigurator offers a static ConfigureAndWatch() method that accepts a FileInfo reference.  ConfigureAndWatch() will monitor the configuration XML file and reconfigure log4net when a change is detected.  This allows you to alter logging behavior at whim while the application is running - very handy for troubleshooting applications in the field, but it adds overhead in the form of a FileSystemWatcher used to monitor the configuration file.

Add the following application configuration file to the console project:

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

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

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

There are a few important things in there.  First is the declaration of the log4net configuration section on line 3; this is mandatory.  The log4net configuration takes up lines 6-15.  There are two parts to the configuration:

  1. one or more appender declarations taking the form of <appender /> elements, and
  2. the root logger declaration, represented by the <root /> XML element.

A real discussion of appenders will have to wait; for now, suffice it to say that a log4net appender is a place where your log entries end up.  In this case, the log is being "appended" to the console.

The root logger controls the general behavior of log4net.  In this example, the root logger is told to send everything to the console appender.

Time to compile and run.  You'll get the following output:

INFO - beginning loop
DEBUG - iteration #0
DEBUG - iteration #1
DEBUG - iteration #2
DEBUG - iteration #3
DEBUG - iteration #4
DEBUG - iteration #5
DEBUG - iteration #6
DEBUG - iteration #7
DEBUG - iteration #8
DEBUG - iteration #9
DEBUG - iteration #10
DEBUG - iteration #11
DEBUG - iteration #12
DEBUG - iteration #13
DEBUG - iteration #14
DEBUG - iteration #15
DEBUG - iteration #16
DEBUG - iteration #17
DEBUG - iteration #18
DEBUG - iteration #19
DEBUG - iteration #20
DEBUG - iteration #21
DEBUG - iteration #22
DEBUG - iteration #23
DEBUG - iteration #24
DEBUG - iteration #25
DEBUG - iteration #26
DEBUG - iteration #27
DEBUG - iteration #28
DEBUG - iteration #29
DEBUG - iteration #30
DEBUG - iteration #31
DEBUG - iteration #32
DEBUG - iteration #33
DEBUG - iteration #34
DEBUG - iteration #35
DEBUG - iteration #36
DEBUG - iteration #37
DEBUG - iteration #38
DEBUG - iteration #39
DEBUG - iteration #40
DEBUG - iteration #41
DEBUG - iteration #42
DEBUG - iteration #43
DEBUG - iteration #44
DEBUG - iteration #45
DEBUG - iteration #46
DEBUG - iteration #47
DEBUG - iteration #48
DEBUG - iteration #49
DEBUG - iteration #50
DEBUG - iteration #51
DEBUG - iteration #52
DEBUG - iteration #53
DEBUG - iteration #54
DEBUG - iteration #55
DEBUG - iteration #56
DEBUG - iteration #57
DEBUG - iteration #58
DEBUG - iteration #59
DEBUG - iteration #60
DEBUG - iteration #61
DEBUG - iteration #62
DEBUG - iteration #63
DEBUG - iteration #64
DEBUG - iteration #65
DEBUG - iteration #66
DEBUG - iteration #67
DEBUG - iteration #68
DEBUG - iteration #69
DEBUG - iteration #70
DEBUG - iteration #71
DEBUG - iteration #72
DEBUG - iteration #73
DEBUG - iteration #74
DEBUG - iteration #75
DEBUG - iteration #76
DEBUG - iteration #77
DEBUG - iteration #78
DEBUG - iteration #79
DEBUG - iteration #80
DEBUG - iteration #81
DEBUG - iteration #82
DEBUG - iteration #83
DEBUG - iteration #84
DEBUG - iteration #85
DEBUG - iteration #86
DEBUG - iteration #87
DEBUG - iteration #88
DEBUG - iteration #89
DEBUG - iteration #90
DEBUG - iteration #91
DEBUG - iteration #92
DEBUG - iteration #93
DEBUG - iteration #94
DEBUG - iteration #95
DEBUG - iteration #96
DEBUG - iteration #97
DEBUG - iteration #98
DEBUG - iteration #99
INFO - loop has completed

Taming log4net Output

This example logs a fair amount of cruft.  The DEBUG-level logging inside of the loop overshadows the INFO-level logging outside of the loop.  In a real scenario, this DEBUG-level output may be necessary when troubleshooting application behavior, but it becomes a lot noise when instrumenting the application in production.

Thankfully log4net provides a filter on the logging output.  In your project's app.config, find the <level /> XML element and alter it like so:

<level value="INFO" />

Compile and run; the program log is significantly truncated:

INFO - beginning loop
INFO - loop has completed

Specifically, all DEBUG-level log entries are missing from the log output.  The level value instructs the logger of the minimum level at which log entries should be processed.  It can be one of these values:

  • ALL: all log entries are appended to the log;
  • DEBUG: Debug, Info, Warn, Error, and Fatal messages are appended to the log.  This is functionally identical to ALL;
  • INFO: Info, Warn, Error, and Fatal messages are appended to the log;
  • WARN: Warn, Error, and Fatal messages are appended to the log;
  • ERROR: Error and Fatal messages are appended to the log;
  • FATAL: only Fatal messages are appended to the log;
  • OFF: all log entries are ignored.  Logging is effectively disabled in this case.

Coming Up

You have enough knowledge at this point to do some pretty powerful things; however, there's a lot more to be had from log4net.  Next time I'll discuss the many varieties of appenders that ship with log4net, and demonstrate how log4net can funnel a single log message to multiple places. 



Log4Net Tutorial pt 1: Getting Started

§ June 4, 2008 14:00 by beefarino |

I've found logging to be one of the most effective debugging and troubleshooting techniques in my engineering bag, but I'm surprised at how infrequently other people seem to use it.  The arguments orbit around the notion that adding any form of logging won't be that helpful, or that it will slow the application to a crawl.  My experience with application logging has been very positive, and quite frankly I would be a lot less effective without it.

This post is the first in a series aimed at making you comfortable and confident in using log4net as an application logging layer in your .NET applications.  Seriously, it'll make your life a lot easier.

About log4net

My logging layer of choice for .NET is log4net from the Apache Software Foundation.  It's open source, well-documented, extensible, and comes ripe with features right off the vine.  There are alternative logging platforms available if open source isn't an option for you, such as the Microsoft Logging Application Block or, if you're willing to fork out some cash, LucidLog.Net; I can't comment on them directly as I have no experience with either - I've heard good things, but I've also heard that log4net is more feature-rich that both of these.

Note: This series of posts references log4net version 1.2.10.

Getting log4net

log4net is available here as a zip archive. 

The archive contains a ton of stuff; for posterity, here are some hilites of what you'll find in there:

  • \bin houses the log4net binaries.  The distribution contains versions of log4net built for specific platforms of .NET, including Microsoft .NET, Mono, Rotor, and the Compact Framework.
  • \doc contains the log4net documentation.  Open index.html to start your perusing. 
  • \examples contains several small, digestible sample logging applications in various languages and platforms.
  • \src holds the log4net source code.
  • \tests contains unit tests for the log4net source code.

A Quick Example

  1. Open Visual Studio and create a new Console application project.
  2. Add to the project a reference to the \bin\net\2.0\release\log4net.dll assembly in the log4net distribution.
  3. Modify your Main() method like so:
using System;
namespace Tutorial1_GettingStarted
{
    class Program
    {
        static void Main( string[] args )
        {
            log4net.Config.BasicConfigurator.Configure();
            log4net.ILog log = log4net.LogManager.GetLogger( typeof( Program ) );           

            log.Debug( "Hello World!" );
            log.Info( "I'm a simple log4net tutorial." );
            log.Warn( "... better be careful ..." );
            log.Error( "ruh-roh: an error occurred" );
            log.Fatal( "OMG we're dooooooomed!" );
           
            Console.ReadLine();  // so you can read the output
        }
    }
}

 

Before running the application, take a close look at the code.  On line 8, the log4net subsystem is configured in the most basic way possible.  Using the BasicConfigurator will cause log4net to output log entries to the console using a default layout (more on layouts in a moment).  log4net configuration is a very broad topic and can get rather deep, but it can be this shallow and narrow too. 

Line 9 requests a logger from the LogManager object.  Logger objects implement the ILog interface, which is what your application will use to instrument itself and percolate log entries.

Lines 11-15 use the logger to log a few statements with various severity levels.  log4net defines 5 such levels:

  • Debug: fine-grained statements concerning program state, typically used for debugging;
  • Info: informational statements concerning program state, representing program events or behavior tracking;
  • Warn: statements that describe potentially harmful events or states in the program;
  • Error: statements that describe non-fatal errors in the application; this level is used quite often for logging handled exceptions;
  • Fatal: statements representing the most severe of error conditions, assumedly resulting in program termination.

Compile and run the application, and you'll see output to the console similar to the following:

93 [10] DEBUG Tutorial1_GettingStarted.Program (null) - Hello World!
156 [10] INFO Tutorial1_GettingStarted.Program (null) - I'm a simple log4net tutorial.
156 [10] WARN Tutorial1_GettingStarted.Program (null) - ... better be careful ...
156 [10] ERROR Tutorial1_GettingStarted.Program (null) - ruh-roh: an error occurred
156 [10] FATAL Tutorial1_GettingStarted.Program (null) - OMG we're dooooooomed!

 

Note that each log statement is accompanied by a bunch of data.  I mentioned that the BasicConfigurator uses a default layout; layouts determine how log4net formats a log statement.  In this case, the BasicConfigurator is using a layout that includes stuff like the identifier of the thread from which the log entry was made, the level of the log entry, etc.

Coming Up

That's it for now - just a quick survey of the logging landscape to get you started.  Next time I'd like to talk more about log4net configuration, specifically how to use the app.config file to make log4net ignore log entries below a certain severity level.



Adopting User Stories pt 3: Two Steps Forward

§ May 27, 2008 16:36 by beefarino |

We had a lot of problems trying to use user stories as the basis for a product backlog.  We haven't had a retrospective yet, and I anticipate having to wear my asbestos boxers for that wondrous event; however, I have noticed that some of the bigger picture aspects of what I tried to accomplish have established roots in the team.

Phrasing Requirements

One of the things I kept beating into the team's head was Mike Cohn's user story template

"As a <user role>, I want to <feature activity> so I can <value achieved>."

Sticking to this template helped us in many ways:

  • it pushed the team into thinking from the user's perspective, which greatly improved our ability to communicate about the feature by having a common, iconic user to reference;
  • it forced a value statement for every feature, which made blatantly evident the features that were also-rans;
  • it made creating acceptance tests a breeze.

Several other projects have flared up at the office, and what I'm seeing is the product owners continuing to use this template to communicate their requirements.  That means better discussion and more acceptance testing.  That makes me happy.

The Need for Accountability

One of the points of using user stories as the product backlog was to enable the team to develop vertical slices through the system - get a single feature working end-to-end - rather than horizontal slices - building up an entire system layer, such as a database or front-end in isolation.  I wanted a cycle of feedback for the team, get a feature into QA for testing, in front of the stakeholders for comment, back to the developers for refinement.  The softer side of the team - by that I mean the product owner and customer representatives - wanted that too.  But the vertical development never happened.  The developers simply would have no part of it, citing various reasons that are locally valid but miss the global point.  Instead, they chose to work on horizontal layers of the system.  Milestones came and went, no features were evident, and QA was sitting on their hands for over three weeks.

The stakeholders brought up the notion of recourse: how would development be held accountable for the missed milestones?  The answer, much to my chagrin, was that they would not.  There is no delicate way to explain the situation, but it may help to understand that the efforts of the developers were praised by their senior manager.  

I've been reeling over this for a week now, my eyes bloodshot from searching for a positive in this dim and ugly situation, and the thing I keep coming back to is this notion of transparency.  Everyone - the team, the stakeholders, and the innocent by-standers - knows why milestones were missed.  So at least we can collectively acknowledge the situation, and that there is a need for holding the team accountable for disrupting the feedback loop.

Or not, depending on the way the wind blows... 



A Coalesce Filter for PowerShell

§ May 22, 2008 16:49 by beefarino |

Here's a little PowerShell script that acts as a coalescing pipeline filter:

param( [scriptblock] $predicate={ $_ } )
begin
{
       $script:found = $false;
       $script:item = $null;
}
process
{
       if( ! $script:found -and ( &$predicate ) )
       {
               $script:found = $true;
               $script:item = $_;
       }
}
end
{
       return $script:item;
} 

When used as a pipeline filter, this script returns the first non-null object coming out of the executing pipeline.  Here's a simple example:

$value = @( $null, "first", "second" ) | coalesce;

The result of this script is that $value is equal to "first".  I find myself using this quite a bit for things like default values for optional parameters:

param( $p1, $p2 );
$value = @( $p1, $p2, "defaultValue" ) | coalesce; 

The $predicate parameter allows you to pass in your own criteria as a script block; e.g.:

$p1 = @( $a, $b, $c ) | coalesce { $_ -gt 1 };

will return the first value from the list greater than 1.

Looks a lot like the where-object filter, except that coalesce returns only the first object from the pipeline matching the specified criteria.

Enjoy!