How to test specific logging formatting in Python (using `pytest` and `unittest`)

Question

I am implementing a specific logging format, which is going to be parsed by another service for logging/monitoring/alerting purposes. Due to this, the logging format needs to be very specific.

I need to test that my application is indeed using the format I want. However, for whatever reason, pytest is using its own formatting and ignoring mine.

Reproducible example below:

# logtest.py
##### LOGGING CONFIGURATiON
import logging

LOG_CONFIG_FORMAT = '%(asctime)s {%(process)d-%(thread)d} %(levelname)s \
%(name)s@%(lineno)d my_field_1=%(my_field_1)s my_field_2=%(my_field_2)s my_field_3=\
%(my_field_3)s: %(message)s '

logging.basicConfig(level="DEBUG", format=LOG_CONFIG_FORMAT)


def get_logger(logger_name: str):
    logger = logging.getLogger(logger_name)
    adapter = logging.LoggerAdapter(logger, {
        'my_field_2': None,
        'my_field_1': None,
        'my_field_3': None
    })
    return adapter


##### APPLICATION CODE
logger = get_logger(__name__)


def my_func():
    for i in range(3):
        if i > 1:
            logger.extra = {
                'my_field_2': 'BOOM!!!',
                'my_field_1': 'BUST!!!',
                'my_field_3': 'CRASH!!!'
            }
        logger.debug(i)


##### EXECUTE APPLICATION FUNCTION
my_func()


##### TESTING CODE
import unittest


class TestCase(unittest.TestCase):

    def test_log(self):
        with self.assertLogs(level="DEBUG") as cm:
            my_func()
            print(cm.output)
            self.assertIn('my_field_1', cm.output[0])

If I execute python logtest.py I get the correct formatting. If I execute pytest logtest.py I get pytest's own formatting.

Not being concerned about pytest's console output, how can I test that the application logs are formatted indeed the way I want?

Answer 1

If you just want to test the formatting, you don't need to use basicConfig() and assertLogs() - instead, you could use an approach like the following:

import logging
import unittest
import sys

class TestHandler(logging.Handler):
    def __init__(self, *args, **kwargs):
        super().__init__(*args, **kwargs)
        self.messages = []
        
    def handle(self, record):
        self.messages.append(self.format(record))

LOG_CONFIG_FORMAT = '%(asctime)s {%(process)d-%(thread)d} %(levelname)s \
%(name)s@%(lineno)d my_field_1=%(my_field_1)s my_field_2=%(my_field_2)s my_field_3=\
%(my_field_3)s: %(message)s '

formatter = logging.Formatter(LOG_CONFIG_FORMAT)
handler = TestHandler()
handler.setFormatter(formatter)
logger = logging.getLogger(__name__)
logger.setLevel(logging.DEBUG)
logger.addHandler(handler)
adapter = logging.LoggerAdapter(logger, {
    'my_field_2': 'f2',
    'my_field_1': 'f1',
    'my_field_3': 'f3'
})

class TestCase(unittest.TestCase):
    def test_formatting(self):
        adapter.debug('Hello')
        last = handler.messages[-1]
        self.assertIn('my_field_1=f1 my_field_2=f2 my_field_3=f3: Hello ', last)
        
if __name__ == '__main__':
    sys.exit(unittest.main())

You can adapt the above example to your specific needs. Instead of TestHandler, you could use a logging.handlers.MemoryHandler and then interrogate the buffered records for specific conditions. In this case, as you're just testing the formatted output, I've used the approach above to illustrate that.