ScrumShocked

§ September 29, 2008 15:19 by beefarino |

I've been following a very interesting series of posts (starting here) from Matt Grommes detailing his experiences managing his first agile project; today he posted a sort of team retrospective.  Having cataloged my own successes and failures during by brief attempt at agile project management, I was eager to see how Matt's experiences compared to my own.  I was surprised to see that the problems he lists are either identical or orthogonal to mine (I was expecting one or the other, but not both).  For instance, Matt found as I did that keeping the backlog tasks and estimates accurate became an issue as the sprint wore on, and that failing to discuss and estimate the product backlog caused significant problems.  But while Matt's team concludes they did too much planning up-front and not enough later, but I think we had too little forethought and too much ad hoc cram-it-in work later.

In any event, Matt seems to have at least one very good thing going for him: his team is committed to improving themselves.  I hate to admit it, but we've reverted to the neverending ground-and-pound routine we've been maintaining for almost four years now.  We calling it "scrum," but I know it's not scrum and it's not agile because these things give it away:

  • we rarely estimate anything, we just beat on features and bugs until they're completed;
  • we almost always miss deadlines, which are fairly arbitrary anyway due to the lack of estimations;
  • we don't have much "team spirit" - or perhaps I'm simply excluded from it.  Instead specific indivuals are recognized as the owners of various parts of the system, and it's a bit of a political battle to be involved outside of your sandbox;
  • we generally have four or five projects ongoing, with team focus split between several of them at any given time;
  • we don't iterate or increment, we go dark for weeks, develop like madmen, and throw it over the wall to QA when we're done;
  • we don't retrospect projects anymore, we move immediately to the next project without discussing what worked or didn't work so things get better over time.

I find it odd that we would shun the beneficial aspects of scrum and agile - the transparency of our work, clarity of tasks, the focus on communication, the postponement of details, the sharing of labor, the confidence of cycles, the leverage of teamwork, the push to improve the team - while at the same time embracing a commitment to work full throttle to meet a deadline.

Well, good luck with it Matt, and keeps those posts coming - seems to me like y'all are off to a good start.



Log4Net Tutorial pt 8: Lossy Logging

§ September 11, 2008 15:42 by beefarino |

Ok, so I know I've said twice now that I was going to relay some real-life log4net experiences, but a few days ago Georg Jansen (author of the very kewl Log4Net Dashboard, which I plan to describe in a future post) demonstrated a feature of log4net I've never used before: lossy logging.  After using the feature for a few days, I'm completely sold on it and decided to write up another tutorial.

What is Lossy Logging?

Logging is a very useful tool, but it's not something you want to leave enabled in production if you don't need it.  Each log message take a few cycles away from your application, and the persistence of messages does consume system resources.  Of course you can configure log4net to disable logging, either by setting the root logger level to OFF or removing all appenders from the root logger.  The problem is that by disabling logging altogether, you won't get any juicy details if something goes awry in your application.

Lossy logging gives you a great compromise: under normal operation your application will not log any messages; however, if your application logs an error, a small batch of messages leading up to the error is placed into the log, giving you the error and a snapshot of system activity just before it happened.  How awesome it that?!

Lossy Logging Example

Open Visual Studio, create a new console project, and reference log4net.  Add the following code to the Program class:

namespace Tutorial8_LossyLog
{
    class Program
    {
        static void Main( string[] args )
        {
            log4net.Config.XmlConfigurator.Configure();
            static log4net.ILog Log = log4net.LogManager.GetLogger(
                System.Reflection.MethodBase.GetCurrentMethod().DeclaringType
            );
               
            for( int i = 0; i < 100; ++i )
            {
                Log.DebugFormat( "this is debug msg #{0}", i );
            }
               
            Log.Error( "error: an error occurred!" );           
            Log.Warn( "warning: you've been warned" );
        }
    }
}

The program outputs a series of 100 numbered debug log messages, followed by a single error message and a warning message.

Add an app.config to the project:

<?xml version="1.0" encoding="utf-8" ?>
<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>

    <appender name="LossyConsoleAppender" type="log4net.Appender.BufferingForwardingAppender">
      <bufferSize value="20" />
      <lossy value="true"/>
      <evaluator type="log4net.Core.LevelEvaluator">
        <threshold value="ERROR" />
      </evaluator>
      <appender-ref ref="ConsoleAppender" />
    </appender>

    <root>
      <level value="DEBUG" />
      <appender-ref ref="LossyConsoleAppender" />
    </root>
  </log4net>
