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.



Log4Net Tutorial pt 3: Appenders

§ June 9, 2008 15:38 by beefarino |

I've discussed using XML to configure lognet, during which I briefly touched on log4net appenders.  An appender is an object that persists your log messages someplace.  In this post, I'd like to give you a quick overview of the wealth of apppenders available in log4net and show you how you can use them to direct a single log message to multiple places.

A Quick Survey

Here is a quick sampling of the appenders available in the log4net distribution:

Type NameDescription
log4net.Appender.AdoNetAppender Appender that logs to a database.
log4net.Appender.AnsiColorTerminalAppender Appends logging events to the terminal using ANSI color escape sequences.
log4net.Appender.AspNetTraceAppender Appends log events to the ASP.NET TraceContext system.
log4net.Appender.BufferingForwardingAppender Buffers events and then forwards them to attached appenders.
log4net.Appender.ColoredConsoleAppender Appends logging events to the console.
log4net.Appender.ConsoleAppender Appends logging events to the console.
log4net.Appender.DebugAppender Appends log events to the Debug system.
log4net.Appender.EventLogAppender Writes events to the system event log.
log4net.Appender.ForwardingAppender This appender forwards logging events to attached appenders.
log4net.Appender.FileAppender Appends logging events to a file.
log4net.Appender.LocalSyslogAppender Logs events to a local syslog service.
log4net.Appender.MemoryAppender Stores logging events in an array.
log4net.Appender.NetSendAppender Logs entries by sending network messages using the NetMessageBufferSend native function.
log4net.Appender.OutputDebugStringAppender Appends log events to the OutputDebugString system.
log4net.Appender.RemoteSyslogAppender Logs events to a remote syslog daemon.
log4net.Appender.RemotingAppender Delivers logging events to a remote logging sink.
log4net.Appender.RollingFileAppender Appender that rolls log files based on size or date or both.
log4net.Appender.SmtpAppender Send an e-mail when a specific logging event occurs, typically on errors or fatal errors.
log4net.Appender.SmtpPickupDirAppender Send an email when a specific logging event occurs, typically on errors or fatal errors. Rather than sending via smtp it writes a file that  another service, such as the IIS SMTP agent, can use to manage sending the messages.
log4net.Appender.TelnetAppender Appender that allows clients to connect via Telnet to receive log messages.
log4net.Appender.TraceAppender Appends log events to the Trace system.
log4net.Appender.UdpAppender Sends logging events as connectionless UDP datagrams to a remote host or multicast using the UdpClient class.

There's a lot of them, so to keep this post reasonable I'm focusing on the most basic appenders: the console appenders, debug appenders, and file appenders.  However, all of the available appenders are covered in detail in the log4net documentation if you want to learn more about them, and I'll be describing other appenders in upcoming posts as well.

ConsoleAppender and ColoredConsoleAppender

These appenders are useful only for console applications, where they provide immediate feedback during program execution.

There is one configurable aspect of the ConsoleAppender - the target property identifies what output stream to use when outputting log entries:

<appender name="ConsoleAppender" type="log4net.Appender.ConsoleAppender">
    <target value="Console.Error" />
    <layout type="log4net.Layout.SimpleLayout" />
</appender>

It can be either "Console.Out" (the default value if left uspecified) to use the standard output stream or "Console.Error" to use the standard error stream.  

I always favor ColoredConsoleAppender over ConsoleAppender, because the ColoredConsoleAppender will colorize the log message by its severity level.  This makes finding relevant log messages amidst the program output a lot easier.  For example, compare this output from the ConsoleAppender:

to the same output from the ColoredConsoleAppender:

The color mapping is completely configurable, as shown in this example appender configuration XML:

<appender name="ColoredConsoleAppender" type="log4net.Appender.ColoredConsoleAppender">
  <target value="Console.Error" />
  <mapping>
    <level value="FATAL" />
    <foreColor value="Red" />
    <backColor value="White" />
  </mapping>
  <mapping>
    <level value="ERROR" />
    <foreColor value="Red, HighIntensity" />
  </mapping>
  <mapping>
    <level value="WARN" />
    <foreColor value="Yellow" />
  </mapping>
  <mapping>
    <level value="INFO" />
    <foreColor value="Cyan" />
  </mapping>
  <mapping>
    <level value="DEBUG" />
    <foreColor value="Green" />
  </mapping>
  <layout type="log4net.Layout.SimpleLayout" />
</appender>

Each <mapping /> element must contain a severity level, and can also contain a <foreColor /> and/or <backColor /> element.  Color selection is limited to the following choices:

  • Blue
  • Green
  • Red
  • Yellow
  • Purple
  • Cyan
  • White

In addition, you can include "HighIntensity" in the color value to use a brighter shade of a color, as shown in the ERROR color mapping in the above configuration example.

These appenders are useful only for console-based programs.  It won't hurt anything if you try to use this appender from a UI or web application, you just won't see any of your log messages.  

DebugAppender and TraceAppender

These appenders act as adapters on the .NET System.Diagnostics.Debug and System.Diagnostics.Trace classes.  Because of this, there is very little option in their configurations; both appenders have a single configurable property named ImmediateFlush that controls whether log output is flushed to the Debug or Trace writers immediately:

