test_logging.py

import datetime

import pytest

from pytestqt.qt_compat import qt_api


# qInfo is not exposed by PySide6 < 6.8.2 (#225)
HAS_QINFO = qt_api.qInfo is not None


@pytest.mark.parametrize("test_succeeds", [True, False])
@pytest.mark.parametrize("qt_log", [True, False])
def test_basic_logging(testdir, test_succeeds, qt_log):
    """
    Test Qt logging capture output.

    :type testdir: _pytest.pytester.TmpTestdir
    """
    testdir.makepyfile(
        f"""
        import sys
        from pytestqt.qt_compat import qt_api

        def to_unicode(s):
            return s.decode('utf-8', 'replace') if isinstance(s, bytes) else s

        def print_msg(msg_type, context, message):
            sys.stderr.write(to_unicode(message) + '\\n')
        qt_api.QtCore.qInstallMessageHandler(print_msg)

        def test_types():
            if {HAS_QINFO}:
                qt_api.qInfo('this is an INFO message')
            qt_api.qDebug('this is a DEBUG message')
            qt_api.qWarning('this is a WARNING message')
            qt_api.qCritical('this is a CRITICAL message')
            assert {test_succeeds}
        """
    )
    res = testdir.runpytest(*(["--no-qt-log"] if not qt_log else []))
    if test_succeeds:
        assert "Captured Qt messages" not in res.stdout.str()
        assert "Captured stderr call" not in res.stdout.str()
    else:
        if qt_log:
            res.stdout.fnmatch_lines(
                [
                    "*-- Captured Qt messages --*",
                    *(["*QtInfoMsg: this is an INFO message*"] if HAS_QINFO else []),
                    "*QtDebugMsg: this is a DEBUG message*",
                    "*QtWarningMsg: this is a WARNING message*",
                    "*QtCriticalMsg: this is a CRITICAL message*",
                ]
            )
        else:
            res.stdout.fnmatch_lines(
                [
                    "*-- Captured stderr call --*",
                    *(["this is an INFO message*"] if HAS_QINFO else []),
                    "this is a DEBUG message*",
                    "this is a WARNING message*",
                    "this is a CRITICAL message*",
                ]
            )


def test_qtlog_fixture(qtlog):
    """
    Test qtlog fixture.
    """
    expected = []
    if HAS_QINFO:
        qt_api.qInfo("this is an INFO message")
        expected.append((qt_api.QtCore.QtMsgType.QtInfoMsg, "this is an INFO message"))

    qt_api.qDebug("this is a DEBUG message")
    qt_api.qWarning("this is a WARNING message")
    qt_api.qCritical("this is a CRITICAL message")

    expected += [
        (qt_api.QtCore.QtMsgType.QtDebugMsg, "this is a DEBUG message"),
        (qt_api.QtCore.QtMsgType.QtWarningMsg, "this is a WARNING message"),
        (qt_api.QtCore.QtMsgType.QtCriticalMsg, "this is a CRITICAL message"),
    ]

    records = [(m.type, m.message.strip()) for m in qtlog.records]
    assert records == expected
    # `records` attribute is read-only
    with pytest.raises(AttributeError):
        qtlog.records = []


@pytest.mark.parametrize("arg", ["--no-qt-log", "--capture=no", "-s"])
def test_fixture_with_logging_disabled(testdir, arg):
    """
    Test that qtlog fixture doesn't capture anything if logging is disabled
    in the command line.

    :type testdir: _pytest.pytester.TmpTestdir
    """
    testdir.makepyfile(
        """
        from pytestqt.qt_compat import qt_api

        def test_types(qtlog):
            qt_api.qWarning('message')
            assert qtlog.records == []
        """
    )
    res = testdir.runpytest(arg)
    res.stdout.fnmatch_lines("*1 passed*")


