How to get non-blocking/real-time behavior from Python logging module? (output to PyQt QTextBrowser)

Question

Description: I have written a custom log handler for capturing log events and writing them to a QTextBrowser object (working sample code shown below).

Issue: Pressing the button invokes someProcess(). This writes two strings to the logger object. However, the strings only appear after someProcess() returns.

Question: How do I get the logged strings to appear in the QTextBrowser object immediately/in real-time? (i.e. as soon as a logger output method is invoked)

from PyQt4 import QtCore, QtGui
import sys
import time
import logging
logger = logging.getLogger(__name__)

class ConsoleWindowLogHandler(logging.Handler):
    def __init__(self, textBox):
        super(ConsoleWindowLogHandler, self).__init__()
        self.textBox = textBox

    def emit(self, logRecord):
        self.textBox.append(str(logRecord.getMessage()))

def someProcess():
    logger.error("line1")
    time.sleep(5)
    logger.error("line2")

if __name__ == "__main__":
    app = QtGui.QApplication(sys.argv)
    window = QtGui.QWidget()
    textBox = QtGui.QTextBrowser()
    button = QtGui.QPushButton()
    button.clicked.connect(someProcess)
    vertLayout = QtGui.QVBoxLayout()
    vertLayout.addWidget(textBox)
    vertLayout.addWidget(button)
    window.setLayout(vertLayout)
    window.show()
    consoleHandler = ConsoleWindowLogHandler(textBox)
    logger.addHandler(consoleHandler)
    sys.exit(app.exec_())

