Chapter 11: Getting to Production

A fire drill and a real fire look identical for the first ten seconds. The alarm sounds the same. People stand up the same way. What tells them apart is everything that was already in place before the alarm went off: whether the exits were marked, whether anyone knew which stairwell to use, whether the building even had a plan. Production incidents work the same way. The gRPC call that fails at 3am looks exactly like the gRPC call that failed in a unit test at 3pm — same error, same stack, same shape. What tells them apart is everything already in place before that call failed: whether the error said anything useful, whether anyone could see it happening, whether a retry made things better or quietly made them worse.

localdir-csi works. Every RPC this book has built is tested, green, and proven against a real cluster. That was never really in question — TDD makes "does it work" almost boring to answer. What this chapter asks is a different question: if this driver were running for real, at 3am, with nobody watching, would anyone be able to tell what went wrong? Right now, mostly not. This chapter closes that gap in two concrete ways — structured, auditable error codes, and logs and metrics an operator can actually use, actually scraped off a real running pod — without changing what this driver does, only what it's like to run.

What "production" doesn't mean here

Worth saying plainly, the way this book has named every other honest simplification: this chapter does not turn localdir-csi into something you'd actually run in a real cluster. It still stores volumes as plain directories on one node, with no real capacity enforcement, no multi-node story, and no real backend underneath it. Volume Expansion was cut from this book's plan for exactly this reason — ControllerExpandVolume/NodeExpandVolume would have nothing real to exercise, since CreateVolume never enforced a real size limit to begin with. Padding out an RPC nobody could meaningfully test isn't "getting to production," it's decoration.

What is real, and worth a whole chapter: the operational concerns that apply to this driver exactly as much as they'd apply to a driver backed by a real SAN. Bad error codes confuse real callers regardless of what's underneath. Missing logs and metrics leave a real operator blind regardless of what's underneath. Both problems are real, and fixable, without pretending this toy driver is something it isn't.

Structured error codes: an audit, and a DRY pass

Every RPC in this driver already returns a codes.X — that's been true since Chapter 3. What hasn't happened yet is checking that every one of those codes actually matches what the CSI spec says callers should expect. The spec's own spec.md documents, RPC by RPC, which conditions map to which gRPC code — the same kind of upstream source this book has checked before drafting since Chapter 3's "check the interfaces first" convention, just applied retroactively this time, against code that already shipped.

Read internal/driver/controller.go and internal/driver/node.go against that table, RPC by RPC, and it holds up. A few gaps are real but already-named simplifications — DeleteVolume never returns FAILED_PRECONDITION for "volume in use," because this driver has no real attachment tracking to know that; ControllerPublishVolume never returns NOT_FOUND for a nonexistent node, because a single-node driver has no node registry to check against. Both already flagged, in Chapter 7 and Chapter 8's own text — nothing new to fix there.

Two other gaps used to live on this list too: CreateVolume not checking capacity on retry, and NodePublishVolume not checking access mode on retry. Both real bugs, not simplifications — and both already closed by the time this chapter starts. NodePublishVolume got its fix in Chapter 6, the moment its own IsMountPoint check turned out to answer a narrower question than "is this genuinely the same request." CreateVolume got its fix in Chapter 9, the moment a real csi-sanity run turned the same suspicion into a real failing test. Nothing left to fix here — but the audit does turn up something the fixes themselves left behind.

Read those two fixes next to CreateSnapshot's own idempotency check from Chapter 10, and the same nine lines show up in all three, changed only in which metadata type they read and what they compare:

if existing, err := readXMeta(d.dataDir, id); err == nil {
	if <conflict> {
		return nil, status.Errorf(codes.AlreadyExists, ...)
	}
	// ...use existing, return early...
} else if !os.IsNotExist(err) {
	return nil, status.Errorf(codes.Internal, "reading ... metadata: %v", err)
}

Three RPCs, three metadata types, one repeated shape: read a record, and turn "does it exist" into one of three answers — no record yet, here's the record, or something went wrong reading it. Always DRY says that repetition is overdue for collapsing, the same way Chapter 6's own test helpers collapsed a different repeated shape a few chapters back.

Add internal/driver/meta.go:

package driver

import "os"

// readMetaOrZero reads metadata via read. If a record exists, it comes
// back with found=true. If none exists yet, readMetaOrZero returns the
// zero value with found=false and no error — the one signal every
// idempotency check in this driver needs before deciding whether a
// request is the first one for this name, or a retry of one already
// recorded. Any other read error is returned as-is, for the caller to
// wrap into its own codes.Internal message.
func readMetaOrZero[T any](read func() (T, error)) (meta T, found bool, err error) {
	meta, err = read()
	if err == nil {
		return meta, true, nil
	}
	if os.IsNotExist(err) {
		var zero T
		return zero, false, nil
	}
	var zero T
	return zero, false, err
}

Then each of the three call sites shrinks by a line and reads a little straighter. CreateVolume, in internal/driver/controller.go:

	existing, found, err := readMetaOrZero(func() (volumeMeta, error) {
		return readVolumeMeta(d.dataDir, req.GetName())
	})
	if err != nil {
		return nil, status.Errorf(codes.Internal, "reading volume %q metadata: %v", req.GetName(), err)
	}
	if found {
		if existing.CapacityBytes != requestedBytes {
			return nil, status.Errorf(codes.AlreadyExists, "volume %q already exists with a different capacity", req.GetName())
		}
		return &csi.CreateVolumeResponse{
			Volume: &csi.Volume{
				VolumeId:      req.GetName(),
				CapacityBytes: existing.CapacityBytes,
			},
		}, nil
	}

