# -*- coding: utf-8 -*- import os import re from io import open 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_root_logger_affected(testdir): testdir.makepyfile( """ import logging logger = logging.getLogger() def test_foo(): logger.info('info text ' + 'going to logger') logger.warning('warning text ' + 'going to logger') logger.error('error text ' + 'going to logger') assert 0 """ ) log_file = testdir.tmpdir.join("pytest.log").strpath result = testdir.runpytest("--log-level=ERROR", "--log-file=pytest.log") assert result.ret == 1 # The capture log calls in the stdout section only contain the # logger.error msg, because of --log-level=ERROR. result.stdout.fnmatch_lines(["*error text going to logger*"]) stdout = result.stdout.str() assert "warning text going to logger" not in stdout assert "info text going to logger" not in stdout # The log file should contain the warning and the error log messages and # not the info one, because the default level of the root logger is # WARNING. assert os.path.isfile(log_file) with open(log_file) as rfh: contents = rfh.read() assert "info text going to logger" not in contents assert "warning text going to logger" in contents assert "error text going to logger" in contents def test_log_cli_level_log_level_interaction(testdir): testdir.makepyfile( """ import logging logger = logging.getLogger() def test_foo(): logger.debug('debug text ' + 'going to logger') logger.info('info text ' + 'going to logger') logger.warning('warning text ' + 'going to logger') logger.error('error text ' + 'going to logger') assert 0 """ ) result = testdir.runpytest("--log-cli-level=INFO", "--log-level=ERROR") assert result.ret == 1 result.stdout.fnmatch_lines( [ "*-- live log call --*", "*INFO*info text going to logger", "*WARNING*warning text going to logger", "*ERROR*error text going to logger", "=* 1 failed in *=", ] ) assert "DEBUG" not in result.stdout.str() 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 --*", "CRITICAL *test_log_cli_enabled_disabled.py* 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 ", "WARNING*test_log_cli_default_level.py* 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(.+)\nWARNING(.+)\nWARNING(.+)", result.stdout.str(), re.MULTILINE, ) is not None ) assert ( re.search( r"(.+)live log finish(.+)\nWARNING(.+)\nWARNING(.+)", 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 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) stdout = result.stdout.str() 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 stdout else: result.stdout.fnmatch_lines( ["*test_log_cli_auto_enable*100%*", "=* 1 passed in *="] ) assert "INFO" not in stdout assert "WARNING" not in stdout 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={}".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={}".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={} 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={} 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 def test_log_file_unicode(testdir): log_file = testdir.tmpdir.join("pytest.log").strpath testdir.makeini( """ [pytest] log_file={} log_file_level = INFO """.format( log_file ) ) testdir.makepyfile( """ # -*- coding: utf-8 -*- from __future__ import unicode_literals import logging def test_log_file(): logging.getLogger('catchlog').info("Normal message") logging.getLogger('catchlog').info("├") logging.getLogger('catchlog').info("Another normal message") """ ) result = testdir.runpytest() # 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, encoding="utf-8") as rfh: contents = rfh.read() assert "Normal message" in contents assert u"├" in contents assert "Another normal message" 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 import contextlib from functools import partial from _pytest.logging import _LiveLoggingStreamHandler class MockCaptureManager: calls = [] @contextlib.contextmanager def global_and_fixture_disabled(self): self.calls.append("enter disabled") yield self.calls.append("exit disabled") 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 == ["enter disabled", "exit disabled"] else: assert MockCaptureManager.calls == [] assert out_file.getvalue() == "\nsome message\n" def test_collection_live_logging(testdir): testdir.makepyfile( """ import logging logging.getLogger().info("Normal message") """ ) result = testdir.runpytest("--log-cli-level=INFO") result.stdout.fnmatch_lines( [ "collecting*", "*--- live log collection ---*", "*Normal message*", "collected 0 items", ] ) def test_collection_logging_to_file(testdir): log_file = testdir.tmpdir.join("pytest.log").strpath testdir.makeini( """ [pytest] log_file={} log_file_level = INFO """.format( log_file ) ) testdir.makepyfile( """ import logging logging.getLogger().info("Normal message") def test_simple(): logging.getLogger().debug("debug message in test_simple") logging.getLogger().info("info message in test_simple") """ ) result = testdir.runpytest() assert "--- live log collection ---" not in result.stdout.str() assert result.ret == 0 assert os.path.isfile(log_file) with open(log_file, encoding="utf-8") as rfh: contents = rfh.read() assert "Normal message" in contents assert "debug message in test_simple" not in contents assert "info message in test_simple" in contents def test_log_in_hooks(testdir): log_file = testdir.tmpdir.join("pytest.log").strpath testdir.makeini( """ [pytest] log_file={} log_file_level = INFO log_cli=true """.format( log_file ) ) testdir.makeconftest( """ import logging def pytest_runtestloop(session): logging.info('runtestloop') def pytest_sessionstart(session): logging.info('sessionstart') def pytest_sessionfinish(session, exitstatus): logging.info('sessionfinish') """ ) result = testdir.runpytest() result.stdout.fnmatch_lines(["*sessionstart*", "*runtestloop*", "*sessionfinish*"]) with open(log_file) as rfh: contents = rfh.read() assert "sessionstart" in contents assert "runtestloop" in contents assert "sessionfinish" in contents def test_log_in_runtest_logreport(testdir): log_file = testdir.tmpdir.join("pytest.log").strpath testdir.makeini( """ [pytest] log_file={} log_file_level = INFO log_cli=true """.format( log_file ) ) testdir.makeconftest( """ import logging logger = logging.getLogger(__name__) def pytest_runtest_logreport(report): logger.info("logreport") """ ) testdir.makepyfile( """ def test_first(): assert True """ ) testdir.runpytest() with open(log_file) as rfh: contents = rfh.read() assert contents.count("logreport") == 3 def test_log_set_path(testdir): report_dir_base = testdir.tmpdir.strpath testdir.makeini( """ [pytest] log_file_level = DEBUG log_cli=true """ ) testdir.makeconftest( """ import os import pytest @pytest.hookimpl(hookwrapper=True, tryfirst=True) def pytest_runtest_setup(item): config = item.config logging_plugin = config.pluginmanager.get_plugin("logging-plugin") report_file = os.path.join({}, item._request.node.name) logging_plugin.set_log_path(report_file) yield """.format( repr(report_dir_base) ) ) testdir.makepyfile( """ import logging logger = logging.getLogger("testcase-logger") def test_first(): logger.info("message from test 1") assert True def test_second(): logger.debug("message from test 2") assert True """ ) testdir.runpytest() with open(os.path.join(report_dir_base, "test_first"), "r") as rfh: content = rfh.read() assert "message from test 1" in content with open(os.path.join(report_dir_base, "test_second"), "r") as rfh: content = rfh.read() assert "message from test 2" in content