feat(observability): attach trace exemplars to the duration histograms (MAPCO-11496)

CONTRIBUTING.md

@@ -84,10 +84,12 @@ is no release-candidate branch.
   |:---|:---|
   | `docs/ogc-api-tiles.md` | `docs/ogc-api-tiles.md` |
   | `docs/tile-matrix-sets.md` | `docs/ogc-api-tiles.md`, `tms/doc.go`, `tms/registry.go` |
-  | `docs/layered-cache.md` | `README.md` § "Layered cache" |
+  | `docs/layered-cache.md` | `README.md` § "Layered cache", `observability/prometheus/README.md` |
   | `docs/configuration.md` § Redis | `cache/redis/README.md` |
   | `docs/tracing.md`, `docs/configuration.md` § Tracing | `tracing/README.md` |
-  | `docs/logging.md` | `internal/log/log.go`, `tracing/README.md` § "Correlating logs with traces" |
+  | `docs/logging.md` | `internal/log/log.go`, `tracing/README.md` §§ "Correlating logs with traces", "Correlating metrics with traces" |
+  | `docs/http-endpoints.md` § `/metrics` | `observability/prometheus/README.md`, `observability/prometheus.metricsHandler` |
+  | `docs/tracing.md` § "Relationship to metrics" | `observability/prometheus/README.md` § "Trace exemplars", `tracing/README.md` § "Correlating metrics with traces" |
 
 Once the pull request is open a maintainer reviews it and may ask for changes. Keep it up to date as
 other work lands on `master` ahead of yours.

atlas/cache_init_test.go

@@ -8,6 +8,15 @@ import (
 	"github.com/MapColonies/shigola/cache"
 )
 
