Peterson's Ponderings

Logging: So easy to do, why wait?

Do your enterprise applications log?  If they aren't, when there is a system problem you probably wish they did or wish the logging you worked in was more robust or consolidated.  I encounter a lot of applications where logging was an after-thought that occurred when issues began occurring in production and team's realized they can't hit F5 and step through code to determine the problem.  For a lot of developers logging is not something that is intuitively thought of when writing code, primarily because the everyday development IDE now has such robust debugging capabilities logging isn't needed during development.  Once code is in production though the situation is drastically different and trace logging becomes a critical difference between solving an issue in 5 minutes or 5 hours.  Five hours in production downtime can equate to thousands or millions of dollars depending on the system.

How a system will log should be a feature discussed during system design along with business functionality.  In many enterprise systems today there are multiple servers and applications all contributing to the end result.  A centralized and real-time configurable logging architecture is crucial.  There are many ways to log - writing to a database, writing to files, dropping messages on a queue, utilizing the event log, etc.  My preference is to centralize logging to a stand alone database so that the OLTP application database is not affected by the logging activity.  This centralized data is where all of the different applications write their log entries.  The log data can then be viewed, searched or reported using any sort of package reporting software (such as Crystal Reports) or a simple custom WinForm/Web application (a data grid and query buttons to load information).  When using centralized logging it is important to log with each message entry the machine name, date/time, thread, log level (error, warning, informational, verbose, etc) and component that the entry originated from.  With this meta data you can easily isolate and view log entries from only one trouble server, buggy component, period of time, ect.

There are two simple ways you can incorporate logging into your applications.  One is to use a freeware community component called log4net (found on Sourceforge - http://sourceforge.net/projects/log4net).  This component has been around for a few years now so it is very reliable and the performance overhead is small if you limit your active logging level in production (and this level can be changed on the fly without restarting your applications).  Log4net allows you to log to a single or multiple locations by just changing the settings in your app.config file.  It has built in support to log to a database, event viewer, and file and you can extend it with custom code to allow it to log to any customized logging architecture you may be using.

Another way to log is to make your own TraceListener class and then use Trace.Write calls within your code to utilized your custom trace class.  To make a TraceListener you need to inherit from the TraceListener class and Overload the Write and WriteLine methods to direct the log entry to your custom logging location.  Here is an example of a simple trace listener that writes to a database. 

Friend Class ClientLog

Inherits TraceListener

Public Overloads Overrides Sub Write(ByVal message As String)

   Me.Write(message, Convert.ToString(LogLevel.Debug))

End Sub

Public Overloads Overrides Sub WriteLine(ByVal message As String)

   Me.Write(message, Convert.ToString(LogLevel.Debug))

End Sub

'Main method that logs, all other overloads call this method to log the message

Public Overloads Overrides Sub Write(ByVal message As String, ByVal category As String)

Try

'check the configuration, load the log level

   Dim isLoggingEnabled As Boolean = Convert.ToBoolean(ConfigurationSettings.AppSettings("Debug"))

'if category of logging was 1 or 2 then always log, if 3 then log if isLoggingEnabled is true

   Dim logEntryLevel As Integer = Convert.ToInt32(category)

   If (logEntryLevel < 3) Or isLoggingEnabled Then

      'log an entry into the database   

      Dim tickCnt As Integer = Environment.TickCount

      'TODO: You'll want to have other data available here to log such as the methodname, thread information, etc. Just expand your write method signature to pass along that information too.

      'insert the log entry

      SqlHelper.ExecuteNonQuery(SqlHelper.LOCAL_DPEDB_CONNECTION_STRING, CommandType.StoredProcedure, "Logs_Insert", New SqlParameter() {New SqlParameter("@SeverityLevel", logEntryLevel), New SqlParameter("@TickCount", tickCnt), New SqlParameter("@Message", message)})

   End If

Catch ex As Exception

   'TODO: handle the exception but don't throw it to the caller. You don't want logging issues (such as the logging database down for maintanence) causing your business logic to fail.

End Try

End Sub

End Class

You can then wrap this with a static class entry point that configures and then executes the TraceListener class.

Public Enum LogLevel

   Err = 1

End Enum

Public Class Log

   Private Shared _logType As LogType = LogType.Client

   Public Enum LogType

     End Enum

   Public Shared Sub InitializeLogging(ByVal logType As LogType)

      Trace.Listeners.Add(New ClientLog)

      Trace.AutoFlush = True

   End Sub

   Public Shared Sub Write(ByVal message As String)

   End Sub

   Public Shared Sub Write(ByVal message As String, ByVal level As LogLevel)

   End Sub

End Class

Once you have logging built into the architecture its still up to your project team to make it a habit of entering log writing statements into their code.  If they don't there will be nothing to help trace the execution path of the code when you enable logging in that production outage scenario.  Teach your developers to get in the habit of logging with the correct log level at decision points in the code.  I try to follow rules similar to these:

• Log an error in all exception handlers.  This includes writing the exception information into the log.
• Log a warning in logic branches where code is continuing, but data did not look as it was expected.  Be sure to include the suspect data value(s) in the log entry.
• Log an informational entry when a significant piece of logic completes including how much data was transacted and/or how long the transaction took.  (i.e. "The file c:\data.txt was successfully processed for 45 orders.")
• Log debug/verbose entries at logic branch points to help perform a detailed trace of the code.  These low level log entries won't show up in the log in normal production mode, they would only be enabled when there was a serious problem that needed to be traced through or during development to help follow code execution without having to step through logic in the debugger.

It's hard to express how beneficial good logging is until you run into a production issue where you wish you would have had it!