Instrument a Service with Wide Events

Naseebullah Ahmadi  Senior Software Engineer, London

You're about to add logging to a new service, or you're staring at an existing one where every incident turns into a grep-and-guess session across a dozen disconnected log lines. Replace the step-by-step logs with one wide event per request.

11 min read
#engineering

Structured logging only pays off if the fields are actually there when an incident hits. This is the reference for wiring a wide event into a request handler correctly the first time, in whichever language the service happens to be written in.

In one line

Build one event object per request, add fields to it as the request progresses, and emit it exactly once at the end (success or error). Search by the highest-cardinality field you have (user ID, order ID, request ID) instead of grepping strings, and tail-sample once volume makes logging everything expensive.

You're here when

Signs this is your situation
  • A new service, job, or webhook handler and you're about to add its first logger.info calls

  • An incident review that ends in "the logs didn't have the field we needed"

  • A user-reported bug where searching their ID returns some, but not all, of the relevant lines

  • Concurrent requests interleave in the log viewer and you can't tell which line belongs to which one

The play

  1. 1

    At the top of the handler, create one event object seeded with whatever you already know: a request ID, the route, the method.

  2. 2

    Wrap the handler body so every exit path, success, an early return, an error, still reaches the emit step. Nothing else changes about the handler's control flow.

  3. 3

    At each point you'd normally have written a step-by-step log line, set a field on the event instead. Set fields on both the happy path and the error path, not just on success.

  4. 4

    Emit the event exactly once, with everything accumulated so far plus a duration: one structured-log call in a finally/defer, or, in a language with RAII, a span that logs itself on close.

  5. 5

    Pick field names once and reuse them everywhere (userId, not user_id in one handler and uid in another). A field searched two different ways is two searches, not one.

  6. 6

    Prefer the highest-cardinality identifier you have available at query time: a user ID or order ID narrows a search far more than a status code or route ever will.

@itsnas checkout.rs
codecheckout.rs
// The span's own fields *are* the wide event: declared empty here,
// filled in as the handler learns them, emitted once when the span
// closes (see main.rs).
#[tracing::instrument(
    name = "checkout",
    skip(state, req),
    fields(
        request_id = %uuid::Uuid::new_v4(),
        user_id = tracing::field::Empty,
        order_id = tracing::field::Empty,
        outcome = tracing::field::Empty,
    )
)]
async fn checkout(
    State(state): State<AppState>,
    Json(req): Json<CheckoutRequest>,
) -> Result<Json<CheckoutResponse>, AppError> {
    let span = tracing::Span::current();
 
    // Step 1: load the cart, record who this request is for the
    // moment we know it.
    let cart = state
        .db
        .load_cart(&req.cart_id)
        .await
        .inspect_err(|_| span.record("outcome", "error"))?;
    span.record("user_id", cart.user_id.to_string().as_str());
 
    // Step 2: place the order, record the outcome either way.
    let order = place_order(&state, &cart)
        .await
        .inspect_err(|_| span.record("outcome", "error"))?;
    span.record("order_id", order.id.to_string().as_str());
    span.record("outcome", "success");
 
    Ok(Json(CheckoutResponse { order_id: order.id }))
}
main
Nas (@itsnas)

Same method, five ecosystems, and the emit step is where they actually diverge. #rust's #tracing span and C#'s System.Diagnostics.Activity both piggyback on the language's own guaranteed-cleanup primitive (Drop, using/IDisposable), so the emit happens on every exit path for free once it's wired up once. Go's defer earns the same guarantee by hand, one line at the top of the function. TypeScript and #python (via #structlog's bind()) have neither, so the try/finally in The play above is doing real work in those two, not just following convention; leave it out and an early return is a request with no event at all. The Wide Event Logger snip and Your Logging Sucks work the TypeScript version through in full.

Which path

New service, no logging yet

  • Skip step-by-step logging entirely, start with wide events from the first handler.
  • Standardize field names in one shared type before the second handler copies the first one's typos.

Existing service, already logging step-by-step

  • Retrofit the highest-traffic, most-incident-prone endpoints first; don't do a repo-wide sweep in one PR.
  • Leave the old log lines in place until the wide event has shipped and been used in at least one real debugging session, then remove them.

Gotchas

  1. 1

    Logging inside a loop or a called helper

    Reintroduces the interleaving problem one function at a time. Pass the event down (or use request-scoped context, or the ambient span a #[tracing::instrument]-style helper already gives you) and set the field from inside the helper instead of writing a fresh log line.

  2. 2

    Only setting fields you need for the success case

    The decline reason, the retry count, the partial state: almost everything worth knowing during an incident only exists on the failure path. Set it there, not just on success.

  3. 3

    Excluding high-cardinality fields to save on ingest cost

    User ID, order ID, and request ID are exactly the fields worth searching by. A column-oriented log store doesn't choke on them the way older string-search platforms did; dropping them to save money removes the fields that make the event useful.

  4. 4

    Shipping this and leaving every call site logging step-by-step

    The helper itself does nothing without call sites actually setting meaningful fields on it. Treat the rollout as rewriting the log calls, not just installing a library.

  5. 5

    Logging every field at 100% once traffic is real

    Wide events cost more bytes per request than a short line does. At volume, keep 100% of errors and slow requests, and tail-sample the boring successful ones down to a few percent.

Confirm you're clear

  1. 1

    Pick a real incident from the last month and check whether the wide event for that request would have answered it in one query.

  2. 2

    Two concurrent requests to the same endpoint produce two separate, fully-tagged rows, not interleaved fragments.

  3. 3

    Field names match across every handler that emits them; a search by userId finds every service, not just the one you last edited.

  4. 4

    A deliberately thrown error inside the handler still produces an emitted event with outcome: 'error'.