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.
  • And you can find even more placeholders in the documentation.

Colorize it!

In order to make the output much prettier and easier to read, you can add some color by the mean of terminal escape sequences

Putting the escape sequence in an environment variable might be a bit tricky. The trick I use which work with bash or zsh, is to use echo -e in single back quotes.

export QT_MESSAGE_PATTERN="`echo -e "\033[34m%{function}\033[0m: %{message}"`"

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.

KDE4 style:
export QT_MESSAGE_PATTERN="`echo -e "%{appname}(%{pid})/(%{category}) \033\[31m%{if-debug}\033\[34m%{endif}%{function}\033\[0m: %{message}"`"

Time in green; blue Function name for debug; red 3-frames backtrace for warnings. Category in yellow in present:
export QT_MESSAGE_PATTERN="`echo -e "\033[32m%{time h:mm:ss.zzz}%{if-category}\033[32m %{category}:%{endif} %{if-debug}\033[34m%{function}%{endif}%{if-warning}\033[31m%{backtrace depth=3}%{endif}%{if-critical}\033[31m%{backtrace depth=3}%{endif}%{if-fatal}\033[31m%{backtrace depth=3}%{endif}\033[0m %{message}"`"

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!

If you like this blog and want to read similar articles, consider subscribing via our RSS feed, by e-mail or follow us on twitter or add us on G+.

Submit on reddit Submit on reddit Tweet about it Share on Facebook Post on Google+

Article posted by Olivier Goffart on 19 February 2015

Get notified when we post a new interesting article!

© 2016 Woboq GmbH