py.test logging messages and test results/assertions into a single file

Question

I am starting to work with py.test at the moment for a new project. We are provisioning Linux servers and I need to write a script to check the setup and configuration of these servers. I thought that py.test is a good way to implement these tests and it is working quite fine until now.

The problem I face right now is that I need a log file at the end of these tests showing some log messages for each test and the result of the test. For the log messages I use logger:

logging.basicConfig(filename='config_check.log', level=logging.INFO)
pytest.main()
logging.info('all done')

As an example test I have this:

def test_taintedKernel():
    logging.info('checking for tainted kernel')
    output = runcmd('cat /proc/sys/kernel/tainted')
    assert output == '0', 'tainted kernel found'

So in my logfile I would like an output like that:

INFO:root:checking for tainted kernel
ERROR:root:tainted kernel found
INFO:root:next test
INFO:root:successful
INFO:root:all done

But I cannot get the test results into the logfile, instead I get the standard output on stdout after the tests:

======================================= test session starts =======================================
platform linux2 -- Python 2.6.8 -- py-1.4.22 -- pytest-2.6.0
collected 14 items 

test_basicLinux.py .............F

============================================ FAILURES =============================================
_______________________________________ test_taintedKernel ________________________________________

    def test_taintedKernel():
        logging.info('checking for tainted kernel')
        output = runcmd('cat /proc/sys/kernel/tainted')
>       assert output == '0', 'tainted kernel found'
E       AssertionError: tainted kernel found

test_basicLinux.py:107: AssertionError
=============================== 1 failed, 13 passed in 6.07 seconds ===============================

This may be quite confusing for the users of my script. I tried to get into logger and pytest_capturelog since it was mentioned here quite often but I am for sure doing something wrong since I just don't get it. Maybe just a lack of understanding how this really works. Hope you can give me some hints on this. Please let me know if anything is missing here.

Thanks in advance for your help,

Stephan

Answer 1

pytest's job is to capture output and present it to the operator. So, rather than trying to get pytest to do the logging the way you want it, you can build the logging into your tests.

Python's assert command just takes a truth value, and a message. So, instead of using a bare assert in your tests, you can write a small function that does the logging if the value is false (which is the same condition that triggers the assert to fail), then calls the assert, so that you get the logging you want, plus the assert-driven behavior that creates the console output.

Here's a small test file using such a function:

# test_foo.py
import logging

def logAssert(test,msg):
    if not test:
        logging.error(msg)
        assert test,msg

def test_foo():
    logging.info("testing foo")
    logAssert( 'foo' == 'foo', "foo is not foo")

def test_foobar():
    logging.info("testing foobar")
    logAssert( 'foobar' == 'foo', "foobar is not foo")

Here's the test runner, very similar to yours:

# runtests.py
import logging
import pytest

logging.basicConfig(filename='config_check.log', level=logging.INFO)
logging.info('start')
pytest.main()
logging.info('done')

Here's the output:

# python runtests.py
==== test session starts ========================
platform linux2 -- Python 2.6.6 -- py-1.4.22 -- pytest-2.6.0
collected 2 items

test_foo.py .F

========== FAILURES ============================
________ test_foobar __________________________

    def test_foobar():
        logging.info("testing foobar")
>       logAssert( 'foobar' == 'foo', "foobar is not foo")

test_foo.py:14:
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 

test = False, msg = 'foobar is not foo'

    def logAssert(test,msg):
        if not test:
            logging.error(msg)
>           assert test,msg
E           AssertionError: foobar is not foo

test_foo.py:6: AssertionError    ==== 1 failed, 1 passed in 0.02 seconds =======

And here's the log that gets written:

# cat config_check.log 
INFO:root:start
INFO:root:testing foo
INFO:root:testing foobar
ERROR:root:foobar is not foo
INFO:root:done

Answer 2

Since version 3.3, pytest supports live logging to terminal and file. Example test module:

import logging
import os


def test_taintedKernel():
    logging.info('checking for tainted kernel')
    output = os.system('cat /proc/sys/kernel/tainted')
    assert output == 0, 'tainted kernel found'

Configure of logging to file can be done in pytest.ini:

[pytest]
log_file = my.log
log_file_level = DEBUG
log_file_format = %(asctime)s [%(levelname)8s] %(message)s (%(filename)s:%(lineno)s)
log_file_date_format=%Y-%m-%d %H:%M:%S

Running the test yields as usual:

$ pytest
======================================================= test session starts ========================================================
...
collected 1 item                                                                                                                   

test_spam.py .                                                                                                               [100%]

===================================================== 1 passed in 0.01 seconds =====================================================

Now check the written log file:

$ cat my.log
2019-07-12 23:51:41 [    INFO] checking for tainted kernel (test_spam.py:6)

For more examples of emitting live logs to both terminal and log file, check out my answer to Logging within py.test tests .

Reference: Live Logs section in pytest docs.