Nicer debug output in Qt using QT_MESSAGE_PATTERN

If you are using Qt, you might have some qDebug or qWarning statements in your code.
But did you know that you can greatly improve the output of those with the QT_MESSAGE_PATTERN environment variable?
This blog post will give you some hints and examples of what you can do.

The default message pattern just prints the message (and the category if one was specified), but qDebug
has the possibility to output more information.
You can display cool things like the line of code, the function name or more by using some placeholders in the pattern.

QT_MESSAGE_PATTERN="%{message}"

Some example of placeholder:

%{file} and %{line} are the location of the qDebug statement (file and line number)

%{function} just shows the function name. Contrary to the Q_FUNC_INFO, which is really the raw
function name, this shows a short prettier version of the function name without the arguments or not so useful decorators

%{time [format]} shows the time, at which the debug statement is emitted. Using the format you can show the
time since the process startup, or an absolute time, with or without the date. Having the milliseconds in the debug output is helpful
to get timing information about your code

%{threadid}, %{pid}, %{appname} are useful
if the logs are mixed between severals application, or to find out from which thread something is run.

That example will print the function in blue, and then the message in the normal color

Conditions

KDE's kDebug has colored debug output support since KDE 4.0
(it is enabled by setting the KDE_COLOR_DEBUG environment variable).
It printed the function name in blue for normal debug messages, and in red for warnings or critical messages.
I wanted the same in Qt, so some placeholders were added to have an output that depends on the type of message.

The content of what is between %{if-debug} and %{endif} will only be used for qDebug statements but not for qWarning.
Similarly, we have %{if-warning} and %{if-critical}. There is also %{if-category}
that will only be displayed if there is a category associated with this message.

Backtrace (linux-only)

On Linux, it is possible to show a short backtrace for every debug output.

Use the %{backtrace} placeholder, which can be configured to show more or less call frames.

In order for Qt to be able to determine the backtrace, it needs to find the symbol names from the symbol table.
By default, this is only going to display exported functions within a library. But you can tell the linker to include
this information for every function. So if you wish to use this feature, you need
to link your code with the -rdynamic option.

Add this in your .pro file if you are using qmake:

QMAKE_LFLAGS += -rdynamic

Remember while reading this backtrace that symbols might be optimized away by the compiler. That is the case for inline functions, or functions
with the tail-call optimization
See man backtrace.

Examples of patterns

And now, here are a few ready to use patterns that you can put in your /etc/profile, ~/.bashrc, ~/.zshrc
or wherever you store your shell configuration.

Note that since Qt 5.4, the information about the function name of the file location is only available if
your code is compiled in debug mode or if you define QT_MESSAGELOGCONTEXT in your compiler flags.
For this reason %{backtrace depth=1} might be more accurate than %{function}

Don't hesitate to post your own favorite pattern in the comments.

Final words

The logging system has become quite powerful in Qt5. You can have categories and hooks. I invite you to read
the documentation for more
information about the debugging option that are at your disposal while using Qt.

Woboq is a software company that specializes in development and consulting around Qt and C++. Hire us!