live logging is not working from a function called by @unittest.skipIf #3964
Description
Based on an example at https://stackoverflow.com/questions/4673373/logging-within-py-test-tests let's create the following files in a directory:
# pytest.ini
[pytest]
log_cli = 1
log_cli_level = INFO
log_cli_format = %(asctime)s [%(levelname)8s] %(message)s (%(filename)s:%(lineno)s)
log_cli_date_format=%Y-%m-%d %H:%M:%S
and
# test_spam.py
import logging
import os
import unittest
LOGGER = logging.getLogger(__name__)
def test_eggs():
LOGGER.info('eggs info')
LOGGER.warning('eggs warning')
LOGGER.error('eggs error')
LOGGER.critical('eggs critical')
assert True
# Looks like needs to be moved out of the test class so that @unittest.skipIf can see it
def _are_test_env_variables_set():
LOGGER.critical('### critical from _are_test_env_variables_set()')
return os.environ.get('FOO') is not None
class TestSomeTestClass(unittest.TestCase):
def setUp(self):
LOGGER.critical('### critical from setUp()')
@unittest.skipIf(not _are_test_env_variables_set(),
"test environment variables need to be set")
def test_foo(self):
LOGGER.critical('### critical from test_foo()')
assert True
Run from the directory with the FOO variable being set, e.g.:
$ FOO=foo pytest test_spam.py
======================================================================== test session starts =========================================================================
platform linux -- Python 3.7.0, pytest-3.8.0, py-1.6.0, pluggy-0.7.1 -- /usr/bin/python
cachedir: .pytest_cache
rootdir: /home/avangel/pytest-test, inifile: pytest.ini
collected 2 items
test_spam.py::test_eggs
--------------------------------------------------------------------------- live log call ----------------------------------------------------------------------------
2018-09-10 18:05:24 [ INFO] eggs info (test_spam.py:11)
2018-09-10 18:05:24 [ WARNING] eggs warning (test_spam.py:12)
2018-09-10 18:05:24 [ ERROR] eggs error (test_spam.py:13)
2018-09-10 18:05:24 [CRITICAL] eggs critical (test_spam.py:14)
PASSED [ 50%]
test_spam.py::TestSomeTestClass::test_foo
--------------------------------------------------------------------------- live log call ----------------------------------------------------------------------------
2018-09-10 18:05:24 [CRITICAL] ### critical from setUp() (test_spam.py:25)
2018-09-10 18:05:24 [CRITICAL] ### critical from test_foo() (test_spam.py:30)
PASSED [100%]
====================================================================== 2 passed in 0.01 seconds ======================================================================
As you can see logs from both setUp() and test_foo() appear, but not from _are_test_env_variables_set().
(you can also run with pytest test_spam.py in which case even setUp() is not seem to be executed, but I guess it is OK)