Monitoring Log Files

Log files are funny things. They can contain lots of useful information but they can also be a frustrating experience to understand and read. 

Typically when an error occurs in an application there will usually be an entry in a log file. So in the current application I am testing, I know that when I see an unhandled exception in the UI there will be an entry in the log file which will tell me why and where the error occurred.

So imagine my surprise when during a testing session in which I was  looking for a particular entry in a log file, I noticed that there was an error and I realised that at that time I had not noticed any strange or peculiar behaviour in the UI. This got me thinking about how I can find bugs that do not manifest themselves in the UI......  

Now at the time we didn't have any log file analysis tools like Splunk and after seeing the error in the logs I thought it would be a good idea to some how monitor the log files. Now complex enterprise analysis tools like Splunk were a no no so I had to think of something else. I narrowed it down to the following:

1) Write my own log file analysis tools using C#

2) Extend our existing Log4Net configuration

Option 1 was a possibility but having a 2 year old did not give me the time I needed to write one in my spare time, so option 2 was the option I decided to go with. 

Now having no Log4Net experience meant I had to go and do some research. So after speaking to some of the developers and doing a bit of Googling I managed to come up with the changes needed. 

So before I explain the changes I made here is some background information on Log4Net

1) It a tool to help the programmer output log statements to a variety of output targets.

2) It has the concept of loggers and these lie at the heart of Log4Nets configuration. Loggers are organised into a hierarchy and give the programmer run-time control on which logging statements are printed or not. Loggers are assigned levels through the configuration of log4net. A log statement is routed through to the appender depending on its level and its logger.


3) You can add additional Appenders to create new logging. You need to add an appender so Log4Net knows where to store your log messages. An appender is a C# class that can transform a log message, including its properties, and persist it somewhere


4) Log4Net has different levels of logging and these are:

• ALL
• DEBUG
• INFO
• WARN
• ERROR
• FATAL
• OFF

The changes I made

So after thinking about what I wanted to achieve out of this I decided to make the following changes:

- Write all levels above (and including) WARN to a new log file
- Add a new appender to email me when the levels above (and including) WARN occur in the log file.
Here is the config that I added:

<root>        <appender name="WarningAndErrorAppender" type="log4net.Appender.RollingFileAppender">
<filter type="log4net.Filter.LevelRangeFilter">
        <levelMin value="WARN" />
      </filter>
      <file value="../log/WarningsAndErrors.txt" />
      <appendToFile value="true" />
      <maxSizeRollBackups value="500" />
      <maximumFileSize value="20MB" />
      <rollingStyle value="Composite" />
      <datePattern value="-yyyy-MM-dd" />
      <preserveLogFileNameExtension value="true" />
      <staticLogFileName value="true" />
      <layout type="log4net.Layout.PatternLayout">
        <header value="[Log Start]&#xA;" />
        <footer value="[Log End]&#xA;" />
        <conversionPattern value="%date [%thread] [%property{user}] [%property{request}] %-5level %logger - %message%newline" />
      </layout>
    </appender>
    <appender name="EmailAppender" type="log4net.Appender.SmtpAppender">
<filter type="log4net.Filter.LevelRangeFilter">
        <levelMin value="WARN" />
      </filter>
         <to value="<EMail address>" />
    <from value="<EMail address>" />
    <subject value="WARNING OR ERROR IN LOGS" />
    <smtpHost value="<SMTP value>" />
    <bufferSize value="512" />
    <lossy value="false" />
      <layout type="log4net.Layout.PatternLayout">
        <header value="[Log Start]&#xA;" />
        <footer value="[Log End]&#xA;" />
        <conversionPattern value="%date [%thread] [%property{user}] [%property{request}] %-5level %logger - %message%newline" />
      </layout>
    </appender>
</root>

So how did this help me?

• Found issues that did not manifest themselves in the UI that otherwise I may not of realised had occurred.

• When I was notified of an issue in the log file I was more easily able to note down the exact steps that were performed as the email notified me relatively soon after the error in the log file occurred.

• Taught me that you can use an exciting tool to aids testing and that you don't need to buy something in. OK it may not be exactly what you want but if it adds value to your testing then it is worth it. 

Extending the configuration

I extended this by writing a PowerShell script that makes the changes to the log file automatically. This script was then run during deployment of the application to the sever and it meant that  I had extra log file analysis without have to do anything manually. 

So there you have it, a simple solution that has added value to my testing and helped catch issues that may not of been immediately obvious.