logging not captured

[zsluedem]

test_5.py file content

import logging
logger = logging.getLogger(__file__)

def test_1():
    logger.info('123123')

def test_2():
    logger.info('123123')

def test_3():
    logger.info('123123')

def test_4():
    logger.info('123123')

pytest.ini

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

run pytest test/test_5 -n auto

logs:

================================================================= test session starts =================================================================
platform darwin -- Python 3.6.5, pytest-4.1.1, py-1.7.0, pluggy-0.8.1 -- /Users/w/.virtualenvs/pytest_xdist_fixture_scope_test/bin/python
cachedir: .pytest_cache
rootdir: /Users/w/pytest_xdist_fixture_scope_test, inifile: pytest.ini
plugins: xdist-1.26.0, forked-1.0.1
[gw0] darwin Python 3.6.5 cwd: /Users/w/pytest_xdist_fixture_scope_test
[gw1] darwin Python 3.6.5 cwd: /Users/w/pytest_xdist_fixture_scope_test
[gw2] darwin Python 3.6.5 cwd: /Users/wpytest_xdist_fixture_scope_test
[gw3] darwin Python 3.6.5 cwd: /Users/wpytest_xdist_fixture_scope_test
[gw0] Python 3.6.5 (default, Apr 25 2018, 14:23:58)  -- [GCC 4.2.1 Compatible Apple LLVM 9.1.0 (clang-902.0.39.1)]
[gw1] Python 3.6.5 (default, Apr 25 2018, 14:23:58)  -- [GCC 4.2.1 Compatible Apple LLVM 9.1.0 (clang-902.0.39.1)]
[gw2] Python 3.6.5 (default, Apr 25 2018, 14:23:58)  -- [GCC 4.2.1 Compatible Apple LLVM 9.1.0 (clang-902.0.39.1)]
[gw3] Python 3.6.5 (default, Apr 25 2018, 14:23:58)  -- [GCC 4.2.1 Compatible Apple LLVM 9.1.0 (clang-902.0.39.1)]
gw0 [4] / gw1 [4] / gw2 [4] / gw3 [4]
scheduling tests via LoadScheduling

test/test_5.py::test_1
test/test_5.py::test_2
[gw0] [ 25%] PASSED test/test_5.py::test_1
test/test_5.py::test_3
[gw1] [ 50%] PASSED test/test_5.py::test_2
[gw2] [ 75%] PASSED test/test_5.py::test_3
test/test_5.py::test_4
[gw3] [100%] PASSED test/test_5.py::test_4

============================================================== 4 passed in 1.47 seconds ===============================================================

There are no logs print out.
I saw #256 , but it doesn't help

[nicoddemus]

Hi @zsluedem,

Thanks for the report.

If you force one of the tests to fail and use logging.warning, you will see the output:

def test_3():
    logger.warning('123123')
    assert 0

λ pytest .tmp\test-capture.py -n2 -q
bringing up nodes...
F                                                                                            [100%]
============================================ FAILURES =============================================
_____________________________________________ test_3 ______________________________________________
[gw0] win32 -- Python 3.6.3 x:\pytest-xdist\.env36\scripts\python.exe

    def test_3():
        logger.warning('123123')
>       assert 0
E       assert 0

.tmp\test-capture.py:12: AssertionError
---------------------------------------- Captured log call ----------------------------------------
2019-01-17 19:14:16 WARNING (MainThread) test-capture.py:11 123123
1 failed in 0.76 seconds

I'm using logging.warning because that's the default logging setting, and I suspect that log_cli_level setting in your pytest.ini is not having an effect is due to a problem on how config is initialized in workers. This is something which @RonnyPfannschmidt is working on.

[simonfontana]

Hi @nicoddemus. Could you link the issue that @RonnyPfannschmidt is working on?

[nicoddemus]

Sure, it is actually a "project" involving a lot of issues: https://github.com/pytest-dev/pytest/projects/2

[sourcecode14]

@nicoddemus and @RonnyPfannschmidt : Can you please let me know , when this issue will be resolved , as we are facing issues due to this . Awaiting your reply .

[nicoddemus]

Hi @sagardaine,

Unfortunately @RonnyPfannschmidt is a hiatus right now, so this work is halted at the moment. @RonnyPfannschmidt can provide more information about when he plans to get back to this.

[nicoddemus]

Indeed it is a initialization problem, reproducible example:

import logging

logger = logging.getLogger('foo')
def test_3():
    logger.info('123123')
    assert 0

[pytest]
log_cli=true
log_cli_level=DEBUG

 λ pytest test_foo.py
======================== test session starts ========================
...
collected 1 item

test_foo.py::test_3
--------------------------- live log call ---------------------------
INFO     foo:test_foo.py:5 123123
FAILED                                                         [100%]

============================= FAILURES ==============================
______________________________ test_3 _______________________________

    def test_3():
        logger.info('123123')
>       assert 0
E       assert 0

test_foo.py:6: AssertionError
------------------------- Captured log call -------------------------
INFO     foo:test_foo.py:5 123123
===================== 1 failed in 0.03 seconds ======================

λ pytest test_foo.py -n2
======================== test session starts ========================
gw0 [1] / gw1 [1]
scheduling tests via LoadScheduling

