Backend

Structured Logging That Scales Across Services and Jobs

Free-form logs break once a request crosses services. Here is how JSON logs, a correlation ID, and one shared schema make a distributed request traceable.

A single service with a single log file is easy to debug. You grep for an error string, read the lines around it, and you have the story. That model breaks the moment a request touches a second service, or hands work to an async worker, or spawns a background job. Now the story of one request is scattered across three log streams, interleaved with thousands of unrelated lines, with no thread tying them together. The fix is not more logging. It is logging as structured data with a shared identifier that follows the request everywhere it goes. This post shows how to get there: JSON logs instead of sentences, a correlation ID generated at the entry point and propagated through every hop, and one schema every service agrees on.

Why free-form text logs stop scaling

A line like user 4021 failed to charge card, retrying reads fine to a human. To a log system it is an opaque string. If you want to answer "how many charge failures happened for annual-plan users in the last hour," you cannot, because "annual plan" and "charge failure" are buried in prose that varies from one log call to the next. One engineer writes charge failed, another writes payment declined, a third writes could not bill. They mean the same event and no query can group them.

The deeper problem shows up when a request spans services. An API server receives a request, calls a billing service, which enqueues a job for a worker. Something fails in the worker. You have the worker's error, but nothing connects it back to the original request, the user, or the API call that started it. You end up correlating by timestamp and guesswork, scrolling three terminals hoping the timing lines up. At low volume this is annoying. At real volume it is impossible, because dozens of unrelated requests are interleaved in each stream within the same second.

Free-form logs assume a human reads them in order. Distributed systems violate both assumptions: nothing is in order, and no human can read the volume. Logs have to become queryable data.

Logs are data, not sentences

The shift in mindset is this: a log line is not a message a person reads, it is a record a machine queries. Instead of formatting values into a sentence, you emit fields. The event name is a field. The user ID is a field. The outcome is a field. The message, if any, is just one more field, and not the important one.

Here is the same charge failure as free-form text and as structured data.

Aspect Free-form text Structured (JSON)
Shape user 4021 failed to charge, retrying {"event":"charge_failed","user_id":4021,"retry":true}
Filter by event substring match, fragile event = "charge_failed"
Aggregate not possible count() group by user_plan
Cross-service join timestamp guessing join on trace_id
Schema varies per author one agreed set of fields
Reads to a human, in order a query engine, any order

Once logs are fields, the log collector does the work you used to do by eye. You filter to one event type, group by any field, count over a time window, and chart the result. The question "how many charge failures for annual-plan users in the last hour" becomes a filter and a group-by instead of an impossible grep.

In Go, the standard library ships log/slog for exactly this. The key insight is that you attach values as typed key-value pairs, not as interpolated strings.

import "log/slog"

logger := slog.New(slog.NewJSONHandler(os.Stdout, &slog.HandlerOptions{
	Level: slog.LevelInfo,
}))

// Not this. The values are trapped inside a sentence.
// logger.Info(fmt.Sprintf("user %d failed to charge, retry=%v", userID, true))

// This. Every value is a field the collector can query.
logger.Info("charge failed",
	slog.String("event", "charge_failed"),
	slog.Int("user_id", userID),
	slog.String("plan", "annual"),
	slog.Bool("retry", true),
)

The output is one JSON object per line, which every log collector parses natively:

{"time":"2026-07-17T09:14:22+09:00","level":"INFO","msg":"charge failed","event":"charge_failed","user_id":4021,"plan":"annual","retry":true}

Notice the event field is separate from msg. The message is human-friendly text that can change freely. The event is a stable machine key you query on, and it must never drift. Pick the event names once and treat them as an API.

The correlation ID that ties a request together

Structured fields make one service queryable. A correlation ID makes the whole system traceable. The idea is simple: when a request first enters your system, generate a unique ID for it. Then attach that ID to every log line, every downstream service call, and every job the request spawns. To reconstruct the entire journey of one request across every service, you filter on one value.

The ID goes by several names, trace_id, request_id, correlation_id. What matters is that it is created once at the edge and never regenerated. The entry point, usually an HTTP middleware, is where it is born.

// Middleware: reuse an inbound trace ID if a trusted upstream sent one,
// otherwise mint a fresh one. Store it on the context so every log call
// downstream can read it.
type ctxKey string

const traceIDKey ctxKey = "trace_id"

func TraceMiddleware(next http.Handler) http.Handler {
	return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
		traceID := r.Header.Get("X-Trace-Id")
		if traceID == "" {
			traceID = newTraceID() // e.g. a random 16-byte hex string
		}

		ctx := context.WithValue(r.Context(), traceIDKey, traceID)

		// Bind the trace ID into a logger stored on the context, so no
		// call site has to remember to pass it.
		reqLogger := slog.With(slog.String("trace_id", traceID))
		ctx = context.WithValue(ctx, loggerKey, reqLogger)

		w.Header().Set("X-Trace-Id", traceID)
		next.ServeHTTP(w, r.WithContext(ctx))
	})
}

// Every handler pulls the request-scoped logger back off the context.
func loggerFrom(ctx context.Context) *slog.Logger {
	if l, ok := ctx.Value(loggerKey).(*slog.Logger); ok {
		return l
	}
	return slog.Default()
}

Now any log call inside the request carries the trace ID automatically, because the logger was bound with it once at the edge.

