Your Logging Sucks!

Here's the problem in one line: your logs are lying to you, not maliciously, they're just not equipped to tell the truth. That lands because almost every engineer has already lived it. A customer says their payment failed, you open the log search, you type their email, and you get back a handful of lines in three different formats, none of which say why. This post walks through why the normal way of logging a request produces exactly that outcome, and what replaces it, using a checkout endpoint as the example throughout.

What normal logging looks like

Here's a checkout handler instrumented the way most services are: a log statement at each meaningful step, so you can watch a request move through the function.

@itsnas — TypeScript

Hide line numbersCopy code

async function checkout(req: Request) {
  logger.info('received checkout request')
 
  const cart = await getCart(req.body.cartId)
  logger.info('loaded cart')
 
  await validateStock(cart.items)
  logger.info('stock confirmed')
 
  const attempt1 = await stripe.paymentIntents.create({
    amount: cart.total,
    currency: 'usd',
  })
  logger.info('payment attempt 1: declined')
 
  const attempt2 = await stripe.paymentIntents.create({
    amount: cart.total,
    currency: 'usd',
  })
  logger.info('payment attempt 2: succeeded')
 
  const order = await createOrder(cart, attempt2.id)
  logger.info('order confirmed')
 
  return json(200, { orderId: order.id })
}

Show all 26 lines

main

Nas (@itsnas)

Run this for one user at a time and it reads fine, a story with a beginning, middle, and end. Run it for real traffic and the story disappears. Two users hit checkout a few hundred milliseconds apart and their lines interleave in the order the events actually happened, not the order either request cares about, and this is genuinely what it looks like in the log viewer:

checkout-service (production)16 lines

1. 14:32:01.204ZINFO[gateway]received checkout request
2. 14:32:01.211ZINFO[gateway]received checkout request
3. 14:32:01.340ZINFO[checkout]loaded cart
4. 14:32:01.352ZINFO[checkout]loaded cart
5. 14:32:01.398ZDEBUG[inventory]item sku_9f2 in stock: 12 units
6. 14:32:01.410ZINFO[checkout]stock confirmed
7. 14:32:01.487ZINFO[checkout]stock confirmed
8. 14:32:01.780ZWARN[payments]stripe api slow response: 612ms
9. 14:32:01.902ZINFO[payments]payment attempt 1: declined
10. 14:32:01.918ZINFO[payments]payment attempt 1: declined
11. 14:32:02.201ZINFO[payments]payment attempt 2: succeeded
12. 14:32:02.266ZINFO[checkout]order confirmed
13. 14:32:02.310ZINFO[payments]payment attempt 2: succeeded
14. 14:32:02.375ZINFO[checkout]order confirmed
15. 14:32:02.402ZINFO[gateway]sent response 200
16. 14:32:02.418ZINFO[gateway]sent response 200

Show all 16 lines

Tag every line with a request ID and you can now reconstruct one request out of the interleaved mess, which is real progress and also not enough. You still have thirteen rows to JOIN in your head, in whatever tool you're searching, and you still only get the fields someone remembered to log on that specific line. The decline reason, the card's last four digits, which attempt number succeeded, the user's subscription tier, none of that is on the line that says payment attempt 1: declined unless someone thought to put it there on that line, that day. Miss one field and the information existed in memory when the log statement ran and is gone the moment the process moves on.

Why "just use OpenTelemetry" doesn't fix it

#opentelemetry is a real answer to a different question: how do you get logs, traces, and metrics off a box and into a vendor without hand-rolling an exporter for each one. It says nothing about what a log line should contain. Wrap the same step-by-step logging in OTel spans and you get the same thirteen disconnected fragments, now shipped over a standard protocol instead of stdout. The problem was never the transport.

The fix: one wide event per request

The fix is a wide event: instead of a log line per step, build a single event object over the life of the request, adding fields to it as things happen, and emit it exactly once, at the end. Stripe calls the same idea a canonical log line: one row per request that's the authoritative record of what happened to it.

@itsnas — TypeScript

Hide line numbersCopy code

