0x05: (Mostly) Irrefutable, Secure, and Performant FastAPI Logging with Structlog -- Fundamentals

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.

Here’s a question, have you managed to go through all of your projects and think about logging in every single one?

I sure haven’t — it’s really easy to forget. That said, logging happens to be an important part of security, in terms of knowing what’s going on in your environment and where. It’s a little tricky to catch a thief if you have no alarms in place to detect them.

I'll let you in on a little secret: You've probably experienced why logging is so important, just in a different context. In fact, I have myself, and I know it because it has direct parallels with situations developers and other workers alike all over the world might find themselves in.

A Problem of Dishes

I used to have a roommate who is, thankfully, long gone now. For the sake of anonymity, I'll call him Bruce.

Bruce was a . . . problem. To put it professionally, he would repeatedly cause issues in the house, ranging from leaving napkins he'd used to stifle a bloody nose (gross), to making severe messes in the bathroom, to constantly arguing over chores. Dishes were a major point of contention.

You see, living with three roommates means some dishes are naturally going to get mixed up. I myself sometimes don't have the best memory for what's mine and what isn't. It's easy to forget whose are whose, especially if the dishes aren't done immediately after use.

However, with Bruce in particular, not knowing whose dishes were whose resulted in sometimes entire weeks where we had a full counter of dishes piling up. What felt like the default response when this happened was:

"Those aren't mine."

This, naturally, got frustrating. Sometimes Bruce would admit to some dishes being his -- but others would remain there for weeks. Nobody else would admit to the dishes being theirs. Of course, I'm not innocent of this either (again, memory). But they had to be somebody's. So sometimes people would wash dishes that weren't theirs, just because we lacked one critical thing: Non-repudiation.

Non-repudiation: Programmatic Accountability

Non-repudiation as a security goal is the inability for someone to do something, and then deny having done it. In other words, it's a sort of forced accountability. In the world of tech, blockchain exemplifies this concept perfectly. It is an unchangeable ledger of every transaction ever recorded on it.

For instance, say in the hypothetical distant future we all use cryptocurrency for transactions. You buy something you weren't supposed to: a new bike. You knew your spouse would be upset, so you don't tell them about the transaction. However, you come to them a little while later, and they are pissed. They know what you did. How?

They checked the blockchain. They saw a cryptographically verified (read: functionally impossible for an unassisted human to change) transaction of you sending money to a bike shop. If you try to say it wasn't you, then that means your private key -- essentially your bank password for crypto -- has been compromised, and that has far worse implications than a few thousand dollars burning a hole in your wallet. You can't even deny it; you've been caught red handed.

Once you see this example, it's pretty clear how this can translate into security. Knowing exactly who has performed what action at any given time, such as clients performing actions on servers in a given network, gives you much more authority to take action in the event of malicious behaviour.

Log Injection

One way that an attacker can ruin a security expert's day is by messing with logs. Logs are often considered a source of truth in applications from video games to mainframes. Messing with them can have nasty consequences.

There are a few outcomes of log injection according to the OWASP foundation:

• Log forgery: Creating new log entries, or modifying existing ones, to mask or obfuscate behaviour

• XSS attacks: Injecting an XSS payload into the logs in the hopes they'll show up elsewhere in the application (e.g. admin panels).

• Code execution: Remember Log4j? Yeah, that's a textbook example.

The most common potential issue, however, is attackers abusing character encodings to create or modify entries. The classic CRLF (carriage return, line feed) is the de-facto way of making a line break in text data. Programmers might recognize it as "\r\n", though "\n", the line feed, is also commonly used for simplicity.

Taking this a step further, we can see what an attacker might do to nefarious ends.

Say we have the following Python toy example:

Now, when you run this and look at the log file, you'll get 3 log messages even though you only called the log function twice. The reason? That newline is literally creating a new line in the log file, causing the remaining text to look like another legitimate log message!

INFO:__main__:User entered: HelloINFO:__main__:User entered: GoodbyeINFO:__main__:Forged Log Message!

How do we fix this? The obvious answer might be to do some character encoding sanitization -- swapping out blacklisted characters for less unsavoury ones -- but that has its own problems. Arie Bovenburg has a fantastic article going into more detail. He also mentions structured logging as a potential solution to the CRLF problem.

Let's do some digging into how we can use structured logging to not just solve our log injection woes, but also supercharge our existing logging systems.

(More) Secure Structured Logging

Structured logging, in a nutshell, is working with logs in a way beyond simple lines in a log file. In the case of structlog, it's working with logs in a method similar to Python dictionaries and the standard logging library.

So, why does this work? With structured logging, no part of the logged event bleeds into others, or even the rest of the logs. This is huge for being able to isolate logging events, even if an attacker tries to mask their behaviour. Even if the attacker tries to perform a more sophisticated log injection attack that somehow perfectly mimics the environment and parameters, there is something that renders their efforts meaningless: bound attributes.

