Using log4net with ASPDotNetStorefront 9.4.0

Introduction

In this post I'll describe:

• Why go to the trouble of setting up log4net,
• how to set up log4net within ASPDotNetStorefront including
• how to initialize log4net in ASPDotNetStorefront and
• how to configure log4net to simulate the standard ASPDotNetStorefront logging mechanism.

Why log4net?

ASPDotNetStorefront already has a static logging class: SysLog. When you call its methods LogMessage and LogException, the message or exception details are is written to the system log table. Site administrators can view the log by navigating the admin console menu to Configuration > Maintenance > View System Log. So, why would you want to add another logging framework?

Verbosity

ASPDotNetStorefront's SysLog class is small, but I find its methods a little unwieldy. When I need to instrument up some code or print a useful message to the log I end up writing a lot of calls like this:

SysLog.LogMessage("Commissions sent for payment", 
    String.Format("Sent `{0}` payment requests totaling `{1}` {2} for processing.", 
      number, amount, PayPalPaymentCurrency), 
    MessageTypeEnum.Informational, MessageSeverityEnum.Message); 

Here, we supply the title and detail of the message, along with some metadata about the nature of the message we're logging. This is fine, but with log4net the method defines the log level instead of the parameters, and you get string formatting for free:

log.InfoFormat("Commissions sent for payment" + "\n" + 
    "Sent `{0}` payment requests totaling `{1}` {2} for processing.",
    number, amount, PayPalPaymentCurrency);

It's less verbose, letting the writer focus on the content of the message and spend less time mining intellisense for the message enumerations required as parameters.

Selective logging and dynamic configuration

The log.InfoFormat call above sets the log level to Info, roughly corresponding to MessageTypeEnum.Informational and MessageSeverityEnum.Message. However, what if you need to instrument up some code to debug a feature running on the live site? Sure, you can use Asp.Net tracing to print information to the page, but what if your hypothetical module doesn't actually correspond to a single page? Or, what if you want to log variables that actual live users are interacting with? You don't want your traces ending up on live pages where your users can see them.

With log4net you can log to many different outputs, including the database or a local log file. You can also define the current threshold for logging. log4net will not output any messages that fall below the current log level.

log4net can be configured in many ways, but one very useful way is through the web.config (or app.config) file. The setting that concerns us in this case is the threshold of logging:

log.DebugFormat("CustomerId: {0}", Customer.Current.CustomerID);

Using the logging level Debug we can instrument up the code using DebugFormat statements, saving all the data we want. We stick this code in production, and let it gather up all the session or backoffice process data we're interested in. Info level statements are still logged because the Info level has a greater value than Debug. When we're done, we just change the logging level in the config file and all the DebugFormat statements are ignored, and Info statements continue to be logged.

Now, our Info statement letting us know commissions have been paid is still logged, but our debug statements are ignored. We didn't have to re-release a version of the code without the logging statements. If we want to again log the debug statements at a later time, we can simply change the log level back to Debug to get the same output.

Flexibility of output

The ability to adjust how much logging is output is great, but another place where log4net shines is the variety of output methods. By using different appenders, we can send log messages to any number of outputs, including local files, the windows event log, a remote linux box, or even a database. That's perfect for mimicing ASPDotNetStorefront's own SysLog class.

Setting up log4net within ASPDotNetStorefront

Add log4net to the project

Getting log4net into our project is pretty easy using nuget. 

Trick ASPDotNetStorefront into initializing log4net

ASPDotNetStorefront doesn't provide access to the code behind of the Global.asax application file. We can use a little trick to ensure that log4net is initialized once and only once: we will create a class called Startup in the App_Code folder and include the log4net configuration method in its static constructor. Just by referencing the name of the class we can ensure that the initializer is called.

namespace AspDotNetStorefront
{

    /// 
    /// A placeholder class to perform one-time initialization
    /// 
    public class Startup
    {
        static Startup()
        {
            log4net.Config.XmlConfigurator.Configure();
        }
    }
}

This statement tells log4net to read its configuration from the application's XML config file. For ASP.Net web apps, that's web.config, of course.

Now, add a field to a class that will be called early in the site initialization process. A good candidate is SkinBase. Initialize the field with a call to the default constructor for Startup. This will hopefully prevent the CLR compiler from optimizing out a member that isn't referenced anywhere else.

