Sitecore log4net ADO Logging Part 1: The Appender

This details how to create an ADO.NET log appender for log4net in Sitecore.
This post is split into two parts:

• Part 1: The custom appender for log4net (this post)
• Part 2: The custom ASR report for viewing the logs including a custom detail screen

This will cover the first part.

A Note of Namespace

You will need a reference to Sitecore.Logging. The namespaces for the log4net classes are all in log4net (e.g. log4net.Appender) but they exist in the Sitecore.Logging.dll file. Don’t get confused and add the log4net.dll file. This is not the correct library. All the namespaces and class names are the same or similar, but they will not work as expected.

Building an ADONetAppender

Out of the box, Sitecore comes with an Appender named ADONetAppender (if you have just AdoNetAppender - you have the wrong DLL). Using this Appender is just fine, but I wanted to include some more fields. Originally I had done it in a helper class that I would call before logging an error. But by creating my own Appender, I could handle it all in one place.
The first thing I did was to inherit from the built in appender:

public class AdoNetAppender : log4net.Appender.ADONetAppender {

Then I override the Append method:

protected override void Append(log4net.spi.LoggingEvent loggingEvent) {

Inside that method, I found all the information that I needed. The LoggingEvent object that’s passed contains a property named Properties that will contain all the information available to the appender:

log4net.helpers.PropertiesCollection col = loggingEvent.Properties;

Then they can be assigned as follows:

col["{PROPERTYNAME}"] = “Value”;

After all the properties are set, I simply called the base append method:

base.Append(loggingEvent);

Here is the full set of code for the custom AdoNetAppender: (note: this contains some methods that were originally part of extention methods for the Language class, but was added to this class for brevity)

    public class AdoNetAppender : log4net.Appender.ADONetAppender {
        public string connectionStringName { get; set; }

        public override void ActivateOptions() {
            this.ConnectionString = System.Configuration.ConfigurationManager.ConnectionStrings[connectionStringName].ConnectionString;
            base.ActivateOptions();
        }


        private static Language tryParseLanguage(string name) {
            Sitecore.Diagnostics.Assert.ArgumentNotNull((object)name, "name");
            Language result;
            if (tryParseLanguage(name, out result))
                return result;
            throw new ArgumentException(string.Format("Could not parse the language '{0}'. Note that a custom language name must be on the form: isoLanguageCode-isoRegionCode-customName. The language codes are two-letter ISO 639-1, and the regions codes are are two-letter ISO 3166. Also, customName must not exceed 8 characters in length. Valid example: en-US-East. For the full list of requirements, see: http://msdn2.microsoft.com/en-US/library/system.globalization.cultureandregioninfobuilder.cultureandregioninfobuilder.aspx", (object)name));
        }

        private static bool tryParseLanguage(string name, out Language result) {
            Sitecore.Diagnostics.Assert.ArgumentNotNull((object)name, "name");
            result = (Language)null;
            if (name.Equals("__Standard Values", StringComparison.OrdinalIgnoreCase) || name.Equals("__language", StringComparison.OrdinalIgnoreCase) || !LanguageManager.IsValidLanguageName(name))
                return false;
            if (LanguageManager.LanguageRegistered(name) || LanguageManager.RegisterLanguage(name)) {
                return true;
            }
            return true;
        }



        private Language getLanguage() {
            Language language1 = Sitecore.Context.Items["sc_Language"] as Language;
            if (language1 != null)
                return language1;
            string name = string.Empty;
            Sitecore.Sites.SiteContext site = Sitecore.Context.Site;
            if (site != null) {
                name = WebUtil.GetCookieValue(site.GetCookieKey("lang"), site.Language);
                Assert.IsNotNull((object)name, "languageName");
            }
            if (name.Length == 0)
                name = Settings.DefaultLanguage;

            try {
                Language language2 = tryParseLanguage(name);
                if (Sitecore.Configuration.State.Sites.IsSiteResolved)
                    Sitecore.Context.Items["sc_Language"] = (object)language2;
                return language2;
            } catch (Exception) { }
            return null;
        }


        protected override void Append(log4net.spi.LoggingEvent loggingEvent) {
            log4net.helpers.PropertiesCollection col = loggingEvent.Properties;
            if (!object.ReferenceEquals(Environment.MachineName, null)) {
                col["machine"] = Environment.MachineName;
            }

            HttpContext context = null;
            User currentUser = null;
            Item contextItem = null;
            Language language = null;

            try { context = HttpContext.Current; } catch { }
            try { currentUser = Sitecore.Context.User; } catch { }
            try { contextItem = Sitecore.Context.Item; } catch { }

            if (loggingEvent.LoggerName != "System.RuntimeType") {
                try { language = Sitecore.Context.Language; } catch { }
                if (language != null) {
                    col["Language"] = language;
                }
            }

            try {
                if (currentUser != null) {
                    col["CurrentUser"] = currentUser.DisplayName;

                    var roles = "";
                    foreach (var role in currentUser.Roles) {
                        roles += role.DisplayName + ",";
                    }
                    roles = roles.Substring(0, roles.Length - 1); // remove last comma
                    col["Roles"] = roles;
                }
            } catch { }

            if (contextItem != null) {
                col["SitecoreItemID"] = contextItem.ID.ToString();
                col["SitecoreItemName"] = contextItem.Name;
            }

            if (context != null) {
                try {
                    string ipAddress = context.Request.ServerVariables["HTTP_CLIENT_IP"];
                    if (String.IsNullOrEmpty(ipAddress)) {
                        ipAddress = context.Request.ServerVariables["HTTP_X_FORWARDED_FOR"];
                    }
                    if (String.IsNullOrEmpty(ipAddress)) {
                        ipAddress = context.Request.ServerVariables["REMOTE_ADDR"];
                    }
                    if (!String.IsNullOrEmpty(ipAddress)) {
                        col["IpAddress"] = ipAddress;
                    }

                    if (!String.IsNullOrEmpty(context.Request.ServerVariables["X-FORWARDED-FOR"])) {
                        col["ForwardedIpAddress"] = context.Request.ServerVariables["X-FORWARDED-FOR"];
                    }

                    string referrer = context.Request.ServerVariables["HTTP_REFERER"];
                    col["HttpReferrer"] = referrer;

                    string currentUrl = context.Request.Url.AbsoluteUri;
                    col["HttpUrl"] = currentUrl;

                    string method = context.Request.HttpMethod;
                    col["HttpMethod"] = method;

                    if (method.ToLower() == "post") {
                        var formVariables = "";
                        if (context.Request.Form.Count > 0) {
                            foreach (string key in context.Request.Form) {
                                var value = context.Request.Form[key];
                                formVariables += "|   " + key + " : " + value.ToString() + System.Environment.NewLine;
                            }
                        }
                        col["FormVariables"] = formVariables;
                    }

                    HttpCookieCollection cookies = context.Request.Cookies;
                    string userAgent = context.Request.ServerVariables["HTTP_USER_AGENT"];
                    col["HttpUserAgent"] = userAgent;

                    string queryString = context.Request.ServerVariables["QUERY_STRING"];
                    if (!String.IsNullOrEmpty(queryString)) {
                        col["HttpQueryString"] = queryString;
                    }

                    if (cookies != null && cookies.Count > 0) {
                        var strCookies = "";
                        for (int c = 0; c < cookies.Count; c++) {
                            HttpCookie cookie = cookies.Get(c);
                            strCookies += String.Format(CultureInfo.CurrentCulture, "|  HTTP Cookie: {0} = {1}{2}", cookie.Name, cookie.Value, Environment.NewLine);
                        }
                        col["HttpCookies"] = strCookies;
                    }
                } catch { }
            }

            base.Append(loggingEvent);
        }
    }

The log4net configuration

Next I needed to add an appender into the log4net configuration section. I did this in the usual Sitecore include file. It belongs under configuration/sitecore/log4net and references the custom AdoNetAppender class I created:

<appender name="AdoNetAppender" type="Rizzi.SC.AdoLogging.Appenders.AdoNetAppender, Rizzi.SC.AdoLogging">

Underneath that we can set the log level. In this case we are only logging ERRORS or worse:

<level value="ERROR" />

Then we add the connection type. In this case I’m using an SqlConnection:

<param name="ConnectionType" value="System.Data.SqlClient.SqlConnection, System.Data, Version=2.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089" />

For the connection string, we added a param named connectionStringName. This is automatically mapped to the property of the same name in the custom AdoNetAppender class. The value of this property maps to a connection string of the same name in the connection string file:

<param name="connectionStringName" value="log4net"/>

Please note that you can add any property you want to an Appender class and specify the value as a parameter in the config file.
Next is the CommandText. This is the insert statement for inserting the actual data into the table:

<param name="CommandText" value="INSERT INTO [Log]([Date],[Thread],[Level],[Logger],[Message],[Exception],[MachineName], [CurrentUser], [Roles], [SitecoreItemID], [SitecoreItemName], [Language], [IpAddress], [ForwardedIpAddress], [HttpReferrer], [HttpUrl], [HttpMethod], [FormVariables], [HttpUserAgent], [HttpQueryString], [HttpCookies]) VALUES (@log_date, @thread, @log_level, @logger, @message, @exception, @MachineName, @CurrentUser, @Roles, @SitecoreItemID, @SitecoreItemName, @Language, @IpAddress, @ForwardedIpAddress, @HttpReferrer, @HttpUrl, @HttpMethod, @FormVariables, @HttpUserAgent, @HttpQueryString, @HttpCookies)" />

The next set of parameters are mappings for the actual fields to be logged. They are all of param name=”Parameter”:

<param name="Parameter">

There are a few different ways to reference the fields. The ParameterName sub param maps to the query in the CommandText:

<param name="ParameterName" value="@log_date" />

Then you need the type. This can be any type available in the database:

<param name="DbType" value="DateTime" />

Or

<param name="DbType" value="String" />

If a size is needed for that type, you can specify that also:

<param name="Size" value="255" />

The next part is the Layout. There are a few different Layouts that you can use, but in the end I ended up using the PatternLayout for all my parameters. There are list of different values that you can have for the ConversionPattern for the PatternLayout. There is a list here: [LINK]. Please note that I had issues along the way with there not being a 1 for 1 between this list and reality. But in the end I think that that had to do with the log4net namespace issue defined above.
The ConverionPattern starts with a % variable. They all seem to be one character (regardless of what the documentation might say). For example. %t is the tread, %p is the loglevel, etc. And, yes, the letters don’t seem to have any bearing on what they do. They are case sensitive.
For the Log Level:

<param name="Layout" type="log4net.Layout.PatternLayout">
    <param name="ConversionPattern" value="%p" />
</param>

The %d that I have has a format on it:

<param name="Layout" type="log4net.Layout.PatternLayout">
    <param name="ConversionPattern" value="%d{yyyy&apos;-&apos;MM&apos;-&apos;dd HH&apos;:&apos;mm&apos;:&apos;ss&apos;.&apos;fff}" />
</param>

For our custom properties, we need to use the ConversionPattern variable %P. You specify the Property name inside of the curly braces:

<param name="ConversionPattern" value="%P{MachineName}" />

Finally, you will need to reference this appender in your appender chain. This example just adds it to the end. If you need to patch it, you can use the usual way to patch:after or patch:before:

<root>
            <appender-ref ref="AdoNetAppender" />
</root>

Here is the full configuration:

<?xml version="1.0" encoding="utf-8"?>
<configuration xmlns:patch="http://www.sitecore.net/xmlconfig/">
    <sitecore>
        <log4net>
            <appender name="AdoNetAppender" type="Rizzi.SC.AdoLogging.Appenders.AdoNetAppender, Rizzi.SC.AdoLogging">
                <!--<appender name="AdoNetAppender" type="log4net.Appender.ADONetAppender">-->
                <!--<bufferSize value="1" />-->
                <level value="ERROR" />

                <param name="ConnectionType" value="System.Data.SqlClient.SqlConnection, System.Data, Version=2.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089" />
                <param name="connectionStringName" value="log4net"/>
                <param name="CommandText" value="INSERT INTO [Log]([Date],[Thread],[Level],[Logger],[Message],[Exception],[MachineName], [CurrentUser], [Roles], [SitecoreItemID], [SitecoreItemName], [Language], [IpAddress], [ForwardedIpAddress], [HttpReferrer], [HttpUrl], [HttpMethod], [FormVariables], [HttpUserAgent], [HttpQueryString], [HttpCookies]) VALUES (@log_date, @thread, @log_level, @logger, @message, @exception, @MachineName, @CurrentUser, @Roles, @SitecoreItemID, @SitecoreItemName, @Language, @IpAddress, @ForwardedIpAddress, @HttpReferrer, @HttpUrl, @HttpMethod, @FormVariables, @HttpUserAgent, @HttpQueryString, @HttpCookies)" />
                <param name="Parameter">
                    <param name="ParameterName" value="@log_date" />
                    <param name="DbType" value="DateTime" />
                    <param name="Layout" type="log4net.Layout.PatternLayout">
                        <param name="ConversionPattern" value="%d{yyyy&apos;-&apos;MM&apos;-&apos;dd HH&apos;:&apos;mm&apos;:&apos;ss&apos;.&apos;fff}" />
                    </param>
                </param>
                <param name="Parameter">
                    <param name="ParameterName" value="@thread" />
                    <param name="DbType" value="String" />
                    <param name="Size" value="255" />
                    <param name="Layout" type="log4net.Layout.PatternLayout">
                        <param name="ConversionPattern" value="%t" />
                    </param>
                </param>
                <param name="Parameter">
                    <param name="ParameterName" value="@log_level" />
                    <param name="DbType" value="String" />
                    <param name="Size" value="50" />
                    <param name="Layout" type="log4net.Layout.PatternLayout">
                        <param name="ConversionPattern" value="%p" />
                    </param>
                </param>
                <param name="Parameter">
                    <param name="ParameterName" value="@logger" />
                    <param name="DbType" value="String" />
                    <param name="Size" value="255" />
                    <param name="Layout" type="log4net.Layout.PatternLayout">
                        <param name="ConversionPattern" value="%c" />
                    </param>
                </param>
                <param name="Parameter">
                    <param name="ParameterName" value="@message" />
                    <param name="DbType" value="String" />
                    <param name="Size" value="-1" />
                    <param name="Layout" type="log4net.Layout.PatternLayout">
                        <param name="ConversionPattern" value="%m" />
                    </param>
                </param>
                <param name="Parameter">
                    <param name="ParameterName" value="@exception" />
                    <param name="DbType" value="String" />
                    <param name="Size" value="-1" />
                    <layout type="log4net.Layout.ExceptionLayout" />
                </param>
                <param name="Parameter">
                    <param name="ParameterName" value="@MachineName" />
                    <param name="DbType" value="String" />
                    <param name="Size" value="4000" />
                    <param name="Layout" type="log4net.Layout.PatternLayout">
                        <param name="ConversionPattern" value="%P{MachineName}" />
                    </param>
                </param>
                <param name="Parameter">
                    <param name="ParameterName" value="@CurrentUser" />
                    <param name="DbType" value="String" />
                    <param name="Size" value="255" />
                    <param name="Layout" type="log4net.Layout.PatternLayout">
                        <param name="ConversionPattern" value="%P{CurrentUser}" />
                    </param>
                </param>
                <param name="Parameter">
                    <param name="ParameterName" value="@Roles" />
                    <param name="DbType" value="String" />
                    <param name="Size" value="255" />
                    <param name="Layout" type="log4net.Layout.PatternLayout">
                        <param name="ConversionPattern" value="%P{Roles}" />
                    </param>
                </param>
                <parameter>
                    <parameterName value="@SitecoreItemID" />
                    <dbType value="String" />
                    <size value="255" />
                    <layout type="log4net.Layout.PatternLayout">
                        <conversionPattern value="%P{SitecoreItemID}" />
                    </layout>
                </parameter>
                <param name="Parameter">
                    <param name="ParameterName" value="@SitecoreItemName" />
                    <param name="DbType" value="String" />
                    <param name="Size" value="255" />
                    <param name="Layout" type="log4net.Layout.PatternLayout">
                        <param name="ConversionPattern" value="%P{SitecoreItemName}" />
                    </param>
                </param>
                <param name="Parameter">
                    <param name="ParameterName" value="@Language" />
                    <param name="DbType" value="String" />
                    <param name="Size" value="255" />
                    <param name="Layout" type="log4net.Layout.PatternLayout">
                        <param name="ConversionPattern" value="%P{Language}" />
                    </param>
                </param>
                <param name="Parameter">
                    <param name="ParameterName" value="@IpAddress" />
                    <param name="DbType" value="String" />
                    <param name="Size" value="255" />
                    <param name="Layout" type="log4net.Layout.PatternLayout">
                        <param name="ConversionPattern" value="%P{IpAddress}" />
                    </param>
                </param>
                <param name="Parameter">
                    <param name="ParameterName" value="@ForwardedIpAddress" />
                    <param name="DbType" value="String" />
                    <param name="Size" value="255" />
                    <param name="Layout" type="log4net.Layout.PatternLayout">
                        <param name="ConversionPattern" value="%P{ForwardedIpAddress}" />
                    </param>
                </param>
                <param name="Parameter">
                    <param name="ParameterName" value="@HttpReferrer" />
                    <param name="DbType" value="String" />
                    <param name="Size" value="-1" />
                    <param name="Layout" type="log4net.Layout.PatternLayout">
                        <param name="ConversionPattern" value="%P{HttpReferrer}" />
                    </param>
                </param>
                <param name="Parameter">
                    <param name="ParameterName" value="@HttpUrl" />
                    <param name="DbType" value="String" />
                    <param name="Size" value="-1" />
                    <param name="Layout" type="log4net.Layout.PatternLayout">
                        <param name="ConversionPattern" value="%P{HttpUrl}" />
                    </param>
                </param>
                <param name="Parameter">
                    <param name="ParameterName" value="@HttpMethod" />
                    <param name="DbType" value="String" />
                    <param name="Size" value="255" />
                    <param name="Layout" type="log4net.Layout.PatternLayout">
                        <param name="ConversionPattern" value="%P{HttpMethod}" />
                    </param>
                </param>
                <param name="Parameter">
                    <param name="ParameterName" value="@FormVariables" />
                    <param name="DbType" value="String" />
                    <param name="Size" value="-1" />
                    <param name="Layout" type="log4net.Layout.PatternLayout">
                        <param name="ConversionPattern" value="%P{FormVariables}" />
                    </param>
                </param>
                <param name="Parameter">
                    <param name="ParameterName" value="@HttpUserAgent" />
                    <param name="DbType" value="String" />
                    <param name="Size" value="255" />
                    <param name="Layout" type="log4net.Layout.PatternLayout">
                        <param name="ConversionPattern" value="%P{HttpUserAgent}" />
                    </param>
                </param>
                <param name="Parameter">
                    <param name="ParameterName" value="@HttpQueryString" />
                    <param name="DbType" value="String" />
                    <param name="Size" value="-1" />
                    <param name="Layout" type="log4net.Layout.PatternLayout">
                        <param name="ConversionPattern" value="%P{HttpQueryString}" />
                    </param>
                </param>
                <param name="Parameter">
                    <param name="ParameterName" value="@HttpCookies" />
                    <param name="DbType" value="String" />
                    <param name="Size" value="-1" />
                    <param name="Layout" type="log4net.Layout.PatternLayout">
                        <param name="ConversionPattern" value="%P{HttpCookies}" />
                    </param>
                </param>
            </appender>
            <root>
                <appender-ref ref="AdoNetAppender" />
            </root>
        </log4net>
    </sitecore>
</configuration>

Creating the database

Here is the schema of the table:

CREATE TABLE [dbo].[Log](
    [ID] [bigint] IDENTITY(1,1) NOT NULL,
    [Date] [datetime] NOT NULL,
    [Thread] [varchar](255) NOT NULL,
    [Level] [varchar](255) NOT NULL,
    [Logger] [varchar](255) NOT NULL,
    [Message] [varchar](max) NOT NULL,
    [Exception] [varchar](max) NOT NULL,
    [MachineName] [varchar](4000) NOT NULL,
    [CurrentUser] [varchar](255) NOT NULL,
    [Roles] [varchar](1000) NOT NULL,
    [SitecoreItemID] [varchar](255) NOT NULL,
    [SitecoreItemName] [varchar](255) NOT NULL,
    [Language] [varchar](255) NOT NULL,
    [IpAddress] [varchar](255) NOT NULL,
    [ForwardedIpAddress] [varchar](255) NOT NULL,
    [HttpReferrer] [varchar](max) NOT NULL,
    [HttpUrl] [varchar](max) NOT NULL,
    [HttpMethod] [varchar](255) NOT NULL,
    [FormVariables] [varchar](max) NOT NULL,
    [HttpUserAgent] [varchar](255) NOT NULL,
    [HttpQueryString] [varchar](max) NOT NULL,
    [HttpCookies] [varchar](max) NOT NULL
) ON [PRIMARY] TEXTIMAGE_ON [PRIMARY]

Troubleshooting and Log4net’s Log

After completing all of this, you may find yourself in a place where nothing is being logged to the table. Here are a few things you can do.

1. Try adding <bufferSize value="1" /> to the appender configuration file. This will make sure records are written right away. For me, this didn’t seem to make a difference either way, so mine is commented at the moment.
   
2. Enable Log4net’s log. This requires two configuration changes: Add the following Application Setting (not a Sitecore setting):
   

<add key="log4net.Internal.Debug" value="true" />

Add the following to the Web.config file underneath the Sitecore node:

<system.diagnostics>
        <trace autoflush="true">
            <listeners>
                <add    name="textWriterTraceListener"
            type="System.Diagnostics.TextWriterTraceListener"
initializeData="[PATH]\data\log4net.txt" />
            </listeners>
        </trace>
    </system.diagnostics>

Now you should get a txt file with the log4net log.