Logging For Multi Threaded Applications

• Download source - 24.6 Kb

Note

For sample application refer: http://www.codeproject.com/threads/BlackSabbatch.asp

Why write a Log file

Log file is always good for an application to log errors and informative situations. Say for example your application does a transaction with credit cards. Now if the credit card processing succeeds and order update fails, you got a genuine situation. This can be handled if a good logging and log checking mechanism is in place. However the above was just an example.

One of the main debugging/trouble shooting tools for multi threaded projects is a log file for function entry/exit and diagnostic purpose data logging and error logging. Logs have to be thread safe for this purpose as multiple threads can access the log file simultaneously. I have a bunch of macros to make the usage easy. I will illustrate the usage of these macros with examples.

Justification of Use

I have seen this mechanism being used in call center applications. Logging would leave the application virtually as fast as without it, however tracking down an issue will be rather easier and in many cases very predictable. Rather than asking about the description of a bug, all you have to do is to get the log for the error.

Usage

When the application starts, the logging objects has to be created as below

CLogFile::Create();

When the application exits the logging objects has to be deleted as follows.

CLogFile::Release();

The macros are declared in LoggingAPI.h and the usage is as follows.

1. FUNCENTRY

   Usage: FUNCENTRY("CHTTPThread::InitInstance"); Use this at the start of the fn.

2. FUNCEND

   Usage: FUNCEND; Use this at the end of the fn.

3. FUNCRETURN

   Usage: FUNCRETURN(FALSE); Use this at the end of the fn.

4. INFOLOG

   Usage:

   INFOLOG(("Thread ID: %d \n",pThread->m_nThreadID));</P>
   <P>INFOLOG(("Thread Creation Succeeded \n"));</P>

   Note: The usage is like CString::Format() with arguments put in a ( ). The message is prefixed with Data:

5. THREADDATALOG

   Usage: Same as INFOLOG, Just a different name for clarity.

6. LOGWARNING

   Usage: Same as INFOLOG. However the message is prefixed with Warning:

7. LOGERROR

   Usage: Same as INFOLOG. However the message is prefixed with Error:

8. LOGFATALERROR

Log file location

