Skip to content

Set timed_out attrib on reports for logging customization #90

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Closed
wants to merge 3 commits into from
Closed
Show file tree
Hide file tree
Changes from 2 commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
34 changes: 34 additions & 0 deletions README.rst
Original file line number Diff line number Diff line change
Expand Up @@ -215,6 +215,40 @@ debugging frameworks modules OR if pytest itself drops you into a pdb
session using ```--pdb``` or similar.


Logging Customization
=====================

This plugin sets a new ``timed_out`` attribute on report objects via
the ``pytest_runtest_makereport`` hook. This way logging can be
customized in your ``conftest.py`` by implementing
``pytest_report_teststatus``::

@pytest.hookimpl(tryfirst=True)
def pytest_report_teststatus(report, **kwargs):
"""Adapted from
https://github.com/pytest-dev/pytest/blob/38d8deb74d95077ebf189440ca047e14f8197da1/src/_pytest/runner.py#L202
"""
d = "%.2f" % getattr(report, "duration", -1.0)
if report.passed:
return "passed", "P", "PASSED (%s)" % d
if getattr(report, "timed_out", False):
return "failed", "T", "TIMEOUT (%s)" % d
if report.failed:
return "failed", "F", "FAILED (%s)" % d
return None

This will print ``T`` (or ``TIMEOUT (5.00)`` if verbose) in case a test
times out. You might want to restrict this to the *call* phase because
the above code would print three symbols (lines) per test; one for each of
the three test phases *setup*, *call* and *teardown* (use ``report.when``).
Remark: If a ``report`` has the ``timed_out`` attribute, it can have three
values: ``True`` or ``False`` if the test ran and a timeout appeared or did
not appear. If the value is ``None``, the item might have been run with
timeout being disabled or something unexpected has happened. This way all
checks are reliable, and ``report.timed_out`` still works, because
``bool(None)`` is ``False``.


Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Great docs update! ❤️

Changelog
=========

Expand Down
18 changes: 18 additions & 0 deletions pytest_timeout.py
Original file line number Diff line number Diff line change
Expand Up @@ -99,6 +99,7 @@ def pytest_runtest_protocol(item):
teardown, then this hook installs the timeout. Otherwise
pytest_runtest_call is used.
"""
item.pytest_timeout__timed_out = None
func_only = get_func_only_setting(item)
if func_only is False:
timeout_setup(item)
Expand Down Expand Up @@ -136,6 +137,20 @@ def pytest_report_header(config):
]


@pytest.hookimpl(hookwrapper=True)
def pytest_runtest_makereport(item, call):
"""Set report.timed_out after it is generated by pytest_runtest_makereport.

This method is a wrapper that sets timed_out if the call has a matching excinfo
value. Note that in that case report.failed and report.timed_out are true (both!).
"""
r = yield
if not hasattr(r, "get_result"):
return
report = r.get_result()
report.timed_out = getattr(item, "pytest_timeout__timed_out", None)


@pytest.hookimpl(tryfirst=True)
def pytest_exception_interact(node):
"""Stop the timeout when pytest enters pdb in post-mortem mode."""
Expand Down Expand Up @@ -227,6 +242,7 @@ def timeout_teardown(item):
cancel = getattr(item, "cancel_timeout", None)
if cancel:
cancel()
item.pytest_timeout__timed_out = False


def get_env_settings(config):
Expand Down Expand Up @@ -366,6 +382,7 @@ def timeout_sigalrm(item, timeout):
if is_debugging():
return
__tracebackhide__ = True
item.pytest_timeout__timed_out = True
nthreads = len(threading.enumerate())
if nthreads > 1:
write_title("Timeout", sep="+")
Expand All @@ -383,6 +400,7 @@ def timeout_timer(item, timeout):
"""
if is_debugging():
return
item.pytest_timeout__timed_out = True # for consistency
try:
capman = item.config.pluginmanager.getplugin("capturemanager")
if capman:
Expand Down
33 changes: 33 additions & 0 deletions test_pytest_timeout.py
Original file line number Diff line number Diff line change
Expand Up @@ -482,3 +482,36 @@ def custom_trace(*args):
module.custom_trace = custom_trace