</configuration>

The logging configuration defines two appenders, one very generic Console appender and a BufferingForwardingAppender.  As the name implies, the latter appender buffers log messages and forwards them in batches to one or more other appenders.  You can probably tell from the configuration XML that I've set this appender up with a 20-message buffer.  The lossy and evaluator parameters work together to define when the log message buffer is forwarded to the "base" appender.  More on that in a moment ....

Build and run; the command console will output the following:

DEBUG - this is debug msg #81
DEBUG - this is debug msg #82
DEBUG - this is debug msg #83
DEBUG - this is debug msg #84
DEBUG - this is debug msg #85
DEBUG - this is debug msg #86
DEBUG - this is debug msg #87
DEBUG - this is debug msg #88
DEBUG - this is debug msg #89
DEBUG - this is debug msg #90
DEBUG - this is debug msg #91
DEBUG - this is debug msg #92
DEBUG - this is debug msg #93
DEBUG - this is debug msg #94
DEBUG - this is debug msg #95
DEBUG - this is debug msg #96
DEBUG - this is debug msg #97
DEBUG - this is debug msg #98
DEBUG - this is debug msg #99
ERROR - error: an error occurred!

The program issues a total of 102 log messages (100 DEBUG, one ERROR, and one WARN), but the console only contains 20 messages (19 DEBUG and 1 ERROR).  So what happened to the other 82 DEBUG and WARN messages?

When the BufferingForwardingAppender's lossy property is enabled, the appender will buffer log messages without forwarding them.  If the buffer fills up, the oldest messages are dropped from the buffer to make room for the new messages.  

The evaluator property determines when the appender forwards the messages from the buffer to its base appenders.  There is only one evaluator defined in log4net - the LevelEvaluator.  The LevelEvaluator triggers the forward when a log message is received that meets or exceeds the configured threshold.  The example above is configured so that an ERROR message triggers the appender to forward its buffer to the ConsoleAppender.

Lossy Appender Types

Here is a list of appenders in the log4net distribution that can operate "lossy:"

log4net.Appender.AdoNetAppender
log4net.Appender.RemotingAppender
log4net.Appender.SmtpAppender
log4net.Appender.SmtpPickupDirAppender
log4net.Appender.BufferingForwardingAppender

Coming Up

Ok, seriously, next time it'll be all about log4net best practices, and I promise to show you how you can't live without it.  Really!



Log4Net Tutorial pt 7: Filters

§ September 5, 2008 06:37 by beefarino |

In the Context tutorial I said that my next log4net post would focus on real-world examples.  However, I received this request from a college in the U.K.:

I would like to have 2 logs, ... I would like to have levels Debug, Info & Warn logged to the one log and all Error & Fatal logged to the second log. ...  Do you know if this is possible with log4net?

This is very easy to do using a feature of log4net I haven't discussed yet: filters.  Filters are applied to individual appenders via the log4net configuration, and they help the appender determine whether a log event should be processed by the appender.  They may sound like the appender threshold property, and indeed some filters behave similarly; however, filters offer far more control over logging behavior.

Filter Example

Open Visual Studio, create a new console project, and reference log4net.  Add the following code to the Program class:

namespace Tutorial7_Filters
{
    class Program
    {
        static void Main( string[] args )
        {
            log4net.Config.XmlConfigurator.Configure();
            log4net.ILog Log = log4net.LogManager.GetLogger(
                System.Reflection.MethodBase.GetCurrentMethod().DeclaringType
               );
            Log.Fatal( "this is a fatal msg" );
            Log.Error( "this is an error msg" );
            Log.Warn( "this is a warn msg" );
            Log.Info( "this is an info msg" );
            Log.Debug( "this is a debug msg" );
        }
    }
}

Add an app.config to the project and update it like so:

<?xml version="1.0" encoding="utf-8" ?>
<configuration>
  <configSections>
    <section name="log4net" type="log4net.Config.Log4NetConfigurationSectionHandler, log4net"/>
  </configSections>
  <log4net>
    <appender name="LogFileAppender" type="log4net.Appender.FileAppender">
      <file value="log.txt" />
      <filter type="log4net.Filter.LevelRangeFilter">
        <levelMin value="DEBUG" />
        <levelMax value="WARN" />
      </filter>
      <layout type="log4net.Layout.SimpleLayout" />
    </appender>
    <appender name="ErrorFileAppender" type="log4net.Appender.FileAppender">
      <file value="errors.txt" />
      <filter type="log4net.Filter.LevelRangeFilter">
        <levelMin value="ERROR" />
        <levelMax value="FATAL" />
      </filter>
      <layout type="log4net.Layout.SimpleLayout" />
    </appender>
    <root>
      <level value="DEBUG" />
      <appender-ref ref="LogFileAppender" />
      <appender-ref ref="ErrorFileAppender" />
    </root>
  </log4net>
