Update documentation for Qt logging

Author: nicoddemus

docs/index.rst

@@ -66,8 +66,8 @@ activate a new fresh environment and execute::
 
 .. _virtualenv: http://virtualenv.readthedocs.org/
 
-Quick Tutorial
-==============
+Tutorial
+========
 
 ``pytest-qt`` registers a new fixture_ named ``qtbot``, which acts as *bot* in the sense
 that it can send keyboard and mouse events to any widgets being tested. This way, the programmer
@@ -261,13 +261,225 @@ You can disable the automatic exception hook on individual tests by using a
 
 Or even disable it for your entire project in your ``pytest.ini`` file::
 
+.. code-block:: ini
+
     [pytest]
     qt_no_exception_capture = 1
 
 This might be desirable if you plan to install a custom exception hook.
 
+Qt Logging Capture
+==================
+
+.. versionadded:: 1.4
+
+Qt features its own logging mechanism through ``qInstallMsgHandler``
+(``qInstallMessageHandler`` on Qt5) and ``qDebug``, ``qWarning``, ``qCritical``
+functions. These are used by Qt to print warning messages when internal errors
+occur.
+
+``pytest-qt`` automatically captures these messages and displays them when a
+test fails, similar to what ``pytest`` does for ``stderr``  and ``stdout`` and
+the `pytest-catchlog <https://github.com/eisensheng/pytest-catchlog>`_ plugin.
+For example:
+
+.. code-block:: python
+
+    from pytestqt.qt_compat import qWarning
+
+    def do_something():
+        qWarning('this is a WARNING message')
+
+    def test_foo(qtlog):
+        do_something()
+        assert 0
+
+
+.. code-block:: bash
+
+    $ py.test test.py -q
+    F
+    ================================== FAILURES ===================================
+    _________________________________ test_types __________________________________
+
+        def test_foo():
+            do_something()
+    >       assert 0
+    E       assert 0
+
+    test.py:8: AssertionError
+    ---------------------------- Captured Qt messages -----------------------------
+    QtWarningMsg: this is a WARNING message
+    1 failed in 0.01 seconds
+
+
+Qt logging capture can be disabled altogether by passing the ``--no-qt-log``
+to the command line, which will fallback to the default Qt bahavior of printing
+emitted messages directly to ``stderr``:
+
+.. code-block:: bash
+
+    py.test test.py -q --no-qt-log
+    F
+    ================================== FAILURES ===================================
+    _________________________________ test_types __________________________________
+
+        def test_foo():
+            do_something()
+    >       assert 0
+    E       assert 0
+
+    test.py:8: AssertionError
+    ---------------------------- Captured stderr call -----------------------------
+    this is a WARNING message
+
+
+``pytest-qt`` also provides a ``qtlog`` fixture, which tests can use
+to check if certain messages were emitted during a test::
+
+    def do_something():
+        qWarning('this is a WARNING message')
+
+    def test_foo(qtlog):
+        do_something()
+        emitted = [(m.type, m.message.strip()) for m in qtlog.records]
+        assert emitted == [(QtWarningMsg, 'this is a WARNING message')]
+
+Keep in mind that when ``--no-qt-log`` is passed in the command line,
+``qtlog.records`` will always be an empty list. See
+:class:`Record <pytestqt.plugin.Record>` for reference documentation on
+``Record`` objects.
+
+The output format of the messages can also be controlled by using the
+``--qt-log-format`` command line option, which accepts a string with standard
+``{}`` formatting which can make use of attribute interpolation of the record
+objects:
+
+.. code-block:: bash
+
+    $ py.test test.py --qt-log-format="{rec.when} {rec.type_name}: {rec.message}"
+
+Keep in mind that you can make any of the options above the default
+for your project by using pytest's standard ``addopts`` option in you
+``pytest.ini`` file:
+
+
+.. code-block:: ini
+
+    [pytest]
+    qt_log_format = {rec.when} {rec.type_name}: {rec.message}
+
+
+Automatically failing tests when logging messages are emitted
+-------------------------------------------------------------
+
+Printing messages to ``stderr`` is not the best solution to notice that
+something might not be working as expected, specially when running in a
+continuous integration server where errors in logs are rarely noticed.
+
+You can configure ``pytest-qt`` to automatically fail a test if it emits
+a message of a certain level or above using the ``qt_log_level_fail`` ini
+option:
+
+
+.. code-block:: ini
+
+    [pytest]
+    qt_log_level_fail = CRITICAL
+
+With this configuration, any test which emits a CRITICAL message or above
+will fail, even if no actual asserts fail within the test:
+
+.. code-block:: python
+
+    from pytestqt.qt_compat import qCritical
+
+    def do_something():
+        qCritical('WM_PAINT failed')
+
+    def test_foo(qtlog):
+        do_something()
+
+
+.. code-block:: bash
+
+    >py.test test.py --color=no -q
+    F
+    ================================== FAILURES ===================================
+    __________________________________ test_foo ___________________________________
+    test.py:5: Failure: Qt messages with level CRITICAL or above emitted
+    ---------------------------- Captured Qt messages -----------------------------
+    QtCriticalMsg: WM_PAINT failed
+
+The possible values for ``qt_log_level_fail`` are:
+
+* ``NO``: disables test failure by log messages.
+* ``DEBUG``: messages emitted by ``qDebug`` function or above.
+* ``WARNING``: messages emitted by ``qWarning`` function or above.
+* ``CRITICAL``: messages emitted by ``qCritical`` function only.
+
+If some failures are known to happen and considered harmless, they can
+be ignored by using the ``qt_log_ignore`` ini option, which
+is a list of regular expressions matched using ``re.search``:
+
+.. code-block:: ini
+
+    [pytest]
+    qt_log_level_fail = CRITICAL
+    qt_log_ignore =
+        WM_DESTROY.*sent
+        WM_PAINT failed
+
+.. code-block:: bash
+
+    py.test test.py --color=no -q
+    .
+    1 passed in 0.01 seconds
+
+
+Messages which do not match any of the regular expressions
+defined by ``qt_log_ignore`` make tests fail as usual:
+
+.. code-block:: python
+
+    def do_something():
+        qCritical('WM_PAINT not handled')
+        qCritical('QObject: widget destroyed in another thread')
+
+    def test_foo(qtlog):
+        do_something()
+
+.. code-block:: bash
+
+    py.test test.py --color=no -q
+    F
+    ================================== FAILURES ===================================
+    __________________________________ test_foo ___________________________________
+    test.py:6: Failure: Qt messages with level CRITICAL or above emitted
+    ---------------------------- Captured Qt messages -----------------------------
+    QtCriticalMsg: WM_PAINT not handled  (IGNORED)
+    QtCriticalMsg: QObject: widget destroyed in another thread
+
+
+You can also override ``qt_log_level_fail`` and ``qt_log_ignore`` settins
+from ``pytest.ini`` in some tests by using a mark with the same name:
+
+.. code-block:: python
+
+    def do_something():
+        qCritical('WM_PAINT not handled')
+        qCritical('QObject: widget destroyed in another thread')
+
+    @pytest.mark.qt_log_level_fail('CRITICAL')
+    @pytest.mark.qt_log_ignore('WM_DESTROY.*sent', 'WM_PAINT failed')
+    def test_foo(qtlog):
+        do_something()
+
+Reference
+=========
+
 QtBot