assert pytest_timeout.is_debugging(custom_trace)


def test_logging_customization(testdir):
testdir.makepyfile(
conftest="""
import pytest

@pytest.hookimpl(hookwrapper=True)
def pytest_runtest_makereport(item, call):
r = yield
if not hasattr(r, "get_result"):
return
report = r.get_result()
timed_out = False
if hasattr(call.excinfo, "value"):
msg = getattr(call.excinfo.value, "msg", None)
if isinstance(msg, str) and msg.startswith("Timeout >"):
timed_out = True
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

What would you think of using item.name to know whether the test should have timed out or not? Or even go further and just write two tests, or rather parametrise this test.

Copy link
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I am not sure if the name thing would work: test_suppresses_timeout_when_debugger_is_entered contains the word timeout but the test asserts that no timeout occurs. test_ini_method does not contain the string timeout but the test expects a timeout. There is no correlation between the names and the expected outcome. Also, using item.name might break the test when another feature pr adds another test. Seeing an unrelated test fail might become an unnecessary nightmare for the developer of the other feature. The only possible way would be to create a decorator @expect(timeout: Optional[bool]) and mark all tests. I am not sure if that is ideal. The call.excinfo.value method should be reliable and detect a timeout if it has occurred I think. Ideally, we could shift this conftest into a wrapper such that all tests are run with this test. That would probably also require a separate decorator for all existing tests though. What'd be your preference?
I'll experiment with it later this week and maybe I can come up with something more general...

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

regarding names, your test only contains two test names: test_times_out and test_does_not_time_out. The rest of the tests in this file are isolated from your test.

But I think it's even better to parametrise this test and make a different conftest.py based on the parameter so it knows whether to expect a timeout or not

Copy link
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Okay, I'll try to push it into as many tests as I can. However, my schedule has changed a little so I had to postpone working on this to next week...

Copy link
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I managed to get a wide-ranging implementation of the test for this pr working. It is very experimental let's say if not completely opaque and ugly.

It uses a pytest hook to create a conftest.py file before every test in the pytest-timeout suite is run. The thing that annoys me most is that I am not sure if this can be easily identified as the source of tests failing. Hence I marked that last commit as temporary; either it shall be discarded or possibly changed merged into the previous one.
Here is the commit message:

TEMPORARY commit: implement test for #90

This commit implements a test for #90 (logging customisation) that is
wide-ranging as it (ab)uses all other tests in the suite to also check
that the feature implemented in the above-mentioned pull request works.

As the implications are currently not completely clear, this commit is
marked as temporary and will either be discarded or merged into a
previous commit in the pr before it is merged.

The most important open question is:
If a change breaks #90, will this be visible to the developers?
The tests in the suite run other tests using the `tempdir` facility and
this hacky implementation just adds a `conftest.py` to each of the
temporary directories. Will the message from the assert message ever
reach the output of the pytest-timeout test suite? Can that be somehow
enforced from within the child-tests or their pytest runner?

Copy link
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@flub: If you find the time, I'd be glad to hear your opinion about that idea.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

hi! again, thanks for your patience.
I don't think this is the right direction though, we shouldn't be changing the entire test suite, just adding a few tests for the new functionality. I think your original test was fine as structure and overall approach, i thought the only tweak needed was to split it into two tests so you didn't have to try and detect whether the test was was going to time out or not. Since both tests are rather similar i suggested parametrisation as a shortcut, but that's not strictly required if you're not sure how to use that.

assert bool(getattr(report, "timed_out", None)) == timed_out
"""
)
testdir.makepyfile(
"""
import time

def test_times_out():
time.sleep(2)

def test_does_not_time_out():
time.sleep(0.1)
"""
)
testdir.runpytest("--timeout=1", "-ss")