[Development] Proposal: Changing the default output of qDebug and friends

[k***@nokia.com]

Hi there,

In Qt 4 qDebug, qWarning etc just printed whatever was passed in. In Qt 5 we've been changing this (1) so that you can configure Qt to print additional information by setting the QT_MESSAGE_PATTERN environment variable. However, we didn't change the default so far - so without setting QT_MESSAGE_PATTERN we still just print the message. I just had a discussion (2) with Thiago Macieira and David Faure where we agreed that we'd like to still change this for Qt 5.0 ...

My personal motivation is that if e.g. the type would be always part of the message Qt Creator could use this information to colorize/filter output. Adding the app name / PID would identify the app in case of system logs, adding the function would give you a clue where on earth you added this one debug statement just printing "true" ;) So, what do you think about changing the default format to e.g.

"[%{type}] %{appname}(%{pid}) %{function} %{message}"

Example output:

[warning] QtCreator(16693) QtSupport::BaseQtVersion::qtVersionString - Cannot determine the Qt version: /home/kkoehne/dev/qt/test/bin/qmake cannot be run.

or

[warning] QtQmlViewer(16790) unknown - file:///home/kkoehne/dev/qt/qt-5/qtdeclarative/examples/tutorials/gettingStartedQml/texteditor.qml:52:5: Type MenuBar unavailable

Regards

Kai


PS:

[Lincoln Ramsay]

[Lincoln Ramsay]

Why can't Creator just set the QT_MESSAGE_PATTERN environment variable
then and leave the default alone? Creator would not need to show the
filename and line number, just use them for when you click on the warnings.

And related to this...

