0x06: (Mostly) Irrefutable, Secure, and Performant FastAPI Logging with Structlog -- Implementation

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.

FastAPI Structlog Middleware - Secure, Async, and Easy

Here's where we get to the logging work itself. As the title suggests, we're going to be using structlog for this project. The example API itself is very rudimentary, but it's enough to get you started in terms of working with structured logging and middleware.

Now, you could probably pretty easily find a logging middleware library for this -- however, sometimes default middleware doesn't cut it. So let's build our own!

Requirements

• Python, 3.10 and up is best

• Your brain

Poetry? Nope, I want this to be barebones. Something you can theoretically stick into a Docker container and work with immediately. However, if you're worried about messing up other dependencies on your system, I would recommend a virtual environment of some kind for this.

Setup

We're going to want to get the following project directory set up:

secure-logging/├── requirements.txt└── secure_logging/ ├── __init__.py ├── logging.py ├── main.py └── middleware.py

Don't worry about logging.py for now, that won't come into play until Part 3. secure_logging, with the underscore (_), is going to be our actual Python module, where as the one with the dash (-) will be the project root.

Open up the requirements.txt file and add the following dependencies:

fastapi[all]structlogrich

rich is a dependency for structlog to have some nice coloured output in the terminal, and fastapi[all] gets us all of FastAPI's submodules without having to play any dependency management games. __init__.py lets us import within secure_logging as we please.

Install the packages:

pip install -r requirements.txt

Let's get coding.

A Toybox API Setup

Let's start with a super simple API setup in main.py. Two endpoints: One "hello world" index endpoint, and a login endpoint. This thing doesn't even have a database, just a plaintext set of credentials to illustrate the logging. This goes without saying, but for the love of the universe don't do this in your actual projects!

Told you it was simple. Like I said, 2 endpoints, and a plaintext set of admin credentials. This is a solid playground to test out our logging setup, both with and without user input.

Adding Middleware

Let's switch over to the middleware.py file and get that started. We're going to need to make a subclass of the Starlette HTTP middleware class, since FastAPI is based on that framework.

This is about the simplest scaffold we can make:

We start by importing all of the necessary items, then we have an initializer that gets a Structlog Bound Logger. This is going to be what we're going to use for the rest of this tutorial.

The dispatch function right now is pretty barebones: Take in a request object and a function to call the next item in the middleware chain, make the call, return the response. Let's add some stuff.

In order to assess what we want to add, we need to know what Structlog gives us by default. Their documentation provides an example:

By looking at this image, we have a few things: A timestamp, a log severity level (indicated by the "info" in brackets), the event itself, and some metadata on a per-log basis. Great start!

Structlog has one ace up its sleeve we can use to our advantage, though: We can bind attributes to loggers for future use. Here's some more info on log contexts in Structlog if you need to wrap your head around it.

Based on the events and attributes we identified in part 1, there are a few things I want to bind on top of what Structlog already gives us:

• A request ID, to be able to group disparate log entries for a single request.

• A log start timestamp, to identify particularly long running requests.

• A security flag to ID whether the event is security related. False by default to avoid excess noise.

• Some information about the client requesting the resource.

• And, finally, some information about the endpoint being requested.

Here's what that looks like. Update your dispatch function to look like the following:

user_agent is simply the user agent of the client making the HTTP request. Similarly, client is the IP address and port of said client. path and method relate to the HTTP path and method used to request our endpoint, respectively. request_id is that random request ID I mentioned -- a random UUID (UUIDv4) will effectively guarantee uniqueness for >99.99% of projects. Finally, log_time is the time at which logs for the request began, and security is that security flag I mentioned earlier.

That request.state.logger will allow us to pass the logger into the requests themselves. This is critical to be able to get more detailed data within the endpoints themselves.

One last bit of code: I want to add a completion log entry, similar to how Uvicorn adds log entries when the request completes, to alert you of which endpoint was accessed and what the status code was. This on its own would be a pretty good drop in replacement for Uvicorn!

Add the following just below the response = await call_next(request) line:

This is a little redundant, as we've already declared the method and path as bound attributes, but it helps for developer visibility. If you prefer, you can drop the level to debug instead.

That said, what the heck is request.state.logger.ainfo doing? Short answer: It's an asynchronous version of request.state.logger.info. Same thing, just determines whether or not it blocks the event loop.

Now, we just need to import and add the middleware into the app:

This should be enough to give it a quick test. Spin up the server:

uvicorn secure_logging.main:app --reload

Now make an HTTP request to your index endpoint (http://localhost:8000 is your default). I used curl for this:

curl http://localhost:8000

It might be a little tricky to make out, but success! We have the method, endpoint, and status code in the request itself, and then the metadata we added as attributes! Let's go!

Going Further

Now that we have logging middleware, we can add in logging messages wherever we want within the application itself.

Update your API endpoints to look like this:

Let's go through this one endpoint at a time.

GET /

This one is dead simple. An async Info event that demonstrates the string interpolation that should be the default with logging anyway. "index" is the name of the function, so it acts as a beacon of code location. However, there are more sophisticated ways to do this that we'll explore in Part 3.

POST /login

This demonstrates some of the "when to log" decisions we discussed in Part 1. We have two points of logging: one where the user has successfully done so, and one where they have not. Whether the failure to log in should be a warning or an error is realistically up to you and your application.

Now, at the beginning of the function there is a call to request.state.logger.bind. This is creating a new bound logger off of our existing one, setting the security flag because, hey, this is a security event either way! This should give you an idea of how you can adapt this to the other scenarios.

Testing for Log Injection

Now to get to the topic that sparked this article: Can you use this to prevent log injections?

We can first test the login endpoint's normal fail state with a curl command:

curl -X POST -H 'Content-Type: application/json' \ -d '{"username":"admin", "password": "admin"}'\ http://localhost:8000/login

Well, we know the failure logs are working! Let's try to actually inject into those logs.

curl -X POST -H 'Content-Type: application/json' \ -d '{"username":"admin\ninjection", "password": "admin"}' \ http://localhost:8000/login

Nice! This should even guard against more sophisticated attacks with ANSI codes and highlighting -- except in production, the logs are (probably) going to be in JSON format anyway! So the attack is wasted!

Conclusion

In this part, we looked at actually implementing secure logging with Structlog in FastAPI. Next time, we’ll look at automating the testing of your logs, as well as deploying them to production!