#1634 qtlogging.ini (category logging) breaks RG_WARNING

[Yves Guillemot]

Writing to RG_WARNING doesn't work in LilyPondExporter whatever the build mode is.

Looking inside Debug.h shows that RG_WARNING and RG_DEBUG share the same definition:

    #define RG_DEBUG QDebug(QtDebugMsg) << RG_MODULE_STRING
    #define RG_WARNING QDebug(QtDebugMsg) << RG_MODULE_STRING

[Ted Felix]

Works fine for me. I threw an RG_WARNING into LilyPondExporter's ctor and it comes out in a debug build.

Looking inside Debug.h shows that RG_WARNING and RG_DEBUG share the same definition

That is correct. The difference is that RG_WARNING is always defined as that, whereas RG_DEBUG is only defined as that for a DEBUG build without RG_NO_DEBUG_PRINT.

[Yves Guillemot]

With the following modification of LilyPondExporter.cpp:

 m_selection(selection),
 SKIP_PROPERTY("LilyPondExportSkipThisEvent")
{
+    std::cout << "AAAAA\n";
+    RG_WARNING << "BBBBB";
+    RG_DEBUG << "CCCCC";
+    
 m_composition = &m_doc->getComposition();
 m_studio = &m_doc->getStudio();
 m_notationView = parent;

Running LilyPond preview with RG build in release mode outputs:

(...)
JackClient::AcquireSelfRealTime error
do_connect: could not connect to socket
connect: Aucun fichier ou dossier de ce type
QSettings for LilyPond (populateDefaultValues):
  lilyexportmarkermode: 0
  lilyraggedbottom: false

QSettings for LilyPond (slotApply):
  lilyexportmarkermode: 0
  lilyraggedbottom: false

AAAAA
LilyPondProcessor::LilyPondProcessor():  mode: 1 m_filename: rosegarden_tmp_dgtEDa.ly
LilyPondProcessor::runConvertLy()
LilyPondProcessor::runLilyPond()
LilyPondProcessor::runFinalStage()

Same thing with RG build in debug mode outputs:

(...)
JackClient::AcquireSelfRealTime error
do_connect: could not connect to socket
connect: Aucun fichier ou dossier de ce type
WARNING: Rosegarden::Exception: "Failed to connect to LIRC"
WARNING: Rosegarden::Exception: "L'ouverture de /dev/tranzport0 (périphérique tranzport) a échouée"
QSettings for LilyPond (populateDefaultValues):
  lilyexportmarkermode: 0
  lilyraggedbottom: false

QSettings for LilyPond (slotApply):
  lilyexportmarkermode: 0
  lilyraggedbottom: false

AAAAA
LilyPondProcessor::LilyPondProcessor():  mode: 1 m_filename: rosegarden_tmp_wJhdgY.ly
LilyPondProcessor::runConvertLy()
LilyPondProcessor::runLilyPond()
LilyPondProcessor::runFinalStage()

Commenting out "#define RG_NO_DEBUG_PRINT 1" at the beginning of LilyPondExporter.cpp doesn't change anything.
It seems that RG_DEBUG, RG_WARNING, etc... never work on my system.
May it be some environment variable? But which?
Any idea of how I can debug that?

[Philip Leishman]

Yes the RG_WARNING output is actually a debug output. See also the discussion to feature request 492.
So maybe you have a qtlogging.ini file set (eg. with environment QT_LOGGING_CONF set).
If so you must ensure that default.debug is set to true. this enables all Rosegarden debug and warning outputs.

[Philip Leishman]

I think we posted at about the same time !!
:)
See https://doc.qt.io/qt-5/qloggingcategory.html for info about the ini file.

[Yves Guillemot]

Thanks Philip.
Indeed, there is a qtlogging.ini files I never suspected on my system which turns off all Qt debug messages.
Once debug validated and some rules added to get rid of the avalanche of Qt messages, RG_WARNING is working fine.

Now there is a problem: RG_WARNING is needed to warn the user that something unexpected is going wrong somewhere in RG.
But if RG_WARNING didn't work out of the box on my system, why should it work on the system of any user?

Is it possible to shortcircuit qtlogging.ini and other related environment variables from inside a Qt application?
Should RG_WARNING be replaced with (or straightly redirected to) std::cerr?

[Ted Felix]

Two thoughts come to mind...

Documentation. We should mention qtlogging.ini and its potentially annoying effects in Debug.h. Also provide a solution.

