Cross-cut Logging

• Download demo project - 287 KB
• Download source - 19.9 KB

Contents

• Introduction
• Background
• Requirements
• Configuration::Examples
• Usage::Examples
• Implementation Details
• Class Diagram
• Conclusion
• See Also
• Revision History

Introduction

This article attempts to illustrate a logging strategy that allows for an easy, extendable, cross-cut implementation. While the utmost goal has been simplicity, the solution runs tangent to the aspect-oriented programming concepts and the Enterprise Library's Logging Application Block. The ideas discussed here are not language specific, but they do stem from a Windows-based object-oriented application development experience.

Here are some related CodeProject articles:

• Get Logging with the Enterprise Library[^], By Piers Lawson
• A Comprehensive Logging Package for .NET[^], By Jeff Varszegi

... and a two-part article with really cool ideas:

• A service to manage and create logfiles[^]
• A real-time logfile viewer[^], By Rob Manderson

The logging library proposed in this article is implemented in Delphi in under 800 lines of code. The enclosed source code contains:

LogAgent	A demo application that employs the logging library
LogLib	A set of core objects and interfaces
LogViewer	An outline of a module for log file manipulation, nice-to-have draft

The equivalent .NET implementation in C# has been 50% completed, and will be included in the next revision of this article. In this case, the broadcast mechanism had to be revisited.

The logging behaviour is configurable by a single XML file.

Background

"Logging is the archetypal example of a crosscutting concern because a logging strategy necessarily affects every single logged part of the system. Logging thereby crosscuts all logged classes and methods." [^]

The presented logging module has been conceived and delivered in the summer of 2008. In short, it is designed to be a decoupled, unobtrusive, secure, and flexible solution to one of the basic aspects in software construction. It is implied that:

• Decoupled means that it can be modified at any time without the need to edit the rest of the system,
• Unobtrusive means that it does not have any adverse effect on the performance or the stability of the system,
• Secure means that it does not introduce security breaches in the system, and
• Flexible means that it can be configured to meet a wide variety of debugging, testing, troubleshooting, and production scenarios.

In addition, it meets the following set of requirements:

Requirements

Input

The input to the logging system may include any or all of the following items:

Source ID	(e.g., module::procedure::variable)
Custom message	(e.g., division by zero is never 47)
Priority	(e.g., high, medium, low)
Severity	(e.g., fatal, critical, etc.)
Type	(e.g., exception, error, warning, information)
System Message	(e.g., exception message)
Call Stack
Details	(e.g. name-value pairs)

The definition of some of these fields can be made compliant with existent logging standards. Most common logging standards include the Common Log Format [^] and the SysLog [^]. More resources on data logging can be found here[^].

Output

The output from the logging module is defined based on the following configuration items:

Verbose	(e.g., inclusion of details, priority, severity, call stack, etc.)
Format	(e.g., XML, database, flat)
Filter	(e.g., exclusion of source: type; source: priority, etc.)
Location	(e.g., filename, database connection string, etc.)
Encryption

Interface (optional)

The interface can be graphical and/or console/command-based. The interface should provide the means to:

• Read logs
• Search logs
• Clear logs
• List logs
• Decrypt logs

Miscellaneous

• Logging can be accessed from any module
• Provides exception handling
• Provides mechanism for queuing/batch handling (optional)
• Resources are not locked by logging
• Response time is irrelevant in logging
• Max log size is a configurable parameter
• Provides a mechanism for automatic purging
• Supports encryption for privacy purposes

Configuration

The user can decide what and where to log using an XML configuration file, named LogConfig.xml. When this file is not present or it does not contain the XML entities described below, no data gets logged. It is a fast and easy way to disable / enable logging. But beware that this design decision may pose a risk of exposure of confidential log data if such confidential data is logged. Best practices dictate that confidential data must not be logged in production environments.

Step 1

The configuration file defines a log (file) entity, <Log>, with a set of attributes and filters. The following attributes can be used:

