Can't access "Captured stderr call" section of logging

[westhomas]

• [X] Include a detailed description of the bug or suggestion

I'm attempting to capture the output of a custom logging configuration dict. But for some reason the once I use logging.config.dictConfig all the logging output is pushed into the Captured stderr call and I can't see it in the caplog fixture.

How do I access this logging data?

• [X] pip list of the virtual environment you are using

Package        Version  Location
-------------- -------- -------------------
aiohttp        3.3.2
aioredis       1.2.0
async-timeout  3.0.1
atomicwrites   1.3.0
attrs          19.1.0
certifi        2019.3.9
chardet        3.0.4
coverage       4.5.3
datadog        0.21.0
decorator      4.4.0
flake8         3.5.0
hiredis        1.0.0
idna           2.6
idna-ssl       1.1.0
mccabe         0.6.1
more-itertools 7.0.0
multidict      4.5.2
pip            10.0.1
pluggy         0.6.0
py             1.8.0
pyaml          17.12.1
pycodestyle    2.3.1
pyflakes       1.6.0
pytest         3.6.3
pytest-aiohttp 0.3.0
pytest-asyncio 0.5.0
pytest-cov     2.5.1
pytest-html    1.13.0
pytz           2018.4
PyYAML         5.1
redis          3.2.1
requests       2.18.4
setuptools     39.2.0
simplejson     3.16.0
six            1.12.0
urllib3        1.22
wheel          0.31.1
yarl           1.3.0

• [X] pytest and operating system versions

pytest         3.6.3
docker Desktop Mac Version 2.0.0.3 (31259) running python:3.6.5-slim container

• [X] Minimal example if possible

import logging
import logging.config
import pytest

logger = logging.getLogger(__name__)

LOGGING = {
    'version': 1,
    'disable_existing_loggers': False,
    'formatters': {
        'console': {
            'datefmt': "%Y-%m-%dT%H:%M:%S",
            'format': "%(asctime)s.%(msecs)d %(levelname)s %(processName)s:%(threadName)s %(name)s %(message)s",
        }
    },
    'handlers': {
        'console': {
            'class': 'logging.StreamHandler',
            'formatter': 'console',
            'level': 'DEBUG',
        },
    },
    'loggers': {
        '': {
            'handlers': ['console'],
            'level': 'DEBUG',
            'propagate': True
        }
    },
}

logging.config.dictConfig(LOGGING)

def test_logging_time_formatting(caplog):
    caplog.set_level(logging.DEBUG)

    logger.info("testing")

    print(caplog.record_tuples)

    assert "INFO MainProcess:MainThread test_logging testing" in caplog.text

Running this test gives me this output (notice the INFO log in the Captured stderr call section):

docker-compose run --rm utils bash -c 'pytest -v tests/test_logging.py'
=========================================================================================================================================================================================================== test session starts ============================================================================================================================================================================================================
platform linux -- Python 3.6.5, pytest-3.6.3, py-1.8.0, pluggy-0.6.0 -- /usr/local/bin/python3
cachedir: .pytest_cache
rootdir: /code/utils, inifile:
plugins: html-1.13.0, cov-2.5.1, asyncio-0.5.0, aiohttp-0.3.0
collected 1 item

tests/test_logging.py::test_logging_time_formatting FAILED                                                                                                                                                                                                                                                                                                                                                                           [100%]

================================================================================================================================================================================================================= FAILURES =================================================================================================================================================================================================================
_______________________________________________________________________________________________________________________________________________________________________________________________________ test_logging_time_formatting _______________________________________________________________________________________________________________________________________________________________________________________________________

caplog = <_pytest.logging.LogCaptureFixture object at 0x7f7689814f60>

    def test_logging_time_formatting(caplog):
        caplog.set_level(logging.DEBUG)

        logger.info("testing")

        print(caplog.record_tuples)

>       assert "INFO MainProcess:MainThread test_logging testing" in caplog.text
E       AssertionError: assert 'INFO MainProcess:MainThread test_logging testing' in 'test_logging.py             43 INFO     testing\n'
E        +  where 'test_logging.py             43 INFO     testing\n' = <_pytest.logging.LogCaptureFixture object at 0x7f7689814f60>.text

