Capturing Qt logging

[The-Compiler]

Continuing the discussion from hackebrot/qutebrowser#8 (comment) here 😄

I agree it's a good idea to do a fixture similiar to caplog, with a .records() and maybe .setLevel() and .atLevel() as well.

Levels of messages

In Qt, there are the following logging "levels"/functions - I also checked how much it's used in the whole qtbase sourcecode:

• qFatal(): An error which means any further execution of the application is useless. Calls abort() immediately by default, so probably should never be captured as we'll not get to the point to display the captured output. Used 178 times, for things like when no screen was found, or you're mixing incompatible Qt libraries.
• qCritical(): A critical issue. Qt should IMHO use this for many things which are actually only qWarnings, but it's only used 88 times.
• qWarning(): Used for a lot of messages which aren't really "just warnings", but Qt is (or thinks it is) able to recover from. Used 2601 times.
• qDebug(): Used for debug output (1692 times), but only if you recompile Qt yourself with -debug.

Handling of qFatal()

As said I think this should not be captured. The Qt documentation says:

If you are using the default message handler this function will abort on Unix systems to create a core dump. On Windows, for debug builds, this function will report a _CRT_ERROR enabling you to connect a debugger to the application.

I wonder how this should be handled, as it's probably a good idea to keep that behaviour. Maybe disable the custom message handler from inside it, and then call qFatal() with the given message again?

Other levels

I think qCritical() / qWarning() / qDebug() should all be captured and printed with failed tests by default.

However as said, I'd also like to have a way to always print qCritical()/qWarning(). Maybe some --qt-log-always option, and a --qt-log-format option so I can get it in the format I want?

[nicoddemus]

Thanks for the detailed description and research about usage in qt base code. 😄

I also think that qFatal probably should not be handled, leaving the default behavior (exactly how I'm not sure, your suggestion might work).

About the rest, I think we are in agreement. I can start working on this next week, unless you are willing to help out, in which case I'm more than happy to provide any help I can. 😄

[The-Compiler]

I'll let you do it then - I have a lot of things on my qutebrowser todo list anyways 😆

Thanks!

[nicoddemus]

Sure thing. I'll add you as a reviewer to the PR then, if you don't mind. 😊

[nicoddemus]

@The-Compiler I was wondering, what's the actual use case you have for wanting captured messages to be displayed immediately, as opposed only when a test fails?

I ask because we had the same problem at work but opted to make a test that outputs an unexpected message (say, qWarning or above) to fail instead, as in our experience, messages emitted to the console during a test run are seldom seen (specially during C.I.). Of course, the level which would cause a test to fail could be controlled project-wide and test-by-test basis, and perhaps even regexes could be used to allow certain messages within a test.

[The-Compiler]

Failing a test on certain messages would work as well, sure - and probably it'll be more useful for people not having the same configuration I do.

Right now, I have buildbot configured so it detects the logging output, and marks the step as "passed with warnings":

class UnitTestCommand(ToxCommand):

    def __init__(self, toxenv='unittests'):
        ToxCommand.__init__(self, toxenv=toxenv,
            description='running unittests', descriptionDone='unittests',
            name='unittests', timeout=120)

    def createSummary(self, log):
        warncount = 0
        with open('/tmp/buildbot-debug', 'w') as f:
            for line in log.getText().splitlines():
                f.write(line)
                if 'LOG' in line:
                    warncount += 1
        self.setProperty('unittest-warnings', warncount, 'Build')

    def evaluateCommand(self, cmd):
        if cmd.rc != 0:
            return FAILURE
        if self.getProperty('unittest-warnings', False):
            return WARNINGS
        return SUCCESS

This will then show up like this for example.

[nicoddemus]

I see, nice setup (although I couldn't access the link).

But in my proposal your current setup would no longer work and you would have to adapt it... would that be OK?

On second thought, to keep your setup working, you would just have to disable qt message capture so they would go to stderr as usual and be captured by your custom command.

[The-Compiler]

Hm, weird, the link should work fine (and doesn't require login).

Sure, I can easily adapt the setup. The problem with the default output is there's no prefix or anything for Qt messages, so I can't easily filter them. On the other hand, I probably could just check if there's anything on stderr, as nothing writes to stderr normally!

[nicoddemus]

Hmm, you're right.

Well, I will write a more detailed proposal for this later during lunch to see what you think. 😄

Cheers, 🍻

[nicoddemus]

Proposal

Have new configuration variables that control if tests which emit messages using Qt logging system (qWarning, qCritical, etc.) to fail:

[pytest]
qt_log_fail_level = warning
qt_log_fail_ignore = 
    .*paint not sent.*
    .*widget not closed properly.*

• qt_log_fail_level: the possible values are: disabled, debug, warning, critical (fatal will always quit the interpreter, so it is not included in this list). This controls which message level and above emitted during a test execution causes that test to fail. A value of warning will make tests that emit any messages from both qWarning and qCritical to fail, for example. The failure will not happen at the exact point of where the message was emitted, as they may happen from within C++ code, but will be stored and display later during test reporting, along with any assertion failures (if any). For example:

      def test_widget(qtbot):
           widget = MyWidget()
           ...
           widget.do_something()  # this generates a few qWarnings
           assert widget.contents() == 'expected contents'

  Will generate output like this:

  >       assert widget.contents() == 'expected contents'
  E       assert 'obtained contents' == 'expected contents'
  E         - obtained contents
  E         + expected contents
  test_foo.py:5: AssertionError
  ---
  Failure: Qt messages above level "warning" emitted:
    - QtWarningMsg: Paint event not sent as expected
    - QtDebugMsg: Count exceeded maximum
  

• qt_log_failure_ignore: list of regular expressions which prevents messages that match them from failing a test, regardless of their level. If a test fails (from an assertion failure or other messages), ignored messages are displayed too, marked as "ignored":

  ---
  Failure: Qt messages above level "warning" emitted:
    - QtWarningMsg: Paint event not sent as expected (IGNORED)
    - QtDebugMsg: Count exceeded maximum
  

Besides the configuration variables, markers with the same name are also available that can control the behavior on a per-test basis, for example:

# disables failure from log messages
@pytest.mark.qt_log_fail_level("disabled")
def test_widget1(qtbot):
    ...

# sets failure to critical, ignoring a specific message
@pytest.mark.qt_log_fail_level("critical")
@pytest.mark.qt_log_ignore(".*WM_DESTROY sent.*")
def test_widget2(qtbot):
    ...

Final note: the logging configuration is applied to all test functions, regardless if they use qtbot fixture or not.

@The-Compiler and @jdreaver, your comments are very welcome! 😄

[The-Compiler]

That would certainly work for my use case, and looks flexible enough so it also works for many other scenarios.

What would the default for qt_log_fail_level be? It'd probably be an useful feature to be turned on by default - but then again, most things in Qt are qWarnings, some critical, some not (see the list of suppressed messages in qutebrowser)

[nicoddemus]

I would say the default would be "disabled"; I wouldn't like for test suites to start breaking just by updating pytest-qt to 1.4.0... after all, it is easy to just add a line to pytest.ini to enable the desired behavior.