Fun to Program -- Debug: level 1

This was originally written and created around 2013 and may require to be updated. (2021)

Debug: level 1

Debugging is the major part of programing.

If your code fails by an unknown cause, it is primitive but is often used technique to embed logging codes for key internal parameters. This logging must be disabled for the normal program execution.

TIP: Use the script(1) command to obtain a file copy of the console output. Piping the COMMAND output as “COMMAND 2>&1 |tee typescript” is an alternative.

If your code assumes something, it is good idea to protect this assumption with an assertion code, i.e., a conditional reporting and aborting code. If the assertion code fails, you know you hit a bug. This is a very effective and preventive debug method.

Let’s review some cliches used to embed such codes.

Shell logging

Embedding many “echo "..."” lines works fine to debug short shell programs.

But it can get tangled with normal output codes. So disabling them for production use and removing them later may not be trivial for larger shell programs.

You can solve this complication by defining a purpose specific debug function.

The cli-log program logs an error message if the variable DEBUG is set.

Example of a shell code cli-log with logging capability.

#!/bin/sh
# Un-comment the following to activate debug messages
#DEBUG="TRUE"
debug ()
{
    if [ -n "$DEBUG" ]; then
        echo "$@" >&2
    fi
}
FOO=$1
BAR=$2
debug "I: debug log message: FOO=$FOO, BAR=$BAR"
echo "$FOO $BAR!"

Execution example of logging for a shell code cli-log.

$ ./cli-log Hello World
Hello World!
$ DEBUG=TRUE ./cli-log Hello World
I: debug log message: FOO=Hello, BAR=World
Hello World!

TIP: Unlike Bash, Dash which offers /bin/sh on the recent Debian system does not support $LINENO for wheezy.

Python logging

Embedding many “print("...")” lines works fine to debug short Python programs.

Let’s try to log in a better way as done for the above shell code.

The cli-log program logs an error message if the variable DEBUG is set.

Example of a Python 3 code cli-log with logging capability.

#!/usr/bin/python3
import sys,os,inspect
try:
    DEBUG = os.environ["DEBUG"]
except KeyError:
    DEBUG = 0

def debug (msg):
    """Outputs to sys.stderr if DEBUG is non-zero."""
    if (DEBUG):
        print(msg, file=sys.stderr)

def lineno():
    """Returns the current line number."""
    return inspect.currentframe().f_back.f_lineno

def main():
    foo = sys.argv[1]
    bar = sys.argv[2]
    if (foo != bar):
        debug("L: line=%i, foo=%s, bar=%s" % (lineno(), foo, bar))
    print(foo + " " + bar +'!')

if __name__ == '__main__': 
    main()

TIP: On Python 2, you should replace “#!/usr/bin/python3” with “#!/usr/bin/python”; and “print(msg, file=sys.stderr)” with “print >> sys.stderr, msg”.

Execution example of logging for a Python code cli-log.

$ ./cli-log Hello World
Hello World!
$ DEBUG=TRUE ./cli-log Hello World
L: line=21, foo=Hello, bar=World
Hello World!

See:

C logging

Embedding many “printf(fmt, ...)” or “fprintf(stderr, fmt, ...)” lines works fine to debug short C programs.

TIP: The unifdef command may be handy for removing these useless debug lines after finishing the debug, if they are enclosed between a pair of macros such as #ifdef DEBUG and #endif.

Let’s try to log in a better way as done for the above shell and Python codes.

I made a generic C header file logerr.h for this purpose.

A C header code logerr.h with logging capability.

#include <stdlib.h>
#include <stdio.h>