Auto-detect. Is there some way to detect that qtlogging.ini has problematic settings? Maybe QLoggingCategory::isDebugEnabled() or some other function? Then we can log a warning to std::cerr recommending a solution. Or maybe we should just override it and force the appropriate settings to provide the proper old logging behavior? I think Philip has done that successfully with QLoggingCategory::setFilterRules().

[Ted Felix]

See also [feature-requests:#492].

[Mark R. Rubin]

My newbie's 2 cents: I'm all for anything that makes logging more configurable, at runtime or compile time. I've found little use for RG_DEBUG because turning it on, either via -DCMAKE_BUILD_TYPE=Debug or manually editing Debug.h (I wish there was a -D flag to going to a ?= variable in a Makefile, but I still don't understand cmake) results in such a spew of messages that I can't find my own output among them. So I just use temporary RG_WARNINGs in my code, or even fall back to a raw qDebug() sometimes. RG_WARNING is annoying because it's misnamed for my use (I'm actually debugging), but whatever.

I'll throw in another, more important, $2 here and say that all the user-facing RG_WARNINGs in the code base should be removed and replaced with the statusbar/setContextHelp() or popping up a dialog for more critical messages. I thought I was the only nerd left who still runs software like RG from the shell commandline, although maybe some of you guys are as bad as I am. It doesn't matter -- I'll bet that 99% of the non-developer users are starting it from some "desktop environment" (I hate them) and will never see anything sent to stderr/stdout. If I'm wrong and there is some shell-centrism in the design, why do I have to fight the file dialogs which have no concept of $PWD and force me to navigate back from wherever I last saved or loaded a file to where I am (and want to be) now? At least $ rosegarden some_file.rg still works, so a heartfelt thanks for that.

[Philip Leishman]

I would consider all RG_WARNINGs as essentially output for developers or maybe an interested user who wants to dig a little deeper. Actually I think rosegarden does quite a good job of warning the user with popup messages etc. when the user really needs to be informed.
Actually RG_DEBUG is configurable at compile time using the RG_NO_DEBUG_PRINT macro. Normally this is set and the debug output is suppressed. If I want to see debug output I just comment this line out and get all the debug output from this file. I do this a lot.
So RG_WARNING is really just a debug output which is not switched off by RG_NO_DEBUG_PRINT !
I personally would prefer runtime configuration - this is the category logging from feature request 492. I think this would also help the "interested user" who wants to dig deeper but is not yet as far as compiling roesgarden.

[Mark R. Rubin]

I would consider all RG_WARNINGs as essentially output for developers ...

Point taken, and if that's the intent and the code follows it, all's good. I know I've seen counterexamples, e.g. MatrixView::slotDiatonicTranspose()

if (intervalDialog.getChangeKey())
{
    RG_WARNING << "Transposing changing keys is not currently supported on selections";
}

which returns immediately after that, doing nothing and potentially leaving the user going, "What? Nothing happened. Did I do something wrong?"

But yes, most of them report code errors that shouldn't possibly happen yet aren't fatal, so if the above is a small mistake they can be tracked down one by one as we come across them. I know I've fixed a few in the course of doing my bug reports and feature requests.

RG_NO_DEBUG_PRINT macro

Yes, I've used that to turn RG_DEBUG on and off at a per-file instead of application level. Even per-file it's usually more spam than I can handle so I fall back to RG_WARNING, qDebug(), or even std::cerr. Again, it's just the very minor annoyance that "WARNING" hurts my eyes because my brain's thinking "DEBUG". And some kind of fine-grained, runtime control would be the ultimate:

$ rosegarden --debug-level=info
$ rosegarden --debug-level=7
$ rosegarden --debug-module=notation
$ rosegarden --debug-class=NotationStaff

Hey, I can dream, can't I? ;)

Thanks for clarifying the RG_WARNING design/policy.

[Yves Guillemot]

Whatever the RG_WARNING message is for, it should always be displayed (in debug or release build).
Here is a quote from misc/debug.h:

// Use RG_WARNING for recoverable errors that shouldn't usually occur, but
// we want to know about them when debugging issues with users. These will
// always be written to the debug output even with RG_NO_DEBUG_PRINT defined.
// For a normal run, there should be no RG_WARNING output.
// This works in both debug and release builds. Formerly, std::cerr was
// used for this.

In my opinion, RG_WARNING is mainly a complicated and unreliable way to replace the good old std::cerr which is still working fine.

[Ted Felix]

I never anticipated that category logging would come along and break RG_WARNING. The idea was to have something that indicates what it is for. It is for warnings. I really had the best of intentions when I created it. The road to you know where...

[Philip Leishman]

I think the logging system is quite good. I believe that good old qDebug() is the same as QDebug(QtDebugMsg) which is the same as category logging with type debug and category "default" !
This is used for RG_DEBUG and RG_WARNING
maybe RG_WARNING should use QDebug(QtWarningMsg) !
A qlogging.ini file is always going to have an effect !
I still see an advantage in moving entirely to category logging and using the ini file to switch logging on and off.

[Yves Guillemot]

Ted, I never doubt your intentions were the best.
It's sometimes difficult to predict every behaviours following a code change.

I have no doubt that the Qt debug tools work fine, but RG_WARNING is more for printing messages than for debugging.

I just sent a merge request (rg_warning branch) which modify RG_WARNING to use std::cerr rather than qDebug.

The new RG_WARNING shoud work exactly as the previous one (except for qtlogging.ini).

There is a new macro RG_WARNING_, ending with an underscore, which may be used to pass a few options:

• RG_WARNING_() is identical to RG_WARNING
• RG_WARNING_(POS) << something
  replaces the module string with the file name and the line number
• RG_WARNING_(NNL) << something
  doesn't send automatically an end of line
• RG_WARNING(POSNNL)
  combines the two previous options
• DBG
  is a shortcut for RG_WARNING_(POS) which can be used for debugging.
  "DBG;" alone writes it's filename and line number when executed.

I'm not sure all these options are really useful, but they were easy to implement.
If you think they are not desirable, I can remove them.

[Mark R. Rubin]

Yves: Sorry, but I think there's a problem with this. The current RG_WARNING built on top of QDebug() has many of that class's features that I have mixed feelings about, including the automatic addition of spaces between inserted objects and the addition of the newline at the end -- all very convenient, but that prevent concatenating text or appending to previous output when desired.

But more importantly, all(??) Qt classes implement some kind of QDebug &operator<<(QDebug &stream, const SomeQtObject &obj) but not the same for std::ostream. I know I use RG_WARNING to print Qt objects, and I believe there are other places in the code that do the same. If nothing else, QStrings can't be used with std::ostream without .toStdString(), and almost everything in RG is QStrings (which again I have mixed feelings about).

I cloned your branch with the change and tried RG_WARNING << someQtObject;, which confirmed my fears (it did not compile). Sorry for the bad news, and many apologies if I've missed something obvious and am wrong about all this.

[Yves Guillemot]

The current RG_WARNING built on top of QDebug() has many of that class's features that I have mixed feelings about, including the automatic addition of spaces between inserted objects and the addition of the newline at the end

The new RG_WARNING doesn't automatically insert spaces. Is this really a problem?

all very convenient, but that prevent concatenating text or appending to previous output when desired.

If needed, it's now possible to do

RG_WARNING_(NNL) << something;
(...)
std::cerr << something_else << std::endl;

I know I use RG_WARNING to print Qt objects, and I believe there are other places in the code that do the same. If nothing else, QStrings can't be used with std::ostream without .toStdString(), and almost everything in RG is QStrings (which again I have mixed feelings about).

The new RG_WARNING, as the previous one, can print QStrings without .toStdString().
If you need to output a QString on std::ostream and don't want to add the .toStdString(), you only have to include "misc/Strings.h" which defines the << operator for QString.

I cloned your branch with the change and tried RG_WARNING << someQtObject;, which confirmed my fears (it did not compile).

It didn't compile in debug mode because I forgot a ROSEGARDENPRIVATE_EXPORT keyword. It should be fixed now.
Apart from this, I'm not surprised it didn't compile if you try to write some QtObject other than QString with RG_WARNING.
I see RG_WARNING as a way to write short messages, as with std::cerr before, not as a tool to dump any QtObject.
The current RG (master branch) compiles fine with the new QT_WARNING.

The true question is what is RG_WARNING for?
To write short messages (including QStrings) or to write long ones including the dump of QtObjects?
If you really need to write complex QtObjects on a standard output, why not to straightly use some tool from the qDebug/qWarning family?

[Mark R. Rubin]

The new RG_WARNING doesn't automatically insert spaces. Is this really a problem?

For me, not particularly. Like I said, I find the qDebug/qWarning family's automatic spacing and newlines both convenient (as per its obvious design intent) and limiting (can't concatenate strings or do multiple outputs to the same line).

