Logs You Can Search, and Secrets You Cannot Read

Logs are written for the moment when something is wrong, you have no idea what, and the only evidence is what the process happened to record. A line is useful then if it is findable, meaning machine-parseable fields rather than sentences, and safe, meaning no secret in it, because logs are copied into search systems that many more people can read than can read production.

Structured, meaning fields

// Not this.
l.Info(fmt.Sprintf("item %s created with quantity %d in %dms", id, qty, ms))

// This.
l.InfoContext(ctx, "item created",
	slog.String("item_id", id),
	slog.Uint64("quantity", uint64(qty)),
	slog.Int64("duration_ms", ms),
)

The first produces a line a human can read and a machine has to guess at. The second produces JSON with named fields, so item_id:"019813a0-..." is a query rather than a substring search that also matches every other identifier of that shape. The message stays a short fixed string and everything variable becomes an attribute, because a message that interpolates values makes every occurrence unique and defeats grouping. InfoContext rather than Info passes the context, which is how the trace ID gets onto the record.

The stack

Go’s log/slog is the interface. logutil is configuration: turning the strings "JSON" and "INFO" from a config file into a working handler, holding the common attributes, and providing the hook seam.

logsrv is a slog.Handler backed by zerolog, which writes each record’s attributes directly onto a zerolog event.

You can drop either. slog with the standard library’s NewJSONHandler is a complete answer for many services, and logutil will build one. zerolog and zap used directly are both reasonable and both mean your code is written against their API rather than the standard library’s, which is the trade: slog is the interface every future Go library will speak.

The two backends are interchangeable and not byte-identical. The message field is message through zerolog and msg through the standard library, the injected trace ID lands after the record’s attributes in one and before them in the other, and an error implementing json.Marshaler renders as its message string in one and as an object in the other. None of that matters until you build a parser against one and switch.

Configuration

logcfg, _ := logutil.NewConfig(
	logutil.WithOutWriter(os.Stderr),
	logutil.WithFormat(logFormat),
	logutil.WithLevel(logLevel),
	logutil.WithCommonAttr(logattr...),
)

stderr rather than a file. A container’s log driver, a systemd journal and a developer’s terminal all read the standard streams. A service that writes its own log file has taken on rotation, permissions and disk space, and has hidden its output from the thing that was going to collect it.

Format is JSON or CONSOLE, parsed from configuration. JSON in every deployed environment. Console is for a terminal, where the JSON is unreadable.

Level uses syslog names rather than slog’s four: EMERGENCY, ALERT, CRITICAL, ERROR, WARNING, NOTICE, INFO, DEBUG, plus TRACE. More than most services use, and the ones that earn their keep are ERROR for something that needs a human, WARNING for something that recovered, INFO for events an operator wants to see, and DEBUG for the rest. Records below the configured level are dropped before encoding, so the level is also a cost control.

Both are parsed during startup, per page 03, so an invalid value fails the process instead of silently falling back.

Common attributes, and why release correlation matters

logattr := []logutil.Attr{
	slog.String("program", AppName),
	slog.String("version", version),
	slog.String("release", release),
}

program separates this service’s lines from the other twenty writing into the same log store, and version and release come from the linker flags page 03 set.

Error rate rises at 14:20 and the deploy dashboard says a rollout started at 14:15 and is 40% through. With release on every line, grouping errors by release shows in seconds whether they all come from the new build; without it you are correlating timestamps against a deployment log and guessing. After a rollback the errors either stop or keep arriving tagged with the old release, and those mean different things.

The trace ID

A trace ID is a single value that identifies one request everywhere it goes. Set it once at the boundary, carry it in the context, log it on every record, forward it on every outbound call.

traceid is the mechanism:

id := traceid.FromHTTPRequestHeader(r, traceid.DefaultHeader, traceid.DefaultValue)
ctx := traceid.NewContext(r.Context(), id)

DefaultHeader is X-Request-ID. The HTTP server does this when WithTraceIDHeaderName is set (page 07), and the outbound client does the reverse (page 11).

Two details there are security properties rather than conveniences. FromHTTPRequestHeader validates before accepting: 1 to 64 characters from [0-9A-Za-z._-], and anything else, including an absent header, becomes the default. Without that check a value containing a newline and a fabricated JSON object lets a caller forge log entries, and log injection is a real technique. NewContext is idempotent, returning the context unchanged when an ID is already present, so calling it at several layers cannot overwrite the caller’s ID. ForceContext overwrites, for the case where the service has just decided the authoritative value.

