Simple C++ Debugging and Logging

Example using macros to implement simple debugging and logging functions that log to the console.

Debugging

Modern IDEs usually provide symbolic debugging tools that allow you to step through code line-by-line and examine variables. But sometimes it is more convenient to be able to print information to the console as the program is running. This is one of the oldest debugging techniques and was commonplace before the advent of symbolic debuggers.

One of the key features of debugging output is that it should not print in production code. In fact, it would be ideal if it didn't even compile into our production code so that production code isn't slowed down by debugging code. This can be accomplished using C++ preprocessor macros that check the symbol DEBUG.

#define DEBUG
//#undef DEBUG

You can define or undefine the symbol DEBUG as needed at the beginning of your compilation unit (CPP file) but more than likely your IDE defines DEBUG appropriately when you run in debug vs production/release configuration.

There is an idea promoted by Bertrand Meyer called Design by Contract that helps us formalize what software components expect as inputs (preconditions), produce as an output (postconditions) and maintain as internal state (invariants). We also can formalize any assumptions embedded in the code (assumes). If we are able to code these into our program with debugging statements, then when we are testing we can have the program terminate if any of the preconditions, postconditions, invariants or assumptions fail. This allows us to quickly find problems and fix them so that the conditions hold.

If you create a "Debug.h" file for debugging code, you can easily define macros for these conditions that only generate code when the symbol DEBUG is defined.

#ifdef DEBUG
#define PRECONDITION(b) LOG_FATAL(!(b), "Precondition failure: " #b)
#define POSTCONDITION(b) LOG_FATAL(!(b), "Postcondition failure: " #b)
#define INVARIANT(b) LOG_FATAL(!(b), "Invariant failure: " #b)
#define ASSUME(b) LOG_FATAL(!(b), "Assumption failure: " #b)
#else
#define PRECONDITION(b)
#define POSTCONDITION(b)
#define INVARIANT(b)
#define ASSUME(b)
#endif

All four of the macros take an expression which is true when the conditions hold. This defines the contract for your code (typically a function). If everything is working properly then these conditions will be true. If they are ever false the code will print an error message and immediately throw an exception to terminate the program. LOG_FATAL() will be defined below in the logging section of this post.

In the macros we use the #b syntax to append a string representation of the macro argument b to the failure message. This way we know which condition was violated.

#include <iostream>
#include <cmath>
#include "Debug.h"

using namespace std;

double square_root(double x) {
    PRECONDITION(x >= 0);
    ASSUME(x < 1e6);
    double result = sqrt(x);
    INVARIANT(result >= 0);
    POSTCONDITION(result == 0.0 || abs(result * result - x) / x < 0.001);
    return result;
}

int main(int argc, const char * argv[]) {
    double testValues[] = {5, 0, 1e7, -1};
    for (auto x : testValues) {
        try {
            cout << "sqrt(" << x << ") = " << square_root(x) << endl;
        } catch (exception &ex) {
            // nop
        }
    }
}

Would produce the following results such as...

sqrt(5) = 2.23607
sqrt(0) = 0
sqrt(1e+07) = main.cpp(28):FATAL:Assumption failure: x < 1e6
sqrt(-1) = main.cpp(27):FATAL:Precondition failure: x >= 0

The key concept behind Design by Contract is that preconditions, invariants and postconditions form the contract for a function. The preconditions are the responsibility of the code that calls the function. If the preconditions fail, it is the fault of the calling code. If the preconditions are met then the function is obligated to make sure that the invariants and postconditions are met. If either of these fail, it is due to the code in the function itself. Preconditions, postconditions and invariants go a long way to making sure that our code is provably correct. Implementing them in code allows us to use them for debugging. Assumptions are used primarily to put into code, any assumptions that the code makes that should always be true.

Logging

The debugging macros above were implemented with a simple logging call, namely LOG_FATAL(). This macro and other simple logging macros can be written that allow your code to output different levels of logging messages. These logging messages can be helpful in debugging and they can also be left in the production code to help diagnose runtime problems as well. To our "Debug.h" file we can add the following macros...

// To turn on logging macros for logging to console
// copy one of the following LOG_LEVEL defines to your
// program before including "Debug.h". Best set at project level
// in IDE.
//#define LOG_LEVEL 0     // Fatal only
//#define LOG_LEVEL 1     // Fatal or Error
//#define LOG_LEVEL 2     // Fatal, Error or Warning
//#define LOG_LEVEL 3     // Fatal, Error, Warning or Info
//#define LOG_LEVEL 4     // Fatal, Error, Warning, Info or Debug

#define LOG_PRINTF(b, level, args...) { if (b) { \
        std::cout << __FILE_NAME__ << "(" << __LINE__ << "):" << level << ":"; \
        std::fprintf(stdout, args); \
        std::cout << std::endl; \
    }}

#if LOG_LEVEL >= 0
#define LOG_FATAL(b, args...) LOG_PRINTF((b), "FATAL", args){if (b) throw std::exception();}
#else
#define LOG_FATAL(b, ...)
#endif

