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 (https://github.com/pytest-dev/pytest-xdist/issues/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

[nicoddemus]

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

Yes that is right: we can't transmit arbitrary output from workers easily under the current xdist implementation (which uses execnet under the covers), which is the same problem as in https://github.com/pytest-dev/pytest-xdist/issues/296.

[andreabisello]

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

Yes that is right: we can't transmit arbitrary output from workers easily under the current xdist implementation (which uses execnet under the covers), which is the same problem as in #296.

thanks @nicoddemus but not sure, in my use case, file logging will be corrupted (see the previous comment), so with xdist is never possible to log anything, console or file. If you think logging to file should work, maybe there is something wrong in my configuration. Another question is "why does pytest-logger is working with xdist?"

[az-pz]

If anyone stumbles upon this, there is a workaround. Use

import sys
sys.stdout = sys.stderr

Use this only for debugging purposes. Credit: https://stackoverflow.com/a/37210976/2312300

[JonesKenzie]

@arizzubair sorry I tried this solution but I couldn't figure out how to make it work. I guess this is not a replacement for Live Logs?

Any way, there are no available solution yet to show live logs?

[az-pz]

@JonesKenzie , did you use -s, -vvvv and --log-cli-level=debug arguments while running tests?

[Lz1427611970]

Mark it and I'll try again if it solves the problem，thanks.