Structured Logging, Configuration and Containers

An alert fires at 02:00 and you open the log stream. Four hundred lines from the last minute, six replicas, and the only thing you know is that one customer's checkout call failed. Without a request ID the search is hopeless: you want a line you have never seen in a stream where every line looks the same. With one, you paste sixteen characters into the search box and get the four lines that belong to that call.

Logging, configuration and packaging decide whether a service can be operated, and all three share a failure shape: the mistake costs nothing today and everything on the day you need it.

A request ID makes one call findable, and the context carries it

The identifier has to reach every line the request writes, including lines five calls deep in code that has never heard of HTTP. That rules out a package-level variable, which two concurrent calls would overwrite, and a global logger reconfigured per request, which has the same problem. An id string argument works and pollutes every signature between the handler and the database.

The context is already threaded from the handler through everything that touches the request. Put the ID and a logger carrying it there:

func Middleware(base *slog.Logger) func(http.Handler) http.Handler {
	return func(next http.Handler) http.Handler {
		return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
			id := r.Header.Get("X-Request-ID")
			if id == "" {
				id = NewID() // "req-" + 8 random bytes, hex encoded
			}
			logger := base.With(slog.String("request_id", id))
			ctx := WithID(r.Context(), id)
			ctx = WithLogger(ctx, logger)
			w.Header().Set("X-Request-ID", id)
			next.ServeHTTP(w, r.WithContext(ctx))
		})
	}
}

Two details matter. The ID comes from the incoming header when a proxy or caller supplies one, because that is the ID somebody else is already searching for. And the response carries it back, so the person reporting the failure can be asked for it instead of a timestamp.

Handlers take the logger from the context. From(ctx) returns the default logger when there is none, so a background job can call the same helper:

func From(ctx context.Context) *slog.Logger {
	if l, ok := ctx.Value(loggerKey).(*slog.Logger); ok && l != nil {
		return l
	}
	return slog.Default()
}

The handler that writes the line never mentions the ID: With baked it into the logger once.

time=2026-10-16T20:00:08.152493Z level=INFO msg="pprof listening" addr=127.0.0.1:16070 scope="loopback only"
time=2026-10-16T20:00:09.361435Z level=INFO msg=request request_id=7f3a1c9e method=GET path=/work status=200 duration=17µs
time=2026-10-16T20:00:09.371616Z level=INFO msg=request request_id=req-16c2d60448f6aeae method=GET path=/work status=200 duration=21µs

The first line came from a client that sent its own X-Request-ID; the second was given one. Both are greppable.

Two handlers, one decision, and the level comes from outside

The standard library's log/slog gives you one logging call and a choice of handler. slog.NewJSONHandler writes one JSON object per line, which a log collector wants. slog.NewTextHandler writes key=value pairs, which a person wants. Pick per deployment:

opts := &slog.HandlerOptions{Level: cfg.LogLevel}
if cfg.LogFormat == "text" {
	return slog.New(slog.NewTextHandler(os.Stdout, opts))
}
return slog.New(slog.NewJSONHandler(os.Stdout, opts))

The level comes from the same configuration, which makes debug logging an environment change and a restart rather than a code change and a deploy. That is the argument against making it dynamic: a level that changes while the service runs is a variable every goroutine reads.

One less obvious part of the API is worth adopting immediately: the DebugContext, InfoContext and ErrorContext variants make a handler that forgot to pass the context visible at the call. WithGroup nests attributes under a name, so a subsystem's fields cannot collide with the transport's:

db := logger.WithGroup("db")
db.Info("query finished", slog.Duration("took", d), slog.Int("rows", n))

// {"msg":"query finished","db":{"took":1200000,"rows":3}}

Some values must never reach a log line, and the fix is upstream of the logger

Credentials, session tokens, API keys, Authorization headers, passwords, connection strings with the password in them, and personal data the service has no business retaining: none belongs in a log. Logs are copied, and one line lands in a collector, a dashboard, a ticket and a laptop. Revoking a token that is in five places means rotating it.