If we're going to have warnings that result in click-to-locate then we
really need to find a way of doing perl-style carp (ie. warning from the
caller's context).

I think that both Windows and Glibc have a facility that may allow this
to be done but getting something truly cross-platform may not be possible.


The QList.at() assertion has always struck me as totally useless because
unless you've got a debugger attached you aren't told (and thus cannot
find out) _where_ the code that triggered the assertion is. The ability
to warn from the caller's perspective would make this assertion so much
more useful.

[Olivier Goffart]

Post by Lincoln Ramsay

Why can't Creator just set the QT_MESSAGE_PATTERN environment variable
then and leave the default alone? Creator would not need to show the
filename and line number, just use them for when you click on the warnings.

I think I agree with that. Creator can put whatever is needed for better
experience. We don't need yo change the default.

Post by Lincoln Ramsay
And related to this...
If we're going to have warnings that result in click-to-locate then we
really need to find a way of doing perl-style carp (ie. warning from the
caller's context).
I think that both Windows and Glibc have a facility that may allow this
to be done but getting something truly cross-platform may not be possible.
The QList.at() assertion has always struck me as totally useless because
unless you've got a debugger attached you aren't told (and thus cannot
find out) _where_ the code that triggered the assertion is. The ability
to warn from the caller's perspective would make this assertion so much
more useful.

...

That would be possible with runtime backtrace (#include <execinfo.h>
backtrace(), on Linux)
So one could add some tokens in QT_MESSAGE_PATTERN to get the backtrace.
The problem is that runtime backtrace is often not really accurate.

[Lincoln Ramsay]

That would be possible with runtime backtrace (#include<execinfo.h>
backtrace(), on Linux)
So one could add some tokens in QT_MESSAGE_PATTERN to get the backtrace.
The problem is that runtime backtrace is often not really accurate.

Getting a whole backtrace is another problem entirely. I'd just like to
see the caller's filename and line number used when a function is trying
to warn you that someone has used it incorrectly.

And yeah... optimized binaries make it difficult for this to work 100%
while it's an add-on to the language :(

[Olivier Goffart]

Post by Lincoln Ramsay

That would be possible with runtime backtrace (#include<execinfo.h>
backtrace(), on Linux)
So one could add some tokens in QT_MESSAGE_PATTERN to get the backtrace.
The problem is that runtime backtrace is often not really accurate.

Getting a whole backtrace is another problem entirely. I'd just like to
see the caller's filename and line number used when a function is trying
to warn you that someone has used it incorrectly.

Ant the only way to do it is to get a backtrace.

But you could specify, in the pattern, the number of stack frame you want. (I
suppose two would already be enough in most cases.

Post by Lincoln Ramsay
And yeah... optimized binaries make it difficult for this to work 100%
while it's an add-on to the language :(

[k***@nokia.com]

-----Original Message-----
Behalf Of Ramsay Lincoln (Nokia-MP/Brisbane)
Sent: Thursday, March 29, 2012 1:42 AM
Subject: Re: [Development] Proposal: Changing the default output of
qDebug and friends

[Lincoln Ramsay]

Why can't Creator just set the QT_MESSAGE_PATTERN environment
variable then and leave the default alone? Creator would not need
to show the filename and line number, just use them for when you
click on the warnings.

You're right, that's actually what I intend do for apps started from
within Qt Creator, and which is why I don't suggest including
%{file}, %{line} in the default pattern.

My bad. I thought you were suggesting them in the default :)

Anyhow: Is the current default of printing just the message really
the optimal one?

Possibly not. I suspect though that turning on all the options by
default will prove frustrating for many use cases.

Lets define some shall we?

Running an app with warnings/debugs that does to the "system output". On
Linux, this is ~/.xsession-errors and here, app+pid would be useful. On
Windows this is the debug log... I can't remember if it includes app+pid
already or not. On Mac this is Console.app and this already includes
app+pid.

Running multiple apps with all output put into a single log file (say,
on an embedded system that doesn't use syslog) the app+pid would be useful.

Running an app from the command line, you don't need app+pid because
you're only looking at one app's output.

It seems to me that app+pid may not be so useful by default.

But I guess having the type (avoiding redundant warning/error), function
(avoiding Q_FUNC_INFO) and message should be ok as long as it doesn't
bloat message length too much...

[k***@nokia.com]

-----Original Message-----
From: Ramsay Lincoln (Nokia-MP/Brisbane)
Sent: Thursday, March 29, 2012 9:20 AM
To: Koehne Kai (Nokia-MP/Berlin)
Subject: Re: [Development] Proposal: Changing the default output of
qDebug and friends

Why can't Creator just set the QT_MESSAGE_PATTERN environment
variable then and leave the default alone? Creator would not need to
show the filename and line number, just use them for when you click
on the warnings.

You're right, that's actually what I intend do for apps started from
within Qt Creator, and which is why I don't suggest including %{file},
%{line} in the default pattern.

My bad. I thought you were suggesting them in the default :)

Anyhow: Is the current default of printing just the message really the
optimal one?

Possibly not. I suspect though that turning on all the options by default will
prove frustrating for many use cases.
Lets define some shall we?
Running an app with warnings/debugs that does to the "system output". On
Linux, this is ~/.xsession-errors and here, app+pid would be useful. On
Windows this is the debug log... I can't remember if it includes app+pid
already or not. On Mac this is Console.app and this already includes
app+pid.
Running multiple apps with all output put into a single log file (say, on an
embedded system that doesn't use syslog) the app+pid would be useful.
Running an app from the command line, you don't need app+pid because
you're only looking at one app's output.
It seems to me that app+pid may not be so useful by default.
But I guess having the type (avoiding redundant warning/error), function
(avoiding Q_FUNC_INFO) and message should be ok as long as it doesn't
bloat message length too much...

...

For my original proposal I took inspiration from the KDE debug output. Anyhow, I agree that the application name / pid just adds noise if you launched your app yourself from the shell.

So, about "[%{type}] %{function} - %{message}" then?

Any other opinions? Olivier, do you think that's sensible?

Regards

Kai

--
Lincoln Ramsay - Senior Software Engineer Qt Development Frameworks,
Nokia - http://qt.nokia.com/

[Olivier Goffart]

Post by k***@nokia.com
For my original proposal I took inspiration from the KDE debug output.
Anyhow, I agree that the application name / pid just adds noise if you
launched your app yourself from the shell.
So, about "[%{type}] %{function} - %{message}" then?
Any other opinions? Olivier, do you think that's sensible?

Bikesheding topic :-) but if you ask my opinion, I think the %{type} is a bit
too much information.

My personal preference would be: "%{function}: %message"

[David Faure]

I again saw qDebugs committed with Q_FUNC_INFO explicitely in them, which
shows that yes, the default should be changed :-)

Post by Olivier Goffart

Post by k***@nokia.com
For my original proposal I took inspiration from the KDE debug output.
Anyhow, I agree that the application name / pid just adds noise if you
launched your app yourself from the shell.
So, about "[%{type}] %{function} - %{message}" then?
Any other opinions? Olivier, do you think that's sensible?

Bikesheding topic :-) but if you ask my opinion, I think the %{type} is a
bit too much information.

