log4net database logging with custom parameters

Question

I have database logging in place using the AdoNetAppender. What I'd like to do is log the user identity on each log statement. However, I don't want to use the standard log4net %identity parameter for two reasons:

1. log4net warn that its extremely slow as it has to look up the context identity.
2. In some service components the standard identity is a service account but we have already captured the user identity in a variable and I'd like to use that.

I have seen code where some people use the log4net.ThreadContext to add additional properties but I understand that this is 'unsafe' due to thread interleaving (and it is also a performance drain).

My approach has been to extend the AdoNetAppenderParameter class thus:

public class UserAdoNetAppenderParameter : AdoNetAppenderParameter
{

    public UserAdoNetAppenderParameter()
    {
        DbType = DbType.String;
        PatternLayout layout = new PatternLayout();
        Layout2RawLayoutAdapter converter = new Layout2RawLayoutAdapter(layout);
        Layout = converter;
        ParameterName = "@username";
        Size = 255;
    }


    public override void Prepare(IDbCommand command)
    {            
        command.Parameters.Add(this);
    }


    public override void FormatValue(IDbCommand command, LoggingEvent loggingEvent)
    {            
        string[] data = loggingEvent.RenderedMessage.Split('~');
        string username = data[0];
        command.Parameters["@username"] = username;
    }

}

and then programmatically add this to the current appender like so:

ILog myLog = LogManager.GetLogger("ConnectionService");
IAppender[] appenders = myLog.Logger.Repository.GetAppenders();
AdoNetAppender appender = (AdoNetAppender)appenders[0];                    

appender.AddParameter(new UserAdoNetAppenderParameter());

myLog.InfoFormat("{0}~{1}~{2}~{3}", userName, "ClassName", "Class Method", "Message");

The intention here is to use a standard format for messages and parse the first part of the string which should always be the username. The FormatValue() method of the custom appender parameter should then use only that part of the string so that it can be written to a separate field in the log database.

My problem is that no log statements are written to the database. Oddly, when debugging, a breakpoint in the FormatValue() method is only hit when I stop the service.

I've trawled through loads of stuff relating to this but haven't yet found any answers. Has anyone managed to do this, or am I on the wrong trail. P.S. I've also tried extending the AdoNetAppender but it doesnt give you access to set the parameter values.

Answer 1

I also needed to log structured data and liked to use logging interface like this:

log.Debug( new {
    SomeProperty: "some value",
    OtherProperty: 123
})

So I also wrote custom AdoNetAppenderParameter class to do the job:

public class CustomAdoNetAppenderParameter : AdoNetAppenderParameter
{
    public override void FormatValue(IDbCommand command, LoggingEvent loggingEvent)
    {
        // Try to get property value
        object propertyValue = null;
        var propertyName = ParameterName.Replace("@", "");

        var messageObject = loggingEvent.MessageObject;
        if (messageObject != null)
        {
            var property = messageObject.GetType().GetProperty(propertyName);
            if (property != null)
            {
                propertyValue = property.GetValue(messageObject, null);
            }
        }

        // Insert property value (or db null) into parameter
        var dataParameter = (IDbDataParameter)command.Parameters[ParameterName];
        dataParameter.Value = propertyValue ?? DBNull.Value;
    }
}

Now log4net configuration can be used to log any property of given object:

<?xml version="1.0" encoding="utf-8"?>
<log4net>
    <appender name="MyAdoNetAppender" type="log4net.Appender.AdoNetAppender">
        <connectionType value="System.Data.SqlClient.SqlConnection, System.Data, Version=1.0.3300.0, Culture=neutral, PublicKeyToken=b77a5c561934e089" />
        <connectionString value="... your connection string ..." />
        <commandText value="INSERT INTO mylog ([level],[someProperty]) VALUES (@log_level,@SomeProperty)" />

        <parameter>
            <parameterName value="@log_level" />
            <dbType value="String" />
            <size value="50" />
            <layout type="log4net.Layout.PatternLayout">
                <conversionPattern value="%level" />
            </layout>
        </parameter>

        <parameter type="yourNamespace.CustomAdoNetAppenderParameter, yourAssemblyName">
            <parameterName value="@SomeProperty" />
            <dbType value="String" />
            <size value="255" />
        </parameter>
    </appender>

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

Answer 2

After some experimentation, I finally got this to work. Ensuring that log4net's internal logging helped identify the errors and downloading the log4net source code and reviewing the AdoNetAppenderParameter class showed how the FormatValue() method should be used. So, here's the amended custom appender parameter:

public class UserAdoNetAppenderParameter : AdoNetAppenderParameter
{        

    public override void FormatValue(IDbCommand command, LoggingEvent loggingEvent)
    {            
        string[] data = loggingEvent.RenderedMessage.Split('~');
        string username = string.Empty;
        if (data != null && data.Length >= 1)
            username = data[0];

        // Lookup the parameter
        IDbDataParameter param = (IDbDataParameter)command.Parameters[ParameterName];

        // Format the value
        object formattedValue = username;

        // If the value is null then convert to a DBNull
        if (formattedValue == null)
        {
            formattedValue = DBNull.Value;
        }

        param.Value = formattedValue;
    }

}

And to use this, I add it in the log4net config file like this:

<parameter type="MyAssembly.Logging.UserAdoNetAppenderParameter, MyAssembly">
 <parameterName value="@username" />
 <dbType value="String" />
 <size value="255" />
 <layout type="log4net.Layout.PatternLayout" value="%message" />  
</parameter>

And by convention, my log statements will be something like this:

if (log.IsDebugEnabled)
    log.DebugFormat("{0}~{1}~{2}", username, someOtherParameter, message);

If you look at the class, it uses data[0] as the username, so it is dependant on following the convention. It does, however, get the username into its own parameter and into a separate field in the log database table, without resorting to stuffing it temporarily into the unsafe ThreadContext.

Answer 3

Yes, thread agility means that you might not get the correct data back. For log4net, you will want to stick it in your HttpContext's Items collection.

The trouble is you have to do some work to get it back out when it's time to write those values to the database because of this I have always used Marek's Adaptive Property Provider class to do the grunt work for me. It's super simple to use it as all you have to do is the following:

log4net.ThreadContext.Properties["UserName"] = AdaptivePropertyProvider.Create("UserName", Thread.CurrentPrincipal.Identity.Name);

The adaptive property will know the appropriate place to retrieve the value when log4net requests it.

Alternative Option

If you're not stuck with log4net, NLog makes logging for ASP.NET websites way more simple because they natively support ASP.NET applications. Usage and even configuration is almost identical to log4net!