how to verfify python log format in unittest?

Question

Recently I am writting an python logging extension, and I want to add some tests for my extension to verify whether my extension work as expected.
However, I don't know how to capture the complete log and compare with my excepted result in unittest/pytest.

simplified sample:

# app.py
import logging
def create_logger():
    formatter = logging.Formatter(fmt='%(name)s-%(levelname)s-%(message)s')
    hdlr = logging.StreamHandler()
    hdlr.setFormatter(formatter)
    logger = logging.getLogger(__name__)
    logger.setLevel('DEBUG')
    logger.addHandler(hdlr)
    return logger


app_logger = create_logger()

Here is my tests

Attempt 1: unittest

from app import app_logger
import unittest


class TestApp(unittest.TestCase):

    def test_logger(self):
        with self.assertLogs('', 'DEBUG') as cm:
            app_logger.debug('hello')
        # or some other way to capture the log output.
        self.assertEqual('app-DEBUG-hello', cm.output)

• expected behaviour:

  cm.output = 'app-DEBUG-hello'
  

• actual behaviour

  cm.output = ['DEBUG:app:hello']
  

Attempt 2: pytest caplog

from app import app_logger
import pytest


def test_logger(caplog):
    app_logger.debug('hello')
    assert caplog.text == 'app-DEBUG-hello'

• expected behaviour:

  caplog.text = 'app-DEBUG-hello'
  

• actual behaviour

  caplog.text = 'test_logger.py               6 DEBUG    hello'
  

Attempt 3: pytest capsys

from app import app_logger import pytest

def test_logger(capsys):
    app_logger.debug('hello')
    out, err = capsys.readouterr()
    assert err
    assert err == 'app-DEBUG-hello'

• expected behaviour:

  err = 'app-DEBUG-hello'
  

• actual behaviour

  err = ''
  

Considering there will be many tests with different format, I don't want to check the log format manually. I have no idea how to get complete log as I see on the console and compare it with my expected one in the test cases. Hoping for your help, thx.

Answer 1

I know this is old but posting here since it pulled up in google for me...

Probably needs cleanup but it is the first thing that has gotten close for me so I figured it would be good to share.

Here is a test case mixin I've put together that lets me verify a particular handler is being formatted as expected by copying the formatter:

import io
import logging

from django.conf import settings
from django.test import SimpleTestCase
from django.utils.log import DEFAULT_LOGGING

class SetupLoggingMixin:
    def setUp(self):
        super().setUp()
        logging.config.dictConfig(settings.LOGGING)
        self.stream = io.StringIO()
        self.root_logger = logging.getLogger("")
        self.root_hdlr = logging.StreamHandler(self.stream)

        console_handler = None
        for handler in self.root_logger.handlers:
            if handler.name == 'console':
                console_handler = handler
                break

        if console_handler is None:
            raise RuntimeError('could not find console handler')

        formatter = console_handler.formatter
        self.root_formatter = formatter
        self.root_hdlr.setFormatter(self.root_formatter)
        self.root_logger.addHandler(self.root_hdlr)

    def tearDown(self):
        super().tearDown()
        self.stream.close()
        logging.config.dictConfig(DEFAULT_LOGGING)

And here is an example of how to use it:

class SimpleLogTests(SetupLoggingMixin, SimpleTestCase):
    def test_logged_time(self):
        msg = 'foo'
        self.root_logger.error(msg)
        self.assertEqual(self.stream.getvalue(), 'my-expected-message-formatted-as-expected')

Answer 2

After reading the source code of the unittest library, I've worked out the following bypass. Note, it works by changing a protected member of an imported module, so it may break in future versions.

from unittest.case import _AssertLogsContext
_AssertLogsContext.LOGGING_FORMAT = 'same format as your logger'

After these commands the logging context opened by self.assertLogs will use the above format. I really don't know why this values is left hard-coded and not configurable.

I did not find an option to read the format of a logger, but if you use logging.config.dictConfig you can use a value from the same dictionary.