async function checkout(req: Request) {
  const event = createEvent('checkout', { requestId: req.id })
 
  try {
    const cart = await getCart(req.body.cartId)
    event.set({
      userId: req.userId,
      cartId: cart.id,
      cartTotal: cart.total,
      itemCount: cart.items.length,
    })
 
    await validateStock(cart.items)
 
    let intent: Stripe.PaymentIntent | undefined
    let attempts = 0
 
    for (const key of [
      idempotencyKey(req, 1),
      idempotencyKey(req, 2),
    ]) {
      attempts++
      intent = await stripe.paymentIntents.create(
        { amount: cart.total, currency: 'usd', confirm: true },
        { idempotencyKey: key },
      )
      if (intent.status === 'succeeded') break
      event.set({
        [`declineCode_${attempts}`]:
          intent.last_payment_error?.decline_code,
      })
    }
 
    event.set({
      paymentAttempts: attempts,
      paymentStatus: intent?.status,
    })
    if (intent?.status !== 'succeeded') {
      throw new PaymentDeclinedError(intent?.id)
    }
 
    const order = await createOrder(cart, intent.id)
    event.set({ orderId: order.id, outcome: 'success' })
 
    return json(200, { orderId: order.id })
  } catch (error) {
    event.set({
      outcome: 'error',
      errorType:
        error instanceof Error ? error.constructor.name : 'unknown',
      errorMessage:
        error instanceof Error ? error.message : String(error),
    })
    throw error
  } finally {
    event.emit()
  }
}

Show all 58 lines

main

Nas (@itsnas)

Re-run the two-users-at-once trace against this version. Each request builds its own event object, a plain variable in that request's own closure, so there's no interleaving to untangle. When it's done, one logger.info call emits every field that mattered: user, cart, both payment attempts with their decline codes, which one succeeded, the resulting order, all as one structured row.

@itsnas — JSON

Hide line numbersCopy code

{
  "event": "checkout",
  "requestId": "req_9f2a",
  "userId": "usr_412",
  "cartId": "cart_88b1",
  "cartTotal": 4999,
  "itemCount": 2,
  "declineCode_1": "insufficient_funds",
  "paymentAttempts": 2,
  "paymentStatus": "succeeded",
  "orderId": "ord_7712",
  "outcome": "success",
  "durationMs": 842
}

main

Nas (@itsnas)

Run this against real traffic and the log viewer looks completely different: still one row per request, no matter how many requests come through, and the level tells you the outcome before you've even read the message: error means it never completed, warn means it completed but something was off, debug means it was uninteresting enough not to page anyone. Here's a few seconds of it:

checkout-service (production)18 lines

1. 14:32:01.204ZINFO[checkout]checkout requestId=req_9f2a userId=usr_412 cartId=cart_88b1 cartTotal=4999 itemCount=2 declineCode_1=insufficient_funds paymentAttempts=2 paymentStatus=succeeded orderId=ord_7712 outcome=success durationMs=842
2. 14:32:01.223ZERROR[checkout]checkout requestId=req_a01c userId=usr_701 cartId=cart_55f0 cartTotal=1299 itemCount=1 declineCode_1=insufficient_funds declineCode_2=insufficient_funds paymentAttempts=2 paymentStatus=declined outcome=error errorType=PaymentDeclinedError durationMs=968
3. 14:32:01.318ZWARN[checkout]checkout requestId=req_c17b userId=usr_233 cartId=cart_9a04 cartTotal=8499 itemCount=4 paymentAttempts=1 paymentStatus=succeeded orderId=ord_7714 outcome=success processorLatencyMs=3120 durationMs=3210
4. 14:32:01.402ZDEBUG[checkout]checkout requestId=req_d92f userId=usr_119 cartId=cart_2c71 cartTotal=2599 itemCount=1 paymentAttempts=0 paymentStatus=succeeded orderId=ord_7715 outcome=success replay=true durationMs=6
5. 14:32:01.489ZINFO[checkout]checkout requestId=req_e114 userId=usr_884 cartId=cart_71a2 cartTotal=3499 itemCount=1 paymentAttempts=1 paymentStatus=succeeded orderId=ord_7716 outcome=success durationMs=402
6. 14:32:01.567ZINFO[checkout]checkout requestId=req_f228 userId=usr_305 cartId=cart_0c9e cartTotal=6299 itemCount=3 paymentAttempts=1 paymentStatus=succeeded orderId=ord_7717 outcome=success durationMs=511
7. 14:32:01.648ZERROR[checkout]checkout requestId=req_g33a userId=usr_662 cartId=cart_4d17 cartTotal=1999 itemCount=1 declineCode_1=expired_card paymentAttempts=1 paymentStatus=declined outcome=error errorType=PaymentDeclinedError durationMs=214
8. 14:32:01.702ZINFO[checkout]checkout requestId=req_h447 userId=usr_190 cartId=cart_88ef cartTotal=899 itemCount=1 paymentAttempts=1 paymentStatus=succeeded orderId=ord_7718 outcome=success durationMs=298
9. 14:32:01.789ZDEBUG[checkout]checkout requestId=req_i551 userId=usr_812 cartId=cart_a201 cartTotal=1599 itemCount=1 paymentAttempts=0 paymentStatus=succeeded orderId=ord_7719 outcome=success replay=true durationMs=5
10. 14:32:01.861ZINFO[checkout]checkout requestId=req_j665 userId=usr_047 cartId=cart_b312 cartTotal=4499 itemCount=2 paymentAttempts=1 paymentStatus=succeeded orderId=ord_7720 outcome=success durationMs=356
11. 14:32:01.944ZWARN[checkout]checkout requestId=req_k779 userId=usr_528 cartId=cart_c423 cartTotal=9999 itemCount=5 paymentAttempts=1 paymentStatus=succeeded orderId=ord_7721 outcome=success processorLatencyMs=2890 durationMs=2977
12. 14:32:02.018ZINFO[checkout]checkout requestId=req_l883 userId=usr_951 cartId=cart_d534 cartTotal=2799 itemCount=1 paymentAttempts=1 paymentStatus=succeeded orderId=ord_7722 outcome=success durationMs=274
13. 14:32:02.096ZERROR[checkout]checkout requestId=req_m997 userId=usr_204 cartId=cart_e645 cartTotal=5499 itemCount=2 declineCode_1=insufficient_funds declineCode_2=insufficient_funds paymentAttempts=2 paymentStatus=declined outcome=error errorType=PaymentDeclinedError durationMs=1102
14. 14:32:02.171ZINFO[checkout]checkout requestId=req_n101 userId=usr_369 cartId=cart_f756 cartTotal=3299 itemCount=1 paymentAttempts=1 paymentStatus=succeeded orderId=ord_7723 outcome=success durationMs=331
15. 14:32:02.243ZINFO[checkout]checkout requestId=req_o215 userId=usr_582 cartId=cart_0867 cartTotal=1199 itemCount=1 paymentAttempts=1 paymentStatus=succeeded orderId=ord_7724 outcome=success durationMs=289
16. 14:32:02.319ZDEBUG[checkout]checkout requestId=req_p329 userId=usr_713 cartId=cart_1978 cartTotal=799 itemCount=1 paymentAttempts=0 paymentStatus=succeeded orderId=ord_7725 outcome=success replay=true durationMs=4
17. 14:32:02.394ZINFO[checkout]checkout requestId=req_q443 userId=usr_856 cartId=cart_2a89 cartTotal=7499 itemCount=3 paymentAttempts=1 paymentStatus=succeeded orderId=ord_7726 outcome=success durationMs=467
18. 14:32:02.471ZERROR[checkout]checkout requestId=req_r557 userId=usr_027 cartId=cart_3b90 cartTotal=2499 itemCount=1 declineCode_1=fraud_suspected paymentAttempts=1 paymentStatus=declined outcome=error errorType=PaymentDeclinedError durationMs=189