The tempting defensive move is a ReplaceAttr hook that scrubs keys named token or password. Use it as a backstop, not as the mechanism: it only sees attributes passed as attributes, so a credential formatted into a message string or a wrapped error goes past it. Decide at the call what the line may contain:

{"time":"2026-10-16T19:49:29.743873Z","level":"INFO","msg":"token exchange","token":"sk_live_9f3c21ab77"}

That value is now in the log stream for as long as the retention policy says. The version that ships logs something that is useful for support and useless to an attacker:

{"time":"2026-10-16T20:00:13.964511Z","level":"INFO","msg":"token exchange","token_len":18,"token_present":true}

You can still answer what matters: did the request carry a token, and was it the wrong length, meaning a truncated paste rather than a revoked credential? You cannot answer "what was the token", which is the point. The same reflex applies to errors: a driver error often contains the DSN, and slog.Any("error", err) prints it.

Configuration without a library: read the environment, then refuse to start

For a service this size, a configuration library is a dependency you do not need. You need a rule about where each setting comes from and one place that decides a configuration is usable: environment variables for what differs between deployments, a Defaults() function returning safe values, and a Validate method called once before anything is opened.

Load takes a Lookup function instead of reading os.Getenv, so its tests never touch the real environment:

type Lookup func(key string) (string, bool)

func FromEnv(key string) (string, bool) { return os.LookupEnv(key) }

func Load(lookup Lookup) (Config, error) { ... }

The second return value from os.LookupEnv is why this signature exists. "Unset" and "set to empty" are different facts, and treating them alike is how a deployment that forgot DSN silently keeps the development default.

Validation has to cover combinations that look fine individually: the profiling address must differ from the public address, because pprof on the public port is an information leak on a schedule, and in production it must be loopback with the DSN present. None of that is visible in one value, so Validate takes the whole Config.

Report every bad value at once, because fixing them one at a time costs restarts

A startup check that returns on the first problem means a restart cycle per bad variable: fix LOG_LEVEL, restart, discover READ_TIMEOUT ninety seconds later. Join the errors and print all of them:

var errs []error
if v, ok := lookup("READ_TIMEOUT"); ok {
	d, err := time.ParseDuration(v)
	if err != nil || d <= 0 {
		errs = append(errs, fmt.Errorf("READ_TIMEOUT=%q: want a positive duration like 5s", v))
	} else {
		c.ReadTimeout = d
	}
}
// ...
return c, errors.Join(errs...)

Real output from one start with several variables wrong at once. The process exits with status 2 and never opens a socket:

$ LOG_LEVEL=verbose LOG_FORMAT=xml READ_TIMEOUT=30 WORKERS=0 ./profilesvc
configuration rejected:
LOG_LEVEL="verbose": want debug, info, warn or error
READ_TIMEOUT="30": want a positive duration like 5s
WORKERS="0": want an integer between 1 and 1024
LOG_FORMAT="xml": want json or text
$ echo $?
2

Status 2 for a configuration failure and status 1 for a runtime failure is worth keeping: a script can tell "retrying will not help" from "something broke".

A static binary in scratch is the point of the two-stage build

CGO_ENABLED=0 is not a performance flag. It produces a binary with no dynamic loader and no libc, which is what makes the final image possible. The build stage carries the toolchain and the module download; the second stage copies one file. There is no shell to exploit, no package manager to update, and no CVE feed for a base image with a hundred packages in it.

# Stage 1: build. The builder image carries the toolchain and is thrown away.
FROM golang:1.26 AS build

WORKDIR /src

# Dependencies first, so a source change does not invalidate the module layer.
COPY go.mod ./
RUN go mod download

COPY . .

RUN CGO_ENABLED=0 GOOS=linux go build \
      -trimpath \
      -ldflags="-s -w" \
      -o /out/profilesvc ./cmd/profilesvc

# Stage 2: run. An empty filesystem, no shell, no package manager, no libc.
FROM scratch

COPY --from=build /out/profilesvc /profilesvc

# Nothing in the image needs to write, so run as a user that cannot.
USER 65534:65534

EXPOSE 8080
ENTRYPOINT ["/profilesvc"]

