Add unittests for LoggingPlugin (excluding perf tests)

_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):

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'),
+    )

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

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*",
+    ])

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