Test Logging in Django

Background

Logging is an important part of software development. We use logging to track events for purposes of error handling, auditing, security, and so on. Like any other code you write, you need to be able to make sure it works. Perhaps even more importantly, you need to make sure it continues to work as the codebase evolves. Tests are how we ensure this.

Example Log

One particular use I see quite often is catching an exception where you'd otherwise prefer for execution to continue.

try:
    # some block
    pass
except SomeException:
    logger.exception("Something bad happened.")

With this approach, the code will continue without interruption but the exception and log message will end up in our log so we can review later. Let's see how to test it.

Testing Logs

The docs point to a couple tools to test logs.

• assertLogs(logger=None, level=None)
• assertNoLogs(logger=None, level=None)

These two context managers allow us to test both sides of a block that contains a log: a log did occur and a log did not occur. Since these are context managers, the tests should be structured as "with" blocks. Then, the test should check the contents of the message to make sure it was properly constructed .

# tests.py

with self.assertNoLogs(logger="my_logger", level="WARNING":
    # code that doesn't produce a log
    pass


with self.assertLogs(logger="my_logger", level="WARNING" as cm:
    # code that DOES produce a log
    # make sure the log message is correct
    self.assertEqual(cm.output, ["log-message"])

What We're Testing

In a recent article I published, Flatpages In Django Part 2: Extending Flatpages, a simple log was produced to notify admins that an object was retrieved using a primary key but the slug in the URL didn't match what was stored against the object. A suspicious operation but the desire is for execution to continue without user interruption and instead let admins separately investigate.

We'll use this as a more realistic example. At this point it may be useful to pause and familiarize yourself with the this article before continuing.

import logging

from django.contrib.flatpages.views import render_flatpage
from django.contrib.flatpages.models import FlatPage
from django.shortcuts import get_object_or_404


logger = logging.getLogger(__name__)


def flatpage_by_id(request, obj_id):

    f = get_object_or_404(FlatPage, pk=obj_id)
    path = request.get_full_path()
    if f.url != path:
        logger.warning(f"The flatpage with url '{f.url}' doesn't match the request path '{path}'.")
    return render_flatpage(request, f)

In this view function, we retrieve an object by a primary key. The path from the request object is compared to the URL stored on the FlatPage object. If the values don't match, we log the discrepancy. Either way, execution continues.

The Test

The test itself will have two parts:

• A block that tests that no log is produced, and
• A block that tests that a log IS produce and checks that the message is what we expect it to be.

All of this will be tested assuming that the FlatPage object already exists. We'll use one for example purposes with title, URL, and primary key of "Privacy Policy," "/privacy-policy/," and "1" respectively. This object will be accessible with the name "flatpage."

Make Sure No Logs Are Produced

First, we test that under normal conditions, we won't have a log generated.

reversed_url = reverse("privacy-policy")

with self.assertNoLogs(logger.name, "WARNING"):
    # there should not be a log
    response = self.client.get(reversed_url)
    self.assertEqual(response.request.get("PATH_INFO"), flatpage.url)

Produce a Log and Check That Its Correct

Now let's update the URL field of the FlatPage object so the conditional is caught, and a log is generated.

flatpage.url = "/not-the-correct-url/"
flatpage.save()

When we run the following test, our view will encounter a path that differs from the stored URL and a log will be produced.

reversed_url = reverse("privacy-policy")

with self.assertLogs(logger.name, "WARNING") as cm:
    # a log should be produced letting us know we have a bad url
    response = self.client.get(reversed_url)
    self.assertNotEqual(response.request.get("PATH_INFO"), flatpage.url)
    log_message = "The flatpage with url '{}' doesn't match the request path '{}'."
    self.assertEqual(
        cm.output,
        [f"WARNING:{logger.name}:"
         f"{log_message.format(flatpage.url, response.request.get('PATH_INFO'))}"]
    )

First, we check that the path and URL field aren't equal. This is somewhat of a sanity check to ensure our test is set up properly. Next, we build the log message based on what's present in the view. Then we compare the output stored by the context manager to make sure the log produces the message we expect.

Things To Note

The logger used in the view doesn't have an explicitly defined name. Instead the logger was initialized as:

import logging

logger = logging.getLogger(__name__)

In this situation, the __name__ will be the module name. Not something that's likely to change often in our app. But just the same, I wouldn't write the logger's name explicitly in the test. Instead, import the logger from the view into the test and access its name directly. That way, if the module name ever changes, this test doesn't break.

from myapp import logger

with self.assertLogs(logger.name, "WARNING") as cm:
    pass

Bringing It All Together

With all three parts of the above test plus imports and set up, we have:

from django.test import TestCase
from django.contrib.flatpages.models import FlatPage
from django.urls import reverse

from utils.flatpages.views import logger


class TestFlatPageByIdView(TestCase):
    fixtures = [
        "utils/fixtures/sites.json",
        "utils/fixtures/flatpages.json",
    ]

    @classmethod
    def setUpTestData(cls):
        cls.static_url = "/privacy-policy/"
        cls.reversed_url = reverse("privacy-policy")  # flatpage id 1
        # noinspection PyUnresolvedReferences
        cls.flatpage = FlatPage.objects.get(id=1)

    def test_logs_bad_url(self):
        # path and url should equal
        with self.assertNoLogs(logger.name, "WARNING"):
            # there should not be a log
            response = self.client.get(self.reversed_url)
            self.assertEqual(response.request.get("PATH_INFO"), self.flatpage.url)

        # now update flatpage with a bad url so a log is produced
        self.flatpage.url = "/not-the-correct-url/"
        self.flatpage.save()

        with self.assertLogs(logger.name, "WARNING") as cm:
            # a log should be produced letting us know we have a bad url
            response = self.client.get(self.reversed_url)
            self.assertNotEqual(response.request.get("PATH_INFO"), self.flatpage.url)
            log_message = "The flatpage with url '{}' doesn't match the request path '{}'."
            self.assertEqual(
                cm.output,
                [f"WARNING:{logger.name}:"
                 f"{log_message.format(self.flatpage.url, response.request.get('PATH_INFO'))}"]
            )

The above initializes a FlatPage object using Fixtures. Because the FlatPage model uses the Django Sites Framework as a dependency, I also import this fixture and do so first. You could instead create these objects directly in your setUp or setUpTestData methods if you didn't want to use Fixtures.

Last, I want to mention that I would include a number of other tests along with the logging test. What's discussed here is just one component to a broader test of a view function.

Final Thoughts

Logs need to be tested. Especially because a log is often produced within the context of a serious event. This may be a less-frequently encountered test situation but one that needs to be tested, nonetheless. Fortunately, both Python and Django provide for easy-to-use tools to do just that.

With the above, we test both sides of the condition (a situation that produces a log and one that doesn't) and then we test to make sure we produced the message correctly. By including what's discussed here, you're well on your way to making sure your logging will function as desired.