[Development] Proposal: Changing the default output of qDebug and friends
kai.k...@nokia.com
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: From an IDE perspective including the file + line would help so that you could just 'jump' to the source of a warning by clicking on it. However, the file string can get quite long (think about shadow builds) ...
[1] Documented in http://doc-snapshot.qt-project.org/5.0/debug.html#warning-and-debugging-messages
[2] http://codereview.qt-project.org/#change,21655
--
Kai Koehne
Senior Software Engineer
Nokia, Mobile Phones
Nokia gate5 GmbH
Firmensitz: Invalidenstr. 117, 10115 Berlin, Germany
Registergericht: Amtsgericht Charlottenburg, Berlin: HRB 106443 B
Umsatzsteueridentifikationsnummer: DE 812 845 193
Geschäftsführer: Dr. Michael Halbherr, Karim Tähtivuori
_______________________________________________
Development mailing list
Devel...@qt-project.org
http://lists.qt-project.org/mailman/listinfo/development
Lincoln Ramsay
> PS: From an IDE perspective including the file + line would help so
> that you could just 'jump' to the source of a warning by clicking on
> it. However, the file string can get quite long (think about shadow
> builds) ...
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.
--
Lincoln Ramsay - Senior Software Engineer
Qt Development Frameworks, Nokia - http://qt.nokia.com/
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
> On 03/29/2012 09:41 AM, ext Lincoln Ramsay wrote:
> > 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.
> 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 :(
--
Lincoln Ramsay - Senior Software Engineer
Qt Development Frameworks, Nokia - http://qt.nokia.com/
Olivier Goffart
> On 03/29/2012 09:54 AM, ext Olivier Goffart wrote:
> > 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.
> And yeah... optimized binaries make it difficult for this to work 100%
> while it's an add-on to the language :(
kai.k...@nokia.com
> From: development-bounces+kai.koehne=noki...@qt-project.org
> [mailto:development-bounces+kai.koehne=noki...@qt-project.org] On
> Behalf Of Ramsay Lincoln (Nokia-MP/Brisbane)
> Sent: Thursday, March 29, 2012 1:42 AM
> To: devel...@qt-project.org
> Subject: Re: [Development] Proposal: Changing the default output of
> qDebug and friends
>
> On 03/29/2012 12:39 AM, ext kai.k...@nokia.com wrote:
> > PS: From an IDE perspective including the file + line would help so
> > that you could just 'jump' to the source of a warning by clicking on
> > it. However, the file string can get quite long (think about shadow
> > builds) ...
Hi Lincoln,
> 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.
Anyhow: Is the current default of printing just the message really the optimal one ? It leads to anti-patterns like
qDebug() << Q_FUNC_INFO << xxx;
// note that QT_MESSAGE_PATTERN="%{function} %{message}" produces much nicer output
or
qWarning() << "Warning: xxx";
It also leads to a misuse of using qDebug for 'normal' application output, e.g.
// misuse of qDebug, will look ugly with QT_MESSAGE_PATTERN, might break with future category logging
if (app.arguments().size() != 2)
qDebug() << "myapp <file>";
So IMO a bit more verbose output wouldn't harm, and actually help in keeping the code clean.
Regards
Kai
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...
kai.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)
> Cc: devel...@qt-project.org
> Subject: Re: [Development] Proposal: Changing the default output of
> qDebug and friends
>
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
Olivier Goffart
> 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"
Shawn Rutledge
> 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.
--
MVH, Shawn Rutledge ❖ "ecloud" on IRC