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.
FUNCENTRY
Usage: FUNCENTRY("CHTTPThread::InitInstance");
Use this at the
start of the fn.
FUNCEND
Usage: FUNCEND;
Use this at the end of the fn.
FUNCRETURN
Usage: FUNCRETURN(FALSE);
Use this at the end of the fn.
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:
THREADDATALOG
Usage: Same as INFOLOG
, Just a different name for clarity.
LOGWARNING
Usage: Same as INFOLOG
. However the message is prefixed with
Warning:
LOGERROR
Usage: Same as INFOLOG
. However the message is prefixed with
Error:
LOGFATALERROR
Usage: Same as
INFOLOG
.
However the message is prefixed with Fatal Error:
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)
{
CString csLogFileName = "C:\\BlackSabbath.log";
.
.
.
CAppConfigReader* pConfig = CAppConfigReader::GetInstance(
(LPTSTR)(LPCTSTR)csXMLFileName);
if(NULL != pConfig)
{
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
- Function Level = 0
- Info Level = 1
- Warning Level = 2
- Error Level = 3
- 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"
Example of Using Log
CBlackSabbathDlg::~CBlackSabbathDlg()
{
FUNCENTRY("CBlackSabbathDlg::~CBlackSabbathDlg");
busyAVIG.DestroyWindow();
cleanupThreadsAndData();
if(NULL != pNewMenuM)
{
delete pNewMenuM;
pNewMenuM = NULL;
}
DeleteCriticalSection(&BrokenListLockG);
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()
.
csLogFileName = AppendNowTimeStampToFileName(csLogFileName);
I am a software programmer with 17 years of experience working on Microsoft technologies using various tools. Using spare time I play Ping Pong and enjoy music and movies.I come from Trichur, a town in kerala, India. I love code forums and feel obligated to contribute every once in a while.
I think Internet and the information share it provides is mind boggling. Do we ever believe, tomorrow always brings to reality,above and beyond what dreams can glimpse.