10:00:01.00 INFO processing request...
10:00:01.01 INFO request processed.
10:00:01.03 INFO processing request...
10:00:01.04 INFO request processed.
10:00:01.07 INFO processing request...
10:00:01.08 INFO request processed.
10:00:01.09 INFO processing request...
10:00:01.10 INFO request processed.
10:00:01.09 INFO processing request...
10:00:01.10 INFO request processed.
10:00:01.09 INFO processing request...
10:00:01.10 INFO request processed.
...Look in wonder at this incredibly helpful diarrhea of application logging.
Now, don’t lie to me. I know you’ve got something like this somewhere.
When you have this kind of excessive logging, finding a problem can mean scrolling through hundreds of lines to find the odd one out. Or, even better, you add some filters to a log query and remove the garbage. But whether you scroll or filter, you’re paying for these logs both literally (your bill) and figuratively (your sanity).
Now, I know these logs often don’t come from a place of ignorance. When we build applications, we want a timeline of events. It helps us understand what is happening even after everyone has long forgotten how the application actually works. Personally, I still want that timeline. I just don’t want all this noise with it.
So, the obvious answer is just to clean up your logging statements and change the log level, right? Well… yes.
…
…
…
Oh, you’re still here? That sounds tedious and brittle, and your fellow lazy developers would never bother? I guess we have other options.
Sampling and rate limiting are common solutions to this problem. Both reduce how much we log, but they choose what to keep differently. Random sampling might keep each message with a 33% probability, while rate limiting puts a cap on how often messages can be emitted.
I tend to group messages of the same kind together, emit the first occurrence, and then suppress repeats for a set interval. Pure random sampling makes for inconsistent log timings that don’t match my personal expectations (OCD).
So, say we allow each message group to emit at most once a minute. The first message emits immediately. Repeats increment a counter until the minute is up; then the next occurrence passes with the number of messages we suppressed. The new output might look like this:
10:00:01.00 INFO processing request...
10:00:01.01 INFO request processed.
10:00:01.45 WARN invalid data.
10:01:01.00 INFO processing request... (suppressed_count: 99)
10:01:01.01 INFO request processed. (suppressed_count: 99)
10:01:01.08 ERROR connection request closed.
...Here, each INFO group had 99 repeats suppressed between its two emitted lines.
The timestamp is when the emitted message happened. We still know the requests kept coming, but we’ve lost the timestamps and fields from those 99 repeats.
Oh? You need to reconstruct an individual request that was suppressed? Tough luck.
…
Fine, fine! We’ll look at how we could potentially address this problem later.
Getting back to it, let’s think about how we could design a suppression logger. We need a key to identify each message group and a bit of state for that key: when we last emitted a message and how many repeats we’ve suppressed since.
Each row in the buffer tracks a separate message group. Here, processing request... was last emitted at 10:00:01.00, and 99 repeats have been suppressed since. When another matching message arrives at 10:01:01.00, the minute is up, so it emits with suppressed_count: 99. We then reset that row’s counter to zero and update its last emission time. The other rows keep their own counts and intervals.
This version only checks the interval when another message arrives. If the group goes quiet, its remaining count stays in memory. Reporting that count without another message means adding a timer or a flush operation.
That leaves one important choice: the message group key, which decides what we get to see. Say we are writing our own custom proxy, like Envoy, that forwards requests to two services, payments and search. Each request gets its own trace_id, and these four failures happen inside one suppression interval:
10:00:01.00 ERROR upstream unavailable {"service": "payments", "trace_id": "a1"}
10:00:01.01 ERROR upstream unavailable {"service": "payments", "trace_id": "a2"}
10:00:01.02 ERROR upstream unavailable {"service": "search", "trace_id": "a3"}
10:00:01.03 ERROR upstream unavailable {"service": "payments", "trace_id": "a4"}If we group by level and message text, only the first line emits. Everything else counts as a repeat, including the failure from search. Now our logs tell us payments is unavailable and say nothing about search.
Key: level + message
10:00:01.00 ERROR upstream unavailable {"service": "payments", "trace_id": "a1"} (suppressed_count: 0)Add service to the key, and the first failure from each service emits. The two remaining payments failures are suppressed together. We can see that both services are having problems without logging every failed request.
Key: level + message + service
10:00:01.00 ERROR upstream unavailable {"service": "payments", "trace_id": "a1"} (suppressed_count: 0)
10:00:01.02 ERROR upstream unavailable {"service": "search", "trace_id": "a3"} (suppressed_count: 0)Add trace_id too, and all four lines emit. Every request has a different trace, so every message gets a new key. We’ve kept all the detail and suppressed nothing.
Key: level + message + service + trace_id
10:00:01.00 ERROR upstream unavailable {"service": "payments", "trace_id": "a1"} (suppressed_count: 0)
10:00:01.01 ERROR upstream unavailable {"service": "payments", "trace_id": "a2"} (suppressed_count: 0)
10:00:01.02 ERROR upstream unavailable {"service": "search", "trace_id": "a3"} (suppressed_count: 0)
10:00:01.03 ERROR upstream unavailable {"service": "payments", "trace_id": "a4"} (suppressed_count: 0)For this example, I’d use level + message + service. I’d still put trace_id on the emitted log so I can investigate that request, but leave it out of the suppression key. That does mean giving up the traces on the suppressed requests.
Every key we keep also costs a small amount of memory. In this example, including service gives us two keys. Including trace_id gives us four and a new one for every failed request after that. Picking a bad key could, in theory, give you millions of entries in your suppression buffer. That’s just inefficient, and I will wag my finger at you, so try to keep this in mind.
So we now have a high-level idea of how a suppression logger can work and the pitfalls we need to watch out for. Let’s get to the actual fun part - implementing this in Go (Coming Soon).