</configuration>

This configuration defines two file appenders, each with a unique filter applied (lines 12 and 23).  The filter on the first appender will log events with levels DEBUG, INFO, and WARN; the filter on the second appender will log event with levels ERROR and FATAL.

Build and run; the command console will flash for a moment with no output.  Check the working directory and open log.txt:

WARN - this is a warn msg
INFO - this is an info msg
DEBUG - this is a debug msg

Note that only the DEBUG, INFO, and WARN messages appear in this file.  The errors.txt log file contains only ERROR and FATAL log messages:

FATAL - this is a fatal msg
ERROR - this is an error msg

Filter Survey

Here is a list of the filters available in the log4net distribution:

Type NameDescription
log4net.Filter.LevelMatchFilter Filters log events that match a specific logging level; alternatively this can be configured to filter events that DO NOT match a specific logging level.
log4net.Filter.LevelRangeFilter Similar to the LevelMatchFilter, except that instead of filtering a single log level, this filters on an inclusive range of contiguous levels.
log4net.Filter.LoggerMatchFilter Filters log events based on the name of the logger object from which they are emitted.
log4net.Filter.StringMatchFilter Filters log events based on a string or regular expression match against the log message.
log4net.Filter.PropertyFilter Filters log events based on a value or regular expression match against a specific context property.
log4net.Filter.DenyAllFilter Effectively drops all logging events for the appender.

You can also define your own filter by implementing the log4net.Filter.IFilter interface or deriving from the log4net.Filter.FilterSkeleton class.

You can apply multiple filters to an appender; they will be evaluated as a chain in configuration order.  Each filter in the chain can either accept the message, deny the message, or punt to the next filter in the chain.   The first filter to explicitly allow or deny a log message stops the filter chain and determines the fate of log message.

Logger and Level Filters

The LoggerMatchFilter filters against the name of the logger emitting the message.  This filter can be configured using the following properties:

  • loggerToMatch: a string value to match against the message's logger name.  The match is made using the String.StartsWith method;
  • acceptOnMatch: a boolean value indicating whether a matching logger name results in accepting the message (true) or rejecting it (false).  This defaults to true, meaning that only matching logger names will be allowed into the appender.

The LevelMatchFilter filters against a specific log message level.  This filter can be configured using the following properties:

  • levelToMatch: the log level to match - either DEBUG, INFO, WARN, ERROR, or FATAL;
  • acceptOnMatch: a boolean value indicating whether to accept log levels matching the levelToMatch property (true), or reject log levels matching the levelToMatch property (false).  Defaults to true.

The LevelRangeFilter allows you to configure a range of log levels to filter on:

  • levelMin: the minimum log level to match - either DEBUG, INFO, WARN, ERROR, or FATAL;
  • levelMax: the minimum log level to match - either DEBUG, INFO, WARN, ERROR, or FATAL;
  • acceptOnMatch: a boolean value indicating whether to accept log levels matching the levelToMatch property (true), or to punt filtering to the next filter in the chain (false).  Defaults to true.  Note that any log level outside of the [levelMin, levelMax] range is denied by this filter.

Message and Property Filters

If you need to filter messages based on their message content, you need StringMatchFilter.  This filter can be configured as follows:

  • regexToMatch: a regular expression to match against the log message.  Note this regex is created with the Compiled option enabled for performance;
  • stringToMatch: a static string to match against the log message.  The match is made using the String.IndexOf method to see if the static string exists in the log message, which is a case-sensitive search.
  • acceptOnMatch: a boolean value indicating whether to accept log messages matching the string or regex (true), or to deny log messages matching the string or regex (false).  Defaults to true.  

Note that any log messages not matching the filter criteria are punted to the next filter in the chain.  If you specify both the regexToMatch and stringToMatch filters, the regexToMatch wins out and the string comparison is never executed, even if the regex fails to match.

