Guidelines and HOWTOs/Debugging/Using Error Messages: Difference between revisions

From KDE Community Wiki
*>Pippin
No edit summary
(Separate "how to turn on logging in someone's code" from "how to add logging to my code".)
(12 intermediate revisions by 8 users not shown)
Line 1: Line 1:
= Qt 4 / kdelibs 4 =
= Qt 5 / KDE Frameworks 5 =
 
<tt>kDebug()</tt> and friends have been deprecated in KDE Frameworks 5, and you should use Qt's built-in debugging instead.  We recommend that you use [https://doc.qt.io/qt-5/qloggingcategory.html QLoggingCategory], particularly for libraries and plugins.  Note that this is only available in Qt 5.2 and later.
 
== Controlling Messages ==
The source code for a library, plugin, or program named "Foo" may contain statements like
<syntaxhighlight lang="cpp-qt">
qCDebug(LOG_FOO) << "Log something:" << someVariable;
</syntaxhighlight>
Here, <tt>LOG_FOO</tt> is a ''logging category''.  If debug-level messages have been enabled for that logging category, then the statement will write a message to <tt>stderr</tt>.
 
Some source file will define the logging category:
<syntaxhighlight lang="cpp-qt">
Q_LOGGING_CATEGORY(LOG_FOO, "some.namespace.foo")
</syntaxhighlight>
Here, <tt>"some.namespace.foo"</tt> is the ''category name''.  Once you know the category's name, you can
set the <tt>QT_LOGGING_RULES</tt> environment variable to enable debug-level messages for the category:
<syntaxhighlight lang="bash">
QT_LOGGING_RULES="some.namespace.foo.debug=true"
</syntaxhighlight>
 
Logging rules can be more complex than the example above.  They can specify wildcards in the category name, enable or disable more than one message level, and control more than one logging category.
They can also be stored in various configuration files.  Please see the QLoggingCategory documentation for details.
 
