logging level and output capture sensitive to environment and confusing

[adigitoleo]

I am experiencing sporadic and unusual behaviour with pytest, which is related to a few issues already posted here but I can't be sure that it's the same thing.

I am developing a package which uses pytest. I run tests in three environments:

• Arch Linux with python 3.10.6 environment from venv
• Ubuntu 20.04.5 with python 3.10.6 environment from a combination of pyenv and venv
• Linux CI on github using ubuntu-latest and latest Python 3.10

Right now I'm facing an issue which appeared sporadically but now seems to be reproducible on Arch. Running pytest I hit the infamous option names already defined error, and no tests are run. I think this was caused by pytest trying to run tests from a git-worktree subdirectory, so this is a different issue to what will be discussed in the rest of this thread.

I also have a second issue, which appears only in the CI environment but not on my local Ubuntu. Pytest is not respecting my logging options, and always captures verbose log messages on console.

Environment

Pip list of my local environments all look like:

Package            Version             Editable project location
------------------ ------------------- -------------------------
aiohttp            3.8.1
aiosignal          1.2.0
async-timeout      4.0.2
attrs              22.1.0
black              22.8.0
charset-normalizer 2.1.1
click              8.1.3
cycler             0.11.0
flake8             5.0.4
fonttools          4.37.1
frozenlist         1.3.1
idna               3.3
iniconfig          1.1.1
kiwisolver         1.4.4
llvmlite           0.39.1
matplotlib         3.5.3
mccabe             0.7.0
multidict          6.0.2
mypy               0.971
mypy-extensions    0.4.3
numba              0.56.2
numpy              1.23.2
packaging          21.3
pathspec           0.10.1
petsc4py           3.17.2
Pillow             9.2.0
pip                22.2.2
platformdirs       2.5.2
pluggy             1.0.0
py                 1.11.0
pycodestyle        2.9.1
pydrex             0.1.dev177+gd254819 /home/admin/vcs/PyDRex
pyflakes           2.5.0
pyparsing          3.0.9
pytest             7.1.3
python-dateutil    2.8.2
scipy              1.9.1
setuptools         59.8.0
six                1.16.0
tomli              2.0.1
typing_extensions  4.3.0
vtk                9.2.0rc2
wslink             1.8.2
yarl               1.8.1

where pydrex is the editable dev package.

I don't have any pytest config files except a conftest.py with some fixtures, a custom CLI arg definition and some logging defaults. The relevant section is:

def pytest_configure(config):
    config.option.log_cli = True
    if config.getoption("--log-cli-level") is None:
        config.option.log_cli_level = "INFO"
    else:
        config.option.log_cli_level = config.getoption("--log-cli-level")
    config.option.log_cli_format = _log.LOGGER_CONSOLE.formatter._fmt


def pytest_addoption(parser):
    parser.addoption(
        "--outdir",
        metavar="DIR",
        default=None,
        help="output directory in which to store PyDRex figures/logs",
    )


@pytest.fixture
def outdir(request):
    return request.config.getoption("--outdir")

I also set up a logger with the possibility to have multiple handlers at different verbosity levels:

LOGGER = logging.getLogger("pydrex")
# To allow for multiple handlers at different levels, default level must be DEBUG.
LOGGER.setLevel(logging.DEBUG)
# Set up console handler, turned on by default.
LOGGER_CONSOLE = logging.StreamHandler()
# The format string is stored in .formatter._fmt
LOGGER_CONSOLE.setFormatter(
    logging.Formatter("%(levelname)s [%(asctime)s] %(name)s: %(message)s")
)
LOGGER_CONSOLE.setLevel(logging.INFO)
LOGGER.addHandler(LOGGER_CONSOLE)

The behaviour I expect based on the above setup is:

• live logging to console by default, with level INFO
• no message capturing (?)
• optional arg --outdir can be used via the fixture
• live logging level can be controlled via --log-cli-level

Instead I observe:

• On Arch, test collection failure due to parser_addoption separate issue caused by git-worktree
• On Ubuntu (local), everything works as expected
• In CI (Ubuntu), pytest captures INFO logs on stderr and DEBUG logs on "captured logs"

[adigitoleo]

I can prevent capturing in the CI runs with -s however this makes --log-cli-level become useless.

[adigitoleo]

