diff --git a/AUTHORS b/AUTHORS index 90089e9a5..f1769116d 100644 --- a/AUTHORS +++ b/AUTHORS @@ -168,6 +168,7 @@ Tarcisio Fischer Tareq Alayan Ted Xiao Thomas Grainger +Thomas Hisch Tom Viner Trevor Bekolay Tyler Goodlet diff --git a/_pytest/config.py b/_pytest/config.py index 2f28bb7bf..4fe8bd106 100644 --- a/_pytest/config.py +++ b/_pytest/config.py @@ -105,7 +105,7 @@ default_plugins = ( "mark main terminal runner python fixtures debugging unittest capture skipping " "tmpdir monkeypatch recwarn pastebin helpconfig nose assertion " "junitxml resultlog doctest cacheprovider freeze_support " - "setuponly setupplan warnings").split() + "setuponly setupplan warnings logging").split() builtin_plugins = set(default_plugins) diff --git a/_pytest/logging.py b/_pytest/logging.py new file mode 100644 index 000000000..ed4db25ad --- /dev/null +++ b/_pytest/logging.py @@ -0,0 +1,337 @@ +from __future__ import absolute_import, division, print_function + +import logging +from contextlib import closing, contextmanager +import sys +import six + +import pytest +import py + + +DEFAULT_LOG_FORMAT = '%(filename)-25s %(lineno)4d %(levelname)-8s %(message)s' +DEFAULT_LOG_DATE_FORMAT = '%H:%M:%S' + + +def get_option_ini(config, *names): + for name in names: + ret = config.getoption(name) # 'default' arg won't work as expected + if ret is None: + ret = config.getini(name) + if ret: + return ret + + +def pytest_addoption(parser): + """Add options to control log capturing.""" + group = parser.getgroup('logging') + + def add_option_ini(option, dest, default=None, type=None, **kwargs): + parser.addini(dest, default=default, type=type, + help='default value for ' + option) + group.addoption(option, dest=dest, **kwargs) + + add_option_ini( + '--no-print-logs', + dest='log_print', action='store_const', const=False, default=True, + type='bool', + help='disable printing caught logs on failed tests.') + add_option_ini( + '--log-level', + dest='log_level', default=None, + help='logging level used by the logging module') + add_option_ini( + '--log-format', + dest='log_format', default=DEFAULT_LOG_FORMAT, + help='log format as used by the logging module.') + add_option_ini( + '--log-date-format', + dest='log_date_format', default=DEFAULT_LOG_DATE_FORMAT, + help='log date format as used by the logging module.') + add_option_ini( + '--log-cli-level', + dest='log_cli_level', default=None, + help='cli logging level.') + add_option_ini( + '--log-cli-format', + dest='log_cli_format', default=None, + help='log format as used by the logging module.') + add_option_ini( + '--log-cli-date-format', + dest='log_cli_date_format', default=None, + help='log date format as used by the logging module.') + add_option_ini( + '--log-file', + dest='log_file', default=None, + help='path to a file when logging will be written to.') + add_option_ini( + '--log-file-level', + dest='log_file_level', default=None, + help='log file logging level.') + add_option_ini( + '--log-file-format', + dest='log_file_format', default=DEFAULT_LOG_FORMAT, + help='log format as used by the logging module.') + add_option_ini( + '--log-file-date-format', + dest='log_file_date_format', default=DEFAULT_LOG_DATE_FORMAT, + help='log date format as used by the logging module.') + + +@contextmanager +def logging_using_handler(handler, logger=None): + """Context manager that safely registers a given handler.""" + logger = logger or logging.getLogger(logger) + + if handler in logger.handlers: # reentrancy + # Adding the same handler twice would confuse logging system. + # Just don't do that. + yield + else: + logger.addHandler(handler) + try: + yield + finally: + logger.removeHandler(handler) + + +@contextmanager +def catching_logs(handler, formatter=None, + level=logging.NOTSET, logger=None): + """Context manager that prepares the whole logging machinery properly.""" + logger = logger or logging.getLogger(logger) + + if formatter is not None: + handler.setFormatter(formatter) + handler.setLevel(level) + + with logging_using_handler(handler, logger): + orig_level = logger.level + logger.setLevel(min(orig_level, level)) + try: + yield handler + finally: + logger.setLevel(orig_level) + + +class LogCaptureHandler(logging.StreamHandler): + """A logging handler that stores log records and the log text.""" + + def __init__(self): + """Creates a new log handler.""" + logging.StreamHandler.__init__(self, py.io.TextIO()) + self.records = [] + + def emit(self, record): + """Keep the log records in a list in addition to the log text.""" + self.records.append(record) + logging.StreamHandler.emit(self, record) + + +class LogCaptureFixture(object): + """Provides access and control of log capturing.""" + + def __init__(self, item): + """Creates a new funcarg.""" + self._item = item + + @property + def handler(self): + return self._item.catch_log_handler + + @property + def text(self): + """Returns the log text.""" + return self.handler.stream.getvalue() + + @property + def records(self): + """Returns the list of log records.""" + return self.handler.records + + @property + def record_tuples(self): + """Returns a list of a striped down version of log records intended + for use in assertion comparison. + + The format of the tuple is: + + (logger_name, log_level, message) + """ + return [(r.name, r.levelno, r.getMessage()) for r in self.records] + + def clear(self): + """Reset the list of log records.""" + self.handler.records = [] + + def set_level(self, level, logger=None): + """Sets the level for capturing of logs. + + By default, the level is set on the handler used to capture + logs. Specify a logger name to instead set the level of any + logger. + """ + if logger is None: + logger = self.handler + else: + logger = logging.getLogger(logger) + logger.setLevel(level) + + @contextmanager + def at_level(self, level, logger=None): + """Context manager that sets the level for capturing of logs. + + By default, the level is set on the handler used to capture + logs. Specify a logger name to instead set the level of any + logger. + """ + if logger is None: + logger = self.handler + else: + logger = logging.getLogger(logger) + + orig_level = logger.level + logger.setLevel(level) + try: + yield + finally: + logger.setLevel(orig_level) + + +@pytest.fixture +def caplog(request): + """Access and control log capturing. + + Captured logs are available through the following methods:: + + * caplog.text() -> string containing formatted log output + * caplog.records() -> list of logging.LogRecord instances + * caplog.record_tuples() -> list of (logger_name, level, message) tuples + """ + return LogCaptureFixture(request.node) + + +def get_actual_log_level(config, *setting_names): + """Return the actual logging level.""" + + for setting_name in setting_names: + log_level = config.getoption(setting_name) + if log_level is None: + log_level = config.getini(setting_name) + if log_level: + break + else: + return + + if isinstance(log_level, six.string_types): + log_level = log_level.upper() + try: + return int(getattr(logging, log_level, log_level)) + except ValueError: + # Python logging does not recognise this as a logging level + raise pytest.UsageError( + "'{0}' is not recognized as a logging level name for " + "'{1}'. Please consider passing the " + "logging level num instead.".format( + log_level, + setting_name)) + + +def pytest_configure(config): + config.pluginmanager.register(LoggingPlugin(config), + 'logging-plugin') + + +class LoggingPlugin(object): + """Attaches to the logging module and captures log messages for each test. + """ + + def __init__(self, config): + """Creates a new plugin to capture log messages. + + The formatter can be safely shared across all handlers so + create a single one for the entire test session here. + """ + self.log_cli_level = get_actual_log_level( + config, 'log_cli_level', 'log_level') or logging.WARNING + + self.print_logs = get_option_ini(config, 'log_print') + self.formatter = logging.Formatter( + get_option_ini(config, 'log_format'), + get_option_ini(config, 'log_date_format')) + + log_cli_handler = logging.StreamHandler(sys.stderr) + log_cli_format = get_option_ini( + config, 'log_cli_format', 'log_format') + log_cli_date_format = get_option_ini( + config, 'log_cli_date_format', 'log_date_format') + log_cli_formatter = logging.Formatter( + log_cli_format, + datefmt=log_cli_date_format) + self.log_cli_handler = log_cli_handler # needed for a single unittest + self.live_logs = catching_logs(log_cli_handler, + formatter=log_cli_formatter, + level=self.log_cli_level) + + log_file = get_option_ini(config, 'log_file') + if log_file: + self.log_file_level = get_actual_log_level( + config, 'log_file_level') or logging.WARNING + + log_file_format = get_option_ini( + config, 'log_file_format', 'log_format') + log_file_date_format = get_option_ini( + config, 'log_file_date_format', 'log_date_format') + self.log_file_handler = logging.FileHandler( + log_file, + # Each pytest runtests session will write to a clean logfile + mode='w') + log_file_formatter = logging.Formatter( + log_file_format, + datefmt=log_file_date_format) + self.log_file_handler.setFormatter(log_file_formatter) + else: + self.log_file_handler = None + + @contextmanager + def _runtest_for(self, item, when): + """Implements the internals of pytest_runtest_xxx() hook.""" + with catching_logs(LogCaptureHandler(), + formatter=self.formatter) as log_handler: + item.catch_log_handler = log_handler + try: + yield # run test + finally: + del item.catch_log_handler + + if self.print_logs: + # Add a captured log section to the report. + log = log_handler.stream.getvalue().strip() + item.add_report_section(when, 'log', log) + + @pytest.hookimpl(hookwrapper=True) + def pytest_runtest_setup(self, item): + with self._runtest_for(item, 'setup'): + yield + + @pytest.hookimpl(hookwrapper=True) + def pytest_runtest_call(self, item): + with self._runtest_for(item, 'call'): + yield + + @pytest.hookimpl(hookwrapper=True) + def pytest_runtest_teardown(self, item): + with self._runtest_for(item, 'teardown'): + yield + + @pytest.hookimpl(hookwrapper=True) + def pytest_runtestloop(self, session): + """Runs all collected test items.""" + with self.live_logs: + if self.log_file_handler is not None: + with closing(self.log_file_handler): + with catching_logs(self.log_file_handler, + level=self.log_file_level): + yield # run all the tests + else: + yield # run all the tests diff --git a/changelog/2794.feature b/changelog/2794.feature new file mode 100644 index 000000000..9cff1c4bb --- /dev/null +++ b/changelog/2794.feature @@ -0,0 +1,3 @@ +Pytest now captures and displays output from the standard `logging` module. The user can control the logging level to be captured by specifying options in ``pytest.ini``, the command line and also during individual tests using markers. Also, a ``caplog`` fixture is available that enables users to test the captured log during specific tests (similar to ``capsys`` for example). For more information, please see the `docs `_. + +This feature was introduced by merging the popular `pytest-catchlog `_ plugin, thanks to `Thomas Hisch `_. Be advised that during the merging the backward compatibility interface with the defunct ``pytest-capturelog`` has been dropped. \ No newline at end of file diff --git a/doc/en/contents.rst b/doc/en/contents.rst index 6b9eed010..7a6570e0b 100644 --- a/doc/en/contents.rst +++ b/doc/en/contents.rst @@ -30,6 +30,7 @@ Full pytest documentation xunit_setup plugins writing_plugins + logging goodpractices pythonpath diff --git a/doc/en/logging.rst b/doc/en/logging.rst new file mode 100644 index 000000000..e3bf56038 --- /dev/null +++ b/doc/en/logging.rst @@ -0,0 +1,192 @@ +.. _logging: + +Logging +------- + +.. versionadded 3.3.0 + +.. note:: + + This feature is a drop-in replacement for the `pytest-catchlog + `_ plugin and they will conflict + with each other. The backward compatibility API with ``pytest-capturelog`` + has been dropped when this feature was introduced, so if for that reason you + still need ``pytest-catchlog`` you can disable the internal feature by + adding to your ``pytest.ini``: + + .. code-block:: ini + + [pytest] + addopts=-p no:logging + +Log messages are captured by default and for each failed test will be shown in +the same manner as captured stdout and stderr. + +Running without options:: + + pytest + +Shows failed tests like so:: + + ----------------------- Captured stdlog call ---------------------- + test_reporting.py 26 INFO text going to logger + ----------------------- Captured stdout call ---------------------- + text going to stdout + ----------------------- Captured stderr call ---------------------- + text going to stderr + ==================== 2 failed in 0.02 seconds ===================== + +By default each captured log message shows the module, line number, log level +and message. Showing the exact module and line number is useful for testing and +debugging. If desired the log format and date format can be specified to +anything that the logging module supports. + +Running pytest specifying formatting options:: + + pytest --log-format="%(asctime)s %(levelname)s %(message)s" \ + --log-date-format="%Y-%m-%d %H:%M:%S" + +Shows failed tests like so:: + + ----------------------- Captured stdlog call ---------------------- + 2010-04-10 14:48:44 INFO text going to logger + ----------------------- Captured stdout call ---------------------- + text going to stdout + ----------------------- Captured stderr call ---------------------- + text going to stderr + ==================== 2 failed in 0.02 seconds ===================== + +These options can also be customized through a configuration file: + +.. code-block:: ini + + [pytest] + log_format = %(asctime)s %(levelname)s %(message)s + log_date_format = %Y-%m-%d %H:%M:%S + +Further it is possible to disable reporting logs on failed tests completely +with:: + + pytest --no-print-logs + +Or in you ``pytest.ini``: + +.. code-block:: ini + + [pytest] + log_print = False + + +Shows failed tests in the normal manner as no logs were captured:: + + ----------------------- Captured stdout call ---------------------- + text going to stdout + ----------------------- Captured stderr call ---------------------- + text going to stderr + ==================== 2 failed in 0.02 seconds ===================== + +Inside tests it is possible to change the log level for the captured log +messages. This is supported by the ``caplog`` fixture:: + + def test_foo(caplog): + caplog.set_level(logging.INFO) + pass + +By default the level is set on the handler used to catch the log messages, +however as a convenience it is also possible to set the log level of any +logger:: + + def test_foo(caplog): + caplog.set_level(logging.CRITICAL, logger='root.baz') + pass + +It is also possible to use a context manager to temporarily change the log +level:: + + def test_bar(caplog): + with caplog.at_level(logging.INFO): + pass + +Again, by default the level of the handler is affected but the level of any +logger can be changed instead with:: + + def test_bar(caplog): + with caplog.at_level(logging.CRITICAL, logger='root.baz'): + pass + +Lastly all the logs sent to the logger during the test run are made available on +the fixture in the form of both the LogRecord instances and the final log text. +This is useful for when you want to assert on the contents of a message:: + + def test_baz(caplog): + func_under_test() + for record in caplog.records: + assert record.levelname != 'CRITICAL' + assert 'wally' not in caplog.text + +For all the available attributes of the log records see the +``logging.LogRecord`` class. + +You can also resort to ``record_tuples`` if all you want to do is to ensure, +that certain messages have been logged under a given logger name with a given +severity and message:: + + def test_foo(caplog): + logging.getLogger().info('boo %s', 'arg') + + assert caplog.record_tuples == [ + ('root', logging.INFO, 'boo arg'), + ] + +You can call ``caplog.clear()`` to reset the captured log records in a test:: + + def test_something_with_clearing_records(caplog): + some_method_that_creates_log_records() + caplog.clear() + your_test_method() + assert ['Foo'] == [rec.message for rec in caplog.records] + +Live Logs +^^^^^^^^^ + +By default, pytest will output any logging records with a level higher or +equal to WARNING. In order to actually see these logs in the console you have to +disable pytest output capture by passing ``-s``. + +You can specify the logging level for which log records with equal or higher +level are printed to the console by passing ``--log-cli-level``. This setting +accepts the logging level names as seen in python's documentation or an integer +as the logging level num. + +Additionally, you can also specify ``--log-cli-format`` and +``--log-cli-date-format`` which mirror and default to ``--log-format`` and +``--log-date-format`` if not provided, but are applied only to the console +logging handler. + +All of the CLI log options can also be set in the configuration INI file. The +option names are: + +* ``log_cli_level`` +* ``log_cli_format`` +* ``log_cli_date_format`` + +If you need to record the whole test suite logging calls to a file, you can pass +``--log-file=/path/to/log/file``. This log file is opened in write mode which +means that it will be overwritten at each run tests session. + +You can also specify the logging level for the log file by passing +``--log-file-level``. This setting accepts the logging level names as seen in +python's documentation(ie, uppercased level names) or an integer as the logging +level num. + +Additionally, you can also specify ``--log-file-format`` and +``--log-file-date-format`` which are equal to ``--log-format`` and +``--log-date-format`` but are applied to the log file logging handler. + +All of the log file options can also be set in the configuration INI file. The +option names are: + +* ``log_file`` +* ``log_file_level`` +* ``log_file_format`` +* ``log_file_date_format`` diff --git a/doc/en/plugins.rst b/doc/en/plugins.rst index ec031e9e0..bba7d3ecd 100644 --- a/doc/en/plugins.rst +++ b/doc/en/plugins.rst @@ -27,9 +27,6 @@ Here is a little annotated list for some popular plugins: for `twisted `_ apps, starting a reactor and processing deferreds from test functions. -* `pytest-catchlog `_: - to capture and assert about messages from the logging module - * `pytest-cov `_: coverage reporting, compatible with distributed testing diff --git a/doc/en/usage.rst b/doc/en/usage.rst index a8c6d40a0..1cb64ec87 100644 --- a/doc/en/usage.rst +++ b/doc/en/usage.rst @@ -189,7 +189,6 @@ in your code and pytest automatically disables its output capture for that test: for test output occurring after you exit the interactive PDB_ tracing session and continue with the regular test run. - .. _durations: Profiling test execution duration diff --git a/setup.py b/setup.py index 61e880c2a..68b8ec065 100644 --- a/setup.py +++ b/setup.py @@ -43,7 +43,7 @@ def has_environment_marker_support(): def main(): - install_requires = ['py>=1.4.33', 'six>=1.10.0', 'setuptools'] + install_requires = ['py>=1.4.34', 'six>=1.10.0', 'setuptools'] # if _PYTEST_SETUP_SKIP_PLUGGY_DEP is set, skip installing pluggy; # used by tox.ini to test with pluggy master if '_PYTEST_SETUP_SKIP_PLUGGY_DEP' not in os.environ: diff --git a/testing/logging/test_fixture.py b/testing/logging/test_fixture.py new file mode 100644 index 000000000..b5bee4233 --- /dev/null +++ b/testing/logging/test_fixture.py @@ -0,0 +1,70 @@ +# -*- coding: utf-8 -*- +import logging + + +logger = logging.getLogger(__name__) +sublogger = logging.getLogger(__name__+'.baz') + + +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) diff --git a/testing/logging/test_reporting.py b/testing/logging/test_reporting.py new file mode 100644 index 000000000..c02ee2172 --- /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('logging-plugin') + 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('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', '--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('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 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('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)) + + # 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_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('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 diff --git a/testing/test_capture.py b/testing/test_capture.py index 0fd012f7b..f961694ff 100644 --- a/testing/test_capture.py +++ b/testing/test_capture.py @@ -342,26 +342,6 @@ class TestLoggingInteraction(object): # verify proper termination assert "closed" not in s - def test_logging_initialized_in_test(self, testdir): - p = testdir.makepyfile(""" - import sys - def test_something(): - # pytest does not import logging - assert 'logging' not in sys.modules - import logging - logging.basicConfig() - logging.warn("hello432") - assert 0 - """) - result = testdir.runpytest_subprocess( - p, "--traceconfig", - "-p", "no:capturelog", "-p", "no:hypothesis", "-p", "no:hypothesispytest") - assert result.ret != 0 - result.stdout.fnmatch_lines([ - "*hello432*", - ]) - assert 'operation on closed file' not in result.stderr.str() - def test_conftestlogging_is_shown(self, testdir): testdir.makeconftest(""" import logging