Wednesday, 4 August 2010

Using ReSharper with Log4Net

Blogging this to remind myself of certain steps, now that I’ve got it set up on a new project, and to share the love.  This is a great tip that I learned from Chris O’Brien when I worked with him on a project in 2009 at Parity Solutions (thanks again Chris!).  It takes a bit of setup, and there is a licensing cost for Resharper, but it’s a brilliant time saver for .Net developers.  The idea has several aspects, as follows:  a) logging is a critical part of any application, but entering the lines of logging code is tedious and repetetive; b) Log4Net is a good standardized way of implementing a logging infrastructure; and c) using Resharper in conjunction with Log4Net eliminates a lot of the tedium.  It’s like “code snippets on steroids.”

Setting up Log4Net

The goal here is to get the Log4Net.DLL referenced in your Visual Studio project.  Go to Log4Net and download.  There is lots of information about Log4Net on the web; use your favorite search engine to learn more (I don’t claim to be an expert, and I’m sure what I’m describing is a fairly rudimentary use of Log4Net, but it seems to work for me). 

Put the DLL in a subdirectory of your solution folder and add a reference to the Log4Net.DLL to your project (I like putting the DLL in a path like <SolutionFolder>/ThirdParty/Log4Net/Log4Net.DLL).

image

Here’s a screenshot of the structure of a test solution:

image

So I’ve got two projects.  First is a class library project that I call “Diagnostics” (and the other is a console app to test logging).  “Diagnostics” contains a reference to the Log4Net.DLL; and two classes.  One is a simple enum that corresponds to Log4Net’s different severity levels:

using System;

 

namespace SomeTestSolution.Diagnostics

{

    /// <summary>

    /// Severity of a log message.

    /// </summary>

    public enum LogLevel

    {

        Debug,

        Info,

        Warning,

        Error,

        FatalError

    }

 

}

 

The other class is the one that does the work.  It allows for two different types of logging messages; one where it’s just a simple string of text, and the other is one where you can create a string.Format (e.g. “Entering method {0} of class {1}”), then it also takes an array of objects which represent the parameters for the formatted string.

using System;

using System.Collections.Generic;

using System.Linq;

using System.Text;

using log4net;

 

namespace SomeTestSolution.Diagnostics

{

    /// <summary>

    /// Provides log/trace functionality to configured log outputs (e.g. file, database, e-mail etc.)

    /// </summary>

    public class TraceHelper

    {

        /// <summary>

        /// Write trace output (currently using Log4Net), formatting the passed arguments into the Message string.

        /// </summary>

        /// <param name="Level">Severity level.</param>

        /// <param name="Log">Instance of logger from calling class.</param>

        /// <param name="Message">Message to write.</param>

        /// <param name="Args">Arguments to insert into message.</param>

        public static void WriteLineFormat(LogLevel Level, ILog Log, string Message, params object[] Args)

        {

            string message = null;

            if (Args != null)

                message = string.Format(Message, Args);

            else

                message = Message;

 

            WriteLine(Level, Log, message);

        }

 

        /// <summary>

        /// Write trace output (currently using Log4Net).

        /// </summary>

        /// <param name="Level">Severity level.</param>

        /// <param name="Log">Instance of logger (log4net ILog) from calling class.</param>

        /// <param name="Message">Message to write.</param>

        public static void WriteLine(LogLevel Level, ILog Log, string Message)

        {

            switch (Level)

            {

                case LogLevel.Debug:

                    if (Log.IsDebugEnabled)

                    {

                        Log.DebugFormat(Message);

                    }

                    break;

                case LogLevel.Info:

                    if (Log.IsInfoEnabled)

                    {

                        Log.InfoFormat(Message);

                    }

                    break;

                case LogLevel.Warning:

                    if (Log.IsWarnEnabled)

                    {

                        Log.WarnFormat(Message);

                    }

                    break;

                case LogLevel.Error:

                    if (Log.IsErrorEnabled)

                    {

                        Log.ErrorFormat(Message);

                    }

                    break;

                case LogLevel.FatalError:

                    if (Log.IsFatalEnabled)

                    {

                        Log.FatalFormat(Message);

                    }

                    break;

            }

        }

    }

}

 

Now let’s turn our attention to the other project in our solution called “LoggingTestApp”.  This is a console application with a single program as follows:

using System;

using log4net;

using SomeTestSolution.Diagnostics;

 

 

namespace LoggingTestApp

{

    class Program

    {

        // this line is required by log4net, in any class where logging is desired.

        // the parameter of "typeof" will be the name of the class.

        private static readonly ILog logger = LogManager.GetLogger(typeof(Program));

 

        static void Main(string[] args)

        {

            TraceHelper.WriteLineFormat(LogLevel.Debug, logger, "Entering method {0} of class {1}.", "Main","Program");

 

            Console.ReadLine();

 

        }

    }

}

Note the required “private static readonly ILog” line at the top.  This enabled the Log4Net functionality in this class.

Also note our (handwritten) line of code used to test the logging, the “TraceHelper.WriteLineFormat” line.  This is an example of the type of code we will automate later when I get into talking about Resharper.  (Note also the fact that the log level is set to “Debug”, which is a threshold you can configure in the App.config file.  You can set it to a higher severity level such as “Warn” or “Error” for production apps).

