logging not captured with pytest 3.3 and xdist

[nicoddemus]

(Moved from pytest-dev/pytest-xdist#256)

Consider this file:

import logging
logger = logging.getLogger(__name__)

def test():
	logger.warn('Some warning')

When executing pytest foo.py -n2, the warning is printed to the console:

============================= test session starts =============================
platform win32 -- Python 3.5.0, pytest-3.3.1, py-1.5.2, pluggy-0.6.0
rootdir: C:\Users\bruno, inifile:
plugins: xdist-1.20.1, forked-0.2
gw0 [1] / gw1 [1]
scheduling tests via LoadScheduling
foo.py                       6 WARNING  Some warning
.                                                                        [100%]
========================== 1 passed in 0.65 seconds ===========================

Executing pytest normally without the -n2 flags then the message is not printed.

Using pytest 3.3.1 and xdist 1.20.1.

[nicoddemus]

I managed to track this problem to the fact that pytest's logging installs a live_logs handler unconditionally around pytest_runtestloop:

pytest/_pytest/logging.py

Lines 327 to 337 in 88f2cc9

	@pytest.hookimpl(hookwrapper=True)
	def pytest_runtestloop(self, session):
	"""Runs all collected test items."""
	with self.live_logs:
	if self.log_file_handler is not None:
	with closing(self.log_file_handler):
	with catching_logs(self.log_file_handler,
	level=self.log_file_level):
	yield # run all the tests
	else:
	yield # run all the tests

This handler is attached directly to sys.stderr:

pytest/_pytest/logging.py

Lines 263 to 272 in 88f2cc9

	log_cli_handler = logging.StreamHandler(sys.stderr)
	log_cli_format = get_option_ini(
	config, 'log_cli_format', 'log_format')
	log_cli_date_format = get_option_ini(
	config, 'log_cli_date_format', 'log_date_format')
	log_cli_formatter = logging.Formatter(
	log_cli_format,
	datefmt=log_cli_date_format)
	self.log_cli_handler = log_cli_handler # needed for a single unittest
	self.live_logs = catching_logs(log_cli_handler,

This is problematic, because we are now capturing the log output twice, once by the pytest's logging capture and another time by pytest's logging capture:

____________________________________ test _____________________________________

    def test():
        logger.warning('Some warning')
>       assert 0
E       assert 0

.tmp\test_logging.py:9: AssertionError
---------------------------- Captured stderr call -----------------------------
test_logging.py              8 WARNING  Some warning
------------------------------ Captured log call ------------------------------
test_logging.py              8 WARNING  Some warning
========================== 1 failed in 0.09 seconds ===========================

One guess is that the order in which plugins are registered matter here, but changing the order of builtin plugins in config does not change the output:

pytest/_pytest/config.py

Lines 104 to 108 in 88f2cc9

	default_plugins = (
	"mark main terminal runner python fixtures debugging unittest capture skipping "
	"tmpdir monkeypatch recwarn pastebin helpconfig nose assertion "
	"junitxml resultlog doctest cacheprovider freeze_support "
	"setuponly setupplan warnings logging").split()

The same doesn't happen in 3.2.5 and pytest-catchlog installed:

================================== FAILURES ===================================
____________________________________ test _____________________________________

    def test():
        logger.warning('Some warning')
>       assert 0
E       assert 0

.tmp\test_logging.py:9: AssertionError
------------------------------ Captured log call ------------------------------
test_logging.py              8 WARNING  Some warning
========================== 1 failed in 0.07 seconds ===========================

Looking at pytest_catchlog/plugin.py I see that it has the same functionality, so I'm not sure yet what's the bug.

I will continue to investigate when I have some more time.

cc @thisch

[twmr]

I'm investigating this issue.

[twmr]

I don't know why but I can no longer reproduce the issue.

(pytest_upstream_venv) thomas-XPS-13-9360 :: ~gr » pip freeze                                                                                                                                                              1 ↵
apipkg==1.4
attrs==17.3.0
execnet==1.5.0
funcsigs==1.0.2
pkg-resources==0.0.0
pluggy==0.6.0
py==1.5.2
pytest==3.3.1
pytest-forked==0.2
pytest-xdist==1.20.1
six==1.11.0
(pytest_upstream_venv) thomas-XPS-13-9360 :: ~gr » pytest test_logging_in_pytest.py 
===================================================================================================== test session starts =====================================================================================================
platform linux2 -- Python 2.7.12, pytest-3.3.1, py-1.5.2, pluggy-0.6.0
rootdir: /home/thomas/gitrepos, inifile:
plugins: forked-0.2, xdist-1.20.1
collected 1 item                                                                                                                                                                                                              

test_logging_in_pytest.py .                                                                                                                                                                                             [100%]

================================================================================================== 1 passed in 0.00 seconds ===================================================================================================
(pytest_upstream_venv) thomas-XPS-13-9360 :: ~gr » pytest test_logging_in_pytest.py -n2
===================================================================================================== test session starts =====================================================================================================
platform linux2 -- Python 2.7.12, pytest-3.3.1, py-1.5.2, pluggy-0.6.0
rootdir: /home/thomas/gitrepos, inifile:
plugins: forked-0.2, xdist-1.20.1
gw0 [1] / gw1 [1]
scheduling tests via LoadScheduling
.                                                                                                                                                                                                                       [100%]
================================================================================================== 1 passed in 0.28 seconds ===================================================================================================
(pytest_upstream_venv) thomas-XPS-13-9360 :: ~gr » 

[nicoddemus]

@thisch when you say "no longer", you mean you at some point could reproduce it and it stopped without apparent cause, or you never seeing this problem in the first place?

[nicoddemus]

Investigating a more, I noticed that the released pytest-catchlog-1.2.2 is very different from the one at master that I pointed out: 1.2.2 has a single pytest_catchlog.py file, while master has a pytest_catchlog package.

If I install pytest-catchlog from master, I get the same behavior as the pytest's builtin logging plugin:

λ pip install  git+https://github.com/eisensheng/pytest-catchlog.git -U
Collecting git+https://github.com/eisensheng/pytest-catchlog.git
  Cloning https://github.com/eisensheng/pytest-catchlog.git to c:\users\bruno\appdata\local\temp\pip-tk6z4r4x-build
Requirement already up-to-date: py>=1.1.1 in c:\users\bruno\pytest\.env35\lib\site-packages (from pytest-catchlog==1.2.2)
Requirement already up-to-date: pytest>=2.6 in c:\users\bruno\pytest (from pytest-catchlog==1.2.2)
Requirement already up-to-date: six>=1.10.0 in c:\users\bruno\pytest\.env35\lib\site-packages (from pytest>=2.6->pytest-catchlog==1.2.2)
Requirement already up-to-date: setuptools in c:\users\bruno\pytest\.env35\lib\site-packages (from pytest>=2.6->pytest-catchlog==1.2.2)
Requirement already up-to-date: attrs>=17.2.0 in c:\users\bruno\pytest\.env35\lib\site-packages (from pytest>=2.6->pytest-catchlog==1.2.2)
Requirement already up-to-date: pluggy<0.7,>=0.5 in c:\users\bruno\pytest\.env35\lib\site-packages (from pytest>=2.6->pytest-catchlog==1.2.2)
Requirement already up-to-date: colorama in c:\users\bruno\pytest\.env35\lib\site-packages (from pytest>=2.6->pytest-catchlog==1.2.2)
Installing collected packages: pytest-catchlog
  Found existing installation: pytest-catchlog 1.2.2
    Uninstalling pytest-catchlog-1.2.2:
      Successfully uninstalled pytest-catchlog-1.2.2
  Running setup.py install for pytest-catchlog ... done
Successfully installed pytest-catchlog-1.2.2

λ pytest .tmp\test_logging.py
============================= test session starts =============================
platform win32 -- Python 3.5.0, pytest-3.2.5, py-1.5.2, pluggy-0.4.0
rootdir: C:\Users\bruno\pytest\.tmp, inifile: pytest.ini
plugins: forked-0.2, catchlog-1.2.2, hypothesis-3.41.0, xdist-1.20.2.dev7+g5889e4c
collected 1 item

.tmp\test_logging.py F

================================== FAILURES ===================================
____________________________________ test _____________________________________

    def test():
        logger.warning('Some warning')
>       assert 0
E       assert 0

.tmp\test_logging.py:9: AssertionError
---------------------------- Captured stderr call -----------------------------
test_logging.py              8 WARNING  Some warning
------------------------------ Captured log call ------------------------------
test_logging.py              8 WARNING  Some warning
========================== 1 failed in 0.08 seconds ===========================

OK, that mystery is solved then! 😅

The "live logs" feature seems to have been added in eisensheng/pytest-catchlog#33 and never been released, which explains why nobody noticed this before.

[twmr]

I saw it once but when working on a fix this issue vanished, even when switching back to the HEAD of origin/master. I can't explain this ...

Yes unfortunately the live test logging feature hasn't been released yet in pytest-catchlog. (That was one of the reason why I wanted to merge it into pytest-core)

I'm glad that this mystery is solved. :)

Do you think that we should try to remove the loglines from the captured stderr output in your example? IMO they should only be visible in the "captured log call" section.

[nicoddemus]

I'm glad that this mystery is solved. :)

Yep!

Do you think that we should try to remove the loglines from the captured stderr output in your example?

I think by default we should not show the the captured log also on stderr, given that we already capturing it. IOW, I think we "live log" should be opt-in, instead the default. As it stands, the only way to disable it is to set log_cli_level in pytest.ini to some number higher than CRITICAL (which is 500).

[pytest]
log_cli_level=9999

Not sure if that should be the default behavior; my take is that pytest should produce clean output when things are passing, but I would like to hear other opinions on this.

Either way, the current behavior is inconsistent: it is only printing the "live log" when running under xdist, otherwise nothing is being printed.

So we have a bug and a request for change here IMO. If everyone agrees I will open separate a issue for the change request about live logs.

[nicoddemus]

Now that the problem has been identified, I'm closing this in favor of a concrete proposal: #3013

[attila123]

For new users of pytest (maybe coming here googling why their logs are not displayed when testing): based on https://docs.pytest.org/en/latest/logging.html I made this pytest.ini file, with which pytest will output all log messages (in a nicely formatted way).

[pytest]
log_cli=true
log_level=NOTSET
log_format = %(asctime)s %(levelname)s (%(threadName)-10s) %(filename)s:%(lineno)d %(message)s
log_date_format = %Y-%m-%d %H:%M:%S

BTW if anyone knows how to add millisecs to log_date_format, it would be welcome. %f does not seem to work (using pytest 3.6.3).
This does not require any command line option for pytest to work. However I found -v adds some nice green "PASSED" etc. results.
Hope this helps.

[twmr]

On Mon, Jul 9, 2018 at 1:14 PM Attila ***@***.***> wrote: BTW if anyone knows how to add millisecs to log_date_format, it would be welcome. %f does not seem to work (using pytest 3.6.3). Hope this helps.

You can use "'%(asctime)s.%(msecs)03d" in your log_format. HTH '

…

— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub <#3009 (comment)>, or mute the thread <https://github.com/notifications/unsubscribe-auth/AAMm9UUsIciyFPf49FFqpXoUvGxyghSRks5uEzr8gaJpZM4Q5ZTI> .