CreateSnapshot, same file:

	existingSnap, foundSnap, err := readMetaOrZero(func() (snapshotMeta, error) {
		return readSnapshotMeta(d.dataDir, req.GetName())
	})
	if err != nil {
		return nil, status.Errorf(codes.Internal, "reading snapshot %q metadata: %v", req.GetName(), err)
	}
	if foundSnap {
		if existingSnap.SourceVolumeID != req.GetSourceVolumeId() {
			return nil, status.Errorf(codes.AlreadyExists, "snapshot %q already exists for a different source volume", req.GetName())
		}
		return &csi.CreateSnapshotResponse{
			Snapshot: &csi.Snapshot{
				SnapshotId:     req.GetName(),
				SourceVolumeId: existingSnap.SourceVolumeID,
				SizeBytes:      existingSnap.SizeBytes,
				CreationTime:   timestamppb.New(existingSnap.CreationTime),
				ReadyToUse:     true,
			},
		}, nil
	}

NodePublishVolume, in internal/driver/node.go — the variable is renamed metaErr here only because err already names the result of the IsMountPoint call one line up:

	if mounted {
		existing, found, metaErr := readMetaOrZero(func() (nodePublishMeta, error) {
			return readNodePublishMeta(d.dataDir, req.GetVolumeId())
		})
		if metaErr != nil {
			return nil, status.Errorf(codes.Internal, "reading volume %q publish metadata: %v", req.GetVolumeId(), metaErr)
		}
		if found && (existing.TargetPath != req.GetTargetPath() || existing.Readonly != req.GetReadonly()) {
			return nil, status.Errorf(codes.AlreadyExists, "volume %q is already published with different parameters", req.GetVolumeId())
		}
		return &csi.NodePublishVolumeResponse{}, nil
	}

This refactor doesn't earn a new red test — nothing about what these three RPCs do changes, only how they ask the same question of their own metadata. The 46 tests already in the suite, spanning every RPC this book has built so far, are the safety net:

go test ./internal/driver/...

ok  	github.com/yourname/localdir-csi/internal/driver	0.013s

Green, unchanged. Three call sites, one shared shape, one file (meta.go) that didn't exist an hour ago — Always DRY, applied to code this book already trusted, not just code it was about to write.

Capability enforcement: a gap the audit above missed

The error-code audit above checked what each RPC returns. It didn't check what each RPC accepts — and that gap is real, not hypothetical. ValidateVolumeCapabilities (Chapter 9) already knows exactly what this driver supports: a mount volume, never a raw block volume, requesting SINGLE_NODE_WRITER access. But ValidateVolumeCapabilities is an advisory RPC — nothing forces a caller to invoke it before CreateVolume, ControllerPublishVolume, or NodePublishVolume, and none of those three actually checks the capability it was handed against that same rule. Right now, a CreateVolume call naming a block-volume capability succeeds anyway; a NodePublishVolume call naming MULTI_NODE_MULTI_WRITER still gets a real bind mount. ValidateVolumeCapabilities would have correctly said no to both — it just never gets asked.

Always DRY says the check belongs in one place, not copy-pasted into four RPCs with four chances to drift out of sync with each other. Add internal/driver/capabilities.go:

package driver

import "github.com/container-storage-interface/spec/lib/go/csi"

// supportsVolumeCapability reports whether c is a capability this
// driver can actually honor: a mount volume — never a raw block
// volume — requesting SINGLE_NODE_WRITER access, the only combination
// Chapter 9's csi-sanity run ever exercised successfully. Every RPC
// that receives a *csi.VolumeCapability calls this before doing any
// real work with it, not just ValidateVolumeCapabilities, whose whole
// job is answering this exact question.
func supportsVolumeCapability(c *csi.VolumeCapability) bool {
	return c.GetMount() != nil &&
		c.GetAccessMode().GetMode() == csi.VolumeCapability_AccessMode_SINGLE_NODE_WRITER
}

With a test, internal/driver/capabilities_test.go:

package driver

import (
	"testing"

	"github.com/container-storage-interface/spec/lib/go/csi"
)

func TestSupportsVolumeCapability_AcceptsSupported(t *testing.T) {
	c := &csi.VolumeCapability{
		AccessType: &csi.VolumeCapability_Mount{Mount: &csi.VolumeCapability_MountVolume{}},
		AccessMode: &csi.VolumeCapability_AccessMode{Mode: csi.VolumeCapability_AccessMode_SINGLE_NODE_WRITER},
	}
	if !supportsVolumeCapability(c) {
		t.Error("supportsVolumeCapability() = false, want true for mount + SINGLE_NODE_WRITER")
	}
}

func TestSupportsVolumeCapability_RejectsUnsupported(t *testing.T) {
	cases := map[string]*csi.VolumeCapability{
		"block volume": {
			AccessType: &csi.VolumeCapability_Block{Block: &csi.VolumeCapability_BlockVolume{}},
			AccessMode: &csi.VolumeCapability_AccessMode{Mode: csi.VolumeCapability_AccessMode_SINGLE_NODE_WRITER},
		},
		"multi-node access mode": {
			AccessType: &csi.VolumeCapability_Mount{Mount: &csi.VolumeCapability_MountVolume{}},
			AccessMode: &csi.VolumeCapability_AccessMode{Mode: csi.VolumeCapability_AccessMode_MULTI_NODE_MULTI_WRITER},
		},
	}
	for name, c := range cases {
		if supportsVolumeCapability(c) {
			t.Errorf("supportsVolumeCapability(%s) = true, want false", name)
		}
	}
}

ValidateVolumeCapabilities's own capability loop (Chapter 9) already checked exactly this, just inline and in two separate if statements. Collapse it onto the new helper:

	for _, c := range req.GetVolumeCapabilities() {
		if !supportsVolumeCapability(c) {
			return &csi.ValidateVolumeCapabilitiesResponse{
				Message: "capability not supported: only a mount volume with SINGLE_NODE_WRITER access is supported",
			}, nil
		}
	}

Then the three RPCs that were missing the check entirely. In CreateVolume (internal/driver/controller.go), right after the existing "capabilities are required" presence check:

	for _, c := range req.GetVolumeCapabilities() {
		if !supportsVolumeCapability(c) {
			return nil, status.Errorf(codes.InvalidArgument, "unsupported volume_capability: only a mount volume with SINGLE_NODE_WRITER access is supported")
		}
	}