<appender name="DebugAppender" type="log4net.Appender.DebugAppender">
    <immediateFlush value="true" />
    <layout type="log4net.Layout.SimpleLayout" />
</appender>

I use the DebugAppender routinely to help work problems in the debugger - the log output shows up right in the debug output window of Visual Studio.  This can be invaluable when trying to isolate race conditions or realtime effects where a breakpoint would ruin the reproducability of the issue.

I've used the TraceAppender when extending applications where custom TraceListener implementations were already in use; this allowed existing modules using log4net to adapt immediately to the proprietary TraceListeners, no code required.

FileAppender and RollingFileAppender

These appenders write log messages to files.  Their configuration is a bit more involved than the other appenders we've discussed.  A typical configuration for the FileAppender might look like this:

<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>

Here's a quick summary of the more common configuration attributes for the FileAppender:

  • file: the full or relative path to the log file;
  • appendToFile: boolean indicating whether the log file should be appended (true) or overwritten (false).  If false, the file overwrite occurs during log4net initialization.  If unspecified, the log file is appended;
  • immediateFlush: boolean indicating whether to flush the log file TextWriter after each log message is written.  The default is true (flush each message after its written);
  • lockingModel: allows control over the log file locking strategy.  This can be either "log4net.Appender.FileAppender+MinimalLock" to allow for loose file locking or "log4net.Appender.FileAppender+ExclusiveLock" to lock the file during program execution.  The default is the exlusive lock, and I highly recommend you stick with that lock for performance reasons.

Now that I've described the FileAppender, heed this advice:

Do not use the FileAppender, ever ever ever.  Use the RollingFileAppender instead.

The log file managed by FileAppender will be allowed to grow without bounds.  This will Tonya-Harding your application's stability when given enough time.  The RollingFileAppender provides rudimentary log file management, configurable size- or date-boxing of the log file, and limited rolling backups of the log file.

<appender name="RollingFileAppender" type="log4net.Appender.RollingFileAppender">
    <file value="log-file.txt" />
    <appendToFile value="true" />
    <rollingStyle value="Size" />
    <maxSizeRollBackups value="10" />
    <maximumFileSize value="1MB" />
    <staticLogFileName value="true" />
    <layout type="log4net.Layout.SimpleLayout" />
</appender>

There is a lot of configurability to the RollingFileAppender; in addition to the options available to the FileAppender, the RollingFileAppender includes these parameters:

  • rollingStyle: this controls how log files are "rolled," and can be one of the following values:
    • Once: the log file is rolled every time log4net is initialized (typically at application startup);
    • Size: the log file is rolled once it breaches a certain size;
    • Date: the log file is rolled based on the current date;
    • Composite: the log file is rolled based on size constraints and the current date;
  • maximumFileSize: the size cap on the log file.  This is an expression of size in the form of "#(KB|MB|GB)".  For instance, "100KB" or "10MB";
  • maxSizeRollBackups: the maximum number of rolled log file backups to maintain when rollingStyle is SIZE; when rollingStyle is COMPOSITE, this indicates the maximum number of roll-offs maintained per day; this property has no effect when rollingStyle is ONCE or DATE;
  • datePattern: the date pattern used to roll files based on date.  The value of this parameter needs to adhere to the format used by the SimpleDateFormatter class;
  • staticLogFileName: a bit of a misnomer - when true this setting indicates whether log4net should actively write logs to the configured file (log-file.txt in our example configuration) and maintain rolling backups by copy.  When false, this setting indicates that log4net will actively log to the latest roll-off file (e.g., log-file1.txt, log-file2.txt, log-file3.txt, etc);
  • countDirection: indicates how roll-off file numbering is managed.  When this parameter is >= 0, the newest log file will have the largest number; e.g., log-file.txt.5 will be newer than log-file.txt.4.  When countDirection < 0, the newest log file will have the lowest number; e.g., log-file.txt.1 will be newer than log-file.txt.2.  If unspecified, countDirection defaults to (-1);

Keep in mind that when using a file appender, the user running the logging process must have rights to create and/or modify the log file in order for log messages to be written properly.  In addition, log4net will create the log file if it does not exist, but it will not create directories in the log file path that do not already exist.  If log4net encounters a problem initializing the file appender (e.g., it cannot create the log file for security reasons), the log file will not be written but your application will continue to execute normally.

Using Multiple Appenders

With all of these appenders available, it may seem difficult to choose just one to meet your logging needs.  But why choose one when you can have as many as you want?

Using multiple appenders is a simple task of specifying each appender you need under the root logger, like so:

<root>
    <level value="ALL" />
    <appender-ref ref="DebugAppender" />
    <appender-ref ref="ColoredConsoleAppender" />
</root>

You can use as many appenders as you want; however, know that for each appender you use you will accrue some runtime overhead.  

Coming Up

You now have control over where your log messages persist.  Next time, I'll describe how you can control the format your log messages as they are written out by each appender, including how to insert context information - such as the thread id, timestamp, or user identity - into the log message automagically.

Edit Notes

07.03.2008: Theo pointed out some inaccuracies in the way I was describing the maxSizeRollBackups and countDirection properties of the RollingFileAppender, which I've attempted to correct.  Thanks, Theo!