ANN: liblogger

"There is no better tool to debug than printf()" -- Latin proverb from an old Chinese man.
That's what every programmer knows. Despite interesting tools like profilers, debuggers and other tracing tool, for a reason or another we often resort to good old printf(). The logic behind this is quite simple: it's available everywhere and have no impact on performace (mostly, on both cases -- don't be picky!), yet it allows you to check out if your program flow is as you expected and if not, what's happening. The bad part, of course, is that it's invasive and cumbersome to type, often introduces errors by itself (come on, raise your hand if you never ever wasted hours debugging to notice that the bug was in the debug message!) GDB and some tools like ltrace or GLibC's latrace are not always available, particularly on embededd systems they may be available but almost unusable. I hit that in the past weeks during some debugging on an old MIPS where I had to investigate why my supposedly correct program did not work, but a proprietary one did. Documentation is almost inexistent and makes you more clueless than not, thus I had to compare what we were doing differently. At first I started doing an old trick to create a shared library to be $LD_PRELOADed on my own that would log what was being called, then dlopen()/dlsym() the actual symbol, call it, then log again, then return. I did it for a handful functions, some I even printed out structure members and although it worked, soon I got bored and hit by the laziness that most programmers have: I must make this automatic. Liblogger was born. Liblogger is Python program that will parse a C header file and generate a source file that does exactly what I described above: log entrance, call the actual function and keep its return value, then log exit, then return the value. That's the basics this single-file without external dependencies do. This source file can then be compiled into a shared object or into the final application. Of course I wanted it to be as helpful as possible, so this first version already includes some nifty features:
  • source file can be compile-time configured using CPP defines to produce colored, thread-safe, timestamped (gettimeofday, clock_gettime), indented (nesting level) output. This output can go to stderr or some given file;
  • generates makefile for you, creating most of aforementioned variations by default. Just pick the one you want to use and LD_PRELOAD it;
  • generate types file with all parsed enums, structs, unions and typedefs;
  • generate formatters file with custom functions to print out known enums, structs and unions. No more copy + sed on the original structs to produce printf() statements manually!
  • will keep errno intact so functions that rely on it will work as it will not be reset by fprintf() calls;
  • can be compiled in a thread-safe way, doing locks around dlopen(), dlsym() and the log FILE* to keep messages atomic. It will also keep the indentation level per-thread and print out thread ids (if not main thread);
  • Behavior is completely controlled with a INI-style configuration file. It can (check for more at README.txt):
    • tell the parser tokens to ignore;
    • filter (positively/negatively) functions to log;
    • specify type formatters you want to use. Couple are provided for basic C types, and you can request it to generate custom formatters for parsed types as mentioned above;
    • specify return value checkers you want to use. Couple are provided, including one that checks for errno and logs the value as a string;
    • if types of parameters and return are safe to be used by formatters, this can be used at various levels to provide black-white lists for these and keep it useful and safe;
    • special handling of return (output) parameters, their values can be dereferenced and printed out after the actual function is called;
Usage should be pretty straightforward but I distribute two examples, one for dbus and another for jpeglib. Part of the dbus example is reproduced below:
  • dbus.cfg
    [global]
    headers = dbus/dbus.h
    overrides = formatters-%(header_name)s.c
    # regular expression for all defines in dbus-macros.h
    ignore-tokens-regexp = (DBUS_MACROS_H|DBUS_BEGIN_DECLS|DBUS_END_DECLS|DBUS_BEGIN_DECLS|DBUS_END_DECLS|DBUS_DEPRECATED|DBUS_DEPRECATED|DBUS_DEPRECATED|DBUS_EXPORT|DBUS_EXPORT|DBUS_EXPORT|DBUS_EXPORT)
    
    [type-formatters]
    DBusHandleMessageFunction = %(prefix)s_log_fmt_pointer
    DBusFreeFunction = %(prefix)s_log_fmt_pointer
    DBusHandleMessageFunction = %(prefix)s_log_fmt_pointer
    
    [safe-formatters]
    DBusHandleMessageFunction = true
    DBusFreeFunction = true
    DBusHandleMessageFunction = true
    
    # be pedantic about safety, let's specify all strings independently
    
    [func-dbus_message_new_method_call]
    parameter-bus_name-safe = true
    parameter-path-safe = true
    parameter-interface-safe = true
    parameter-method-safe = true
    
  • call:
    liblogger.py \
        --config dbus.cfg \
        --makefile Makefile.dbus-connection \
        --makefile-cflags "\`pkg-config --cflags dbus-1\` -I." \
        --custom-formatters formatters-connection.c \
        /usr/include/dbus-1.0/dbus/dbus-connection.h \
        libdbus-1.so \
        log-dbus-connection.c
    make -f Makefile.dbus-connection
    LD_PRELOAD=./log-dbus-connection-color-timestamp.so d-feet