@pytest.mark.parametrize("use_context_manager", [True, False])
def test_disable_qtlog_context_manager(testdir, use_context_manager):
    """
    Test qtlog.disabled() context manager.

    :type testdir: _pytest.pytester.TmpTestdir
    """
    testdir.makeini(
        """
        [pytest]
        qt_log_level_fail = CRITICAL
        """
    )

    if use_context_manager:
        code = "with qtlog.disabled():"
    else:
        code = "if 1:"

    testdir.makepyfile(
        """
        from pytestqt.qt_compat import qt_api
        def test_1(qtlog):
            {code}
                qt_api.qCritical('message')
        """.format(
            code=code
        )
    )
    res = testdir.inline_run()
    passed = 1 if use_context_manager else 0
    res.assertoutcome(passed=passed, failed=int(not passed))


@pytest.mark.parametrize("use_mark", [True, False])
def test_disable_qtlog_mark(testdir, use_mark):
    """
    Test mark which disables logging capture for a test.

    :type testdir: _pytest.pytester.TmpTestdir
    """
    testdir.makeini(
        """
        [pytest]
        qt_log_level_fail = CRITICAL
        """
    )
    mark = "@pytest.mark.no_qt_log" if use_mark else ""

    testdir.makepyfile(
        """
        from pytestqt.qt_compat import qt_api
        import pytest
        {mark}
        def test_1():
            qt_api.qCritical('message')
        """.format(
            mark=mark
        )
    )
    res = testdir.inline_run()
    passed = 1 if use_mark else 0
    res.assertoutcome(passed=passed, failed=int(not passed))


def test_logging_formatting(testdir):
    """
    Test custom formatting for logging messages.

    :type testdir: _pytest.pytester.TmpTestdir
    """
    testdir.makepyfile(
        """
        from pytestqt.qt_compat import qt_api
        def test_types():
            qt_api.qWarning('this is a WARNING message')
            assert 0
        """
    )
    f = "{rec.type_name} {rec.log_type_name} {rec.when:%Y-%m-%d}: {rec.message}"
    res = testdir.runpytest(f"--qt-log-format={f}")
    today = "{:%Y-%m-%d}".format(datetime.datetime.now())
    res.stdout.fnmatch_lines(
        [
            "*-- Captured Qt messages --*",
            f"QtWarningMsg WARNING {today}: this is a WARNING message*",
        ]
    )


@pytest.mark.parametrize(
    "level, expect_passes", [("DEBUG", 1), ("WARNING", 2), ("CRITICAL", 3), ("NO", 4)]
)
def test_logging_fails_tests(testdir, level, expect_passes):
    """
    Test qt_log_level_fail ini option.

    :type testdir: _pytest.pytester.TmpTestdir
    """
    testdir.makeini(
        """
        [pytest]
        qt_log_level_fail = {level}
        """.format(
            level=level
        )
    )
    testdir.makepyfile(
        """
        from pytestqt.qt_compat import qt_api
        def test_1():
            qt_api.qDebug('this is a DEBUG message')
        def test_2():
            qt_api.qWarning('this is a WARNING message')
        def test_3():
            qt_api.qCritical('this is a CRITICAL message')
        def test_4():
            assert 1
        """
    )
    res = testdir.runpytest()
    lines = []
    if level != "NO":
        lines.extend(
            [
                "*Failure: Qt messages with level {} or above emitted*".format(
                    level.upper()
                ),
                "*-- Captured Qt messages --*",
            ]
        )
    lines.append(f"*{expect_passes} passed*")
    res.stdout.fnmatch_lines(lines)


def test_logging_fails_tests_mark(testdir):
    """
    Test mark overrides what's configured in the ini file.

    :type testdir: _pytest.pytester.TmpTestdir
    """
    testdir.makeini(
        """
        [pytest]
        qt_log_level_fail = CRITICAL
        """
    )
    testdir.makepyfile(
        """
        from pytestqt.qt_compat import qWarning
        import pytest
        @pytest.mark.qt_log_level_fail('WARNING')
        def test_1():
            qWarning('message')
        """
    )
    res = testdir.inline_run()
    res.assertoutcome(failed=1)


