==============================================================================
C-Scene Issue #2
Debugging your programs
Kerry D. Mathews II, aka Waterhose
==============================================================================

Still Using printf() as a Lowkey Debugger?

A Programming C on Linux Article by
Kerry D. Mathews II - July 04, 1997


I guess the article title is self-explanatory. I know you've done it,
and I know I still do it. In all probability every programmers has
done it. It's fast. It requires no startup... OK, maybe stdio.h.
The only problem with it, is that it lacks a whole lot of functionality.

In this article, I will show you one way to debug that may be a little
efficient than printf(). Its certainly not the best debugger, but it
fills a niche... and with some tweaking can be a be a great tool for
your toolbox. This debugger function will be called dbugger().


So... our requirements?
	1. Must write results to a specific log file.
	2. Must timestamp every entry.
	3. Must show name of source file and function in use.
	4. Must be able to display variables in dynamic formats.
	5. Must be able to granulate the severity of the debug message.
	6. The log file must not exceed a certain length.

Easy enough.

Well, as much as I avoid global variables, we'll need to add a few to the
executable that we are compiling. 
These will be:

	char *program_name;
	char *DEBUG_FILE;
	int   DEBUG_LEVEL;
	long  DEBUG_MAX;


The need only be included in the main source file of a multi file project.

char *program_name:
The program_name should be explanatory. Please say so. If in question,
it is the name of the executable. It is hand if you are using one log
file to log multiple programs. Examples: "test.exe" or 
"main.c".

char *DEBUG_FILE:
This is the full path and name of the debug log file. An example could
be: "/tmp/debug.log"

int DEBUG_LEVEL:
This is a severity level. The severity levels range from zero to nine.
A zero level severity is the most severe. Level nine is trivial.
Based on this severity level, the decision to log this error is made.
All calls to dbugger with a level equal to, and less (more severe)
will be recorded. More on this later.

long DEBUG_MAX:
This is the maximum acceptable size of a debug log file. In practice,
the maximum file length is DEBUG_MAX plus or minus 512 characters.

Great. This takes care of requirements of 1, (some of)3, 5 and 6.

Lets take care of requirements 2, (the rest of)3 and 4.
To do this we need to look at the structure of the dbugger function.



void dbugger( level, va_alist )
int level;
va_dcl
{
   ...
}

It seems that dbugger takes an integer first. That is the debug level
of this function call. If this function call is the same level as
the DEBUG_LEVEL or smaller (remember zero the the most severe) the it
will be recorded in the debug log file.

That va_alist looks interesting. Take a look at varargs.h sometime, it
is very interesting. It is one of those headers that has stuff you
probably wrote yourself. To fill out the string that we'll write in the
debug log file, we take the format, and the passed arguments and 
vsprintf() the stuff together. In the case of dbugger() we cram all that
stuff into a variable called buf.


	va_list args;
	va_start( args );
		sprintf(buffer, "\n%s|%d|%s|", get_now_time(), getpid(), program_name);
		i = strlen(buffer);
		format = va_arg(args, char*);
		vsprintf(buffer + i, format, args);
	va_end( args );

Oh, hey, look we start out the print buffer with the results from
get_time_now(), getpid(), and program_name. For each line printed in the
debug log file, there is at least those three items. Great for us.

The dbugger timestamps in the granularity of thousandths of a second, not
too shabby. Naturally, getpid() give us the process ID. And the program_name
has been globally declared from the main source file.



That varargs stuff looks complicated. So heres some examples of dbugger:

   dbugger(CRITICAL);
   dbugger(IMPORTANT, "Start" );
   dbugger(IMPORTANT, "Entering: %s", program_name );
   dbugger(URGENT, "Err: %d - %s", errno, perror );
   dbugger(8, "Emp Num: %d Emp Name: %s", atoi(EMP_NUM), EMP_NAME );
   dbugger(0); <-- produces undefines behavior

Ahh... yes. This is cool.  :)

Q: Where did the debug level labels come from? 
A: dbugger.h of course!

Now lets look at the log file:

Jul 14 01:10:48.163|1713|test.c|End of test1
Jul 14 01:10:48.165|1713|test.c|Start of test2
Jul 14 01:10:48.167|1713|test.c|this-is-information lev
Jul 14 01:10:48.170|1713|test.c|End of test2
Jul 14 01:10:48.172|1713|test.c|main
Jul 14 01:10:48.174|1713|test.c|debug_max = 10000
Jul 14 01:10:48.177|1713|test.c|End of main



Lastly, we wanted to debug log file to roll over. Theres an internal
function call roll_over_log that checks the size of the log file.
If the log file is greater than DEBUG_MAX then the debug log file 
is renamed by giving it a ".bak" extension and a new debug log file
is created.

There is example code submitted.
Look for: 
	main.c      - an example program
	dbugger.c   - the dbugger() code
	dbugger.h   - the header file

You can compile it by using: cc -o test main.c debugger.c
Do take notice that: #include "dbugger.h" should be a part of your
includes as well.

In closing, I admit that this debugger function is nifty, but I expect
you linux developers to expound upon it and make it a part of your
programming library.

Sure, I made you include four global variables, but printf never had this
much functionality. Best of all, the code is already written.


Support your local Linux Operating System!

You can download a zipfile of the source in this document here.