The problem is, "debug" is useless, but "WARNING" is useful. This is what
KDebug does (nothing for debug output, WARNING for warnings, and ERROR for
errors).
But %{type_other_than_debug} becomes a bit cumbersome :-)

An alternative is to use colors (I plan on submitting that for Qt-5.1), KDebug
makes the method name blue for debug, and red for warnings.

Post by Olivier Goffart
My personal preference would be: "%{function}: %message"

Let's go for that.

Another issue: QT_MESSAGE_PATTERN only affects qDebug(), but not
QDebug(QIODevice*), because that one sets the bool message_output to false,
and just lets the QTextStream write the message "as is" into the device.
This doesn't look easily fixable though ?

What we do in KDebug, for logging to files, is a custom QIODevice which
reimplements writeData() in order to write the line sent by the QTextStream
(at destruction time). Shall I just call the exported-but-not-documented
qMessageFormatString() there?

What I'm trying to say, in fact, is that I don't see a way to fix this without
a custom iodevice, so QDebug(QIODevice*) should probably be documented as
"doesn't support QT_MESSAGE_PATTERN, use qMessageFormatString if you want to
format the string" ?

[Shawn Rutledge]

Post by k***@nokia.com
Hi there,
In Qt 4 qDebug, qWarning etc just printed whatever was passed in. In Qt 5
we've been changing this (1) so that you can configure Qt to print
additional information by setting the QT_MESSAGE_PATTERN environment
variable. However, we didn't change the default so far - so without setting
QT_MESSAGE_PATTERN we still just print the message. I just had a discussion
(2) with Thiago Macieira and David Faure where we agreed that we'd like to
still change this for Qt 5.0 ...
My personal motivation is that if e.g. the type would be always part of the
message Qt Creator could use this information to colorize/filter output.
Adding the app name / PID would identify the app in case of system logs,
adding the function would give you a clue where on earth you added this one
debug statement just printing "true" ;)

...

Since I'm working with mouse events lately, and event propagation is kindof
confusing, I was thinking I'd like to have a qTrace() feature which would be
rather like qDebug except that it would accept extra parameter(s) to define
the "context" or "flow" that is being traced, and it could be separately
turned on/off and separately redirected. This is what I would do with it:

http://www.umlgraph.org/index.html

(the lower half about sequence diagrams) In fact, a few years ago on a Qt-
based project I used specially-formatted comments in code to define sequence
diagrams; it's just another "literate programming" technique, nice to be able
to define the sequence diagram inline with the code the same way as you can
define your documentation inline with code. But you still have to think like
a computer to make it work with comments, because the sequence does not come
out of the execution order, you have to know what it will do in which order.
Using qTrace would output something which depends on the actual runtime
execution order, and that would vary depending on the use case, so you could
generate a family of diagrams, one for each autotest as well as anything else
of interest.

Maybe I could use some kind of existing debugging technique (like the same way
that gdb does breakpoints, make some sort of auto-continuing breakpoint which
just traces the fact that it has been hit). But that would require a lot of
setup to define just for one test what the breakpoints should be. Or has that
problem been solved already? If there was a tool for scripting which
functions need the trace breakpoints in order to document which "flow", they
could be applied without adding anything to the source code. But depending on
the implementation of such a thing, it might be limited to tracing function
enter/exit, whereas qTrace could go anywhere.

Event propagation is a "flow" which is of long-term interest, and the
correctness of the flow is important both for testing and for documentation.
A lot of bugs could be found by comparing before-and-after diagrams when
changes are made.

Longer-term, Creator could generate selected types of diagrams whenever you
use the debugger. It would give you a more zoomed-out view of execution than
what you can get by just setting breakpoints and looking at stack traces
(which must be repeated because unless I took notes, I probably forgot what I
learned last time).

Quite often in preference to using breakpoints, I add a lot of qDebugs for
tracing, but it's bad etiquette to leave them in place. If there were an
acceptable way of doing tracing, they could be left in the code, but the
compiler would leave them out of non-debug builds. (It's of course important
for performance that they disappear completely from release builds. That
basically means qTrace should be a macro so it can be #defined to do nothing.)
Creator's editor could optionally hide or collapse qTrace lines too, for
anyone who minds the clutter.