tests/test_logging.py:51: AssertionError
----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- Captured stdout call -----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
[('test_logging', 20, 'testing')]
----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- Captured stderr call -----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
2019-04-23T19:54:59.397 INFO MainProcess:MainThread test_logging testing
------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------ Captured log call -------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
test_logging.py             43 INFO     testing
========================================================================================================================================================================================================= 1 failed in 0.11 seconds =========================================================================================================================================================================================================
make: *** [test] Error 1

[underchemist]

I believe I am also experiencing this. I'm am not super familiar with the caplog fixture but if it's intended usage is to capture all logging calls during test execution then like OP I am only seeing logging calls int he capture stderr output of pytest and not in the caplog.records or other related attributes of the fixture.

A simplified view of my application and test code

def setup_logger() -> None:
    dct: Dict[str, Any] = {
        "version": 1,
        "formatters": {
            "formatter": {
                "class": "logging.Formatter",
                "format": "%(name)s:%(levelname)s:%(message)s",
            }
        },
        "handlers": {
            "stream_handler": {
                "class": "logging.StreamHandler",
                "level": "DEBUG",
                "formatter": "formatter",
            }
        },
        "root": {"level": "ERROR", "handlers": ["stream_handler"]},
    }

    dictConfig(dct)

def main(args=None) -> None:
    setup_logger()
    logger: logging.Logger = logging.getLogger(__name__)
    parser: argparse.ArgumentParser = setup_parser()
    args: argparse.Namespace = parser.parse_args(args=args)

    if args.verbose:
        logger.setLevel(logging.DEBUG)

    logger.debug(f"called {__name__} with arguments:")
    for arg_name, arg_value in vars(args).items():
        if arg_value is not None:
            logger.debug(f"{arg_name}: {arg_value}")

    input_geojson(args)
    logger.debug(f"finished splitting geojson")

def test_main_logging(caplog, random_geojson_file):
    cli.main(args=["--verbose", str(random_geojson_file)])
    print(caplog.records)
    assert 0

produces

=================================== FAILURES ===================================
______________________________ test_main_logging _______________________________

caplog = <_pytest.logging.LogCaptureFixture object at 0x7fe56fd4f790>
random_geojson_file = PosixPath('/tmp/pytest-of-ysebastien_wsl/pytest-41/test_main_logging0/random.geojson')

    def test_main_logging(caplog, random_geojson_file):
        cli.main(args=["--verbose", str(random_geojson_file)])
        print(caplog.records)
>       assert 0
E       assert 0

tests/test_cli.py:61: AssertionError
----------------------------- Captured stdout call -----------------------------
[]
----------------------------- Captured stderr call -----------------------------
geojsplit.cli:DEBUG:called geojsplit.cli with arguments:
geojsplit.cli:DEBUG:geojson: /tmp/pytest-of-ysebastien_wsl/pytest-41/test_main_logging0/random.geojson
geojsplit.cli:DEBUG:verbose: True
geojsplit.cli:DEBUG:dry_run: False
geojsplit.cli:DEBUG:starting splitting with geojson /tmp/pytest-of-ysebastien_wsl/pytest-41/test_main_logging0/random.geojson
geojsplit.cli:DEBUG:successfully saved 5 features to /tmp/pytest-of-ysebastien_wsl/pytest-41/test_main_logging0/random_xaaaa.geojson
geojsplit.cli:DEBUG:finished splitting geojson

[joshicola]

Able to "finagle" it by saving the root loggers handler (LogCaptureHandler) for future use:

root_handler = logging.root.handlers[0]
logging.config.dictConfig(LOGGING)
root_handler.setLevel(int(log_level))
root_handler.setFormatter(logging.root.handlers[0].formatter)
logging.root.addHandler(root_handler)

[bsolomon1124]

Also seeing this (pytest 6.2.1).

Seems possibly related to https://github.com/pytest-dev/pytest/issues/5997 (see: https://github.com/pytest-dev/pytest/issues/5997#issuecomment-589177669).

With the same logging setup as OP, I am not able to capture the log records, and since one of their handlers is console/stderr, figured that capsys.readouterr().out might work, but that's an empty string too. I can see Captured stderr call right in front of me but can't get to it...

[bsolomon1124]

Also possibly related to https://github.com/pytest-dev/pytest/issues/7335.