DnLog Debugging Function

[Note: This was originally written for "FYI", the internal newsletter for the worldwide software engineering departments of Dendrite International]

The 5.0 DLL DnLog includes several little known functions that you can use to help monitor, or otherwise debug Windows C code. The most basic is DebugMessage, which will send a printf style formatted message out to DBWin, much like the Windows internal function, DebugOutput(). (DBWin.exe is a program provided by Microsoft in the Windows SDK) Now, you may be asking, "Why do we need DebugMessage if we already have DebugOutput?" Glad you asked. DebugOutput will only work when you are running the Windows debugging binaries, which make some programs, particularly Borland's IDE, run unacceptably slowly. DebugMessage works with the retail binaries.

Also, DebugOutput and well as its cousin OutputDebugString, have this very annoying habit of assuming that if DBWin is not running, that you want the messages displayed on a dumb terminal you just happen to have connect to COM1. Unfortunately, since nearly all Dendrite machines, and, for that matter, most PCs in the world, have either a mouse or modem on COM1, sending ASCII text to that port at random times can cause trouble. To deal with this problem, Microsoft added a System.Ini switch ([debug] OutputTo=NUL), to prevent the output from going where it doesn't belong if DBWin isn't there to take control. So, we'd like to make sure that command is in effect before we try displaying anything with OutputDebugString. Since DebugMessage ultimately uses OutputDebugString, on initialization it looks for the System.Ini setting, and if it's not found, will refuse to output anything.

However, the feature of DebugMessage that could be most important, is that, like the standard library function assert(), DebugMessage is actually a macro that can be effectively removed from the code by the preprocessor during a compile. In fact, calls to DebugMessage are always effectively voided, unless the constant DENDEBUG is #defined. Listing 1, below, shows how this is accomplished.

Two other macros in that listing don't do much by themselves, but help make other tasks easier. SZFUNCNAME() should be placed inside every function in the DLL. With debugging on, it declares a character array called szFuncName holding the name of the function, in the most space efficient way possible, making it available, using a standardized name, to any macro that may need it. But, with debugging off, it's translated as just ((void)(NULL)).

This will have the effect of removing it from the code, saving the space used by the string. (As an unfortunate side effect, since it is sometimes a declaration and sometimes an executable statement, you must place it between the function's last normal local variable declaration, and it's first actual executable line.)

SOURCEFILE, with debugging on, puts the name of the file into character array with a standard name, szFileName. What's wrong with using "__FILE__" every place you need the name of the source file? Most of the time, nothing. Technically, every time you use __FILE__ the compiler creates a separate string, and then later, depending on its mood and switch settings, usually combines them to have all references use the same string. In which case, using szFileName & __FILE__ are exactly the same. However, if the compiler chooses not to combine them, you could have dozens of copies of the same string littering up your data segment. Using SOURCEFILE merely gives you tighter reign over this.

With debugging off, SOURCEFILE defines the same string, but also defines a dummy global szFuncName, since the other ones aren't being defined now. This protects against an undefined variable error should we want to use szFileName in some way that remains with debugging off. (Since szFuncName could be defined to this dummy value, always be sure to use __LINE__ as well, should you ever specifically refer to szFuncName. That way, an error can always be traced back to the line of code that caused it, even if the function name isn't made immediately known. Since __LINE__ produces a numeric value instead of a string, it doesn't face the same problems as __FILE__)

The non-debug definition of DebugMessage may be a bit confusing. It is intended to remove the function call from the source file, much the way that the non-debug definition of SZFUNCNAME does. But, simply #defining it to NULL won't work. Since DebugMessage takes variable number of arguments, which macros don't allow, we have to keep the arguments out of the #define for DebugMessage. In other words, we must use #define DebugMessage instead of #define DebugMessage(a,b,c). So, if "DebugMessage" was just "(void) (NULL)", then the statement:

	DebugMessage("The Value is %d\n", val); 
would be rendered as:
	(void) (NULL) ("The Value is %d\n",val);
which is a syntax error. But, as defined above, it expands to:
	TRUE ?((void)(NULL)) :DEBUGMESSAGE("The Value is %d\n",val);

which is syntactically correct, and, since the value of TRUE is a constant, the compiler will automatically perform the operation, and optimize it down to just "(void) (NULL)" which is what we wanted all along. After the colon, I could have used any function which took variable parameters; DEBUGMESSAGE was just conventient. (If you liked that cute trick, just ask me about the fun stuff you can do with "do {} while (FALSE)" !)

The next macro is LANDMARK. It's very handy if your program is getting lost or locking up. Just librally sprinkle them throughout the troublesome area, and DBWin will keep you updated as to which parts of you code have been executed, by displaying messages in the form "---(Function Name) @ (line number)"

LOADINGSTAMP is intended to be placed in the LibMain function of each DLL, and displays the date and time the file was last compiled as the DLL is loaded into memory. It is helpful when you have several versions of a DLL in different directories, and need to make sure that the latest is being used. Unfortunately, it only gives the date that the source file containing LibMain was last compiled, instead the date the entire DLL was last created. This is not a severe limitation, since most of our DLLs have only one source file each, so these two dates would be the same. (However, I am working on the problem...)

LOG_ID can be used in calls to the logging functions, eg

	lg_LogMess(LOG_ID, "Message %s blah blah", szWhatever);

It uses the file & function name strings described above, but mainly, it replaces three long parameters with one short one, to make the source code easier to read.

void _cdecl DEBUGMESSAGE(LPCSTR format,...);
#if defined(DENDEBUG)
#define DebugMessage	DEBUGMESSAGE
#define SZFUNCNAME(name)	static const char szFuncName[]=#name
#define LANDMARK	DebugMessage("---%s @ %d\n", szFuncName, __LINE__)
#define LOADINGSTAMP	DebugMessage("Loading " __FILE__ " created on " __DATE__ " " __TIME__);
#define SOURCEFILE	static const char szFileName[] = __FILE__
#else
#define DebugMessage	TRUE ? (void) (NULL) : DEBUGMESSAGE
#define SZFUNCNAME(name)	((void)(NULL))
#define LANDMARK	((void)(NULL))
#define LOADINGSTAMP	((void)(NULL)) 
#define SOURCEFILE	static const char szFileName[] =__FILE__; \
static const char szFuncName[] ="---"
#endif
#define LOG_ID szFuncName, szFileName, __LINE__
#include <DnLog.h>
SOURCEFILE;

#pragma argsused
int WINAPI LibMain(HINSTANCE hInst, WORD wDSeg, WORD cbHeapSize, LPSTR lpCmdLine)
{
	LOADINGSTAMP;
	return(TRUE);
}

void _MyTestFunc(void)
{	
	int	x;
	int	n;
	int	retv;
	SZFUNCNAME(MyTestFunc);
	LANDMARK;
	SomePotentiallyDangerousFunction();
	LANDMARK;
	x = 5;
	for (n=0; n < 7; n++)
	{
		DebugMessage("Divisor = %d", x-n);
		retv = SomeOtherFunc(100 / (x-n));
		DebugMessage("Retv = %d", retv);
	}
	LANDMARK;
	return;
}	

Sample Output

Loading MYTEST.C created on 05 January 94 13:15:23
---MyTestFunc @ 16
---MyTestFunc @ 18
Divisor = 5
Retv = 0
Divisor = 4
Retv = 0
Divisor = 3
Retv = 0
Divisor = 2
Retv = 0
Divisor = 1
Retv = 0
Divisor = 0
(GPF Error)

Copyright © 1994, James M. Curran