The true question is what is RG_WARNING for?
To write short messages (including QStrings) or to write long ones including the dump of QtObjects?

That is the question. I've been using RG_WARNING for debug dumps -- which do greatly benefit from the QtObject serialization -- due to the limitations, for my purposes, of RG_DEBUG (necessity of modifying Debug.h, lack of fine-grained control below the file level, etc).

If you need to output a QString on std::ostream and don't want to add the .toStdString(), you only have to include "misc/Strings.h" which defines the << operator for QString.

Thanks, I didn't know about that. There's lots of code in RG to discover, one piece at a time. ;)

If you really need to write complex QtObjects on a standard output, why not to straightly use some tool from the qDebug/qWarning family?

I probably should just do that, especially since I remove my debug code before submitting my merge requests. But I'm trying as much as possible to do things "the Rosegarden way", even when that conflicts with my long-held design/coding/style practices, so I've been trying to use the RG_* macros in preference to my natural tendencies towards std::cerr or, for QtObjects, qDebug.

If needed, it's now possible to do
RG_WARNING_(NNL) << something;

Yes, I saw that. Your implementation seemed very complete and well thought out, which is why I thought the QtObjects failures might be an inadvertent omission.

One more, related topic: My personal opinion is that the large quantity of disabled-by-default RG_DEBUG code that's in the repo shouldn't be there. I'm assuming the justification is something like, "I spent a lot of time adding these useful/accurate/precise diagnostics while debugging this complex code, and if a bug shows up later I want to be able to simply turn it on again instead of having to rewrite it."