Path	Represents the path (absolute or relative) to the log file. All folders on the path have to exist. If a file with the same path already exists, it will be appended to; otherwise, a new file will be created. No default value (e.g., C:\Projects\Logs).
Format	Represents the log file format. In the future, other file types may be included, such as database, XML, etc. No default value (e.g., Flat (text file)).
IncludeOnFilter	Represents the use of filters attached to the log. The following values are defined - 0 (Include all messages except the ones that pass one of the provided filters), 1 (Exclude all messages except the ones that pass one of the provided filters). Defaults to 0 (e.g., 0).
Verbose	Represents the amount of message details to be logged. It is given based on a bitmap, where the following bits are defined - 1 (Timestamp), 2 (User Message), 4 (Source), 8 (Priority), 16 (Severity), 32 (Group), 64 (Category), 128 (System Message), 256 (Call Stack), 512 (Details). A value of 0 corresponds to a value of 1023 (= 1 + 2 + 4 + 8 + 16 + 32 + 64 + 128 + 256 + 512) and means that all message details will be logged. Defaults to 0 (e.g., 3 (Timestamp + User Message)).
Delimiter	Represents the delimiter string to be used in between the message details. Defaults to (Tab) (e.g., ', ' (.csv file)).
Encryption	Represents the encryption setting for the log. Currently, it is not supported. Defaults to 0.
MinSize	Represents the minimum size of the data to be kept in the file during purging. Currently, it is not used because a circular purging is implemented. Defaults to 1KB (1024 bytes) (e.g., 1024).
MaxSize	Represents the maximum size of data to be stored in the file before purging. Currently, once the MaxSize limit is reached, the file position pointer is reset to the beginning of the file so that the oldest log entries are overwritten with new ones. It amounts to a circular purging. The file will never exceed the MaxSize limit. Defaults to 1MB (1048576 bytes) (e.g., 1048576).

Step 2

The configuration defines a filter entity, <Filter>, with a set of attributes. The following attributes can be used:

Source	Represents the message originator (the unit that imports/uses the logging message) (e.g., TLogAgentForm (target messages that are generated by TLogAgentForm)).
UserMsg	Represents the user message (or a part of it). If an empty string is specified, then it matches all messages. Defaults to an empty string (e.g., 'failed' (target messages that contain the string 'failed' in their user message)).
Priority	Represents the message priority. It can be one of the following values - 0 (None), 1 (Low), 2 (Medium), 3 (High). Defaults to 0 (e.g., 3 (target messages with High priority)).
Severity	Represents the message severity. It can be one of the following values - 0 (None), 1 (Minor), 2 (Major), 3 (Critical), 4 (Fatal). Defaults to 0 (e.g., 3 (target messages with Critical severity)).
Group	Represents the message group. It can be one of the following values - 0 (None), 1 (Hint), 2 (Warning), 3 (Error), 4 (Exception). Defaults to 0 (e.g., 3 (target messages designated as Errors)).
Category	Represents the message category. The category is defined as a set of integers from 1 to 100. The numbers from 1 to 100 can be mapped to a meaning and then assigned to the message through its category. Note that messages can have one or more categories, or no category.
SystemMsg	Represents the system / exception message (or a part of it). If an empty string is specified, then it matches all messages. Defaults to an empty string (e.g., typecast (target messages that contain the string 'typecast' in their user message)).

Step 3

To enable logging, place a LogConfig.xml file in the same folder that contains your executable.

Examples

1. Log all messages with all details in a comma-delimited file, named 'Log.csv'.
XML

<?xml version="1.0"?>
<Logs>
    <Log Path='Log.csv' Format='Flat' Delimiter= ', ' IncludeOnFilter='0' />
</Logs>

2. Log messages in two files in the folder '\Logs', where:
• In the first file, 'Log_Form.txt', we store messages coming from TLogAgentForm objects with their timestamp and user message only.
• In the second file, 'Log_Other.txt', we store all messages that have a priority of Medium and High, with their timestamp, user message, and system message only.
XML

<?xml version="1.0"?>
<Logs>
    <Log Path='Logs\Log_Form.txt' Format='Flat' IncludeOnFilter='1' Verbose='3'>
                <Filter Source='TLogAgentForm'/>
        </Log>
    <Log Path='Logs\Log_Other.txt' Format='Flat' IncludeOnFilter='1' Verbose='131'>
                <Filter Priority='3'/>
        <Filter Priority='2'/>
        </Log>
</Logs>

Usage

Inlcude uLogMessage in your uses clause. Then, anytime you want to log a message, call one of the TLogMessage static Post methods (you do not have to worry about creating and destroying objects). You can also create an instance of the object and assign its properties as necessary (this is what you need to do if you want to provide name-value pair details, for example), then call its object Post method (in this case, you are responsible for destroying the instance). Include uLogManager in the uses clause of the startup module of your system.

Examples

TLogMessage.Post(Self, Format('Parsing request with ID: %d', [Source.ID]), lmgHint); 
TLogMessage.Post(Self, 'Failed to send transaction: Provider not configured', 
                 lmgError, lmpHigh, lmsMajor); 
TLogMessage.Post(Self, 'Failed to send transaction', lmgException, 
                 lmpHigh, lmsMajor, e.Message); 

As a result, a user-defined and Windows registered WM_LOG_MESSAGE message will be sent to the application. TLogManager will pick it up and send it to its stores (if any are defined). The TLogStore(s) will log the message if it matches its definition (attributes and filters).

Implementation Details

TLogMessage is the object that represents the pointcut where logging is applied. It includes:

• A set of properties that define the input to the logging module and their access methods.
• A method, Post, that is used to trigger the input to the logging module.

Here, method overloading [^] provides a shortcut for flexible user calls. Also, three of the methods are class/static methods[^] to simplify the usage of the object in terms of creation, invocation, and destruction.