Show all 18 lines

That support ticket from earlier is now one query: userId = usr_412, sorted by time. The row says the first attempt declined for insufficient funds, the second succeeded, and the order was created. No JOIN, no scanning past seventeen unrelated rows to find it, because there's exactly one row per checkout, regardless of how it went.

The field is only useful if you thought to add it

The createEvent helper above (the full implementation is in the Wide Event Logger snip) is deliberately thin: an object, a .set() that merges fields in, and an .emit() that logs once. All the actual value is in which fields get set, and that's a judgment call made by whoever writes the handler, not something the library can supply for you. Cardinality and dimensionality are the two axes worth knowing by name here, because they explain why that judgment call goes wrong in a predictable direction: cardinality is how many distinct values a field can hold (userId is high, httpMethod is low), dimensionality is how many fields the event carries at all. Teams under-log by reflexively excluding exactly the high-cardinality fields (user ID, order ID, decline code) that are the ones worth searching by, because those are also the fields older, string-search-oriented logging platforms historically charged the most to index. A #clickhouse-style column store doesn't have that problem, so the old instinct to drop those fields no longer earns its keep.

1. 1

   Logging inside a loop or a helper, out of habit

   A logger.info call inside validateStock or the retry loop recreates the interleaving problem one function at a time. Call event.set() there instead, and let the one emit at the top carry it.

2. 2

   Only setting fields on the success path

   The decline code, the retry count, the partial cart state: everything useful for debugging shows up on the failure path. Set fields as you learn them, before you know whether the request will succeed.

3. 3

   Treating this as a logging-library swap

   Nothing about createEvent requires a specific vendor. The mistake is installing it and leaving the call sites logging step-by-step exactly as before; the object is only as good as what gets set on it.

4. 4

   Emitting 100% of traffic forever

   Wide events are wider, which means more bytes per request. At real volume, tail-sample: keep every error and every slow request in full, sample the boring, fast, successful ones down to a few percent.

The checkout handler at the top of this post isn't wrong the way a bug is wrong. It runs, it returns the right response, it even logs something at every step. It's wrong the way a filing cabinet with no folders is wrong: the information is in the building somewhere, and finding it during an incident is on you. One event per request, built up as the request happens and written once at the end, is what turns that filing cabinet into an index.

---