test_ok1/testing/logging/test_reporting.py

718 lines
23 KiB
Python

# -*- coding: utf-8 -*-
import re
import os
import six
import pytest
def test_nothing_logged(testdir):
testdir.makepyfile('''
import sys
def test_foo():
sys.stdout.write('text going to stdout')
sys.stderr.write('text going to stderr')
assert False
''')
result = testdir.runpytest()
assert result.ret == 1
result.stdout.fnmatch_lines(['*- Captured stdout call -*',
'text going to stdout'])
result.stdout.fnmatch_lines(['*- Captured stderr call -*',
'text going to stderr'])
with pytest.raises(pytest.fail.Exception):
result.stdout.fnmatch_lines(['*- Captured *log call -*'])
def test_messages_logged(testdir):
testdir.makepyfile('''
import sys
import logging
logger = logging.getLogger(__name__)
def test_foo():
sys.stdout.write('text going to stdout')
sys.stderr.write('text going to stderr')
logger.info('text going to logger')
assert False
''')
result = testdir.runpytest('--log-level=INFO')
assert result.ret == 1
result.stdout.fnmatch_lines(['*- Captured *log call -*',
'*text going to logger*'])
result.stdout.fnmatch_lines(['*- Captured stdout call -*',
'text going to stdout'])
result.stdout.fnmatch_lines(['*- Captured stderr call -*',
'text going to stderr'])
def test_setup_logging(testdir):
testdir.makepyfile('''
import logging
logger = logging.getLogger(__name__)
def setup_function(function):
logger.info('text going to logger from setup')
def test_foo():
logger.info('text going to logger from call')
assert False
''')
result = testdir.runpytest('--log-level=INFO')
assert result.ret == 1
result.stdout.fnmatch_lines(['*- Captured *log setup -*',
'*text going to logger from setup*',
'*- Captured *log call -*',
'*text going to logger from call*'])
def test_teardown_logging(testdir):
testdir.makepyfile('''
import logging
logger = logging.getLogger(__name__)
def test_foo():
logger.info('text going to logger from call')
def teardown_function(function):
logger.info('text going to logger from teardown')
assert False
''')
result = testdir.runpytest('--log-level=INFO')
assert result.ret == 1
result.stdout.fnmatch_lines(['*- Captured *log call -*',
'*text going to logger from call*',
'*- Captured *log teardown -*',
'*text going to logger from teardown*'])
def test_disable_log_capturing(testdir):
testdir.makepyfile('''
import sys
import logging
logger = logging.getLogger(__name__)
def test_foo():
sys.stdout.write('text going to stdout')
logger.warning('catch me if you can!')
sys.stderr.write('text going to stderr')
assert False
''')
result = testdir.runpytest('--no-print-logs')
print(result.stdout)
assert result.ret == 1
result.stdout.fnmatch_lines(['*- Captured stdout call -*',
'text going to stdout'])
result.stdout.fnmatch_lines(['*- Captured stderr call -*',
'text going to stderr'])
with pytest.raises(pytest.fail.Exception):
result.stdout.fnmatch_lines(['*- Captured *log call -*'])
def test_disable_log_capturing_ini(testdir):
testdir.makeini(
'''
[pytest]
log_print=False
'''
)
testdir.makepyfile('''
import sys
import logging
logger = logging.getLogger(__name__)
def test_foo():
sys.stdout.write('text going to stdout')
logger.warning('catch me if you can!')
sys.stderr.write('text going to stderr')
assert False
''')
result = testdir.runpytest()
print(result.stdout)
assert result.ret == 1
result.stdout.fnmatch_lines(['*- Captured stdout call -*',
'text going to stdout'])
result.stdout.fnmatch_lines(['*- Captured stderr call -*',
'text going to stderr'])
with pytest.raises(pytest.fail.Exception):
result.stdout.fnmatch_lines(['*- Captured *log call -*'])
@pytest.mark.parametrize('enabled', [True, False])
def test_log_cli_enabled_disabled(testdir, enabled):
msg = 'critical message logged by test'
testdir.makepyfile('''
import logging
def test_log_cli():
logging.critical("{}")
'''.format(msg))
if enabled:
testdir.makeini('''
[pytest]
log_cli=true
''')
result = testdir.runpytest()
if enabled:
result.stdout.fnmatch_lines([
'test_log_cli_enabled_disabled.py::test_log_cli ',
'*-- live log call --*',
'test_log_cli_enabled_disabled.py* CRITICAL critical message logged by test',
'PASSED*',
])
else:
assert msg not in result.stdout.str()
def test_log_cli_default_level(testdir):
# Default log file level
testdir.makepyfile('''
import pytest
import logging
def test_log_cli(request):
plugin = request.config.pluginmanager.getplugin('logging-plugin')
assert plugin.log_cli_handler.level == logging.NOTSET
logging.getLogger('catchlog').info("INFO message won't be shown")
logging.getLogger('catchlog').warning("WARNING message will be shown")
''')
testdir.makeini('''
[pytest]
log_cli=true
''')
result = testdir.runpytest()
# fnmatch_lines does an assertion internally
result.stdout.fnmatch_lines([
'test_log_cli_default_level.py::test_log_cli ',
'test_log_cli_default_level.py*WARNING message will be shown*',
])
assert "INFO message won't be shown" not in result.stdout.str()
# make sure that that we get a '0' exit code for the testsuite
assert result.ret == 0
def test_log_cli_default_level_multiple_tests(testdir, request):
"""Ensure we reset the first newline added by the live logger between tests"""
filename = request.node.name + '.py'
testdir.makepyfile('''
import logging
def test_log_1():
logging.warning("log message from test_log_1")
def test_log_2():
logging.warning("log message from test_log_2")
''')
testdir.makeini('''
[pytest]
log_cli=true
''')
result = testdir.runpytest()
result.stdout.fnmatch_lines([
'{}::test_log_1 '.format(filename),
'*WARNING*log message from test_log_1*',
'PASSED *50%*',
'{}::test_log_2 '.format(filename),
'*WARNING*log message from test_log_2*',
'PASSED *100%*',
'=* 2 passed in *=',
])
def test_log_cli_default_level_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_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")
def test_log_2(fix):
logging.warning("log message from test_log_2")
''')
testdir.makeini('''
[pytest]
log_cli=true
''')
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),
'*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*',
'*WARNING* <<<<< END <<<<<<<*',
'=* 1 passed in *=',
])
def test_sections_single_new_line_after_test_outcome(testdir, request):
"""Check that only a single new line is written between log messages during
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 <<<<<<<')
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))
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([
'{}::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 <<<<<<<*',
'*WARNING* <<<<< END <<<<<<<*',
'=* 1 passed in *=',
])
assert re.search(r'(.+)live log teardown(.+)\n(.+)WARNING(.+)\n(.+)WARNING(.+)',
result.stdout.str(), re.MULTILINE) is not None
assert re.search(r'(.+)live log finish(.+)\n(.+)WARNING(.+)\n(.+)WARNING(.+)',
result.stdout.str(), re.MULTILINE) is not None
def test_log_cli_level(testdir):
# Default log file level
testdir.makepyfile('''
import pytest
import logging
def test_log_cli(request):
plugin = request.config.pluginmanager.getplugin('logging-plugin')
assert plugin.log_cli_handler.level == logging.INFO
logging.getLogger('catchlog').debug("This log message won't be shown")
logging.getLogger('catchlog').info("This log message will be shown")
print('PASSED')
''')
testdir.makeini('''
[pytest]
log_cli=true
''')
result = testdir.runpytest('-s', '--log-cli-level=INFO')
# fnmatch_lines does an assertion internally
result.stdout.fnmatch_lines([
'test_log_cli_level.py*This log message will be shown',
'PASSED', # 'PASSED' on its own line because the log message prints a new line
])
assert "This log message won't be shown" not in result.stdout.str()
# make sure that that we get a '0' exit code for the testsuite
assert result.ret == 0
result = testdir.runpytest('-s', '--log-level=INFO')
# fnmatch_lines does an assertion internally
result.stdout.fnmatch_lines([
'test_log_cli_level.py* This log message will be shown',
'PASSED', # 'PASSED' on its own line because the log message prints a new line
])
assert "This log message won't be shown" not in result.stdout.str()
# make sure that that we get a '0' exit code for the testsuite
assert result.ret == 0
def test_log_cli_ini_level(testdir):
testdir.makeini(
"""
[pytest]
log_cli=true
log_cli_level = INFO
""")
testdir.makepyfile('''
import pytest
import logging
def test_log_cli(request):
plugin = request.config.pluginmanager.getplugin('logging-plugin')
assert plugin.log_cli_handler.level == logging.INFO
logging.getLogger('catchlog').debug("This log message won't be shown")
logging.getLogger('catchlog').info("This log message will be shown")
print('PASSED')
''')
result = testdir.runpytest('-s')
# fnmatch_lines does an assertion internally
result.stdout.fnmatch_lines([
'test_log_cli_ini_level.py* This log message will be shown',
'PASSED', # 'PASSED' on its own line because the log message prints a new line
])
assert "This log message won't be shown" not in result.stdout.str()
# make sure that that we get a '0' exit code for the testsuite
assert result.ret == 0
@pytest.mark.parametrize('cli_args', ['',
'--log-level=WARNING',
'--log-file-level=WARNING',
'--log-cli-level=WARNING'])
def test_log_cli_auto_enable(testdir, request, cli_args):
"""Check that live logs are enabled if --log-level or --log-cli-level is passed on the CLI.
It should not be auto enabled if the same configs are set on the INI file.
"""
testdir.makepyfile('''
import pytest
import logging
def test_log_1():
logging.info("log message from test_log_1 not to be shown")
logging.warning("log message from test_log_1")
''')
testdir.makeini('''
[pytest]
log_level=INFO
log_cli_level=INFO
''')
result = testdir.runpytest(cli_args)
if cli_args == '--log-cli-level=WARNING':
result.stdout.fnmatch_lines([
'*::test_log_1 ',
'*-- live log call --*',
'*WARNING*log message from test_log_1*',
'PASSED *100%*',
'=* 1 passed in *=',
])
assert 'INFO' not in result.stdout.str()
else:
result.stdout.fnmatch_lines([
'*test_log_cli_auto_enable*100%*',
'=* 1 passed in *=',
])
assert 'INFO' not in result.stdout.str()
assert 'WARNING' not in result.stdout.str()
def test_log_file_cli(testdir):
# Default log file level
testdir.makepyfile('''
import pytest
import logging
def test_log_file(request):
plugin = request.config.pluginmanager.getplugin('logging-plugin')
assert plugin.log_file_handler.level == logging.WARNING
logging.getLogger('catchlog').info("This log message won't be shown")
logging.getLogger('catchlog').warning("This log message will be shown")
print('PASSED')
''')
log_file = testdir.tmpdir.join('pytest.log').strpath
result = testdir.runpytest('-s', '--log-file={0}'.format(log_file), '--log-file-level=WARNING')
# fnmatch_lines does an assertion internally
result.stdout.fnmatch_lines([
'test_log_file_cli.py PASSED',
])
# make sure that that we get a '0' exit code for the testsuite
assert result.ret == 0
assert os.path.isfile(log_file)
with open(log_file) as rfh:
contents = rfh.read()
assert "This log message will be shown" in contents
assert "This log message won't be shown" not in contents
def test_log_file_cli_level(testdir):
# Default log file level
testdir.makepyfile('''
import pytest
import logging
def test_log_file(request):
plugin = request.config.pluginmanager.getplugin('logging-plugin')
assert plugin.log_file_handler.level == logging.INFO
logging.getLogger('catchlog').debug("This log message won't be shown")
logging.getLogger('catchlog').info("This log message will be shown")
print('PASSED')
''')
log_file = testdir.tmpdir.join('pytest.log').strpath
result = testdir.runpytest('-s',
'--log-file={0}'.format(log_file),
'--log-file-level=INFO')
# fnmatch_lines does an assertion internally
result.stdout.fnmatch_lines([
'test_log_file_cli_level.py PASSED',
])
# make sure that that we get a '0' exit code for the testsuite
assert result.ret == 0
assert os.path.isfile(log_file)
with open(log_file) as rfh:
contents = rfh.read()
assert "This log message will be shown" in contents
assert "This log message won't be shown" not in contents
def test_log_level_not_changed_by_default(testdir):
testdir.makepyfile('''
import logging
def test_log_file():
assert logging.getLogger().level == logging.WARNING
''')
result = testdir.runpytest('-s')
result.stdout.fnmatch_lines('* 1 passed in *')
def test_log_file_ini(testdir):
log_file = testdir.tmpdir.join('pytest.log').strpath
testdir.makeini(
"""
[pytest]
log_file={0}
log_file_level=WARNING
""".format(log_file))
testdir.makepyfile('''
import pytest
import logging
def test_log_file(request):
plugin = request.config.pluginmanager.getplugin('logging-plugin')
assert plugin.log_file_handler.level == logging.WARNING
logging.getLogger('catchlog').info("This log message won't be shown")
logging.getLogger('catchlog').warning("This log message will be shown")
print('PASSED')
''')
result = testdir.runpytest('-s')
# fnmatch_lines does an assertion internally
result.stdout.fnmatch_lines([
'test_log_file_ini.py PASSED',
])
# make sure that that we get a '0' exit code for the testsuite
assert result.ret == 0
assert os.path.isfile(log_file)
with open(log_file) as rfh:
contents = rfh.read()
assert "This log message will be shown" in contents
assert "This log message won't be shown" not in contents
def test_log_file_ini_level(testdir):
log_file = testdir.tmpdir.join('pytest.log').strpath
testdir.makeini(
"""
[pytest]
log_file={0}
log_file_level = INFO
""".format(log_file))
testdir.makepyfile('''
import pytest
import logging
def test_log_file(request):
plugin = request.config.pluginmanager.getplugin('logging-plugin')
assert plugin.log_file_handler.level == logging.INFO
logging.getLogger('catchlog').debug("This log message won't be shown")
logging.getLogger('catchlog').info("This log message will be shown")
print('PASSED')
''')
result = testdir.runpytest('-s')
# fnmatch_lines does an assertion internally
result.stdout.fnmatch_lines([
'test_log_file_ini_level.py PASSED',
])
# make sure that that we get a '0' exit code for the testsuite
assert result.ret == 0
assert os.path.isfile(log_file)
with open(log_file) as rfh:
contents = rfh.read()
assert "This log message will be shown" in contents
assert "This log message won't be shown" not in contents
@pytest.mark.parametrize('has_capture_manager', [True, False])
def test_live_logging_suspends_capture(has_capture_manager, request):
"""Test that capture manager is suspended when we emitting messages for live logging.
This tests the implementation calls instead of behavior because it is difficult/impossible to do it using
``testdir`` facilities because they do their own capturing.
We parametrize the test to also make sure _LiveLoggingStreamHandler works correctly if no capture manager plugin
is installed.
"""
import logging
from functools import partial
from _pytest.capture import CaptureManager
from _pytest.logging import _LiveLoggingStreamHandler
class MockCaptureManager:
calls = []
def suspend_global_capture(self):
self.calls.append('suspend_global_capture')
def resume_global_capture(self):
self.calls.append('resume_global_capture')
# sanity check
assert CaptureManager.suspend_capture_item
assert CaptureManager.resume_global_capture
class DummyTerminal(six.StringIO):
def section(self, *args, **kwargs):
pass
out_file = DummyTerminal()
capture_manager = MockCaptureManager() if has_capture_manager else None
handler = _LiveLoggingStreamHandler(out_file, capture_manager)
handler.set_when('call')
logger = logging.getLogger(__name__ + '.test_live_logging_suspends_capture')
logger.addHandler(handler)
request.addfinalizer(partial(logger.removeHandler, handler))
logger.critical('some message')
if has_capture_manager:
assert MockCaptureManager.calls == ['suspend_global_capture', 'resume_global_capture']
else:
assert MockCaptureManager.calls == []
assert out_file.getvalue() == '\nsome message\n'