The default log file will be created at C:\BlackSabbath.log. This is being set in the logfile.cpp function CLogFile::Create(), you can change it to suit your need. However the log file is being read from the application configuration file, if one provided (Ref: http://www.codeproject.com/threads/CheeAppConfig.asp). Application configuration file is being instantiated internally in CLogFile::Create(). The key in application configuration file for log file path is

<P><LogFileName>C:\MyProjects\BlackSabbath\BlackSabbath.log</LogFileName></P>

Here is the relevant code

BOOL CLogFile::Create()
{
if(NULL == pLogFileM)
{
// Default name of log file
CString csLogFileName = "C:\\BlackSabbath.log";
.
.
.
// This is where the application configuration reader in instantiated
// An ideal place to set and read this is from an environment variable
// I leave the implementation to you
CAppConfigReader* pConfig = CAppConfigReader::GetInstance(
  (LPTSTR)(LPCTSTR)csXMLFileName);
if(NULL != pConfig)
{
// Get the log file name
csLogFileName = pConfig->GetValue(CString("/AppLogging/LogFileName"));
}
.
.
.
}
return (NULL != pLogFileM);
}

How to Handle Installation of Application using programs

Be careful when you using code from the sample application provided or source code provided here, in your application. It determines Configuration file path from the executable file name and goes one directory up to find the configuration file in the source code directory. So does it do for all file names. The assumption made is we run from Debug or Release directory. If you don't know where the executable is going to be, please get your value for configuration file name using an environment variable. Why environment variable? This is to handle the situation of software that has to be installed. Write an environment variable with the installation path while install and use the relative path in the configuration file. Concatenating both gives you the real path on client machine.

Setting Error logging level

Using the configuration file you can set the level of error logging. The key is in configuration file as follows

<P><CurrentLoggingLevel>1</CurrentLoggingLevel></P>

The values mean the following

1. Function Level = 0
2. Info Level = 1
3. Warning Level = 2
4. Error Level = 3
5. Fatal Level = 4

CurrentLoggingLevel = 1 in configuration means all the log messages above 1 including 1 will be logged. That means Function Level logging will be ignored.

Files to be included

• AppConfigReader.cpp
• AppConfigReader.h
• LogData.cpp
• LogData.h
• LogFile.cpp
• LogFile.h
• LoggerThread.cpp
• LoggerThread.h
• LoggingAPI.H

Configuration file in the executable directory for run time. Please read section "Log file location"

• BlackSabbathConfig.xml

Example of Using Log

CBlackSabbathDlg::~CBlackSabbathDlg()
{
FUNCENTRY("CBlackSabbathDlg::~CBlackSabbathDlg");
// We have to clean it from here
busyAVIG.DestroyWindow();
// Clean up any more threads remaining
cleanupThreadsAndData();
// Delete the main dialog menu
if(NULL != pNewMenuM)
{
delete pNewMenuM;
pNewMenuM = NULL;
}
// Delete the list control critical section
DeleteCriticalSection(&BrokenListLockG);
// Uninitialize COM
CoUninitialize();
FUNCEND;
}

The relevant logfile entry looks as following

23:52:35.136 Thread(1916) Entering CBlackSabbathDlg::~CBlackSabbathDlg File(C:\MyProjects\BlackSabbath\BlackSabbathDlg.cpp) Line(104)
23:52:35.136 Thread(1916) Entering cleanupThreadsAndData() File(C:\MyProjects\BlackSabbath\utils.cpp) Line(47)
23:52:35.136 Thread(1916) Entering CThreadSafePtrArray::RemoveHead File(C:\MyProjects\BlackSabbath\ThreadSafePtrArray.cpp) Line(118)
23:52:35.146 Thread(1916) Entering CThreadSafePtrArray::RemoveAt File(C:\MyProjects\BlackSabbath\ThreadSafePtrArray.cpp) Line(138)
23:52:35.146 Thread(1916) Exiting CThreadSafePtrArray::RemoveAt File(C:\MyProjects\BlackSabbath\ThreadSafePtrArray.cpp) Line(160)
23:52:35.146 Thread(1916) Exiting CThreadSafePtrArray::RemoveHead File(C:\MyProjects\BlackSabbath\ThreadSafePtrArray.cpp) Line(133)
23:52:35.146 Thread(1916) Entering CThreadSafePtrArray::RemoveHead File(C:\MyProjects\BlackSabbath\ThreadSafePtrArray.cpp) Line(118)
23:52:35.146 Thread(1916) Entering CThreadSafePtrArray::RemoveAt File(C:\MyProjects\BlackSabbath\ThreadSafePtrArray.cpp) Line(138)
23:52:35.146 Thread(1916) Exiting CThreadSafePtrArray::RemoveAt File(C:\MyProjects\BlackSabbath\ThreadSafePtrArray.cpp) Line(160)
23:52:35.146 Thread(1916) Exiting CThreadSafePtrArray::RemoveHead File(C:\MyProjects\BlackSabbath\ThreadSafePtrArray.cpp) Line(133)
23:52:35.146 Thread(1916) Exiting cleanupThreadsAndData() File(C:\MyProjects\BlackSabbath\utils.cpp) Line(130)
23:52:35.146 Thread(1916) Exiting CBlackSabbathDlg::~CblackSabbathDlg

You can see the sequence of function execution here.

Meaning of Log entries

Normal Function Exit

14:09:13.219 Thread(1540) Entering CMRUCombo::AddToMRUList File(c:\myprojects\blacksabbath\mrucombo.cpp) Line(56)
14:09:13.219 Thread(1540) Exiting CMRUCombo::AddToMRUList File(c:\myprojects\blacksabbath\mrucombo.cpp) Line(80)

Abnormal Function Exit

14:24:21.305 Thread(1516) Abnormally exiting CBlackSabbathApp:InitInstance File(c:\myprojects\blacksabbath\blacksabbath.cpp)

This is not pleasant. Can be because of two reasons.

You forgot to terminate the function with FUNCEND or FUNCRETURN.

There was an unhandled exception and the control was lost from the function. This demonstrates one more advantage of logging, detecting exceptions.

Data Logging

01:59:14.643 Thread(1224) Data: Opening link http://www.msn.com at depth 0 (null) File(C:\MyProjects\BlackSabbath\HTTPThread.cpp) Line(156)

Which functions to avoid logging

However the logging is according to your discretion as to what you redeem important and what you don't. Type of functions to avoid from logging are UpdateCommandUI, PreTranslateMsg, OnPaint, OnDraw, OnTimer, CArray::GetAt derived handlers. The reason is that they are frequently called functions and will explode your log file and make it less readable. However when you get a bug, please don't overlook the possibility that one of these "no logging" functions is the culprit.

Log file Cleanup

Please note that the log file is always created with the time stamp appended for archiving log files. Hence please also note a new file will be created per instance and remember, this will make your hard drive run out of space and routine log file clean up will be required. If you need to remove the time stamp and rewrite the same log file, comment out the following line from

CLogFile::Create()

// Append time Stamp To log file name
csLogFileName = AppendNowTimeStampToFileName(csLogFileName);