The user-defined message[^] used for logging request notification is defined and registered as follows:

Delphi

WM_LOG_MESSAGE := RegisterWindowMessage('LogMsg');

It is broadcast in an asynchronous call with the PostMessage[^] function, with the logging message instance itself as a parameter.

Delphi

PostMessage(HWND_BROADCAST, WM_LOG_MESSAGE, Integer(self), 0);

Note that HWND_BROADCAST is not very economic because all open window handles receive the message.

• A method, Match, that is used to compare logging messages and the overlap of their properties.

TLogManager is a thread that listens for logging messages, enqueues them, and then sends them to its stores. It is intended not to interfere with the regular operation of the system. It includes:

• A list of messages enqueued for processing by the thread
• A list of stores ready to deposit the logging messages to their specified destinations
• A window handle that intercepts windows messages, handles WM_LOG_MESSAGE, and enqueues the logging messages to the list of messages
Delphi

procedure TLogManager.WndProc(var msg: TMessage);
begin
  FTerminated := (Msg.Msg = WM_NCDESTROY);

  if Msg.Msg = WM_LOG_MESSAGE then
    Messages.Add(TLogMessage(Msg.WParam))
  else
    if not FTerminated then
      Msg.Result := DefWindowProc(FWinHandle, Msg.Msg, Msg.wParam, Msg.lParam);
end;

• The thread's Execute method
Delphi

procedure TLogManager.Execute;
var
  msg: TObject;
  idx: integer;
begin
  while not FTerminated do begin
    while Messages.Count > 0 do begin
      msg := TLogMessage(Messages.Extract(Messages.First));
      if msg is TLogMessage then begin
        for idx := 0 to Stores.Count - 1 do begin
          //if supports(Stores.Items[idx], ILogStore, store) then
          //  store.Push(msg);
          if (Stores.Items[idx] is TLogStoreAbstract) then
            (Stores.Items[idx] as TLogStoreAbstract).Push(TLogMessage(msg));
        end;
      end;
      msg.Free;
    end;
    Sleep(LOG_IDLETIME);
  end;
end;

TLogStoreFlat is a realization of the ILogStore interface. It is used to store the logging message to its final destination; in this case, a plain text, delimited file.

procedure TLogStoreFlat.Push(Msg: TLogMessage);
var
  s: string;
begin
  if Msg <> nil then begin
    if (FFileStream.Handle > 0) and (Include(Msg)) then begin
      s := Parse(Msg);
      FFileStream.Write(s[1], Length(s));
      FFileStream.Write(LOGDEFAULT_LINEFEED[1], Length(LOGDEFAULT_LINEFEED));
    end;
  end;
  Purge;
end;

Messages are stored only if they meet the user defined store filters.

function TLogStoreFlat.Include(Msg: TLogMessage): boolean;
var
  idx: integer;
begin
  Result := True;
  if (FFilters <> nil) then begin
    Result := False; 
    for idx := 0 to FFilters.Count - 1 do begin
      Result := Result or (FFilters.Items[idx] as TLogMessage).Match(Msg);
    end;
  end;
  // IncludeOnFiler = True => Exclude all messages except the ones that pass a filter
  // InlcudeOnFilter = False => Include all messages except the ones that pass a filter
  Result := not(Result xor FIncludeOnFilter);
end;

Class Diagram

Conclusion

Did you learn anything interesting/fun/annoying while writing the code? Yeah! It is hard to write an article...

To Dos

• Implement the LogViewer GUI
• Implement other log store formats such as XML, database, etc.
• Integrate the encryption algorithm(s)
• Complete the (C#) .NET implementation
• Enhance the log message Match method by using Regular Expressions
• Use MSMQ instead of PostMessage, HWND_BROADCAST (HWND_BROADCAST is not tested on Vista OS)
• Devise a way to get the call stack in Delphi

I tried to get the Current Address Pointer using the following code, but I was unsuccessful (and the information was not useful):

{$IFOPT W+}
  {$DEFINE STACKFRAMES_ON}
  {$W-}
{$ENDIF}

function GetCurrReturnAddr: Pointer;
var
  Addr: Pointer;
begin
  asm
    mov edx, [ebp+4];   // EDX := (EBP+4)^;
    mov Addr, edx;      // Address := EDX;
  end;
  Result := Addr;
end;

function GetCurrInstructionAddr: Pointer;
asm
  mov eax, [esp];       // Result := ESP^;  // Return Address
end;

{$IFDEF STACKFRAMES_ON}
  {$W+}
  {$UNDEF STACKFRAMES_ON}
{$ENDIF}

See Also

• Aspect-Oriented Software Development[^].

Revision History

• 2009-03-03: Fixed the links to the demo and source files.
• 2009-03-01: Added a reference to Rob Manderson's articles.
• 2009-02-28: Initial revision.