I’ve used log4net in several projects to help with logging and debugging, but a unique requirement came up where I wanted to log not just human readable strings but to use the logging capability to store information about the actions users are performing on a MVC4 application.
I wanted to track the User, the Controller and the Action the user invoked, how long it took and if there was any error that occurred. So I created a custom class to represent this called ActionLoggerInfo and an custom ActionFilterAttribute which I applied as a global filter which called log4net to log the object.
public class ActionLoggerInfo
{
public string Controller { get; set; }
public string Action { get; set; }
public string User { get; set; }
public long ActionDurationInMillis { get; set; }
public string ExceptionDetails { get; set; }
public override string ToString()
{
return JsonConvert.SerializeObject(this);
}
}
I logged actions from the filter using the standard Info method.
ILog _actionLogger = LogManager.GetLogger("ActionLogger");
. . .
var actionInfo = new ActionLoggerInfo()
{
// set values of action info object
…
};
_actionLogger.Info(actionInfo);
Quite importantly the log4net log methods (Debug, Info, Warn, …) accept message as object and not as a string, which allows for neat decoupling of serialization to happen via configurable layout patterns and converters.
Overriding the ToString method of my custom ActionLoggerInfo class got me some of the way because when the default converters were called, they would invoke the ToString override and I could serialize the object to Json, but what I really wanted was for the individual fields of the custom info object to be saved in seperate columns of a table so that I could cobble together some very simple usage reporting for the site. Since I was targetting a SQL environment having a message string that would have to be parsed for each logged row simply wouldn’t cut it.
I needed a way to map individual fields in the log to columns in an AdoNetAppender.
Out the box, log4net provides a bunch of conversion pattern names that can be used in the log pattern string to shape your log, written in printf style (for example %message). To solve the problem I needed to introduce a new named pattern to represent my custom object and then be able to address individual fields within it.
Adding a named Conversion Pattern
The route I took to do this was to create a custom PatternLayout class in order to introduce the new conversion pattern name %actionInfo for the ActionLoggerInfo class.
public class ActionLayoutPattern : PatternLayout
{
public ActionLayoutPattern()
{
AddConverter(new ConverterInfo
{
Name = "actionInfo",
Type = typeof(ActionConverter)
}
);
}
}
You’ll notice that there is no link to ActionLoggerInfo directly in this pattern, it only serves to establish the name "actionInfo" and the converter ActionConverter to be used to perform the conversion.
The Converter
The converter is responsible for handling conversion requests of a LoggingEvent when log4net calls it internally to render a given pattern name to the writer. The converter can then inspect whichever aspect of the LoggingEvent it needs to retrieve the value to write, including the MessageObject that was originally logged.
Since we’re passing the custom object in as the MessageObject we have everything that we need to inspect the object and pull out the fields that we want to log wh.
Patterns in log4net follow a %conversionPatternName{option} syntax. Where the conversionPatternName is used to identify which converter to use from the PatternLayout‘s list of converters, and the option in squiggly brackets allows you to pass additional information.
In the case of a custom object this gives us the mechanism we need to specify which field of an object we are wanting to render. eg. %actionInfo{controller}
The option in the %<conversionPatternName>{<option>} pattern syntax is extracted and mapped to ActionConvert.Option when the converter is invoked, so it is trivial to inspect it and return the field you want.
public class ActionConverter : PatternConverter
{
protected override void Convert(System.IO.TextWriter writer, object state)
{
if (state == null)
{
writer.Write(SystemInfo.NullText);
return;
}
var loggingEvent = state as LoggingEvent;
var actionInfo = loggingEvent.MessageObject as ActionLoggerInfo;
if (actionInfo == null)
{
writer.Write(SystemInfo.NullText);
}
else
{
switch(this.Option.ToLower())
{
case "controller" :
writer.Write(actionInfo.Controller);
break;
case "action" :
writer.Write(actionInfo.Action);
break;
case "duration" :
writer.Write(actionInfo.ActionDurationInMillis);
break;
case "user" :
writer.Write(actionInfo.User);
break;
case "exceptiondetails" :
writer.Write(actionInfo.ExceptionDetails);
break;
default :
writer.Write(SystemInfo.NullText);
break;
}
}
}
}
Using a bit of Reflection it would be easy to make a generic object converter that could reflect to extract the values properties of an object based on the option parameter, but for my purposes the switch statement was adequate
Creating the Log Table in the database
CREATE SCHEMA [Logs]
GO
CREATE TABLE [Logs].[Actions]
(
[Id] INT NOT NULL IDENTITY(1,1) PRIMARY KEY,
[Date] [datetime] NOT NULL,
[Thread] [varchar] (255) NOT NULL,
[Level] [varchar] (50) NOT NULL,
[Logger] [varchar] (255) NOT NULL,
[Message] [varchar] (4000) NOT NULL,
[Exception] [varchar] (2000) NULL,
[Controller] [varchar] (2000) NULL,
[Action] [varchar] (2000) NULL,
[User] [varchar] (2000) NULL,
[Duration] [int] NULL
)
Easily done.
Configuring the AdoNetAppender
We have to modify the commandText of the appender to contain the new database fields and parameters for the custom object’s fields.
Each parameter is then specified explicitly with our custom PatternLayout (in this example MyApp.ActionLayoutPattern) and with a conversionPattern that uses the custom conversion pattern name (in this example %actionInfo) and the field {controller}.
<parameter>
<parameterName value="@controller" />
<dbType value="String" />
<size value="2000" />
<layout type="MyApp.ActionLayoutPattern">
<conversionPattern value="%actionInfo{controller}" />
</layout>
</parameter>
Full appender config example :
<log4net>
<appender name="AdoNetAppender" type="log4net.Appender.AdoNetAppender">
<bufferSize value="100" />
<connectionType value="System.Data.SqlClient.SqlConnection, System.Data, Version=1.0.3300.0, Culture=neutral, PublicKeyToken=b77a5c561934e089" />
<connectionString value="Data Source=(localdb)\Projects;Initial Catalog=LoggingDB;Integrated Security=true;" />
<commandText value="INSERT INTO [Logs].[Actions] ([Date],[Thread],[Level],[Logger],[Message],[Exception],[Controller],[Action],[User],[Duration]) VALUES (@log_date, @thread, @log_level, @logger, @message, @exception, @controller, @action, @user, @duration)" />
<parameter>
<parameterName value="@log_date" />
<dbType value="DateTime" />
<layout type="log4net.Layout.RawTimeStampLayout" />
</parameter>
<parameter>
<parameterName value="@thread" />
<dbType value="String" />
<size value="255" />
<layout type="log4net.Layout.PatternLayout">
<conversionPattern value="%thread" />
</layout>
</parameter>
<parameter>
<parameterName value="@log_level" />
<dbType value="String" />
<size value="50" />
<layout type="log4net.Layout.PatternLayout">
<conversionPattern value="%level" />
</layout>
</parameter>
<parameter>
<parameterName value="@logger" />
<dbType value="String" />
<size value="255" />
<layout type="log4net.Layout.PatternLayout">
<conversionPattern value="%logger" />
</layout>
</parameter>
<parameter>
<parameterName value="@message" />
<dbType value="String" />
<size value="4000" />
<layout type="log4net.Layout.PatternLayout">
<conversionPattern value="%message" />
</layout>
</parameter>
<parameter>
<parameterName value="@exception" />
<dbType value="String" />
<size value="2000" />
<layout type="log4net.Layout.ExceptionLayout" />
</parameter>
<parameter>
<parameterName value="@controller" />
<dbType value="String" />
<size value="2000" />
<layout type="Beam.Ui.Filters.ActionLayoutPattern">
<conversionPattern value="%actionInfo{controller}" />
</layout>
</parameter>
<parameter>
<parameterName value="@action" />
<dbType value="String" />
<size value="2000" />
<layout type="Beam.Ui.Filters.ActionLayoutPattern">
<conversionPattern value="%actionInfo{action}" />
</layout>
</parameter>
<parameter>
<parameterName value="@user" />
<dbType value="String" />
<size value="2000" />
<layout type="Beam.Ui.Filters.ActionLayoutPattern">
<conversionPattern value="%actionInfo{user}" />
</layout>
</parameter>
<parameter>
<parameterName value="@duration" />
<dbType value="Int32" />
<layout type="Beam.Ui.Filters.ActionLayoutPattern">
<conversionPattern value="%actionInfo{duration}" />
</layout>
</parameter>
</appender>
…
</log4net>
Great I hope that helps someone else in a similar position.
Related Articles
Here are the articles that helped me along the way…
Log4Net custom LayoutPattern - Dejan Fajfar (April 2011)