If you run the application from within a terminal application, like [http://www.kde.org/applications/system/konsole/ Konsole], you will see the logging output in that terminal window.  If you use an Integrated Development Environment like [https://kde.org/applications/en/development/org.kde.kdevelop KDevelop] it will display the output in its windows.  Otherwise, the messages will usually appear in {{path|~/.xsession-errors}} or {{path|~/.X.err}} if you use a login manager like KDM, or on the console you ran <tt>startx</tt> from if you started X that way. Also check the systemd log, since the application could be its direct child process.
 
== Adding Logging to Your Code ==
For a library or plugin called "Foo", you should have a common header that contains the following declaration  (e.g. called "foo-debug.h")
<syntaxhighlight lang="cpp-qt">
#include <QLoggingCategory>
Q_DECLARE_LOGGING_CATEGORY(LOG_FOO)
</syntaxhighlight> and exactly one source file containing <syntaxhighlight lang="cpp-qt">
#include "foo-debug.h"
Q_LOGGING_CATEGORY(LOG_FOO, "some.namespace.foo")
</syntaxhighlight>
 
You should treat the category name (<tt>"some.namespace.foo"</tt> in the example) as something like reverse DNS; it cannot contain spaces, and dots indicate a hierarchy.  For example, KDE PIM category names all start with <tt>"org.kde.pim."</tt>.


When you start a konsole and type the commands to start an application you
To simplify the setup, you can use the ECM macro <tt>[https://api.kde.org/ecm/module/ECMQtDeclareLoggingCategory.html ecm_qt_declare_logging_category]</tt>, which generates the respective source files for you:
will see all sorts of statements are printed in the konsole while the
<syntaxhighlight lang="cmake">
application is running. All applications print these messages, to look
include(ECMQtDeclareLoggingCategory)
at them you have to know where to look. The application will have to be
ecm_qt_declare_logging_category(FOO_SRCS
compiled with the debugging enabled. So using a precompiled package from a distribution
    HEADER foo-debug.h
probably will not give you this information. If you compiled the application
    IDENTIFIER "LOG_FOO"
yourself, make sure the configure option <tt>--disable-debug</tt> was not used.
    CATEGORY_NAME "some.namespace.foo"
)
</syntaxhighlight>


In KDE all debugging text-output can be switched on or off based on so
Logging lines then look like <syntaxhighlight lang="cpp-qt">
called '''areas'''. One application can be one or more area. One part of the kde base libraries can be another area. Enabling/disabling these areas from being printed can be done using the '''kdebugdialog''' application. For simple debugging selecting all
#include "foo-debug.hpp"
sections is probably wise.
qCDebug(LOG_FOO) << "Log something:" << someVariable;
qCWarning(LOG_FOO) << "Something bad happened that users (end-users, or application developers using this library) should be aware of";
qCCritical(LOG_FOO) << "Something happened so bad we had to terminate the application";
</syntaxhighlight>


When you are debugging it is best to simply start a konsole and start the
The syntax is much like <tt>cout</tt>, and most native C++ types, Qt-provided types and KF-provided types can be passed directly (like with <tt>someVariable</tt> in the example).
application from there. In a konsole you could simply type:
<pre>
kicker
</pre>
and in the konsole kicker could return a message like:
<pre>
ERROR: kicker is already running!
</pre>
When a lot of output is written to the konsole it might go out of view before
you could read it, therefor it is easy to create a text file which contains
all this information, to do so type the following:
<pre>
application 2&gt;&amp;1 | tee debug.log
</pre>
where 'application' can be replaced with the application you are debugging.
Afterwards you could open the file 'debug.log' to look at the messages again.


If you are NOT starting the application from a konsole the messages will be
With Qt 5.2, the <tt>qCDebug</tt> line will not produce any output; this is because logging categories are disabled by default.  You need to include the line <syntaxhighlight lang="cpp-qt">
logged somewhere else, or they could have been discarded by the program that
QLoggingCategory::setFilterRules(QStringLiteral("foo.debug = true"));
started your application.
</syntaxhighlight>
somewhere in the application code, generally in the <tt>main()</tt> function.  Of course, you would typically disable this call in release versions.


If your application is started by clicking on an icon your best bet is to check
== Improving Logging Output ==
the following log files. Beware; they contain logs for a lot of applications,
not just the application you are debugging!


'''Case 1: Graphical login (i.e. kdm, gdm, xdm, etc.)'''
Qt provides a way of controlling the output of the logging methods via an environment variable. You can tell it to include the application name and PID, as well as the debugging category, and color-code the text.  For example, running the following lines in your shell will produce something that looks quite like <tt>kDebug</tt>'s colored output: <syntaxhighlight lang="bash">
c=`echo -e "\033"`
export QT_MESSAGE_PATTERN="%{appname}(%{pid})/(%{category}) $c\[31m%{if-debug}$c\[34m%{endif}%{function}$c\[0m: %{message}"
unset c
</syntaxhighlight>


The debug messages get redirected into the file {{path|~/.xsession-errors}} or
== Managing Lots of Output ==
{{path|~/.X.err}} in your home directory (that is with a leading dot '.' also
watch the Capital).


'''Case 2: You are using startx:'''
If you have lots of debugging statements, they may appear too fast and leave the terminal window before you can read them.  There are three main ways to deal with this:
# [https://doc.qt.io/qt-5/qloggingcategory.html#setFilterRules Disable some logging categories] to limit the amount of output generated
# Increase the amount of scrollback in the terminal so that output is not lost; in Konsole, you can go to <tt>Settings > Edit Current Profile...</tt> and click on the <tt>Scrollback</tt> tab to change this.  Konsole also has a useful search feature: just press <tt>Ctrl+Shift+F</tt> or click <tt>Find...</tt> on the <tt>Edit</tt> menu.
# Save the output to a file; <tt>tee</tt> is useful for this.  For example, you can run <syntaxhighlight lang="bash">application 2>&1 | tee debug.log</syntaxhighlight> to save the output to the file <tt>debug.log</tt> while still viewing it in the terminal.


Use the following command to restart your session:
= Qt 4 / kdelibs 4 =
startx 2&gt;&amp;1 | tee startx.log


so that all the debug messages of applications started at KDE's startup (and
kdelibs provides a [http://api.kde.org/4.0-api/kdelibs-apidocs/kdecore/html/group__kdebug.html family of functions] that output information to <tt>stderr</tt>, meaning that if you run an application from the terminal, it will be displayed in that terminal window.  If you run the application from the desktop (using KRunner or the application menu, for example), the output will normally appear in {{path|~/.xsession-errors}} or {{path|~/.X.err}} if you use a login manager like KDM, or on the console you ran <tt>startx</tt> from if you started X that way.
any application launched from the panel etc.) go to the file "startx.log"


== Links ==
To use these functions in your code, you need to include the correct header file <syntaxhighlight lang="cpp-qt">
#include <KDebug>
</syntaxhighlight>
and then you can use the functions <syntaxhighlight lang="cpp-qt">
kDebug() << "Something happened that only developers care about" << someVariable;
kWarning() << "Something bad happened that users (end-users, or application developers using this library) should be aware of";
kError() << "Something even worse happened";
kFatal() << "Something happened so bad we had to terminate the application";
</syntaxhighlight>


The debug messages are usually printed in C++ with the kDebug or kWarning statement. Example:
The syntax is much like <tt>cout</tt>, and most native C++ types, Qt-provided types and kdelibs-provided types can be passed directly (like with <tt>someVariable</tt> in the example).
<pre>
kDebug(1210) << "arbitrary message";
kWarning(1210) << "this rather should not happen";
</pre>
The number 1210 (so called ''debug area'') in this case represents kicker.  You can omit the number.


See also: [http://api.kde.org/4.0-api/kdelibs-apidocs/kdecore/html/group__kdebug.html kDebug/kWarning API documentation] and [http://websvn.kde.org/trunk/KDE/kdelibs/kdecore/kdebug.areas?view=markup kdebug.areas] for list of debug areas numbers.
Note that the <tt>kDebug</tt> calls will only do anything if the code was compiled with debugging enabled (and so will generally not work in packages from a distribution). This means <tt>cmake</tt> should be run with the <tt>-DCMAKE_BUILD_TYPE=debugfull</tt> argument. The other functions, however, will produce output no matter how the code was compiled.
Note that you can use ''add_definition(-DKDE_DEFAULT_DEBUG_AREA=<number>)'' in CMakeLists.txt to specify default debug area.


= Qt 5 / KDE Frameworks 5 =
== Debug Areas ==


<tt>kDebug()</tt> and friends have been deprecated in KDE Frameworks 5, and you should use Qt's built-in debugging instead. We recommend that you use [http://doc-snapshot.qt-project.org/qt5-stable/qloggingcategory.html QLoggingCategory], particularly for libraries and plugins.  Note that this is only available in Qt 5.2 and later.
The debugging output can be controlled at runtime using debugging areas.  This allows enabling debugging output for only certain libraries or plugins, for example.  Debugging areas are numbers, so the <tt>KStatusNotifierItemPrivate::registerToDaemon</tt> method in the kdeui library, for example, has the call <syntaxhighlight lang="cpp-qt">
  kDebug(299) << "Registering a client interface to the KStatusNotifierWatcher";
</syntaxhighlight>
The file <tt>kdebug.areas</tt> in the <tt>kdecore</tt> directory of kdelibs indicates that the number 299 is associated with "kdeui (KNotification)".


In particular, for a library or plugin called "Foo", you should have a common header that contains the following declaration
This information is used by the <tt>kdebugdialog</tt> utility (which you can just run from the commandline or using KRunner) to turn these areas on and off, enabling or disabling those <tt>kDebug</tt> statements.  It is also used by <tt>kDebug</tt>, <tt>kWarning</tt>, <tt>kError</tt> and <tt>kFatal</tt> to indicate which component output the line. For example, the line in the above example would produce the line <pre>kwalletmanager(642)/kdeui (KNotification) KStatusNotifierItemPrivate::registerToDaemon: Registering a client interface to the KStatusNotifierWatcher</pre>
  #include <QLoggingCategory>
when executed from within the application kwalletmanager, with PID 642.
Q_DECLARE_LOGGING_CATEGORY(LOG_FOO)
and exactly one source file containing
Q_LOGGING_CATEGORY(LOG_FOO, "foo")


You should treat the string as something like reverse DNS; it cannot contain spaces, and dots indicate a heirarchyFor example, a Plasma dataengine called "Foo" might use the category <tt>"plasma.engine.foo"</tt>.
For applications, you can generally just omit the area number, and <tt>kDebug</tt> will use the default areaIf you are developing a library or a plugin, though, you should get a number assigned (via the kde-core-devel mailing list) for your library or plugin, and use it in your code.  Rather than using the number directly in every call to <tt>kDebug</tt> and friends, you can just add<syntaxhighlight lang="cmake">
add_definition(-DKDE_DEFAULT_DEBUG_AREA=<number>)
</syntaxhighlight>
to your <tt>CMakeLists.txt</tt> file.


Logging lines then look like
== Improving Log Output ==
qCDebug(LOG_FOO) << "Log something:" << stuff();
qCWarning(LOG_FOO) << "Something bad happened that users (end-users, or application developers using this library) should be aware of";
qCCritical(LOG_FOO) << "Something happened so bad we had to terminate the application";


With Qt 5.2, the <tt>qCDebug</tt> line will not produce any output; this is because logging categories are disabled by defaultYou need to include the line
There are a couple of useful environment variables to control the output of <tt>kDebug</tt> and friends<syntaxhighlight lang="bash">
QLoggingCategory::setFilterRules(QStringLiteral("foo.debug = true"));
export KDE_COLOR_DEBUG=1
somewhere in the application code, generally in the <tt>main()</tt> function.  Of course, you would typically disable this call in release versionsQt 5.3 will hopefully include a way to change this configuration externally, without recompiling.
</syntaxhighlight> will make them produce colored output, and <syntaxhighlight lang="bash">
export KDE_DEBUG_TIMESTAMP=1
</syntaxhighlight> will include timestamps in the output<syntaxhighlight lang="bash">
export KDE_DEBUG_TIMESTAMP=2
</syntaxhighlight> can be used to include milliseconds in the timestamps.


If you run your application from within a terminal application, like [http://www.kde.org/applications/system/konsole/ Konsole], you will see the logging output in that terminal window.  Otherwise, it will usually appear in <tt>~/.xsession-errors</tt>.


== Improving Logging Output ==


Qt provides a way of controlling the output of the logging methods via an environment variable.  You can tell it to include the application name and PID, as well as the debugging category, and color-code the text.  For example, running the following lines in your shell will produce something that looks quite like <tt>kDebug</tt>'s colored output:
<syntaxhighlight lang="bash">
c=`echo -e "\033"`
export KDE_DEBUG_NOPROCESSINFO=1
export QT_MESSAGE_PATTERN="%{appname}(%{pid})/(%{category}) $c\[31m%{if-debug}$c\[34m%{endif}%{function}$c\[0m: %{message}"
export KDE_DEBUG_NOAREANAME=1
unset c
export KDE_DEBUG_NOMETHODNAME=1
export KDE_DEBUG_FILELINE=1
</syntaxhighlight>The above commands toggle various components of the debug messages.


== Managing Lots of Output ==
== Managing Lots of Output ==


If you have lots of debugging statements, they may appear too fast and leave the terminal window before you can read them.  There are three main ways to deal with this:
If you have lots of debugging statements, they may appear too fast and leave the terminal window before you can read them.  There are three main ways to deal with this:
# [http://doc-snapshot.qt-project.org/qt5-stable/qloggingcategory.html#setFilterRules Disable some logging categories] to limit the amount of output generated
# Use <tt>kdebugdialog</tt> to disable some logging areas to limit the amount of output generated
# Increase the amount of scrollback in the terminal so that output is not lost; in Konsole, you can go to <tt>Settings > Edit Current Profile...</tt> and click on the <tt>Scrollback</tt> tab to change this.  Konsole also has a useful search feature: just press <tt>Ctrl+Shift+F</tt> or click <tt>Find...</tt> on the <tt>Edit</tt> menu.
# Increase the amount of scrollback in the terminal so that output is not lost; in Konsole, you can go to <tt>Settings > Edit Current Profile...</tt> and click on the <tt>Scrollback</tt> tab to change this.  Konsole also has a useful search feature: just press <tt>Ctrl+Shift+F</tt> or click <tt>Find...</tt> on the <tt>Edit</tt> menu.
# Save the output to a file; <tt>tee</tt> is useful for this.  For example, you can run <pre>application 2&gt;&amp;1 | tee debug.log</pre> to save the output to the file <tt>debug.log</tt> while still viewing it in the terminal.
# Save the output to a file; <tt>tee</tt> is useful for this.  For example, you can run <pre>application 2&gt;&amp;1 | tee debug.log</pre> to save the output to the file <tt>debug.log</tt> while still viewing it in the terminal.  This can also be used to capture output from <tt>startx</tt>.

Revision as of 19:47, 7 September 2020

Qt 5 / KDE Frameworks 5

kDebug() and friends have been deprecated in KDE Frameworks 5, and you should use Qt's built-in debugging instead. We recommend that you use QLoggingCategory, particularly for libraries and plugins. Note that this is only available in Qt 5.2 and later.

Controlling Messages

The source code for a library, plugin, or program named "Foo" may contain statements like

qCDebug(LOG_FOO) << "Log something:" << someVariable;

Here, LOG_FOO is a logging category. If debug-level messages have been enabled for that logging category, then the statement will write a message to stderr.

Some source file will define the logging category:

Q_LOGGING_CATEGORY(LOG_FOO, "some.namespace.foo")

Here, "some.namespace.foo" is the category name. Once you know the category's name, you can set the QT_LOGGING_RULES environment variable to enable debug-level messages for the category:

QT_LOGGING_RULES="some.namespace.foo.debug=true"

Logging rules can be more complex than the example above. They can specify wildcards in the category name, enable or disable more than one message level, and control more than one logging category. They can also be stored in various configuration files. Please see the QLoggingCategory documentation for details.

If you run the application from within a terminal application, like Konsole, you will see the logging output in that terminal window. If you use an Integrated Development Environment like KDevelop it will display the output in its windows. Otherwise, the messages will usually appear in ~/.xsession-errors or ~/.X.err if you use a login manager like KDM, or on the console you ran startx from if you started X that way. Also check the systemd log, since the application could be its direct child process.

Adding Logging to Your Code

For a library or plugin called "Foo", you should have a common header that contains the following declaration (e.g. called "foo-debug.h")

#include <QLoggingCategory>
Q_DECLARE_LOGGING_CATEGORY(LOG_FOO)

and exactly one source file containing

#include "foo-debug.h"
Q_LOGGING_CATEGORY(LOG_FOO, "some.namespace.foo")

You should treat the category name ("some.namespace.foo" in the example) as something like reverse DNS; it cannot contain spaces, and dots indicate a hierarchy. For example, KDE PIM category names all start with "org.kde.pim.".

To simplify the setup, you can use the ECM macro ecm_qt_declare_logging_category, which generates the respective source files for you:

include(ECMQtDeclareLoggingCategory)
ecm_qt_declare_logging_category(FOO_SRCS
    HEADER foo-debug.h
    IDENTIFIER "LOG_FOO"
    CATEGORY_NAME "some.namespace.foo"
)

Logging lines then look like

#include "foo-debug.hpp"
qCDebug(LOG_FOO) << "Log something:" << someVariable;
qCWarning(LOG_FOO) << "Something bad happened that users (end-users, or application developers using this library) should be aware of";
qCCritical(LOG_FOO) << "Something happened so bad we had to terminate the application";

The syntax is much like cout, and most native C++ types, Qt-provided types and KF-provided types can be passed directly (like with someVariable in the example).

With Qt 5.2, the qCDebug line will not produce any output; this is because logging categories are disabled by default. You need to include the line

QLoggingCategory::setFilterRules(QStringLiteral("foo.debug = true"));

somewhere in the application code, generally in the main() function. Of course, you would typically disable this call in release versions.

Improving Logging Output

Qt provides a way of controlling the output of the logging methods via an environment variable. You can tell it to include the application name and PID, as well as the debugging category, and color-code the text. For example, running the following lines in your shell will produce something that looks quite like kDebug's colored output:

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

Managing Lots of Output

If you have lots of debugging statements, they may appear too fast and leave the terminal window before you can read them. There are three main ways to deal with this:

  1. Disable some logging categories to limit the amount of output generated
  2. Increase the amount of scrollback in the terminal so that output is not lost; in Konsole, you can go to Settings > Edit Current Profile... and click on the Scrollback tab to change this. Konsole also has a useful search feature: just press Ctrl+Shift+F or click Find... on the Edit menu.
  3. Save the output to a file; tee is useful for this. For example, you can run
    application 2>&1 | tee debug.log
    
    to save the output to the file debug.log while still viewing it in the terminal.

Qt 4 / kdelibs 4

kdelibs provides a family of functions that output information to stderr, meaning that if you run an application from the terminal, it will be displayed in that terminal window. If you run the application from the desktop (using KRunner or the application menu, for example), the output will normally appear in ~/.xsession-errors or ~/.X.err if you use a login manager like KDM, or on the console you ran startx from if you started X that way.

To use these functions in your code, you need to include the correct header file

#include <KDebug>

and then you can use the functions

kDebug() << "Something happened that only developers care about" << someVariable;
kWarning() << "Something bad happened that users (end-users, or application developers using this library) should be aware of";
kError() << "Something even worse happened";
kFatal() << "Something happened so bad we had to terminate the application";

The syntax is much like cout, and most native C++ types, Qt-provided types and kdelibs-provided types can be passed directly (like with someVariable in the example).

Note that the kDebug calls will only do anything if the code was compiled with debugging enabled (and so will generally not work in packages from a distribution). This means cmake should be run with the -DCMAKE_BUILD_TYPE=debugfull argument. The other functions, however, will produce output no matter how the code was compiled.

Debug Areas

The debugging output can be controlled at runtime using debugging areas. This allows enabling debugging output for only certain libraries or plugins, for example. Debugging areas are numbers, so the KStatusNotifierItemPrivate::registerToDaemon method in the kdeui library, for example, has the call

 kDebug(299) << "Registering a client interface to the KStatusNotifierWatcher";

The file kdebug.areas in the kdecore directory of kdelibs indicates that the number 299 is associated with "kdeui (KNotification)".

This information is used by the kdebugdialog utility (which you can just run from the commandline or using KRunner) to turn these areas on and off, enabling or disabling those kDebug statements. It is also used by kDebug, kWarning, kError and kFatal to indicate which component output the line. For example, the line in the above example would produce the line

kwalletmanager(642)/kdeui (KNotification) KStatusNotifierItemPrivate::registerToDaemon: Registering a client interface to the KStatusNotifierWatcher

when executed from within the application kwalletmanager, with PID 642.

For applications, you can generally just omit the area number, and kDebug will use the default area. If you are developing a library or a plugin, though, you should get a number assigned (via the kde-core-devel mailing list) for your library or plugin, and use it in your code. Rather than using the number directly in every call to kDebug and friends, you can just add

add_definition(-DKDE_DEFAULT_DEBUG_AREA=<number>)

to your CMakeLists.txt file.

Improving Log Output

There are a couple of useful environment variables to control the output of kDebug and friends.

export KDE_COLOR_DEBUG=1

will make them produce colored output, and

export KDE_DEBUG_TIMESTAMP=1

will include timestamps in the output.

export KDE_DEBUG_TIMESTAMP=2

can be used to include milliseconds in the timestamps.


export KDE_DEBUG_NOPROCESSINFO=1
export KDE_DEBUG_NOAREANAME=1
export KDE_DEBUG_NOMETHODNAME=1
export KDE_DEBUG_FILELINE=1

The above commands toggle various components of the debug messages.

Managing Lots of Output

If you have lots of debugging statements, they may appear too fast and leave the terminal window before you can read them. There are three main ways to deal with this:

  1. Use kdebugdialog to disable some logging areas to limit the amount of output generated
  2. Increase the amount of scrollback in the terminal so that output is not lost; in Konsole, you can go to Settings > Edit Current Profile... and click on the Scrollback tab to change this. Konsole also has a useful search feature: just press Ctrl+Shift+F or click Find... on the Edit menu.
  3. Save the output to a file; tee is useful for this. For example, you can run
    application 2>&1 | tee debug.log
    to save the output to the file debug.log while still viewing it in the terminal. This can also be used to capture output from startx.