diff --git a/_pytest/logging.py b/_pytest/logging.py index 53e704b0d..aa0c46948 100644 --- a/_pytest/logging.py +++ b/_pytest/logging.py @@ -335,7 +335,7 @@ def pytest_configure(config): # No log_level was provided, default to WARNING log_file_level = logging.WARNING config._catchlog_log_file_level = log_file_level - config.pluginmanager.register(LoggingPlugin(config)) + config.pluginmanager.register(LoggingPlugin(config), 'loggingp') class LoggingPlugin(object): diff --git a/testing/logging/conftest.py b/testing/logging/conftest.py new file mode 100644 index 000000000..9b559d7eb --- /dev/null +++ b/testing/logging/conftest.py @@ -0,0 +1,33 @@ +# -*- coding: utf-8 -*- +from __future__ import absolute_import, division, print_function + +import pytest + + +pytest_plugins = 'pytester' + + +def pytest_addoption(parser): + parser.addoption('--run-perf', + action='store', dest='run_perf', + choices=['yes', 'no', 'only', 'check'], + nargs='?', default='check', const='yes', + help='Run performance tests (can be slow)', + ) + + parser.addoption('--perf-graph', + action='store', dest='perf_graph_name', + nargs='?', default=None, const='graph.svg', + help='Plot a graph using data found in --benchmark-storage', + ) + parser.addoption('--perf-expr', + action='store', dest='perf_expr_primary', + default='log_emit', + help='Benchmark (or expression combining benchmarks) to plot', + ) + parser.addoption('--perf-expr-secondary', + action='store', dest='perf_expr_secondary', + default='caplog - stub', + help=('Benchmark (or expression combining benchmarks) to plot ' + 'as a secondary line'), + ) diff --git a/testing/logging/test_compat.py b/testing/logging/test_compat.py new file mode 100644 index 000000000..0c527b587 --- /dev/null +++ b/testing/logging/test_compat.py @@ -0,0 +1,80 @@ +# -*- coding: utf-8 -*- +import pytest + + +def test_camel_case_aliases(testdir): + testdir.makepyfile(''' + import logging + + logger = logging.getLogger(__name__) + + def test_foo(caplog): + caplog.setLevel(logging.INFO) + logger.debug('boo!') + + with caplog.atLevel(logging.WARNING): + logger.info('catch me if you can') + ''') + result = testdir.runpytest() + assert result.ret == 0 + + with pytest.raises(pytest.fail.Exception): + result.stdout.fnmatch_lines(['*- Captured *log call -*']) + + result = testdir.runpytest('-rw') + assert result.ret == 0 + result.stdout.fnmatch_lines(''' + =*warning* summary*= + *caplog.setLevel()*deprecated* + *caplog.atLevel()*deprecated* + ''') + + +def test_property_call(testdir): + testdir.makepyfile(''' + import logging + + logger = logging.getLogger(__name__) + + def test_foo(caplog): + logger.info('boo %s', 'arg') + + assert caplog.text == caplog.text() == str(caplog.text) + assert caplog.records == caplog.records() == list(caplog.records) + assert (caplog.record_tuples == + caplog.record_tuples() == list(caplog.record_tuples)) + ''') + result = testdir.runpytest() + assert result.ret == 0 + + result = testdir.runpytest('-rw') + assert result.ret == 0 + result.stdout.fnmatch_lines(''' + =*warning* summary*= + *caplog.text()*deprecated* + *caplog.records()*deprecated* + *caplog.record_tuples()*deprecated* + ''') + + +def test_records_modification(testdir): + testdir.makepyfile(''' + import logging + + logger = logging.getLogger(__name__) + + def test_foo(caplog): + logger.info('boo %s', 'arg') + assert caplog.records + assert caplog.records() + + del caplog.records()[:] # legacy syntax + assert not caplog.records + assert not caplog.records() + + logger.info('foo %s', 'arg') + assert caplog.records + assert caplog.records() + ''') + result = testdir.runpytest() + assert result.ret == 0 diff --git a/testing/logging/test_fixture.py b/testing/logging/test_fixture.py new file mode 100644 index 000000000..bdfa67ecc --- /dev/null +++ b/testing/logging/test_fixture.py @@ -0,0 +1,99 @@ +# -*- coding: utf-8 -*- +import sys +import logging + + +logger = logging.getLogger(__name__) +sublogger = logging.getLogger(__name__+'.baz') + +u = (lambda x: x.decode('utf-8')) if sys.version_info < (3,) else (lambda x: x) + + +def test_fixture_help(testdir): + result = testdir.runpytest('--fixtures') + result.stdout.fnmatch_lines(['*caplog*']) + + +def test_change_level(caplog): + caplog.set_level(logging.INFO) + logger.debug('handler DEBUG level') + logger.info('handler INFO level') + + caplog.set_level(logging.CRITICAL, logger=sublogger.name) + sublogger.warning('logger WARNING level') + sublogger.critical('logger CRITICAL level') + + assert 'DEBUG' not in caplog.text + assert 'INFO' in caplog.text + assert 'WARNING' not in caplog.text + assert 'CRITICAL' in caplog.text + + +def test_with_statement(caplog): + with caplog.at_level(logging.INFO): + logger.debug('handler DEBUG level') + logger.info('handler INFO level') + + with caplog.at_level(logging.CRITICAL, logger=sublogger.name): + sublogger.warning('logger WARNING level') + sublogger.critical('logger CRITICAL level') + + assert 'DEBUG' not in caplog.text + assert 'INFO' in caplog.text + assert 'WARNING' not in caplog.text + assert 'CRITICAL' in caplog.text + + +def test_log_access(caplog): + logger.info('boo %s', 'arg') + assert caplog.records[0].levelname == 'INFO' + assert caplog.records[0].msg == 'boo %s' + assert 'boo arg' in caplog.text + + +def test_record_tuples(caplog): + logger.info('boo %s', 'arg') + + assert caplog.record_tuples == [ + (__name__, logging.INFO, 'boo arg'), + ] + + +def test_unicode(caplog): + logger.info(u('bū')) + assert caplog.records[0].levelname == 'INFO' + assert caplog.records[0].msg == u('bū') + assert u('bū') in caplog.text + + +def test_clear(caplog): + logger.info(u('bū')) + assert len(caplog.records) + caplog.clear() + assert not len(caplog.records) + + +def test_special_warning_with_del_records_warning(testdir): + p1 = testdir.makepyfile(""" + def test_del_records_inline(caplog): + del caplog.records()[:] + """) + result = testdir.runpytest_subprocess(p1) + result.stdout.fnmatch_lines([ + "*'caplog.records()' syntax is deprecated," + " use 'caplog.records' property (or caplog.clear()) instead", + "*1 *warnings*", + ]) + + +def test_warning_with_setLevel(testdir): + p1 = testdir.makepyfile(""" + def test_inline(caplog): + caplog.setLevel(0) + """) + result = testdir.runpytest_subprocess(p1) + result.stdout.fnmatch_lines([ + "*'caplog.setLevel()' is deprecated," + " use 'caplog.set_level()' instead", + "*1 *warnings*", + ]) diff --git a/testing/logging/test_reporting.py b/testing/logging/test_reporting.py new file mode 100644 index 000000000..af75eb632 --- /dev/null +++ b/testing/logging/test_reporting.py @@ -0,0 +1,398 @@ +# -*- coding: utf-8 -*- +import os +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() + 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() + 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() + 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 -*']) + + +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('loggingp') + assert plugin.log_cli_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_cli_default_level.py PASSED', + ]) + result.stderr.fnmatch_lines([ + "* This log message will be shown" + ]) + for line in result.errlines: + try: + assert "This log message won't be shown" in line + pytest.fail("A log message was shown and it shouldn't have been") + except AssertionError: + continue + + # make sure that that we get a '0' exit code for the testsuite + assert result.ret == 0 + + +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('loggingp') + 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', '--log-cli-level=INFO') + + # fnmatch_lines does an assertion internally + result.stdout.fnmatch_lines([ + 'test_log_cli_level.py PASSED', + ]) + result.stderr.fnmatch_lines([ + "* This log message will be shown" + ]) + for line in result.errlines: + try: + assert "This log message won't be shown" in line + pytest.fail("A log message was shown and it shouldn't have been") + except AssertionError: + continue + + # 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 PASSED', + ]) + result.stderr.fnmatch_lines([ + "* This log message will be shown" + ]) + for line in result.errlines: + try: + assert "This log message won't be shown" in line + pytest.fail("A log message was shown and it shouldn't have been") + except AssertionError: + continue + + # 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_level = INFO + """) + testdir.makepyfile(''' + import pytest + import logging + def test_log_cli(request): + plugin = request.config.pluginmanager.getplugin('loggingp') + 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 PASSED', + ]) + result.stderr.fnmatch_lines([ + "* This log message will be shown" + ]) + for line in result.errlines: + try: + assert "This log message won't be shown" in line + pytest.fail("A log message was shown and it shouldn't have been") + except AssertionError: + continue + + # make sure that that we get a '0' exit code for the testsuite + assert result.ret == 0 + + +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('loggingp') + 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)) + + # 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('loggingp') + 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_file_ini(testdir): + log_file = testdir.tmpdir.join('pytest.log').strpath + + testdir.makeini( + """ + [pytest] + log_file={0} + """.format(log_file)) + testdir.makepyfile(''' + import pytest + import logging + def test_log_file(request): + plugin = request.config.pluginmanager.getplugin('loggingp') + 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('loggingp') + 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