Skip to content
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.

Sign up for GitHub

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

Jump to bottom

Fixes to live logs #3175

Closed
wants to merge 3 commits into from
Closed

Fixes to live logs #3175

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
3 commits
Select commit Hold shift + click to select a range
1aa25ec
Also handle logstart and logfinish hooks
s0undt3ch Jan 31, 2018
53eaafe
Don't traceback on unkown sections.
s0undt3ch Jan 31, 2018
6dbb49f
Enable live logs is log_cli_level is passed/set explicitly
s0undt3ch Jan 31, 2018
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
29 changes: 22 additions & 7 deletions _pytest/logging.py
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -337,6 +337,11 @@ def __init__(self, config):
"""
self._config = config

# enable live logs if log_cli_level is explicitly set
log_cli_level = get_actual_log_level(self._config, 'log_cli_level', 'log_level')
if log_cli_level is not None:
# enable live logs if log_cli_level is explicitly set
config._inicache['log_cli'] = config._parser._inidict['log_cli'] = True
# enable verbose output automatically if live logging is enabled
if self._config.getini('log_cli') and not config.getoption('verbose'):
# sanity check: terminal reporter should not have been loaded at this point
Expand Down Expand Up @@ -371,18 +376,20 @@ def _runtest_for(self, item, when):
formatter=self.formatter, level=self.log_level) as log_handler:
if self.log_cli_handler:
self.log_cli_handler.set_when(when)
if not hasattr(item, 'catch_log_handlers'):
if item and not hasattr(item, 'catch_log_handlers'):
item.catch_log_handlers = {}
item.catch_log_handlers[when] = log_handler
item.catch_log_handler = log_handler
if item:
item.catch_log_handlers[when] = log_handler
item.catch_log_handler = log_handler
try:
yield # run test
finally:
del item.catch_log_handler
if item:
del item.catch_log_handler
if when == 'teardown':
Copy link
Member

Choose a reason for hiding this comment

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

This should be indented (under if item:) right?

Copy link
Contributor Author

Choose a reason for hiding this comment

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

Not necessarily because item does exist on teardown. But it can be moved.

Copy link
Member

Choose a reason for hiding this comment

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

Oh you are right, well up to you!

del item.catch_log_handlers

if self.print_logs:
if self.print_logs and item:
# Add a captured log section to the report.
log = log_handler.stream.getvalue().strip()
item.add_report_section(when, 'log', log)
Expand All @@ -402,9 +409,17 @@ def pytest_runtest_teardown(self, item):
with self._runtest_for(item, 'teardown'):
yield

@pytest.hookimpl(hookwrapper=True)
def pytest_runtest_logstart(self):
if self.log_cli_handler:
self.log_cli_handler.reset()
with self._runtest_for(None, 'start'):
yield

@pytest.hookimpl(hookwrapper=True)
def pytest_runtest_logfinish(self):
with self._runtest_for(None, 'finish'):
yield

@pytest.hookimpl(hookwrapper=True)
def pytest_runtestloop(self, session):
Expand Down Expand Up @@ -474,10 +489,10 @@ def emit(self, record):
if self.capture_manager is not None:
self.capture_manager.suspend_global_capture()
try:
if not self._first_record_emitted or self._when == 'teardown':
if not self._first_record_emitted or self._when in ('teardown', 'finish'):
self.stream.write('\n')
self._first_record_emitted = True
if not self._section_name_shown:
if not self._section_name_shown and self._when:
self.stream.section('live log ' + self._when, sep='-', bold=True)
self._section_name_shown = True
logging.StreamHandler.emit(self, record)
Expand Down
1 change: 1 addition & 0 deletions changelog/3175.bugfix
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -0,0 +1 @@
Don't traceback when logging on unknown(unhandled) sections.
1 change: 1 addition & 0 deletions changelog/3175.feature
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -0,0 +1 @@
Enable live logs is log_cli_level is passed/set explicitly
Copy link
Member

Choose a reason for hiding this comment

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

I'm not sure about this, I can imagine someone setting log_cli_level in their pytest.ini file so that they can enable/disable live logging in the command line without having to also pass the log level each time...

@Thisch what do you think?

Copy link
Contributor Author

Choose a reason for hiding this comment

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

In that case I think we need a CLI flag to enable live logs.

Copy link
Member

Choose a reason for hiding this comment

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

We have the log_cli configuration option, which can be changed directly in the command-line: -o log_cli=True. 😉

Copy link
Contributor

Choose a reason for hiding this comment

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

I'm not sure if setting log_cli_level on the command line or in an ini file should automatically set log_cli to True. I would prefer if we have a similar shortcut for live logging, like we have for disabling stream capturing (-s).

Copy link
Contributor Author

Choose a reason for hiding this comment

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

@Thisch --log-cli? --logs-stream?

Copy link
Member

Choose a reason for hiding this comment

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

I'm OK about having a --log-cli flag, although it is so close to -o log_cli=true that I'm not sure it adds much. What about having a short option for it instead? And what that would be?

Copy link
Contributor

Choose a reason for hiding this comment

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

Maybe -S in analogy to -s?

Copy link
Member

Choose a reason for hiding this comment

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

Too close IMHO... @RonnyPfannschmidt are you 👎 on having a command-line for this, as you mentioned in #3190 (comment)?

1 change: 1 addition & 0 deletions changelog/3175.trivial
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -0,0 +1 @@
Allow the logging plugin, when live logs are enabled, to handle the hooks `pytest_runtest_logstart` and `pytest_runtest_logfinish`.
78 changes: 77 additions & 1 deletion testing/logging/test_reporting.py
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -226,8 +226,20 @@ def test_log_2():


def test_log_cli_default_level_sections(testdir, request):
"""Check that with live logging enable we are printing the correct headers during setup/call/teardown."""
"""Check that with live logging enable we are printing the correct headers during
start/setup/call/teardown/finish."""
filename = request.node.name + '.py'
testdir.makeconftest('''
import pytest
import logging

def pytest_runtest_logstart():
logging.warning('>>>>> START >>>>>')

def pytest_runtest_logfinish():
logging.warning('<<<<< END <<<<<<<')
''')

testdir.makepyfile('''
import pytest
import logging
Expand All @@ -252,26 +264,90 @@ def test_log_2(fix):
result = testdir.runpytest()
result.stdout.fnmatch_lines([
'{}::test_log_1 '.format(filename),
'*-- live log start --*',
'*WARNING* >>>>> START >>>>>*',
'*-- live log setup --*',
'*WARNING*log message from setup of test_log_1*',
'*-- live log call --*',
'*WARNING*log message from test_log_1*',
'PASSED *50%*',
'*-- live log teardown --*',
'*WARNING*log message from teardown of test_log_1*',
'*-- live log finish --*',
'*WARNING* <<<<< END <<<<<<<*',

'{}::test_log_2 '.format(filename),
'*-- live log start --*',
'*WARNING* >>>>> START >>>>>*',
'*-- live log setup --*',
'*WARNING*log message from setup of test_log_2*',
'*-- live log call --*',
'*WARNING*log message from test_log_2*',
'PASSED *100%*',
'*-- live log teardown --*',
'*WARNING*log message from teardown of test_log_2*',
'*-- live log finish --*',
'*WARNING* <<<<< END <<<<<<<*',
'=* 2 passed in *=',
])


def test_live_logs_unknown_sections(testdir, request):
"""Check that with live logging enable we are printing the correct headers during
start/setup/call/teardown/finish."""
filename = request.node.name + '.py'
testdir.makeconftest('''
import pytest
import logging

def pytest_runtest_protocol(item, nextitem):
logging.warning('Unknown Section!')

def pytest_runtest_logstart():
logging.warning('>>>>> START >>>>>')

def pytest_runtest_logfinish():
logging.warning('<<<<< END <<<<<<<')
''')

testdir.makepyfile('''
import pytest
import logging

@pytest.fixture
def fix(request):
logging.warning("log message from setup of {}".format(request.node.name))
yield
logging.warning("log message from teardown of {}".format(request.node.name))

def test_log_1(fix):
logging.warning("log message from test_log_1")

''')
testdir.makeini('''
[pytest]
log_cli=true
''')

result = testdir.runpytest()
result.stdout.fnmatch_lines([
'*WARNING*Unknown Section*',
'{}::test_log_1 '.format(filename),
'*-- live log start --*',
'*WARNING* >>>>> START >>>>>*',
'*-- live log setup --*',
'*WARNING*log message from setup of test_log_1*',
'*-- live log call --*',
'*WARNING*log message from test_log_1*',
'PASSED *100%*',
'*-- live log teardown --*',
'*WARNING*log message from teardown of test_log_1*',
'*-- live log finish --*',
'*WARNING* <<<<< END <<<<<<<*',
'=* 1 passed in *=',
])


def test_log_cli_level(testdir):
# Default log file level
testdir.makepyfile('''
Expand Down