Logging in a database with log4net

As I wrote here before, it’s a good idea to write logs elsewhere than a plain file or a rolling file. Usually, logging frameworks know how to log in a database. We had this kind of demand lately: use log4net to trace information in a relational database (SQL Server).

Using log4net to log in a table does not prescribe anything regarding the format of the table. Actually, every particularities is setup in log4net configuration.

The resulting configuration for log4net is like this:

<?xml version="1.0" encoding="utf-8"?>
<log4net>
    <appender name="LogSignElecAppender" type="log4net.Appender.AdoNetAppender">
        <bufferSize value="1" />
        <connectionType value="System.Data.SqlClient.SqlConnection, System.Data, Version=1.0.3300.0, Culture=neutral, PublicKeyToken=b77a5c561934e089" />
        <connectionString value="<data source configuration>" />
        <commandText value="INSERT INTO LOG_TABLE (DATE, 2_CH_CODE, MESSAGE) VALUES (@DATE, @2_CH_CODE, @MESSAGE)" />
        <parameter>
          <parameterName value="@DATE" />
          <dbType value="DateTime" />
          <layout type="log4net.Layout.RawTimeStampLayout" />
        </parameter>
        <parameter>
          <parameterName value="@2_CH_CODE" />
          <dbType value="String" />
          <size value="2" />
          <layout type="log4net.Layout.PatternLayout">
            <conversionPattern value="%property{2_CH_CODE}" />
          </layout>
        </parameter>
        <parameter>
          <parameterName value="@MESSAGE" />
          <dbType value="String" />
          <size value="2000" />
          <layout type="log4net.Layout.PatternLayout">
            <conversionPattern value="%message" />
          </layout>
        </parameter>
    </appender>
    <logger name="LogSignElecLogger" >
    <level value="DEBUG" />
        <appender-ref ref="LogSignElecAppender" />
    </logger>
</log4net>

It deserves some explanations.

• commandText tag contains the INSERT statement. Bind variables are prefixed by @. They’ll be replaced by our parameters declaration
• each parameter is described within parameter tags. parameterName contains the name of the parameter in the query. dbType contains the type in the database, allowing log4net to do the tranlations. Tag layout describes what will be put in the table field. More about this bellow.
• You declare your logger, referencing your AdoNetAppender as you would do with any kind of appender.

Let me tell you more about this layout definition. The layout describes what piece of information will be put in the corresponding table field. You can see above different examples of layout:

• log4net.Layout.RawTimeStampLayout: insert the current time, which is convenient for a date-kind field
• log4net.Layout.PatternLayout: it must come with a conversionPattern, which can be either a field that is conveyed by log4net in the appenders, like the %message here (but you can also have the current logged user, the thread, and so on.) or a custom property, that you can access with the %property{KEY} string as you can see here.

Here we get to what I strongly dislike in this way of doing. The custom properties you want to track in your logs are passed to the logger through a context, that can be either global (shared within all the threads) or specific to the thread. Here is how you pass your custom properties through the context of a thread:

log4net.ThreadContext.Properties["2_CH_CODE"] = "XX";

Then you log:

// Getting the instance of the logger configured above, wired to the
// AdoNetAppender.
var logger = LogManager.GetLogger("LogSignElecLogger");

// The log threshold is set as DEBUG
logger.Debug("This message is logged in the table!");

I still wonder why the logging methods do not propose to pass custom properties as a Dictionary.

It leads me to another issue: the null values

Guess what is the other thing that we had to struggle with? Letting a field to NULL while logging into the database! Actually, bay default, when you pass null as a custom property, the appender write the string "(null)" in the database (or a substring of that if your field is shorter). You can configure log4net to put another string but it will still put a non empty string in the DB. The solution is to tweak the insert query in log4net configuration.

INSERT INTO LOG_TABLE (DATE, 2_CH_CODE, MESSAGE) VALUES (@DATE, CASE WHEN @2_CH_CODE = ’(n’ THEN NULL ELSE @2_CH_CODE END, @MESSAGE)

In the example above, I test equality for ’(n’ because the size of the field is set to 2 in the database.

And what if it goes wrong?

A logger should never go wrong. If it does, it should not blow the whole application. What if the database is not reachable? What if the table structure or constraints change for some reasons and the insert statement returns SQL errors. By default, you see nothing. You just figure out that you have no logs. Fortunately, you can setup the logger to show it’s internal logging messages. Actually I did not try it, I do not want to know every internal crap that could be thrown up by log4net, srsly.

It’s time for a conclusion

As you can see, the information is redundant between the SQL table definition, the insert statement and the fields configuration in the appender. I strongly recommend to script that up using a pivot format to describe the table (I chose JSON) and the logger layout fo write information in the fields. Then write a script to get :

• the CREATE TABLE statement,
• the log4net configuration,
• table documentation for you lovable client.

This way, a change (like modifying a field length) can be applied everywhere it’s needed.

The other advice is to wonder if the logging framework is the right tool for your need. In our case, the client wanted to track the access to third party services that are often down and get an objective idea of the availability of these services. The logs are either activated or not, so we do not need the whole range of logging levels. Honestly, the only log4net feature that was needed is the ability to listen for the changes in the configuration file.

If I had the choice, I would have done everything in code giving the possibility to configure the activation through an API or a UI. This way I would have add a direct access to the eventual errors and it would have saved me from configuration hell. The main problem is that in our case, we have a lot of custom properties and not so much standard properties. As I said I’m not comfortable with sending them through a context.

I hope that long post could help you, dear reader.