Bound attributes allow you to add a sort of metadata to log events, which can give you additional information. The classic example is a timestamp, which logs the time at which the event was logged. We can go a little further, though. We'll also need to figure out what events to even log for security purposes.

An Abbreviated Guide to "What Do I Even Log?!"

The OWASP Foundation provides a handy cheatsheet for figuring out how to do logging and get rid of those "insufficient logging and monitoring" findings off your penetration test reports. However, as I was reading through it, I realized this wasn't just for web applications: it was for any kind of network logging. So we're going to need to chop things down a bit to get to something more manageable.

Events

In general, you should keep an eye out for (and log) the following items:

• Input and output validation errors. Any time your application finds something weird, like a protocol violation, strange encoding, or mismatch? Log it.

• Authentication and authorization failures as well as authentication successes. Logging the failures is obvious. However, if someone logs into your app successfully, log that, too -- it could be coming from a different IP, user agent, or some other indicator that something might be up.

• Session management failures. If someone modifies a cookie in an unexpected way, or changes the session ID, flag it.

• Any errors or other system events. Runtime errors, connectivity and third party service problems, the works. OWASP also suggests logging file upload virus hits, since those could have an impact on diagnosing issues.

• Startups and shutdowns. Any time the application, or something it's talking to, spools up or shuts down, log it. This means any time your logging system starts up, too. This helps with availability monitoring.

• Higher-risk functionality. Anything that potentially changes state in your application? Log it. Doubly so for sensitive data.

• Legal stuff. Anything to do with agreeing to a privacy policy, terms of service, permissions, log it.

Optionally, you would also do well to look at the following:

• Sequencing failures. If someone sends items out of order, that should signal something is amiss.

• Excessive use. Relevant for rate limiting, but also any sort of brute force attack.

• Data changes. Has a user changed their password, email, or bank account details? Log it. This could be under higher-risk functionality, but applicable to any sort of data change.

• Fraud, criminal activity, or other suspicious or unexpected behaviour. This kind of goes without saying.

• Configuration changes. Attackers might change configuration to open up future exploits, or Jeremy might change a config option on you that could affect you without you knowing. Both are good reasons to log this stuff.

• Application code file or memory changes. A little more nebulous, but if something about your codebase changes mid-run? Could signal trouble. I've run into a handful of CTF challenges where the vulnerability involved modifying the Python file off of which the page was running -- anything can happen!

With that (still) long list out of the way, let's also talk about what to include with each log.

Attributes

Every event is going to have some attributes along with it. Since we're working with a web server, let's modify the OWASP list a little to narrow things down.

• When: You'll want both a log and event time, as well as an interaction ID. The first two are timestamps, and you can use UUIDv4 identifiers for the third. The separate log and event times will tell you if you have abnormally long running processes. The interaction IDs can help piece together separate logs as part of a single chain -- this is also kind of the secret ingredient to fighting log injection. Attackers would have to know a lot about the inner workings of the application to pull that kind of attack off -- often more time and effort than the average hacker is willing to put in.

• Where: Logging the application relevant details helps, especially an application name or ID, network address, and which service is producing the log. Geolocations might be relevant as well, as they can indicate logins from different regions, like we mentioned earlier with logging successful authentications. Code location and exact window/location/page can help, but for our purposes, we can usually get away with logging the API endpoint for that.

• Who: Logging the source IP and port is going to most relevant here, as will user agents as they can also give some insight into potential attacks. However, make sure you have legal authority to do the former. Also, for authenticated requests, you can log a database ID or username to figure out which user is making what request.

• What: Finally, logging the type of event, its severity, and whether it's a security event is crucial. A security flag can help sort the development logs from the security logs, so any time you're logging the events mentioned above, having the security flag active will save you some digging. You can also add some description or details to the log, either in the event itself or as added metadata.

For more information, I highly recommend reading through the OWASP Logging Cheat Sheet yourself -- especially for an idea of what not to log.

Summary of What to Log

Events:

• Validation Errors

• Authentication successes/failures, authorization failures

• Session management failures

• Errors and system events

• Startups and Shutdowns

• High risk functionality

• Legal

Recommended, But Optional Events:

• Sequencing Failures

• Excessive Use

• Data Changes

• Fraud/Criminal Activity/Suspicious Behaviour

• Config Changes

• Code File/Memory Changes

Attributes:

• Log Time, Event Time, Interaction ID

• App Name/ID, Network Address, Service, Geolocation, API Endpoint/Page

• Source IP, Source Port, User Agent, User ID (if relevant)

• Event Type, Severity, Security Relevance, Description/Details

Conclusion

In this article, we took a look at why non-repudiation in logging is important, how hackers can take control of logs, and what sort of things we should log in our applications. In the next part, we’ll take a look at how to implement this logging in FastAPI.