Pytest logging ignores options in pytest.ini

Question

I have a test that I am running with:

pytest --capture=no --verbose --rootdir=testing/ testing/tests/docker_test.py

from /home/user/development/. The test checks if some containers are running and uses the default logging framework of Python 3.6. The logger inside the test file is configured as follows:

logger = logging.getLogger(__name__)
logger.setLevel(logging.INFO)
logging.basicConfig(level=logging.INFO, stream=sys.stdout, format="%(asctime)s %(levelname)s %(message)s")

Inside tests I am using the logger as follows:

logger.info(f"TEST SUCCESSFUL: container {container_name} is running")
logger.info(f"TEST SUCCESSFUL: all required containers are running")

Inside testing (the root directory) I have a file pytest.ini:

[pytest]
log_level = INFO
log_cli_level = INFO
log_format = %(asctime)s %(levelname)s %(message)s
log_cli_format = %(asctime)s %(levelname)s %(message)s
log_date_format = %H:%M:%S
log_cli_date_format = %H:%M:%S

Basically I do not want any date to be in the timestamp and I want pytest to log live to the command line when I am running the tests.

For one I am wondering what asctime stands for. It looks like "ascii time". I do not want a standardized timestamp, but instead the format I describe in the pytest.ini. That is why I also tried to use date, datetime and timestamp, instead of asctime, all resulting in an error. So I guess asctime is the only way to get a timestamp.

However, pytest seems to ignore all the options I am setting in my pytest.ini file, although is indicates, that it found the file, when I am running the tests:

cachedir: testing/.pytest_cache
rootdir: /home/user/development/testing, inifile: pytest.ini

How can I change the timestamp in pytest logging?

Firefly

Answer 1

I guess what you are missing is log_cli = 1 (or true/yes/etc) in your pytest.ini. Besides that, with the config you're provided the log records are printed in the format you specified in log_cli_format. You can even reduce the pytest.ini to:

[pytest]
log_cli = 1
log_cli_level = INFO
log_cli_format = %(asctime)s %(levelname)s %(message)s
log_cli_date_format = %H:%M:%S

Also, the above config will take care of the root logger config in test session, so you shouldn't need to configure the logger in tests for live logging. Just call the logger in tests:

import logging

def test_spam():
    logger = logging.getLogger(__name__)
    logger.info('spam')
    logger.warning('eggs')
    logger.error('bacon')

This will print:

$ pytest
============================== test session starts ================================
platform linux -- Python 3.6.5, pytest-3.4.1, py-1.5.3, pluggy-0.6.0 -- /data/gentoo64/usr/bin/python3.6
cachedir: .pytest_cache
rootdir: /data/gentoo64/home/u0_a82/projects/stackoverflow/so-50677656, inifile: pytest.ini
plugins: mock-1.6.3, cov-2.5.1, flaky-3.4.0
collected 1 item

testing/tests/test_docker.py::test_logs
---------------------------------- live log call ----------------------------------
16:29:12 INFO spam
16:29:13 WARNING eggs
16:29:13 ERROR bacon
PASSED                                                                       [100%]
============================ 1 passed in 1.08 seconds =============================

For one I am wondering what asctime stands for

The logging docs are a bit laconic about it:

Human-readable time when the LogRecord was created. By default this is of the form ‘2003-07-08 16:49:45,896’ (the numbers after the comma are millisecond portion of the time).

However, asctime does not mean that the records will be always formatted using time.asctime - it's only the default datetime format used when you don't pass your own to the logging.Formatter (second argument in the formatter constructor).

Ate