logs were lying to me

Hey {{first name | there}}. Welcome to our 5,370 new readers. This past weekend I was building a small Kubernetes operator with the usual controller-runtime setup, a reconcile loop watching a custom resource and trying to make the world match the spec. It mostly worked until it didn’t.

In today’s technical notes:

Now I'm going to venture into the territory of "every operator has a story," but this one felt significant enough to turn into a post. I had a weekend of work on a small Kubernetes operator involving controller-runtime reconcile logic watching a custom resource.

Most of it was working, until it was not. So I found myself grepping through my simple log statements looking for logs for reconciling foo-worker in namespace prod. Initially, I was grepping for just the object key; when that didn't turn up enough context, I tried adding the message and also the namespace to the regex.

The reconcile loop's main log line (we'll see why this is a problem shortly) is:

reconciling foo-worker in namespace prod

I have most of the context I need in my regex, but the namespace is appearing inside a string like "reconciling foo-worker in namespace prod." So that information is still trapped in prose, when it would obviously be better as queryable data, and I'm increasingly desperate with regex.

Then I stopped for a moment and realized that exactly the same problem that I was solving for my operator was also a solved problem at a vastly larger scale, right in Kubernetes.

The core idea is an immutable message describing the event, with as much variable data as is required as labelled fields. As a consequence, Kubernetes has moved from log lines like this using klog.Infof format strings:

delete pod %s with policy %s,

to structured logging using klog.InfoS and klog.ErrorS, preserving the fixed message as a prefix while turning the variable parts into labelled fields , message plus alternating key/value pairs  as this log in JSON (almost):

{"msg":"delete pod","pod":"nginx-2335656954-6p729","policy":"Delete"}

The message becomes a constant; everything variable becomes a labelled field.

The migration is informed by some pretty clear guidance: start each message with a capital letter and avoid a trailing period, and always use lowerCamelCase for the key names. Far more importantly, normalize the key names so that each semantic field is always represented by one key chosen at the outset, and consistently used throughout the code base.

Putting this into action, the main event in a controller's reconcile loop is often something like this, and even if it's not capturing every interesting detail you're going to wish you could filter by, this is a great first step:

klog.InfoS("Reconciling", "controller", "k8s.dna/demo", "fooWorker", fooWorker, "obj", obj)

And in case some action fails in this context:

klog.ErrorS(err, "Failed to update status", "fooWorker", fooWorker)

So how does this solve my original query? Well, as you can see, the namespace is not trapped inside a sentence, and the "obj" reference includes namespace/name, not just the name.

 Additionally, the error is attached as a first-class field, err, which enables me to filter the logs straight down to the relevant rows, and then see the ordered sequence that quickly reveals the problem: the stale object was fetched from the cluster before the failure, but that object was the stale version, so it gets re-fetched.

By the way, there's one more rule worth bearing in mind, while the log level plays a role in what a filter returns, it should not influence what gets logged. 

Record with klog.ErrorS regardless of the value of V(), and avoid logging genuinely unexpected or un-swallowed failures at info level. Expected conflicts should be logged at info level and given a reason field; that way, when the log level is set low enough, the high severity around an unexpected error still stands out against the lower-severity logs for conditions that were expected.

So this is a solved problem and the solution is far from unique to Kubernetes. There is a shift underway in Kubernetes (and in Go log/slog in 1.21) to have stable logs matching an "event" message with typed fields, captured in every major ecosystem with Python structlog, Node pino, and Rust tracing. These will typically be emitted as JSON so that observability backends can treat logs as structured data for filtering, correlation, aggregation, and querying.

Unstructured logs push parsing and schema reconstruction downstream, and that's usually at the worst possible time.

Better to pay the cost of structured logging once at the source, where you know the values and their meanings. 

In conclusion, I think structured logging, in addition to Kubernetes' rich event system, makes it that much easier to correlate events. However, it does have a learning curve, especially if you are writing a controller.

Know an engineer who will find this helpful? Share this link with them

Jubril Oyetunji
CTO, EverythingDevOps