A request arriving with X-Request-ID: abc123 produces records tagged traceid=abc123, and outbound calls carry the same header, so one search returns the request’s path through the system.

That is correlation rather than distributed tracing: no spans, no timings, no causal ordering. Page 13 covers what OpenTelemetry adds and how to turn it on.

A metric per log level

Bootstrap installs a hook on the log config before building the logger:

logCfg.HookFn = func(level logutil.LogLevel, message string) {
	m.IncLogLevelCounter(logutil.LevelName(level))

	if callerHookFn != nil {
		callerHookFn(level, message)
	}
}

Every emitted record increments a counter labelled with its level, and any caller-installed hook is chained after.

Error rate becomes a metric rather than a log query, graphable at one-second resolution and alertable without a log-search backend in the alerting path. It also puts a cost on log levels: logging at Error for something that recovered inflates a number somebody is alerting on. That is why Bootstrap logs its own context-cancellation path at Info:

case <-ctx.Done():
	l.Info("context canceled")

with the comment saying exactly that. Context cancellation is a normal shutdown trigger, and logging it at Warn would put a spike on every deploy.

Redaction

A service handles credentials, tokens, personal data and payment details, and logs HTTP dumps when something goes wrong. Those two facts meet in a log store that far more people can read than can read the production database. redact removes secrets from text before it is written, running every pattern in a single pass, so the cost does not grow with the number of rules enabled.

Nine rule classes:

RuleUserinfo catches the leak nobody plans for. A DSN is user:password@tcp(host)/db, a connection failure wraps it into an error message, and the error message gets logged. That path has nothing to do with request handling and it puts the database password in the logs.

It is on by default

The HTTP client, the HTTP server and the reverse proxy all redact with redact.Default() when no redact function is given. Redaction is never lost by forgetting an option.

Losing it takes a deliberate act:

httpserver.WithRedactFn(redact.InsecureNoRedaction)

The name is the design. Grep for InsecureNoRedaction and you find every place in the codebase where redaction was turned off, which is a review question rather than an archaeology exercise.

Departing from the default

The reference service builds its own:

func newLogRedactor() *redact.Redactor {
	return redact.New(
		redact.WithExtraTokens("floof"),
		redact.WithoutTokens("amount", "balance"),
		redact.WithLuhnCheck(true),
	)
}

WithExtraTokens adds house-specific key names the built-in keyword set does not know. Each argument is matched against the tokenised key, so floof covers floof, userFloof and floof_id. Every organisation has a few of these.

WithoutTokens removes built-in keywords. This service logs monetary amounts that are not sensitive on their own, and replacing every amount field with *** makes the logs useless for what they are most often read for. The source comment records the decision next to the code.

WithLuhnCheck(true) narrows card redaction to digit runs that pass the Luhn checksum. The default is off, which over-redacts, hiding unrelated identifiers that share a card’s prefix and length. Turning it on trades a little safety for readable logs: right for a service full of numeric identifiers, wrong for one handling payment data.

One Redactor is built and shared by every client and server, immutable after construction and safe for concurrent use.

Disabling a whole rule class

WithoutRules exists and the reference service leaves it commented out with an explanation:

// redact.WithoutRules(
// 	redact.RuleHeaders,
// 	redact.RuleJSON,
// 	...
// ),

Every class left enabled keeps redacting, so this is a safe partial opt-out. What it should not do is turn redaction off entirely by listing all nine: that hides the decision inside a constructor, where a reader sees a configured redactor and assumes redaction is happening. InsecureNoRedaction at the call sites makes the same choice visible where it takes effect.

What to log, and what not to

Log what an operator or an investigator would want, at a level matching the attention it deserves: a request completing with its method, path, status and duration, a dependency failing, a retry, shutdown starting and finishing, anything that changed state.

Do not log:

• Full request and response bodies as a matter of course. They are large, they are usually the most sensitive thing the service handles, and the redactor is a filter rather than a guarantee. Log them on error paths, behind a configuration switch, with redaction.
• Anything inside a tight loop. A log line per row of a result set turns a 1000-row query into 1000 records, and the collector will drop them or the bill will notice.
• The same failure at every layer. An error logged by the repository, then by the service layer, then by the handler is one problem and three records, and the middle two carry nothing the first did not. Wrap errors with context and log once, at the boundary where a decision was made about it.

fmt.Errorf("loading item %s: %w", id, err) at each layer builds a message that reads as a path through the code, and one slog.Any("error", err) at the top writes all of it once. Page 10 covers what happens to that error on its way to a status code.

Next: Servers, Binders, and the Routes You Get for Free, which starts Part III.