The PropertyFilter performs the same behavior as the StringMatchFilter, except that the match is made against the value of a context property.  It is configured like so:

  • key: the name of the property value to match;
  • regexToMatch: a regular expression to match against the specified property value.  Note this regex is created with the Compiled option enabled for performance;
  • stringToMatch: a static string to match against the specified property value.  The match is made using the String.IndexOf method to see if the static string exists in the property value, which is a case-sensitive search.
  • acceptOnMatch: a boolean value indicating whether to accept messages with a property value matching the string or regex (true), or to deny messages with a property value matching the string or regex (false).  Defaults to true.  

Just like the StringMatchFilter, the PropertyFilter will punt filtering when the property value does not match the filter criteria, and regexToMatch trumps and excludes stringToMatch.  In addition, if the property identified does not exist in the current context, filtering is punted.

DenyAllFilter

This filter simply denies all filtering.  When this is used, it's always at the end of a filter chain to block unwanted log messages from the appender.

An Extended Example

Update Program.cs to the following:

namespace Tutorial7_Filters
{
    class Program
    {
        static void Main( string[] args )
        {
            log4net.Config.XmlConfigurator.Configure();
            log4net.ILog Log = log4net.LogManager.GetLogger( System.Reflection.MethodBase.GetCurrentMethod().DeclaringType );
            log4net.ILog OMGLog = log4net.LogManager.GetLogger( "OMGLogger" );
            
            Log.Fatal( "this is a fatal msg" );
            Log.Error( "this is an error msg" );
            Log.Warn( "this is a warn msg" );
            Log.Info( "this is an info msg" );
            Log.Debug( "this is a debug msg" );
            OMGLog.Fatal( "OMG!!  this is a fatal msg" );
            OMGLog.Error( "OMG!!  this is an error msg" );
            OMGLog.Warn( "OMG!!  this is a warn msg" );
            OMGLog.Info( "OMG!!  this is an info msg" );
            OMGLog.Debug( "OMG!!  this is a debug msg" );
        }
    }
}

On lines 8 and 9 two logger objects are created, one based off of the name of the containing type and another named simply "OMGLogger".  Now update the app.config to the following:

<?xml version="1.0" encoding="utf-8" ?>
<configuration>
  <configSections>
    <section name="log4net" type="log4net.Config.Log4NetConfigurationSectionHandler, log4net"/>
  </configSections>
  <log4net>
    <appender name="OMGLogAppender" type="log4net.Appender.FileAppender">
      <file value="omglog.txt" />
      
      <filter type="log4net.Filter.LevelRangeFilter">
        <levelMin value="ERROR" />
        <levelMax value="FATAL" />
        <acceptOnMatch value="false" />
      </filter>
      <filter type="log4net.Filter.LoggerMatchFilter">
        <loggerToMatch value="OMGLogger" />
      </filter>
      <filter type="log4net.Filter.DenyAllFilter" />
      <layout type="log4net.Layout.SimpleLayout" />
    </appender>
    <root>
      <level value="DEBUG" />
      <appender-ref ref="OMGLogAppender" />
    </root>
  </log4net>
</configuration>


Compile and run, the command console will blip on your screen.  Open the omglog.txt file:

FATAL - OMG!!  this is a fatal msg
ERROR - OMG!!  this is an error msg

Note that because of our chained filter, only log messages that meet the following criteria were allowed into the omglog.txt file:

  1. the log message level is ERROR or FATAL;
  2. the log message originated from the OMGLogger.

Coming Up

For realsies next time I'll discuss some personal experiences with log4net saving me hours of work and making me a hero.  I'll also cover some logging best practices in that or a later post.



Log4Net Tutorial pt 6: Log Event Context

§ September 1, 2008 14:54 by beefarino |

There are times when your log messages need some context to be most useful.  For example, if your application supports multiple concurrent clients, it would be helpful to know the client to which each log statement applies.  If a piece of code is used by several components, it would be nice for the log messages to reflect which component is calling the code.  log4net provides a very simple mechanism to accommodate such needs.

Open Visual Studio, create a new console project, and add a reference to the log4net assembly.  Add the following code to your program.cs file:

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

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

Note line 10, where a property named "myContext" is added to the ThreadContext static class and assigned a simple string value.  Next 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 (%property{myContext}) [%level]- %message%newline" />
      </layout>
    </appender>

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

Line 11 contains the layout pattern for our log; the %property{myContext} format specifier will be replaced with the value of the "myContext" property at the time the message is logged.