For now I have switched to a more defensive set of options that won't print above WARNING level by default:

def pytest_configure(config):
    # Make sure --log-cli-level can be used by default.
    config.option.log_cli = True
    # Make sure pytest never prints more than WARNING messages by default.
    config.option.log_level = "WARNING"
    # Inherit format for "live logs" (--log-cli-level) from our logger.
    config.option.log_cli_format = _log.LOGGER_CONSOLE.formatter._fmt

I still find the interaction of these different CLI args/options around output and logging to be confusing. Some of them seem to affect both "live logs" and "captured logs" modes in unintuitive ways. I'm not sure that this is a very useful report so feel free to close it.

[adigitoleo]

After restarting/rebooting various environments the behaviouor has changed once again. I now have live logs but some of them are formatted incorrectly, and without the -s flag I get all of the logs duplicated in a captured stderr section, which is unhelpfully printed after the stack traces of failed tests and so obscures them. Perhaps I'll give up on the live feedback option for now, and just use my own methods to log to files. Either I'm doing something very wrong or this is all much more brittle/complicated than I would expect.

[adigitoleo]

Final comment: I note that pytest itself fails its test suite when I use the -s command line option:

FAILED testing/test_config.py::TestDebugOptions::test_debug_help - Failed: nomatch: '*Store internal tracing debug information in this log*'
FAILED testing/test_helpconfig.py::test_help - Failed: nomatch: '  -m MARKEXPR           Only run tests matching given mark expression. For'
FAILED testing/test_stepwise.py::test_sw_skip_help - Failed: nomatch: '*Implicitly enables --stepwise.'

I also observe similar behaviour running pytest on itself, which is that the -s (--capture=no) option counterintuitively produces a large amount of output and makes both --log-level and --log-cli-level have no effect. I am also unable to silence the output with --show-capture=no.

I think there are probably multiple issues here, which may deserve individual trackers:

• Is there really a need for both --capture and --show-capture? As far as I can tell, they only differ in that --capture applies always but --show-capture only applies to failed tests? --disable-warnings being separate from --capture also seems unnecessary.
• I propose that by default, logging output should never be captured/printed/shown, unless an explicit option (from the logging plugin!) is set. Basically a removal of the "captured log output" section.
• Clarify or fix what is going on with --log-level and --log-cli-level and how to control verbosity of the logging pluggin ("live logs"?) and document how to set logging options from conftest.py (or is that disallowed?).
• Clarify the hierarchy of option settings: Should CLI args, .ini files or the conftest.py get priority? I would expect it to be CLI args > conftest.py > .ini but I don't really care as long as it is clear.

One last thing, from the cli help:

  --log-level=LEVEL     Level of messages to catch/display. Not set by default,
                        so it depends on the root/parent log handler's effective
                        level, where it is "WARNING" by default.

I don't understand: Not set by default, [...] it is "WARNING" by default. Is that referring to the fact that Pythons logging module sets its root logger to WARNING by default? How does pytest know that that the root logger is always going to be the parent? I think the last part of that sentence should be deleted, or changed to simply say that by default, Python's root logger will be used.

[reed9999]

I'm seeing exactly these three failures any time I don't redirect stdout somehow.. In Python 3.9 on Linux:

• if I don't redirect the tox/pytest stdout from the terminal the 3 failures occur.
• if run the same tests with stdout redirected, either using > or implicitly with nohup, the tests pass.

Since this is my first time trying to build from source, I'm trying to control my environments pretty tightly. My primary reproducible environment is on a fresh AWS EC2 instance from the Amazon Linux 2023 AMI. I can also reproduce the above behavior (pass if redirected; fail if to a terminal) on a Windows Subsystem for Linux (WSL) v2 environment with Ubuntu 20.04.2 LTS without too much customization yet.

I'll post some scripts to reproduce in my next comment.

[reed9999]

sudo yum install -y git
sudo yum install -y pip3
sudo pip3 install --upgrade build
sudo pip3 install --upgrade setuptools

git clone https://github.com/pytest-dev/pytest.git
pushd pytest

python3 -m venv ~/.virtualenvs/pytestdev
source ~/.virtualenvs/pytestdev/bin/activate
python3 -m pip install --editable .
python3 -m pip install tox
tox
popd

I'd imagine the virtualenv stuff is redundant because already managed by tox; is that right?