Table of contents
- Preface to the version 1.6.3.93
- Preface to the third release
- Introduction
- Code that debugs itself
- Requirements to the debug macros
- QAFDebug debug macros
- Using the debug macros
- Error log file and VC++ debug trace window
- Release vs. debug builds
- Customizing the debug log for your projects
- Unit tests support
- Syntax coloring and AutoText completions
- Additional examples
- Appendix A: References
- Appendix B: Drawbacks of C++ standard ASSERTs
- Appendix C: History
- Appendix D: Missing features
- Appendix E: Q_TRACEX macro and trace logs
Preface to the version 1.6.3.93
The new release features support of VC++ 6.0/7.0/7.1/8 (tested on VC++ 6.0 SP 6 and VC++ .NET 2005 beta) and Linux support
(tested in Feudora Core 2 distribution). Unfortunately, I was not able to test it under VC++ .NET 2003 and Embedded VC++,
but it should remain compatible. Anyway, I keep the previous version sources available too, with only minimal fixes suggested
here in the forum. The new release does not change the critical debug log functionality, so I'd suggest you to move
to the new version only if you need its new features: VC++ 2005 support, Linux support, or trace log classes, which were
improved significantly (look at Appendix E: Q_TRACEX macro and trace logs).
Notes regarding Embedded VC++ support: only critical error log is available (qafdebug.h and qafdebug.cpp). Trace log
is developed using templates, and Embedded VC++ does not support templates as far as I know.
Notes regarding Linux support: it is not complete, comparing to Windows. I did not implement multithread synchronization
in trace log classes. There is no printing of version numbers, and even the name of the application. I'd appreciate help
with improving Linux support. An important thing about trace logs that on Linux they are configured using environment variables.
Preface to the third release
After publishing this article, the debug macros were improved significantly, so I decided to publish a new release of
the code.
It features support of VC++ 6.0/7.0/7.1 (tested on VC++ 6.0 SP 5 and VC++ .NET 2003) and support of Embedded VC++ 3.0
(thanks to Vadim Entov for porting the sources to Windows CE).
The output error message format is changed for better readability and details. Now it provides detailed information about
the error (both error code and message), version of the debugged application and optionally the file name and version of
the source DLL module that reports about the error (a very handy feature when one has several DLLs sharing the same source
files). Also, now the error log is written in UTF-8 format which simplifies mixing UNICODE and ASCII modules.
C:\SOColl\SOMain.cpp(137) : Check error: got 10 (0xA) while expected 0 (0x0)
time: 2003-12-08 17:34:33:443
process: 0x00000280
thread: 0x00000560
application: C:\Program Files\MSOffice\WINWORD.EXE <10.0.5522.0>
module: C:\SOColl\Debug\SOColl.dll <1.6.0.8>
last error: 2, The system cannot find the file specified.
expression: ERR_NO_ERROR == DoProcess( szInputFile )
There are several new macros added: Q_CHECK, Q_ERROR_SUCCESS, Q_MAPI_ERROR,
Q_RETURN, Q_MFC_EXCEPTION, Q_STD_EXCEPTION and Q_SET_MODULE (thanks
to Andrey Krasnopolsky for his help in the development of the library). Also, there is an optional QSockErr.h header
that implements Q_SOCKET_ERROR macro that simplifies reporting socket errors.
I updated only few sections in the article: look at Using the debug macros for the new macro descriptions,
check Unit tests support for better unit tests introduction, read Customizing the
debug log for your projects for changes and improvements, do not miss also the new Additional examples
section with some examples that visualize the power of the debug macros.
After several attempts to use this error log facility as a trace log, I decided to explain the difference between error
and trace logs as I see it. Look at Appendix E: Q_TRACEX macro and trace logs. I attached the trace
logs facility to this article. Note that I did not invest as much time into the trace logs facility, and while I constantly
use it, I still do not find time to finish the trace log levels feature (I'll appreciate any help with that). Thus the trace
log sources are provided AS-IS with short explanations.
I wish to thank everybody in this forum for helping me to better understand and argument my position, especially Marc
Clifton, Daniel Turini, Sam Levy, Stoyan Damov, Alex Reser and Stewart Tootill. I wish to thank too the organizers and maintainers
of this community for their ideas, time and efforts.
Introduction
Standard C++ debug macros are not rich. Usually only a couple of such macros with some variations is there in your toolkit:
ASSERT() and TRACE() (look at
[MSDN: Assertions]
for complete list of the standard debug macros). In its general implementation, ASSERT() pops up a dialog box
and/or terminates the program. TRACE() usually outputs a string to the debug output.
"Assert yourself" concept is extremely useful in debugging but it is diminished by limitations of standard debug macros.
They do have severe drawbacks (look at the Appendix B: Drawbacks of C++ standard ASSERTs). They are
not suitable especially for the projects I work on: DLLs and ActiveX COM objects, often running on a server. They lack some
features important to me (like the ability to have release builds with the critical error log, reporting the actual error
message to that log and controlling module versions). I cannot allow them to terminate the server process. I do not want
to bother QA guys with the "Abort, Retry, Ignore" dialog boxes. Finally I do not like how these ASSERTs appear
in the source code (look at the Listing 2). I want an alternative.
More than that, traditionally the role of these debug macros is limited to the input parameters testing while they can
detect a wide scope of programming errors. I think that the design of the standard ASSERT macro limits its
power. To overcome the ASSERT's limitations, I developed a set of simple, flexible and powerful debug macros
that allow me to catch most of the programming errors on early stages of development. Even more, these macros, as a tool,
stimulate writing the "code that debugs itself". The technique and the tool presented here proved their usefulness in real
projects.
Code that debugs itself
Before we go into the implementation details, I want to guide you to the idea of writing the "code that debugs itself".
This idea is simple, it is very old, and it was not me who invented it: code defensively, show up the defects and always
check error returns (look at [The Practice of Programming, page 142]).
Here's an example. Suppose you have a function like this one (the example is Win32, VC++, COM and ATL specific):
HRESULT ConvertFile2File( BSTR bstrInFileName, BSTR * pbstrRet )
{
if( NULL == bstrRet )
return E_INVALIDARG;
QComDispatchDriver piConvDisp;
HRESULT hr = piConvDisp.CreateObject
( L"QTxtConvert.QTxtConv", CLSCTX_LOCAL_SERVER );
if( FAILED(hr) )
return hr;
hr = piConvDisp.Invoke1( L"Convert",
CComVariant(bstrInFileName), NULL );
if( FAILED(hr) )
return hr;
CComVariant varTemp;
hr = piConvDisp.Get( L"Target", &varTemp );
if( FAILED(hr) )
return hr;
hr = varTemp.ChangeType( VT_BSTR );
if( FAILED(hr) )
return hr;
CComBSTR bstrResult = varTemp.bstrVal;
hr = piConvDisp.Get( L"Author", &varTemp );
if( Q_SUCCEEDED( hr ) &&
Q_ASSERT( VT_BSTR == V_VT(&varTemp) ) )
{
CComBSTR szAuthor = V_BSTR( &varTemp );
if( szAuthor.Length() > 0 )
{
bstrResult += L"&>";
bstrResult += szAuthor;
}
}
return bstrResult.CopyTo(pbstrRet);
}
This function is defensive and its error processing is okay. It is pretty good for the release code but first you must
debug this code. Here I have a problem - while this function accurately returns the error code, I have no idea what caused
the error. This function may return the same E_FAIL from 6 different places. The only way to know where it
failed is to go through it step by step in the debugger, that is not always possible. The user or a QA guy will find some
feature(s) non-working with no diagnostic of the problem. What would you do?
Well, at this point, the ASSERT() macro comes to help us. Using the ASSERT macro, we can spot
the error at the moment it happens. We can test the input parameters, illegal conditions and our design assumptions. Look
at the resulting code:
HRESULT ConvertFile2File( BSTR bstrInFileName, BSTR * pbstrRet )
{
ASSERT( NULL != bstrRet );
ASSERT( SysStringLen(bstrInFileName) > 0 );
if( NULL == bstrRet )
return E_INVALIDARG;
QComDispatchDriver piConvDisp;
HRESULT hr = piConvDisp.CreateObject
( L"QTxtConvert.QTxtConv", CLSCTX_LOCAL_SERVER );
ASSERT( SUCCEEDED(hr) );
if( FAILED(hr) )
return hr;
hr = piConvDisp.Invoke1( L"Convert",
CComVariant(bstrInFileName), NULL );
ASSERT( (E_INVALID_FORMAT == hr) || SUCCEEDED(hr) );
if( FAILED(hr) )
return hr;
CComVariant varTemp;
hr = piConvDisp.Get( L"Target", &varTemp );
ASSERT( SUCCEEDED(hr) );
if( FAILED(hr) )
return hr;
hr = varTemp.ChangeType( VT_BSTR );
ASSERT( SUCCEEDED(hr) );
if( FAILED(hr) )
return hr;
CComBSTR bstrResult = varTemp.bstrVal;
hr = piConvDisp.Get( L"Author", &varTemp );
ASSERT( SUCCEEDED(hr) );
ASSERT( VT_BSTR == V_VT(&varTemp) );
if( SUCCEEDED( hr ) && ( VT_BSTR == V_VT(&varTemp) ) )
{
CComBSTR szAuthor = V_BSTR( &varTemp );
if( szAuthor.Length() > 0 )
{
bstrResult += L"&>";
bstrResult += szAuthor;
}
}
hr = bstrResult.CopyTo(pbstrRet);
ASSERT( SUCCEEDED(hr) );
return hr;
}
Is it long and ugly? - Yes, I agree. Is it a misuse of ASSERTs? - Not at all! (May be only a bit :) )
The usual place for ASSERTs is at the beginning of the function where it tests for input parameters. Most
programmers stop on that. I think they forget that ASSERTs are also a tool to test design assumptions
and illegal conditions. I assume that the object must be registered and available. I assume that it must never fail
in Convert(). I assume that there are two BSTR properties. Finally, I assume that my object will
not eat all the computer's memory. All of those are my design assumptions. I test my assumptions by adding ASSERTs.
This fact does not eliminate the regular error handling, not at all.
Well, I mix here runtime error conditions (memory overflow) with runtime programming errors or illegal conditions (NULL
pointer in input parameters). I think they are very close to each other since they are not expected by my algorithm. These
are unexpected errors that should be handled by ASSERTs. I never will use asserts to test expected
errors (like writing to a read-only file). You can see in the code that I filter one expected error that may occur in
this function: the Convert method may return the E_UNKNOWN_FORMAT error. There are no other expected
errors (like file read errors) because the input file is generated by the caller process and must be always available for
me. If it cannot be read, this is an unexpected error.
I definitely want to have all this debug staff, but I do not like how the code looks. And even if I know that the code
failed in a specific place, I would like to know why - to get the HRESULT code at least. Plus, I may repeat
again all what I wrote in the Appendix B: Drawbacks of C++ standard ASSERTs. I think now it is the
right time to present the right tool.
Requirements to the debug macros
When discussing this article in the forum, I quoted "The Practice Of Programming" by Brian W. Kernighan and Rob Pike.
They say that most of the programmers (companies) write their own versions of the ASSERT macro to overcome
the limitations of the standard one. They just recommended to use some other name in order to not break others code.
When I first started to think about a set of debug macros, I defined the following requirements:
- Only few easy-to-use functions or macros with clear semantic (to make them user-friendly... sorry - developer-friendly).
- Error report is sent either to file or debug console (no pop-up dialog boxes, look at the Appendix
B for Drawback #2).
- Switching on/off the debug macros should not affect the normal program execution (adding a debug macro should not
cause evaluating the expression twice, look at the Appendix B for Drawback #5).
- Debug macros can be transparently integrated into the source code and removing them in the release build should
not change the algorithm (each
ASSERT macro generally takes a separate line and causes the program to repeat
the tested condition twice).
- Error report must be available in both debug and release builds depending on conditional defines (in certain cases,
I want to keep the error log in release builds - it makes detecting defects in early production much easier).
While developing the debug macros, I formulated some additional requirements, most of which were assumed by me but not
stated:
- Debug macros must report as much information about the error as possible: location, module, error code, error message
and last system error.
- Debug macros must be very light-weight when no error occurs (as little overhead as possible). But in the case of
an error to be reported, the time of reporting does not matter (overhead is not important).
- Debug macros implementation should not depend on RTTI, exceptions or templates feature of C++ language (Windows
CE, for instance, does not fully support them).
- Debug macros must allow multiple threads and processes reporting to the error log concurrently. Still, since critical
errors are supposed to be rare (few per day), synchronization mechanism may be simplified.
- Version numbers of the application and DLL where the error occurred - it helps to identify the responsible DLL even
if several DLLs share some of the source codes, and it helps to locate a correct version of source code in the source
control system.
I realized that using C++ syntax it is very simple to reach these requirements. It took me about 10 releases to come
up with the first set of debug macros and about an year to improve it to the current state :-).
QAFDebug debug macros
bool Q_ASSERT( bool )
This is the macro similar to the regular ASSERT() macro. It returns the same value as it receives. And
it reports if the bool is false (good condition failed).
if( Q_ASSERT( NULL != lpszString ) )
;
else
return ERROR;
bool Q_INVALID( bool )
This is the macro that is very useful in testing parameters. It returns the same value as it receives. And it reports
if the bool is true (bad condition succeeded).
if( Q_INVALID( NULL == lpszString ) )
return ERROR;
bool Q_SUCCEEDED( HRESULT )
This is the macro similar to the regular SUCCEEDED() macro. It actually uses SUCCEEDED()
inside. And it reports if HRESULT is an error.
hr = varTemp.ChangeType( VT_BSTR );
if( Q_SUCCEEDED( hr ) )
;
else
return hr;
bool Q_FAILED( HRESULT )
This is the macro similar to the regular FAILED() macro. It actually uses FAILED() inside.
And it reports if HRESULT is an error.
if( Q_FAILED(hr) )
return hr;
HRESULT Q_ERROR( HRESULT )
This is a special macro that returns the same input value. It is useful in places where you get a result and return
it immediately without testing.
return Q_ERROR( bstrResult.CopyTo(pbstrRet) );
bool Q_ERROR_SUCCESS( DWORD )
This is a macro for testing ERROR_SUCCESS-compatible error codes returned by many Win32 API functions
(by registry functions, for example). This macro will report if the given error code differs from ERROR_SUCCESS
constant. It will report the error message too.
DWORD dwRet = RegQueryValueEx( hKey, _T("Value"), NULL, &dwType,
(LPBYTE)szBuf, &dwSize );
if( Q_ERROR_SUCCESS( dwRet ) )
;
bool Q_CHECK( dwConstant, dwExpression )
This is a macro for testing any expected values. This macro will report if the expected dwConstant differs
from the result returned by dwExpression. It will report both the expected and received values.
DWORD dwErr = DASetOption( NULL, SCCOPT_FIFLAGS );
if( Q_CHECK( DAERR_OK, m_dwErr ) )
;
void Q_MAPI_ERROR( HRESULT, MAPI_Interface )
This is a special macro for reporting errors returned by MAPI interfaces. Each MAPI interface has a special facility
for converting the error codes to error messages. Such code takes more than 10 lines, so I implemented it as a macro.
This macro has to be used as a statement, not as an expression.
HRESULT hr = piProfAdmin->CreateProfile( szName, NULL, 0,
MAPI_DEFAULT_SERVICES );
if( Q_FAILED( hr ) )
{
Q_MAPI_ERROR( hr, piProfAdmin );
return hr;
}
int Q_SOCKET_ERROR( int )
This is a special macro for reporting errors returned by WSAGetLastError() function from Windows Sockets
API (WinSock). While WinSock has a lot of well-documented error codes, it has no function that returns a human-readable
string message for an error (as far as I know). This macro converts the error code to a string message and returns it.
It does nothing if the error code is 0. This macro is defined in QSockErr.h header file.
if( SOCKET_ERROR == listen( socket, SOMAXCONN ) )
{
int nRet = WSAGetLastError();
if( WSAENETDOWN != nRet )
Q_SOCKET_ERROR( nRet );
return nRet;
}
void Q_RETURN( hr )
This is a shortcut macro for testing an HRESULT expression and returning from the function in case of
any failure. It represents the following logic:
if( Q_FAILED(hr) )
return hr;
Actual code is a bit more complex to protect from executing the tested expression twice. This macro has to be used
as a statement, not as an expression.
Q_RETURN( piWordApp->GetDocument( &piDoc ) );
Q_RETURN( piDoc->GetSelection( &piSel ) );
Q_RETURN( piSel->Copy() );
void Q_MFC_EXCEPTION( CException ) void Q_EXCEPTION( CException )
This is a special macro that is very useful when processing exceptions in MFC Wizard-generated code. It reports the
error message contained in the exception. This macro has to be used as a statement, not as an expression.
catch{ CException & e )
{
Q_MFC_EXCEPTION( e );
}
void Q_STD_EXCEPTION( std::exception )
This is a special macro that is very useful when processing C++ standard library exceptions. It reports the error
message contained in the exception. This macro has to be used as a statement, not as an expression.
catch{ std::exception & e )
{
Q_STD_EXCEPTION( e );
}
void Q_LOG( LPCTSTR )
This macro writes a custom error message to the error log. It replaces un-descriptive Q_ASSERT(false).
This macro has to be used as a statement, not as an expression.
DLLEXPORT int Func01( LPCTSTR lpszString )
{
Q_LOG( _T("This function is deprecated "
"and it should never be called!") );
}
void Q_SET_MODULE( szModuleName )
This is a special macro for setting the current DLL module name. I did not find a simple automatic way to know in
context of which DLL the code executes, so I use a special static string variable. You need to specify only the file
name of the DLL module, and it will automatically find its location and version number at runtime. This macro is not
necessary for an EXE module. Usually, it has to be added to DllMain() function. This macro has to be used
as a statement, not as an expression.
BOOL APIENTRY DllMain( HANDLE hModule,
DWORD ul_reason_for_call, LPVOID lpReserved )
{
switch (ul_reason_for_call)
{
case DLL_PROCESS_ATTACH:
{
Q_SET_MODULE( _T("MODULE.DLL") );
...
Using the debug macros
Now, let's return to that function and add the debug macros in it. Once we add the debug macros, the function will carefully
report about all unexpected errors at the moment they happen. And the error reporting staff does not take too much space
in the code and time to implement. No more than it is needed, I mean.
#include "QAFDebug.h"
...
HRESULT ConvertFile2File( BSTR bstrInFileName, BSTR * pbstrRet )
{
if( Q_INVALID(NULL == bstrRet)
|| Q_INVALID(SysStringLen(bstrInFileName) <= 0) )
return E_INVALIDARG;
QComDispatchDriver piConvDisp;
HRESULT hr = piConvDisp.CreateObject( L"QTxtConvert.QTxtConv",
CLSCTX_LOCAL_SERVER );
if( Q_FAILED(hr) )
return hr;
hr = piConvDisp.Invoke1( L"Convert",
CComVariant(bstrInFileName), NULL );
if( (E_INVALID_FORMAT == hr) || Q_FAILED(hr) )
return hr;
CComVariant varTemp;
hr = piConvDisp.Get( L"Target", &varTemp );
if( Q_FAILED(hr) )
return hr;
hr = varTemp.ChangeType( VT_BSTR );
if( Q_FAILED(hr) )
return hr;
CComBSTR bstrResult = varTemp.bstrVal;
hr = piConvDisp.Get( L"Author", &varTemp );
if( Q_SUCCEEDED( hr )
&& Q_ASSERT( VT_BSTR == V_VT(&varTemp) ) )
{
CComBSTR szAuthor = V_BSTR( &varTemp );
if( szAuthor.Length() > 0 )
{
bstrResult += L"&>";
bstrResult += szAuthor;
}
}
return Q_ERROR( bstrResult.CopyTo(pbstrRet) );
}
The syntax of these macros is clear. As you can see, the expression is evaluated only once so the algorithm remains the
same in the debug and release builds. If you disable the debug staff, it only will remove these Q_ signs not
touching the program logic (it's an allegory but it's close to the truth).
When something goes wrong (the programmer tries to access an invalid property name or there is no enough memory), the
program will write to the error log file all the error information available:
C:\Work\XM\XMClient.cpp(770) : Unspecified error
time: 2003-12-22 12:34:48:044
process: 0x000012D4
thread: 0x00001088
application: c:\connector\xmsrv.exe <1.0.0.15>
module: c:\connector\XMClient.dll <1.0.0.24>
last error: 1008, An attempt was made to reference
a token that does not exist.
expression: FAILED(0x80004005)
You have all the required information here: the name and the version of the hosting process, the last error code, your
module and its version, the location in the source file and description of the error (sure, E_FAIL provided
in this example is not very descriptive :), but there are other error codes). In many cases it is enough to take a look
at the log record on the QA computer to understand what's wrong with your program.
In debug build, the same log message is output to the debug log in VC++ IDE. It allows quick navigation to the source
of the error.
In order to use the debug macros, you need to add two files to your project: QAFDebug.h and QAFDebug.cpp.
You might need linking your program to version.lib library (in VC++ 6.0, it is not linked to the project by default).
I recommend also to adjust several constants in the source code to define the desired location and maximum size of the log
file. Look at the Customizing section.
Error log file and VC++ debug trace window
I like the error log to be printed in the debug trace window of my VC++ IDE when I'm running the debugger, and to be
written to the file otherwise. This is what I implemented there. The error log is written to the file and duplicated for
the VC++ IDE or other trace tools (like DebugView from http://www.sysinternals.com/).
I have a lot of different ActiveXs and DLLs hosted by different processes, so I need to have a single well known location
for the log file. I decided to put it under the folder:
C:\Documents and settings\UserName\Application Data\MyCompany\Log\error.log
Note that Windows CE does not have a large file system. Actually, it has about four standard root folders and that's
it. Therefore, on Windows CE, the error log is written to the analog of My Documents folder. In this folder, it creates
the sub-folder \MyCompany\Log\. In fact, I'd recommend switching the error log off in release builds for Windows
CE - a hand-held device has limited resources.
For DLLs hosted by NT services (they have no current user account), I use the All Users or Default User
folders (it differs between Windows versions). Or you may define an environment variable named QAFERRORLOGPATH.
I think using the environment variable is the best way for NT services.
An endless error log is dangerous. Therefore, I implemented a maximum log file size limit (by default, 1 Mb). There are
two log files at each moment - the current one and the previous one. Generally, 1 record takes about 300-600 bytes, so I
reserve space for about 2,000 records. This should be enough and the size limit guarantees that both log files together
will not be larger than 1 Mb. Note that usually, if the application works as it was expected, you will not find the error
log files at all.
All processes write to the same log file. Of course, access to it should be synchronized. But since it is the critical
error log and not a regular trace log, and critical errors happen quite seldom, I use the file itself for synchronization.
I lock it on opening and try to open the file several times (max. 200 msec) if it is locked by someone else. This protects
me from any kind of deadlocks.
Release vs. debug builds
Jon Bentley in his [Programming Pearls, page 50] quotes Tony Hoare who said that a programmer who uses assertions while
testing and turns them off during production is like a sailor who wears a life vest while drilling on shore and takes it
off at sea. The question "to assert or not to assert in release" already caused a lot of discussions here in the forum.
I think the answer is quite simple: whenever you know that the product is stable, you are free to switch off the assertions
for better performance and security. You are free to switch them off if the product is not stable yet as well :).
In certain cases, I believe it is useful to keep the critical error log switched on even in release builds. In a start-up
company and on early stages of production, when the QA/RND loops are very short, tests do not cover 100% of features and
new releases almost immediately go to production (for me, as a developer, even an internal release or a pilot project means
"production"), there is no chance to release a fully tested build. Developers receive many defect reports from outside and
in most cases they are hard to reproduce. In such situations, the critical error log becomes extremely useful. The macros
make the program several Kb bigger and affect the performance a bit (maximum two assembler instructions per macro when no
error is detected), but the cost is worth to pay it.
The set of macros presented here is very flexible - you may decide to switch it on/off depending on the debug/release
builds. Even specific parts of it may be switched on/off. From my experience, it is useful to switch maximum reporting in
debug builds, and keep only the error log file enabled in release builds (usually nobody traces the release product). These
are the default settings. Look at the next section if you want to override this. I also switch off the unit tests support
in release builds since unit tests are a bit heavy.
Customizing the debug log for your projects
First of all, I recommend you to change the following constants in QAFDebug.h and define them to something unique
for your projects:
#define QAFDEBUG_COMPANY_NAME "YourCompany"
Your company name which defines a unique subfolder in the application data folder,
and also a key in the registry for configuration.
QAFDEBUG_LOG_ENV_VAR = _T("QAFERRORLOGPATH")
Name of the environment variable that may set the output debug log folder.
QAFDEBUG_SILENCE_MUTEX = _T("QAFDebugMutex001A")
The name of the mutex for synchronizing with the unit test support staff.
QDEBUG_SHMEMFILE = _T("QAFDbgMemFile01")
The name of the memory-mapped-file that stores the shared flags for the unit test support staff.
You might also want to correct the following constants in QAFDebug.h:
QAFDEBUG_LOG_FILE_MAX_SIZE = (1024 * 1024)
Maximum log file size in bytes (not in characters as in the previous versions).
QAFDEBUG_LOG_FILE_NAME = _T("error.log")
The current error log file name.
QAFDEBUG_LOG_OLD_FILE_NAME = _T("error.old.log")
The previous error log file name.
The following defines allow, switching off specific features of the debug log (or any reporting at all):
QAF_DISABLED
Switch off any error reporting (not used by default).
QAF_LOGFILE_DISABLED
Switch off writing to the error log file (not used by default).
QAF_OUTPUTDEBUGSTRING_DISABLED
Switch off writing to the debug trace window (defined in release builds by default).
QAF_UNITTEST_DISABLED
Switch off unit test support (defined in release builds by default).
Unit tests support
I use CppUnit for unit test automation. Once I reviewed
quite a lot of unit testing frameworks for C++ and decided to take it as most suitable for my needs. Writing unit tests
is tedious work but it saves my time later, when debugging and testing changes in the code.
Writing test cases in CppUnit is not difficult. In addition to test case, test suite and fixture classes which are easy
to learn, there are a few "work-horse" macros. The most basic of them is CPPUNIT_ASSERT macro. This macro executes
an expression and reports if it succeeded or failed. A typical test case may look like this:
void CUnitTest::testCase01( void )
{
CPPUNIT_ASSERT( SUCCEEDED( QAFGetRegKey() ) );
CPPUNIT_ASSERT( 0 == _tcscmp( ST_VAR, _T("100%") ) );
...
}
If any of the lines fail, CppUnit will report the location of the failure. My problem was that it cannot report what
exactly happened - CppUnit only knows the end result of the expression: TRUE or FALSE. Here debug
macros come to help. If the functions being called are instrumented with QAFDebug macros, they will carefully
report to the debug log file what went wrong in the function body. The unit test runner may collect the error log file and
attach it to the unit test report log.
Usually, the unit test does not only tests if the function works. A good unit test should also test the function call
with wrong parameters and ensure it returns correct error code. The error becomes being a normal, desired behavior. For
example, look at the following unit test case:
void CUnitTest::testCase01( void )
{
CPPUNIT_ASSERT( FAILED( QAFGetRegKey( NULL ) ) );
CPPUNIT_ASSERT( 0 != _tcscmp( ST_VAR, _T("0%") ) );
...
}
In this case, I need to temporarily disable the error log, test that the function fails, and enable the error log back.
In order to support this, I added two macros:
void Q_SILENT( expression );
This macro disables the error log, evaluates the expression and enables the error log back.
void Q_ENABLE_DEBUG_LOG;
This macro unconditionally enables the error log. It is useful when the log might remain disabled by an exception
thrown in the previous test case. By including it, you ensure that the error log is switched on.
void CUnitTest::testCase01( void )
{
Q_ENABLE_DEBUG_LOG;
CPPUNIT_ASSERT( SUCCEEDED( QAFGetRegKey() ) );
CPPUNIT_ASSERT( 0 == _tcscmp( ST_VAR, _T("100%") ) );
Q_SILENT( CPPUNIT_ASSERT( FAILED( QAFGetRegKey( NULL ) ) ) );
Q_SILENT( CPPUNIT_ASSERT( 0 != _tcscmp( ST_VAR, _T("0%") ) ) );
...
}
The unit test support introduces some overhead. Synchronization between processes requires using mutexes and a memory
mapped file. Therefore, I only keep it in debug builds and exclude it in release builds. Usually, I do the same for the
unit tests - only debug builds contain tests. Again, the overhead becomes an issue if only the tested application starts
writing hundreds of messages to the error log file. If no error occurred, only a couple of additional assembler instructions
execute per macro.
Syntax coloring and AutoText completions
There are many opportunities to make programming simpler and faster. I present here a couple of add-ins (most of VC++
programmers should already know them) that help me not only with the debug macros but with the entire coding process. You
can find the corresponding files in the QAFDebug_doc.zip.
The UserType.dat file makes Visual Studio 6.0 to highlight common ATL and MFC classes, types, macros and functions
as keywords (in blue). This helps a lot because the colored standard types are easy to recognize and you do less syntax
mistakes. I added my debug macros to this file, so they are highlighted too. This file should be put under the folder:
C:\Program Files\Microsoft Visual Studio\Common\MSDev98\Bin
The VAssist.tpl file contains keyboard shortcuts for Visual Assist 6.0 that make typing commonly used constructions
faster. Visual Assist 6.0 from http://www.wholetomato.com/ is
one of the most useful add-ins for Visual Studio 6.0 that upgrades IntelliSense features of VC++. I strongly recommend this
add-in. I added several keyboard shortcuts for my macros to make my life simpler. You must not replace this file,
but add its contents to the existing one.
Now, when I type qs, it automatically inserts Q_SUCCEEDED(). The other shortcuts mean:
qa (Q_ASSERT()), qi (Q_INVALID()), qf (Q_FAILED()),
qe (Q_ERROR()), qx (Q_EXCEPTION(e)), ql (Q_LOG( _T("")
);), qc (Q_CHECK( , )) and qr (Q_RETURN();). This file is usually
located under the following folder (you also may edit it from Visual Assist options):
C:\Program Files\Visual Assist 6.0\Misc
Additional examples
From time to time, I work with JNI (Java Native Calls) DLL modules. Often, the interface of the module cares little about
the error reporting - the only thing important to the caller is whether the call succeeded or not. Thus, there is not much
left for the postmortem failure analysis. Let's take a function that should never fail under normal conditions. Only when
it meets something unexpected, it would return a failure. The following JNI wrapper calls a C function LRS().
It does not report the error code returned from this function. Instead, it simply returns an empty string in case of any
error. The critical error log keeps trace of all internal failures.
JNIEXPORT jstring JNICALL Java_com_company_ta_Detector_getTaFromFile
(JNIEnv * env, jclass cls, jstring jFileName)
{
if( Q_INVALID( NULL == env ) )
return NULL;
if( Q_INVALID( NULL == jFileName ) )
return env->NewStringUTF( "" );
char szLang[MAX_PATH] = { 0 };
const char * FileName = NULL;
FileName = env->GetStringUTFChars( jFileName, NULL );
if( Q_INVALID( NULL == FileName ) )
return env->NewStringUTF( "" );
int nRet = LRS( FileName, szLang );
if( !Q_CHECK( NO_ERROR, nRet ) )
return env->NewStringUTF( "" );
return env->NewStringUTF( szLang );
}
Another example is taken from a custom socket connection protocol. Any data transfer protocol relies heavily on many
assumptions (buffer sizes, constants, relations between different variables). Implementing a complex error processing using
exceptions with tracing can be painful and may affect performance. After the protocol is fully debugged, the error processing
will seldom be needed. Here assertions become very handy. Actually, using assertions in this function helped me in discovering
and fixing one very rare and difficult bug.
if( (0 != m_dwAttachSize) && (ulBufSize > ulBytesSentRet) )
{
if( Q_INVALID( m_dwRemained > m_dwAttachSize ) )
{
Q_CHECK( m_dwRemained, m_dwAttachSize );
return OP_FAILED;
}
unsigned long ulDataSize = ulBufSize - ulBytesSentRet;
if( ulDataSize > m_dwRemained )
ulDataSize = m_dwRemained;
unsigned long ulWritten = 0;
DWORD dwPos = m_dwAttachSize - m_dwRemained;
if( 0x0000 == m_wCodePage )
{
dwPos = 0;
bool bRet = ReadAttachment( dwPos, ulDataSize );
if( Q_INVALID( ! bRet ) )
{
Q_CHECK( 0, dwPos );
Q_CHECK( 0, ulDataSize );
return OP_FAILED;
}
}
if( Q_INVALID( NULL == m_pAttachment) )
return OP_FAILED;
if( 0xFFFF == m_wCodePage )
ret = pChannel.SendUTF16( m_pAttachment + dwPos,
ulDataSize, ulWritten );
else
ret = pChannel.Send( m_pAttachment + dwPos,
ulDataSize, ulWritten );
Q_INVALID( OP_NEED_MORE_DATA == ret );
Q_INVALID( 0 == ulWritten );
if( OP_FAILED == ret )
return ret;
ulBytesSentRet += ulWritten;
m_dwProcessed += ulWritten;
m_dwRemained -= ulWritten;
}
Q_CHECK( GetPacketSize(), m_dwProcessed + m_dwRemained );
Appendix A: References
- Debugging Applications by John Robbins
An excellent book on debugging Win32 applications.
- Writing Solid Code by Steve Maguire
This book should be studied in schools... schools of programming, I mean :). This is my favorite. In a very popular
manner, it discusses writing high quality programs and touches the entire development circle.
- The Pragmatic Programmer - From Journeyman to Master by Andrew Hunt and David Thomas
Another favorite of mine. It belongs to the same genre as Writing Solid Code, but of course it is different. Must
to read, IMHO.
- Code Complete by Steve McConnell
This book is too academic but also recommended. I'd say it lacks a bit of fun.
- The Practice of Programming by Brian W. Kernighan and Rob Pike
This book is a kind of old fashion but still valuable.
- Programming Pearls by Jon Bentley
This book speaks more about algorithms than about style of coding. But there are a couple of interesting chapters.
- ATL/AUX Library by Andrew Nosenko
The idea behind the debug macros in this library is very similar to mine. They convert HRESULT error
codes to meaningful error messages.
- Extended Debug macros by Jungsul Lee
Macros there implement only the idea of having the error processing in release builds. There is no log file and I
do not like the idea of breaking the program execution.
- A Treatise on Using Debug and Trace classes...
by Marc Clifton
The author of this article is actually who inspired me to re-write this article and better argument my position.
I liked to learn from his experience too.
- Considerations for implementing trace facilities
in release builds... by Vagif Abilov
Look at the title. A good one.
- MSDN:
Assertions by Microsoft (C)
A short and complete reference of all assertions available in VC++.
- Enhancing Assertions by Andrei
Alexandrescu and John Torjo
A very interesting article on using templates to construct ASSERTs.
- CppUnit
C++ unit testing framework that I'd undoubtedly recommend.
- A set of template classes for working with the registry
by Daniel Andersson
Once upon a time, I took his set of simple classes for working with registry and used it till now. While the original
sources are significantly modified, I keep the link to the original author. These classes are used in
QTrace trace log facility.
Appendix B: Drawbacks of C++ standard ASSERTs
This is an example of the standard assertion message that is displayed by the ANSI assert() function. Personally,
I do not like the standard assertions coming with VC++. They suffer from many little but annoying defects. I'm sure that
the framework I present here is also full of drawbacks :) (Appendix D lists the missing features only). Still, mine provides
me with more goods.
- Drawback 1: Missing information.
The regular assert only knows the process name, the source file name and the line number. I find it
useful to print also the timestamp, process ID, thread ID, the last error code and the error message itself. I use this
information in conjunction with the trace log which is formatted similarly. The most useful fields are the error message
and the last error code.
- Drawback 2: The pop up dialog box.
Most of the standard ASSERT macros pop up a dialog box like the one on the screenshot. When you are
working on a project that does not have a UI, such as a Windows NT service or a COM out-of-process server, this dialog
box might be missed by the user or even might hang the process (look at [Debugging Applications, page 60]). Also, I
never saw a QA person who liked to get these dialog boxes because she can do nothing except choosing "Ignore". I prefer
to have a single well-known file with the error log.
- Drawback 3: Redirecting the
stderr to a file.
The C run-time library allows redirecting the assertion to a file or to the OutputDebugString API by
calling the _CrtSetReportMode function (look at [Debugging Applications, page 61]). But none of these functions
take care of the common file location for all your programs. Neither do they truncate the file in case it becomes too
large. (I'm not quite honest here - it is possible to write a helper class which will do it.) At last, in a case you
develop a COM in-process object or a DLL, you are not in charge to redirect stderr because it belongs to
the entire process (this is one of my problems with regular ASSERTs).
- Drawback 4: Change state of the system.
All the Microsoft-supplied assertions suffer from one fatal flaw: they change the state of the system. This issue
is discussed in detail in [Debugging Applications, page 62], here I'll explain it in short. Many of the Win32 API functions
use the SetLastError and GetLastError functions. And it is often needed to test the last error
code to react differently on different errors. VC++ CRT macros do not preserve the last error code while at the same
moment these macros themselves call other Win32 functions which might destroy the last error code by setting it to 0.
(To be honest again, I have to say that I found this argument when recently I started to re-read this book in searching
information for the revised article).
- Drawback 5: Potential side effects.
Almost any coding style book mentions the danger of assertions' side effects. (Look at [Writing Solid Code, page
38], [Code Complete, page 96] and
[MSDN:
Assertions].) If the expression you test in the ASSERT macro is complex and includes function calls,
this expression may occasionally change data. The debug version of the program may became dependent on this occasionality,
and the release build will fail because of the missing function call. While the golden rule is to try never call functions
in the assertions, these things still happen. I believe that by integrating the assertions into the actual algorithms,
it is possible to eliminate this class of defects. Note that in this case, when assertions are disabled, the compiler is
able to optimize out unnecessary equations, with minor exceptions which may be handled manually.
Appendix C: History
QAFDebug/QAFTrace version 1.6.3.93
- The article is updated with latest changes and fixes.
- Support for VC++ 6.0/7.0/7.1/8.0 (tested on VC++ 6.0 SP 6 and VC++ .NET 2005 beta).
- Support for Linux (tested in Feudora Core 2 distribution).
- Improvements and fixes in the trace log facitlity - corrected names of the macros, added trace log levels,
added DEBUG-only and DEBUG/RELEASE logs.
QAFDebug/QAFTrace version 1.6.0.71
- Same as version 1.6.0.70 + fixed several minor bugs noted in the forum + added #pragma for automatic linking to version.lib.
QAFDebug version 1.6.0.70
- The article is updated with latest changes and fixes.
- Support for VC++ 6.0/7.0/7.1 (tested on VC++ 6.0 SP 5 and VC++ .NET 2003).
- Support for Embedded VC++ 3.0 (thanks to Vadim Entov for porting the sources to Windows CE).
- The output error message format is changed for better readability and details.
- New macros added:
Q_CHECK, Q_ERROR_SUCCESS, Q_MAPI_ERROR, Q_SOCKET_ERROR,
Q_RETURN, Q_MFC_EXCEPTION, Q_STD_EXCEPTION and Q_SET_MODULE
(thanks to Andrey Krasnopolsky for his help in the development of the library).
- The output error message contains the source module file name and version number.
- Fixed buffer overflow bug for large messages (now error messages are truncated to 600 characters).
QAFDebug version 1.5.0.20
- The article is completely re-written with better examples and argumentation.
- Fixed a syntax error in the
Q_EXCEPTION macro.
- Fixed a memory allocation error in UNICODE builds (I allocated bytes instead of
TCHARs).
- Added preserving the last error code as in [Debugging Applications, page 62].
- In RELEASE builds, I removed printing the expression - it should optimize the size of the executable
a bit, since the file name and line number are enough to locate the problem.
Appendix D: Missing features
- I'd like to report the call stack, at least in the DEBUG builds. The problem is that most of the examples
are Windows NT specific.
- I'd like to be able to get the error reports in real-time. Let's say, I define a computer in the network that gathers
all the error logs, sorts them and forwards to the responsible developers. This should visualize the silent defects
that QA is not used to notice.
- In case the program is running from the debugger, I'd still like to be able to fall into the debugger in case of
an error, but this should be a kind of switch (this feature is something that I've lost from the standard
ASSERT
macro).
Appendix E: TRACEX macro and trace logs
Some time after writing the debug error log facility, I catch myself on attempts to use this log as a trace log. I clearly
understood that the error log design goals did not suite the trace log requirements. A good trace log must have:
- strong synchronization to prevent different threads and processes from deadlocking or running into race conditions.
- multiple debug levels.
- rich output message format options:
printf()-style, C++ stream <<-style, memory dumps.
- numerous trace log files for different modules.
- little performance impact when the log is disabled.
- ability to switch trace logs on per-file basis from a single well-known location.
- specific light-weight output format (something like: Timestamp, ProcessID, ThreadID, Message, Source file, line).
- Ability to automatically write the source code position to the trace log.
- Ability to write trace logs to different output streams (to file, console or VC++ IDE).
None of those are implemented in the critical error log facility. Moreover, these requirements contradict with the requirements
of the critical error log. I've analyzed every trace debug log I could find at that moment. No one suited me completely
but I learned a lot and got new ideas. It is not a big deal to write a trace log, so I wrote it. (The big deal is to improve
it to a "professional" component, with rich features and documentation.) To the moment the unit is quite stable,
but there are many features still waiting to be implemented. Anyway, I like its flexibility, simplicity, and rich formatting options.
Let me demonstrate its usage:
#include "QAFTrace.h"
#ifdef QD_TRACE_ENABLED
QTrace::LogFile log( _T("mylogfile.log"), QTrace::TraceDebug, 512 * 1024 );
#endif
int main()
{
int i = 65, j = 5;
int arr[5] = { i, i, i, i, i };
QD_TRACEX( log, "Output a simple string" );
QD_TRACEX( log, L"Output a UNICODE string, j = " << j );
QD_TRACEX( log, QTrace::Format( "printf-style %d, %d", i, j )
<< " and more!" );
QD_TRACEX( log, "Format hex codes = 0x" << QTrace::Hex( i ) );
QD_TRACEX( log, QTrace::Dump( &arr[0], sizeof(arr), _T("int[5]") ) );
return 0;
}
The output will look like:
01:31 14:05:01:342 [3DA:11E] Output a simple string <== c:\wrk\tst.cpp(10)
01:31 14:05:01:342 [3DA:11E] Output a UNICODE string + j = 5 <== c:\wrk\tst.cpp(11)
01:31 14:05:01:359 [3DA:11E] printf-style 65, 5 and more! <== c:\wrk\tst.cpp(12)
01:31 14:05:01:383 [3DA:11E] Format hex codes = 0x41 <== c:\wrk\tst.cpp(13)
01:31 14:05:01:402 [3DA:11E] Memory dump of "int[5]", address 0x3FE56470,
size 20b (0x14) <== c:\wrk\tst.cpp(14)
3FE56470 00 00 41 00 00 00 41 00 00 00 41 00 00 00 41 00 ..A...A...A...A.
3FE56480 00 00 41 00 ..A.
The trace log contains only the important information - timestamp, process and thread ID, the message and the source
file location (similar messages may be output from different functions). There may be different trace log files in one process,
and many processes can write to the same trace log. All trace logs are created in the same folder where the critical error
log is located. Each trace log can be switched on/off through the registry under /HKLM/Software/YourCompany/Log/
using a DWORD registry value named the same as the trace log file name ("mylogfile.log" in my example).
By default, the trace log is disabled, and you should define a specific value in the registry to enable it. Note that on Linux
the trace log is enabled by setting an environment variable. This environment variable has the same name as the log file,
with dots replaced by underscores "mylogfile_log".
Usually, I either create a static log class instance, or add it as a member of another class - there is no problem with
multiple instances of the same trace error log because they use a named mutex for synchronization (not implemented on Linux yet).
When the trace log is disabled, the performance impact is very little - Q_TRACEX macro is converted into
if( !log.IsEnabled() ) ; else log.output(); construction.
There are two sets of trace macros: QD_XXXX and QR_XXXX. QD_XXXX macros are completely excluded from RELEASE builds
for the sake of performance. QR_XXXX macros allow creating trace logs which will be available in both DEBUG and
RELEASE builds.
Again, the trace debug log is purposed to help in debugging the system and the critical error log is intended for QA
and early production bug diagnostics. These are very different goals. When the program works as expected, the critical error
log should remain empty and the debug trace log might be flooded by trace messages (if it is enabled, of course).