Compile and run; the context value is reflected in the log output:

Tutorial6_Context.Program (Logging from Main) [INFO]- this is an info message

Context Scopes

There are actually three logging contexts available in log4net.  Like the logger architecture, contexts are organized into a hierarchy where properties in the more granular contexts override property values in less granular contexts.

ContextDescription
log4net.GlobalContext A global context shared across all application threads and app domains. If two threads set the same property on the GlobalContext, one value will overwrite the other.
log4net.ThreadContext Any properties set in this context are scoped to the calling thread. In other words, in this context two threads can set the same property to different values without stomping on each other.
log4net.ThreadLogicalContext This context behaves similarly to the ThreadContext, except that the scope is defined by logical thread boundaries. I'll be honest and say that I've never used the ThreadLogicalContext in my career, but if you're working with a custom thread pool algorithm or hosting the CLR, you may find some use for this one.

Calculated Context Values

Context property values don't have to be strings.  You can set the value of a context property to any object reference; the value of the object's ToString method will be used to obtain the context property value when a logging event occurs.  This can be useful when you need a context property to represent a calculated state at the time of each logging event.  For instance, perhaps you want to track your application's use of the CPU:

namespace Tutorial6_Context
{
    public class CalcualtedContextProperty
    {
        public override string ToString()
        {
            return Process.GetCurrentProcess().TotalProcessorTime.ToString();
        }
    }
}

Set a context property value to an instance of this new class:

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

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

The result is each log entry containing the application's total CPU time at the time the log entry was made:

Tutorial6_Context.Program (00:00:00.2968750) [INFO]- this is an info message

ThreadContext Stacks

ThreadContext and ThreadLogicalContext can store property values in stacks (available via the Stacks static property of each class).  These stacks are very handy, as they allow you to track program states in the context of a log message:

namespace Tutorial6_Context
{
    class Program
    {
        static log4net.ILog Log = null;

        static void Main( string[] args )
        {
            log4net.Config.XmlConfigurator.Configure();
            Log = log4net.LogManager.GetLogger( System.Reflection.MethodBase.GetCurrentMethod().DeclaringType );
            using( log4net.ThreadContext.Stacks[ "myContext" ].Push( "outer" ) )
            {
                Log.Info( "this is the first message" );
                using( log4net.ThreadContext.Stacks[ "myContext" ].Push( "inner" ) )
                {
                    Log.Info( "this is the second message" );
                }
            }
            Log.Info( "this is the third message" );
            Console.ReadLine();
        }
    }
}

Pushing a property value onto a stack returns an IDisposable that, when disposed, pops the property value off of the stack.  The logging output reflects the state of the context stack at each logging event; the stack is represented as a space-delimited list, with newer items appearing later in the list:

Tutorial6_Context.Program (outer) [INFO]- this is the first message
Tutorial6_Context.Program (outer inner) [INFO]- this is the second message
Tutorial6_Context.Program ((null)) [INFO]- this is the third message

Context stacks are incredibly useful for wrapping access to a shared piece of code.  For example, in the following code two methods call the same utility routine; a marker is pushed onto the property stack before each call:

namespace Tutorial6_Context
{
    class Program
    {
        static log4net.ILog Log = null;

        static void Main( string[] args )
        {
            log4net.Config.XmlConfigurator.Configure();
            Log = log4net.LogManager.GetLogger( System.Reflection.MethodBase.GetCurrentMethod().DeclaringType );

            FirstAction();
            SecondAction();

            Console.ReadLine();

        }

        static void FirstAction()
        {
            using( log4net.ThreadContext.Stacks[ "myContext" ].Push( "FirstAction" ) )
            {
                UtilityRoutine();
            }
        }

        static void SecondAction()
        {
            using( log4net.ThreadContext.Stacks[ "myContext" ].Push( "SecondAction" ) )
            {
                UtilityRoutine();
            }
        }
        
        static void UtilityRoutine()
        {
            Log.Info( "this is an info message" );
        }
    }
}

Each log message produced by the utility routine reflects the context in which it was called:

Tutorial6_Context.Program (from:FirstAction) [INFO]- this is an info message
Tutorial6_Context.Program (from:SecondAction) [INFO]- this is an info message

Coming Up

These 6 tutorials cover the logging mechanics available in log4net.  So in the next post or two, I'd like to show you how logging has saved my hide using real examples from my career.