Structured Logging I Add on Day One of Every Project

Every project I start gets structured logging before it gets a single feature. Three fields on each log line. It takes about twenty minutes to set up and it has saved me from more 2am guessing sessions than any monitoring dashboard ever has.

The idea is simple. A log line should be something you can search, not something you have to read.

Why I stopped using console.log for anything real

A plain console.log("user saved") is fine until you have two users saving at once. Then your terminal is a stream of "user saved" with no way to tell which request did what.

I lived with that for too long. When something broke, I'd scroll up through hundreds of lines trying to match a timestamp to a stack trace. Half the time I gave up and added more logs, redeployed, and waited for the bug to happen again.

The fix wasn't a fancy tool. It was deciding that every log line is a JSON object with a fixed shape.

Here's the shape I settle on day one:

log.info({
  request_id: "req_8f3a",
  event: "order.created",
  ctx: { order_id: 4471, user_id: 88, total_cents: 2990 }
})

Three things matter here. The request_id ties every line from one request together. The event is a dotted name I can filter on. The ctx object holds the real values I'll want when I'm staring at an incident.

That's it. No schema committee, no logging framework with forty config options. A function that wraps whatever logger I'm using and enforces those three keys.

The reason I do this before features is that logging is cheap to add early and expensive to retrofit. If I write forty route handlers with naked console.log calls, going back to fix them all is a day of boring work nobody wants to do. If the first handler I write uses the structured wrapper, every handler after it copies the pattern for free.

I treat it like a naming convention. Once the first one exists, the rest fall in line. I wrote about that effect in The Command Naming Convention Every RAXXO Tool Follows, where a single early decision shaped everything that came after. Logging is the same deal. The habit does the work, not the willpower.

The request_id is the whole trick

If I had to keep one of the three fields, it's request_id.

Picture an order that fails. The failure log says "payment declined". Useful. But what led there? Without a shared id, you can't tell. With one, you type request_id:req_8f3a into your log search and get the full story in order: request received, user looked up, cart validated, payment attempted, payment declined.

That's a timeline. From one search box.

I generate the id at the entry point. For an HTTP server that's a middleware that runs before anything else. It makes a short random id, attaches it to the request, and every log call inside that request reads it.

The hard part isn't generating the id. It's carrying it. In async code the id has to survive across awaits, across callbacks, across every function the request touches. Passing it manually as an argument to every function is miserable and you'll forget.

Node has a clean answer: AsyncLocalStorage. You set the id once at the entry point and read it anywhere downstream without threading it through arguments. The logger reaches into that store and stamps the id on every line automatically. I never have to think about it again after the middleware is written.

Async is where most logging setups quietly fall apart, so it's worth getting the context propagation right early. If you want the deeper context on how Node behaves under load, see I Found the Exact Recursion Depth That Crashes Node, which gets into the runtime details.

One thing I learned the slow way: use a short random id, not an incrementing counter. Counters leak information about how many requests you've handled and they collide across restarts. Eight random characters are enough to be unique within a debugging window, short enough to copy by hand, and they don't tell a stranger anything.

If a request crosses a service boundary, I pass the id along in a header so the downstream service logs under the same id. Then one search spans two services. That's the moment structured logging stops being a nice-to-have.

The event name is for machines, the context is for you

I split what goes in a log line into two jobs.

The event field is a short dotted string like order.created, payment.failed, or cache.miss. It's for filtering and counting. I can ask my log tool "how many payment.failed in the last hour" and get a number without any text parsing. The event name is a machine handle.

The ctx object is for the human reading it at 2am. That's me. It holds the actual values: which order, which user, what amount, what the response time was. When I'm debugging I don't want adjectives, I want numbers. The same way I'd rather measure than guess in Debounce vs Throttle: I Counted Every Call, I want the real values in the log, not a vague message.

The mistake I used to make was cramming everything into the message string. "payment failed for order 4471 amount 2990". That reads fine to a person and is useless to a machine. You can't filter on it cleanly, you can't graph it, and the format drifts every time a different part of the code logs a payment.

Pull the values out into fields and the string becomes a stable label. The values live in ctx where a query can reach them.

I keep a small rule for ctx: log ids and numbers, not whole objects. Dumping a full user object into a log line is how secrets end up in plaintext. I pick the two or three fields I'd actually search on. An order_id and a total_cents, not the entire order with the customer's address attached.

Levels matter less than people think, but I still use three. info for things that happened, warn for things that are recoverable but odd, error for things that broke. I don't use debug in anything that ships because debug logs that nobody reads are just noise with a cost.

The payoff shows up during an incident. I search by event to find the failures, then grab a request_id from one of them, then search that id to get the full timeline of that one broken request. Filter, pick, expand. That loop is fast because the fields were there from line one.

What this actually costs and when it pays off

The setup cost is small. A logging wrapper, a middleware, the AsyncLocalStorage plumbing. For a new project I budget about twenty minutes. For an existing project it's longer because you're editing every log call, which is exactly why I don't let a project reach that state.

The runtime cost is close to nothing. Building a JSON object and serializing it is cheaper than the database query the line is probably describing. I ship JSON logs to a file or stdout and let the platform collect them. No extra service to run.

The payoff is lumpy. Most days structured logging does nothing visible. You write features, logs pile up, you don't look at them. Then one night a payment flow breaks and the difference between a structured setup and a pile of console.log is the difference between a five-minute search and a two-hour scroll.

I've had the bad version. Scrolling a terminal at 2am, copying timestamps into a notepad, trying to reconstruct which log lines belonged to the failing request. It's slow and you make mistakes while tired. The structured version is: paste the id, read the timeline, see the line where it broke.

There's a second payoff that's easy to miss. Structured logs are a dataset. Once events have stable names and numeric fields, I can count them. How often does the cache miss. What's the p95 response time on the slow route. How many signups failed validation yesterday. That's observability for free, built from logs I was already writing. I don't need a separate analytics pipeline to answer basic questions about what my code is doing.

I treat this the same way I treat the safety nets I build into every tool. An undo button and an export button are things you add before you need them, not after. I wrote about that mindset in The Export Button Every RAXXO Tool Ships With. Logging belongs in that same category of boring insurance.

If you want to keep the logs manageable, resist the urge to log everything. One line per meaningful event beats ten lines per request. A noisy log is as useless as no log, because the signal drowns. I'd rather have fifteen well-chosen events than two hundred that blur together.

Bottom Line

Add the three fields on your first log line, not your first outage. A request_id carried through async code, a dotted event name for filtering, and a ctx object holding real values. Twenty minutes of setup and you've turned debugging from reading into searching.

If you're starting something new this week, write the logging wrapper before the first route. The first handler sets the pattern and everything after it copies for free. If you're on an existing project, add the wrapper now and convert log calls as you touch them, rather than scheduling a cleanup day that never comes.

I run almost all of this through Claude Code, including the boring plumbing like the AsyncLocalStorage setup that's easy to get subtly wrong. If you want to see how I structure that workflow end to end, the Claude Blueprint walks through how I set up a new project so these habits are in place from the start.

Future you, at 2am, will thank present you for the search box.