public class SkinBase : System.Web.UI.Page
{
    public Startup startup = new Startup();

    // the rest of SkinBase ...
}

Configure log output and log level

Next, tell log4net how to configure itself. Add an element to the config section for log4net if it's not already there so that .NET knows how to load the XML:

  
...

log4net needs at least two entities configured within the log4net element in web.config: an appender and the root logger. The appender defines how messages are written to a data store or message sink. The logger is the object your code calls when logging. If you set the threshold log level of the root logger, then it is the default for every log call. By setting the appender reference for a logger you connect a logging command to a way of outputting the message.

AdoNetAppender

An appender is essentially a log output method. For this example, we will output to the same table that ASPDotNetStorefront's SysLog logger outputs to, which I'll refer to as [The System Log Table]. (You can easily find the name of this table when looking at the database in Ssms, or in the SQL scripts used to initialize a new database).

Building on log4net's example configuration, we can mimic the calls that SysLog would use to write to the [The System Log Table] table. First, we set the buffer size (how many log messages will be batched up before being written), the connection type information, and the connection string to the database:

Next, we need to set up the SQL we'll use to write to the database. The SQL will take parameters that are provided by log4net:

• the message or message and stack trace of the exception you logged,
• the ID of the thread that was executing when the log command was issued,
• the log level of the message,
• the name of the logger (we'll determine this later), and
• the DateTime at which the message was generated.

These are configured using XML elements that give the name of the parameter as passed into the SQL function, the database type that the parameter will be used, and some formatting.

The last part is the SQL that will write the log message to the database:

INSERT INTO [The System Log Table] (
  [Message], 
  [Details], 
  [Type], 
  [Severity], 
  [CreatedOn]
) 
VALUES(
  -- Message
  case
    when len(@message) > 100 
    then left(@message, 100) + '...' 
    else @message 
  end,
  -- Details
  ' logger: ' + @logger + 
    ' exception: ' + 
    case
      when len(@exception) > 0 
      then @exception 
      else 'none'
    end 
    + ' thread: ' + @thread +
   ' ' + @message,
  -- Type
  case
    when len(@exception) > 0
    then 'GeneralException' 
    when @log_level='ALL' or
         @log_level='DEBUG' or
         @log_level='TRACE' or
         @log_level='TRACE_INT' or
         @log_level='INFO'
    then 'Informational' 
    else 'GeneralException' 
  end, 
  -- Severity
  case
    when @log_level='ALL' or
         @log_level='DEBUG' or
         @log_level='TRACE' or
         @log_level='TRACE_INT' or
         @log_level='INFO' 
    then 'Message' 
    else 'Error'
  end,
  -- CreatedOn
  @log_date
)

The first column stores the message. This will be displayed on the log admin page along with the message date, type, and severity. If the log message is longer than 100 characters, we truncate it and show ellipses. The second column lists the details of the log message. These will be revealed when the admin clicks on the arrow on the left of the log message list and loaded via ajax. The details includes the name of the logger, the exception details if they exist, the thread ID, and finally the message. Then we map the details of the message to a message type and the log level to the severity. Finally, we add the log date. This is put into the commandText element within the appender section of the log4net config.

Root Logger

The root logger is the master logger. As we'll see later, you can have as many loggers as you want. However, the root logger is somewhat akin to the master switch. By setting the logging threshold for the root logger, you can set the minimum level for all of the other loggers.

Though it can be much more complicated, all we need to do for our example is to tell the root appender where to log and at what level

	...
  
    
    
  

The complete log4net config section

Here's the whole configuration put together:

  
 ...
  
    
      
      
      
      [The System Log Table] ([Message], [Details], [Type], [Severity], [CreatedOn]) VALUES ( case when len(@message) > 100 then left(@message, 100) + '...' else @message end, ' logger: ' + @logger + ' exception: ' + case when len(@exception) > 0 then @exception else 'none' end + ' thread: ' + @thread + ' ' + @message, case when len(@exception) > 0 then 'GeneralException' when @log_level='ALL' or @log_level='DEBUG' or @log_level='TRACE' or @log_level='TRACE_INT' or @log_level='INFO' then 'Informational' else 'GeneralException' end, case when @log_level='ALL' or @log_level='DEBUG' or @log_level='TRACE' or @log_level='TRACE_INT' or @log_level='INFO' then 'Message' else 'Error' end, @log_date)"/>