In ControllerPublishVolume, same file, right after its own "volume_capability is required" check:

	if !supportsVolumeCapability(req.GetVolumeCapability()) {
		return nil, status.Error(codes.InvalidArgument, "unsupported volume_capability: only a mount volume with SINGLE_NODE_WRITER access is supported")
	}

And in NodePublishVolume (internal/driver/node.go), right after its own "volume_capability is required" check:

	if !supportsVolumeCapability(req.GetVolumeCapability()) {
		return nil, status.Error(codes.InvalidArgument, "unsupported volume_capability: only a mount volume with SINGLE_NODE_WRITER access is supported")
	}

Two tests prove the wiring, not just the helper. In internal/driver/controller_test.go:

func TestCreateVolume_RejectsUnsupportedCapability(t *testing.T) {
	d := newTestDriverInTempDir(t)

	req := &csi.CreateVolumeRequest{
		Name: "vol-1",
		VolumeCapabilities: []*csi.VolumeCapability{{
			AccessType: &csi.VolumeCapability_Block{Block: &csi.VolumeCapability_BlockVolume{}},
			AccessMode: &csi.VolumeCapability_AccessMode{Mode: csi.VolumeCapability_AccessMode_SINGLE_NODE_WRITER},
		}},
	}

	_, err := d.CreateVolume(t.Context(), req)
	requireStatusCode(t, err, codes.InvalidArgument, req)
}

And in internal/driver/node_test.go:

func TestNodePublishVolume_RejectsUnsupportedCapability(t *testing.T) {
	d := newTestDriver(t, t.TempDir(), &fakeMounter{})

	req := &csi.NodePublishVolumeRequest{
		VolumeId:   "vol-1",
		TargetPath: filepath.Join(t.TempDir(), "target"),
		VolumeCapability: &csi.VolumeCapability{
			AccessType: &csi.VolumeCapability_Mount{Mount: &csi.VolumeCapability_MountVolume{}},
			AccessMode: &csi.VolumeCapability_AccessMode{Mode: csi.VolumeCapability_AccessMode_MULTI_NODE_MULTI_WRITER},
		},
	}

	_, err := d.NodePublishVolume(t.Context(), req)
	requireStatusCode(t, err, codes.InvalidArgument, req)
}

go test ./internal/driver/...

ok  	github.com/yourname/localdir-csi/internal/driver	0.014s

Green — four RPCs now agree on what this driver supports, checked in exactly one place, instead of one RPC knowing the rule and three others silently ignoring it.

Path safety: an audit of everything this driver joins onto a path

