Thursday, March 13, 2014

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.

3 comments:

Jamie said...

You are a gentleman and scholar! I've had a persistent Qt run-time issue that I haven't been able to capture, as it lies outside the bounds of the normal Python error stream. This post explained exactly how to add custom Qt error handling, and has (hopefully) given my software the robustness I've been striving for.

Thanks!

Dave Gradwell said...

Superb -- particularly the redirection into Python's logging module. Thank you kindly!

gregor said...

Thanks so much for sharing this! I ´ve been struggeling with my errors for over 3 weeks - now it´s solved. Finally I got an error message I could work with! GREAT!