Contents
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:
... and a two-part article with really cool ideas:
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.
"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:
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
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.
- Log all messages with all details in a comma-delimited file, named 'Log.csv'.
="1.0"
<Logs>
<Log Path='Log.csv' Format='Flat' Delimiter= ', ' IncludeOnFilter='0' />
</Logs>
- 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.
="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>
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.
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).
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:
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.
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
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
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 (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;
Result := not(Result xor FIncludeOnFilter);
end;
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):
function GetCurrReturnAddr: Pointer;
var
Addr: Pointer;
begin
asm
mov edx, [ebp+4];
mov Addr, edx;
end;
Result := Addr;
end;
function GetCurrInstructionAddr: Pointer;
asm
mov eax, [esp];
end;
- 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.