One more gap the error-code audit didn't cover, because it's not about codes at all: every RPC that touches the filesystem builds a path by joining d.dataDir with a caller-supplied string — a volume ID, a snapshot ID — and CSI identifiers are opaque by spec. Nothing stops a caller from naming a volume ../../etc or snapshots (this driver's own reserved subdirectory). The external-provisioner-generated names this book's own proofs have used so far happen to look safe; the spec never promised that, and every grpcurl demonstration since Chapter 7 has reached this driver's socket directly, no sidecar validation in front of it at all.

One helper closes every one of those joins at once, in internal/driver/paths.go:

package driver

import (
	"fmt"
	"path/filepath"
	"strings"
)

// reservedNames are subdirectories this driver's own bookkeeping
// already owns under dataDir. A volume or snapshot ID that collided
// with one of these would silently corrupt the driver's own metadata
// instead of failing loudly.
var reservedNames = map[string]bool{
	"snapshots": true,
	".csi-meta": true,
}

// safeChildPath joins name onto root, the same way every RPC in this
// driver already has with filepath.Join — but refuses to do it at all
// if name could escape root or collide with a reserved directory.
// CSI volume/snapshot IDs are caller-supplied and opaque; this driver
// has no sidecar in front of it once a caller reaches its socket
// directly, so it has to be the one place that says no.
func safeChildPath(root, name string) (string, error) {
	if name == "" {
		return "", fmt.Errorf("name must not be empty")
	}
	if reservedNames[name] {
		return "", fmt.Errorf("name %q collides with a reserved internal directory", name)
	}
	if name == "." || name == ".." || strings.ContainsAny(name, `/\`) {
		return "", fmt.Errorf("name %q is not a valid path component", name)
	}
	child := filepath.Join(root, name)
	cleanRoot := filepath.Clean(root)
	if child != cleanRoot && !strings.HasPrefix(child, cleanRoot+string(filepath.Separator)) {
		return "", fmt.Errorf("name %q escapes the data root", name)
	}
	return child, nil
}

The separator-and-..-literal checks catch the common case in plain English; the final prefix check is the one that actually matters, because filepath.Join already runs filepath.Clean internally — anything cleverer than a literal .. component that still resolves outside root after cleaning gets caught there, not by the earlier checks. Four cases worth a real test each, in internal/driver/paths_test.go:

package driver

import (
	"path/filepath"
	"testing"
)

func TestSafeChildPath_AcceptsValidName(t *testing.T) {
	root := t.TempDir()
	got, err := safeChildPath(root, "vol-1")
	if err != nil {
		t.Fatalf("safeChildPath() error = %v, want nil", err)
	}
	if want := filepath.Join(root, "vol-1"); got != want {
		t.Errorf("safeChildPath() = %q, want %q", got, want)
	}
}

func TestSafeChildPath_RejectsTraversal(t *testing.T) {
	if _, err := safeChildPath(t.TempDir(), "../escape"); err == nil {
		t.Error("safeChildPath() = nil error, want one for a traversal attempt")
	}
}

func TestSafeChildPath_RejectsSeparators(t *testing.T) {
	if _, err := safeChildPath(t.TempDir(), "sub/dir"); err == nil {
		t.Error("safeChildPath() = nil error, want one for an embedded separator")
	}
}

func TestSafeChildPath_RejectsReservedNames(t *testing.T) {
	root := t.TempDir()
	for _, name := range []string{"snapshots", ".csi-meta"} {
		if _, err := safeChildPath(root, name); err == nil {
			t.Errorf("safeChildPath(%q) = nil error, want one for a reserved name", name)
		}
	}
}

Wiring it in means every existing filepath.Join(d.dataDir, ...) (or filepath.Join(dataDir, ...) inside a metadata-path helper) becomes a checked call instead, returning codes.InvalidArgument on rejection — an invalid ID is a caller mistake, not a server failure. The call sites, each a one-line change plus an error check:

Each replacement follows the same shape:

	path, err := safeChildPath(d.dataDir, req.GetVolumeId())
	if err != nil {
		return nil, status.Errorf(codes.InvalidArgument, "invalid volume_id: %v", err)
	}

— path used exactly where the old filepath.Join result was, nothing else in any of these methods changes. Run the full suite after wiring every site in the table above:

go test ./internal/driver/...

ok  	github.com/yourname/localdir-csi/internal/driver	0.015s

Green — every id this driver ever joins onto a real path now goes through one function that can say no, and that function has its own tests proving it actually does.

Structured logging: one interceptor, every RPC

The second problem named above: missing logs leave a real operator blind. Right now, nothing in internal/driver logs anything. A CreateVolume call that fails shows up as a gRPC error the caller sees — and nowhere else. On a real cluster, the caller is usually external-provisioner, several hops away from whoever is debugging.

The tempting fix is to add a klog.InfoS call at the top and bottom of every RPC method. Always DRY says no: that's the same four lines, copy-pasted into eleven methods, all of them needing to change in lockstep the day the log format changes. gRPC has a purpose-built answer to exactly this shape of problem — a unary interceptor: a function that wraps every RPC call, given the request, the handler, and a chance to run code before and after it runs. Wire one in once, and every RPC — this one and every one added later — gets logging for free, without a single klog call inside any RPC method itself. This is Open/Closed in its purest form: adding logging to RPC number twelve requires touching zero existing files.

k8s.io/klog/v2 is the structured logging package the rest of Kubernetes uses — InfoS and ErrorS take a message and alternating key/value pairs, rather than a Printf-style format string. Add it the same way every other real dependency in this book got added, back in Chapter 2:

go get k8s.io/klog/v2

klog has no public Output variable to redirect for a test — capturing its output means installing a real logr.Logger via SetLogger, the same way klog's own real test suite does it. k8s.io/klog/v2/textlogger supplies a ready-made one: a logr.Logger that writes plain text to whatever io.Writer it's given, and it's already part of the k8s.io/klog/v2 module — no separate dependency to add for it.

Start with the test, in internal/driver/logging_test.go:

package driver

import (
	"bytes"
	"context"
	"errors"
	"strings"
	"testing"

	"google.golang.org/grpc"
	"k8s.io/klog/v2"
	"k8s.io/klog/v2/textlogger"
)

func TestLoggingInterceptor_LogsSuccess(t *testing.T) {
	var buf bytes.Buffer
	klog.SetLogger(textlogger.NewLogger(textlogger.NewConfig(textlogger.Output(&buf))))
	t.Cleanup(klog.ClearLogger)

	handler := func(ctx context.Context, req any) (any, error) {
		return "ok", nil
	}
	info := &grpc.UnaryServerInfo{FullMethod: "/csi.v1.Controller/CreateVolume"}

	_, err := LoggingInterceptor(t.Context(), nil, info, handler)
	if err != nil {
		t.Fatalf("LoggingInterceptor() returned an error: %v", err)
	}

	got := buf.String()
	if !strings.Contains(got, "RPC succeeded") {
		t.Errorf("log output = %q, want it to contain %q", got, "RPC succeeded")
	}
	if !strings.Contains(got, "/csi.v1.Controller/CreateVolume") {
		t.Errorf("log output = %q, want it to contain the method name", got)
	}
}

func TestLoggingInterceptor_LogsFailure(t *testing.T) {
	var buf bytes.Buffer
	klog.SetLogger(textlogger.NewLogger(textlogger.NewConfig(textlogger.Output(&buf))))
	t.Cleanup(klog.ClearLogger)

	wantErr := errors.New("volume not found")
	handler := func(ctx context.Context, req any) (any, error) {
		return nil, wantErr
	}
	info := &grpc.UnaryServerInfo{FullMethod: "/csi.v1.Controller/DeleteVolume"}

	_, err := LoggingInterceptor(t.Context(), nil, info, handler)
	if err != wantErr {
		t.Fatalf("LoggingInterceptor() error = %v, want %v", err, wantErr)
	}

	got := buf.String()
	if !strings.Contains(got, "RPC failed") {
		t.Errorf("log output = %q, want it to contain %q", got, "RPC failed")
	}
	if !strings.Contains(got, "volume not found") {
		t.Errorf("log output = %q, want it to contain the error", got)
	}
}

Each test installs a textlogger pointed at a bytes.Buffer instead of the default stderr, and clears it in t.Cleanup via klog.ClearLogger, so no other test in the package inherits a logger whose buffer has since gone out of scope. klog.InfoS/ErrorS route through whatever's installed with SetLogger — install a logger, and every top-level klog.InfoS/ErrorS call anywhere in the program starts going through it instead of the classic stderr path.

Neither LoggingInterceptor nor grpc.UnaryServerInfo/UnaryHandler exist yet:

go test ./internal/driver/... -run TestLoggingInterceptor

./logging_test.go:25:12: undefined: LoggingInterceptor
./logging_test.go:50:12: undefined: LoggingInterceptor
FAIL	github.com/yourname/localdir-csi/internal/driver [build failed]

grpc.UnaryServerInfo, grpc.UnaryHandler, and grpc.UnaryServerInterceptor are real types this driver's existing google.golang.org/grpc dependency already provides — no new module to add for them.

With those in place, internal/driver/logging.go:

package driver

import (
	"context"
	"time"

	"google.golang.org/grpc"
	"k8s.io/klog/v2"
)

// LoggingInterceptor logs every unary RPC call once, on the way out:
// a structured success line with the method name and how long it took,
// or a structured error line with the method name and the error. Wire
// it in once, as a grpc.UnaryInterceptor, and every RPC — this one and
// every one added later — gets consistent logging for free, without a
// single klog call inside any RPC method itself.
func LoggingInterceptor(
	ctx context.Context,
	req any,
	info *grpc.UnaryServerInfo,
	handler grpc.UnaryHandler,
) (any, error) {
	start := time.Now()
	resp, err := handler(ctx, req)
	duration := time.Since(start)

	if err != nil {
		klog.ErrorS(err, "RPC failed", "method", info.FullMethod, "duration", duration)
		return resp, err
	}

	klog.InfoS("RPC succeeded", "method", info.FullMethod, "duration", duration)
	return resp, nil
}

go test ./internal/driver/... -run TestLoggingInterceptor -v

=== RUN   TestLoggingInterceptor_LogsSuccess
--- PASS: TestLoggingInterceptor_LogsSuccess (0.00s)
=== RUN   TestLoggingInterceptor_LogsFailure
--- PASS: TestLoggingInterceptor_LogsFailure (0.00s)
PASS
ok  	github.com/yourname/localdir-csi/internal/driver	0.004s

Green. LoggingInterceptor is a plain function — nothing about it requires a running server, which is exactly why it could be unit tested by calling it directly with a stub handler, the same way every RPC method in this book has been tested since Chapter 3.

It's worth being precise about what actually happens at request time, because LoggingInterceptor's signature — (ctx, req, info, handler) — looks like an ordinary function until you notice that one of its arguments is itself a function it hasn't called yet. When a CreateVolume request arrives at a server wired with grpc.UnaryInterceptor(driver.LoggingInterceptor), gRPC's own machinery decodes the request off the wire into a *csi.CreateVolumeRequest, and then — instead of calling the driver's CreateVolume method directly — packages that call up as a closure (a grpc.UnaryHandler value, func(ctx, req) (any, error)) and calls LoggingInterceptor(ctx, req, info, thatClosure). The interceptor is handed "the rest of this request's life" as a value; nothing runs until the interceptor's own body decides to run it.

From there, LoggingInterceptor's four lines run in an order worth tracing explicitly:

1. start := time.Now() runs first — genuinely before the RPC, code the interceptor controls and CreateVolume never sees.
2. handler(ctx, req) — the interceptor calls the closure it was handed. This is the moment CreateVolume actually runs. Everything inside it is invisible to LoggingInterceptor, which only sees what goes in and what eventually comes back out.
3. Control returns to LoggingInterceptor, now holding resp, err, and duration := time.Since(start) — all three exist only because the interceptor waited for handler to return before computing anything with them.
4. klog.InfoS/ErrorS runs — genuinely after the RPC — and LoggingInterceptor returns (resp, err) unchanged, back up to gRPC, which encodes it onto the wire exactly as if no interceptor existed at all.

That's the whole mechanism: an interceptor is a function willing to call another function partway through its own body, with license to run code on either side of that call. CreateVolume never sees LoggingInterceptor and never needs to — Chapter 6's Dependency Inversion note (depend on abstractions, not concretions) shows up here in a different shape: CreateVolume doesn't depend on an abstraction for logging, it depends on nothing at all, because logging was never its job to know about in the first place.

Wiring it in is one more line in cmd/localdir-csi/main.go, alongside the existing service registrations:

	server := grpc.NewServer(grpc.UnaryInterceptor(driver.LoggingInterceptor))
	csi.RegisterIdentityServer(server, d)
	csi.RegisterControllerServer(server, d)
	csi.RegisterNodeServer(server, d)
	reflection.Register(server)

Every RPC this driver has, or will ever have, now logs a structured success or failure line — without one line of logging code inside CreateVolume, NodePublishVolume, or any of the other nine methods already written.

Metrics: the same pattern, twice

Missing logs is half the observability gap named earlier — the other half is missing metrics. Logs answer "what happened on this one call"; metrics answer "how is this driver doing, in aggregate, right now" — how many CreateVolume calls failed in the last five minutes, what NodePublishVolume's p99 latency looks like. A real operator needs both, and neither one substitutes for the other.

The DRY argument from the logging section applies again, unchanged: instrumenting every RPC method by hand means eleven near-identical blocks of counter and histogram code, all needing to move together. MetricsInterceptor is a second, independent interceptor, built the same way as LoggingInterceptor — which is worth pausing on, because it's a small proof of Single Responsibility working as advertised. Logging and metrics are two different concerns; the interceptor pattern lets them live in two different files, each one just as unit-testable in isolation as the other, neither one aware the other exists.

github.com/prometheus/client_golang/prometheus is the real metrics library most of the Kubernetes ecosystem uses. Two shapes matter here. A CounterVec is a family of monotonically-increasing counts, one per distinct combination of label values — rpc_requests_total{method="...",code="OK"} is a different counter from rpc_requests_total{method="...",code="NotFound"}, even though both live under the same CounterVec. A HistogramVec is the same idea applied to latency: instead of one number, each label combination gets a set of cumulative bucket counts (Buckets — how many observations fell at or below each threshold) plus a running sum and count, which is what lets a real Prometheus server compute p50/p95/p99 later without this driver ever calculating a percentile itself. Both are built from an Opts struct (CounterOpts/HistogramOpts) whose Namespace/Subsystem/Name fields get joined with underscores into the final metric name — this driver's Subsystem: "localdir_csi", Name: "rpc_requests_total" becomes localdir_csi_rpc_requests_total on the wire.

"On the wire" is worth making concrete, because this chapter is about to build it for real, against a real running pod: once a driver MustRegisters its collectors and serves promhttp.Handler() on an HTTP endpoint (a real but separate piece of plumbing — this driver's Unix-socket gRPC server has no HTTP port of its own), a real Prometheus server scraping it sees plain text shaped like this:

# HELP localdir_csi_rpc_requests_total Total number of RPCs handled, by method and result code.
# TYPE localdir_csi_rpc_requests_total counter
localdir_csi_rpc_requests_total{code="OK",method="/csi.v1.Controller/CreateVolume"} 12
localdir_csi_rpc_requests_total{code="NotFound",method="/csi.v1.Controller/DeleteVolume"} 1

# HELP localdir_csi_rpc_duration_seconds RPC latency in seconds, by method.
# TYPE localdir_csi_rpc_duration_seconds histogram
localdir_csi_rpc_duration_seconds_bucket{method="/csi.v1.Controller/CreateVolume",le="0.005"} 0
localdir_csi_rpc_duration_seconds_bucket{method="/csi.v1.Controller/CreateVolume",le="0.01"} 3
localdir_csi_rpc_duration_seconds_bucket{method="/csi.v1.Controller/CreateVolume",le="0.025"} 9
localdir_csi_rpc_duration_seconds_bucket{method="/csi.v1.Controller/CreateVolume",le="+Inf"} 12
localdir_csi_rpc_duration_seconds_sum{method="/csi.v1.Controller/CreateVolume"} 0.183
localdir_csi_rpc_duration_seconds_count{method="/csi.v1.Controller/CreateVolume"} 12

Every le ("less than or equal") bucket is cumulative — the +Inf bucket always equals the total count — which is what lets Prometheus interpolate a percentile across buckets it never saw an individual observation land in directly. None of this book's code produces that text; real client_golang does, via its expfmt encoder, the moment something calls promhttp.Handler().

Add the real library the same way, one go get for the package and its test-only testutil helper:

go get github.com/prometheus/client_golang/prometheus
go get github.com/prometheus/client_golang/prometheus/testutil
go get github.com/prometheus/client_model/go

A metric's value can only be read back out two ways: scrape /metrics over HTTP for real, or — inside a test, without a server — call github.com/prometheus/client_golang/prometheus/testutil.ToFloat64, a genuine public export built for exactly this. It takes any prometheus.Collector that reports exactly one number and returns that number; CounterVec.WithLabelValues(...) returns a Counter, and the real Counter interface already embeds Collector, so handing one straight to ToFloat64 needs no extra plumbing.

Histograms are a different story — ToFloat64 explicitly panics on anything that isn't a Gauge, Counter, or Untyped, because a histogram doesn't reduce to one number. The real, idiomatic way to check what a histogram recorded — the same pattern client_golang's own test suite uses — is to Write it into a dto.Metric (the same protobuf message a real scrape produces) and read GetHistogram().GetSampleCount() off that. One wrinkle worth knowing before it surprises a reader: HistogramVec.WithLabelValues(...) returns the real API's narrow Observer interface (just Observe(float64)), not the fuller Histogram interface that has Write on it — reaching Write needs an explicit type assertion, s.(prometheus.Histogram), the same way real code calling this must.

The test, in internal/driver/metrics_test.go:

package driver

import (
	"context"
	"testing"

	"github.com/prometheus/client_golang/prometheus"
	"github.com/prometheus/client_golang/prometheus/testutil"
	dto "github.com/prometheus/client_model/go"
	"google.golang.org/grpc"
	"google.golang.org/grpc/codes"
	"google.golang.org/grpc/status"
)

func TestMetricsInterceptor_RecordsSuccess(t *testing.T) {
	handler := func(ctx context.Context, req any) (any, error) { return "ok", nil }
	info := &grpc.UnaryServerInfo{FullMethod: "/csi.v1.Controller/CreateVolume"}

	before := testutil.ToFloat64(rpcRequestsTotal.WithLabelValues(info.FullMethod, "OK"))

	if _, err := MetricsInterceptor(t.Context(), nil, info, handler); err != nil {
		t.Fatalf("MetricsInterceptor() returned an error: %v", err)
	}

	after := testutil.ToFloat64(rpcRequestsTotal.WithLabelValues(info.FullMethod, "OK"))
	if after != before+1 {
		t.Errorf("rpc_requests_total{method=%q,code=OK} = %v, want %v", info.FullMethod, after, before+1)
	}

	var m dto.Metric
	if err := rpcDurationSeconds.WithLabelValues(info.FullMethod).(prometheus.Histogram).Write(&m); err != nil {
		t.Fatalf("Write() failed: %v", err)
	}
	if m.GetHistogram().GetSampleCount() == 0 {
		t.Errorf("rpc_duration_seconds{method=%q} recorded no observations", info.FullMethod)
	}
}

func TestMetricsInterceptor_RecordsFailure(t *testing.T) {
	handler := func(ctx context.Context, req any) (any, error) {
		return nil, status.Error(codes.NotFound, "volume not found")
	}
	info := &grpc.UnaryServerInfo{FullMethod: "/csi.v1.Controller/DeleteVolume"}

	before := testutil.ToFloat64(rpcRequestsTotal.WithLabelValues(info.FullMethod, "NotFound"))

	if _, err := MetricsInterceptor(t.Context(), nil, info, handler); err == nil {
		t.Fatal("MetricsInterceptor() returned no error, want NotFound")
	}

	after := testutil.ToFloat64(rpcRequestsTotal.WithLabelValues(info.FullMethod, "NotFound"))
	if after != before+1 {
		t.Errorf("rpc_requests_total{method=%q,code=NotFound} = %v, want %v", info.FullMethod, after, before+1)
	}
}

Both tests read before/after deltas on the package-level counters rather than asserting an absolute value — rpcRequestsTotal is shared across every test in the package, so any test asserting an absolute count would be quietly coupled to every other test's call order. The histogram check only appears in the success test, and only checks that something was recorded, not an absolute count, for the same reason.

go test ./internal/driver/... -run TestMetricsInterceptor

# github.com/yourname/localdir-csi/internal/driver [github.com/yourname/localdir-csi/internal/driver.test]
internal/driver/metrics_test.go:7:2: "github.com/prometheus/client_golang/prometheus" imported and not used
internal/driver/metrics_test.go:19:31: undefined: rpcRequestsTotal
internal/driver/metrics_test.go:21:15: undefined: MetricsInterceptor
internal/driver/metrics_test.go:25:30: undefined: rpcRequestsTotal
internal/driver/metrics_test.go:31:12: undefined: rpcDurationSeconds
internal/driver/metrics_test.go:45:31: undefined: rpcRequestsTotal
internal/driver/metrics_test.go:47:15: undefined: MetricsInterceptor
internal/driver/metrics_test.go:51:30: undefined: rpcRequestsTotal
FAIL	github.com/yourname/localdir-csi/internal/driver [build failed]

That first line is real, and a little counterintuitive: prometheus genuinely is used, at the .(prometheus.Histogram) assertion further down — but with rpcDurationSeconds undefined, the compiler's error recovery gives up on that whole statement before it reaches the assertion, so it never marks the import as referenced. It's a real Go compiler quirk under cascading errors, not a mistake in the test.

internal/driver/metrics.go:

package driver

import (
	"context"
	"time"

	"github.com/prometheus/client_golang/prometheus"
	"google.golang.org/grpc"
	"google.golang.org/grpc/status"
)

var (
	rpcRequestsTotal = prometheus.NewCounterVec(
		prometheus.CounterOpts{
			Subsystem: "localdir_csi",
			Name:      "rpc_requests_total",
			Help:      "Total number of RPCs handled, by method and result code.",
		},
		[]string{"method", "code"},
	)

	rpcDurationSeconds = prometheus.NewHistogramVec(
		prometheus.HistogramOpts{
			Subsystem: "localdir_csi",
			Name:      "rpc_duration_seconds",
			Help:      "RPC latency in seconds, by method.",
			Buckets:   []float64{.005, .01, .025, .05, .1, .25, .5, 1, 2.5, 5, 10},
		},
		[]string{"method"},
	)
)

// MetricsInterceptor records one counter increment and one duration
// observation per RPC call, labeled by method and (for the counter) the
// result code. Wire it in alongside LoggingInterceptor — the two are
// independent, so either can be added, removed, or reused on its own.
func MetricsInterceptor(
	ctx context.Context,
	req any,
	info *grpc.UnaryServerInfo,
	handler grpc.UnaryHandler,
) (any, error) {
	start := time.Now()
	resp, err := handler(ctx, req)
	duration := time.Since(start).Seconds()

	rpcRequestsTotal.WithLabelValues(info.FullMethod, status.Code(err).String()).Inc()
	rpcDurationSeconds.WithLabelValues(info.FullMethod).Observe(duration)

	return resp, err
}

go test ./internal/driver/... -run TestMetricsInterceptor -v

=== RUN   TestMetricsInterceptor_RecordsSuccess
--- PASS: TestMetricsInterceptor_RecordsSuccess (0.00s)
=== RUN   TestMetricsInterceptor_RecordsFailure
--- PASS: TestMetricsInterceptor_RecordsFailure (0.00s)
PASS
ok  	github.com/yourname/localdir-csi/internal/driver	0.006s

Green — two interceptors now, LoggingInterceptor and MetricsInterceptor, each tested in complete isolation from the other. The wiring from the logging section only has room for one: grpc.UnaryInterceptor installs exactly one interceptor. The real grpc package's answer for more than one is grpc.ChainUnaryInterceptor, which takes any number of interceptors and nests them: the first one listed ends up outermost, wrapping every interceptor after it the same way nested function calls wrap each other — first's code runs before second's on the way in, and after second's on the way back out. That matters for this driver's wiring, because it decides what a caller sees timed:

	server := grpc.NewServer(grpc.ChainUnaryInterceptor(
		driver.LoggingInterceptor,
		driver.MetricsInterceptor,
	))
	csi.RegisterIdentityServer(server, d)
	csi.RegisterControllerServer(server, d)
	csi.RegisterNodeServer(server, d)
	reflection.Register(server)

LoggingInterceptor listed first means its own time.Since(start) includes MetricsInterceptor's work — the log line reports how long the RPC actually took a caller to get an answer, metrics recording included, not just the bare handler.

Serving metrics for real

Recording a metric and being able to see it are two different things. rpcRequestsTotal and rpcDurationSeconds update in memory on every RPC — that part is already proven by metrics_test.go. But nothing so far reads those numbers back out except a unit test calling testutil.ToFloat64 directly. On a real cluster, the thing that reads them out is a Prometheus server, and it can only do that by making an HTTP request. This driver doesn't have an HTTP server — its only listener is the Unix-socket gRPC server kubelet talks to. Fixing that is a few real lines, not an exercise, so this section builds it and then goes and looks at it running on a real pod.

CounterVec/HistogramVec values only show up on a scrape once they're registered with a prometheus.Registry — creating them with NewCounterVec/NewHistogramVec does not register them anywhere on its own. prometheus.MustRegister does that; it panics on a registration error (a name collision, say), which is the right failure mode here — a metrics wiring bug should be loud at startup, not silently drop data forever. Add the registration call to internal/driver/metrics.go, right after the two var declarations:

func init() {
	prometheus.MustRegister(rpcRequestsTotal, rpcDurationSeconds)
}

prometheus.MustRegister with no explicit Registry argument registers against prometheus.DefaultRegisterer — the same default registry promhttp.Handler() reads from with no arguments of its own. That pairing is why the wiring in main.go doesn't have to pass anything explicit between the two: registering here and serving there agree on "the default registry" without either line naming it.

main.go gets one more piece, alongside the existing gRPC server startup — a second server, on a second port, running the whole time the driver runs. Two new imports: net/http, the standard library's own HTTP server, and github.com/prometheus/client_golang/prometheus/promhttp, the sub-package that turns a Registry into an http.Handler:

	go func() {
		http.Handle("/metrics", promhttp.Handler())
		if err := http.ListenAndServe(":9090", nil); err != nil {
			klog.ErrorS(err, "metrics server failed")
		}
	}()

That go func() matters as much as the two lines inside it. http.ListenAndServe blocks — it doesn't return until the server stops or fails — so without go, starting the metrics server would mean the driver's real job, serving the CSI gRPC socket, never starts. Running it in its own goroutine means the metrics HTTP server and the gRPC server run side by side, on two different listeners (:9090 for HTTP, the Unix socket for gRPC), each blocking only its own goroutine.

The deploy manifest needs to say the port exists, or nothing outside the pod's own network namespace can reach it. Both deploy/node.yaml and deploy/controller.yaml run this same driver binary, so both containers get the same addition:

        ports:
        - containerPort: 9090
          name: metrics

That's everything the code needs. The rest of this section is running it for real: rebuild and redeploy the driver, then reach port 9090 on a live pod the same way kubectl port-forward reaches any other pod port, and see what a real Prometheus scrape would see.

make deploy
kubectl port-forward deployment/localdir-csi-controller 9090:9090

make deploy already waits for both the Controller and Node rollouts to finish (Chapter 2), so by the time port-forward runs, the pod on the other end is genuinely the freshly built binary, not whatever was running before.

Then, in a second terminal, with a couple of volumes already created against the driver so the counters aren't sitting at zero:

curl -s localhost:9090/metrics | grep localdir_csi

# HELP localdir_csi_rpc_duration_seconds RPC latency in seconds, by method.
# TYPE localdir_csi_rpc_duration_seconds histogram
localdir_csi_rpc_duration_seconds_bucket{method="/csi.v1.Controller/CreateVolume",le="0.005"} 23
localdir_csi_rpc_duration_seconds_bucket{method="/csi.v1.Controller/CreateVolume",le="0.01"} 23
localdir_csi_rpc_duration_seconds_bucket{method="/csi.v1.Controller/CreateVolume",le="0.025"} 23
localdir_csi_rpc_duration_seconds_bucket{method="/csi.v1.Controller/CreateVolume",le="+Inf"} 23
localdir_csi_rpc_duration_seconds_sum{method="/csi.v1.Controller/CreateVolume"} 0.004305040999999999
localdir_csi_rpc_duration_seconds_count{method="/csi.v1.Controller/CreateVolume"} 23
# HELP localdir_csi_rpc_requests_total Total number of RPCs handled, by method and result code.
# TYPE localdir_csi_rpc_requests_total counter
localdir_csi_rpc_requests_total{code="OK",method="/csi.v1.Controller/CreateSnapshot"} 34
localdir_csi_rpc_requests_total{code="OK",method="/csi.v1.Controller/CreateVolume"} 23
localdir_csi_rpc_requests_total{code="OK",method="/csi.v1.Controller/DeleteSnapshot"} 24
localdir_csi_rpc_requests_total{code="OK",method="/csi.v1.Controller/DeleteVolume"} 36
localdir_csi_rpc_requests_total{code="OK",method="/csi.v1.Identity/GetPluginInfo"} 3
localdir_csi_rpc_requests_total{code="OK",method="/csi.v1.Identity/Probe"} 2

Every counter above is real — a scrape off a real localdir-csi-controller pod on a kind cluster, after this book's own test traffic (the Chapter 10 snapshot proofs, a handful of CreateVolume calls) had already run against it. CreateVolume alone recorded 23 calls, all code="OK", and its histogram's +Inf bucket — 23 — equals its total count, exactly the cumulative-bucket property explained above. Read the same numbers off your own pod with the three commands above and they'll differ in the counts, not in the shape.

What you should have now

• internal/driver/meta.go's readMetaOrZero, collapsing a read/compare/decide shape that had been hand-written three times — in NodePublishVolume (Chapter 6), CreateVolume (Chapter 9), and CreateSnapshot (Chapter 10) — into one generic helper, all three call sites updated, all 46 pre-existing tests still green with no behavior change
• Confirmation, from a real audit against the CSI spec's own error-code table, that every other already-known simplification (DeleteVolume's missing FAILED_PRECONDITION, ControllerPublishVolume's missing node-not-found NOT_FOUND) is still exactly what Chapter 7 and Chapter 8 already said it was — nothing new to fix, this time
• internal/driver/capabilities.go's supportsVolumeCapability, closing a real gap the error-code audit itself missed: CreateVolume, ControllerPublishVolume, and NodePublishVolume now reject any capability ValidateVolumeCapabilities would already have refused, instead of silently accepting it
• internal/driver/paths.go's safeChildPath, closing a second real gap: every RPC that joins a caller-supplied volume or snapshot ID onto d.dataDir now rejects traversal attempts, embedded separators, and collisions with this driver's own reserved directories, instead of handing an unvalidated opaque string straight to os.MkdirAll or os.RemoveAll
• internal/driver/logging.go and internal/driver/metrics.go: two independent gRPC unary interceptors, each tested by calling it directly with a stub handler, wired into main.go with grpc.ChainUnaryInterceptor — no RPC method anywhere logs or instruments itself
• k8s.io/klog/v2 and github.com/prometheus/client_golang, both real dependencies added with plain go get, the same way this book has added every other module since Chapter 2 — no fakes, no replace directives, nothing this chapter's tests couldn't compile against on a fresh clone
• prometheus.MustRegister wired into internal/driver/metrics.go, and a :9090 HTTP server started alongside the gRPC server in main.go, serving promhttp.Handler() at /metrics — the difference between recording a metric and anyone actually being able to read it
• Real confirmation, off a redeployed pod on the user's own kind cluster via kubectl port-forward and curl, that localdir_csi_rpc_requests_total and localdir_csi_rpc_duration_seconds show up on /metrics exactly as reasoned through above — not just a unit test reading the same counters back via testutil.ToFloat64
• All 58 tests, gofmt, go vet, and go build clean across the whole module — the same bar every chapter since Chapter 3 has held to

Two honest gaps remain. The metrics HTTP server has no TLS and no auth — fine for a kubectl port-forward demo, not fine for a real multi-tenant cluster, where a real deployment would either put it behind a NetworkPolicy restricting who can reach port 9090, or front it with something that authenticates scrapes. And nothing here wires up a Prometheus ServiceMonitor or a Service object for automatic discovery — this chapter proves the endpoint exists and answers correctly; pointing a real Prometheus Operator at it automatically, rather than a manual port-forward, is ordinary Kubernetes plumbing, not something specific to this driver.

Chapter 12 turns to proving all of this automatically: real Go tests against a real kind cluster, codifying the manual kubectl and grpcurl sequences this book has run by hand since Chapter 8 — including a regression test for the real CreateSnapshot idempotency bug Chapter 10 hit live.