test_foo.py::test_3
[gw0] [100%] FAILED test_foo.py::test_3

============================= FAILURES ==============================
______________________________ test_3 _______________________________
[gw0] win32 -- Python 3.7.3 c:\users\bruno.esss.co\temp\.env-test-packs\scripts\python.exe

    def test_3():
        logger.info('123123')
>       assert 0
E       assert 0

test_foo.py:6: AssertionError
===================== 1 failed in 0.44 seconds ======================

[nicoddemus]

Hmm on the other hand, I just noticed that not using log_cli, but just normal logging capture, works as expected:

[pytest]
log_level=DEBUG

λ pytest test_foo.py -n2
======================== test session starts ========================
...
gw0 [1] / gw1 [1]
F                                                              [100%]
============================= FAILURES ==============================
______________________________ test_3 _______________________________
[gw0] win32 -- Python 3.7.3 c:\users\bruno.esss.co\temp\.env-test-packs\scripts\python.exe

    def test_3():
        logger.info('123123')
>       assert 0
E       assert 0

test_foo.py:6: AssertionError
------------------------- Captured log call -------------------------
INFO     foo:test_foo.py:5 123123
===================== 1 failed in 0.42 seconds ======================

So it does not seem to be a problem with initialization, but with capturing output on workers, which is a long standing issue and hard to fix (#296).

[neXussT]

I'm running into this as well. I need my fixtures to print out INFO level logs, but they are never seen, nor are ERROR level during a successful run (tried, just to see). v1.30.0

[karaage-kkkris]

Hey, I have the same request related to this ticket. I need the tests and fixtures to print out INFO level logs since some logs are important for people to check. Do not know if there is a solution right now. Thanks.

[andreabisello]

one year 7 months later, someone has found a workaround?

pytest-xdist is too much important for me ( many thanks pytest-xdist plugin developers <3 ) but i need to store DEBUG logs in a file and output ERROR log in console.

for now , it is only possible to store anything in the file but obtain console output only if test is failing, right?

many thanks.

[andreabisello]

Hmm on the other hand, I just noticed that not using log_cli, but just normal logging capture, works as expected:

[pytest]
log_level=DEBUG

λ pytest test_foo.py -n2
======================== test session starts ========================
...
gw0 [1] / gw1 [1]
F                                                              [100%]
============================= FAILURES ==============================
______________________________ test_3 _______________________________
[gw0] win32 -- Python 3.7.3 c:\users\bruno.esss.co\temp\.env-test-packs\scripts\python.exe

    def test_3():
        logger.info('123123')
>       assert 0
E       assert 0

test_foo.py:6: AssertionError
------------------------- Captured log call -------------------------
INFO     foo:test_foo.py:5 123123
===================== 1 failed in 0.42 seconds ======================

So it does not seem to be a problem with initialization, but with capturing output on workers, which is a long standing issue and hard to fix (#296).

mmh i think not,

log area overwritten and corrupted, for example this is a log without xdist

19-08-2020 17:15:57 test_prima_funzionalita.py test_rosso_uno WARNING warning!
19-08-2020 17:15:57 test_prima_funzionalita.py test_rosso_uno ERROR error!
19-08-2020 17:15:57 test_prima_funzionalita.py test_rosso_uno CRITICAL critical!
19-08-2020 17:15:57 test_prima_funzionalita.py test_rosso_due WARNING warning!
19-08-2020 17:15:57 test_prima_funzionalita.py test_rosso_due ERROR error!
19-08-2020 17:15:57 test_prima_funzionalita.py test_rosso_due CRITICAL critical!
19-08-2020 17:15:57 test_prima_funzionalita.py test_rosso_tre WARNING warning!
19-08-2020 17:15:57 test_prima_funzionalita.py test_rosso_tre ERROR error!
19-08-2020 17:15:57 test_prima_funzionalita.py test_rosso_tre CRITICAL critical!
19-08-2020 17:15:57 test_seconda_funzionalita.py test_bianco WARNING warning!
19-08-2020 17:15:57 test_seconda_funzionalita.py test_bianco ERROR error!
19-08-2020 17:15:57 test_seconda_funzionalita.py test_bianco CRITICAL critical!
19-08-2020 17:15:57 test_seconda_funzionalita.py test_verde WARNING warning!
19-08-2020 17:15:57 test_seconda_funzionalita.py test_verde ERROR error!
19-08-2020 17:15:57 test_seconda_funzionalita.py test_verde CRITICAL critical!
19-08-2020 17:15:57 test_seconda_funzionalita.py test_arancione WARNING warning!
19-08-2020 17:15:57 test_seconda_funzionalita.py test_arancione ERROR error!
19-08-2020 17:15:57 test_seconda_funzionalita.py test_arancione CRITICAL critical!

this is with -n auto

19-08-2020 17:16:19 test_prima_funzionalita.py test_rosso_due WARNING warning!
19-08-2020 17:16:19 test_prima_funzionalita.py test_rosso_due ERROR error!
19-08-2020 17:16:19 test_prima_funzionalita.py test_rosso_due CRITICAL critical!
cal!

you see "cal" is a piece of a row or log, and you get only 4