def test_logging_fails_ignore(testdir):
    """
    Test qt_log_ignore config option.

    :type testdir: _pytest.pytester.TmpTestdir
    """
    testdir.makeini(
        """
        [pytest]
        qt_log_level_fail = CRITICAL
        qt_log_ignore =
            WM_DESTROY.*sent
            WM_PAINT not handled
        """
    )
    testdir.makepyfile(
        """
        from pytestqt.qt_compat import qt_api
        import pytest

        def test1():
            qt_api.qCritical('a critical message')
        def test2():
            qt_api.qCritical('WM_DESTROY was sent')
        def test3():
            qt_api.qCritical('WM_DESTROY was sent')
            assert 0
        def test4():
            qt_api.qCritical('WM_PAINT not handled')
            qt_api.qCritical('another critical message')
        """
    )
    res = testdir.runpytest()
    lines = [
        # test1 fails because it has emitted a CRITICAL message and that message
        # does not match any regex in qt_log_ignore
        "*_ test1 _*",
        "*Failure: Qt messages with level CRITICAL or above emitted*",
        "*QtCriticalMsg: a critical message*",
        # test2 succeeds because its message matches qt_log_ignore
        # test3 fails because of an assert, but the ignored message should
        # still appear in the failure message
        "*_ test3 _*",
        "*AssertionError*",
        "*QtCriticalMsg: WM_DESTROY was sent*(IGNORED)*",
        # test4 fails because one message is ignored but the other isn't
        "*_ test4 _*",
        "*Failure: Qt messages with level CRITICAL or above emitted*",
        "*QtCriticalMsg: WM_PAINT not handled*(IGNORED)*",
        "*QtCriticalMsg: another critical message*",
        # summary
        "*3 failed, 1 passed*",
    ]
    res.stdout.fnmatch_lines(lines)


@pytest.mark.parametrize("message", ["match-global", "match-mark"])
@pytest.mark.parametrize("marker_args", ["'match-mark', extend=True", "'match-mark'"])
def test_logging_mark_with_extend(testdir, message, marker_args):
    """
    Test qt_log_ignore mark with extend=True.

    :type testdir: _pytest.pytester.TmpTestdir
    """
    testdir.makeini(
        """
        [pytest]
        qt_log_level_fail = CRITICAL
        qt_log_ignore = match-global
        """
    )
    testdir.makepyfile(
        """
        from pytestqt.qt_compat import qt_api
        import pytest

        @pytest.mark.qt_log_ignore({marker_args})
        def test1():
            qt_api.qCritical('{message}')
        """.format(
            message=message, marker_args=marker_args
        )
    )
    res = testdir.inline_run()
    res.assertoutcome(passed=1, failed=0)


@pytest.mark.parametrize(
    "message, error_expected", [("match-global", True), ("match-mark", False)]
)
def test_logging_mark_without_extend(testdir, message, error_expected):
    """
    Test qt_log_ignore mark with extend=False.

    :type testdir: _pytest.pytester.TmpTestdir
    """
    testdir.makeini(
        """
        [pytest]
        qt_log_level_fail = CRITICAL
        qt_log_ignore = match-global
        """
    )
    testdir.makepyfile(
        """
        from pytestqt.qt_compat import qt_api
        import pytest

        @pytest.mark.qt_log_ignore('match-mark', extend=False)
        def test1():
            qt_api.qCritical('{message}')
        """.format(
            message=message
        )
    )
    res = testdir.inline_run()

    if error_expected:
        res.assertoutcome(passed=0, failed=1)
    else:
        res.assertoutcome(passed=1, failed=0)


