multi file C program, how best to implement optional logging?

Question

I have a multi file C program. I'd like the user to be able to specify different debugging levels at run time.

What is the best way to implement this?

I was thinking of having a debug(level, "message") type function exported and used everywhere. Any better/other ideas?

Answer 1

There is a very good C port of log4j, log4c.

Answer 2

I have two closely related debug systems that I use (declared in a single header for hysterical raisins). The simpler one has a single debug level and printf-like functions that take a debugging level and only emit the output if the debug level is set high enough. The more complex one provides for different debugging sub-systems, each behaving like the simpler one (so, for example, I can have macro debugging at a different level from the input debugging, or the rules debugging, or ...).

The other issue not addressed by your question is how to enable debugging at run time. I've always used command line options -- usually '-d' for 'basic debugging at level 3', and '-D nn' for debugging at level nn. Or, with the complex system:' -D input=3,macros=5,rules=1'. It would not be hard to have an environment variable with the same semantics.

From the header which implements these:

/*
** Usage:  TRACE((level, fmt, ...))
** "level" is the debugging level which must be operational for the output
** to appear. "fmt" is a printf format string. "..." is whatever extra
** arguments fmt requires (possibly nothing).
** The non-debug macro means that the code is validated but never called.
** -- See chapter 8 of 'The Practice of Programming', by Kernighan and Pike.
*/
#ifdef DEBUG
#define TRACE(x)    db_print x
#else
#define TRACE(x)    do { if (0) db_print x; } while (0)
#endif /* DEBUG */

#ifndef lint
#ifdef DEBUG
/* This string can't be made extern - multiple definition in general */
static const char jlss_id_debug_enabled[] = "@(#)*** DEBUG ***";
#endif /* DEBUG */
#ifdef MAIN_PROGRAM
const char jlss_id_debug_h[] = "@(#)$Id: debug.h,v 3.6 2008/02/11 06:46:37 jleffler Exp $";
#endif /* MAIN_PROGRAM */
#endif /* lint */

#include <stdio.h>

extern int      db_getdebug(void);
extern int      db_newindent(void);
extern int      db_oldindent(void);
extern int      db_setdebug(int level);
extern int      db_setindent(int i);
extern void     db_print(int level, const char *fmt,...);
extern void     db_setfilename(const char *fn);
extern void     db_setfileptr(FILE *fp);
extern FILE    *db_getfileptr(void);

/* Semi-private function */
extern const char *db_indent(void);

/**************************************\
** MULTIPLE DEBUGGING SUBSYSTEMS CODE **
\**************************************/

/*
** Usage:  MDTRACE((subsys, level, fmt, ...))
** "subsys" is the debugging system to which this statement belongs.
** The significance of the subsystems is determined by the programmer,
** except that the functions such as db_print refer to subsystem 0.
** "level" is the debugging level which must be operational for the
** output to appear. "fmt" is a printf format string. "..." is
** whatever extra arguments fmt requires (possibly nothing).
** The non-debug macro means that the code is validated but never called.
*/
#ifdef DEBUG
#define MDTRACE(x)  db_mdprint x
#else
#define MDTRACE(x)  do { if (0) db_mdprint x; } while (0)
#endif /* DEBUG */

extern int      db_mdgetdebug(int subsys);
extern int      db_mdparsearg(char *arg);
extern int      db_mdsetdebug(int subsys, int level);
extern void     db_mdprint(int subsys, int level, const char *fmt,...);
extern void     db_mdsubsysnames(char const * const *names);

Answer 3

In Windows (and broadly across Microsoft), we use Event Tracing for Windows (ETW) extensively. ETW is an efficient static logging mechanism. The NT kernel and many components are very well instrumented. ETW has a lot of advantages:

• Any ETW event provider can be dynamically enabled/disabled at run time - no rebooting or process restarts required. Most ETW providers provide granular control over individual events, or groups of events.
• Formatting of event data is not done a run time (which can be very expensive). Its done when the event trace is post processed.
• ETW is the underlying mechanism for The Windows Event Log. If you build your instrumentation correctly you get application level logging for free.
• Your component can support very granular enabling of events, either individually, by levels, or in groups (or in any combination). You can also put multiple providers in our code.
• Events from any provider (most importantly the kernel) can be merged into a single trace so all events can be correlated.
• A merged trace can be copied off the box and fully processed - with symbols.
• The NT kernel sample profile interrupt can generate an ETW event - this yields a very light weight sample profile that can be used any time
• On Vista and Windows Server 2008, logging an event is lock free and fully multi-core aware - a thread on each processor can independently log events with no synchronization needed between them.
• ETW is efficient when logging is off as well - its just a simple Boolean check (ETW dos this, or you can do it explicitly). Note, this does not require a kernel mode transition. Its all done in process.

This is hugely valuable for us, and can be for your Windows code as well - ETW is usable by any component - including user mode, drivers and other kernel components.

Many people like to watch their logging output as their program or component runs. This is easy to do with ETW. We often do is write a streaming ETW consumer. Instead of putting printfs in the code, I just put ETW events at interesting places. When my component is running, I can then just run my ETW watcher at any time - the watcher receives the events and displays them, counts them, or does other interesting things with them.

Most code can benefit from well implemented logging. Well implemented static run-time logging can make finding many problems straight forward - without it, you have zero visibility into what is happening in your component. You can look at inputs, outputs and guess -that's about it.

They key here is the term 'well implemented'. Instrumentation must be in the right place. Like any thing else, this requires some thought and planning. If it is not in helpful/interesting places, then it will not help you find problems in a a development, testing, or deployed scenario. You can also have too much instrumentation causing perf problems when it is on - or even off!

There are several tools in windows to help you with ETW based loggers and events. These include logman.exe and tracerpt.exe. There are also the xperf tools which are focused on performance, but can also control any ETW provider and dump log files.

Answer 4

Jonathan's suggestion is good but since C99 we have variadic macros so one doesn't need to use double braces for debug macro.

There is a light version of logging header I use:

#define LOG_FATAL    (1)
#define LOG_ERR      (2)
#define LOG_WARN     (3)
#define LOG_INFO     (4)
#define LOG_DBG      (5)

#define LOG(level, ...) do {  \
                            if (level <= debug_level) { \
                                fprintf(dbgstream,"%s:%d:", __FILE__, __LINE__); \
                                fprintf(dbgstream, __VA_ARGS__); \
                                fprintf(dbgstream, "\n"); \
                                fflush(dbgstream); \
                            } \
                        } while (0)
extern FILE *dbgstream;
extern int  debug_level;

So wherever I need to log something, I just add line like

LOG(LOG_ERR, "I/O error %s occured while opening file %s", strerror(errno), filename);

During program initialisation you need to specify values for dbgstream (usually defaults to stderr) and debug_level.

For real projects instead of calling fprintf many times I just call my function from LOG macro and pass __FILE__, __LINE__ and __VA_ARGS_ as argument - that function also prints date, time and pid in log line, and don't do fflush() every time - only when buffering counter exceeds preset value - itsignificantly increases logging performance.

But please be aware that some compilers may not support variadic macros as it was introduced only in C99.