#ifdef NLOGERR
#define logerr(level,fmt,...)
#else
#define logerr(level,fmt, ...) \
if(level <= logerr_level) { \
    fprintf(stderr, "%s: %s:%d: ", \
        level >= 3 ? "D" : level == 2 ? "I" : level == 1 ? "N" : "W" , \
        __FILE__, __LINE__); \
    fprintf(stderr, fmt, ##__VA_ARGS__); \
    fflush(stderr); \
    } \
else /* the single statement cliche to avoid breaking if(...)-construct */
#endif

#define LOGERR_WARN        0       /* W: warning       always */
#define LOGERR_NOTICE      1       /* N: notice        -v */
#define LOGERR_INFO        2       /* I: informational -vv */
#define LOGERR_DEBUG       3       /* D: debug         -vvv */

int logerr_level = LOGERR_WARN;

Here,

This logerr macro is safe to use even after if(...)-construct.
The global variable logerr_level is used to control the logging threadshold of the logerr macro.
The NLOGERR macro controls deactivation of the logerr macro.

TIP: do { ... ; } while(0) is another construct frequently used in the macro definition to avoid breaking if(...)-construct.

TIP: GNU extention form of the variadic macro “, ##__VA_ARGS__” is used in place of “, __VA_ARGS__” to deal with the case of zero extra argument. See Variadic Macros.

The cli-log.c program logs an error message if the variable DEBUG is set or the -v option is used.

Example of a C code cli-log.c with logging capability.

#include <stdlib.h>
#include <stdio.h>
#include <unistd.h> /* getopt */
#include "logerr.h"

int main(int argc, char **argv)
{
    int c;
    int logerr_level = 0;
    char* env_debug = NULL;
    env_debug = getenv("DEBUG");
    if (env_debug) {
        logerr_level = atoi(env_debug);
    }
    while ((c = getopt(argc, argv, "v")) != -1) {
        switch (c) {
        case 'v':
            logerr_level += 1;
            break;
        default:
            printf("unknown option = %c = ascii(0%x)\n",
                    optopt, optopt);
            printf("return value of getopt() = %c\n", c);
        }
    }
    printf("logerr_level = %i\n", logerr_level);
    logerr(LOGERR_NOTICE,"optind = %i\n", optind);
    logerr(LOGERR_INFO,"argc = %i\n", argc);
    logerr(LOGERR_DEBUG,"argv[0] = %s\n", argv[0]);
    if (optind + 2 == argc) {
        printf("%s %s!\n", argv[optind], argv[optind+1]);
    } else {
        logerr(LOGERR_WARN,"%i arg(s) / 2 args needed\n", argc - optind);
        printf("Oops!\n");
    }
    return EXIT_SUCCESS;
}

Compile and execution example with logging for a C code cli-log.c.

$ gcc -Wall -o cli-log cli-log.c
$ ./cli-log Hello
W: cli-log.c:33: 1 arg(s) / 2 args needed
logerr_level = 0
Oops!
$ ./cli-log Hello World
logerr_level = 0
Hello World!
$ ./cli-log -v Hello World
N: cli-log.c:27: optind = 2
logerr_level = 1
Hello World!
$ ./cli-log -vv Hello World
N: cli-log.c:27: optind = 2
I: cli-log.c:28: argc = 4
logerr_level = 2
Hello World!
$ ./cli-log -vvv Hello World
N: cli-log.c:27: optind = 2
I: cli-log.c:28: argc = 4
D: cli-log.c:29: argv[0] = ./cli-log
logerr_level = 3
Hello World!
$ ./cli-log -vvv Hello World EXT
N: cli-log.c:27: optind = 2
I: cli-log.c:28: argc = 5
D: cli-log.c:29: argv[0] = ./cli-log
W: cli-log.c:33: 3 arg(s) / 2 args needed
logerr_level = 3
Oops!
$ DEBUG=2 ./cli-log -v Hello World
N: cli-log.c:27: optind = 2
I: cli-log.c:28: argc = 4
D: cli-log.c:29: argv[0] = ./cli-log
logerr_level = 3
Hello World!

You can completely remove logging capability in compile time by defining the NLOGERR macro.

Compile and execution example without logging for a C code cli-log.c.

$ gcc -Wall -DNLOGERR -o cli-log-no cli-log.c
$ DEBUG=3 ./cli-log-no -vvv Hello World
logerr_level = 6
Hello World!
$ DEBUG=3 ./cli-log-no -vvv Hello
logerr_level = 6
Oops!

If you have some logging lines which are only needed for testing phase, please enclose them between a pair of macros such as #ifdef TESTERRLOG and #endif and remove them with the unifdef command.

TIP: For the serious logging, consider using syslog(3).

Shell assertion

If you know something should not happen, test it to ensure it.

The cli-assert program aborts with an error message if the first and the second arguments do not match.

Example of a shell code cli-assert with assertion.

#!/bin/sh
error ()
{
    echo "$@" >&2
    exit 1
}
FOO=$1
BAR=$2
if [ ! "$FOO" = "$BAR" ]; then
    error "E: FOO and BAR do not match."
fi
echo "Input matches: $FOO = $BAR"

Execution example with assertion for a shell code cli-assert.

$ ./cli-assert apple apple
Input matches: apple = apple
$ ./cli-assert apple orange
E: FOO and BAR do not match.

Python assertion

If you know something should not happen, test it to ensure it.

The cli-assert program aborts with an error message if the first argument is not a non-negative value.

Example of a Python code cli-assert with assertion.

#!/usr/bin/python3
def main():
    import sys
    arg = sys.argv[1]
    assert int(arg) >= 0, "argument should be positive but " + arg
    print("argument is " + arg)

if __name__ == '__main__': 
    main()

Execution example with assertion for a Python code cli-assert.

$ ./cli-assert 1
argument is 1
$ ./cli-assert -1
Traceback (most recent call last):
  File "./cli-assert", line 9, in <module>
    main()
  File "./cli-assert", line 5, in main
    assert int(arg) >= 0, "argument should be positive but " + arg
AssertionError: argument should be positive but -1

C assertion

If assertion fails, the C assert(3) macro prints an error message to standard error and terminates the program by calling abort(3).

The cli-assert.c program aborts with an error message if the first and only argument is not a non-negative value.

Example of a C code cli-assert.c with assertion.

#include <stdlib.h>
#include <stdio.h>
#include <assert.h>

int main(int argc, char **argv)
{
    int i;
    assert(argv[1] != NULL);
    assert(argv[2] == NULL);
    i = atoi(argv[1]);
    assert(i >= 0);
    if (i >= 0) {
        printf("Argument is a single non-negative value: %i\n", i);
    }
    return EXIT_SUCCESS;
}

Compile and execution example with assertion for a C code cli-assert.c.

$ gcc -Wall -o cli-assert cli-assert.c
$ ./cli-assert 1
Argument is a single non-negative value: 1
$ ./cli-assert -1
cli-assert: cli-assert.c:11: main: Assertion `i >= 0' failed.
Aborted
$ ./cli-assert
cli-assert: cli-assert.c:8: main: Assertion `argv[1] != ((void *)0)' failed.
Aborted
$ ./cli-assert 1 2
cli-assert: cli-assert.c:9: main: Assertion `argv[2] == ((void *)0)' failed.
Aborted

As for “core dumped”, please see ELF: Core dump.

TIP: Never call an expression with side effects as the argument of the C assert(3) macro if those side effects are essential. This is because the C assert(3) macro may be disabled by defining the macro NDEBUG for the production code and the argument may never be executed when it is needed.

TIP: Ian Jackson said “-DNDEBUG is (normally) Evil, Bad and Wrong. … you shouldn’t set it. Even if upstream specify it it can be right to remove it.”

You can completely remove assertion capability in compile time by defining the NDEBUG macro.

Compile and execution example without assertion for a C code cli-assert.c.

$ gcc -Wall -DNDEBUG -o cli-assert-no cli-assert.c
$ ./cli-assert-no 1
Argument is a single non-negative value: 1
$ ./cli-assert-no -1

Top

Fun to Program – Debug: level 1

Date: 2013/08/10 (initial publish), 2021/08/02 (last update)

Source: en/fun2-00010.md

TOC