Random Notes: Another log4net HowTo

Intro and Configuration

Log4net is a sophisticated logging library for .NET applications (web or otherwise). It’s not however cumbersome to use, neither it’s intrusive I believe. I will try in this post to illustrate what I think is good configuration for this library. A configuration that lets a .NET application uses but not have a hard dependency on it.

You start by downloading the library here http://logging.apache.org/log4net/. There you’ll also find good examples and documentation. Add a reference to your .NET app.

Now there are a number of ways you can configure the library, what to log (date & time stamp, thread #, custom message, exceptions etc) and where to log (a database, a file or the standard output {console}). A good way to configure the library is tell your application and the assembly level where the configuration file for log4net (typically an XML file) lives. You do so by adding the below line to your AssemblyInfo.vb or (AsssemblyInfo.cs) class

<Assembly: log4net.Config.XmlConfigurator(ConfigFile:="MyAppLog4net.config", Watch:=True)>

The configFile can a full-path to your log4net configuration file. The watch flag if set true tells log4net to reload the configuration at runtime if the configuration file was changed.

Now technically you can start logging. Given the simple config file below

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

</layout>

</appender>

<root>

<appender-ref ref="RollingFile" />

</root>

</log4net>

With this log file we can log a visit to web page

Protected Sub Page_Load(ByVal sender As Object, ByVal e As System.EventArgs) Handles Me.Load

log4net.LogManager.GetLogger(Me.GetType().Name).Info(Me.Request.Path + " visited.")

End Sub

A sample output: 2012-04-21 09:21:33,970 INFO 21 default_aspx - /Default.aspx visited.

A better approach (create your own wrapper):

Instead of invoking log4net directly from your business logic layer, data layer, etc. a better approach is to create wrapper logging layer. The benefit is that you decouple your application from a specific logging implementation.

One way to do this is to create an interface that defines your logging operations. A simple interface can look like the below.

Public Interface ICustomLog

Sub Debug(ByVal source As Type, ByVal message As String, ByVal exception As Exception, ByVal customObject As CustomLogProperties)

Sub Info(ByVal source As Type, ByVal message As String, ByVal exception As Exception, ByVal customObject As CustomLogProperties)

Sub Warn(ByVal source As Type, ByVal message As String, ByVal exception As Exception, ByVal customObject As CustomLogProperties)

Sub [Error](ByVal source As Type, ByVal message As String, ByVal exception As Exception, ByVal customObject As CustomLogProperties)

Sub Fatal(ByVal source As Type, ByVal message As String, ByVal exception As Exception, ByVal customObject As CustomLogProperties)

End Interface

Any type of logging implementation will then have to adhere to the defined interface. The parameters passed to various logging methods will apparent later, hopefully.

Here is an implementation that will rely fundamentally on log4net. But before showing the concrete implementation, let’s talk about custom properties that you can tell log4net to log for you.

Logging Custom Properties using log4net [.Core.LoggingEvent]

By default log4net will log a number of properties (thread number, date of event, custom message etc.). If you wish to add properties that are specific to your application, log4net will let you do that through a number of ways. One of the ways that you can load a log4net logger object with custom properties is through using the LoggingEvent class. The sample code will illustrate how. One of the common issues one runs to when using custom properties is that even it appears the code is using them correctly, they don’t show in the log file/ log table etc. This is almost always due to the fact that configuration file is not written correctly to tell log4net how to render or from where to get the custom properties; so special care needs to be given to how the configuration is written.

For example, let’s assume that one of the requirements of your is logging three custom properties: the SessionID {asp.net SessionID}, the raw request’s URL, and an application name. Putting these three variables in a custom object is a good idea (CustomLogProperties in sample). Every time we need to log an event with then create an instance of CustomLogProperites and pass to our logger who takes care of creating a LoggingEvent populated with the custom properties.

Private Sub SetCustomLogProperties(ByVal loggingEvent As log4net.Core.LoggingEvent, ByVal customLogObject As CustomLogProperties)

If customLogObject Is Nothing OrElse loggingEvent Is Nothing Then

Return

End If

loggingEvent.Properties(CustomFileLogger.ApplicationNameKey) = customLogObject.ApplicationName

loggingEvent.Properties(CustomFileLogger.RequestKey) = customLogObject.RequestPath

loggingEvent.Properties(CustomFileLogger.ASPSesssionIDKey) = customLogObject.SessionID

End Sub

Private Function GetLoggingEvent(ByVal source As Type, ByVal logger As log4net.ILog, ByVal message As String, ByVal exception As Exception _

, ByVal level As log4net.Core.Level, ByVal customLogObject As Object) As log4net.Core.LoggingEvent

If source Is Nothing OrElse logger Is Nothing Then

Return Nothing

End If

Dim loggingEvent As New log4net.Core.LoggingEvent(source, logger.Logger.Repository, logger.Logger.Name, level, message, exception)

SetCustomLogProperties(loggingEvent, customLogObject)

Return loggingEvent

End Function

Public Sub Debug(ByVal source As Type, ByVal message As String, ByVal exception As Exception, _

ByVal customLogObject As CustomLogProperties) Implements ICustomLog.Debug

Dim logger As log4net.ILog = GetLogger(source)

Dim loggingEvent = GetLoggingEvent(source, logger, message, exception, log4net.Core.Level.Debug, customLogObject)

If loggingEvent IsNot Nothing Then

logger.Debug(message)

End If

End Sub

Here is the relevant portion of the log configuration file which will instruct the log4net library on how to write the custom properties

<conversionPattern value="%date %level %thread %logger - %message %exception [%property{ApplicationName}]

[%property{RequestPath}] [%property{SessionID}] %newline" />

</layout>

Notice the use of %property{property_name} syntax.

Code Listings

Configuration

    
 <?xml version="1.0" encoding="utf-8" ?>
<log4net>
  <appender name="RollingFile" type="log4net.Appender.RollingFileAppender">
    <file value="myLog.log" />
    <appendToFile value="true" />
    <maximumFileSize value="100KB" />
    <maxSizeRollBackups value="2" />

    <layout type="log4net.Layout.PatternLayout">
      <conversionPattern value="%date %level %thread %logger - %message %exception [%property{ApplicationName}]
                         [%property{RequestPath}] [%property{SessionID}] %newline" />
    </layout>
  </appender>

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

Sample Code

 

Partial Public Class _Default
    Inherits System.Web.UI.Page
    Private logger As ICustomLog = CustomFileLogger.GetInstance()
    Protected Sub Page_Load(ByVal sender As Object, ByVal e As System.EventArgs) Handles Me.Load
        'log4net.LogManager.GetLogger(Me.GetType().Name).Info(Me.Request.Path + " visited.")
        logger.Info(Me.GetType(), "Page visitied", Nothing, New CustomLogProperties() With {.ApplicationName = "MyApp", .RequestPath = Request.RawUrl, .SessionID = Me.Session.SessionID})
        CauseAndLogException()
    End Sub
    Private Sub CauseAndLogException()
        Dim str = "4/31/2012"
        Try
            DateTime.Parse(str)
        Catch ex As Exception
            logger.Error(Me.GetType(), "An error occurred in " + System.Reflection.MethodBase.GetCurrentMethod().Name, ex, New CustomLogProperties With _
                         {.ApplicationName = "MyApp", .RequestPath = Request.RawUrl, .SessionID = Me.Session.SessionID})
        End Try
    End Sub
End Class

Public Interface ICustomLog
    Sub Debug(ByVal source As Type, ByVal message As String, ByVal exception As Exception, ByVal customObject As CustomLogProperties)
    Sub Info(ByVal source As Type, ByVal message As String, ByVal exception As Exception, ByVal customObject As CustomLogProperties)
    Sub Warn(ByVal source As Type, ByVal message As String, ByVal exception As Exception, ByVal customObject As CustomLogProperties)
    Sub [Error](ByVal source As Type, ByVal message As String, ByVal exception As Exception, ByVal customObject As CustomLogProperties)
    Sub Fatal(ByVal source As Type, ByVal message As String, ByVal exception As Exception, ByVal customObject As CustomLogProperties)
End Interface
Public Class CustomFileLogger
    Implements ICustomLog
    Private Shared _loggers As Dictionary(Of Type, log4net.ILog) = New Dictionary(Of Type, log4net.ILog)
    Private Shared _lock = New Object()
    Private Shared _instance As ICustomLog = Nothing
    Private Sub New()
    End Sub
    Public Shared Function GetInstance() As ICustomLog
        If _instance Is Nothing Then
            _instance = New CustomFileLogger()
        End If
        Return _instance
    End Function
    Private Function GetLogger(ByVal source As Type) As log4net.ILog
        SyncLock _lock
            If CustomFileLogger._loggers.ContainsKey(source) Then
                Return CustomFileLogger._loggers(source)
            Else
                Dim logger As log4net.ILog = log4net.LogManager.GetLogger(source)
                CustomFileLogger._loggers.Add(source, logger)
                Return logger
            End If
        End SyncLock
    End Function
    Private Sub SetCustomLogProperties(ByVal loggingEvent As log4net.Core.LoggingEvent, ByVal customLogObject As CustomLogProperties)
        If customLogObject Is Nothing OrElse loggingEvent Is Nothing Then
            Return
        End If
        loggingEvent.Properties(CustomFileLogger.ApplicationNameKey) = customLogObject.ApplicationName
        loggingEvent.Properties(CustomFileLogger.RequestKey) = customLogObject.RequestPath
        loggingEvent.Properties(CustomFileLogger.ASPSesssionIDKey) = customLogObject.SessionID
    End Sub
    Private Function GetLoggingEvent(ByVal source As Type, ByVal logger As log4net.ILog, ByVal message As String, ByVal exception As Exception _
                                     , ByVal level As log4net.Core.Level, ByVal customLogObject As Object) As log4net.Core.LoggingEvent
        If source Is Nothing OrElse logger Is Nothing Then
            Return Nothing
        End If
        Dim loggingEvent As New log4net.Core.LoggingEvent(source, logger.Logger.Repository, logger.Logger.Name, level, message, exception)
        SetCustomLogProperties(loggingEvent, customLogObject)
        Return loggingEvent
    End Function
    Public Sub Debug(ByVal source As Type, ByVal message As String, ByVal exception As Exception, _
                     ByVal customLogObject As CustomLogProperties) Implements ICustomLog.Debug
        Dim logger As log4net.ILog = GetLogger(source)
        Dim loggingEvent = GetLoggingEvent(source, logger, message, exception, log4net.Core.Level.Debug, customLogObject)
        If loggingEvent IsNot Nothing Then
            logger.Debug(message)
        End If
    End Sub
    Public Sub Info(ByVal source As Type, ByVal message As String, ByVal exception As Exception, ByVal customLogObject As CustomLogProperties) Implements ICustomLog.Info
        Dim logger As log4net.ILog = GetLogger(source)
        Dim loggingEvent = GetLoggingEvent(source, logger, message, exception, log4net.Core.Level.Info, customLogObject)
        If loggingEvent IsNot Nothing Then
            logger.Logger.Log(loggingEvent)
        End If
    End Sub
    Public Sub Warn(ByVal source As Type, ByVal message As String, ByVal exception As Exception, ByVal customLogObject As CustomLogProperties) Implements ICustomLog.Warn
        Dim logger As log4net.ILog = GetLogger(source)
        Dim loggingEvent = GetLoggingEvent(source, logger, message, exception, log4net.Core.Level.Warn, customLogObject)
        If loggingEvent IsNot Nothing Then
            logger.Logger.Log(loggingEvent)
        End If
    End Sub
    Public Sub [Error](ByVal source As Type, ByVal message As String, ByVal exception As Exception, ByVal customLogObject As CustomLogProperties) Implements ICustomLog.Error
        Dim logger As log4net.ILog = GetLogger(source)
        Dim loggingEvent = GetLoggingEvent(source, logger, message, exception, log4net.Core.Level.Error, customLogObject)
        If loggingEvent IsNot Nothing Then
            logger.Logger.Log(loggingEvent)
        End If
    End Sub
    Public Sub Fatal(ByVal source As Type, ByVal message As String, ByVal exception As Exception, ByVal customLogObject As CustomLogProperties) Implements ICustomLog.Fatal
        Dim logger As log4net.ILog = GetLogger(source)
        Dim loggingEvent = GetLoggingEvent(source, logger, message, exception, log4net.Core.Level.Fatal, customLogObject)
        If loggingEvent IsNot Nothing Then
            logger.Logger.Log(loggingEvent)
        End If
    End Sub
    Private Shared Sub FlushLog()
        For Each log In _loggers
            Dim rep As log4net.Repository.ILoggerRepository
            rep = log.Value
            For Each appender As log4net.Appender.BufferingAppenderSkeleton In rep.GetAppenders()
                appender.Flush()
            Next
        Next
    End Sub
    Private Shared ReadOnly ApplicationNameKey As String = "ApplicationName"
    Private Shared ReadOnly RequestKey As String = "RequestPath"
    Private Shared ReadOnly ASPSesssionIDKey As String = "SessionID"
End Class
Public Class CustomLogProperties
    Public ApplicationName As String
    Public RequestPath As String
    Public SessionID As String
End Class

Useful Links:
http://logging.apache.org/log4net/
http://haacked.com/archive/2006/09/27/Log4Net_Troubleshooting.aspx

Random Notes

Saturday, April 21, 2012

Another log4net HowTo

No comments:

Post a Comment