Every line is load-bearing. COPY go.mod before COPY . . means editing a Go file does not re-download the module cache. -trimpath keeps this machine's home directory out of the binary. -s -w drops the symbol table and DWARF data: the same package builds to 9,380,178 bytes plain and 6,420,466 bytes with those flags. USER 65534:65534 means the process cannot write anything, because the image has no directory it owns.

The Linux cross-build confirms the static part without a container runtime. It produces an ELF executable with no interpreter, which is what scratch needs:

$ CGO_ENABLED=0 GOOS=linux GOARCH=amd64 go build -trimpath -ldflags="-s -w" -o deploy/profilesvc-linux-amd64 ./cmd/profilesvc
$ file deploy/profilesvc-linux-amd64
deploy/profilesvc-linux-amd64: ELF 64-bit LSB executable, x86-64, version 1 (SYSV), statically linked, Go BuildID=..., stripped

This machine has no running Docker daemon, so the image was not built or run while writing this lesson: docker version fails to reach /var/run/docker.sock. The Dockerfile is verified by its parts (the static Linux binary, the copy ordering, the flags) and not by a docker build. Run docker build -t profilesvc . and confirm the second stage runs and docker run --rm profilesvc prints its listening line.

If PID 1 is a shell, SIGTERM never reaches your shutdown code

A runtime sends SIGTERM to PID 1 and nothing else. If PID 1 is your binary, that reaches the signal.NotifyContext handler module 4 wrote. If PID 1 is a shell that started your binary in the background, the shell takes the signal and your program never learns.

This is measurable. The harness starts the same service three ways, sends SIGTERM after 1.2 seconds, and records whether the service logged its own shutting down line:

A. binary is PID 1                           exited in 1ms        graceful_shutdown_logged=true
B. sh -c exec (exec replaces sh)             exited in 2ms        graceful_shutdown_logged=true
C. sh -c 'binary & wait'  (sh stays PID 1)   exited in 0s         graceful_shutdown_logged=false

Cases A and B are correct, and B is the one to remember: sh -c 'exec /profilesvc' replaces the shell with the binary, so the program is PID 1. Case C is what a wrapper script that starts the service and sleeps does:

before SIGTERM: service alive = true (sh pid 21800 is PID 1)
sh exited; service still listening = true
  t+1s: service alive = true
  t+2s: service alive = true
  t+3s: service alive = true
runtime gives up and SIGKILLs the container:

The drain never runs, in-flight requests are cut when the grace period expires, and a background worker keeps going for as long as the runtime allows. In Kubernetes the pod sits in Terminating until terminationGracePeriodSeconds expires and the kubelet sends SIGKILL, turning a half-second deploy into ten seconds, every deploy. Three fixes exist: the exec form of ENTRYPOINT, exec in the script, or docker run --init so a tiny init process forwards signals. Prefer the first: it costs nothing and cannot be forgotten in another image.

if v := os.Getenv("CACHE_DSN"); v != "" {
	c.CacheDSN = v
}

if v, ok := lookup("CACHE_DSN"); ok {
	switch {
	case v == "":
		errs = append(errs, errors.New("CACHE_DSN is set but empty: unset it to use the default"))
	case !strings.HasPrefix(v, "redis://"):
		errs = append(errs, fmt.Errorf("CACHE_DSN=%q: want a redis:// URL", v))
	default:
		c.CacheDSN = v
	}
}

Which is the thread running through all six modules. Every choice in this course is about where a value lives and who owns it. A type owns its invariants, so a Message the parser alone can build cannot carry a negative byte count. An interface is owned by the code that calls it, which is why it is declared next to the consumer. An error is a value the caller decides about, not a jump the runtime decides about. A goroutine's lifetime is owned by the context it started with, which is the only reason cancellation propagates. A transaction owns the rows it touches, a migration owns the schema's shape, a request owns its logger and its ID, a container owns one process, and a test owns the input it claims to exercise. None of that is a Go feature. It is one question asked at six levels, and the services that stay calm are the ones where the answer is the same at every level.