Using log4net: some observations when logging is under load

So, here is the first of what I hope will be many posts coming out of my new project. As with most .NET developers, I use log4net to log to text files and to a database. It is one of the more flexible logging frameworks and is relatively easy to set up. However, recently I have found what I think is a bug in log4net, which I will explain how to generate it and also how to overcome it.

Firstly, some basic configuration details. Below is my basic configuration for log4net.
<log4net> <appender name="LogFileAppender" type="log4net.Appender.FileAppender"> <file value="logs\web.log"> <appendtofile value="true"> <lockingmodel type="log4net.Appender.FileAppender+MinimalLock"> <layout type="log4net.Layout.PatternLayout"> <conversionpattern value="%date [%thread] %-5level %logger - %message %exception%newline"> </conversionpattern></layout> </lockingmodel></appendtofile></file></appender> <appender name="AdoNetAppender" type="log4net.Appender.AdoNetAppender"> <buffersize value="1"> <connectiontype value="System.Data.SqlClient.SqlConnection, System.Data, Version=4.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089"> <connectionstring value="data source=&lt;server&gt;;initial catalog=&lt;database&gt;;integrated security=true;persist security info=True"> <commandtext value="INSERT INTO CodeLog ([Date],[Thread],[Level],[Logger],[Message],[Exception]) VALUES (@log_date, @thread, @log_level, @logger, @message, @exception)"> <parameter> <parametername value="@log_date"> <dbtype value="DateTime"> <layout type="log4net.Layout.RawTimeStampLayout"> </layout></dbtype></parametername></parameter> <parameter> <parametername value="@thread"> <dbtype value="String"> <size value="255"> <layout type="log4net.Layout.PatternLayout"> <conversionpattern value="%thread"> </conversionpattern></layout> </size></dbtype></parametername></parameter> <parameter> <parametername value="@log_level"> <dbtype value="String"> <size value="50"> <layout type="log4net.Layout.PatternLayout"> <conversionpattern value="%level"> </conversionpattern></layout> </size></dbtype></parametername></parameter> <parameter> <parametername value="@logger"> <dbtype value="String"> <size value="255"> <layout type="log4net.Layout.PatternLayout"> <conversionpattern value="%logger"> </conversionpattern></layout> </size></dbtype></parametername></parameter> <parameter> <parametername value="@message"> <dbtype value="String"> <size value="4000"> <layout type="log4net.Layout.PatternLayout"> <conversionpattern value="%message"> </conversionpattern></layout> </size></dbtype></parametername></parameter> <parameter> <parametername value="@exception"> <dbtype value="String"> <size value="2000"> <layout type="log4net.Layout.ExceptionLayout"> </layout></size></dbtype></parametername></parameter> </commandtext></connectionstring></connectiontype></buffersize></appender> <root> <level value="ALL"> <appender-ref ref="LogFileAppender"> <appender-ref ref="AdoNetAppender"> </appender-ref></appender-ref></level></root> </log4net> Basicly, I have set up log4net to log to a text file and also to a database.

Now, as far as I am aware there is nothing specifically wrong about this configuration. It does indeed log to both a database and also a text file. However, under load some curious things happen. First of all, you can get an I/O race condition appearing regularly in the logs. This is because the load can cause 2 threads to want to write to the text file at the same time, causing the I/O race condition to occur. To fix this, remove the text file log appender updating the root node as below:
<root> <level value="ALL"> <!-- <appender-ref ref="LogFileAppender" /> --> <appender-ref ref="AdoNetAppender"> </appender-ref></level></root> This then leaves the database logger configured. So far so good. Lets say that for production you want to turn off logging entirly, the following configuration will work:
<root> <level value="OFF"> <!-- <appender-ref ref="LogFileAppender" /> --> <appender-ref ref="AdoNetAppender"> </appender-ref></level></root> Note that we have now turned all logging OFF. If your like me, you would think that this would be the end of it. You have turned off logging, end of story. But this is actually where things can get interesting. Lets say your site or web service gets under heavy load and requires data access out side of the logging framework (even to a different database). Over time, your web site stops working, all queries to the database fail. Yes, you can restart IIS and everything will go back to working again. But this is not an actual solution, it is something you would do when you had nothing else to try and you need to get the site back up and running as soon as possible.

So, what caused the issue? From what I can tell if you have a ADO appender as in the example above, you can't just turn off logging. From what I have experienced this will still connect to the database AND WONT RELEASE THE CONNECTION TIL THE CONNECTION EXPIRES. And that is the key thing here. If your database connections time out after 2 minutes, you can see how the connection pool can get clogged with these open logging connections that do nothing. What you need to do is remove or comment out the ADO appender from the list of appenders as below:
<root> <level value="OFF"> <!-- <appender-ref ref="LogFileAppender" /> --> <!-- <appender-ref ref="AdoNetAppender" /> --> </level></root> From what I have noticed, if logging is turned on, then the issue does not arise. It is only when the logging is off and there is an ADO appender there that this is an issue. I ran some tests against a web service, and with logging turned off and the ADO appender commented out, I could get 516k requests though a web service over the course of an hour with no adverse affects. As soon as I uncommented the ADO appender, the test ran for 5 minutes then started experiencing major issues, with all database connectivity stopping soon after.

Side note:
If you want to use the above to configure to a database, below is the SQL that you need to create the table. Just make sure your connection string is correct and that the user that is running the website has access to the databse the table is in.
CREATE TABLE [dbo].[CodeLog]( [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] [varchar](4000) NOT NULL, [Exception] [varchar](2000) NULL ) ON [PRIMARY]