#if LOG_LEVEL >= 1
#define LOG_ERROR(b, args...) LOG_PRINTF((b), "ERROR", args)
#else
#define LOG_ERROR(b, ...)
#endif

#if LOG_LEVEL >= 2
#define LOG_WARN(b, args...) LOG_PRINTF((b), "WARNING", args)
#else
#define LOG_WARN(b, ...)
#endif

#if LOG_LEVEL >= 3
#define LOG_INFO(b, args...) LOG_PRINTF((b), "INFO", args)
#else
#define LOG_INFO(b, ...)
#endif

#if LOG_LEVEL >= 4
#define LOG_DEBUG(b, args...) LOG_PRINTF((b), "DEBUG", args)
#else
#define LOG_DEBUG(b, ...)
#endif

The logging is sent to the console which can be redirected if desired to a file when the program is run. There are five different logging macros corresponding to the levels FATAL, ERROR, WARN, INFO and DEBUG. Which macros log and which ones are no-ops depends on the value you define for LOG_LEVEL. This symbol can be defined in your main program before you include "Debug.h" but it is more easily set in your IDE as was the DEBUG symbol earlier.

The log macros all take a boolean expression as the first argument. This expression controls the logging. The message will only be logged if the expression is true. The remaining arguments are a format string and zero or more additional arguments as would be used in a call to printf(). All the logging macros print the source code filename and line number where the log message was coded. All except LOG_FATAL() will log the message and continue. In the case of LOG_FATAL() an exception will be thrown after the message is logged to try to end the program.

If we add the following lines to our main program...

LOG_ERROR(true, "Open the pod bay doors, %s.", "Hal");
LOG_WARN(true, "The %s are coming!", "British");
int x = 5;
LOG_INFO(true, "X: %d", x);
LOG_DEBUG(x > 2, "%d > 2", x);

We should see the following output...

main.cpp(81):ERROR:Open the pod bay doors, Hal.
main.cpp(82):WARNING:The British are coming!
main.cpp(84):INFO:X: 5
main.cpp(85):DEBUG:5 > 2

The full source for "Debug.h" is as follows...

Debug.h
//
// Created by Richard Lesh on 11/3/21.
// Copyright © 2021 Richard Lesh.  All rights reserved.
//

// To turn on DEBUG macros for programming by contract
// copy one of the following DEBUG defines to your program
// before including "Debug.h".  Best set at project level in IDE.
//#define DEBUG
//#undef DEBUG

// To turn on logging macros for logging to console
// copy one of the following LOG_LEVEL defines to your
// program before including "Debug.h". Best set at project level
// in IDE.
//#define LOG_LEVEL 0     // Fatal only
//#define LOG_LEVEL 1     // Fatal or Error
//#define LOG_LEVEL 2     // Fatal, Error or Warning
//#define LOG_LEVEL 3     // Fatal, Error, Warning or Info
//#define LOG_LEVEL 4     // Fatal, Error, Warning, Info or Debug

#ifndef _DEBUG_H
#define _DEBUG_H

#include <cstdio>
#include <iostream>

#define LOG_PRINTF(b, level, args...) { if (b) { \
        std::cout << __FILE_NAME__ << "(" << __LINE__ << "):" << level << ":"; \
        std::fprintf(stdout, args); \
        std::cout << std::endl; \
    }}

#ifdef PARAMETERPACKS_H

#ifdef DEBUG
#define PRECONDITION(b) LOG_FATAL(!(b), "Precondition failure: " #b)
#define POSTCONDITION(b) LOG_FATAL(!(b), "Postcondition failure: " #b)
#define INVARIANT(b) LOG_FATAL(!(b), "Invariant failure: " #b)
#define ASSUME(b) LOG_FATAL(!(b), "Assumption failure: " #b)
#else
#define PRECONDITION(b)
#define POSTCONDITION(b)
#define INVARIANT(b)
#define ASSUME(b)
#endif

#if LOG_LEVEL >= 0
#define LOG_FATAL(b, args...) LOG_PRINTF((b), "FATAL", args){if (b) throw std::exception();}
#else
#define LOG_FATAL(b, ...)
#endif

#if LOG_LEVEL >= 1
#define LOG_ERROR(b, args...) LOG_PRINTF((b), "ERROR", args)
#else
#define LOG_ERROR(b, ...)
#endif

#if LOG_LEVEL >= 2
#define LOG_WARN(b, args...) LOG_PRINTF((b), "WARNING", args)
#else
#define LOG_WARN(b, ...)
#endif

#if LOG_LEVEL >= 3
#define LOG_INFO(b, args...) LOG_PRINTF((b), "INFO", args)
#else
#define LOG_INFO(b, ...)
#endif

#if LOG_LEVEL >= 4
#define LOG_DEBUG(b, args...) LOG_PRINTF((b), "DEBUG", args)
#else
#define LOG_DEBUG(b, ...)
#endif

#endif