Trapping Qt log messages

Using PyQt5, you can install your own handler for Qt's log messages and do with them as you wish, for example diverting them to a Python log file. There are (as usual) some surprises, but by and large, it works.

The context is CoBro, my little web-comic browser. It uses QWebKit to display single HTML pages. After displaying one particular comic (Two Guys and Guy) the webkit code likes to emit a couple of log messages like "error: Internal problem, this method must only be called once." Annoying since there is nothing you can do about it, and it doesn't seem to cause any harm. (BTW this is a known problem, see Qt Bug #30298.)

So I add the following code to Cobro, after creating the App and the main window and everything and we are just about ready to show the main window and enter the event loop:

    from PyQt5.QtCore import qInstallMessageHandler, QMessageLogContext
    from PyQt5.Qt import QtMsgType

    def myQtMsgHandler( msg_type, msg_log_context, msg_string ) :
        print('file:', msg_log_context.file)
        print('function:', msg_log_context.function)
        print('line:', msg_log_context.line)
        print('  txt:', msg_string)

    qInstallMessageHandler(myQtMsgHandler)

Now what comes out on stderr is this:

file: access/qnetworkreplyhttpimpl.cpp
function: void QNetworkReplyHttpImplPrivate::error(QNetworkReplyImpl::NetworkError, const QString &)
line: 1929
  txt: QNetworkReplyImplPrivate::error: Internal problem, this method must only be called once.

Ta-daaaa! We have intercepted a Qt log message and analyzed it to show where in the Qt code it originated. One surprise is that the "function" member of the QMessageLogContext object is not a simple function name, but the full C++ signature. Another surprise is that, when I stop on this code in a debugger and look at the msg_log_context item, its members are not strings but "sip reference" objects. Nevertheless by the magic of PyQt5 they print as strings.

Well, printing this bumf isn't a lot of use. What would be more useful, is to divert it into the Python log stream, like this:

    def myQtMsgHandler( msg_type, msg_log_context, msg_string ) :
        # Convert Qt msg type to logging level
        log_level = [logging.DEBUG,
                     logging.WARN,
                     logging.ERROR,
                     logging.FATAL] [ int(msg_type) ]
        logging.log(logging.DEBUG,
                    'Qt context file is '+msg_log_context.file
                    )
        logging.log(logging.DEBUG,
                    'Qt context line and function: {0} {1}'.format(
                        msg_log_context.line, msg_log_context.function)
                    )
        logging.log(log_level, 'Qt message: '+msg_string)

In other words, log the gritty details of the QMessageLogContext at the DEBUG level, but log its actual text at its own self-assigned severity, as translated into Python logging's values. The above code works and now I can redirect QWebKit's annoying messages into CoBro's log file.

Python logging and unit testing

PPQT 2 is to be pretty much a complete rewrite of version 1. I built the first version in an ad-hoc way, adding features one at a time to the basic editor, and as a result its software structure is rather ramshackle. Information about different data structures and formats leaks all over. So now I know where it's going, the next version can be properly compartmentalized and structured.

And better-tested! V1 got "tested" by my using it. V2, I am determined, will have a separate unit-test driver for each module, and every added function means adding test code to exercise it. We be professional here!

And logging! V1 has no logging of any kind. There may be one or two places where an except clause has a print statement in it (blush) but that's it. So I read up on Python logging, and each module will have its named logger and log some occasional INFO lines, always WARN lines where the module is working around some problem, and occasionally ERROR lines.

So the first module finished (yay!) is metadata.py and it has several places where it detects and logs errors. So how, in the matching metadata_test.py, can I test whether the module wrote the expected thing to the log?

There may be better ways, but this is how I'm doing it. First, at the top of the test module is this, which I expect will be boilerplate repeated in every test driver.

# set up logging to a stream
import io
log_stream = io.StringIO()
import logging
logging.basicConfig(stream=log_stream,level=logging.INFO)
def check_log(text):
    global log_stream
    "check that the log_stream contains text, rewind the log, return T/F"
    log_data = log_stream.getvalue()
    x = log_stream.seek(0)
    x = log_stream.truncate()
    return (-1 < log_data.find(text))

During execution of the unit test, log output is directed to an in-memory stream. In the test code, the module under test is provoked into seeing an error that should cause it to write a log line. Then you can just code assert check_log('some text the test should have logged'). The assertion fails if the string isn't in the log. If it succeeds, execution continues with the log cleared out for the next test.

Looking at it now, I think maybe check_log() should take two parameters, the text and the level, so as to verify that the message is at the expected level:

assert check_log('whatever',logging.WARN)

I'll leave that as an exercise. Meaning, I'm too lazy to do it now.

Incidentally, another goal of V2 is to have localized (e.g. translated) text in the visible UI. Perhaps log messages should also be translated but... nah.