EDIT: thanks to the answer by @abarnert, I managed to write this piece of working code using QThread. I subclassed QThread in order to run some function someProcess in a background thread. For the signalling, I had to resort to old-style Signal and Slots (I'm not sure how to do it in the new-style). I created a dummy QObject in order to be able to emit signals from the logging handler.

from PyQt4 import QtCore, QtGui
import sys
import time
import logging
logger = logging.getLogger(__name__)

#------------------------------------------------------------------------------
class ConsoleWindowLogHandler(logging.Handler):
    def __init__(self, sigEmitter):
        super(ConsoleWindowLogHandler, self).__init__()
        self.sigEmitter = sigEmitter

    def emit(self, logRecord):
        message = str(logRecord.getMessage())
        self.sigEmitter.emit(QtCore.SIGNAL("logMsg(QString)"), message)

#------------------------------------------------------------------------------
class Window(QtGui.QWidget):
    def __init__(self):
        super(Window, self).__init__()

        # Layout
        textBox = QtGui.QTextBrowser()
        self.button = QtGui.QPushButton()
        vertLayout = QtGui.QVBoxLayout()
        vertLayout.addWidget(textBox)
        vertLayout.addWidget(self.button)
        self.setLayout(vertLayout)

        # Connect button
        self.button.clicked.connect(self.buttonPressed)

        # Thread
        self.bee = Worker(self.someProcess, ())
        self.bee.finished.connect(self.restoreUi)
        self.bee.terminated.connect(self.restoreUi)

        # Console handler
        dummyEmitter = QtCore.QObject()
        self.connect(dummyEmitter, QtCore.SIGNAL("logMsg(QString)"),
                     textBox.append)
        consoleHandler = ConsoleWindowLogHandler(dummyEmitter)
        logger.addHandler(consoleHandler)

    def buttonPressed(self):
        self.button.setEnabled(False)
        self.bee.start()

    def someProcess(self):
        logger.error("starting")
        for i in xrange(10):
            logger.error("line%d" % i)
            time.sleep(2)

    def restoreUi(self):
        self.button.setEnabled(True)

#------------------------------------------------------------------------------
class Worker(QtCore.QThread):
    def __init__(self, func, args):
        super(Worker, self).__init__()
        self.func = func
        self.args = args

    def run(self):
        self.func(*self.args)

#------------------------------------------------------------------------------
if __name__ == "__main__":
    app = QtGui.QApplication(sys.argv)
    window = Window()
    window.show()
    sys.exit(app.exec_())

Denature

If your edit was a proper answer, it would be the canonical solution to the common problem of displaying log messages in both PyQt and PySide widgets. Unlike all similar solutions to all similar questions (e.g., this, this), your edit leverages slots and signals and hence operates non-blockingly. That's fantastic. – Plainsman

What's less fantastic is the use of old-style slots and signals and a hypetextual QTextBrowser rather than a read-only plaintext QTextArea. Use of new-style slots and signals should obviate the need for the dummyEmitter intermediary. Likewise, to quote official QTextBrowser documentation: "If you want a text browser without hypertext navigation use QTextEdit and use QTextEdit::setReadOnly() to disable editing." – Plainsman

Answer 1

The real problem here is that you're blocking the entire GUI for 5 seconds by sleeping in the main thread. You can't do that, or no updates will show up, the user won't be able to interact with your app, etc. The logging issue is just a minor sub-consequence of that major problem.

And if your real program is calling some code from a third-party module that takes 5 seconds or does something blocking, it will have the exact same problem.

In general, there are two ways to do slow, blocking things without blocking a GUI (or other event-loop-based) app:

1. Do the work in a background thread. Depending on your GUI framework, from a background thread, you usually can't call functions directly on the GUI or modify its objects; you instead have to use some mechanism to post messages to the event loop. In Qt, you normally do this through the signal-slot mechanism. See this question for details.

2. Break the job up into non-blocking or guaranteed-only-very-short-term-blocking jobs that return quickly, each scheduling the next right before returning. (With some GUI frameworks, you can do the equivalent in-line by calling something like safeYield or calling the event loop recursively, but you don't do that with Qt.)

Given that someProcess is some external code that you can't modify, which either takes seconds to finish or does something blocking, you can't use option 2. So, option 1 it is: run it in a background thread.

Fortunately, this is easy. Qt has ways to do this, but Python's ways are even easier:

t = threading.Thread(target=someProcess)
t.start()

Now, you need to change ConsoleWindowLogHandler.emit so that, instead of directly modifying textBox, it sends a signal to get that done in the main thread. See Threads and QObjects for all the details, and some good examples.

More concretely: The Mandelbrot example uses a RenderThread that doesn't actually draw anything, but instead sends a renderedImage signal; the MandelbrotWidget then has an updatePixmap slot that it connects to the renderedImage signal. In the same way, your log handler wouldn't actually update the text box, but instead send a gotLogMessage signal; then you'd have a LogTextWidget with a updateLog slot that it connects to that signal. Of course for your simple case, you can keep them together in a single class, just as long as you connect the two sides up with a signal-slot connection rather than a direct method call.

You probably want to either keep t around somewhere and join it during shutdown, or set t.daemon = True.

Either way, if you want to know when someProcess is done, you need to use other means of communicating back to your main thread when it's done—again, with Qt, the usual answer is to send a signal. And this also lets you get a result back from someProcess. And you don't need to modify someProcess to do this; just define a wrapper function that calls someProcess and signals its result, and call that wrapper function from the background thread.

Livestock

Thanks. In my real code, someProcess() calls a Python module that calls the logger to provide status updates, and I'd like to be able to display those status updates in real time in a QTextBrowser. I know subprocess lets me capture stdout in a non-blocking way, but in this case, I want to capture logging events in a non-blocking way. The Python module does not know about the GUI. – Denature

@Gilead: Using subprocess (or QProcess if you prefer) from a background thread is no harder than doing anything else from a background thread. Am I missing something here? Have you read Threads and QObjects? Creating background threads is easy, and emitting signals from them automatically works across threads, and that's the way you deal with blocking in Qt. – Livestock

Thanks for the quick response. subProcess is easy to use but it has to call an external program--I'm not sure how I use it with a Python module (which I cannot modify), plus I'm not sure how the logging module would communicate if the subprocess is external. QProcess seems to be similar. – Denature

@Gilead: I only brought up subprocess because you did, and I thought maybe it was inherent to your solution that you were running someone else's script in a child process. If you don't want to use that, a thread is all you need. I've updated the answer to explain. – Livestock

Thanks for your answer. I'd never written anything threaded before, and I was surprised that within a few hours, I managed to figure out how to do it. You're right -- it isn't that hard, especially with Python. I've attached some new code above. It seems to do what I want. The mixing of new and old style signal-and-slots is a bit inelegant though, but I'll leave it for now. Thanks again! – Denature

@Gilead: Threading is actually very easy, and effectively, whenever you can reduce all communication between tasks to queuing messages—which is basically what signals do. It lets you just write each task as if it were sequential and blocking, but it doesn't block, like magic. When threading gets complicated is when you need to share data directly between tasks. (Or when you have thousands of tasks, or when you have multiple CPU-bound tasks and want parallel performance…) – Livestock

Yes, I was kind of worried about adding complexity to my code (esp wrt managing threads). I was contemplating using processes instead, but I now see that threading is a really good solution for problems like this. Thanks! – Denature

Answer 2

Build on top of @Gilead's code and @Cecil's suggestions, I update the code by changing the old-style to new-style signal/slot and changing the QTextBrowser to QTextEdit.

import sys
import time
import logging
from qtpy.QtCore import QObject, Signal, QThread
from qtpy.QtWidgets import QWidget, QTextEdit, QPushButton, QVBoxLayout

logger = logging.getLogger(__name__)


class ConsoleWindowLogHandler(logging.Handler, QObject):
    sigLog = Signal(str)
    def __init__(self):
        logging.Handler.__init__(self)
        QObject.__init__(self)

    def emit(self, logRecord):
        message = str(logRecord.getMessage())
        self.sigLog.emit(message)


class Window(QWidget):
    def __init__(self):
        super(Window, self).__init__()

        # Layout
        textBox = QTextEdit()
        textBox.setReadOnly(True)
        self.button = QPushButton('Click')
        vertLayout = QVBoxLayout()
        vertLayout.addWidget(textBox)
        vertLayout.addWidget(self.button)
        self.setLayout(vertLayout)

        # Connect button
        #self.button.clicked.connect(self.someProcess) # blocking
        self.button.clicked.connect(self.buttonPressed)

        # Thread
        self.bee = Worker(self.someProcess, ())
        self.bee.finished.connect(self.restoreUi)
        self.bee.terminated.connect(self.restoreUi)

        # Console handler
        consoleHandler = ConsoleWindowLogHandler()
        consoleHandler.sigLog.connect(textBox.append)
        logger.addHandler(consoleHandler)

    def buttonPressed(self):
        self.button.setEnabled(False)
        self.bee.start()

    def someProcess(self):
        logger.error("starting")
        for i in range(10):
            logger.error("line%d" % i)
            time.sleep(2)

    def restoreUi(self):
        self.button.setEnabled(True)


class Worker(QThread):
    def __init__(self, func, args):
        super(Worker, self).__init__()
        self.func = func
        self.args = args

    def run(self):
        self.func(*self.args)


def main():
    from qtpy.QtWidgets import QApplication
    app = QApplication(sys.argv)
    window = Window()
    window.show()
    sys.exit(app.exec_())


if __name__ == "__main__":
    main()

Footman

Answer 3

Translating JoeXinfa's answer to PyQt5:

import sys
import time
import logging
from PyQt5.QtCore import QObject, pyqtSignal, QThread
from PyQt5.QtWidgets import QWidget, QTextEdit, QPushButton, QVBoxLayout, QApplication

logger = logging.getLogger(__name__)


class ConsoleWindowLogHandler(logging.Handler, QObject):
    sigLog = pyqtSignal(str)
    def __init__(self):
        logging.Handler.__init__(self)
        QObject.__init__(self)

    def emit(self, logRecord):
        message = str(logRecord.getMessage())
        self.sigLog.emit(message)


class Window(QWidget):
    def __init__(self):
        super(Window, self).__init__()

        # Layout
        textBox = QTextEdit()
        textBox.setReadOnly(True)
        self.button = QPushButton('Click')
        vertLayout = QVBoxLayout()
        vertLayout.addWidget(textBox)
        vertLayout.addWidget(self.button)
        self.setLayout(vertLayout)

        # Connect button
        #self.button.clicked.connect(self.someProcess) # blocking
        self.button.clicked.connect(self.buttonPressed)

        # Thread
        self.bee = Worker(self.someProcess, ())
        self.bee.finished.connect(self.restoreUi)
        self.bee.terminate()

        # Console handler
        consoleHandler = ConsoleWindowLogHandler()
        consoleHandler.sigLog.connect(textBox.append)
        logger.addHandler(consoleHandler)

    def buttonPressed(self):
        self.button.setEnabled(False)
        self.bee.start()

    def someProcess(self):
        logger.error("starting")
        for i in range(10):
            logger.error("line%d" % i)
            time.sleep(2)

    def restoreUi(self):
        self.button.setEnabled(True)


class Worker(QThread):
    def __init__(self, func, args):
        super(Worker, self).__init__()
        self.func = func
        self.args = args

    def run(self):
        self.func(*self.args)


def main():
    app = QApplication(sys.argv)
    window = Window()
    window.show()
    sys.exit(app.exec_())


if __name__ == "__main__":
    main()

Ern

Answer 4

Here is another method. In this example, I add a StreamHandler to the logger that writes to a buffer by inheriting from both QObject and StringIO: When the handler encounters a non-empty string, the bufferMessage signal is emitted and captured in the on_bufferMessage slot.

#!/usr/bin/env python
#-*- coding:utf-8 -*-

import logging, StringIO, time

from PyQt4 import QtCore, QtGui

class logBuffer(QtCore.QObject, StringIO.StringIO):
    bufferMessage = QtCore.pyqtSignal(str)

    def __init__(self, *args, **kwargs):
        QtCore.QObject.__init__(self)
        StringIO.StringIO.__init__(self, *args, **kwargs)

    def write(self, message):
        if message:
            self.bufferMessage.emit(unicode(message))

        StringIO.StringIO.write(self, message)

class myThread(QtCore.QThread):
    def __init__(self, parent=None):
        super(myThread, self).__init__(parent)
        self.iteration = None

    def start(self):
        self.iteration = 3

        return super(myThread, self).start()

    def run(self):        
        while self.iteration:
            logging.info("Hello from thread {0}! {1}".format(0, self.iteration))
            self.iteration -= 1

            time.sleep(3)

class myThread1(QtCore.QThread):
    def __init__(self, parent=None):
        super(myThread1, self).__init__(parent)
        self.iteration = None
        self.logger = logging.getLogger(__name__)

    def start(self):
        self.iteration = 3

        return super(myThread1, self).start()

    def run(self):        
        time.sleep(1)
        while self.iteration:
            self.logger.info("Hello from thread {0}! {1}".format(1, self.iteration))
            self.iteration -= 1

            time.sleep(3)


class myWindow(QtGui.QWidget):
    def __init__(self, parent=None):
        super(myWindow, self).__init__(parent)

        self.pushButton = QtGui.QPushButton(self)
        self.pushButton.setText("Send Log Message")
        self.pushButton.clicked.connect(self.on_pushButton_clicked)

        self.pushButtonThread = QtGui.QPushButton(self)
        self.pushButtonThread.setText("Start Threading")
        self.pushButtonThread.clicked.connect(self.on_pushButtonThread_clicked)

        self.lineEdit = QtGui.QLineEdit(self)
        self.lineEdit.setText("Hello!")

        self.label = QtGui.QLabel(self)

        self.layout = QtGui.QVBoxLayout(self)
        self.layout.addWidget(self.lineEdit)
        self.layout.addWidget(self.pushButton)
        self.layout.addWidget(self.pushButtonThread)
        self.layout.addWidget(self.label)

        self.logBuffer = logBuffer()
        self.logBuffer.bufferMessage.connect(self.on_logBuffer_bufferMessage)

        logFormatter = logging.Formatter('%(levelname)s: %(message)s')

        logHandler = logging.StreamHandler(self.logBuffer)
        logHandler.setFormatter(logFormatter)

        self.logger = logging.getLogger()
        self.logger.setLevel(logging.INFO)
        self.logger.addHandler(logHandler)

        self.thread = myThread(self)
        self.thread1 = myThread1(self)

    @QtCore.pyqtSlot()
    def on_pushButtonThread_clicked(self):
        self.thread.start()
        self.thread1.start()

    @QtCore.pyqtSlot(str)
    def on_logBuffer_bufferMessage(self, message):
        self.label.setText(message)

    @QtCore.pyqtSlot()
    def on_pushButton_clicked(self):
        message = self.lineEdit.text()
        self.logger.info(message if message else "No new messages")

if __name__ == "__main__":
    import sys

    app = QtGui.QApplication(sys.argv)
    app.setApplicationName('myWindow')

    main = myWindow()
    main.show()

    sys.exit(app.exec_())

The best thing about this method is that you can log messages from modules/threads of you main app without having to keep any reference to the logger, for example, by calling logging.log(logging.INFO, logging_message) or logging.info(logging_message)

Katykatya

Oh that's excellent! I might use this for another piece of code that I have. My current piece of code relies on several log handlers, so I do need a reference to logger. But thanks to your example, I now see how to write new-style signal and slots. Thanks! – Denature

@Denature I'm glad you could find it useful, but I hate to insist! :) With this code you do not have to keep any kind of reference to the logger as long as it is in the same Python interpreter process. My answer demonstrates this by calling logging.info instead of logger.info from myThread... you can also direct the output into a specific logger by calling logging.getLogger('someLogger') – Katykatya

how can one add custom log handlers without a logging instance? I need that functionality, and logging doesn't have a addHandler method. I'm not sure I understand (but mind you, this is the first time I'm using the logging module, so I don't understand the nuances!) – Denature

I'll be happy to help you with that, please post it as a question and mention me in a comment here – Katykatya