0x07: (Mostly) Irrefutable, Secure, and Performant FastAPI Logging with Structlog -- Testing and Production

Outline

• Part 1: Fundamentals: Non-repudiation, secure logging practices, and log injection, or: why are we even doing this?

• Part 2: Implementation: Adding performant, secure, structured logging to FastAPI.

• Part 3: Testing and Production: Sanity checking your logs and how to get ready to deploy.

Testing

Now that we have the logs working, let's do some sanity checks to make sure they have the info we expect. Automated testing is a great way of offloading some of that mental effort you have to expend in trying to figure out whether your app works. It can also inform us of whether our logs are working right.

Update your workspace so that it matches the following structure:

.├── requirements.txt├── secure_logging│ ├── __init__.py│ ├── logging.py│ ├── main.py│ └── middleware.py├── test│ ├── conftest.py│ ├── __init__.py│ ├── test_logging.py│ └── test_visual.py└── test_requirements.txt

We're going to be focusing on the test folder first. Let's add some packages for testing in test_requirements.txt:

-r requirements.txtrequestspytestpytest-asyncio

Next, let's install:

pip install -r test_requirements.txt

First, let's take a look at the conftest.py file. This will be where we can create fixtures for our tests.

These fixtures will give us some default data to work with to avoid the grunt work of re-typing statements over and over.

Visual Testing

First, I want to add some test cases to just visually test whether the log injection prevention is happening.

Add the following to the test_visual.py file:

(Note that pytestmark = pytest.mark.anyio is simply to mark all of the test cases as async.)

Then, run it with pytest in a separate terminal and check in your Uvicorn server:

You'll notice that Injection\nTime failed to properly inject a new line, and thus potentially a new log, without messing up the appearance of the log entry itself. The metadata came in right at the end. I encourage you to try this out with varying payloads to test whether this approach truly works for yourself.

Log Capture

To spare you the time of showing the full implemented test suite, I will simply show you the setup for one test case:

This should, as implemented, go through the index endpoint (/) and assess the logs from it. You'll notice that the entries have the metadata that we assigned!

Prepping for Production

There are numerous ways that you can prepare a Structlog logger for production, but one of the most common is to use JSON. This allows easier query processing by log aggregators like ELK (ElasticSearch, Logstash, Kibana). See the Structlog docs for more information.

Another thing I want to do is get rid of the Uvicorn logs. We already have a logger, no need to pollute wherever we're sending these logs!

Open up the logging.py file (remember that thing?) and add the following:

You will also need to add this line somewhere before the logging middleware gets initialized: from secure_logging.logging import *

This does a couple of things. First, it disables the Uvicorn logging, so we're left exclusively with the Structlog entries. Second, it distinguishes between development and production environments, such that we still have that nice rich text while developing, and then the powerful JSON rendering for production. The latter is done through environment variables, so it's easy to swap between environments as necessary.

You can even test this yourself. Spool up a Uvicorn server in production mode:

APP_ENV=production uvicorn secure_logging.main:app

And using that log injection Curl command from part 2, you'll get a JSON log that looks very similar to this:

{ "user_agent": "curl/7.81.0", "client": "127.0.0.1:57468", "path": "/login", "method": "POST", "request_id": "5beca2a5-6859-480b-9c4d-a9f1d5bb0fdb", "log_time": "2024-05-03 19:47:48.689596", "security": true, "event": "User admin\ninjection has failed to log in.", "level": "warning", "timestamp": "2024-05-03T19:47:48.690394"}

Log injection stopped in its tracks. We love to see it!

Conclusion

This has been a journey through secure FastAPI and Python logging with Structlog! This should be useful in your future endeavours, regardless of language -- structured logging is a cross-language, cross-framework concept.

If you'd like to clone the repository and try this for yourself, feel free! Here's a link to the repository.

I wish you the best of luck in development, and if you'd like to be informed of future articles and tutorials, subscribe for free! I want to do my best to create a zero-spam newsletter.