We have been using Log4Net as our logging tool for 3-4 years by now and I just wanted to share how we are using it and how incredibly powerful good logging can be.
First of all, if you are not familiar with Log4Net it is an open source, free-for-use logging framework under the Apache Foundation umbrella. Among its strengths is that it is fairly easy to get started with, it has a low impact on the application performance and it has a lot of adapters that lets you log to a lot of different destinations (console, file, database, event log, etc).
At the beginning we set up logging to console (for those systems that had console output) and file, but after a while we added logging to SQL Server. It is the combination of logs stored in a SQL database and full-text indexing of these logs that really gives us eyes in to what happens on our production servers.
Log to console
Logging to console is definitely the easiest way to get started with Log4Net. But writing to the console output is also the one that gives you least payback in form of long-term insight into your production systems. Log4Net can be configured either using xml or code, but xml is by far the most used. Typically you do the xml configuration in your app/web.config, but you can also keep the Log4Net configuration in separate xml files if you prefer. We chose the app/web.config approach and so the xml for console logging looks like this:<?xml version="1.0" encoding="utf-8"?>
<configuration>
<configSections>
<section
name="log4net"
type="log4net.Config.Log4NetConfigurationSectionHandler,Log4net" />
</configSections>
<log4net>
<root>
<level
value="DEBUG" />
<appender-ref
ref="ConsoleAppender" />
</root>
<appender
name="ConsoleAppender"
type="log4net.Appender.ConsoleAppender">
<layout
type="log4net.Layout.PatternLayout">
<param
name="ConversionPattern"
value="%d [%t] %-5p [%x] - %m%n" />
</layout>
<filter
type="log4net.Filter.LevelRangeFilter">
<param
name="LevelMin"
value="DEBUG" />
<param
name="LevelMax"
value="FATAL" />
</filter>
</appender>
</log4net>
</configuration>You can do this configuration in code as well, but the great benefit of using xml for the configuration is that you can change the settings (for instance the log level threshold) without re-deploying your application. In the case of web hosts you can even change it without restarting the application. If you’ve been a good boy/girl and set up debug-level logging in your code, you can just flip an xml-switch and additional log entries will start flowing in.
Log to file
If you want your logs to survive application restarts (and the console window buffer) and/or have an application that doesn’t have console output, logging to file would be the next step on logging ladder.
The main thing to keep in mind when logging to file is to set limits on how large each log file can get. Log4Net has some defaults that might not suit your situation so be sure to check out the documentation on how you can configure logging to file. For one of our systems we chose to have a 10 mb limit on each file which you can see in this xml config:
<log4net>
<root>
<level value="DEBUG" />
<appender-ref ref="LogFileAppender" />
</root>
<appender
name="LogFileAppender"
type="log4net.Appender.RollingFileAppender">
<param
name="File"
value="logs.txt" />
<param
name="AppendToFile"
value="true" />
<!-- Logfiles are rolled over to backup files when size limit is reached -->
<rollingStyle
value="Size" />
<!-- Maximum number of backup files that are kept before the oldest is erased -->
<maxSizeRollBackups
value="10" />
<!-- Maximum size that the output file is allowed to reach before being rolled over to backup files -->
<maximumFileSize
value="10MB" />
<!-- Indicating whether to always log to the same file -->
<staticLogFileName
value="true" />
<layout type="log4net.Layout.PatternLayout">
<param
name="ConversionPattern"
value="%-5p%d{yyyy-MM-dd hh:mm:ss} – %m%n" />
</layout>
</appender>
</log4net>The above config specifies that maximum 100 mb of logs will be kept on file (10 mb pr file and max 10 files).
Log to console and file
There is no problem logging to both console and file simultaneously and you can even set different log levels on each appender. If you want to have different files for different log levels (e.g. ‘debug.log’, ‘info.log’, etc), you can just configure as many file appenders as you need. Here is an example of logging to both console and file at the same time:
<log4net>
<root>
<level value="INFO" />
<appender-ref ref="LogFileAppender" />
<appender-ref ref="ConsoleAppender" />
</root>
<appender name="LogFileAppender" type="log4net.Appender.RollingFileAppender">
<filter type="log4net.Filter.LevelRangeFilter">
<param name="LevelMin" value="WARN" />
<param name="LevelMax" value="FATAL" />
</filter>
...
</appender>
<appender name="ConsoleAppender" type="log4net.Appender.ConsoleAppender">
...
</appender>
</log4net>
The default log level is set to INFO, which means that unless otherwise specified in the appenders, messages with level INFO, WARN, ERROR and FATAL will be logged. The file appender is set to only log WARN, ERROR and FATAL though.
Log to SQL Server
As already mentioned the logging to file and console is easy to get started with and does not take much effort to set up. Setting up logging to a database takes a bit more work, but it is far from difficult. Here is how we configured logging to a SQL database from one of our web hosts:
<root>
<level value="DEBUG" />
<appender-ref ref="AdoNetAppender" />
</root>
<appender
name="AdoNetAppender"
type="log4net.Appender.AdoNetAppender">
<threshold>INFO</threshold>
<bufferSize
value="50" />
<connectionType
value="System.Data.SqlClient.SqlConnection, System.Data, Version=1.0.3300.0, Culture=neutral, PublicKeyToken=b77a5c561934e089" />
<connectionString
value="data source=SERVERNAME;initial catalog=DATABASE;integrated security=false;persist security info=True;User ID=USERNAMEN;Password=PASSWORD" />
<commandText
value="INSERT INTO Logs ([Date],[Thread],[Source],[Level],[Logger],[Message],[Exception],[HostName]) VALUES (@log_date, @thread, 'LOG SOURCE',@log_level, @logger, @message, @exception, @hostname)" />
<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="@hostname" />
<dbType value="String" />
<size value="255" />
<layout type="log4net.Layout.PatternLayout">
<conversionPattern value="%property{log4net:HostName}" />
</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="-1" />
<layout type="log4net.Layout.PatternLayout">
<conversionPattern value="%message" />
</layout>
</parameter>
<parameter>
<parameterName value="@exception" />
<dbType value="String" />
<size value="-1" />
<layout type="log4net.Layout.ExceptionLayout" />
</parameter>
</appender>
</log4net>
The xml config is the same whether you are configuring logging in web- or app.config (you need to insert your own values for servername, database and login).
The main thing to point out here is the ‘buffer’ element, which tells Log4Net how many log entries to buffer up before writing them the database. There isn’t any correct number here and you need to figure out what suits your environment the best. The trade-offs are performance versus reliability, since a low buffer will take more resources because of the many writes to the database table (and yes, we learned that the hard way off course). A high buffer limit will be less reliable because if your application crashes, the logs not yet written will never be written.
Also; it might make sense to have different buffer limits for different environments. In the development and test/QA environments, a low limit might be preferable since the logs will be written faster to the database. And since the number of log entries will be far less than in the production system, it might be long time to wait for the logs to be available if you run with the same limits as in production. In a production environment, instant logs are in most cases not relevant and performance is more critical. Then again, reliability is also a good thing so you need to find a good trade off.
Another thing to notice is that we have a lot of subsystems (web hosts, windows services, message bus, cron jobs, etc) that logs to the database. To know where the logs come from we add the ‘LOG SOURCE’ as the name of the subsystem where the config is defined in (e.g ‘CommandsHost’ as the web host that receives commands from our application).
To get the logs into a database, you will need to create a table that matches the log entry that you have defined in the appender config. Here is the t-sql to create a table that matches the above config:
CREATE TABLE [dbo].[Logs](
[Id] [int] IDENTITY(1,1) NOT NULL,
[Date] [datetime] NOT NULL,
[Thread] [varchar](255) NOT NULL,
[Level] [varchar](50) NOT NULL,
[Logger] [varchar](255) NOT NULL,
[Message] [nvarchar](max) NOT NULL,
[Exception] [nvarchar](max) NULL,
[Source] [varchar](100) NULL,
[HostName] [nvarchar](255) NULL
CONSTRAINT [PK_Log] PRIMARY KEY CLUSTERED
(
[Id] ASC
)
Xml transforms
Using xml transforms is an easy way to set up different settings for different environments. For web projects this is built into Visual Studio and MSBuild/MSDeploy, so the tooling support for this is pretty good. The only caveat is that the transformation is only run during deployment – not during the build. So if your switching between different build configs in Visual Studio, the web host on your dev machine will only use the web.config – not any of the web.debug.config, web.release.config, etc (unless you are actually deploying to your local IIS).
If you are developing a console/WPF/WebForms application you still can take advantage of the same xml transform as web projects, but the tooling is not built into Visual Studio or MSBuild/MSDeploy. There is however an excellent free tool (VS extension) called SlowCheetah developed by Sayed Ibrahim Hashimi that will do this for you. You can download it as a Visual Studio extension, and it has an extra gem that Visual Studio doesn’t have; transformation preview.
SQL Server Full-Text search
The real power when it comes to database log entries is when you pair it with full-text searching. Full-text search will require quite a bit of resources in the form of hardware (disk, memory, cpu), but you don’t have to (and shouldn’t) set up the full-text indexing on your production database server. Instead you should set up log shipping in SQL Server (or some other form of pulling the logs off your production servers) and then do your full-text indexing and searching on a separate database server.
Pair full-text search of logs with a message based (event driven) system, and you have an incredible insight to your production system and an invaluable, searchable history.
Resources
Log4Net: http://logging.apache.org/log4net/
SlowCheetah: https://visualstudiogallery.msdn.microsoft.com/69023d00-a4f9-4a34-a6cd-7e854ba318b5
6 comments:
Is there a way to ship the log to Archive path before the log is rolled over??
As far as I know, Log4Net does not have this functionality. The easy way to solve this is to make a little batch script and scheduling it via cron or Windows Scheduled Tasks.
Great article! Thanks. One thing I noticed is that your db table is named "Logs" and you insert statement references "Log".
Thanks, Chris! I've corrected "Log" to "Logs" in the xml :)
Great article Kjetil Klaussen !!!
I am also developing an asp.net web application and want to log my exceptions into SQL DB. For this I am using Log4Net AdoNetAppender to log info into SQL DB, now the problem occurs when the DB goes offline. Log4Net doesn't persist the log messages. So all messages get lost while the DB was offline, is there any way to retain the messages until the DB comes online and then log all the messages to DB once it become available. Although by using reconnectonerror value="True" it starts logging again when DB is available but all intermediate messages while DB was offline are not logged.
Or there exist any other approach to log exceptions in Db with offline support.
Hi Rishi!
As far as I know there's no 'fallback' logging in Log4Net, but what you can do is to log to multiple adapters. So for temporary logging (I presume that the log database won't be offline for a long period of time) you can set up a rolling file log in combination with the AdoAdapter.
Another option would be to use an Enterprise Service Bus (ESB) or queueing system, like MSMQ, RabbitMQ or NServiceBus. You can then publish all log messagess as messages on the bus. Then you can set up a 'Log Subscriber' that will take care of putting those messages into e.g. a Sql database. If the database goes offline, the messages will remain in the queue untill the subscriber (database) is ready to process them again.
Hope this helps :)
Post a Comment