Log4net logging from your custom code in Umbraco

Disclaimer: this isn't an introduction to log4net. Please Google for a more generic introduction.

Recent versions of Umbraco ship with Log4Net - previously it was reasonably straightforward to add it to your customisations but now it is really simple to do logging in your custom code. It is also arguably essential as there isn't a current method for receiving the Umbraco page assembly trace in the new MVC "rendering mode".

This blog post will explain how to get a reference to a log4net logger in your custom code and then how to control the Level of your logging and filter messages from your code to their own log file.

First up you'll need a reference to log4net in your project. I recommend referencing the version of log4net that ships with Umbraco directly in the /bin folder of the distribution. Umbraco ships with a patched version of log4net - but the assembly version matches an official version which has got me into a few challenges when referencing via nuget.

Once I have the reference I can add the following to each class that I want to log from:

public class Class1
{
    private static readonly ILog Log =
        LogManager.GetLogger(
            MethodBase.GetCurrentMethod().DeclaringType
        );

You normally put this just inside the class declaration as above. The argument to GetLogger just resolves to the current type and is a convenience so you can paste the same snippet into any class without having to make modifications.

You can now use your Logger anywhere in your code:

Log.Debug("Umbraco is starting");
Log.Info(string.Format("Umbraco is running on {0}", Environment.MachineName));

And you are done - kind of. If you take a look in ~/App_Data/Logs/UmbracoTraceLog.txt then you should find your log messages. The problem is they are interspersed with lots of other messages that Umbraco logs itself making them rather hard to find.

With a little configuration you can write your messages to their own log file. Start by opening up ~/config/log4net.config

Take a copy of the Xml node that begins:

<appender name="AsynchronousLog4NetAppender"

And give it a different and unique name attribute. Also, specify a path to your custom log file in the file child node. My modified example looks like this:

<appender name="CustomAppender" type="Umbraco.Core.Logging.AsynchronousRollingFileAppender, Umbraco.Core">
    <file value="App_Data\Logs\Moriyama.log.txt" />
    <lockingModel type="log4net.Appender.FileAppender+MinimalLock" />
    <appendToFile value="true" />
    <rollingStyle value="Date" />
    <maximumFileSize value="5MB" />
    <layout type="log4net.Layout.PatternLayout">
        <conversionPattern value="%date [%thread] %-5level %logger - %message%newline" />
    </layout>
</appender>

The snippet above is just a definition for your custom log file. You can read lots more about configuring appenders in the log4net documentation.

Finally you need to declare a logger for your namespace, add the following logger declaration to log4net.config

<logger name="Moriyama.UmbracoCustom">
    <level value="DEBUG" />
    <appender-ref ref="CustomAppender" />
</logger>

The name attribute of the logger is a namespace or class name that the logger applies to - change this to the root namespace of your Umbraco customisation project. The ref attribute of the appender-ref node should match the appender name that you create in the previous step.

You logging code should now log into your custom log file. Be aware that you should probably raise the level of your loggers to at least ERROR when going into production.

Here is a complete class example that writes some messages to a log file when Umbraco starts:

using System;
using System.Reflection;
using log4net;
using umbraco.interfaces;

namespace Moriyama.UmbracoCustom
{
    public class Class1 : IApplicationStartupHandler
    {
        private static readonly ILog Log = 
            LogManager.GetLogger(
                MethodBase.GetCurrentMethod().DeclaringType
            );

        public Class1()
        {
            Log.Debug("Umbraco is starting");
            Log.Info(string.Format("Umbraco is running on {0}", Environment.MachineName));
        }
    }
}

The resulting output in my custom log file is as follows:

2013-02-22 09:21:17,154 [34] DEBUG Moriyama.UmbracoCustom.Class1 - Umbraco is starting
2013-02-22 09:21:17,154 [34] INFO  Moriyama.UmbracoCustom.Class1 - Umbraco is running on DARREN-VAIO

With log4net you can change the format of your log entries and also log to a database, XML file or even email.

That is all for now - happy logging.

Sorry I haven't blogged much this year - I will try to do better in 2013.

Comments

Leave a comment