There are a couple more things we need in place for Log4Net to work.  First, we need to update the AssemblyInfo.cs file of our console application with a reference to Log4Net’s XmlConfigurator( ):

using System.Reflection;

using System.Runtime.CompilerServices;

using System.Runtime.InteropServices;

 

// General Information about an assembly is controlled through the following

// set of attributes. Change these attribute values to modify the information

// associated with an assembly.

[assembly: AssemblyTitle("LoggingTestApp")]

[assembly: AssemblyDescription("")]

[assembly: AssemblyConfiguration("")]

[assembly: AssemblyCompany("YourCompany")]

[assembly: AssemblyProduct("LoggingTestApp")]

[assembly: AssemblyCopyright("Copyright © YourCompany")]

[assembly: AssemblyTrademark("")]

[assembly: AssemblyCulture("")]

 

// this line is required to initiate log4net functionality

[assembly: log4net.Config.XmlConfigurator()]

(It should be noted you also need a reference to the Log4Net.DLL in the TestLoggingApp console application project).

Now we also need to set up our “appenders” for Log4Net in our App.config file (this is a fundamental Log4Net concept; it’s how we tell Log4Net where we want its logging output to go).  In this example I’ve got 3 appenders:  one sends output to the console; one is a “RollingFileAppender” which can be configured to roll to a new log file when it reaches specified boundaries of date and/or size; and one to send output to a trace listener.  For testing purposes I’ve got the size set to a very small size for the RollingFileAppender.

<?xml version="1.0" encoding="utf-8" ?>

<configuration>

  <configSections>

    <!-- reference to log4net section -->

    <section name="log4net" type="log4net.Config.Log4NetConfigurationSectionHandler, log4net, Version=1.2.10.0, Culture=neutral, PublicKeyToken=1b44e1d426115821" />

  </configSections>

 

  <!-- Configuration for log4net -->

  <log4net>

    <root>

      <!-- this is the default logging behaviour if no matching logger element is found below -->

      <level value="DEBUG" />

      <appender-ref ref="ConsoleAppender" />

      <appender-ref ref="RollingFileAppender" />

      <appender-ref ref="TraceAppender" />

    </root>

 

    <appender name="ConsoleAppender" type="log4net.Appender.ConsoleAppender">

      <layout type="log4net.Layout.PatternLayout">

        <conversionPattern value="%date [%thread] %-5level %logger [%property{NDC}] - %message%newline" />

      </layout>

    </appender>

 

    <appender name="RollingFileAppender" type="log4net.Appender.RollingFileAppender">

      <file type="log4net.Util.PatternString" value="C:\YourAppDir\Logs\" />

      <AppendToFile value="true" />

      <DatePattern value="yyyyMMdd_HHmm'_trace.log'" />

      <CountDirection value="1" />

      <Threshold value="DEBUG" />

      <LockingModel type="log4net.Appender.FileAppender+MinimalLock" />

      <MaximumFileSize value="5KB" />

      <MaxSizeRollBackups value="-1" />

      <RollingStyle value="Composite" />

      <StaticLogFileName value="false" />

      <layout type="log4net.Layout.PatternLayout">

        <conversionPattern value="%date [%-5level] %logger - %message%newline" />

      </layout>

    </appender>

 

    <appender name="TraceAppender" type="log4net.Appender.TraceAppender">

      <threshold value="DEBUG" />

      <layout type="log4net.Layout.PatternLayout">

        <conversionPattern value="%date %-5level %logger - %message%newline" />

      </layout>

    </appender>

 

  </log4net>

</configuration>

Now, when we run our test app, lo and behold, we get a logging message to the console, and a log file:

image

Setting up Resharper

So that’s all well and good, but it would be tedious to have to write those logging lines by hand every time we want to log the fact that we’re entering a method, or leaving a method, or that we want to log an exception, etc.  Enter Resharper.

First, download and install Resharper.  You can use an evaluation copy if you’re not ready to pay the licensing fee.  It will integrate itself with your copy of Visual Studio, and you’ll see a new “Resharper” menu when you go into VS.  The main power of this whole idea comes from using what are called “Live Templates” in Resharper terminology.  Under the “ReSharper” menu go to “Live Templates…”

image

Click the “New Template” button in the “Templates Explorer”…

image

This will bring up the template editing window, as shown below.  In this example I’ve created a shortcut which will be triggered when the developer enters “lem” while editing a program.  Note how, by entering text surrounded by dollar signs, we can create a variable that will then let you select how ReSharper interprets that variable (see the menu on the right).  It lets you select things like “containing type member name,” which is what you want if you want to indicate the method in which you’re entering the line of code.  Once you’ve finished editing, you save the template.

 image

Now when we go to a program and type “lem” ReSharper displays a little menu of shortcuts.  We can then hit the Tab key and it will automatically enter the line, intelligently figuring out what method and class we’re in:

image

It also displays the “variable” data as entry fields, so we can Tab through them and change them if desired:

image

Once I tab through, the line is now entered as we would expect:

image

So in this case, I just had to type “lem, Tab, Tab, Tab” to enter a line of code that you might enter hundreds of times while writing an application.  Not bad!

Good practice suggests strings should not be hard-coded, but should exist in a Constants class (or a Resources file, or an XML file, or however your good practices manifest themselves).  In this case for the “EnteringMethod” string, I’m using a constant that looks like this:

image

Well, anyway, you get the idea.

Happy coding!