I understand the point, and it's a valid one, but the counterargument is that it clutters up the code, making it hard to read the sometimes already difficult to understand algorithms. My own experience is that when latent bugs do show up they tend to be completely unrelated to the ones I encountered when originally writing the code, and often require completely new debug output to find and fix. Plus, can't the debug be saved in a separate commit, stripped out before release, and so always be available for merging back in later if and when needed?

All of this is just to throw some ideas into this discussion. FWIW, I don't feel strongly about these issues, in contrast to some of those I'm addressing in my feature and merge requests. And of course everyone here, particular the many of you who have put in years if not decades of work on RG, are free to ignore my input. I of course think it's valid and deserves consideration, but you'll have to make up your own minds.

[Ted Felix]

That is the question. I've been using RG_WARNING for debug dumps -- which do greatly benefit from the QtObject serialization -- due to the limitations, for my purposes, of RG_DEBUG (necessity of modifying Debug.h, lack of fine-grained control below the file level, etc).

RG_DEBUG is what you should be using for debugging, not RG_WARNING. Yeah, it's a little annoying with all the other logging that might be present, but this is the "RG" way. However, if you are going to remove the logging before commit, then it doesn't make any difference what you use.

My personal opinion is that the large quantity of disabled-by-default RG_DEBUG code that's in the repo shouldn't be there.

Agree 100%. This is my personal policy. I clean up behind myself. At one time I asked if I could remove all the RG_DEBUGs and was told no. Category Logging encourages leaving lots of (outdated and useless) logging all over the place. One of the many reasons I am not fond of it. It doesn't help me get work done.

These days, I comment out the interesting RG_DEBUGs when I'm in a file if I need them out of the way. Uninteresting ones I remove completely.

[Philip Leishman]

Interesting discussion !!
My opinion:
1. All output (stdout, stderr) is intended for developers. Warnings which are really necessary for the user MUST be provided with a message box or similar.
2. The Qt Debug system is very good and we should use it if we can (output of Qt Objects etc.)
3. the Qt Debug system provides for different types of message from info to critical (see https://doc.qt.io/qt-5/qdebug.html). Also see my suggestion above to define RG_WARNING as QDebug(QtWarningMsg)
4. The message format of qt logging can be changed by the user (QT_MESSAGE_PATTERN environment variable) including file and line number.
5. Additionally it is possible to use category logging for runtime switching on and off of messages.
6. Developers should be aware of the ini file and its consequences (documentation).
7. If debugging is switchable (compile or run time) then you cannot have enough of it. I have often been pleased when debugging to find a suitable debug output ready and waiting for me. I never remove RG_DEBUG lines.

[Ted Felix]

Pushed two commits at [064ebb] in an effort to mitigate this issue. Now if category logging is configured in such a way that might prevent RG_WARNING from coming out, you'll see a warning at the beginning of the debug output along with some helpful suggestions. See main.cpp line 410.

Category logging is here to stay. Regardless of how we feel about it, we need to raise awareness to help avoid problems in the future.

Please review and test latest git.