+// TestCheckCacheTypes asserts the exact set of cache types the tree registers,
+// which makes it sensitive to the fake types the other test files in this
+// package register through cache.Register — a process-wide registry with no way
+// to unregister.
+//
+// It passes because Go runs a package's tests in declaration order, files taken
+// in sorted order, and every file that registers a fake sorts after this one.
+// That is load-bearing: a new test file registering a fake type from a name
+// sorting before "cache_init_test.go" fails this test rather than its own.
 func TestCheckCacheTypes(t *testing.T) {
 	c := cache.Registered()
 	exp := []string{"azblob", "file", "multi", "redis", "s3", "gcs"}

atlas/cache_observability_test.go

@@ -11,6 +11,7 @@ import (
 	"github.com/MapColonies/shigola/cache"
 	"github.com/MapColonies/shigola/dict"
 	"github.com/MapColonies/shigola/internal/faketier"
+	"github.com/MapColonies/shigola/internal/ttools"
 	"github.com/MapColonies/shigola/observability"
 	"github.com/MapColonies/shigola/observability/prometheus"
 )
@@ -96,21 +97,7 @@ func counter(t *testing.T, name string, labels map[string]string) float64 {
 		}
 
 		for _, m := range family.GetMetric() {
-			matched := true
-			for k, v := range labels {
-				found := false
-				for _, pair := range m.GetLabel() {
-					if pair.GetName() == k && pair.GetValue() == v {
-						found = true
-						break
-					}
-				}
-				if !found {
-					matched = false
-					break
-				}
-			}
-			if !matched {
+			if !ttools.HasLabels(m.GetLabel(), labels) {
 				continue
 			}
 

atlas/cache_trace_exemplar_test.go

@@ -0,0 +1,171 @@
+package atlas
+
+import (
+	"context"
+	"testing"
+	"time"
+
+	promclient "github.com/prometheus/client_golang/prometheus"
+	"go.opentelemetry.io/otel/sdk/trace/tracetest"
+
+	"github.com/MapColonies/shigola/cache"
+	"github.com/MapColonies/shigola/internal/faketier"
+	"github.com/MapColonies/shigola/internal/faketracer"
+	"github.com/MapColonies/shigola/internal/log"
+	"github.com/MapColonies/shigola/internal/ttools"
+	"github.com/MapColonies/shigola/tracing"
+)
+
+// Tier names are unique to this file for the reason the neighbouring test files
+// give: the observer registers against the process-wide registry.
+
+// TestExemplarNamesTheSpanThatMeasuredIt is what the wrapping order in
+// instrumentCache is for, checked rather than asserted in prose.
+//
+// Both prior tickets left a comment saying tracing goes outside the metric
+// wrapper so that the operation's span is the active one when the duration is
+// observed (MAPCO-11497, and the same at server.NewRouter). Nothing depended on
+// it until exemplars: with the order inverted every exemplar on the per-tier
+// histogram would name the cache-wide span instead — the same value for every
+// tier, on the one histogram whose whole purpose is telling tiers apart.
+//
+// The two rows are the two levels the claim has to hold at, and they fail
+// differently, which is why the per-tier row also names the inversion
+// explicitly: a whole-cache exemplar naming the cache span is right, and a tier
+// exemplar naming it is the bug.
+func TestExemplarNamesTheSpanThatMeasuredIt(t *testing.T) {
+	type tcase struct {
+		hotType, durableType string
+		family               string
+		labels               map[string]string
+		// wantSpan picks the span the exemplar must name out of the exporter.
+		wantSpan func(*testing.T, *tracetest.InMemoryExporter) tracetest.SpanStub
+		// rejectCacheSpan is the inversion this row can catch: a tier exemplar
+		// naming the cache-wide span is the bug, and a whole-cache exemplar
+		// naming it is correct, so only one row can look for it.
+		rejectCacheSpan bool
+	}
+
+	fn := func(tc tcase) func(*testing.T) {
+		return func(t *testing.T) {
+			hot := faketier.New("hot")
+			durable := faketier.New("durable")
+			durable.Seed(obsKey, []byte("tile"))
+
+			tracer, exporter := faketracer.New(t)
+
+			a := &Atlas{}
+			a.SetCache(tieredCache(t, tc.hotType, tc.durableType, tc.hotType, tc.durableType, hot, durable, 0))
+			a.SetObservability(newObserver(t))
+			a.SetTracing(tracer)
+
+			if _, hit, err := a.GetCache().Get(context.Background(), obsKey); err != nil || !hit {
+				t.Fatalf("Get() = hit %v, err %v; want a hit from the durable tier", hit, err)
+			}
+
+			measured := tc.wantSpan(t, exporter)
+
+			ttools.AssertExemplar(t, promclient.DefaultGatherer, tc.family, tc.labels,
+				measured.SpanContext.TraceID().String(), measured.SpanContext.SpanID().String())
+
+			if !tc.rejectCacheSpan {
+				return
+			}
+
+			// Named so a failure says which way round it went wrong.
+			whole := faketracer.SpanNamed(t, exporter, tracing.SpanCacheGet)
+			exemplar := ttools.ExemplarLabels(t, promclient.DefaultGatherer, tc.family, tc.labels)
+			if exemplar[log.SpanIDKey] == whole.SpanContext.SpanID().String() {
+				t.Error("tier exemplar names the cache-wide span; the metric wrapper is outside the tracing one")
+			}
+		}
+	}
+
+	tests := map[string]tcase{
+		"the tier read": {
+			hotType: "exhot1", durableType: "exdurable1",
+			family: "shigola_cache_tier_duration_seconds",
+			labels: map[string]string{"tier": "exhot1", "sub_command": "get"},
+			wantSpan: func(t *testing.T, exporter *tracetest.InMemoryExporter) tracetest.SpanStub {
+				return faketracer.TierSpan(t, exporter, tracing.SpanTierGet, "exhot1")
+			},
+			rejectCacheSpan: true,
+		},
+		"the chain as a whole": {
+			hotType: "exhot2", durableType: "exdurable2",
+			family: "shigola_cache_duration_seconds",
+			labels: map[string]string{"sub_command": "get"},
+			wantSpan: func(t *testing.T, exporter *tracetest.InMemoryExporter) tracetest.SpanStub {
+				return faketracer.SpanNamed(t, exporter, tracing.SpanCacheGet)
+			},
+		},
+	}
+
+	for name, tc := range tests {
+		t.Run(name, fn(tc))
+	}
+}
+
+// TestDetachedWriteExemplarNamesItsRequest is the property the docs claim for
+// writes and nothing asserted: a cache write runs on the pool goroutine, after
+// the response it belongs to has gone, and its exemplar still names the trace
+// that caused it.
+//
+// It holds only because WritePool derives the write's context with
+// context.WithoutCancel, which drops cancellation and keeps values — so the
+// span context survives into a goroutine whose parent request is over. Swap
+// that for context.Background() and the write still happens, the metric is
+// still observed, and the exemplar silently becomes nothing: a latency spike on
+// cache.Set would stop being clickable with no test failing.
+func TestDetachedWriteExemplarNamesItsRequest(t *testing.T) {
+	hot := faketier.New("hot")
+	durable := faketier.New("durable")
+
+	tracer, exporter := faketracer.New(t)
+
+	a := &Atlas{}
+	a.SetCache(tieredCache(t, "exwhot", "exwdurable", "exwhot", "exwdurable", hot, durable, 0))
+	a.SetObservability(newObserver(t))
+	a.SetTracing(tracer)
+
+	ctx, cancel := context.WithCancel(context.Background())
+	if err := a.GetCache().Set(ctx, obsKey, []byte("tile")); err != nil {
+		t.Fatalf("Set() = %v", err)
+	}
+
+	// The request ends here, which is the whole point: everything the write
+	// still needs has to have been carried by value rather than borrowed.
+	cancel()
+
+	pool := cache.WritePoolOf(a.GetCache())
+	if pool == nil {
+		t.Fatal("no write pool behind the chain; this test would prove nothing about detached writes")
+	}
+	pool.Drain(5 * time.Second)
+
+	// The *per-tier* family, not the whole-cache one. The detachment decorator
+	// sits inside the observability wrapper, so the whole-cache Set is observed
+	// synchronously on the response path, where the live request context is
+	// still in hand and WithoutCancel has nothing to do. Only the tier write
+	// runs on the pool goroutine, which is the observation this property is
+	// about — asserting the whole-cache family instead passes with the
+	// derivation replaced by context.Background(), and so proves nothing.
+	tier := faketracer.TierSpan(t, exporter, tracing.SpanTierSet, "exwdurable")
+
+	// The trace compared against is the *request's*, taken from the whole-cache
+	// span, which is created on the response path while the original context is
+	// still live. Comparing the tier exemplar against the tier span's own trace
+	// would prove nothing: with the derivation replaced by context.Background()
+	// the tier write still gets a span, it is simply the root of a new and
+	// orphaned trace — and an exemplar naming that span would still match it.
+	whole := faketracer.SpanNamed(t, exporter, tracing.SpanCacheSet)
+
+	if tier.SpanContext.TraceID() != whole.SpanContext.TraceID() {
+		t.Fatalf("the detached write ran in trace %v, not the request's %v; it lost the span context on the way to the pool",
+			tier.SpanContext.TraceID(), whole.SpanContext.TraceID())
+	}
+
+	ttools.AssertExemplar(t, promclient.DefaultGatherer, "shigola_cache_tier_duration_seconds",
+		map[string]string{"tier": "exwdurable", "sub_command": "set"},
+		whole.SpanContext.TraceID().String(), tier.SpanContext.SpanID().String())
+}

go.mod

@@ -19,6 +19,7 @@ require (
 	github.com/jackc/pgx/v5 v5.9.2
 	github.com/mattn/goveralls v0.0.5
 	github.com/prometheus/client_golang v1.14.0
+	github.com/prometheus/client_model v0.6.2
 	github.com/redis/go-redis/v9 v9.7.3
 	github.com/theckman/goconstraint v1.10.1-0.20180216224824-e867bde6e4e1
 	go.opentelemetry.io/contrib/instrumentation/net/http/otelhttp v0.67.0
@@ -67,7 +68,6 @@ require (
 	github.com/jmespath/go-jmespath v0.3.0 // indirect
 	github.com/matttproud/golang_protobuf_extensions v1.0.4 // indirect
 	github.com/planetscale/vtprotobuf v0.6.1-0.20240319094008-0393e58bdf10 // indirect
-	github.com/prometheus/client_model v0.6.2 // indirect
 	github.com/prometheus/common v0.39.0 // indirect
 	github.com/prometheus/procfs v0.9.0 // indirect
 	github.com/spf13/pflag v1.0.1 // indirect

internal/faketracer/faketracer.go

@@ -125,3 +125,53 @@ func Int64Attr(span tracetest.SpanStub, key attribute.Key) int64 {
 
 	return -1
 }
+
+// TierSpan returns the span named name that carries the given tier — a read,
+// a write or a purge on one tier of a chain.
+//
+// Here rather than in a test because the lookup is two facts about the tracing
+// package's own data rather than about any test: the span name a tier read
+// takes, and the attribute the tier name lands in. A test that hard-codes
+// either is a test that breaks when tracing renames them.
+//
+// Not used by atlas/tracing_test.go, which wants every tier name at once for a
+// set comparison rather than one span by name.
+func TierSpan(t *testing.T, exporter *tracetest.InMemoryExporter, name, tier string) tracetest.SpanStub {
+	t.Helper()
+
+	for _, span := range SpansNamed(exporter, name) {
+		if StringAttr(span, tracing.AttrCacheTier) == tier {
+			return span
+		}
+	}
+
+	t.Fatalf("no %v span carries tier %v", name, tier)
+
+	return tracetest.SpanStub{}
+}
+
+// RootSpan returns the one recorded span with no parent, failing if there is
+// not exactly one.
+//
+// "Exactly one" is the useful part: a request should root a single trace, and
+// two roots mean something started a sibling trace instead of joining this one.
+//
+// One caller today. server/tracing_test.go checks the same property but finds
+// its roots inside a loop that also tallies span names and trace ids in one
+// pass, and splitting that to call this would make it worse.
+func RootSpan(t *testing.T, exporter *tracetest.InMemoryExporter) tracetest.SpanStub {
+	t.Helper()
+
+	var roots []tracetest.SpanStub
+	for _, span := range exporter.GetSpans() {
+		if !span.Parent.IsValid() {
+			roots = append(roots, span)
+		}
+	}
+
+	if len(roots) != 1 {
+		t.Fatalf("%d root spans, want exactly 1", len(roots))
+	}
+
+	return roots[0]
+}