Using log4net in Web Applications – a real-life example
I have seen many different configurations for Log4Net. Log4Net is a very simple, but flexible framework and there are lot of ways to configure it. Here is a real-life example on how we are using in the applications I am working on.
First off, I won't say that this is the one and only way you should use Log4Net, but it handles most of the scenarios I can think of. Some people think that one should not write wrappers for the loggers and use the logging framework directly in the class, but to be honest I like the wrapper because it makes it very simple to use the logging framework without too much knowledge on how it works. I would say that 95% of what is being logged, is typically errors and debug/useful information. I can't see any problem using a wrapper as I get the information I need from the loggers.
Goals with this log configuration
- Most important is of course logging errors. All errors should be logged.
- Errors should be logged in a global file on the server that will role once a day.
- Errors should be sent by email.
- It should be possible to notify important information by email
- It should be easy for the developers to use the logging framework
- It should be possible to change log-level without restarting the application
Configuration and setup
Log4Net consists of only one DLL. Get the latest version and put it in your bin folder. Make a reference to it in the Web Application Project.
Log4net.config
Create a new config file in the root of your Web Application. Name it Log4Net.config and paste the following code:
<?xml version="1.0" encoding="utf-8" ?>
<configuration>
<configSections>
<section name="log4net" type="log4net.Config.Log4NetConfigurationSectionHandler, log4net" />
</configSections>
<log4net>
<appender name="RollingLogFileAppender" type="log4net.Appender.RollingFileAppender">
<threshold value="INFO" />
<file value="Log\[applicationname].log" />
<appendToFile value="true" />
<rollingStyle value="Date" />
<datePattern value="'.'yyyyMMdd'.log'" />
<layout type="log4net.Layout.PatternLayout">
<conversionPattern value="%date [%thread] %-5level %logger %X{user} %X{url} - %message%newline" />
</layout>
</appender>
<appender name="SmtpAppenderError" type="log4net.Appender.SmtpAppender">
<!--Set threshold for this appender-->
<threshold value="ERROR" />
<to value="[someone]@[somewhere.com]" />
<from value="[someone]@[somewhere.com]" />
<subject value="Error from [applicationname]" />
<smtpHost value="[100.100.100.100]" />
<bufferSize value="1" />
<lossy value="false" />
<layout type="log4net.Layout.PatternLayout">
<conversionPattern value="%date %-5level %logger %X{user} %X{url} - %message%newline" />
</layout>
</appender>
<appender name="SmtpAppenderNotify" type="log4net.Appender.SmtpAppender">
<!--Set threshold for this appender-->
<threshold value="INFO" />
<to value="[someone]@[somewhere.com]" />
<from value="[someone]@[somewhere.com]" />
<subject value="Error from [applicationname]" />
<smtpHost value="[100.100.100.100]" />
<bufferSize value="1" />
<lossy value="false" />
<layout type="log4net.Layout.PatternLayout">
<conversionPattern value="%date - %message%newline" />
</layout>
</appender>
<root>
<level value="Error" />
</root>
<logger name="Application">
<!--Set level for this logger-->
<level value="INFO" />
<appender-ref ref="RollingLogFileAppender" />
<appender-ref ref="SmtpAppenderError" />
</logger>
<logger name="Notify">
<!--Set level for this logger-->
<level value="INFO" />
<appender-ref ref="RollingLogFileAppender" />
<appender-ref ref="SmtpAppenderNotify" />
</logger>
</log4net>
</configuration>
Some comments on the Log4net.config file:
- The RollingFileAppender is great for rolling the logfile once a day.
- It has a threshold of INFO, meaning it will log anything from the application except debug information
- The logfiles are created in a subdirectory of web root. This should be changed on the production server to not expose information about the application.
- The datePattern is specifying how the rolling files are named. The current day will be named "applicationname.log" and yesterdays file will be named "applicationname.log.20081211.log". The rolling file extension (.log) makes it easy to open the file in the same editor as the current log. All files will be sorted correctly when using the ISO style date in the filename.
- In the conversionPattern you will see two speacial entries with the following format: %X{name}. These are custom formats which can be used for special purposes. This configuration adds the authenticated username and the url which fails if there is an error. This is useful information.
- The SmtpAppenders are used for sending emails. It's really not my favourite configuration, spamming the developers or some other people with emails when some errors occur, but some like it.
- The threshold is different for the two SmtpAppenders, as is the subject of the email.
- The buffersize is set to 1 in the example, meaning that the email is sent right away when an error occur. Increasing the buffer will hold the email until the buffer is reached. This can be useful on the production server, especially for the Notify appender as it is probably not that important to notify right away.
- Lossy is set to false, also to send the email right away. It is possible to hold the email until an evaluator is triggered, for instance when a error occurs. Setting lossy to true requires an evaluator.
- It is possible to add filters to the appenders to determine which emails should be sent and which to drop.
- There are two specific loggers that the application will use. The root logger can be used to log 3.party libraries also using Log4Net. I like to use specific loggers in the application and enabling the root logger if I am tracing an error where I need more information from 3.party libraries, ie. NHibernate or other frameworks using Log4net. Remember to set the level for the logger. If not set, the default level is WARN, which means INFO messages will not be logged.
To be able to use the Log4Net.config file instead of putting everything into web.config, you will need to add the following line to AssemblyInfo.vb:
<Assembly: log4net.Config.XmlConfigurator(ConfigFile:="Log4Net.config", Watch:=True)>
The advantage of separating the Log4Net configuration is that it is possible to change the configuration of the logging without restarting the application by changing web.config. It also gives an better overview of the configuration, not having to browse through web.config to find the logging configuration.
Logging unhandled errors
All unhandled errors should be logged, which is pretty easy to achieve in web applications. Here is the Global.asax file:
Imports System.Web
Imports log4net
Imports MainLib
Public Class [Global]
Inherits System.Web.HttpApplication
Sub Application_Start(ByVal sender As Object, ByVal e As EventArgs)
' Fires when the application is started
' Initialize the logger in this context.
LogManager.GetLogger(Me.GetType)
LogHandler.LogInfo("============================", LogHandler.LogType.General)
LogHandler.LogInfo(" Starting application", LogHandler.LogType.General)
LogHandler.LogInfo("============================", LogHandler.LogType.General)
End Sub
Sub Session_Start(ByVal sender As Object, ByVal e As EventArgs)
' Fires when the session is started
End Sub
Sub Application_BeginRequest(ByVal sender As Object, ByVal e As EventArgs)
' Fires at the beginning of each request
End Sub
Sub Application_AuthenticateRequest(ByVal sender As Object, ByVal e As EventArgs)
' Fires upon attempting to authenticate the use
End Sub
Sub Application_Error(ByVal sender As Object, ByVal e As EventArgs)
' Fires when an error occurs
LogHandler.LogError("Unhandled exception occured!",
HttpContext.Current.User, HttpContext.Current.Request.Url,
HttpContext.Current.Server.GetLastError())
End Sub
Sub Session_End(ByVal sender As Object, ByVal e As EventArgs)
' Fires when the session ends
End Sub
Sub Application_End(ByVal sender As Object, ByVal e As EventArgs)
' Fires when the application ends
End Sub
End Class
Comments on Global.asax
- I have added some information logging in the Application_Start event. This will trigger every time the applications starts or recycles. If this occurs often you probably have some problems with resources on the server, ie. too little memory available for the application.
- Application_Error occurs every time an unhandled error occurs. Use this to log all errors not logged elsewhere.
- I have to initialize the logging framework in Application_Start by calling
LogManager.GetLogger(Me.GetType). I'm not sure whether this is a bug or by design. It is not possible to let the LogHandler do the initialization. LogHandler is a wrapper class located in another assembly, maybe that is a problem, without really knowing why. LogManager is a class in Log4Net.
The LogHandler class
Imports System.Security.Principal
Imports log4net
Public Class LogHandler
Const _defaultApplicationLogger As String = "Application"
Public Enum LogType
General
Notify
End Enum
Public Shared Sub LogError(ByVal message As String, ByVal [error] As Exception)
Dim logger As ILog = LogManager.GetLogger(_defaultApplicationLogger)
If Not [error].InnerException Is Nothing Then
[error] = [error].InnerException
End If
If logger.IsErrorEnabled Then
logger.Error(message, [error])
End If
End Sub
Public Shared Sub LogError(ByVal message As String, _
ByVal user As IPrincipal, ByVal url As Uri, _
ByVal [error] As Exception)
SetOptionalParametersOnLogger(user, url)
LogError(message, [error])
End Sub
Public Shared Sub LogInfo(ByVal message As String, ByVal type As LogType)
Dim logger As ILog = Nothing
If type = LogType.Notify Then
logger = LogManager.GetLogger(LogType.Notify.ToString)
Else
logger = LogManager.GetLogger(_defaultApplicationLogger)
End If
If logger.IsInfoEnabled Then
logger.Info(message)
End If
End Sub
Public Shared Sub LogWarning(ByVal message As String, ByVal [error] As Exception)
Dim logger As ILog = LogManager.GetLogger(_defaultApplicationLogger)
If Not [error].InnerException Is Nothing Then
[error] = [error].InnerException
End If
If logger.IsWarnEnabled Then
logger.Warn(message, [error])
End If
End Sub
Public Shared Sub LogWarning(ByVal message As String, _
ByVal user As IPrincipal, ByVal url As Uri, _
ByVal [error] As Exception)
SetOptionalParametersOnLogger(user, url)
LogWarning(message, [error])
End Sub
Private Shared Sub SetOptionalParametersOnLogger(ByVal user As IPrincipal, ByVal url As Uri)
'set user to log4net context, so we can use %X{user} in the appenders
If Not user Is Nothing AndAlso user.Identity.IsAuthenticated Then
MDC.[Set]("user", user.Identity.Name)
End If
'set url to log4net context, so we can use %X{url} in the appenders
MDC.[Set]("url", url.ToString())
End Sub
End Class
Comments on LogHandler
- It's a pretty simple class which is easy to use. I could have added more wrapper methods with overload
- The LogType enum defines whether the message should be notified (emailed) or not.
- If I forget to set the level on the logger in the Log4Net.config, the logger.IsInfoEnabled will return false.
- I am using the MDC class in the Log4Net framework to add the custom entries in the logged message for user and url (see Log4Net.config above)
Handling an error and notifying with success
Sometimes when you know what could go wrong and you want to display a nice error message to the user, you could handle the error and display an errormessage to the user.
Example:
Private Function CreateUser() As User
Dim userName As String = TextBoxUserName.Text
Dim password As String = TextBoxPassword.Text
Try
Dim user As New User(userName, password)
LogHandler.LogInfo("Yahoo! User with username " & userName & " created.", LogHandler.LogType.Notify)
Return user
Catch iunex As InvalidUserNameException
PageTools.DisplayError(Page, iunex)
LogHandler.LogWarning("Error creating user with username " & userName, iunex)
Catch ipex As InvalidPasswordException
PageTools.DisplayError(Page, ipex)
LogHandler.LogWarning("Error creating user with password " & password, ipex)
End Try Return Nothing
End Function
Comments on CreateUser:
- If successful, a notification is sent by email by using the LogInfo method and using LogHandler.Logtype.Notify
- The User class will throw InvalidUserNameException or InvalidPasswordException in the credentials are invalid. I wish to display the errors to the user instead of displaying a general error page. In real life I would probably use some validation before calling the User constructor, but this is only an example.
- In addition to displaying the error to the user, the error is logged as a warning.This means it will be logged, but no email will be sent to the mailbox as this is not an error in the application.
- All other exceptions raised when creating the user will be caught in Application_Error in Global.asax and logged there.
Loginformation
Ok, now I have all the code I need to do decent logging. So what do I expect to see in the logfiles?
When building the application in DEBUG mode I will see the following in the logfile:
2008-12-11 16:56:24,453 [14] INFO Application (null) (null) - ============================
2008-12-11 16:56:24,468 [14] INFO Application (null) (null) - Starting application
2008-12-11 16:56:24,468 [14] INFO Application (null) (null) - ============================
2008-12-11 16:56:25,937 [14] WARN Application 3DX5G3J\knuth http://localhost/fdb/default.aspx -
Error creating user with username Knut Hamang
DAL.InvalidUserNameException: Username is already in use! Please select another username.
at DAL.User..ctor(String username, String password) in C:\Knut\code\Repository\Internal_Systems\fdb\trunk\DAL\User.vb:line 97
at fdb.default.CreateUser() in C:\Knut\code\Repository\Internal_Systems\fdb\trunk\Web\default.aspx.vb:line 69
Building in RELEASE mode I get the following information:
2008-12-11 16:59:21,406 [14] INFO Application (null) (null) - ============================
2008-12-11 16:59:21,421 [14] INFO Application (null) (null) - Starting application
2008-12-11 16:59:21,421 [14] INFO Application (null) (null) - ============================
2008-12-11 16:59:22,812 [14] WARN Application 3DX5G3J\knuth http://localhost/fdb/default.aspx -
Error creating user with username Knut Hamang
DAL.InvalidUserNameException: Username is already in use! Please select another username.
at DAL.User..ctor(String username, String password)
at fdb.default.CreateUser()
The difference is the stacktrace. I get the stacktrace in both cases, but I also get the line numbers in DEBUG mode. I can still read the trace and locate the method in the file that throws the error. The conclusion is that I get enough information to trace and fix the error, if there is one.
Please leave any comments on the configuration, and feel free to discuss different logging strategies for Web Applications.
9 Comments to Using log4net in Web Applications – a real-life example
Hi!
I'm a pretty big fan of Log4Net, but what I do find limiting is that there isn't anything in most logging framework that will let me define a custom structure for logging so the data stored can be easily queried later.
I mean, when you've got millions of log entries, you've either got to read through them all or write an insanely powerful text processor. Instead, if you use custom logging you can simply filter the entries by a database column value (assuming you are logging to a DB)
-Nitin
AlessandroNovember 16, 2009
do you have the example using C#?
Thanks
ckApril 12, 2010
2008-12-11 16:59:21,406 [14] INFO Application (null) (null)
is anyone know what mean by [14] in the above logs?
VenkateshOctober 12, 2010
Wow!!!,
Super, this is what I was looking for. Thank you!!, I guess I am becoming lazy day by day.
Sharing the knowledge is so easy now a days. Is it good or bad? It is really gooooooooooooooood.
HaiderJanuary 13, 2011
Thanks for your great information.
I am using log4net but in my case isDebugEnabled , IsErrorEnabled etc remain always false. I have searched a lot but nothing could be found.
I am using the below code.
===============================================
Private Shared isDebugEnabled As Boolean = log.IsDebugEnabled
If isDebugEnabled Then
log4net.Config.XmlConfigurator.Configure()
log.Debug("This is debug")
End If
================================================
Please guide me, I am tired after much searching.
KaushalFebruary 9, 2011
My website is running under asp.net user under IIS. In that i've created one virtual directory as 'Logs' which is internally pointing to my shared drive folder which is access by limited no. of users. Now my question is, how can i create log file on shared folder using log4Net. Is there anyway by which, i'll provide user credentials when i create object of logger & create file or write log information on shared folder.
Regards,
Kaushal
KaushalFebruary 18, 2011
Ok. I got solution for the query i've asked before.
Here's the solution
In Log4Net configuration, Instead of putting filename, i've put placeholder for property name as below.
In my Log Class
Logger = LogManager.GetLogger(typeof(Class1));
//Do Impersonation to write files on Shared drive having access to Globalcv user.
//DoImpersonationIfRequired();
log4net.GlobalContext.Properties["LogName"] = ConfigurationHelper.LogFileName.ToString();
//Configuring Object
XmlConfigurator.Configure();
Thanks,
Kaushal
rickAugust 18, 2011
Hello.
Your article is very helpful.
But I still have some problem.
My website have several application running under iis.
|-Site_Root
|—-App1
|—-App2
|—-…
|—-web.config
I added log4net configuration in the web.config just as you suggest. There's a log4net.dll in every app's bin folder. But this doesn't work.
If I put a web.config in every app's folder with log4net section in it, logs will be output properly. But I do want all apps can share the root web.config log4net configuration.
Do you have any idea?
FAITHSeptember 26, 2011
Love the way you code vb, I havent seen this kind of beauty since the long lost days.
Leave a comment
Search
Knut Hamang
Recent Posts
Recent Comments
- Lori on Html to Pdf in .NET
- Susan on Html to Pdf in .NET
- Susan on Html to Pdf in .NET
- Ananth on Html to Pdf in .NET
- Tim M on Passing an object to ObjectDataSource
December 25, 2008