pytest leaks all logging output

[ghost]

This is slightly different than the previous issue. If I run pytest tests/unit in the root directory of pyinstaller, logging that has a level of WARNING or higher is leaked. That's fine; there are existing plans for that issue. But if I just run pytest (with no arguments), I encounter a much more serious issue: all logging is printed. On a typical pyinstaller test run, we typically have 50k lines of logging output (estimated); so much output that appveyor truncates the logs.

Please let me know what details you need.

[pytestbot]

GitMate.io thinks the contributor most likely able to help you is @nicoddemus.

[ra-tolson]

I'm seeing this too; log level is getting set to 0 somewhere between pytest_configure and running the tests:

$ cat test_truth.py 
import logging

def test_truth():
    print 'root effective log level:', logging.getLogger().getEffectiveLevel()
    assert True
$ pytest -s
.
.
.
test_truth.py root effective log level: 0

[ghost]

Note: from searching, the only setLevel calls are here:

pytest/_pytest/logging.py

Lines 88 to 103 in 30729b7

	handler.setLevel(level)
	# Adding the same handler twice would confuse logging system.
	# Just don't do that.
	add_new_handler = handler not in root_logger.handlers
	if add_new_handler:
	root_logger.addHandler(handler)
	orig_level = root_logger.level
	root_logger.setLevel(min(orig_level, level))
	try:
	yield handler
	finally:
	root_logger.setLevel(orig_level)
	if add_new_handler:
	root_logger.removeHandler(handler)

[ghost]

Update: after gutting every single function that called setLevel in that file, nothing was changed.

[ghost]

Note: after some debugging, I found that the logger level has nothing to do with this; it's set in both cases to zero and output is captured for one but not for the other.

[durden]

I'm using pytest 3.3.1 and see different behavior for the exact same project in OS X and Windows. Windows leaks all the logs while OS X doesn't, even if there are no failing tests on either.

For example, running just py.test at the top-level of the project on both OSes spams stdout with logs in Windows and nothing but the regular test progress output in OS X. Is it somehow possible this only affects Windows? Maybe I'm seeing a different issue?

[durden]

Actually, let me provide a bit more information. The logs leak in Windows when I'm running with the xdist plugin to run the tests on 2 CPUs. I'm using pytest-xdist 1.21.0 so maybe my issue is with the plugin and not pytest itself. See these these issues for more details:

• logging not captured with pytest 3.3 and xdist #3009
• Proposal: disable "live logging" by default and write to terminal writer instead #3013

[blueyed]

The problem here actually is setting the level to 0, via:

[20]   …/Vcs/pytest/_pytest/runner.py(155)call_and_report()
-> call = call_runtest_hook(item, when, **kwds)
[21]   …/Vcs/pytest/_pytest/runner.py(175)call_runtest_hook()
-> return CallInfo(lambda: ihook(item=item, **kwds), when=when)
[22]   …/Vcs/pytest/_pytest/runner.py(189)__init__()
-> self.result = func()
[23]   …/Vcs/pytest/_pytest/runner.py(175)<lambda>()
-> return CallInfo(lambda: ihook(item=item, **kwds), when=when)
[24]   …/project/.venv/lib/python3.6/site-packages/pluggy/__init__.py(617)__call__()
-> return self._hookexec(self, self._nonwrappers + self._wrappers, kwargs)
[25]   …/project/.venv/lib/python3.6/site-packages/pluggy/__init__.py(222)_hookexec()
-> return self._inner_hookexec(hook, methods, kwargs)
[26]   …/project/.venv/lib/python3.6/site-packages/pluggy/__init__.py(216)<lambda>()
-> firstresult=hook.spec_opts.get('firstresult'),
[27]   …/project/.venv/lib/python3.6/site-packages/pluggy/callers.py(175)_multicall()
-> next(gen)   # first yield
[28] > …/Vcs/pytest/_pytest/logging.py(323)pytest_runtest_teardown()
-> with self._runtest_for(item, 'teardown'):
[29]   /usr/lib/python3.6/contextlib.py(81)__enter__()
-> return next(self.gen)
[30]   …/Vcs/pytest/_pytest/logging.py(299)_runtest_for()
-> formatter=self.formatter) as log_handler:
[31]   /usr/lib/python3.6/contextlib.py(81)__enter__()
-> return next(self.gen)
[32]   …/Vcs/pytest/_pytest/logging.py(105)catching_logs()
-> root_logger.setLevel(min(orig_root_logger_level, level))
[33]   /usr/lib/python3.6/logging/__init__.py(1282)setLevel()
-> self.level = _checkLevel(level)
[34]   …/project/.venv/lib/python3.6/site-packages/pdb.py(1092)__setattr__()
-> old___setattr__(self, attr, value)

(with pdbpp you can use __import__('pdb').break_on_setattr('level')(logger.parent.__class__) to break there)

It sets the level to 0, which enables all message for non-configured loggers
(parents get looked up if a level is not configured for a logger).

I've not really investigated, but it looked like this happens only after the first test - before this INFO is used (which we configure via Django's logging wrapper).

It seems like the root logger needs to get changed to actually see messages, but maybe then existing handlers could get a filter attached to respect the original level?
Another possibility might also be to monkey-patch some method in the logging module even?!

(I've noticed this when using -s, which caused a lot of debug messages to appear; therefore #3013 might help in this regard)

[nicoddemus]

This will be fixed by #3124: the log level will no longer set to 0 implicitly by pytest, it will use the default level unless explicitly asked for a different level using --log-level.