def test_logging_mark_with_invalid_argument(testdir):
    """
    Test qt_log_ignore mark with invalid keyword argument.

    :type testdir: _pytest.pytester.TmpTestdir
    """
    testdir.makepyfile(
        """
        import pytest

        @pytest.mark.qt_log_ignore('match-mark', does_not_exist=True)
        def test1():
            pass
        """
    )
    res = testdir.runpytest()
    lines = [
        "*= ERRORS =*",
        "*_ ERROR at setup of test1 _*",
        "*ValueError: Invalid keyword arguments in {'does_not_exist': True} "
        "for qt_log_ignore mark.",
        # summary
        "*= 1 error in*",
    ]
    res.stdout.fnmatch_lines(lines)


@pytest.mark.parametrize("apply_mark", [True, False])
def test_logging_fails_ignore_mark_multiple(testdir, apply_mark):
    """
    Make sure qt_log_ignore mark supports multiple arguments.

    :type testdir: _pytest.pytester.TmpTestdir
    """
    if apply_mark:
        mark = '@pytest.mark.qt_log_ignore("WM_DESTROY", "WM_PAINT")'
    else:
        mark = ""
    testdir.makepyfile(
        """
        from pytestqt.qt_compat import qt_api
        import pytest
        @pytest.mark.qt_log_level_fail('CRITICAL')
        {mark}
        def test1():
            qt_api.qCritical('WM_PAINT was sent')
        """.format(
            mark=mark
        )
    )
    res = testdir.inline_run()
    passed = 1 if apply_mark else 0
    res.assertoutcome(passed=passed, failed=int(not passed))


def test_lineno_failure(testdir):
    """
    Test that tests when failing because log messages were emitted report
    the correct line number.

    :type testdir: _pytest.pytester.TmpTestdir
    """
    testdir.makeini(
        """
        [pytest]
        qt_log_level_fail = WARNING
        """
    )
    testdir.makepyfile(
        """
        from pytestqt.qt_compat import qt_api
        def test_foo():
            assert foo() == 10
        def foo():
            qt_api.qWarning('this is a WARNING message')
            return 10
        """
    )
    res = testdir.runpytest()
    if qt_api.is_pyqt:
        res.stdout.fnmatch_lines(
            [
                "*test_lineno_failure.py:2: Failure*",
                "*test_lineno_failure.py:foo:5:*",
                "    QtWarningMsg: this is a WARNING message",
            ]
        )
    else:
        res.stdout.fnmatch_lines(
            [
                "*test_lineno_failure.py:2: Failure*",
                "QtWarningMsg: this is a WARNING message",
            ]
        )


def test_context_none(testdir):
    """
    Sometimes PyQt will emit a context with some/all attributes set as None
    instead of appropriate file, function and line number.

    Test that when this happens the plugin doesn't break, and it filters
    out the context information.

    :type testdir: _pytest.pytester.TmpTestdir
    """
    testdir.makepyfile(
        """
        from pytestqt.qt_compat import qt_api

        def test_foo(request):
            log_capture = request.node.qt_log_capture
            context = log_capture._Context(None, None, 0, None)
            log_capture._handle_with_context(qt_api.QtCore.QtMsgType.QtWarningMsg,
                                             context, "WARNING message")
            assert 0
        """
    )
    res = testdir.runpytest()
    assert "*None:None:0:*" not in str(res.stdout)
    res.stdout.fnmatch_lines(["QtWarningMsg: WARNING message"])


def test_logging_broken_makereport(testdir):
    """
    Make sure logging's makereport hookwrapper doesn't hide exceptions.

    See https://github.com/pytest-dev/pytest-qt/issues/98

    :type testdir: _pytest.pytester.TmpTestdir
    """
    testdir.makepyfile(
        conftest="""
        import pytest

        @pytest.hookimpl(hookwrapper=True, tryfirst=True)
        def pytest_runtest_makereport(call):
            if call.when == 'call':
                raise Exception("This should not be hidden")
            yield
    """
    )
    p = testdir.makepyfile(
        """
        def test_foo():
            pass
        """
    )
    res = testdir.runpytest_subprocess(p)
    res.stdout.fnmatch_lines(["*This should not be hidden*"])