-=====
+-----
 
 .. module:: pytestqt.plugin
 .. autoclass:: QtBot
@@ -280,6 +492,11 @@ Signals
 
 .. autoclass:: SignalTimeoutError
 
+Log Capture
+-----------
+
+.. autoclass:: Record
+
 Versioning
 ==========
 

pytestqt/plugin.py

@@ -294,8 +294,8 @@ def waitSignals(self, signals=None, timeout=1000, raising=False):
         Stops current test until all given signals are triggered.
 
         Used to stop the control flow of a test until all (and only
-        all) signals are emitted, or a number of milliseconds, specified by
-        ``timeout``, has elapsed.
+        all) signals are emitted or the number of milliseconds specified by
+        ``timeout`` has elapsed.
 
         Best used as a context manager::
 
@@ -723,14 +723,15 @@ def records(self):
 class Record(object):
     """Hold information about a message sent by one of Qt log functions.
 
-    :attr str message: message contents.
-    :attr Qt.QtMsgType type: enum that identifies message type
-    :attr str type_name: `type` as a string
-    :attr str log_type_name:
-        type name similar to the logging package, for example ``DEBUG``,
-        ``WARNING``, etc.
-    :attr datetime.datetime when: when the message was sent
-    :attr ignored: If this record matches a regex from the "qt_log_ignore"
+    :ivar str message: message contents.
+    :ivar Qt.QtMsgType type: enum that identifies message type
+    :ivar str type_name: ``type`` as string: ``"QtDebugMsg"``,
+        ``"QtWarningMsg"`` or ``"QtCriticalMsg"``.
+    :ivar str log_type_name:
+        type name similar to the logging package: ``DEBUG``,
+        ``WARNING`` and ``CRITICAL``.
+    :ivar datetime.datetime when: when the message was captured
+    :ivar bool ignored: If this record matches a regex from the "qt_log_ignore"
         option.
     """