func chargeHandler(w http.ResponseWriter, r *http.Request) {
	log := loggerFrom(r.Context())
	log.Info("charge started", slog.String("event", "charge_started"))
	// ... every line from here carries the same trace_id
}

Propagating the ID across service and worker boundaries

An ID that lives only inside one service buys you nothing at the boundary. The whole point is that it survives the hop. There are two hops to handle: a synchronous call to another service, and an asynchronous handoff to a worker or job.

For a synchronous HTTP call, the caller reads the trace ID off its context and writes it into an outbound header. The callee's middleware reads that same header, which is why the middleware above checks X-Trace-Id before minting a new one.

// Outbound call: carry the trace ID forward as a header.
func callBilling(ctx context.Context, body io.Reader) (*http.Response, error) {
	req, _ := http.NewRequestWithContext(ctx, http.MethodPost, billingURL, body)
	if id, ok := ctx.Value(traceIDKey).(string); ok {
		req.Header.Set("X-Trace-Id", id)
	}
	return http.DefaultClient.Do(req)
}

For an async handoff the header trick does not apply, because the worker runs later with no live connection to the caller. So the ID travels inside the message. You put it in the job payload, and the worker pulls it out and rebinds its logger the same way the middleware did.

// Enqueue: the trace ID rides along inside the job payload.
type ChargeJob struct {
	TraceID string `json:"trace_id"`
	UserID  int    `json:"user_id"`
}

func enqueueCharge(ctx context.Context, q Queue, userID int) error {
	id, _ := ctx.Value(traceIDKey).(string)
	return q.Push(ChargeJob{TraceID: id, UserID: userID})
}

// Worker: rebuild the request-scoped logger from the payload, so the
// worker's logs share the trace_id of the request that queued the job.
func (w *Worker) handle(job ChargeJob) {
	log := slog.With(slog.String("trace_id", job.TraceID))
	log.Info("charge job picked up", slog.String("event", "charge_job_started"))
	// ... the worker's failure now joins to the original API request
}

With this in place, one trace_id links the API log, the billing service log, and the worker log. When the worker fails, you filter every stream on that ID and read the request's full path in order, across process boundaries, as if it had run in a single log file.

One schema, one time base, everywhere

Propagation only pays off if every service agrees on the fields. If the API server writes trace_id and the worker writes traceId and the billing service writes request_id, you cannot join them, and you are back to guessing. A shared schema is what makes cross-service queries actually work. Agree on a small set of base fields that every service emits on every line:

  • timestamp, in one time base for the whole fleet. Prefer UTC, or a single fixed zone, so lines from different hosts sort correctly. Mixed local zones make ordering a lie.
  • level, the severity.
  • service, the name of the emitting service, so you can filter one service out of the merged stream.
  • event, the stable machine key for what happened.
  • trace_id, the correlation ID from above.

Beyond these, each event adds its own fields. The base set is the contract; the extras are free. The cheapest way to enforce the base set is to build it into a shared logger constructor that every service imports, rather than trusting each team to remember. If the field names live in one library, they cannot drift.

The time base deserves its own emphasis because it is the most common quiet failure. When one host logs in local time and another logs in UTC, a merged view orders events wrong, and a request that actually took 200 milliseconds can appear to travel backward in time. Pick one zone for machine timestamps and never deviate. Render friendly local times at read time in the dashboard, not at write time in the log.

Level discipline and keeping secrets out

Two rules keep the whole system usable once it is in place.

First, spend log levels carefully. error should mean a human needs to act. If routine, recoverable conditions log at error, the level stops meaning anything, alerts based on it cry wolf, and people learn to ignore the one signal that should never be ignored. Use warn for recoverable-but-notable, info for the normal narrative of a request, and debug for detail you would only want while chasing a specific problem. A retry that succeeds is info or warn, not error. Reserve error for the outcomes that actually failed and stayed failed.

Second, never log secrets or personal data. Structured logging makes this trap worse, not better, because it is so easy to dump a whole struct as fields. That struct may hold a password hash, an access token, a full card number, an email address. Logs get shipped to third-party collectors, retained for months, and read by people who should never see raw personal data, so a secret in a log line is a breach waiting to be discovered. Mask or drop sensitive fields at the logging boundary. Log a user ID, never the email. Log that a token was present, never the token. When you log an error object, make sure it does not carry the request body that triggered it.

What structured logging costs

None of this is free, and it is worth naming the price so the tradeoff is deliberate. Structured logging is more verbose to write than a printf, because you name each field instead of dropping values into a sentence. Threading a trace ID through every service call and job payload is wiring you have to build and maintain, and a single service that forgets to propagate the ID creates a blind spot exactly where you least want one. JSON logs are also larger than plain text, and larger logs cost more to ship, store, and retain, especially at info and debug volume.

The mitigations are ordinary. Sampling drops a fraction of high-volume, low-value lines, so successful requests do not each pay full freight while failures still log in full. Level discipline keeps debug out of production storage by default. A shared logging library absorbs the propagation wiring so individual call sites stay simple. Weighed against the alternative, three terminals and timestamp guesswork during an incident while the clock runs, the cost is small. The moment a request fails somewhere in a chain of services, one correlation ID and one queryable schema turn an afternoon of guessing into a single filter, and that is what decides how fast you recover.

Related posts