From 085570a3a6b6d8b05f94f3ce6283c4153dbc9524 Mon Sep 17 00:00:00 2001 From: Niv Greenstein <88280771+NivGreenstein@users.noreply.github.com> Date: Wed, 9 Sep 2026 17:59:00 +0300 Subject: [PATCH 01/27] fix(observability): reuse the http metric families on a second observer MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit newHttpHandler registered its four families with MustRegister, which panics on a duplicate. The registry is process-wide, so a second observer — a second SetObservability call, or a test that builds one of its own — registered the same families again and took the process down. newCache has always gone through registerOrReuse for exactly this reason, and its comment describes this case; this constructor was simply missed. Nothing reached it before because only one observer is built per process in practice and only one test in server/ constructed one. Co-Authored-By: Claude Opus 5 (1M context) --- observability/prometheus/http.go | 16 ++++++++++------ 1 file changed, 10 insertions(+), 6 deletions(-) diff --git a/observability/prometheus/http.go b/observability/prometheus/http.go index b58f3f93..c60293e8 100644 --- a/observability/prometheus/http.go +++ b/observability/prometheus/http.go @@ -64,12 +64,16 @@ func newHttpHandler(registry prometheus.Registerer, prefix string, URLPrefix str []string{}, ) - registry.MustRegister( - handler.inFlightGauge, - handler.counter, - handler.durationSeconds, - handler.responseSizeBytes, - ) + // registerOrReuse, not MustRegister, for the reason its own comment gives: + // the registry is process-wide, so a second observer — a second + // SetObservability, or a test building one of its own — registers these + // same four families again. MustRegister panics on that, which made + // constructing two observers in one process fatal. newCache has always gone + // through registerOrReuse; this constructor was simply missed. + handler.inFlightGauge = registerOrReuse(registry, handler.inFlightGauge) + handler.counter = registerOrReuse(registry, handler.counter) + handler.durationSeconds = registerOrReuse(registry, handler.durationSeconds) + handler.responseSizeBytes = registerOrReuse(registry, handler.responseSizeBytes) return &handler } From 767867710f069581298cad7c19a031071e44332a Mon Sep 17 00:00:00 2001 From: Niv Greenstein <88280771+NivGreenstein@users.noreply.github.com> Date: Wed, 9 Sep 2026 17:59:15 +0300 Subject: [PATCH 02/27] feat(observability): attach trace exemplars to the duration histograms MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit A latency spike in Grafana is now one click from the trace that caused it. The cache, per-tier and HTTP duration observations carry the active trace and span as a Prometheus exemplar, so a slow bucket names the request that landed in it. Three decisions worth the reader's time. Sampling is consulted, which is the opposite of what the log handler does with the same span context (MAPCO-11494). A trace id on a log line still groups a request's lines whether or not Tempo received the trace; an exemplar has no such consolation use, and prometheus keeps one exemplar per bucket, overwritten by the next observation to land there. Unfiltered, at the default sample_ratio of 0.01, the stored exemplar would be a dead link roughly 99 times in 100. The span id rides along with the trace id. The tracing wrappers are installed outside the metric ones at both seams, which two earlier tickets established deliberately and neither could yet make observable — with the span carried, a slow bucket on the per-tier histogram names the tier read that was slow rather than the request as a whole. The label names are the log record's own constants: both surfaces are wired up separately in Grafana and both fail silently when the name is wrong. The metrics route now negotiates OpenMetrics, without which none of the above is scrapeable: OpenMetrics is the only exposition format that encodes exemplars and the classic text format drops them silently. That has a cost, and it is a breaking change for dashboards — under OpenMetrics a bucket boundary that looks like an integer gains a trailing ".0", so le="1" becomes le="1.0" and the series identity changes. Affected: 1, 2.5 and 5 on the cache families, 1, 5 and 10 on the HTTP one. Anything pinning an exact le has to be checked. Handler also takes a pointer receiver like every sibling, clearing a vet copylocks finding on the line being rewritten. Co-Authored-By: Claude Opus 5 (1M context) --- observability/prometheus/cache.go | 17 +- observability/prometheus/exemplar.go | 116 +++++++++ .../prometheus/exemplar_internal_test.go | 246 ++++++++++++++++++ observability/prometheus/http.go | 7 +- observability/prometheus/prometheus.go | 14 +- 5 files changed, 393 insertions(+), 7 deletions(-) create mode 100644 observability/prometheus/exemplar.go create mode 100644 observability/prometheus/exemplar_internal_test.go diff --git a/observability/prometheus/cache.go b/observability/prometheus/cache.go index a3a1aab2..a6b33e3d 100644 --- a/observability/prometheus/cache.go +++ b/observability/prometheus/cache.go @@ -192,6 +192,17 @@ func (co *cache) labels(cmd string, key *tegolaCache.Key) (lbs prometheus.Labels return lbs } +// observeDuration records one operation's latency, pointing at the trace it +// was part of. +// +// ctx is the operation's own context, so the exemplar names the span that +// measured this read rather than the request as a whole: the tracing wrapper is +// installed *outside* this one (atlas.instrumentCache), which is what makes the +// tier's span the active one by the time this runs. +func (co *cache) observeDuration(ctx context.Context, lbs prometheus.Labels, seconds float64) { + observeWithExemplar(co.durationSeconds.With(lbs), seconds, exemplarFrom(ctx)) +} + // Get will record metrics around the getting the tile from the sub cache func (co *cache) Get(ctx context.Context, key *tegolaCache.Key) ([]byte, bool, error) { co.inFlightGauge.Inc() @@ -201,7 +212,7 @@ func (co *cache) Get(ctx context.Context, key *tegolaCache.Key) ([]byte, bool, e // Observed outside the deadline, deliberately: instrumenting inside it // would drop timed-out reads from the histogram — the very events that // make a too-tight timeout_ms diagnosable. - co.durationSeconds.With(lbs).Observe(time.Since(now).Seconds()) + co.observeDuration(ctx, lbs, time.Since(now).Seconds()) if err != nil { co.countReadError(ctx, lbs, err) co.inFlightGauge.Dec() @@ -250,7 +261,7 @@ func (co *cache) Set(ctx context.Context, key *tegolaCache.Key, body []byte) err lbs := co.labels("set", key) now := time.Now() err := co.cache.Set(ctx, key, body) - co.durationSeconds.With(lbs).Observe(time.Since(now).Seconds()) + co.observeDuration(ctx, lbs, time.Since(now).Seconds()) if err != nil { co.errors.With(lbs).Add(1) co.inFlightGauge.Dec() @@ -267,7 +278,7 @@ func (co *cache) Purge(ctx context.Context, key *tegolaCache.Key) error { lbs := co.labels("purge", key) now := time.Now() err := co.cache.Purge(ctx, key) - co.durationSeconds.With(lbs).Observe(time.Since(now).Seconds()) + co.observeDuration(ctx, lbs, time.Since(now).Seconds()) if err != nil { co.errors.With(lbs).Add(1) } diff --git a/observability/prometheus/exemplar.go b/observability/prometheus/exemplar.go new file mode 100644 index 00000000..b44de1fd --- /dev/null +++ b/observability/prometheus/exemplar.go @@ -0,0 +1,116 @@ +package prometheus + +import ( + "context" + "net/http" + + "github.com/prometheus/client_golang/prometheus" + "github.com/prometheus/client_golang/prometheus/promhttp" + "go.opentelemetry.io/otel/trace" + + "github.com/MapColonies/shigola/internal/log" +) + +// The exemplar labels. exemplarTraceIDKey is the one Grafana's Prometheus +// datasource is pointed at to reach Tempo; exemplarSpanIDKey narrows the +// landing to the operation that was actually measured. +// +// Deliberately the same constants the log records carry rather than a second +// spelling of "trace_id": the two surfaces are configured separately in Grafana +// — a derived field on the Loki datasource, an exemplar link on the Prometheus +// one — and both fail *silently* when the name is wrong. One pair of constants +// makes it impossible for a rename to fix one surface and quietly break the +// other. +const ( + exemplarTraceIDKey = log.TraceIDKey + exemplarSpanIDKey = log.SpanIDKey +) + +// exemplarFrom returns the exemplar labels naming the trace active in ctx, or +// nil when there is no trace worth pointing at. +// +// nil is the client's own "no exemplar" signal, so an untraced observation is +// recorded exactly as a plain Observe would record it, with no empty label +// attached and nothing for the exposition to carry. +// +// Sampling *is* consulted here, which is the opposite of what the log handler +// does with the same span context (MAPCO-11494) — and for the reason the two +// differ in purpose. A trace id on a log line still groups that request's +// lines together whether or not Tempo received the trace. An exemplar has no +// such consolation use: its only job is to be a link, and Prometheus keeps one +// exemplar per bucket, overwritten by the next observation that lands there. At +// the default sample_ratio of 0.01 an unfiltered exemplar would therefore be a +// dead link roughly 99 times out of 100 — the stored one is almost always the +// most recent observation, and the most recent observation is almost never +// sampled. Filtering on IsSampled costs the feature nothing it could have had +// and is what makes clicking a bucket actually open a trace. +// +// The span is carried alongside the trace because the observation is made +// *inside* the operation's span, not merely inside the request: the tracing +// wrappers are installed outside the metric ones at both seams +// (atlas.instrumentCache, server.NewRouter). So a slow bucket on the per-tier +// histogram names the tier read that was slow, and a slow bucket on the HTTP +// histogram names the request — rather than both resolving to whatever span +// happened to be open. Without the span id that ordering would make no +// observable difference, which is why it is asserted rather than assumed: +// atlas.TestTierExemplarNamesTheTierSpan. +func exemplarFrom(ctx context.Context) prometheus.Labels { + sc := trace.SpanContextFromContext(ctx) + if !sc.IsValid() || !sc.IsSampled() { + return nil + } + + return prometheus.Labels{ + exemplarTraceIDKey: sc.TraceID().String(), + exemplarSpanIDKey: sc.SpanID().String(), + } +} + +// observeWithExemplar records seconds on obs, attaching exemplar when there is one. +// +// The ExemplarObserver assertion cannot fail for a HistogramVec's observers, +// which are histograms. It is an assertion rather than a cast so that a family +// later changed to a summary — an Observer that is not an ExemplarObserver — +// loses its exemplars instead of panicking on the first traced request. +// +// The nil check is not redundant with ObserveWithExemplar's own handling of nil +// labels. It keeps "an untraced observation is a plain Observe" true at this +// level rather than resting on a documented detail of the client's internals. +func observeWithExemplar(obs prometheus.Observer, seconds float64, exemplar prometheus.Labels) { + if exemplar != nil { + if withExemplar, ok := obs.(prometheus.ExemplarObserver); ok { + withExemplar.ObserveWithExemplar(seconds, exemplar) + return + } + } + + obs.Observe(seconds) +} + +// metricsHandler serves the metrics route, negotiating OpenMetrics. +// +// EnableOpenMetrics is what makes the exemplars this package records reach +// Prometheus at all: OpenMetrics is the only exposition format that encodes +// them, and the classic text format drops them without a word. Recording +// exemplars while serving the default handler would have been a change with no +// observable effect whatsoever. +// +// It changes one other thing, which is the cost of the feature. Under +// OpenMetrics a bucket boundary that would otherwise look like an integer is +// written with a trailing ".0", so a histogram exposes le="1.0" where it used +// to expose le="1" — and a label value is part of a series' identity. The +// affected boundaries are 1, 2.5 and 5 on the cache families and 1, 5 and 10 on +// the HTTP one. Anything matching an exact le — a recording rule, a dashboard +// panel that pins one bucket — has to be checked against the new spelling. The +// alternative was to record exemplars nobody could scrape. +// +// Split out from Handler so a test can scrape a registry of its own: the +// exposition is the half of exemplar support that fails silently, and asserting +// on it against the process-wide default registry would depend on whatever else +// the test binary had registered. +func metricsHandler(registerer prometheus.Registerer, gatherer prometheus.Gatherer) http.Handler { + return promhttp.InstrumentMetricHandler( + registerer, + promhttp.HandlerFor(gatherer, promhttp.HandlerOpts{EnableOpenMetrics: true}), + ) +} diff --git a/observability/prometheus/exemplar_internal_test.go b/observability/prometheus/exemplar_internal_test.go new file mode 100644 index 00000000..592c179b --- /dev/null +++ b/observability/prometheus/exemplar_internal_test.go @@ -0,0 +1,246 @@ +package prometheus + +import ( + "context" + "net/http" + "net/http/httptest" + "strings" + "testing" + + "github.com/prometheus/client_golang/prometheus" + dto "github.com/prometheus/client_model/go" + "go.opentelemetry.io/otel/trace" + + tegolaCache "github.com/MapColonies/shigola/cache" + "github.com/MapColonies/shigola/internal/fakelog" + "github.com/MapColonies/shigola/internal/faketier" +) + +// The trace fixture comes from internal/fakelog rather than internal/faketracer +// on purpose. What these tests need is a bare span context with a recognisable +// id, which is what fakelog holds — faketracer builds a whole SDK tracer +// provider, which is more than an exemplar reads and would put a fourth +// spelling of the same fixed id in the tree. See MAPCO-11494. + +var exemplarKey = &tegolaCache.Key{MapName: "osm", Z: 6, X: 5, Y: 4} + +// TestExemplarFromContext covers the three ways there is nothing to point at +// and the one way there is. +func TestExemplarFromContext(t *testing.T) { + type tcase struct { + ctx context.Context + want string // the trace id expected in the labels; empty means no exemplar + } + + fn := func(tc tcase) func(*testing.T) { + return func(t *testing.T) { + got := exemplarFrom(tc.ctx) + + if tc.want == "" { + if got != nil { + t.Fatalf("exemplarFrom() = %v, want nil so the observation is recorded without one", got) + } + return + } + + if got[exemplarTraceIDKey] != tc.want { + t.Fatalf("exemplarFrom()[%q] = %q, want %q", exemplarTraceIDKey, got[exemplarTraceIDKey], tc.want) + } + if got[exemplarSpanIDKey] != fakelog.SpanIDHex { + t.Errorf("exemplarFrom()[%q] = %q, want %q", exemplarSpanIDKey, got[exemplarSpanIDKey], fakelog.SpanIDHex) + } + if len(got) != 2 { + t.Errorf("exemplarFrom() = %v, want the trace and span ids alone", got) + } + } + } + + tests := map[string]tcase{ + "outside any trace": {ctx: context.Background()}, + // The zero trace id is what an uninitialised or stripped span context + // looks like; pointing an exemplar at it would link nowhere. + "invalid span context": {ctx: fakelog.ContextWith(trace.TraceID{}, fakelog.SpanID, true)}, + // The one that is a judgement rather than a validity check: the trace + // is real but was never exported, so a link to it resolves to nothing. + "valid but unsampled": {ctx: fakelog.TracedContext(false)}, + "sampled": {ctx: fakelog.TracedContext(true), want: fakelog.TraceIDHex}, + } + + for name, tc := range tests { + t.Run(name, fn(tc)) + } +} + +// TestExemplarFitsTheRuneLimit is the acceptance criterion that the label set +// stays inside what the client allows, checked the way the client checks it. +// +// ObserveWithExemplar panics past ExemplarMaxRunes rather than returning an +// error, so the failure mode this guards is a tile server that dies on its +// first traced cache read. A real observation, not just a rune count: the +// limit counts label names and values together, which is easy to get wrong by +// hand and impossible to get wrong this way. +func TestExemplarFitsTheRuneLimit(t *testing.T) { + labels := exemplarFrom(fakelog.TracedContext(true)) + + runes := 0 + for name, value := range labels { + runes += len([]rune(name)) + len([]rune(value)) + } + if runes > prometheus.ExemplarMaxRunes { + t.Fatalf("exemplar labels are %d runes, over the limit of %d", runes, prometheus.ExemplarMaxRunes) + } + t.Logf("exemplar labels are %d of the %d runes allowed", runes, prometheus.ExemplarMaxRunes) + + histogram := prometheus.NewHistogram(prometheus.HistogramOpts{ + Name: "test_exemplar_limit_seconds", + Buckets: cacheDurationBuckets, + }) + + defer func() { + if r := recover(); r != nil { + t.Fatalf("ObserveWithExemplar panicked on %v: %v", labels, r) + } + }() + + histogram.(prometheus.ExemplarObserver).ObserveWithExemplar(0.002, labels) +} + +// TestCacheDurationCarriesTheExemplar is the cache half of the ticket: a tier +// read observed inside a sampled trace names it. +func TestCacheDurationCarriesTheExemplar(t *testing.T) { + registry := prometheus.NewRegistry() + tier := faketier.New("hot") + c := newCache(registry, "test_exemplar_cache", nil, tier) + + //nolint:errcheck // a miss; the exemplar on the duration observation is the subject + c.Get(fakelog.TracedContext(true), exemplarKey) + + if got := exemplarTraceID(t, registry, "test_exemplar_cache_duration_seconds"); got != fakelog.TraceIDHex { + t.Fatalf("cache duration exemplar names trace %q, want %q", got, fakelog.TraceIDHex) + } +} + +// TestCacheDurationOutsideATraceHasNoExemplar is the other acceptance +// criterion: an untraced observation records normally, with nothing attached. +func TestCacheDurationOutsideATraceHasNoExemplar(t *testing.T) { + registry := prometheus.NewRegistry() + tier := faketier.New("hot") + c := newCache(registry, "test_plain_cache", nil, tier) + + //nolint:errcheck // as above + c.Get(context.Background(), exemplarKey) + + histogram := gatherHistogram(t, registry, "test_plain_cache_duration_seconds") + if histogram.GetSampleCount() != 1 { + t.Fatalf("sample count = %d, want the observation to have been recorded anyway", histogram.GetSampleCount()) + } + for _, bucket := range histogram.GetBucket() { + if bucket.GetExemplar() != nil { + t.Fatalf("bucket le=%v carries an exemplar outside a trace", bucket.GetUpperBound()) + } + } +} + +// TestHTTPDurationCarriesTheExemplar is the request half. The span context +// reaches the middleware on the request, which is how it arrives in +// production: the tracing handler is installed outside the metrics one and has +// already replaced the request by the time this runs. +func TestHTTPDurationCarriesTheExemplar(t *testing.T) { + registry := prometheus.NewRegistry() + handler := newHttpHandler(registry, "test_exemplar_api", "", nil) + + instrumented := handler.InstrumentedHttpHandler(http.MethodGet, "/collections/osm/tiles", + http.HandlerFunc(func(w http.ResponseWriter, _ *http.Request) { w.WriteHeader(http.StatusOK) })) + + request := httptest.NewRequest(http.MethodGet, "/collections/osm/tiles", nil). + WithContext(fakelog.TracedContext(true)) + instrumented.ServeHTTP(httptest.NewRecorder(), request) + + if got := exemplarTraceID(t, registry, "test_exemplar_api_duration_seconds"); got != fakelog.TraceIDHex { + t.Fatalf("http duration exemplar names trace %q, want %q", got, fakelog.TraceIDHex) + } +} + +// TestExemplarReachesTheExposition is the one that would have made every other +// test in this file worthless. +// +// Exemplars are recorded in the client either way, but only the OpenMetrics +// encoding transmits them — the classic text encoder has no syntax for them and +// drops them silently. So this scrapes the handler the metrics route actually +// serves, with the Accept header Prometheus sends, and looks for the exemplar +// in the bytes. +func TestExemplarReachesTheExposition(t *testing.T) { + registry := prometheus.NewRegistry() + tier := faketier.New("hot") + c := newCache(registry, "test_scraped_cache", nil, tier) + + //nolint:errcheck // as above + c.Get(fakelog.TracedContext(true), exemplarKey) + + request := httptest.NewRequest(http.MethodGet, "/metrics", nil) + // Prometheus's own scrape header, verbatim. The version list matters: the + // vendored expfmt negotiates OpenMetrics 0.0.1 only, so a header offering + // 1.0.0 alone falls back to the classic text format and the exemplars + // vanish. Prometheus offers both, which is why this works in production. + request.Header.Set("Accept", "application/openmetrics-text;version=1.0.0,"+ + "application/openmetrics-text;version=0.0.1;q=0.75,"+ + "text/plain;version=0.0.4;q=0.5,*/*;q=0.1") + recorder := httptest.NewRecorder() + metricsHandler(registry, registry).ServeHTTP(recorder, request) + + if contentType := recorder.Header().Get("Content-Type"); !strings.Contains(contentType, "openmetrics-text") { + t.Fatalf("Content-Type = %q, want the OpenMetrics encoding that carries exemplars", contentType) + } + + want := exemplarTraceIDKey + `="` + fakelog.TraceIDHex + `"` + if body := recorder.Body.String(); !strings.Contains(body, want) { + t.Fatalf("the exposition does not contain %q; exemplars are recorded but never scraped", want) + } +} + +// gatherHistogram reads one histogram out of a registry by family name. +func gatherHistogram(t *testing.T, gatherer prometheus.Gatherer, name string) *dto.Histogram { + t.Helper() + + families, err := gatherer.Gather() + if err != nil { + t.Fatalf("gather: %v", err) + } + + for _, family := range families { + if family.GetName() != name { + continue + } + if metrics := family.GetMetric(); len(metrics) > 0 { + return metrics[0].GetHistogram() + } + } + + t.Fatalf("no %v in the registry", name) + + return nil +} + +// exemplarTraceID returns the trace id on the first bucket of the named +// histogram that carries an exemplar. +func exemplarTraceID(t *testing.T, gatherer prometheus.Gatherer, name string) string { + t.Helper() + + histogram := gatherHistogram(t, gatherer, name) + + for _, bucket := range histogram.GetBucket() { + exemplar := bucket.GetExemplar() + if exemplar == nil { + continue + } + for _, pair := range exemplar.GetLabel() { + if pair.GetName() == exemplarTraceIDKey { + return pair.GetValue() + } + } + } + + t.Fatalf("no bucket of %v carries an exemplar labelled %v", name, exemplarTraceIDKey) + + return "" +} diff --git a/observability/prometheus/http.go b/observability/prometheus/http.go index c60293e8..ecb9f1eb 100644 --- a/observability/prometheus/http.go +++ b/observability/prometheus/http.go @@ -112,7 +112,12 @@ func (handler *httpHandler) instrumentHandlerDuration(originalRoute string, next labels := prometheus.Labels{ "handler": strings.Join(parts, "/"), } - promhttp.InstrumentHandlerDuration(handler.durationSeconds.MustCurryWith(labels), next).ServeHTTP(w, r) + // The exemplar comes off the request context, which by this point + // carries the server span: the tracing handler wraps this one + // (server.NewRouter), so it has already replaced the request. + promhttp.InstrumentHandlerDuration(handler.durationSeconds.MustCurryWith(labels), next, + promhttp.WithExemplarFromContext(exemplarFrom), + ).ServeHTTP(w, r) }) } diff --git a/observability/prometheus/prometheus.go b/observability/prometheus/prometheus.go index b5899d90..d4c42a76 100644 --- a/observability/prometheus/prometheus.go +++ b/observability/prometheus/prometheus.go @@ -18,7 +18,6 @@ import ( "github.com/MapColonies/shigola/internal/log" "github.com/MapColonies/shigola/observability" "github.com/prometheus/client_golang/prometheus" - "github.com/prometheus/client_golang/prometheus/promhttp" ) type byteSize uint64 @@ -133,8 +132,17 @@ func New(config dict.Dicter) (observability.Interface, error) { func (*observer) Name() string { return Name } -func (observer) Handler(string) http.Handler { return promhttp.Handler() } -func (obs *observer) Init() { obs.initCall.Do(obs.init) } +// Handler serves the metrics route. See metricsHandler for why the exposition +// format is not the client's default. +// +// A pointer receiver like every sibling. It was a value receiver, which copied +// the observer's sync.Once fields on every call — a vet copylocks finding, and +// harmless only because the copy was discarded unread. +func (*observer) Handler(string) http.Handler { + return metricsHandler(prometheus.DefaultRegisterer, prometheus.DefaultGatherer) +} + +func (obs *observer) Init() { obs.initCall.Do(obs.init) } func (obs *observer) init() { obs.PublishBuildInfo() if obs == nil || obs.pushURL == "" { From 1a499b59f9fed3ee1ea529af2c91dba7d6350f98 Mon Sep 17 00:00:00 2001 From: Niv Greenstein <88280771+NivGreenstein@users.noreply.github.com> Date: Wed, 9 Sep 2026 17:59:25 +0300 Subject: [PATCH 03/27] test: pin the exemplar to the span the observation measured MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The wrapping order at both instrumentation seams — tracing outside metrics — was established by MAPCO-11497 with a comment at each site saying trace exemplars would need it. Nothing depended on it until now, and inverting either one leaves the span tree unchanged, so the existing span assertions would keep passing. Both new tests fail on that inversion, and say which way round it went wrong: the per-tier exemplar reports the cache-wide span instead of the tier's, and the request exemplar disappears altogether because the metrics middleware observes a request whose context has no span yet. atlas.TestCheckCacheTypes gained a comment rather than a change. It asserts the exact set of registered cache types, so it is sensitive to the fake types every other test file in the package registers — and it passes only because those files all sort after it. This work hit that: a file named cache_exemplar_test.go failed it, and the same file renamed did not. Co-Authored-By: Claude Opus 5 (1M context) --- atlas/cache_init_test.go | 9 ++ atlas/cache_trace_exemplar_test.go | 177 +++++++++++++++++++++++++++++ server/http_exemplar_test.go | 136 ++++++++++++++++++++++ 3 files changed, 322 insertions(+) create mode 100644 atlas/cache_trace_exemplar_test.go create mode 100644 server/http_exemplar_test.go diff --git a/atlas/cache_init_test.go b/atlas/cache_init_test.go index 42a70249..83202f0c 100644 --- a/atlas/cache_init_test.go +++ b/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"} diff --git a/atlas/cache_trace_exemplar_test.go b/atlas/cache_trace_exemplar_test.go new file mode 100644 index 00000000..6fa93f07 --- /dev/null +++ b/atlas/cache_trace_exemplar_test.go @@ -0,0 +1,177 @@ +package atlas + +import ( + "context" + "testing" + + promclient "github.com/prometheus/client_golang/prometheus" + dto "github.com/prometheus/client_model/go" + "go.opentelemetry.io/otel/sdk/trace/tracetest" + + "github.com/MapColonies/shigola/internal/faketier" + "github.com/MapColonies/shigola/internal/faketracer" + "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. + +// TestTierExemplarNamesTheTierSpan 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. +func TestTierExemplarNamesTheTierSpan(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, "exhot1", "exdurable1", "exhot1", "exdurable1", 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) + } + + whole := faketracer.SpanNamed(t, exporter, tracing.SpanCacheGet) + + hotSpan := spanForTier(t, exporter, "exhot1") + + exemplar := exemplarFor(t, "shigola_cache_tier_duration_seconds", + map[string]string{"tier": "exhot1", "sub_command": "get"}) + + if got, want := exemplar["trace_id"], hotSpan.SpanContext.TraceID().String(); got != want { + t.Errorf("tier exemplar trace_id = %q, want the request's trace %q", got, want) + } + + if got, want := exemplar["span_id"], hotSpan.SpanContext.SpanID().String(); got != want { + t.Errorf("tier exemplar span_id = %q, want the tier's own span %q", got, want) + } + + // The specific inversion the ordering prevents, named so a failure says + // which way round it went wrong. + if exemplar["span_id"] == whole.SpanContext.SpanID().String() { + t.Error("tier exemplar names the cache-wide span; the metric wrapper is outside the tracing one") + } +} + +// TestWholeCacheExemplarNamesTheCacheSpan is the same property one level up: +// the whole-cache family measures the chain, so its exemplar names the chain's +// span rather than a tier's. +func TestWholeCacheExemplarNamesTheCacheSpan(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, "exhot2", "exdurable2", "exhot2", "exdurable2", 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) + } + + whole := faketracer.SpanNamed(t, exporter, tracing.SpanCacheGet) + + exemplar := exemplarFor(t, "shigola_cache_duration_seconds", map[string]string{"sub_command": "get"}) + + if got, want := exemplar["trace_id"], whole.SpanContext.TraceID().String(); got != want { + t.Errorf("whole-cache exemplar trace_id = %q, want %q", got, want) + } + + if got, want := exemplar["span_id"], whole.SpanContext.SpanID().String(); got != want { + t.Errorf("whole-cache exemplar span_id = %q, want the %v span %q", got, tracing.SpanCacheGet, want) + } +} + +// spanForTier returns the tier span carrying the given tier name. +func spanForTier(t *testing.T, exporter *tracetest.InMemoryExporter, tier string) tracetest.SpanStub { + t.Helper() + + for _, span := range faketracer.SpansNamed(exporter, tracing.SpanTierGet) { + if faketracer.StringAttr(span, tracing.AttrCacheTier) == tier { + return span + } + } + + t.Fatalf("no %v span carries tier %v", tracing.SpanTierGet, tier) + + return tracetest.SpanStub{} +} + +// exemplarFor returns the labels of the exemplar on the named family's first +// bucket that carries one, for the sample matching labels. +// +// Read off the process-wide registry, which is safe for exemplars in a way it +// would not be for counters: an untraced observation stores nothing, so only a +// test that both traces and observes leaves an exemplar behind — and the +// assertions compare against a trace id this test's own exporter produced. +func exemplarFor(t *testing.T, name string, labels map[string]string) map[string]string { + t.Helper() + + families, err := promclient.DefaultGatherer.Gather() + if err != nil { + t.Fatalf("gather: %v", err) + } + + for _, family := range families { + if family.GetName() != name { + continue + } + + for _, metric := range family.GetMetric() { + if !hasLabels(metric.GetLabel(), labels) { + continue + } + + for _, bucket := range metric.GetHistogram().GetBucket() { + exemplar := bucket.GetExemplar() + if exemplar == nil { + continue + } + + got := make(map[string]string, len(exemplar.GetLabel())) + for _, pair := range exemplar.GetLabel() { + got[pair.GetName()] = pair.GetValue() + } + + return got + } + + t.Fatalf("no bucket of %v%v carries an exemplar", name, labels) + } + } + + t.Fatalf("no sample of %v matches %v", name, labels) + + return nil +} + +// hasLabels reports whether pairs contain every label in want. +func hasLabels(pairs []*dto.LabelPair, want map[string]string) bool { + for name, value := range want { + found := false + for _, pair := range pairs { + if pair.GetName() == name && pair.GetValue() == value { + found = true + break + } + } + if !found { + return false + } + } + + return true +} diff --git a/server/http_exemplar_test.go b/server/http_exemplar_test.go new file mode 100644 index 00000000..847fefe2 --- /dev/null +++ b/server/http_exemplar_test.go @@ -0,0 +1,136 @@ +package server_test + +import ( + "net/http" + "net/url" + "strings" + "testing" + + promclient "github.com/prometheus/client_golang/prometheus" + "go.opentelemetry.io/otel/sdk/trace/tracetest" + + "github.com/MapColonies/shigola/dict" + "github.com/MapColonies/shigola/internal/faketracer" + "github.com/MapColonies/shigola/observability/prometheus" + "github.com/MapColonies/shigola/server" +) + +// A zoom of its own, inside testLayer2's 10-15 range. +// +// The `handler` label keeps the tile matrix — :tile_matrix is in the observer's +// default observe-vars — so requesting a zoom no other test in this package +// uses puts this test's observations on a series of their own. That matters +// here and nowhere else in the package: prometheus keeps one exemplar per +// bucket and overwrites it, so two tests sharing a series would each be reading +// whichever ran last. +const exemplarTileURI = "/collections/test-map/tiles/WebMercatorQuad/11/3/2" + +// TestRequestExemplarNamesTheRequestSpan is the HTTP half of MAPCO-11496, and +// the regression test for the middleware order server.NewRouter documents. +// +// Inverting that order leaves the span tree exactly as it is — the request span +// is still the root and everything still hangs off it — so +// TestTileRequestProducesOneSpanTree would keep passing. What it changes is +// that the metrics middleware would then run *outside* the tracing one, take +// its duration observation off a request whose context has no span yet, and +// attach no exemplar at all. +func TestRequestExemplarNamesTheRequestSpan(t *testing.T) { + server.HostName = &url.URL{Host: serverHostName} + server.URIPrefix = "/" + + a := newTestMapWithLayers(testLayer2) + a.SetCache(twoTierCache(t, "exemplarhot", "exemplardurable")) + + observer, err := prometheus.New(dict.Dict{}) + if err != nil { + t.Fatalf("prometheus observer: %v", err) + } + a.SetObservability(observer) + + tracer, exporter := faketracer.New(t) + tracer.Install() + a.SetTracing(tracer) + + if _, _, err := doRequest(t, a, http.MethodGet, exemplarTileURI, nil); err != nil { + t.Fatalf("traced request: %v", err) + } + + root := rootSpan(t, exporter) + + exemplar := httpExemplar(t, "shigola_api_duration_seconds", "/11/") + + if got, want := exemplar["trace_id"], root.SpanContext.TraceID().String(); got != want { + t.Errorf("request exemplar trace_id = %q, want %q", got, want) + } + + if got, want := exemplar["span_id"], root.SpanContext.SpanID().String(); got != want { + t.Errorf("request exemplar span_id = %q, want the request span %q", got, want) + } +} + +// rootSpan returns the one recorded span with no parent. +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 — the request", len(roots)) + } + + return roots[0] +} + +// httpExemplar returns the exemplar labels off the api duration histogram whose +// handler label contains match. +func httpExemplar(t *testing.T, name, match string) map[string]string { + t.Helper() + + families, err := promclient.DefaultGatherer.Gather() + if err != nil { + t.Fatalf("gather: %v", err) + } + + for _, family := range families { + if family.GetName() != name { + continue + } + + for _, metric := range family.GetMetric() { + handler := "" + for _, pair := range metric.GetLabel() { + if pair.GetName() == "handler" { + handler = pair.GetValue() + } + } + if !strings.Contains(handler, match) { + continue + } + + for _, bucket := range metric.GetHistogram().GetBucket() { + exemplar := bucket.GetExemplar() + if exemplar == nil { + continue + } + + got := make(map[string]string, len(exemplar.GetLabel())) + for _, pair := range exemplar.GetLabel() { + got[pair.GetName()] = pair.GetValue() + } + + return got + } + + t.Fatalf("no bucket of %v{handler~%q} carries an exemplar", name, match) + } + } + + t.Fatalf("no sample of %v has a handler label containing %q", name, match) + + return nil +} From e383c95166c0e90987cb383548d0c7276ad7afdb Mon Sep 17 00:00:00 2001 From: Niv Greenstein <88280771+NivGreenstein@users.noreply.github.com> Date: Wed, 9 Sep 2026 18:01:03 +0300 Subject: [PATCH 04/27] docs: describe the exemplar-to-trace workflow MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit tracing/README.md gains "Correlating metrics with traces" beside the logs section it mirrors, and says where the two deliberately differ: sampling is consulted for exemplars and not for log records, because an exemplar is only ever a link and prometheus keeps one per bucket — so an unfiltered one would point at a dropped trace 99 times out of 100. The observer's README carries the operator half: which families carry an exemplar and which span each names, and the three things outside this repo that each fail quietly on their own — the scrape format, exemplar storage on the server, and the Grafana datasource link. Both record the two limits. Exemplars are not pushed, so a push_url deployment gets none; and negotiating OpenMetrics respells integer-looking le boundaries with a trailing ".0", which changes those series' identity. Co-Authored-By: Claude Opus 5 (1M context) --- observability/prometheus/README.md | 50 +++++++++++++++++- tracing/README.md | 81 ++++++++++++++++++++++++++++++ 2 files changed, 130 insertions(+), 1 deletion(-) diff --git a/observability/prometheus/README.md b/observability/prometheus/README.md index 7d86997c..ab7b1710 100644 --- a/observability/prometheus/README.md +++ b/observability/prometheus/README.md @@ -13,7 +13,9 @@ type = "prometheus" ``` -The metrics will be exposed on the `/metrics` end point. +The metrics will be exposed on the `/metrics` end point, in the **OpenMetrics** +format when the scraper asks for it — see [Trace exemplars](#trace-exemplars), +which is the reason it does. ### Configuration Properties @@ -28,6 +30,48 @@ The metrics will be exposed on the `/metrics` end point. - `push_cadence` (int) : [Optional] How often to push to the Prometheus Gateway. Defaults to 10 secs. Use a zero or less to only push at the end of the process. +### Trace exemplars + +When [tracing](../../tracing/README.md) is enabled, each duration observation +made inside a **sampled** trace carries that trace and span as a Prometheus +exemplar, so a slow bucket in Grafana links to the trace that produced it. + +| Family | Exemplar | +|:---|:---| +| `shigola_cache_duration_seconds` | the `cache.Get`/`Set`/`Purge` span | +| `shigola_cache_tier_duration_seconds` | the `cache.tier.*` span for that tier | +| `shigola_api_duration_seconds` | the request span | + +The labels are `trace_id` and `span_id`, the same names the log records carry. +Nothing is attached to an observation made outside a trace, or inside an +unsampled one — the observation is recorded exactly as it would have been, with +no empty label. + +`span_id` names the operation that was measured rather than the request, which +is what makes an exemplar on the per-tier histogram useful: it points at the +tier read that was slow, on the one family whose purpose is telling tiers apart. + +**Wiring it up.** Three things outside this repo have to be true, and each fails +quietly on its own: + +1. The scraper must ask for OpenMetrics. Prometheus does by default; the format + is the only one that encodes exemplars, and the classic text format drops + them silently. +2. The server must store them — Prometheus needs + `--enable-feature=exemplar-storage`, Mimir its equivalent. +3. Grafana's Prometheus datasource needs an exemplar link on `trace_id` + pointing at the Tempo datasource. Without it the exemplars render as dots on + the panel with no link behind them. + +Then a bucket with a dot on it is one click from the trace. + +**Two limits.** Exemplars are not pushed: a `push_url` deployment goes through +the classic text format to a Pushgateway, which has no notion of them. And +negotiating OpenMetrics changed the `le` label spelling — a boundary that looks +like an integer gains a trailing `.0`, so `le="1"` is now `le="1.0"` on the 1, +2.5 and 5 boundaries of the cache families and the 1, 5 and 10 of the HTTP one. +Anything matching an exact `le` needs checking. + ### Metrics exposed #### shigola build info @@ -52,6 +96,8 @@ versions of the application. ##### shigola_api_duration_seconds +Carries a [trace exemplar](#trace-exemplars) naming the request span. + A histogram of latencies for requests. As part of a histogram include the support tags: @@ -122,6 +168,8 @@ A counter of the number of tile hits ##### shigola_cache_duration_seconds +Carries a [trace exemplar](#trace-exemplars) naming the cache operation's span. + Buckets: 1-2-5 per decade from 100µs to 5 seconds — 100µs, 250µs, 500µs, 1ms, 2.5ms, 5ms, 10ms, 25ms, 50ms, 100ms, 250ms, 500ms, 1s, 2.5s, 5s. diff --git a/tracing/README.md b/tracing/README.md index 9ccebffc..e5bcdf30 100644 --- a/tracing/README.md +++ b/tracing/README.md @@ -11,6 +11,12 @@ publishes exactly the metric families it published before. `atlas`'s `TestMetricsAreUnaffectedByTracing` asserts that rather than leaving it to be believed. +What tracing does add to both other signals is its ids: on log records, and as +exemplars on the duration histograms — see +[Correlating logs with traces](#correlating-logs-with-traces) and +[Correlating metrics with traces](#correlating-metrics-with-traces). Neither +adds a metric family or a log field outside a trace. + ## What tracing answers that metrics cannot A histogram can say a tile took 300ms. It cannot say whether that was the @@ -239,6 +245,81 @@ Two consequences worth knowing: too — it is now `stack` at the top level rather than `shigola.stack`. Anything parsing that path needs updating; nothing else about the record changed. +## Correlating metrics with traces + +Cache, per-tier and HTTP duration observations carry the active trace and span +as a **Prometheus exemplar**, so a slow histogram bucket in Grafana links +straight to the trace that landed in it (MAPCO-11496): + +``` +shigola_cache_tier_duration_seconds_bucket{tier="durable",sub_command="get",le="0.5"} 3 # {trace_id="4bf92f3577b34da6a3ce929d0e0e4736",span_id="00f067aa0ba902b7"} 0.41 1.7e+09 +``` + +The labels are `internal/log.TraceIDKey` and `SpanIDKey` — the same constants the +log records carry, deliberately. Logs-to-traces and metrics-to-traces are wired +up separately in Grafana (a derived field on the Loki datasource, an exemplar +link on the Prometheus one) and **both fail silently on a wrong name**, so one +pair of constants is what stops a rename from fixing one surface and breaking +the other. + +Which observations carry one: `shigola_cache_duration_seconds`, +`shigola_cache_tier_duration_seconds` and `shigola_api_duration_seconds`. The +size histograms and the counters do not — the ticket asked for the duration +families, and an exemplar is worth having where there is a spike to click. + +**The exposition format is not optional.** OpenMetrics is the only format that +encodes exemplars; the classic Prometheus text format has no syntax for them and +drops them without a word. The metrics route therefore negotiates OpenMetrics +(`observability/prometheus.metricsHandler`), which Prometheus offers in its own +scrape `Accept` header. The vendored `expfmt` negotiates version `0.0.1` only — +enough, because Prometheus offers both `1.0.0` and `0.0.1`, but a hand-rolled +scrape offering `1.0.0` alone silently gets the classic format and no exemplars. + +Storing them is a server-side switch as well: Prometheus needs +`--enable-feature=exemplar-storage`, and Mimir its equivalent, or the exemplars +are scraped and discarded. + +Three properties of this are load-bearing. + +**Sampling *is* consulted — the opposite of the log records above.** An exemplar +is only ever a link, and prometheus keeps one per bucket, overwritten by the next +observation to land there. So the stored exemplar is almost always the most +recent observation, and at `sample_ratio = 0.01` the most recent observation is +almost never sampled: unfiltered, clicking a bucket would open nothing roughly +99 times out of 100. A log line's trace id keeps its consolation use when the +trace was dropped — it still groups that request's lines — and an exemplar has +none, which is why the same span context is filtered here and not there. + +**The span, not just the trace.** The observation is made *inside* the +operation's span because the tracing wrappers are installed outside the metric +ones at both seams — `atlas.instrumentCache` and `server.NewRouter`, each with a +comment saying so. A slow bucket on the per-tier histogram therefore names the +tier read that was slow, not the request as a whole. Inverting either order +leaves the span tree unchanged, so it is pinned by the exemplar instead: +`atlas.TestTierExemplarNamesTheTierSpan` and +`server.TestRequestExemplarNamesTheRequestSpan` both fail on it, and say which +way round it went wrong. + +**Nothing is attached outside a trace.** `exemplarFrom` returns nil, which is +the client's own "no exemplar" signal, so an untraced observation is recorded +exactly as a plain `Observe` would record it — no empty label, nothing for the +exposition to carry. The label set is 63 of the 128 runes the client allows; +past that limit `ObserveWithExemplar` panics rather than returning an error, +which `TestExemplarFitsTheRuneLimit` guards by making a real observation. + +Two consequences worth knowing: + +- **`le` label values changed.** Under OpenMetrics a bucket boundary that would + otherwise look like an integer is written with a trailing `.0`, and a label + value is part of a series' identity — so `le="1"` is now `le="1.0"`. The + affected boundaries are 1, 2.5 and 5 on the cache families and 1, 5 and 10 on + the HTTP one. Anything pinning an exact `le` — a recording rule, a panel + showing one bucket — has to be checked against the new spelling. This was the + price of exemplars being scrapeable at all. +- **Pushed metrics carry no exemplars.** A deployment using `push_url` pushes + through the classic text format to a Pushgateway, which has no notion of + exemplars. Everything above applies to scraped deployments only. + ## Costs when disabled Nothing. A disabled config returns the no-op backend before an exporter is From 57f7b6b1c4ffa951c7ed425a976ada5100ba1a13 Mon Sep 17 00:00:00 2001 From: Niv Greenstein <88280771+NivGreenstein@users.noreply.github.com> Date: Wed, 9 Sep 2026 18:01:23 +0300 Subject: [PATCH 05/27] docs(contributing): map the metrics docs to their source The observer README is now the source for the docs site metrics sections, and docs/tracing.md gained a metrics half. Neither had a row, so a change to exemplar behaviour had no documented docs-site counterpart to update. Co-Authored-By: Claude Opus 5 (1M context) --- CONTRIBUTING.md | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/CONTRIBUTING.md b/CONTRIBUTING.md index 0e03efdc..f702e8bc 100644 --- a/CONTRIBUTING.md +++ b/CONTRIBUTING.md @@ -84,10 +84,11 @@ 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/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. From 26bae12971dc391c721156238a7b5a2d492fbe11 Mon Sep 17 00:00:00 2001 From: Niv Greenstein <88280771+NivGreenstein@users.noreply.github.com> Date: Wed, 9 Sep 2026 18:14:30 +0300 Subject: [PATCH 06/27] test: share the exemplar readers, and derive the respelled le list MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Three test files had grown the same walker — gather, match the family, match the labels, find the first bucket with an exemplar, flatten its labels. internal/ttools is where this package's own precedent puts it: MetricFamilyNames is there for the same reason, and says so. The two atlas tests become one table, since they differed only in the family and the span expected. Only the per-tier row can catch the inversion, so only it checks for it. The le respelling was documented wrong in four places, and wrong in the direction that understates an upgrade break. expfmt appends ".0" only when the shortest 'g' rendering contains neither "." nor "e", so 2.5 was never affected — and the *response-size* families are, because the format is negotiated per scrape rather than per family. TestRespelledBucketBoundaries derives the list from the bucket sets so the docs cannot drift from them again. Also: metricsHandler moves next to Handler, its only caller, rather than sitting in the exemplar file; the server test matches the handler label exactly instead of on a "/11/" substring; and http.go points at registerOrReuse's doc rather than restating it. Co-Authored-By: Claude Opus 5 (1M context) --- atlas/cache_trace_exemplar_test.go | 186 ++++++------------ internal/ttools/metrics.go | 85 ++++++++ observability/prometheus/README.md | 24 ++- observability/prometheus/exemplar.go | 30 --- .../prometheus/exemplar_internal_test.go | 61 +----- observability/prometheus/http.go | 10 +- .../openmetrics_le_internal_test.go | 96 +++++++++ observability/prometheus/prometheus.go | 36 +++- server/http_exemplar_test.go | 60 +----- tracing/README.md | 27 ++- 10 files changed, 340 insertions(+), 275 deletions(-) create mode 100644 observability/prometheus/openmetrics_le_internal_test.go diff --git a/atlas/cache_trace_exemplar_test.go b/atlas/cache_trace_exemplar_test.go index 6fa93f07..43274d22 100644 --- a/atlas/cache_trace_exemplar_test.go +++ b/atlas/cache_trace_exemplar_test.go @@ -5,93 +5,99 @@ import ( "testing" promclient "github.com/prometheus/client_golang/prometheus" - dto "github.com/prometheus/client_model/go" "go.opentelemetry.io/otel/sdk/trace/tracetest" "github.com/MapColonies/shigola/internal/faketier" "github.com/MapColonies/shigola/internal/faketracer" + "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. -// TestTierExemplarNamesTheTierSpan is what the wrapping order in +// 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 +// 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. -func TestTierExemplarNamesTheTierSpan(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, "exhot1", "exdurable1", "exhot1", "exdurable1", 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) +// +// 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 } - whole := faketracer.SpanNamed(t, exporter, tracing.SpanCacheGet) - - hotSpan := spanForTier(t, exporter, "exhot1") + 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")) - exemplar := exemplarFor(t, "shigola_cache_tier_duration_seconds", - map[string]string{"tier": "exhot1", "sub_command": "get"}) + tracer, exporter := faketracer.New(t) - if got, want := exemplar["trace_id"], hotSpan.SpanContext.TraceID().String(); got != want { - t.Errorf("tier exemplar trace_id = %q, want the request's trace %q", got, want) - } + 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 got, want := exemplar["span_id"], hotSpan.SpanContext.SpanID().String(); got != want { - t.Errorf("tier exemplar span_id = %q, want the tier's own span %q", got, want) - } - - // The specific inversion the ordering prevents, named so a failure says - // which way round it went wrong. - if exemplar["span_id"] == whole.SpanContext.SpanID().String() { - t.Error("tier exemplar names the cache-wide span; the metric wrapper is outside the tracing one") - } -} + 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) + } -// TestWholeCacheExemplarNamesTheCacheSpan is the same property one level up: -// the whole-cache family measures the chain, so its exemplar names the chain's -// span rather than a tier's. -func TestWholeCacheExemplarNamesTheCacheSpan(t *testing.T) { - hot := faketier.New("hot") - durable := faketier.New("durable") - durable.Seed(obsKey, []byte("tile")) + measured := tc.wantSpan(t, exporter) + exemplar := ttools.ExemplarLabels(t, promclient.DefaultGatherer, tc.family, tc.labels) - tracer, exporter := faketracer.New(t) + if got, want := exemplar["trace_id"], measured.SpanContext.TraceID().String(); got != want { + t.Errorf("exemplar trace_id = %q, want the request's trace %q", got, want) + } - a := &Atlas{} - a.SetCache(tieredCache(t, "exhot2", "exdurable2", "exhot2", "exdurable2", hot, durable, 0)) - a.SetObservability(newObserver(t)) - a.SetTracing(tracer) + if got, want := exemplar["span_id"], measured.SpanContext.SpanID().String(); got != want { + t.Errorf("exemplar span_id = %q, want %q", got, want) + } - 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) + // The specific inversion the ordering prevents, named so a failure + // says which way round it went wrong. + whole := faketracer.SpanNamed(t, exporter, tracing.SpanCacheGet) + if tc.family == "shigola_cache_tier_duration_seconds" && + exemplar["span_id"] == whole.SpanContext.SpanID().String() { + t.Error("tier exemplar names the cache-wide span; the metric wrapper is outside the tracing one") + } + } } - whole := faketracer.SpanNamed(t, exporter, tracing.SpanCacheGet) - - exemplar := exemplarFor(t, "shigola_cache_duration_seconds", map[string]string{"sub_command": "get"}) - - if got, want := exemplar["trace_id"], whole.SpanContext.TraceID().String(); got != want { - t.Errorf("whole-cache exemplar trace_id = %q, want %q", got, want) + 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 spanForTier(t, exporter, "exhot1") + }, + }, + "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) + }, + }, } - if got, want := exemplar["span_id"], whole.SpanContext.SpanID().String(); got != want { - t.Errorf("whole-cache exemplar span_id = %q, want the %v span %q", got, tracing.SpanCacheGet, want) + for name, tc := range tests { + t.Run(name, fn(tc)) } } @@ -109,69 +115,3 @@ func spanForTier(t *testing.T, exporter *tracetest.InMemoryExporter, tier string return tracetest.SpanStub{} } - -// exemplarFor returns the labels of the exemplar on the named family's first -// bucket that carries one, for the sample matching labels. -// -// Read off the process-wide registry, which is safe for exemplars in a way it -// would not be for counters: an untraced observation stores nothing, so only a -// test that both traces and observes leaves an exemplar behind — and the -// assertions compare against a trace id this test's own exporter produced. -func exemplarFor(t *testing.T, name string, labels map[string]string) map[string]string { - t.Helper() - - families, err := promclient.DefaultGatherer.Gather() - if err != nil { - t.Fatalf("gather: %v", err) - } - - for _, family := range families { - if family.GetName() != name { - continue - } - - for _, metric := range family.GetMetric() { - if !hasLabels(metric.GetLabel(), labels) { - continue - } - - for _, bucket := range metric.GetHistogram().GetBucket() { - exemplar := bucket.GetExemplar() - if exemplar == nil { - continue - } - - got := make(map[string]string, len(exemplar.GetLabel())) - for _, pair := range exemplar.GetLabel() { - got[pair.GetName()] = pair.GetValue() - } - - return got - } - - t.Fatalf("no bucket of %v%v carries an exemplar", name, labels) - } - } - - t.Fatalf("no sample of %v matches %v", name, labels) - - return nil -} - -// hasLabels reports whether pairs contain every label in want. -func hasLabels(pairs []*dto.LabelPair, want map[string]string) bool { - for name, value := range want { - found := false - for _, pair := range pairs { - if pair.GetName() == name && pair.GetValue() == value { - found = true - break - } - } - if !found { - return false - } - } - - return true -} diff --git a/internal/ttools/metrics.go b/internal/ttools/metrics.go index 23b07ee3..47c44fe5 100644 --- a/internal/ttools/metrics.go +++ b/internal/ttools/metrics.go @@ -5,6 +5,7 @@ import ( "testing" "github.com/prometheus/client_golang/prometheus" + dto "github.com/prometheus/client_model/go" ) // MetricFamilyNames is every metric family the process publishes right now, @@ -36,3 +37,87 @@ func MetricFamilyNames(t *testing.T) []string { return names } + +// Histogram returns the one sample of the named histogram family whose labels +// include every pair in labels. +// +// Shared for the reason MetricFamilyNames is: three tests in three packages +// read a histogram back out of a registry to assert what an observation +// recorded, and the family-then-label walk was otherwise written out in each. +// +// gatherer rather than the default registry, because a test asserting on +// exemplars usually wants a registry of its own — the default one is +// process-wide and accumulates whatever else the binary registered. +func Histogram(t *testing.T, gatherer prometheus.Gatherer, name string, labels map[string]string) *dto.Histogram { + t.Helper() + + families, err := gatherer.Gather() + if err != nil { + t.Fatalf("gather: %v", err) + } + + for _, family := range families { + if family.GetName() != name { + continue + } + + for _, metric := range family.GetMetric() { + if hasLabels(metric.GetLabel(), labels) { + return metric.GetHistogram() + } + } + } + + t.Fatalf("no sample of %v matches %v", name, labels) + + return nil +} + +// ExemplarLabels returns the labels of the exemplar on the first bucket of that +// histogram to carry one — the trace and span a traced observation named. +// +// Fatal when no bucket carries one: every caller is asserting that an exemplar +// was attached, and "absent" and "attached with the wrong labels" are different +// failures worth different messages. Use Histogram directly to assert the +// opposite, that nothing was attached. +func ExemplarLabels(t *testing.T, gatherer prometheus.Gatherer, name string, labels map[string]string) map[string]string { + t.Helper() + + histogram := Histogram(t, gatherer, name, labels) + + for _, bucket := range histogram.GetBucket() { + exemplar := bucket.GetExemplar() + if exemplar == nil { + continue + } + + got := make(map[string]string, len(exemplar.GetLabel())) + for _, pair := range exemplar.GetLabel() { + got[pair.GetName()] = pair.GetValue() + } + + return got + } + + t.Fatalf("no bucket of %v matching %v carries an exemplar", name, labels) + + return nil +} + +// hasLabels reports whether pairs contain every label in want. +func hasLabels(pairs []*dto.LabelPair, want map[string]string) bool { + for name, value := range want { + found := false + for _, pair := range pairs { + if pair.GetName() == name && pair.GetValue() == value { + found = true + break + } + } + if !found { + return false + } + } + + return true +} diff --git a/observability/prometheus/README.md b/observability/prometheus/README.md index ab7b1710..88d602b6 100644 --- a/observability/prometheus/README.md +++ b/observability/prometheus/README.md @@ -66,11 +66,25 @@ quietly on its own: Then a bucket with a dot on it is one click from the trace. **Two limits.** Exemplars are not pushed: a `push_url` deployment goes through -the classic text format to a Pushgateway, which has no notion of them. And -negotiating OpenMetrics changed the `le` label spelling — a boundary that looks -like an integer gains a trailing `.0`, so `le="1"` is now `le="1.0"` on the 1, -2.5 and 5 boundaries of the cache families and the 1, 5 and 10 of the HTTP one. -Anything matching an exact `le` needs checking. +the classic text format to a Pushgateway, which has no notion of them. + +And negotiating OpenMetrics changed the `le` label spelling — a boundary that +renders as a whole number gains a trailing `.0`, so `le="1"` is now `le="1.0"`, +which is a different series. The format is negotiated per scrape rather than +per family, so this reaches the size histograms too even though they carry no +exemplars: + +| Family | Respelled | +|:---|:---| +| `shigola_cache_duration_seconds`, `shigola_cache_tier_duration_seconds` | `1`, `5` | +| `shigola_api_duration_seconds` | `1`, `5`, `10` | +| `shigola_cache_response_size_bytes`, `shigola_cache_tier_response_size_bytes` | `1024`, `5120`, `25600`, `102400`, `256000`, `512000` | +| `shigola_api_response_size_bytes` | `512000` | + +`2.5` is untouched, because it already contains a `.`, and so are the megabyte +boundaries, which render as `1.048576e+06` and `5.24288e+06`. +`TestRespelledBucketBoundaries` derives this list from the bucket sets, so it +cannot drift from them. Anything matching an exact `le` needs checking. ### Metrics exposed diff --git a/observability/prometheus/exemplar.go b/observability/prometheus/exemplar.go index b44de1fd..e9b5a3d3 100644 --- a/observability/prometheus/exemplar.go +++ b/observability/prometheus/exemplar.go @@ -2,10 +2,8 @@ package prometheus import ( "context" - "net/http" "github.com/prometheus/client_golang/prometheus" - "github.com/prometheus/client_golang/prometheus/promhttp" "go.opentelemetry.io/otel/trace" "github.com/MapColonies/shigola/internal/log" @@ -86,31 +84,3 @@ func observeWithExemplar(obs prometheus.Observer, seconds float64, exemplar prom obs.Observe(seconds) } - -// metricsHandler serves the metrics route, negotiating OpenMetrics. -// -// EnableOpenMetrics is what makes the exemplars this package records reach -// Prometheus at all: OpenMetrics is the only exposition format that encodes -// them, and the classic text format drops them without a word. Recording -// exemplars while serving the default handler would have been a change with no -// observable effect whatsoever. -// -// It changes one other thing, which is the cost of the feature. Under -// OpenMetrics a bucket boundary that would otherwise look like an integer is -// written with a trailing ".0", so a histogram exposes le="1.0" where it used -// to expose le="1" — and a label value is part of a series' identity. The -// affected boundaries are 1, 2.5 and 5 on the cache families and 1, 5 and 10 on -// the HTTP one. Anything matching an exact le — a recording rule, a dashboard -// panel that pins one bucket — has to be checked against the new spelling. The -// alternative was to record exemplars nobody could scrape. -// -// Split out from Handler so a test can scrape a registry of its own: the -// exposition is the half of exemplar support that fails silently, and asserting -// on it against the process-wide default registry would depend on whatever else -// the test binary had registered. -func metricsHandler(registerer prometheus.Registerer, gatherer prometheus.Gatherer) http.Handler { - return promhttp.InstrumentMetricHandler( - registerer, - promhttp.HandlerFor(gatherer, promhttp.HandlerOpts{EnableOpenMetrics: true}), - ) -} diff --git a/observability/prometheus/exemplar_internal_test.go b/observability/prometheus/exemplar_internal_test.go index 592c179b..05f6cf6f 100644 --- a/observability/prometheus/exemplar_internal_test.go +++ b/observability/prometheus/exemplar_internal_test.go @@ -8,12 +8,12 @@ import ( "testing" "github.com/prometheus/client_golang/prometheus" - dto "github.com/prometheus/client_model/go" "go.opentelemetry.io/otel/trace" tegolaCache "github.com/MapColonies/shigola/cache" "github.com/MapColonies/shigola/internal/fakelog" "github.com/MapColonies/shigola/internal/faketier" + "github.com/MapColonies/shigola/internal/ttools" ) // The trace fixture comes from internal/fakelog rather than internal/faketracer @@ -24,6 +24,9 @@ import ( var exemplarKey = &tegolaCache.Key{MapName: "osm", Z: 6, X: 5, Y: 4} +// The label set a cache built with no observe-vars records a read under. +var getLabels = map[string]string{"sub_command": "get"} + // TestExemplarFromContext covers the three ways there is nothing to point at // and the one way there is. func TestExemplarFromContext(t *testing.T) { @@ -115,7 +118,8 @@ func TestCacheDurationCarriesTheExemplar(t *testing.T) { //nolint:errcheck // a miss; the exemplar on the duration observation is the subject c.Get(fakelog.TracedContext(true), exemplarKey) - if got := exemplarTraceID(t, registry, "test_exemplar_cache_duration_seconds"); got != fakelog.TraceIDHex { + exemplar := ttools.ExemplarLabels(t, registry, "test_exemplar_cache_duration_seconds", getLabels) + if got := exemplar[exemplarTraceIDKey]; got != fakelog.TraceIDHex { t.Fatalf("cache duration exemplar names trace %q, want %q", got, fakelog.TraceIDHex) } } @@ -130,7 +134,7 @@ func TestCacheDurationOutsideATraceHasNoExemplar(t *testing.T) { //nolint:errcheck // as above c.Get(context.Background(), exemplarKey) - histogram := gatherHistogram(t, registry, "test_plain_cache_duration_seconds") + histogram := ttools.Histogram(t, registry, "test_plain_cache_duration_seconds", getLabels) if histogram.GetSampleCount() != 1 { t.Fatalf("sample count = %d, want the observation to have been recorded anyway", histogram.GetSampleCount()) } @@ -156,7 +160,9 @@ func TestHTTPDurationCarriesTheExemplar(t *testing.T) { WithContext(fakelog.TracedContext(true)) instrumented.ServeHTTP(httptest.NewRecorder(), request) - if got := exemplarTraceID(t, registry, "test_exemplar_api_duration_seconds"); got != fakelog.TraceIDHex { + exemplar := ttools.ExemplarLabels(t, registry, "test_exemplar_api_duration_seconds", + map[string]string{"handler": "/collections/osm/tiles"}) + if got := exemplar[exemplarTraceIDKey]; got != fakelog.TraceIDHex { t.Fatalf("http duration exemplar names trace %q, want %q", got, fakelog.TraceIDHex) } } @@ -197,50 +203,3 @@ func TestExemplarReachesTheExposition(t *testing.T) { t.Fatalf("the exposition does not contain %q; exemplars are recorded but never scraped", want) } } - -// gatherHistogram reads one histogram out of a registry by family name. -func gatherHistogram(t *testing.T, gatherer prometheus.Gatherer, name string) *dto.Histogram { - t.Helper() - - families, err := gatherer.Gather() - if err != nil { - t.Fatalf("gather: %v", err) - } - - for _, family := range families { - if family.GetName() != name { - continue - } - if metrics := family.GetMetric(); len(metrics) > 0 { - return metrics[0].GetHistogram() - } - } - - t.Fatalf("no %v in the registry", name) - - return nil -} - -// exemplarTraceID returns the trace id on the first bucket of the named -// histogram that carries an exemplar. -func exemplarTraceID(t *testing.T, gatherer prometheus.Gatherer, name string) string { - t.Helper() - - histogram := gatherHistogram(t, gatherer, name) - - for _, bucket := range histogram.GetBucket() { - exemplar := bucket.GetExemplar() - if exemplar == nil { - continue - } - for _, pair := range exemplar.GetLabel() { - if pair.GetName() == exemplarTraceIDKey { - return pair.GetValue() - } - } - } - - t.Fatalf("no bucket of %v carries an exemplar labelled %v", name, exemplarTraceIDKey) - - return "" -} diff --git a/observability/prometheus/http.go b/observability/prometheus/http.go index ecb9f1eb..ec634d2a 100644 --- a/observability/prometheus/http.go +++ b/observability/prometheus/http.go @@ -64,12 +64,10 @@ func newHttpHandler(registry prometheus.Registerer, prefix string, URLPrefix str []string{}, ) - // registerOrReuse, not MustRegister, for the reason its own comment gives: - // the registry is process-wide, so a second observer — a second - // SetObservability, or a test building one of its own — registers these - // same four families again. MustRegister panics on that, which made - // constructing two observers in one process fatal. newCache has always gone - // through registerOrReuse; this constructor was simply missed. + // Through registerOrReuse, for the reason its own doc comment gives — a + // second observer in the same process re-registers these four families, and + // MustRegister panics on that. newCache has always done this; this + // constructor was simply missed. handler.inFlightGauge = registerOrReuse(registry, handler.inFlightGauge) handler.counter = registerOrReuse(registry, handler.counter) handler.durationSeconds = registerOrReuse(registry, handler.durationSeconds) diff --git a/observability/prometheus/openmetrics_le_internal_test.go b/observability/prometheus/openmetrics_le_internal_test.go new file mode 100644 index 00000000..faed473b --- /dev/null +++ b/observability/prometheus/openmetrics_le_internal_test.go @@ -0,0 +1,96 @@ +package prometheus + +import ( + "bytes" + "strconv" + "testing" +) + +// This file is the evidence for a claim the docs make and an operator acts on: +// which bucket boundaries are respelled by serving OpenMetrics, and therefore +// which `le` series change identity. Getting that list wrong understates an +// upgrade break, so it is derived here rather than worked out by hand. +// +// openMetricsFloat reproduces expfmt.writeOpenMetricsFloat, which is +// unexported: shortest 'g' formatting, with ".0" appended when the result +// contains neither "." nor "e". +func openMetricsFloat(f float64) string { + switch { + case f == 1: + return "1.0" + case f == 0: + return "0.0" + case f == -1: + return "-1.0" + } + + b := strconv.AppendFloat(nil, f, 'g', -1, 64) + if !bytes.ContainsAny(b, "e.") { + b = append(b, '.', '0') + } + + return string(b) +} + +// classicFloat is expfmt.writeFloat, the format served before OpenMetrics. +func classicFloat(f float64) string { + return strconv.FormatFloat(f, 'g', -1, 64) +} + +// TestRespelledBucketBoundaries lists every boundary whose `le` label changed, +// so the set the docs name can be compared against the set that exists. +// +// The rule catches integer-looking values only, which is narrower than it +// first appears: 2.5 already contains a ".", and 5242880 renders as +// "5.24288e+06" and already contains an "e". It is also *not* confined to the +// duration families — the response-size boundaries are whole numbers of bytes +// and nearly all of them are respelled. +func TestRespelledBucketBoundaries(t *testing.T) { + families := map[string][]float64{ + "shigola_cache{,_tier}_duration_seconds": cacheDurationBuckets, + "shigola_api_duration_seconds": httpHandlerDurationBuckets, + "shigola_cache{,_tier}_response_size_bytes": cacheResponseSizeBuckets, + "shigola_api_response_size_bytes": httpHandlerResponseSizeBuckets, + } + + want := map[string][]string{ + "shigola_cache{,_tier}_duration_seconds": {"1 -> 1.0", "5 -> 5.0"}, + "shigola_api_duration_seconds": {"1 -> 1.0", "5 -> 5.0", "10 -> 10.0"}, + "shigola_cache{,_tier}_response_size_bytes": {"1024 -> 1024.0", "5120 -> 5120.0", "25600 -> 25600.0", "102400 -> 102400.0", "256000 -> 256000.0", "512000 -> 512000.0", "1.048576e+06 -> unchanged", "5.24288e+06 -> unchanged"}, + "shigola_api_response_size_bytes": {"512000 -> 512000.0", "1.048576e+06 -> unchanged", "5.24288e+06 -> unchanged"}, + } + + fn := func(buckets []float64, want []string) func(*testing.T) { + return func(t *testing.T) { + var changed []string + for _, le := range buckets { + before, after := classicFloat(le), openMetricsFloat(le) + if before != after { + changed = append(changed, before+" -> "+after) + } + } + + // Only the respellings are compared; the "unchanged" entries above + // record the two that surprise, and are dropped here. + var wantChanged []string + for _, entry := range want { + if !bytes.Contains([]byte(entry), []byte("unchanged")) { + wantChanged = append(wantChanged, entry) + } + } + + if len(changed) != len(wantChanged) { + t.Fatalf("respelled boundaries = %v, documented %v", changed, wantChanged) + } + for i := range changed { + if changed[i] != wantChanged[i] { + t.Errorf("respelled boundary %d = %q, documented %q", i, changed[i], wantChanged[i]) + } + } + } + } + + for name, buckets := range families { + t.Run(name, fn(buckets, want[name])) + } +} diff --git a/observability/prometheus/prometheus.go b/observability/prometheus/prometheus.go index d4c42a76..e2f8cc8a 100644 --- a/observability/prometheus/prometheus.go +++ b/observability/prometheus/prometheus.go @@ -18,6 +18,7 @@ import ( "github.com/MapColonies/shigola/internal/log" "github.com/MapColonies/shigola/observability" "github.com/prometheus/client_golang/prometheus" + "github.com/prometheus/client_golang/prometheus/promhttp" ) type byteSize uint64 @@ -132,8 +133,7 @@ func New(config dict.Dicter) (observability.Interface, error) { func (*observer) Name() string { return Name } -// Handler serves the metrics route. See metricsHandler for why the exposition -// format is not the client's default. +// Handler serves the metrics route. // // A pointer receiver like every sibling. It was a value receiver, which copied // the observer's sync.Once fields on every call — a vet copylocks finding, and @@ -142,6 +142,38 @@ func (*observer) Handler(string) http.Handler { return metricsHandler(prometheus.DefaultRegisterer, prometheus.DefaultGatherer) } +// metricsHandler serves the metrics route, negotiating OpenMetrics. +// +// EnableOpenMetrics is what makes the exemplars this package records reach +// Prometheus at all: OpenMetrics is the only exposition format that encodes +// them, and the classic text format drops them without a word. Recording +// exemplars while serving the default handler would have been a change with no +// observable effect whatsoever. +// +// It changes one other thing, which is the cost of the feature. Under +// OpenMetrics a boundary that renders as a whole number is written with a +// trailing ".0", so a histogram exposes le="1.0" where it used to expose +// le="1" — and a label value is part of a series' identity, so those are +// different series. Which boundaries those are is easy to get wrong in both +// directions, so TestRespelledBucketBoundaries derives the list: 1 and 5 on the +// duration families and 10 as well on the HTTP one, plus every response-size +// boundary from 1024 up to 512000. 2.5 is untouched because it already contains +// a ".", and the megabyte boundaries because they render as 1.048576e+06 and +// 5.24288e+06. Anything matching an exact le — a recording rule, a panel +// pinned to one bucket — has to be checked. The alternative was to record +// exemplars nobody could scrape. +// +// Split out from Handler so a test can scrape a registry of its own: the +// exposition is the half of exemplar support that fails silently, and asserting +// on it against the process-wide default registry would depend on whatever else +// the test binary had registered. +func metricsHandler(registerer prometheus.Registerer, gatherer prometheus.Gatherer) http.Handler { + return promhttp.InstrumentMetricHandler( + registerer, + promhttp.HandlerFor(gatherer, promhttp.HandlerOpts{EnableOpenMetrics: true}), + ) +} + func (obs *observer) Init() { obs.initCall.Do(obs.init) } func (obs *observer) init() { obs.PublishBuildInfo() diff --git a/server/http_exemplar_test.go b/server/http_exemplar_test.go index 847fefe2..18d63444 100644 --- a/server/http_exemplar_test.go +++ b/server/http_exemplar_test.go @@ -3,7 +3,6 @@ package server_test import ( "net/http" "net/url" - "strings" "testing" promclient "github.com/prometheus/client_golang/prometheus" @@ -11,6 +10,7 @@ import ( "github.com/MapColonies/shigola/dict" "github.com/MapColonies/shigola/internal/faketracer" + "github.com/MapColonies/shigola/internal/ttools" "github.com/MapColonies/shigola/observability/prometheus" "github.com/MapColonies/shigola/server" ) @@ -25,6 +25,12 @@ import ( // whichever ran last. const exemplarTileURI = "/collections/test-map/tiles/WebMercatorQuad/11/3/2" +// exemplarHandlerLabel is exemplarTileURI as the observer labels it: the route +// variables named in the observer's default observe-vars keep their value, and +// the tile row and column are collapsed back to their names, because a label +// per tile is a cardinality explosion rather than a metric. +const exemplarHandlerLabel = "/collections/test-map/tiles/WebMercatorQuad/11/:tile_row/:tile_col" + // TestRequestExemplarNamesTheRequestSpan is the HTTP half of MAPCO-11496, and // the regression test for the middleware order server.NewRouter documents. // @@ -57,7 +63,8 @@ func TestRequestExemplarNamesTheRequestSpan(t *testing.T) { root := rootSpan(t, exporter) - exemplar := httpExemplar(t, "shigola_api_duration_seconds", "/11/") + exemplar := ttools.ExemplarLabels(t, promclient.DefaultGatherer, "shigola_api_duration_seconds", + map[string]string{"handler": exemplarHandlerLabel}) if got, want := exemplar["trace_id"], root.SpanContext.TraceID().String(); got != want { t.Errorf("request exemplar trace_id = %q, want %q", got, want) @@ -85,52 +92,3 @@ func rootSpan(t *testing.T, exporter *tracetest.InMemoryExporter) tracetest.Span return roots[0] } - -// httpExemplar returns the exemplar labels off the api duration histogram whose -// handler label contains match. -func httpExemplar(t *testing.T, name, match string) map[string]string { - t.Helper() - - families, err := promclient.DefaultGatherer.Gather() - if err != nil { - t.Fatalf("gather: %v", err) - } - - for _, family := range families { - if family.GetName() != name { - continue - } - - for _, metric := range family.GetMetric() { - handler := "" - for _, pair := range metric.GetLabel() { - if pair.GetName() == "handler" { - handler = pair.GetValue() - } - } - if !strings.Contains(handler, match) { - continue - } - - for _, bucket := range metric.GetHistogram().GetBucket() { - exemplar := bucket.GetExemplar() - if exemplar == nil { - continue - } - - got := make(map[string]string, len(exemplar.GetLabel())) - for _, pair := range exemplar.GetLabel() { - got[pair.GetName()] = pair.GetValue() - } - - return got - } - - t.Fatalf("no bucket of %v{handler~%q} carries an exemplar", name, match) - } - } - - t.Fatalf("no sample of %v has a handler label containing %q", name, match) - - return nil -} diff --git a/tracing/README.md b/tracing/README.md index e5bcdf30..900bc7da 100644 --- a/tracing/README.md +++ b/tracing/README.md @@ -309,13 +309,26 @@ which `TestExemplarFitsTheRuneLimit` guards by making a real observation. Two consequences worth knowing: -- **`le` label values changed.** Under OpenMetrics a bucket boundary that would - otherwise look like an integer is written with a trailing `.0`, and a label - value is part of a series' identity — so `le="1"` is now `le="1.0"`. The - affected boundaries are 1, 2.5 and 5 on the cache families and 1, 5 and 10 on - the HTTP one. Anything pinning an exact `le` — a recording rule, a panel - showing one bucket — has to be checked against the new spelling. This was the - price of exemplars being scrapeable at all. +- **`le` label values changed.** Under OpenMetrics a boundary that renders as a + whole number is written with a trailing `.0`, and a label value is part of a + series' identity — so `le="1"` is now `le="1.0"`, a different series. + `TestRespelledBucketBoundaries` derives the list rather than leaving it to be + worked out, because it is narrower than the rule sounds in one direction and + wider in another: + + | Family | Respelled | + |:---|:---| + | `shigola_cache_duration_seconds`, `..._tier_...` | `1`, `5` | + | `shigola_api_duration_seconds` | `1`, `5`, `10` | + | `shigola_cache_response_size_bytes`, `..._tier_...` | `1024`, `5120`, `25600`, `102400`, `256000`, `512000` | + | `shigola_api_response_size_bytes` | `512000` | + + `2.5` is untouched — it already contains a `.` — and so are the megabyte + boundaries, which render as `1.048576e+06` and `5.24288e+06`. The size + families are affected even though they carry no exemplars, because the format + is negotiated per scrape rather than per family. Anything pinning an exact + `le` has to be checked. This was the price of exemplars being scrapeable at + all. - **Pushed metrics carry no exemplars.** A deployment using `push_url` pushes through the classic text format to a Pushgateway, which has no notion of exemplars. Everything above applies to scraped deployments only. From 19f1044f7df09c85f096525eb7e0635b6939180e Mon Sep 17 00:00:00 2001 From: Niv Greenstein <88280771+NivGreenstein@users.noreply.github.com> Date: Wed, 9 Sep 2026 18:17:52 +0300 Subject: [PATCH 07/27] fix(test): stop TestTracedRequestPublishesNoNewMetrics racing a detached write MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit It failed 4 runs in 6 on origin/development, reporting shigola_cache_hits_total as a family tracing had published. The cause is in its own warm-up: it made two requests against an empty cache expecting the first request's write to make the second a hit, but every cache write goes through the bounded pool off the response path, so the second request races that write. When it lost, both requests missed, the hit families were never published before the snapshot, and the traced request got the blame. The warm-up is now one request against a durable tier that was seeded directly — the hot tier still misses, so the hit and miss families are both published, with nothing asynchronous in the path. 8 runs in 8 green. Seeding needs the cache key, which is easy to get subtly wrong: the tile row and column are the other way round from X and Y, and a wrong key would seed a tile nothing reads and reintroduce the race silently. So the key is asserted against what a tier is actually asked for, and swapping X and Y fails the test by name rather than by flaking. Pre-existing and unrelated to exemplars; fixed here because it makes this branch's CI red for reasons that are not this branch's. Co-Authored-By: Claude Opus 5 (1M context) --- server/http_exemplar_test.go | 3 +- server/tracing_test.go | 81 ++++++++++++++++++++++++++---------- 2 files changed, 62 insertions(+), 22 deletions(-) diff --git a/server/http_exemplar_test.go b/server/http_exemplar_test.go index 18d63444..85e02242 100644 --- a/server/http_exemplar_test.go +++ b/server/http_exemplar_test.go @@ -45,7 +45,8 @@ func TestRequestExemplarNamesTheRequestSpan(t *testing.T) { server.URIPrefix = "/" a := newTestMapWithLayers(testLayer2) - a.SetCache(twoTierCache(t, "exemplarhot", "exemplardurable")) + c, _, _ := twoTierCache(t, "exemplarhot", "exemplardurable") + a.SetCache(c) observer, err := prometheus.New(dict.Dict{}) if err != nil { diff --git a/server/tracing_test.go b/server/tracing_test.go index 5b03e726..edd0157a 100644 --- a/server/tracing_test.go +++ b/server/tracing_test.go @@ -27,15 +27,29 @@ import ( // like tracing being unwired. const tracedTileURI = "/collections/test-map/tiles/WebMercatorQuad/10/3/2" +// tracedTileKey is tracedTileURI as the cache addresses it — the whole map, so +// no layer name, and tileRow/tileCol the other way round from X/Y. +// +// seedDurableTier asserts it against the key a tier is actually asked for +// rather than trusting it: seeding the wrong key would leave the tile +// unreadable and silently reintroduce the race it exists to remove. +var tracedTileKey = &cache.Key{ + TileMatrixSetID: "WebMercatorQuad", + MapName: "test-map", + Z: 10, + X: 2, + Y: 3, +} + // twoTierCache builds hot → durable through cache.For, so the request walks the -// same decorator stack it would in production. -func twoTierCache(t *testing.T, hotType, durableType string) cache.Interface { +// same decorator stack it would in production. The tiers come back so a caller +// can seed one — see seededTwoTierCache. +func twoTierCache(t *testing.T, hotType, durableType string) (cache.Interface, *faketier.Tier, *faketier.Tier) { t.Helper() - for cacheType, tier := range map[string]*faketier.Tier{ - hotType: faketier.New(hotType), - durableType: faketier.New(durableType), - } { + hot, durable := faketier.New(hotType), faketier.New(durableType) + + for cacheType, tier := range map[string]*faketier.Tier{hotType: hot, durableType: durable} { c := tier if err := cache.Register(cacheType, func(dict.Dicter) (cache.Interface, error) { return c, nil }); err != nil { t.Fatalf("register %v: %v", cacheType, err) @@ -52,7 +66,23 @@ func twoTierCache(t *testing.T, hotType, durableType string) cache.Interface { t.Fatalf("building the chain: %v", err) } - return c + return c, hot, durable +} + +// assertSeededKeyWasRead fails if the tile a request looked for is not the one +// seedDurableTier seeded, which is the only way seeding could quietly stop +// working. +func assertSeededKeyWasRead(t *testing.T, calls []faketier.Call) { + t.Helper() + + for _, call := range calls { + if call.Op == faketier.OpGet && call.Key == tracedTileKey.String() { + return + } + } + + t.Fatalf("no tier was asked for %v; the seeded key is wrong and this test is racing a detached write again", + tracedTileKey.String()) } // TestTileRequestProducesOneSpanTree is the acceptance criterion end to end: a @@ -72,7 +102,8 @@ func TestTileRequestProducesOneSpanTree(t *testing.T) { tracer, exporter := faketracer.New(t) a := newTestMapWithLayers(testLayer2) - a.SetCache(twoTierCache(t, "tracedhot", "traceddurable")) + c, _, _ := twoTierCache(t, "tracedhot", "traceddurable") + a.SetCache(c) a.SetTracing(tracer) w, _, err := doRequest(t, a, http.MethodGet, tracedTileURI, nil) @@ -150,7 +181,8 @@ func TestTileRequestWithoutTracingRecordsNothing(t *testing.T) { _, exporter := faketracer.New(t) a := newTestMapWithLayers(testLayer2) - a.SetCache(twoTierCache(t, "untracedhot", "untraceddurable")) + c, _, _ := twoTierCache(t, "untracedhot", "untraceddurable") + a.SetCache(c) w, _, err := doRequest(t, a, http.MethodGet, tracedTileURI, nil) if err != nil { @@ -182,7 +214,9 @@ func TestTracedRequestPublishesNoNewMetrics(t *testing.T) { server.URIPrefix = "/" a := newTestMapWithLayers(testLayer2) - a.SetCache(twoTierCache(t, "metrichot", "metricdurable")) + c, hot, durable := twoTierCache(t, "metrichot", "metricdurable") + durable.Seed(tracedTileKey, []byte("tile")) + a.SetCache(c) observer, err := prometheus.New(dict.Dict{}) if err != nil { @@ -190,22 +224,27 @@ func TestTracedRequestPublishesNoNewMetrics(t *testing.T) { } a.SetObservability(observer) - // Two untraced requests before the snapshot, not one. + // One untraced request before the snapshot, against a cache that is + // already warm. // // A prometheus *Vec publishes a family only once a label set on it has // been observed, so the snapshot has to be taken in a state where every - // family the traced request will touch already exists. One request is not - // enough: the first is a miss on an empty cache and populates only the - // misses families, and it then writes the tile — so the second is a hit - // and publishes shigola_cache_hits_total and its per-tier sibling for the - // first time. Snapshotting after one request blames tracing for the cache - // warming up. - for range 2 { - if _, _, err := doRequest(t, a, http.MethodGet, tracedTileURI, nil); err != nil { - t.Fatalf("untraced request: %v", err) - } + // family the traced request will touch already exists — otherwise the + // cache warming up is blamed on tracing. Against a seeded durable tier one + // request does it: the hot tier misses and the durable one hits, so the + // hit and miss families are both published, and the traced request has the + // same shape. + // + // This used to be two requests against an empty cache, relying on the + // first request's write making the second a hit. Writes are detached + // through the bounded pool, so that was a race, and it lost often enough + // to fail this test roughly half the time on the trunk. + if _, _, err := doRequest(t, a, http.MethodGet, tracedTileURI, nil); err != nil { + t.Fatalf("untraced request: %v", err) } + assertSeededKeyWasRead(t, hot.Calls()) + before := ttools.MetricFamilyNames(t) httpBefore := map[string]float64{} for _, family := range []string{ From 89d5334c0601f02bf415f4b6b7463fd03bcf07ca Mon Sep 17 00:00:00 2001 From: Niv Greenstein <88280771+NivGreenstein@users.noreply.github.com> Date: Thu, 10 Sep 2026 10:01:32 +0300 Subject: [PATCH 08/27] fix: correct the pushed-metrics claim, and act on a second review MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Three docs said a push_url deployment sends "the classic text format to a Pushgateway, which has no notion of exemplars". Both halves are wrong as stated: push.New defaults to expfmt.FmtProtoDelim and nothing here overrides it, and protobuf does carry exemplars — (*histogram).Write fills in dto.Bucket.Exemplar. They now say what is actually verifiable from this tree: the exemplars go out on the wire, what the Pushgateway does with them is its own business and untested here, and push_url is documented for ephemeral jobs rather than the serving path. A comment and a README also pointed at atlas.TestTierExemplarNamesTheTierSpan, which 26bae129 renamed. Rationale comments are load-bearing here, so a pointer to a test that does not exist is worse than none. ttools.ExemplarLabels now takes the newest exemplar by timestamp rather than the first bucket carrying one. That was a genuine flake, not a tidy-up: prometheus keeps one exemplar per bucket, a family on the process-wide registry outlives the test that observed into it, and the two rows of the atlas table both observe the whole-cache family — so under -race, where the spread between two observations is wide enough to put them in different buckets, a row could read its sibling's trace. It failed 1 run in 6; 10 in 10 after, and both ordering mutation checks still fail as they should. Also from the review: the untraced HTTP path had no assertion, though the two paths attach their exemplar through entirely different machinery, so the cache half proved nothing about it; the respelled-le table becomes one tcase map in the repo's usual shape rather than two parallel maps; the atlas table dispatches on a field instead of comparing a family name inside the shared closure; and spanForTier and rootSpan move to internal/faketracer, which already owns the span lookups. Left alone deliberately: the root-span walk in tracing_test.go builds three tallies in one pass, and pulling one out would fragment it. Co-Authored-By: Claude Opus 5 (1M context) --- atlas/cache_trace_exemplar_test.go | 32 +++---- internal/faketracer/faketracer.go | 43 +++++++++ internal/ttools/metrics.go | 34 +++++-- observability/prometheus/README.md | 16 +++- observability/prometheus/exemplar.go | 2 +- .../prometheus/exemplar_internal_test.go | 27 ++++++ .../openmetrics_le_internal_test.go | 91 +++++++++++++------ server/http_exemplar_test.go | 21 +---- tracing/README.md | 13 ++- 9 files changed, 192 insertions(+), 87 deletions(-) diff --git a/atlas/cache_trace_exemplar_test.go b/atlas/cache_trace_exemplar_test.go index 43274d22..c3eb28fd 100644 --- a/atlas/cache_trace_exemplar_test.go +++ b/atlas/cache_trace_exemplar_test.go @@ -37,6 +37,10 @@ func TestExemplarNamesTheSpanThatMeasuredIt(t *testing.T) { 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) { @@ -67,11 +71,13 @@ func TestExemplarNamesTheSpanThatMeasuredIt(t *testing.T) { t.Errorf("exemplar span_id = %q, want %q", got, want) } - // The specific inversion the ordering prevents, named so a failure - // says which way round it went wrong. + if !tc.rejectCacheSpan { + return + } + + // Named so a failure says which way round it went wrong. whole := faketracer.SpanNamed(t, exporter, tracing.SpanCacheGet) - if tc.family == "shigola_cache_tier_duration_seconds" && - exemplar["span_id"] == whole.SpanContext.SpanID().String() { + if exemplar["span_id"] == whole.SpanContext.SpanID().String() { t.Error("tier exemplar names the cache-wide span; the metric wrapper is outside the tracing one") } } @@ -83,8 +89,9 @@ func TestExemplarNamesTheSpanThatMeasuredIt(t *testing.T) { 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 spanForTier(t, exporter, "exhot1") + return faketracer.TierSpan(t, exporter, "exhot1") }, + rejectCacheSpan: true, }, "the chain as a whole": { hotType: "exhot2", durableType: "exdurable2", @@ -100,18 +107,3 @@ func TestExemplarNamesTheSpanThatMeasuredIt(t *testing.T) { t.Run(name, fn(tc)) } } - -// spanForTier returns the tier span carrying the given tier name. -func spanForTier(t *testing.T, exporter *tracetest.InMemoryExporter, tier string) tracetest.SpanStub { - t.Helper() - - for _, span := range faketracer.SpansNamed(exporter, tracing.SpanTierGet) { - if faketracer.StringAttr(span, tracing.AttrCacheTier) == tier { - return span - } - } - - t.Fatalf("no %v span carries tier %v", tracing.SpanTierGet, tier) - - return tracetest.SpanStub{} -} diff --git a/internal/faketracer/faketracer.go b/internal/faketracer/faketracer.go index 43a7c8b6..a9378a7c 100644 --- a/internal/faketracer/faketracer.go +++ b/internal/faketracer/faketracer.go @@ -125,3 +125,46 @@ func Int64Attr(span tracetest.SpanStub, key attribute.Key) int64 { return -1 } + +// TierSpan returns the cache-tier span carrying the given tier name. +// +// Here rather than in the tests that need it because two of them do — atlas +// asserting a tier exemplar, atlas asserting the tier span tree — and because +// the lookup is two facts about this package's own data: the span name a tier +// read takes, and the attribute the tier name lands in. +func TierSpan(t *testing.T, exporter *tracetest.InMemoryExporter, tier string) tracetest.SpanStub { + t.Helper() + + for _, span := range SpansNamed(exporter, tracing.SpanTierGet) { + if StringAttr(span, tracing.AttrCacheTier) == tier { + return span + } + } + + t.Fatalf("no %v span carries tier %v", tracing.SpanTierGet, 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 means something started a sibling trace instead of joining this +// one — which is the failure the propagation tests exist to catch. +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] +} diff --git a/internal/ttools/metrics.go b/internal/ttools/metrics.go index 47c44fe5..aea85b0f 100644 --- a/internal/ttools/metrics.go +++ b/internal/ttools/metrics.go @@ -73,8 +73,18 @@ func Histogram(t *testing.T, gatherer prometheus.Gatherer, name string, labels m return nil } -// ExemplarLabels returns the labels of the exemplar on the first bucket of that -// histogram to carry one — the trace and span a traced observation named. +// ExemplarLabels returns the labels of the most recently stored exemplar on +// that histogram — the trace and span the caller's own observation named. +// +// "Most recently stored", not "the first bucket that has one", and the +// difference is a real test failure rather than a nicety. Prometheus keeps one +// exemplar *per bucket*, and a family on the process-wide registry outlives the +// test that observed into it — so two tests observing the same family leave two +// exemplars behind whenever their observations land in different buckets, and +// the lower bucket's is whichever happened to be faster rather than whichever +// was later. Taking the newest by timestamp makes a caller read back what it +// just recorded; scanning bucket order made that flaky under -race, where the +// spread between two observations is wide enough to separate them. // // Fatal when no bucket carries one: every caller is asserting that an exemplar // was attached, and "absent" and "attached with the wrong labels" are different @@ -85,23 +95,29 @@ func ExemplarLabels(t *testing.T, gatherer prometheus.Gatherer, name string, lab histogram := Histogram(t, gatherer, name, labels) + var newest *dto.Exemplar for _, bucket := range histogram.GetBucket() { exemplar := bucket.GetExemplar() if exemplar == nil { continue } - - got := make(map[string]string, len(exemplar.GetLabel())) - for _, pair := range exemplar.GetLabel() { - got[pair.GetName()] = pair.GetValue() + if newest == nil || exemplar.GetTimestamp().AsTime().After(newest.GetTimestamp().AsTime()) { + newest = exemplar } + } - return got + if newest == nil { + t.Fatalf("no bucket of %v matching %v carries an exemplar", name, labels) + + return nil } - t.Fatalf("no bucket of %v matching %v carries an exemplar", name, labels) + got := make(map[string]string, len(newest.GetLabel())) + for _, pair := range newest.GetLabel() { + got[pair.GetName()] = pair.GetValue() + } - return nil + return got } // hasLabels reports whether pairs contain every label in want. diff --git a/observability/prometheus/README.md b/observability/prometheus/README.md index 88d602b6..3d861b68 100644 --- a/observability/prometheus/README.md +++ b/observability/prometheus/README.md @@ -65,11 +65,17 @@ quietly on its own: Then a bucket with a dot on it is one click from the trace. -**Two limits.** Exemplars are not pushed: a `push_url` deployment goes through -the classic text format to a Pushgateway, which has no notion of them. - -And negotiating OpenMetrics changed the `le` label spelling — a boundary that -renders as a whole number gains a trailing `.0`, so `le="1"` is now `le="1.0"`, +**On pushed metrics.** A `push_url` deployment does not go through the +exposition format above at all: `push.New` defaults to protobuf +(`expfmt.FmtProtoDelim`) and nothing here overrides it. Protobuf *can* carry +exemplars — `(*histogram).Write` fills in `dto.Bucket.Exemplar` — so they are on +the wire, and whether they are stored and re-exposed is the Pushgateway's own +business rather than anything this repo decides. Untested here either way. Note +that `push_url` is documented above for ephemeral jobs such as `shigola cache +seed`, which is not the latency-spike-to-trace workflow this section is about. + +**The `le` label spelling changed.** Negotiating OpenMetrics respells a +boundary that renders as a whole number with a trailing `.0`, so `le="1"` is now `le="1.0"`, which is a different series. The format is negotiated per scrape rather than per family, so this reaches the size histograms too even though they carry no exemplars: diff --git a/observability/prometheus/exemplar.go b/observability/prometheus/exemplar.go index e9b5a3d3..4dc2a570 100644 --- a/observability/prometheus/exemplar.go +++ b/observability/prometheus/exemplar.go @@ -51,7 +51,7 @@ const ( // histogram names the request — rather than both resolving to whatever span // happened to be open. Without the span id that ordering would make no // observable difference, which is why it is asserted rather than assumed: -// atlas.TestTierExemplarNamesTheTierSpan. +// atlas.TestExemplarNamesTheSpanThatMeasuredIt. func exemplarFrom(ctx context.Context) prometheus.Labels { sc := trace.SpanContextFromContext(ctx) if !sc.IsValid() || !sc.IsSampled() { diff --git a/observability/prometheus/exemplar_internal_test.go b/observability/prometheus/exemplar_internal_test.go index 05f6cf6f..1a5e8ef4 100644 --- a/observability/prometheus/exemplar_internal_test.go +++ b/observability/prometheus/exemplar_internal_test.go @@ -167,6 +167,33 @@ func TestHTTPDurationCarriesTheExemplar(t *testing.T) { } } +// TestHTTPDurationOutsideATraceHasNoExemplar is the request half of the same +// acceptance criterion the cache half above covers. Worth both: the two paths +// attach their exemplar through entirely different machinery — one calls +// ObserveWithExemplar itself, the other hands the hook to promhttp — so +// neither's behaviour outside a trace tells you the other's. +func TestHTTPDurationOutsideATraceHasNoExemplar(t *testing.T) { + registry := prometheus.NewRegistry() + handler := newHttpHandler(registry, "test_plain_api", "", nil) + + instrumented := handler.InstrumentedHttpHandler(http.MethodGet, "/collections/osm/tiles", + http.HandlerFunc(func(w http.ResponseWriter, _ *http.Request) { w.WriteHeader(http.StatusOK) })) + + instrumented.ServeHTTP(httptest.NewRecorder(), + httptest.NewRequest(http.MethodGet, "/collections/osm/tiles", nil)) + + histogram := ttools.Histogram(t, registry, "test_plain_api_duration_seconds", + map[string]string{"handler": "/collections/osm/tiles"}) + if histogram.GetSampleCount() != 1 { + t.Fatalf("sample count = %d, want the observation to have been recorded anyway", histogram.GetSampleCount()) + } + for _, bucket := range histogram.GetBucket() { + if bucket.GetExemplar() != nil { + t.Fatalf("bucket le=%v carries an exemplar outside a trace", bucket.GetUpperBound()) + } + } +} + // TestExemplarReachesTheExposition is the one that would have made every other // test in this file worthless. // diff --git a/observability/prometheus/openmetrics_le_internal_test.go b/observability/prometheus/openmetrics_le_internal_test.go index faed473b..b56dec56 100644 --- a/observability/prometheus/openmetrics_le_internal_test.go +++ b/observability/prometheus/openmetrics_le_internal_test.go @@ -46,51 +46,86 @@ func classicFloat(f float64) string { // duration families — the response-size boundaries are whole numbers of bytes // and nearly all of them are respelled. func TestRespelledBucketBoundaries(t *testing.T) { - families := map[string][]float64{ - "shigola_cache{,_tier}_duration_seconds": cacheDurationBuckets, - "shigola_api_duration_seconds": httpHandlerDurationBuckets, - "shigola_cache{,_tier}_response_size_bytes": cacheResponseSizeBuckets, - "shigola_api_response_size_bytes": httpHandlerResponseSizeBuckets, + type tcase struct { + buckets []float64 + // respelled is every boundary whose le label changed, as + // "before -> after". unchanged records the boundaries that surprise by + // *not* changing, so the reason is written down next to the list it is + // absent from. + respelled []string + unchanged []string } - want := map[string][]string{ - "shigola_cache{,_tier}_duration_seconds": {"1 -> 1.0", "5 -> 5.0"}, - "shigola_api_duration_seconds": {"1 -> 1.0", "5 -> 5.0", "10 -> 10.0"}, - "shigola_cache{,_tier}_response_size_bytes": {"1024 -> 1024.0", "5120 -> 5120.0", "25600 -> 25600.0", "102400 -> 102400.0", "256000 -> 256000.0", "512000 -> 512000.0", "1.048576e+06 -> unchanged", "5.24288e+06 -> unchanged"}, - "shigola_api_response_size_bytes": {"512000 -> 512000.0", "1.048576e+06 -> unchanged", "5.24288e+06 -> unchanged"}, - } - - fn := func(buckets []float64, want []string) func(*testing.T) { + fn := func(tc tcase) func(*testing.T) { return func(t *testing.T) { var changed []string - for _, le := range buckets { + for _, le := range tc.buckets { before, after := classicFloat(le), openMetricsFloat(le) if before != after { changed = append(changed, before+" -> "+after) } } - // Only the respellings are compared; the "unchanged" entries above - // record the two that surprise, and are dropped here. - var wantChanged []string - for _, entry := range want { - if !bytes.Contains([]byte(entry), []byte("unchanged")) { - wantChanged = append(wantChanged, entry) + if len(changed) != len(tc.respelled) { + t.Fatalf("respelled boundaries = %v, documented %v", changed, tc.respelled) + } + for i := range changed { + if changed[i] != tc.respelled[i] { + t.Errorf("respelled boundary %d = %q, documented %q", i, changed[i], tc.respelled[i]) } } - if len(changed) != len(wantChanged) { - t.Fatalf("respelled boundaries = %v, documented %v", changed, wantChanged) - } - for i := range changed { - if changed[i] != wantChanged[i] { - t.Errorf("respelled boundary %d = %q, documented %q", i, changed[i], wantChanged[i]) + for _, le := range tc.unchanged { + if got := openMetricsFloat(mustParse(t, le)); got != le { + t.Errorf("%v was documented as unchanged but is written %q", le, got) } } } } - for name, buckets := range families { - t.Run(name, fn(buckets, want[name])) + tests := map[string]tcase{ + "shigola_cache{,_tier}_duration_seconds": { + buckets: cacheDurationBuckets, + respelled: []string{"1 -> 1.0", "5 -> 5.0"}, + // 2.5 already contains a ".", which is the whole rule. + unchanged: []string{"2.5"}, + }, + "shigola_api_duration_seconds": { + buckets: httpHandlerDurationBuckets, + respelled: []string{"1 -> 1.0", "5 -> 5.0", "10 -> 10.0"}, + unchanged: []string{"2.5"}, + }, + "shigola_cache{,_tier}_response_size_bytes": { + buckets: cacheResponseSizeBuckets, + respelled: []string{ + "1024 -> 1024.0", "5120 -> 5120.0", "25600 -> 25600.0", + "102400 -> 102400.0", "256000 -> 256000.0", "512000 -> 512000.0", + }, + // The megabyte boundaries render in exponent form, so they already + // contain an "e". This is why the list stops at 512000. + unchanged: []string{"1.048576e+06", "5.24288e+06"}, + }, + "shigola_api_response_size_bytes": { + buckets: httpHandlerResponseSizeBuckets, + respelled: []string{"512000 -> 512000.0"}, + unchanged: []string{"1.048576e+06", "5.24288e+06"}, + }, } + + for name, tc := range tests { + t.Run(name, fn(tc)) + } +} + +// mustParse reads a boundary back out of its rendered form, so the unchanged +// lists above can be written the way the exposition writes them. +func mustParse(t *testing.T, s string) float64 { + t.Helper() + + f, err := strconv.ParseFloat(s, 64) + if err != nil { + t.Fatalf("parsing %q: %v", s, err) + } + + return f } diff --git a/server/http_exemplar_test.go b/server/http_exemplar_test.go index 85e02242..996d9b93 100644 --- a/server/http_exemplar_test.go +++ b/server/http_exemplar_test.go @@ -6,7 +6,6 @@ import ( "testing" promclient "github.com/prometheus/client_golang/prometheus" - "go.opentelemetry.io/otel/sdk/trace/tracetest" "github.com/MapColonies/shigola/dict" "github.com/MapColonies/shigola/internal/faketracer" @@ -62,7 +61,7 @@ func TestRequestExemplarNamesTheRequestSpan(t *testing.T) { t.Fatalf("traced request: %v", err) } - root := rootSpan(t, exporter) + root := faketracer.RootSpan(t, exporter) exemplar := ttools.ExemplarLabels(t, promclient.DefaultGatherer, "shigola_api_duration_seconds", map[string]string{"handler": exemplarHandlerLabel}) @@ -75,21 +74,3 @@ func TestRequestExemplarNamesTheRequestSpan(t *testing.T) { t.Errorf("request exemplar span_id = %q, want the request span %q", got, want) } } - -// rootSpan returns the one recorded span with no parent. -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 — the request", len(roots)) - } - - return roots[0] -} diff --git a/tracing/README.md b/tracing/README.md index 900bc7da..facf26b2 100644 --- a/tracing/README.md +++ b/tracing/README.md @@ -296,7 +296,7 @@ ones at both seams — `atlas.instrumentCache` and `server.NewRouter`, each with comment saying so. A slow bucket on the per-tier histogram therefore names the tier read that was slow, not the request as a whole. Inverting either order leaves the span tree unchanged, so it is pinned by the exemplar instead: -`atlas.TestTierExemplarNamesTheTierSpan` and +`atlas.TestExemplarNamesTheSpanThatMeasuredIt` and `server.TestRequestExemplarNamesTheRequestSpan` both fail on it, and say which way round it went wrong. @@ -329,9 +329,14 @@ Two consequences worth knowing: is negotiated per scrape rather than per family. Anything pinning an exact `le` has to be checked. This was the price of exemplars being scrapeable at all. -- **Pushed metrics carry no exemplars.** A deployment using `push_url` pushes - through the classic text format to a Pushgateway, which has no notion of - exemplars. Everything above applies to scraped deployments only. +- **Pushed metrics are a different path, and an unverified one.** A `push_url` + deployment never reaches the exposition format above: `push.New` defaults to + protobuf (`expfmt.FmtProtoDelim`) and nothing here overrides it. Protobuf + does carry exemplars — `(*histogram).Write` fills in `dto.Bucket.Exemplar` — + so they go out on the wire, and whether the Pushgateway stores and re-exposes + them is its business, not this repo's. Nothing here tests it. `push_url` is + in any case documented for ephemeral jobs such as `shigola cache seed`, + rather than for the serving path this section is about. ## Costs when disabled From fa1f839343692a994e697ab1c5ac13e62c01bcc5 Mon Sep 17 00:00:00 2001 From: Niv Greenstein <88280771+NivGreenstein@users.noreply.github.com> Date: Thu, 10 Sep 2026 11:06:13 +0300 Subject: [PATCH 09/27] docs(observability): stop restating the respelled-le list a fourth time MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The comment on metricsHandler enumerated the boundaries in prose alongside the two READMEs and the test that derives them — and the previous version of that same comment is where the wrong "2.5" claim survived longest. It now says what the change is and points at the test and the README for which boundaries it touches. ttools.Histogram becomes HistogramSample: it reads as a constructor but returns one label-matched sample. Co-Authored-By: Claude Opus 5 (1M context) --- internal/ttools/metrics.go | 8 ++++---- .../prometheus/exemplar_internal_test.go | 4 ++-- observability/prometheus/prometheus.go | 16 ++++++++-------- 3 files changed, 14 insertions(+), 14 deletions(-) diff --git a/internal/ttools/metrics.go b/internal/ttools/metrics.go index aea85b0f..672f08b9 100644 --- a/internal/ttools/metrics.go +++ b/internal/ttools/metrics.go @@ -38,7 +38,7 @@ func MetricFamilyNames(t *testing.T) []string { return names } -// Histogram returns the one sample of the named histogram family whose labels +// HistogramSample returns the one sample of the named histogram family whose labels // include every pair in labels. // // Shared for the reason MetricFamilyNames is: three tests in three packages @@ -48,7 +48,7 @@ func MetricFamilyNames(t *testing.T) []string { // gatherer rather than the default registry, because a test asserting on // exemplars usually wants a registry of its own — the default one is // process-wide and accumulates whatever else the binary registered. -func Histogram(t *testing.T, gatherer prometheus.Gatherer, name string, labels map[string]string) *dto.Histogram { +func HistogramSample(t *testing.T, gatherer prometheus.Gatherer, name string, labels map[string]string) *dto.Histogram { t.Helper() families, err := gatherer.Gather() @@ -88,12 +88,12 @@ func Histogram(t *testing.T, gatherer prometheus.Gatherer, name string, labels m // // Fatal when no bucket carries one: every caller is asserting that an exemplar // was attached, and "absent" and "attached with the wrong labels" are different -// failures worth different messages. Use Histogram directly to assert the +// failures worth different messages. Use HistogramSample directly to assert the // opposite, that nothing was attached. func ExemplarLabels(t *testing.T, gatherer prometheus.Gatherer, name string, labels map[string]string) map[string]string { t.Helper() - histogram := Histogram(t, gatherer, name, labels) + histogram := HistogramSample(t, gatherer, name, labels) var newest *dto.Exemplar for _, bucket := range histogram.GetBucket() { diff --git a/observability/prometheus/exemplar_internal_test.go b/observability/prometheus/exemplar_internal_test.go index 1a5e8ef4..b85b3066 100644 --- a/observability/prometheus/exemplar_internal_test.go +++ b/observability/prometheus/exemplar_internal_test.go @@ -134,7 +134,7 @@ func TestCacheDurationOutsideATraceHasNoExemplar(t *testing.T) { //nolint:errcheck // as above c.Get(context.Background(), exemplarKey) - histogram := ttools.Histogram(t, registry, "test_plain_cache_duration_seconds", getLabels) + histogram := ttools.HistogramSample(t, registry, "test_plain_cache_duration_seconds", getLabels) if histogram.GetSampleCount() != 1 { t.Fatalf("sample count = %d, want the observation to have been recorded anyway", histogram.GetSampleCount()) } @@ -182,7 +182,7 @@ func TestHTTPDurationOutsideATraceHasNoExemplar(t *testing.T) { instrumented.ServeHTTP(httptest.NewRecorder(), httptest.NewRequest(http.MethodGet, "/collections/osm/tiles", nil)) - histogram := ttools.Histogram(t, registry, "test_plain_api_duration_seconds", + histogram := ttools.HistogramSample(t, registry, "test_plain_api_duration_seconds", map[string]string{"handler": "/collections/osm/tiles"}) if histogram.GetSampleCount() != 1 { t.Fatalf("sample count = %d, want the observation to have been recorded anyway", histogram.GetSampleCount()) diff --git a/observability/prometheus/prometheus.go b/observability/prometheus/prometheus.go index e2f8cc8a..e7cbad0d 100644 --- a/observability/prometheus/prometheus.go +++ b/observability/prometheus/prometheus.go @@ -154,14 +154,14 @@ func (*observer) Handler(string) http.Handler { // OpenMetrics a boundary that renders as a whole number is written with a // trailing ".0", so a histogram exposes le="1.0" where it used to expose // le="1" — and a label value is part of a series' identity, so those are -// different series. Which boundaries those are is easy to get wrong in both -// directions, so TestRespelledBucketBoundaries derives the list: 1 and 5 on the -// duration families and 10 as well on the HTTP one, plus every response-size -// boundary from 1024 up to 512000. 2.5 is untouched because it already contains -// a ".", and the megabyte boundaries because they render as 1.048576e+06 and -// 5.24288e+06. Anything matching an exact le — a recording rule, a panel -// pinned to one bucket — has to be checked. The alternative was to record -// exemplars nobody could scrape. +// different series. Anything matching an exact le, such as a recording rule or +// a panel pinned to one bucket, has to be checked. +// +// Which boundaries those are is deliberately not written out here. +// TestRespelledBucketBoundaries derives the list from the bucket sets, and +// README.md § "Trace exemplars" states it for operators — a prose copy in a +// third place is how the previous version of this comment came to name a +// boundary that is not affected at all. // // Split out from Handler so a test can scrape a registry of its own: the // exposition is the half of exemplar support that fails silently, and asserting From d615316df42970a7ac9a82e71712cdcd0d6e4fb4 Mon Sep 17 00:00:00 2001 From: Niv Greenstein <88280771+NivGreenstein@users.noreply.github.com> Date: Thu, 10 Sep 2026 16:39:29 +0300 Subject: [PATCH 10/27] test: derive the respelled le list from the encoders instead of copying the rule MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The test reimplemented expfmt's unexported writeOpenMetricsFloat and said it "reproduces" it — which put the docs one vendored change away from being wrong with the test still green, and the copy had silently dropped that function's NaN and ±Inf cases. It now registers each bucket set, scrapes it under both exposition formats, and reports the boundaries the two spell differently. Nothing here knows the rule, so a change to it fails by naming the boundary that moved. The four rows are unchanged, which is independent confirmation that the hand-derived table was right. go.mod: client_model moves to the direct require block. internal/ttools now imports it, making this the only first-party importer, and `go mod tidy` in a container agrees — that one line, nothing else, and tidy is a no-op after. Also: the two "outside a trace" tests had identical bodies, now one helper asserting both halves of the criterion — nothing attached, and the observation still recorded. And ttools' comment claimed a gatherer parameter existed because such tests "usually want a registry of its own", while two of three callers pass the default one; it now says why both are needed. Co-Authored-By: Claude Opus 5 (1M context) --- go.mod | 2 +- internal/ttools/metrics.go | 8 +- .../prometheus/exemplar_internal_test.go | 44 ++++--- .../openmetrics_le_internal_test.go | 117 ++++++++++-------- 4 files changed, 97 insertions(+), 74 deletions(-) diff --git a/go.mod b/go.mod index f72ceb76..c369de96 100644 --- a/go.mod +++ b/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 diff --git a/internal/ttools/metrics.go b/internal/ttools/metrics.go index 672f08b9..f100d283 100644 --- a/internal/ttools/metrics.go +++ b/internal/ttools/metrics.go @@ -45,9 +45,11 @@ func MetricFamilyNames(t *testing.T) []string { // read a histogram back out of a registry to assert what an observation // recorded, and the family-then-label walk was otherwise written out in each. // -// gatherer rather than the default registry, because a test asserting on -// exemplars usually wants a registry of its own — the default one is -// process-wide and accumulates whatever else the binary registered. +// gatherer rather than the default registry, because both are needed: a test +// that can build its own registry should, since the default one is +// process-wide and accumulates whatever else the binary registered, but a test +// going through atlas or a real request reaches the metrics only through the +// default registry the observer installs itself against. func HistogramSample(t *testing.T, gatherer prometheus.Gatherer, name string, labels map[string]string) *dto.Histogram { t.Helper() diff --git a/observability/prometheus/exemplar_internal_test.go b/observability/prometheus/exemplar_internal_test.go index b85b3066..6a29b335 100644 --- a/observability/prometheus/exemplar_internal_test.go +++ b/observability/prometheus/exemplar_internal_test.go @@ -134,15 +134,7 @@ func TestCacheDurationOutsideATraceHasNoExemplar(t *testing.T) { //nolint:errcheck // as above c.Get(context.Background(), exemplarKey) - histogram := ttools.HistogramSample(t, registry, "test_plain_cache_duration_seconds", getLabels) - if histogram.GetSampleCount() != 1 { - t.Fatalf("sample count = %d, want the observation to have been recorded anyway", histogram.GetSampleCount()) - } - for _, bucket := range histogram.GetBucket() { - if bucket.GetExemplar() != nil { - t.Fatalf("bucket le=%v carries an exemplar outside a trace", bucket.GetUpperBound()) - } - } + assertRecordedWithoutExemplar(t, registry, "test_plain_cache_duration_seconds", getLabels) } // TestHTTPDurationCarriesTheExemplar is the request half. The span context @@ -182,16 +174,8 @@ func TestHTTPDurationOutsideATraceHasNoExemplar(t *testing.T) { instrumented.ServeHTTP(httptest.NewRecorder(), httptest.NewRequest(http.MethodGet, "/collections/osm/tiles", nil)) - histogram := ttools.HistogramSample(t, registry, "test_plain_api_duration_seconds", + assertRecordedWithoutExemplar(t, registry, "test_plain_api_duration_seconds", map[string]string{"handler": "/collections/osm/tiles"}) - if histogram.GetSampleCount() != 1 { - t.Fatalf("sample count = %d, want the observation to have been recorded anyway", histogram.GetSampleCount()) - } - for _, bucket := range histogram.GetBucket() { - if bucket.GetExemplar() != nil { - t.Fatalf("bucket le=%v carries an exemplar outside a trace", bucket.GetUpperBound()) - } - } } // TestExemplarReachesTheExposition is the one that would have made every other @@ -230,3 +214,27 @@ func TestExemplarReachesTheExposition(t *testing.T) { t.Fatalf("the exposition does not contain %q; exemplars are recorded but never scraped", want) } } + +// assertRecordedWithoutExemplar is the acceptance criterion for an observation +// made outside a trace: recorded exactly as it would have been, carrying +// nothing. Both halves matter — a guard that dropped the observation entirely +// would satisfy "no exemplar" while losing the measurement. +// +// Shared by the cache and HTTP cases, which assert the same thing about two +// entirely different mechanisms: one calls ObserveWithExemplar itself, the +// other hands the hook to promhttp. +func assertRecordedWithoutExemplar(t *testing.T, gatherer prometheus.Gatherer, name string, labels map[string]string) { + t.Helper() + + histogram := ttools.HistogramSample(t, gatherer, name, labels) + + if histogram.GetSampleCount() != 1 { + t.Fatalf("sample count = %d, want the observation to have been recorded anyway", histogram.GetSampleCount()) + } + + for _, bucket := range histogram.GetBucket() { + if bucket.GetExemplar() != nil { + t.Fatalf("bucket le=%v carries an exemplar outside a trace", bucket.GetUpperBound()) + } + } +} diff --git a/observability/prometheus/openmetrics_le_internal_test.go b/observability/prometheus/openmetrics_le_internal_test.go index b56dec56..1cb46665 100644 --- a/observability/prometheus/openmetrics_le_internal_test.go +++ b/observability/prometheus/openmetrics_le_internal_test.go @@ -1,69 +1,95 @@ package prometheus import ( - "bytes" - "strconv" + "net/http" + "net/http/httptest" + "regexp" "testing" + + "github.com/prometheus/client_golang/prometheus" + "github.com/prometheus/client_golang/prometheus/promhttp" ) // This file is the evidence for a claim the docs make and an operator acts on: // which bucket boundaries are respelled by serving OpenMetrics, and therefore // which `le` series change identity. Getting that list wrong understates an -// upgrade break, so it is derived here rather than worked out by hand. +// upgrade break — the first version of these docs named a boundary that is not +// affected at all — so it is derived rather than worked out by hand. // -// openMetricsFloat reproduces expfmt.writeOpenMetricsFloat, which is -// unexported: shortest 'g' formatting, with ".0" appended when the result -// contains neither "." nor "e". -func openMetricsFloat(f float64) string { - switch { - case f == 1: - return "1.0" - case f == 0: - return "0.0" - case f == -1: - return "-1.0" - } +// Derived by *scraping both encoders* rather than by reimplementing the rule +// they apply. An earlier version of this test copied expfmt's unexported +// writeOpenMetricsFloat, which put the docs one vendored change away from being +// wrong with the test still green; the copy also silently dropped that +// function's NaN and ±Inf cases. Nothing here knows the rule, so a change to it +// shows up as a failure naming the boundary that moved. + +// lePattern pulls the le label out of an exposition line. +var lePattern = regexp.MustCompile(`le="([^"]+)"`) + +// scrapeLabels serves a registry in one exposition format and returns the le +// label values it wrote, in bucket order. +func scrapeLabels(t *testing.T, registry *prometheus.Registry, openMetrics bool) []string { + t.Helper() - b := strconv.AppendFloat(nil, f, 'g', -1, 64) - if !bytes.ContainsAny(b, "e.") { - b = append(b, '.', '0') + request := httptest.NewRequest(http.MethodGet, "/metrics", nil) + if openMetrics { + // The one Accept header that reaches the OpenMetrics encoder in this + // vendored expfmt, which negotiates version 0.0.1 only. + request.Header.Set("Accept", "application/openmetrics-text;version=0.0.1") } - return string(b) -} + recorder := httptest.NewRecorder() + promhttp.HandlerFor(registry, promhttp.HandlerOpts{EnableOpenMetrics: openMetrics}). + ServeHTTP(recorder, request) + + var labels []string + for _, match := range lePattern.FindAllStringSubmatch(recorder.Body.String(), -1) { + labels = append(labels, match[1]) + } -// classicFloat is expfmt.writeFloat, the format served before OpenMetrics. -func classicFloat(f float64) string { - return strconv.FormatFloat(f, 'g', -1, 64) + return labels } -// TestRespelledBucketBoundaries lists every boundary whose `le` label changed, -// so the set the docs name can be compared against the set that exists. -// -// The rule catches integer-looking values only, which is narrower than it -// first appears: 2.5 already contains a ".", and 5242880 renders as -// "5.24288e+06" and already contains an "e". It is also *not* confined to the -// duration families — the response-size boundaries are whole numbers of bytes -// and nearly all of them are respelled. +// TestRespelledBucketBoundaries scrapes each bucket set under both exposition +// formats and reports every boundary the two spell differently. func TestRespelledBucketBoundaries(t *testing.T) { type tcase struct { buckets []float64 // respelled is every boundary whose le label changed, as // "before -> after". unchanged records the boundaries that surprise by - // *not* changing, so the reason is written down next to the list it is - // absent from. + // *not* changing, so the reason sits next to the list they are absent + // from. respelled []string unchanged []string } fn := func(tc tcase) func(*testing.T) { return func(t *testing.T) { + registry := prometheus.NewRegistry() + histogram := prometheus.NewHistogram(prometheus.HistogramOpts{ + Name: "test_le_seconds", + Buckets: tc.buckets, + }) + registry.MustRegister(histogram) + // One observation, so every bucket is written out. + histogram.Observe(0) + + classic := scrapeLabels(t, registry, false) + openMetrics := scrapeLabels(t, registry, true) + + if len(classic) != len(openMetrics) { + t.Fatalf("%d le labels classic, %d under OpenMetrics; the two are not comparable", + len(classic), len(openMetrics)) + } + var changed []string - for _, le := range tc.buckets { - before, after := classicFloat(le), openMetricsFloat(le) - if before != after { - changed = append(changed, before+" -> "+after) + unchanged := map[string]bool{} + for i := range classic { + if classic[i] != openMetrics[i] { + changed = append(changed, classic[i]+" -> "+openMetrics[i]) + continue } + unchanged[classic[i]] = true } if len(changed) != len(tc.respelled) { @@ -76,8 +102,8 @@ func TestRespelledBucketBoundaries(t *testing.T) { } for _, le := range tc.unchanged { - if got := openMetricsFloat(mustParse(t, le)); got != le { - t.Errorf("%v was documented as unchanged but is written %q", le, got) + if !unchanged[le] { + t.Errorf("%v was documented as unchanged but the two formats spell it differently", le) } } } @@ -116,16 +142,3 @@ func TestRespelledBucketBoundaries(t *testing.T) { t.Run(name, fn(tc)) } } - -// mustParse reads a boundary back out of its rendered form, so the unchanged -// lists above can be written the way the exposition writes them. -func mustParse(t *testing.T, s string) float64 { - t.Helper() - - f, err := strconv.ParseFloat(s, 64) - if err != nil { - t.Fatalf("parsing %q: %v", s, err) - } - - return f -} From 98c33f811fb0949922b9e33a901b2156152ef750 Mon Sep 17 00:00:00 2001 From: Niv Greenstein <88280771+NivGreenstein@users.noreply.github.com> Date: Thu, 10 Sep 2026 16:55:38 +0300 Subject: [PATCH 11/27] fix: make two faketracer comments true, and use the shared label constants MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit TierSpan's comment claimed two callers "atlas asserting a tier exemplar, atlas asserting the tier span tree". It has one: tracing_test.go wants every tier name at once for a set comparison, not one span by name, so it cannot use this and never will. RootSpan's invoked "the propagation tests", which find their roots inside a loop that also tallies names and trace ids, and which a previous review round talked me out of splitting. Both now say one caller, and why they sit here anyway. The atlas and server tests read exemplar["trace_id"] as a literal while the whole rationale for exemplar.go's constants is that one spelling serves both correlation surfaces. They now go through log.TraceIDKey and log.SpanIDKey — the same constants the exemplar labels are built from, so a rename moves the assertion with the code. tracing/README.md carried a second in-repo copy of the respelled-le table. It now points at the test that derives it and the observer README that states it, keeping the two counterintuitive parts as prose. The "63 of 128 runes" figure it quotes is asserted rather than logged, so the number cannot go stale. getLabels reads as a function; it is readLabels. Co-Authored-By: Claude Opus 5 (1M context) --- atlas/cache_trace_exemplar_test.go | 7 +++-- internal/faketracer/faketracer.go | 18 ++++++++---- .../prometheus/exemplar_internal_test.go | 16 ++++++++--- server/http_exemplar_test.go | 5 ++-- tracing/README.md | 28 ++++++++----------- 5 files changed, 42 insertions(+), 32 deletions(-) diff --git a/atlas/cache_trace_exemplar_test.go b/atlas/cache_trace_exemplar_test.go index c3eb28fd..92062166 100644 --- a/atlas/cache_trace_exemplar_test.go +++ b/atlas/cache_trace_exemplar_test.go @@ -9,6 +9,7 @@ import ( "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" ) @@ -63,11 +64,11 @@ func TestExemplarNamesTheSpanThatMeasuredIt(t *testing.T) { measured := tc.wantSpan(t, exporter) exemplar := ttools.ExemplarLabels(t, promclient.DefaultGatherer, tc.family, tc.labels) - if got, want := exemplar["trace_id"], measured.SpanContext.TraceID().String(); got != want { + if got, want := exemplar[log.TraceIDKey], measured.SpanContext.TraceID().String(); got != want { t.Errorf("exemplar trace_id = %q, want the request's trace %q", got, want) } - if got, want := exemplar["span_id"], measured.SpanContext.SpanID().String(); got != want { + if got, want := exemplar[log.SpanIDKey], measured.SpanContext.SpanID().String(); got != want { t.Errorf("exemplar span_id = %q, want %q", got, want) } @@ -77,7 +78,7 @@ func TestExemplarNamesTheSpanThatMeasuredIt(t *testing.T) { // Named so a failure says which way round it went wrong. whole := faketracer.SpanNamed(t, exporter, tracing.SpanCacheGet) - if exemplar["span_id"] == whole.SpanContext.SpanID().String() { + 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") } } diff --git a/internal/faketracer/faketracer.go b/internal/faketracer/faketracer.go index a9378a7c..d08fcf7a 100644 --- a/internal/faketracer/faketracer.go +++ b/internal/faketracer/faketracer.go @@ -128,10 +128,13 @@ func Int64Attr(span tracetest.SpanStub, key attribute.Key) int64 { // TierSpan returns the cache-tier span carrying the given tier name. // -// Here rather than in the tests that need it because two of them do — atlas -// asserting a tier exemplar, atlas asserting the tier span tree — and because -// the lookup is two facts about this package's own data: the span name a tier -// read takes, and the attribute the tier name lands in. +// One caller today, and here anyway 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, tier string) tracetest.SpanStub { t.Helper() @@ -150,8 +153,11 @@ func TierSpan(t *testing.T, exporter *tracetest.InMemoryExporter, tier string) t // not exactly one. // // "Exactly one" is the useful part: a request should root a single trace, and -// two roots means something started a sibling trace instead of joining this -// one — which is the failure the propagation tests exist to catch. +// 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() diff --git a/observability/prometheus/exemplar_internal_test.go b/observability/prometheus/exemplar_internal_test.go index 6a29b335..4d23ee1d 100644 --- a/observability/prometheus/exemplar_internal_test.go +++ b/observability/prometheus/exemplar_internal_test.go @@ -25,7 +25,7 @@ import ( var exemplarKey = &tegolaCache.Key{MapName: "osm", Z: 6, X: 5, Y: 4} // The label set a cache built with no observe-vars records a read under. -var getLabels = map[string]string{"sub_command": "get"} +var readLabels = map[string]string{"sub_command": "get"} // TestExemplarFromContext covers the three ways there is nothing to point at // and the one way there is. @@ -92,7 +92,15 @@ func TestExemplarFitsTheRuneLimit(t *testing.T) { if runes > prometheus.ExemplarMaxRunes { t.Fatalf("exemplar labels are %d runes, over the limit of %d", runes, prometheus.ExemplarMaxRunes) } - t.Logf("exemplar labels are %d of the %d runes allowed", runes, prometheus.ExemplarMaxRunes) + + // Pinned, not just logged: the exact figure is quoted in tracing/README.md + // and in the PR, and a quoted number nothing asserts is a number that goes + // stale. Change it here and there together — a rise is only a problem at + // the limit, but it should be a deliberate edit either way. + const documented = 63 + if runes != documented { + t.Errorf("exemplar labels are %d runes; tracing/README.md says %d", runes, documented) + } histogram := prometheus.NewHistogram(prometheus.HistogramOpts{ Name: "test_exemplar_limit_seconds", @@ -118,7 +126,7 @@ func TestCacheDurationCarriesTheExemplar(t *testing.T) { //nolint:errcheck // a miss; the exemplar on the duration observation is the subject c.Get(fakelog.TracedContext(true), exemplarKey) - exemplar := ttools.ExemplarLabels(t, registry, "test_exemplar_cache_duration_seconds", getLabels) + exemplar := ttools.ExemplarLabels(t, registry, "test_exemplar_cache_duration_seconds", readLabels) if got := exemplar[exemplarTraceIDKey]; got != fakelog.TraceIDHex { t.Fatalf("cache duration exemplar names trace %q, want %q", got, fakelog.TraceIDHex) } @@ -134,7 +142,7 @@ func TestCacheDurationOutsideATraceHasNoExemplar(t *testing.T) { //nolint:errcheck // as above c.Get(context.Background(), exemplarKey) - assertRecordedWithoutExemplar(t, registry, "test_plain_cache_duration_seconds", getLabels) + assertRecordedWithoutExemplar(t, registry, "test_plain_cache_duration_seconds", readLabels) } // TestHTTPDurationCarriesTheExemplar is the request half. The span context diff --git a/server/http_exemplar_test.go b/server/http_exemplar_test.go index 996d9b93..949af092 100644 --- a/server/http_exemplar_test.go +++ b/server/http_exemplar_test.go @@ -9,6 +9,7 @@ import ( "github.com/MapColonies/shigola/dict" "github.com/MapColonies/shigola/internal/faketracer" + "github.com/MapColonies/shigola/internal/log" "github.com/MapColonies/shigola/internal/ttools" "github.com/MapColonies/shigola/observability/prometheus" "github.com/MapColonies/shigola/server" @@ -66,11 +67,11 @@ func TestRequestExemplarNamesTheRequestSpan(t *testing.T) { exemplar := ttools.ExemplarLabels(t, promclient.DefaultGatherer, "shigola_api_duration_seconds", map[string]string{"handler": exemplarHandlerLabel}) - if got, want := exemplar["trace_id"], root.SpanContext.TraceID().String(); got != want { + if got, want := exemplar[log.TraceIDKey], root.SpanContext.TraceID().String(); got != want { t.Errorf("request exemplar trace_id = %q, want %q", got, want) } - if got, want := exemplar["span_id"], root.SpanContext.SpanID().String(); got != want { + if got, want := exemplar[log.SpanIDKey], root.SpanContext.SpanID().String(); got != want { t.Errorf("request exemplar span_id = %q, want the request span %q", got, want) } } diff --git a/tracing/README.md b/tracing/README.md index facf26b2..f275d5b1 100644 --- a/tracing/README.md +++ b/tracing/README.md @@ -312,23 +312,17 @@ Two consequences worth knowing: - **`le` label values changed.** Under OpenMetrics a boundary that renders as a whole number is written with a trailing `.0`, and a label value is part of a series' identity — so `le="1"` is now `le="1.0"`, a different series. - `TestRespelledBucketBoundaries` derives the list rather than leaving it to be - worked out, because it is narrower than the rule sounds in one direction and - wider in another: - - | Family | Respelled | - |:---|:---| - | `shigola_cache_duration_seconds`, `..._tier_...` | `1`, `5` | - | `shigola_api_duration_seconds` | `1`, `5`, `10` | - | `shigola_cache_response_size_bytes`, `..._tier_...` | `1024`, `5120`, `25600`, `102400`, `256000`, `512000` | - | `shigola_api_response_size_bytes` | `512000` | - - `2.5` is untouched — it already contains a `.` — and so are the megabyte - boundaries, which render as `1.048576e+06` and `5.24288e+06`. The size - families are affected even though they carry no exemplars, because the format - is negotiated per scrape rather than per family. Anything pinning an exact - `le` has to be checked. This was the price of exemplars being scrapeable at - all. + Anything pinning an exact `le`, such as a recording rule or a panel showing + one bucket, has to be checked. + + **Which boundaries, exactly, is deliberately not repeated here.** + `TestRespelledBucketBoundaries` derives the list by scraping both encoders, + and `observability/prometheus/README.md` § "Trace exemplars" states it for + operators. Two things about it are counterintuitive — `2.5` is untouched, and + the response-size families are affected despite carrying no exemplars — and a + third prose copy is how the previous version of this section came to name a + boundary that never changes at all. + - **Pushed metrics are a different path, and an unverified one.** A `push_url` deployment never reaches the exposition format above: `push.New` defaults to protobuf (`expfmt.FmtProtoDelim`) and nothing here overrides it. Protobuf From 9b617be42838ddf50727414c4b2344dcd1e989c9 Mon Sep 17 00:00:00 2001 From: Niv Greenstein <88280771+NivGreenstein@users.noreply.github.com> Date: Thu, 10 Sep 2026 17:24:50 +0300 Subject: [PATCH 12/27] refactor: finish the ttools extraction, and table the exemplar 2x2 MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit hasLabels was extracted into ttools and left one caller short: atlas's own counter() still inlined the same nested label match. It is now ttools.HasLabels, and counter is twenty lines shorter. The four duration-exemplar tests were a 2x2 — cache and HTTP, each traced and untraced — written as four functions in a package whose documented pattern is a table keyed by name. They are one table now, which also made it obvious that only the trace id was being asserted; both rows check the span too, and each row fails on the mutation it should. Handler took its registerer from the package default while the observer holds exactly that field. It reads its own now, so an observer built against another registry serves that one, with the nil guard its siblings all have — the pointer receiver taken to clear a vet finding is also a receiver that can be nil. scrapeLabels returns le values rather than labels; it is scrapeLE. Co-Authored-By: Claude Opus 5 (1M context) --- atlas/cache_observability_test.go | 17 +-- internal/ttools/metrics.go | 11 +- .../prometheus/exemplar_internal_test.go | 136 +++++++++++------- .../openmetrics_le_internal_test.go | 11 +- observability/prometheus/prometheus.go | 15 +- 5 files changed, 110 insertions(+), 80 deletions(-) diff --git a/atlas/cache_observability_test.go b/atlas/cache_observability_test.go index b85213ff..26115de1 100644 --- a/atlas/cache_observability_test.go +++ b/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 } diff --git a/internal/ttools/metrics.go b/internal/ttools/metrics.go index f100d283..7ecaaeba 100644 --- a/internal/ttools/metrics.go +++ b/internal/ttools/metrics.go @@ -64,7 +64,7 @@ func HistogramSample(t *testing.T, gatherer prometheus.Gatherer, name string, la } for _, metric := range family.GetMetric() { - if hasLabels(metric.GetLabel(), labels) { + if HasLabels(metric.GetLabel(), labels) { return metric.GetHistogram() } } @@ -122,8 +122,13 @@ func ExemplarLabels(t *testing.T, gatherer prometheus.Gatherer, name string, lab return got } -// hasLabels reports whether pairs contain every label in want. -func hasLabels(pairs []*dto.LabelPair, want map[string]string) bool { +// HasLabels reports whether pairs contain every label in want — a subset +// match, so a caller names only the labels it cares about and ignores whatever +// else the observe-vars added. +// +// Exported because the sample lookups here are not the only place that needs +// it: atlas's own counter() reader matches labels the same way. +func HasLabels(pairs []*dto.LabelPair, want map[string]string) bool { for name, value := range want { found := false for _, pair := range pairs { diff --git a/observability/prometheus/exemplar_internal_test.go b/observability/prometheus/exemplar_internal_test.go index 4d23ee1d..49ec3389 100644 --- a/observability/prometheus/exemplar_internal_test.go +++ b/observability/prometheus/exemplar_internal_test.go @@ -116,74 +116,100 @@ func TestExemplarFitsTheRuneLimit(t *testing.T) { histogram.(prometheus.ExemplarObserver).ObserveWithExemplar(0.002, labels) } -// TestCacheDurationCarriesTheExemplar is the cache half of the ticket: a tier -// read observed inside a sampled trace names it. -func TestCacheDurationCarriesTheExemplar(t *testing.T) { - registry := prometheus.NewRegistry() - tier := faketier.New("hot") - c := newCache(registry, "test_exemplar_cache", nil, tier) - - //nolint:errcheck // a miss; the exemplar on the duration observation is the subject - c.Get(fakelog.TracedContext(true), exemplarKey) - - exemplar := ttools.ExemplarLabels(t, registry, "test_exemplar_cache_duration_seconds", readLabels) - if got := exemplar[exemplarTraceIDKey]; got != fakelog.TraceIDHex { - t.Fatalf("cache duration exemplar names trace %q, want %q", got, fakelog.TraceIDHex) +// TestDurationExemplars is the ticket's two halves against its two states — +// the cache path and the HTTP path, each inside a sampled trace and outside any +// trace. +// +// One table rather than four functions because the four rows assert one claim +// between them, and the interesting comparison is down the columns: the two +// paths attach their exemplar through entirely different machinery — the cache +// calls ObserveWithExemplar itself, the HTTP side hands the hook to promhttp — +// so neither's behaviour tells you the other's, in either state. +func TestDurationExemplars(t *testing.T) { + type tcase struct { + // observe makes one duration observation against the registry, in the + // context the row is about, and returns the family and label set it + // landed on. + observe func(*testing.T, *prometheus.Registry) (string, map[string]string) + traced bool } -} -// TestCacheDurationOutsideATraceHasNoExemplar is the other acceptance -// criterion: an untraced observation records normally, with nothing attached. -func TestCacheDurationOutsideATraceHasNoExemplar(t *testing.T) { - registry := prometheus.NewRegistry() - tier := faketier.New("hot") - c := newCache(registry, "test_plain_cache", nil, tier) + fn := func(tc tcase) func(*testing.T) { + return func(t *testing.T) { + registry := prometheus.NewRegistry() - //nolint:errcheck // as above - c.Get(context.Background(), exemplarKey) + family, labels := tc.observe(t, registry) - assertRecordedWithoutExemplar(t, registry, "test_plain_cache_duration_seconds", readLabels) -} + if !tc.traced { + assertRecordedWithoutExemplar(t, registry, family, labels) -// TestHTTPDurationCarriesTheExemplar is the request half. The span context -// reaches the middleware on the request, which is how it arrives in -// production: the tracing handler is installed outside the metrics one and has -// already replaced the request by the time this runs. -func TestHTTPDurationCarriesTheExemplar(t *testing.T) { - registry := prometheus.NewRegistry() - handler := newHttpHandler(registry, "test_exemplar_api", "", nil) + return + } - instrumented := handler.InstrumentedHttpHandler(http.MethodGet, "/collections/osm/tiles", - http.HandlerFunc(func(w http.ResponseWriter, _ *http.Request) { w.WriteHeader(http.StatusOK) })) + exemplar := ttools.ExemplarLabels(t, registry, family, labels) + if got := exemplar[exemplarTraceIDKey]; got != fakelog.TraceIDHex { + t.Errorf("exemplar names trace %q, want %q", got, fakelog.TraceIDHex) + } + if got := exemplar[exemplarSpanIDKey]; got != fakelog.SpanIDHex { + t.Errorf("exemplar names span %q, want %q", got, fakelog.SpanIDHex) + } + } + } - request := httptest.NewRequest(http.MethodGet, "/collections/osm/tiles", nil). - WithContext(fakelog.TracedContext(true)) - instrumented.ServeHTTP(httptest.NewRecorder(), request) + // cacheRead observes one tier read through the metric wrapper. + cacheRead := func(prefix string, ctx context.Context) func(*testing.T, *prometheus.Registry) (string, map[string]string) { + return func(t *testing.T, registry *prometheus.Registry) (string, map[string]string) { + c := newCache(registry, prefix, nil, faketier.New("hot")) - exemplar := ttools.ExemplarLabels(t, registry, "test_exemplar_api_duration_seconds", - map[string]string{"handler": "/collections/osm/tiles"}) - if got := exemplar[exemplarTraceIDKey]; got != fakelog.TraceIDHex { - t.Fatalf("http duration exemplar names trace %q, want %q", got, fakelog.TraceIDHex) + //nolint:errcheck // a miss; the exemplar on the duration observation is the subject + c.Get(ctx, exemplarKey) + + return prefix + "_duration_seconds", readLabels + } } -} -// TestHTTPDurationOutsideATraceHasNoExemplar is the request half of the same -// acceptance criterion the cache half above covers. Worth both: the two paths -// attach their exemplar through entirely different machinery — one calls -// ObserveWithExemplar itself, the other hands the hook to promhttp — so -// neither's behaviour outside a trace tells you the other's. -func TestHTTPDurationOutsideATraceHasNoExemplar(t *testing.T) { - registry := prometheus.NewRegistry() - handler := newHttpHandler(registry, "test_plain_api", "", nil) + // request serves one request through the metrics middleware. The span + // context arrives on the request, which is how it arrives in production: + // the tracing handler is installed outside the metrics one and has already + // replaced the request by the time this runs. + request := func(prefix string, ctx context.Context) func(*testing.T, *prometheus.Registry) (string, map[string]string) { + return func(t *testing.T, registry *prometheus.Registry) (string, map[string]string) { + const route = "/collections/osm/tiles" + + handler := newHttpHandler(registry, prefix, "", nil) + instrumented := handler.InstrumentedHttpHandler(http.MethodGet, route, + http.HandlerFunc(func(w http.ResponseWriter, _ *http.Request) { w.WriteHeader(http.StatusOK) })) + + r := httptest.NewRequest(http.MethodGet, route, nil) + if ctx != nil { + r = r.WithContext(ctx) + } + instrumented.ServeHTTP(httptest.NewRecorder(), r) - instrumented := handler.InstrumentedHttpHandler(http.MethodGet, "/collections/osm/tiles", - http.HandlerFunc(func(w http.ResponseWriter, _ *http.Request) { w.WriteHeader(http.StatusOK) })) + return prefix + "_duration_seconds", map[string]string{"handler": route} + } + } - instrumented.ServeHTTP(httptest.NewRecorder(), - httptest.NewRequest(http.MethodGet, "/collections/osm/tiles", nil)) + tests := map[string]tcase{ + "a cache read in a sampled trace": { + observe: cacheRead("test_exemplar_cache", fakelog.TracedContext(true)), + traced: true, + }, + "a cache read outside any trace": { + observe: cacheRead("test_plain_cache", context.Background()), + }, + "a request in a sampled trace": { + observe: request("test_exemplar_api", fakelog.TracedContext(true)), + traced: true, + }, + "a request outside any trace": { + observe: request("test_plain_api", nil), + }, + } - assertRecordedWithoutExemplar(t, registry, "test_plain_api_duration_seconds", - map[string]string{"handler": "/collections/osm/tiles"}) + for name, tc := range tests { + t.Run(name, fn(tc)) + } } // TestExemplarReachesTheExposition is the one that would have made every other diff --git a/observability/prometheus/openmetrics_le_internal_test.go b/observability/prometheus/openmetrics_le_internal_test.go index 1cb46665..c5dee24b 100644 --- a/observability/prometheus/openmetrics_le_internal_test.go +++ b/observability/prometheus/openmetrics_le_internal_test.go @@ -26,9 +26,10 @@ import ( // lePattern pulls the le label out of an exposition line. var lePattern = regexp.MustCompile(`le="([^"]+)"`) -// scrapeLabels serves a registry in one exposition format and returns the le -// label values it wrote, in bucket order. -func scrapeLabels(t *testing.T, registry *prometheus.Registry, openMetrics bool) []string { +// scrapeLE serves a registry in one exposition format and returns the le label +// values it wrote, in bucket order. openMetrics picks the encoder; false is the +// classic text format this route served before exemplars. +func scrapeLE(t *testing.T, registry *prometheus.Registry, openMetrics bool) []string { t.Helper() request := httptest.NewRequest(http.MethodGet, "/metrics", nil) @@ -74,8 +75,8 @@ func TestRespelledBucketBoundaries(t *testing.T) { // One observation, so every bucket is written out. histogram.Observe(0) - classic := scrapeLabels(t, registry, false) - openMetrics := scrapeLabels(t, registry, true) + classic := scrapeLE(t, registry, false) + openMetrics := scrapeLE(t, registry, true) if len(classic) != len(openMetrics) { t.Fatalf("%d le labels classic, %d under OpenMetrics; the two are not comparable", diff --git a/observability/prometheus/prometheus.go b/observability/prometheus/prometheus.go index e7cbad0d..c7ac07aa 100644 --- a/observability/prometheus/prometheus.go +++ b/observability/prometheus/prometheus.go @@ -138,8 +138,19 @@ func (*observer) Name() string { return Name } // A pointer receiver like every sibling. It was a value receiver, which copied // the observer's sync.Once fields on every call — a vet copylocks finding, and // harmless only because the copy was discarded unread. -func (*observer) Handler(string) http.Handler { - return metricsHandler(prometheus.DefaultRegisterer, prometheus.DefaultGatherer) +func (obs *observer) Handler(string) http.Handler { + // The observer's own registerer, not the package default, even though New + // only ever sets it to that: an observer built against some other registry + // should serve that registry rather than quietly serving the global one. + // The gatherer has no such field to read, so it stays the default. + // + // nil-guarded like every sibling here — the pointer receiver this took to + // clear a vet copylocks finding is also a receiver that can now be nil. + if obs == nil { + return metricsHandler(prometheus.DefaultRegisterer, prometheus.DefaultGatherer) + } + + return metricsHandler(obs.registry, prometheus.DefaultGatherer) } // metricsHandler serves the metrics route, negotiating OpenMetrics. From 664a175823d881d7aec812449d2a959ec9f44b23 Mon Sep 17 00:00:00 2001 From: Niv Greenstein <88280771+NivGreenstein@users.noreply.github.com> Date: Thu, 10 Sep 2026 17:39:49 +0300 Subject: [PATCH 13/27] fix: repair three dangling comment pointers, and one overclaimed commit MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Three comments in server/tracing_test.go named seedDurableTier and seededTwoTierCache. Neither exists: the second was written and inlined again in the same change, and the comments were left behind. This is the second time this branch has done it, and 89d5334c's own message is the argument against it — "a pointer to a test that does not exist is worse than none". 9b617be4 claimed "an observer built against another registry serves that one". It did not: the registerer followed obs.registry while the gatherer stayed the package default, so such an observer would have registered its scrape counter into one registry and served another's metrics — worse than not following it at all. The gatherer now comes off the registerer, which is a *prometheus.Registry in every case this has, and that type is both. The exemplarTraceIDKey/exemplarSpanIDKey aliases were a middle man: this package's tests asserted through them while atlas and server used log.TraceIDKey directly, so "one spelling serves both correlation surfaces" was half true. The aliases are gone and the comment explaining the coupling now sits at the use site. ttools gains AssertExemplar, which is the trace-and-span compare pair that was written out in three files. Its failures name the family, and all three packages still fail when the span id is dropped. CONTRIBUTING.md said "`master` is always the most recent state of the code, and pull requests are opened against it". Since 2026-09-07 master is the rewound branch and development is the trunk, so it was telling contributors to open pull requests against a branch with no history — and it says so three lines above the mapping table this branch already edits. Co-Authored-By: Claude Opus 5 (1M context) --- CONTRIBUTING.md | 17 +++++++----- atlas/cache_trace_exemplar_test.go | 11 +++----- internal/ttools/metrics.go | 25 +++++++++++++++++ observability/prometheus/exemplar.go | 27 +++++++------------ .../prometheus/exemplar_internal_test.go | 23 +++++++--------- observability/prometheus/prometheus.go | 16 ++++++++--- server/http_exemplar_test.go | 14 +++------- server/tracing_test.go | 18 +++++++------ 8 files changed, 84 insertions(+), 67 deletions(-) diff --git a/CONTRIBUTING.md b/CONTRIBUTING.md index f702e8bc..ea77fc74 100644 --- a/CONTRIBUTING.md +++ b/CONTRIBUTING.md @@ -55,16 +55,21 @@ behaviour to this repository's maintainers. MapColonies tracks work on Shigola in the **MAPCO** Jira project, and a pull request title carries its issue key in parentheses — that is what makes the ticket findable from the pull request list and -from the squashed commit left on `master`. Contributors without access to that tracker should +from the squashed commit left on the trunk. Contributors without access to that tracker should reference the GitHub issue number instead; nothing here requires a Jira account. ## Making a change -`master` is always the most recent state of the code, and pull requests are opened against it. There -is no release-candidate branch. +**`development` is the trunk**, and pull requests are opened against it. There is no +release-candidate branch. -* **Never commit or push to `master`.** Branch as `/` — `fix/cache-histogram-buckets`, - `feat/ogc-tiles` — push the branch, and open a pull request. +GitHub's default branch is still `master`, which is *not* the trunk: on 2026-09-07 it was rewound +to the initial commit, so a pull request merged there lands on a branch with none of the project's +history in it. `gh pr create` targets it unless `--base development` is passed, so pass that +explicitly rather than relying on the default. + +* **Never commit or push to `development`, nor to the stale `master`.** Branch as `/` — + `fix/cache-histogram-buckets`, `feat/ogc-tiles` — push the branch, and open a pull request. * **Commit messages follow [Conventional Commits](https://www.conventionalcommits.org/):** `(): `, where type is one of `feat`, `fix`, `docs`, `chore`, `refactor`, `test`, `ci`, `perf`, `build`, `style`, `revert`. Subject in lowercase imperative, no @@ -91,7 +96,7 @@ is no release-candidate branch. | `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. +other work lands on `development` ahead of yours. ### Not sure where to start? diff --git a/atlas/cache_trace_exemplar_test.go b/atlas/cache_trace_exemplar_test.go index 92062166..6a834660 100644 --- a/atlas/cache_trace_exemplar_test.go +++ b/atlas/cache_trace_exemplar_test.go @@ -62,15 +62,9 @@ func TestExemplarNamesTheSpanThatMeasuredIt(t *testing.T) { } measured := tc.wantSpan(t, exporter) - exemplar := ttools.ExemplarLabels(t, promclient.DefaultGatherer, tc.family, tc.labels) - if got, want := exemplar[log.TraceIDKey], measured.SpanContext.TraceID().String(); got != want { - t.Errorf("exemplar trace_id = %q, want the request's trace %q", got, want) - } - - if got, want := exemplar[log.SpanIDKey], measured.SpanContext.SpanID().String(); got != want { - t.Errorf("exemplar span_id = %q, want %q", got, want) - } + ttools.AssertExemplar(t, promclient.DefaultGatherer, tc.family, tc.labels, + measured.SpanContext.TraceID().String(), measured.SpanContext.SpanID().String()) if !tc.rejectCacheSpan { return @@ -78,6 +72,7 @@ func TestExemplarNamesTheSpanThatMeasuredIt(t *testing.T) { // 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") } diff --git a/internal/ttools/metrics.go b/internal/ttools/metrics.go index 7ecaaeba..f58c33e5 100644 --- a/internal/ttools/metrics.go +++ b/internal/ttools/metrics.go @@ -6,6 +6,8 @@ import ( "github.com/prometheus/client_golang/prometheus" dto "github.com/prometheus/client_model/go" + + "github.com/MapColonies/shigola/internal/log" ) // MetricFamilyNames is every metric family the process publishes right now, @@ -144,3 +146,26 @@ func HasLabels(pairs []*dto.LabelPair, want map[string]string) bool { return true } + +// AssertExemplar checks that the named histogram's most recent exemplar points +// at the given trace and span. +// +// Shared because three tests in three packages make exactly this pair of +// comparisons — the prometheus observer's own against a fixed fixture, atlas's +// against the tier span the read produced, server's against the request span — +// and the label names are the load-bearing part: log.TraceIDKey and +// log.SpanIDKey are what Grafana is configured with, so a test spelling them +// itself is a test that keeps passing after a rename that broke correlation. +func AssertExemplar(t *testing.T, gatherer prometheus.Gatherer, name string, labels map[string]string, wantTrace, wantSpan string) { + t.Helper() + + exemplar := ExemplarLabels(t, gatherer, name, labels) + + if got := exemplar[log.TraceIDKey]; got != wantTrace { + t.Errorf("%v exemplar names trace %q, want %q", name, got, wantTrace) + } + + if got := exemplar[log.SpanIDKey]; got != wantSpan { + t.Errorf("%v exemplar names span %q, want %q", name, got, wantSpan) + } +} diff --git a/observability/prometheus/exemplar.go b/observability/prometheus/exemplar.go index 4dc2a570..9ca7dce9 100644 --- a/observability/prometheus/exemplar.go +++ b/observability/prometheus/exemplar.go @@ -9,21 +9,6 @@ import ( "github.com/MapColonies/shigola/internal/log" ) -// The exemplar labels. exemplarTraceIDKey is the one Grafana's Prometheus -// datasource is pointed at to reach Tempo; exemplarSpanIDKey narrows the -// landing to the operation that was actually measured. -// -// Deliberately the same constants the log records carry rather than a second -// spelling of "trace_id": the two surfaces are configured separately in Grafana -// — a derived field on the Loki datasource, an exemplar link on the Prometheus -// one — and both fail *silently* when the name is wrong. One pair of constants -// makes it impossible for a rename to fix one surface and quietly break the -// other. -const ( - exemplarTraceIDKey = log.TraceIDKey - exemplarSpanIDKey = log.SpanIDKey -) - // exemplarFrom returns the exemplar labels naming the trace active in ctx, or // nil when there is no trace worth pointing at. // @@ -58,9 +43,17 @@ func exemplarFrom(ctx context.Context) prometheus.Labels { return nil } + // log.TraceIDKey and log.SpanIDKey, not a second spelling of "trace_id". + // The exemplar link on Grafana's Prometheus datasource and the derived + // field on its Loki datasource are configured separately, and both fail + // *silently* when the name is wrong — so one pair of constants is what + // makes it impossible for a rename to fix one surface and quietly break + // the other. There is deliberately no alias for them in this package + // either: the tests here and in atlas and server all assert through these + // same two names. return prometheus.Labels{ - exemplarTraceIDKey: sc.TraceID().String(), - exemplarSpanIDKey: sc.SpanID().String(), + log.TraceIDKey: sc.TraceID().String(), + log.SpanIDKey: sc.SpanID().String(), } } diff --git a/observability/prometheus/exemplar_internal_test.go b/observability/prometheus/exemplar_internal_test.go index 49ec3389..927a27fe 100644 --- a/observability/prometheus/exemplar_internal_test.go +++ b/observability/prometheus/exemplar_internal_test.go @@ -13,6 +13,7 @@ import ( tegolaCache "github.com/MapColonies/shigola/cache" "github.com/MapColonies/shigola/internal/fakelog" "github.com/MapColonies/shigola/internal/faketier" + "github.com/MapColonies/shigola/internal/log" "github.com/MapColonies/shigola/internal/ttools" ) @@ -25,7 +26,7 @@ import ( var exemplarKey = &tegolaCache.Key{MapName: "osm", Z: 6, X: 5, Y: 4} // The label set a cache built with no observe-vars records a read under. -var readLabels = map[string]string{"sub_command": "get"} +var readOpLabels = map[string]string{"sub_command": "get"} // TestExemplarFromContext covers the three ways there is nothing to point at // and the one way there is. @@ -46,11 +47,11 @@ func TestExemplarFromContext(t *testing.T) { return } - if got[exemplarTraceIDKey] != tc.want { - t.Fatalf("exemplarFrom()[%q] = %q, want %q", exemplarTraceIDKey, got[exemplarTraceIDKey], tc.want) + if got[log.TraceIDKey] != tc.want { + t.Fatalf("exemplarFrom()[%q] = %q, want %q", log.TraceIDKey, got[log.TraceIDKey], tc.want) } - if got[exemplarSpanIDKey] != fakelog.SpanIDHex { - t.Errorf("exemplarFrom()[%q] = %q, want %q", exemplarSpanIDKey, got[exemplarSpanIDKey], fakelog.SpanIDHex) + if got[log.SpanIDKey] != fakelog.SpanIDHex { + t.Errorf("exemplarFrom()[%q] = %q, want %q", log.SpanIDKey, got[log.SpanIDKey], fakelog.SpanIDHex) } if len(got) != 2 { t.Errorf("exemplarFrom() = %v, want the trace and span ids alone", got) @@ -146,13 +147,7 @@ func TestDurationExemplars(t *testing.T) { return } - exemplar := ttools.ExemplarLabels(t, registry, family, labels) - if got := exemplar[exemplarTraceIDKey]; got != fakelog.TraceIDHex { - t.Errorf("exemplar names trace %q, want %q", got, fakelog.TraceIDHex) - } - if got := exemplar[exemplarSpanIDKey]; got != fakelog.SpanIDHex { - t.Errorf("exemplar names span %q, want %q", got, fakelog.SpanIDHex) - } + ttools.AssertExemplar(t, registry, family, labels, fakelog.TraceIDHex, fakelog.SpanIDHex) } } @@ -164,7 +159,7 @@ func TestDurationExemplars(t *testing.T) { //nolint:errcheck // a miss; the exemplar on the duration observation is the subject c.Get(ctx, exemplarKey) - return prefix + "_duration_seconds", readLabels + return prefix + "_duration_seconds", readOpLabels } } @@ -243,7 +238,7 @@ func TestExemplarReachesTheExposition(t *testing.T) { t.Fatalf("Content-Type = %q, want the OpenMetrics encoding that carries exemplars", contentType) } - want := exemplarTraceIDKey + `="` + fakelog.TraceIDHex + `"` + want := log.TraceIDKey + `="` + fakelog.TraceIDHex + `"` if body := recorder.Body.String(); !strings.Contains(body, want) { t.Fatalf("the exposition does not contain %q; exemplars are recorded but never scraped", want) } diff --git a/observability/prometheus/prometheus.go b/observability/prometheus/prometheus.go index c7ac07aa..77884f6c 100644 --- a/observability/prometheus/prometheus.go +++ b/observability/prometheus/prometheus.go @@ -139,10 +139,15 @@ func (*observer) Name() string { return Name } // the observer's sync.Once fields on every call — a vet copylocks finding, and // harmless only because the copy was discarded unread. func (obs *observer) Handler(string) http.Handler { - // The observer's own registerer, not the package default, even though New + // The observer's own registry, not the package default, even though New // only ever sets it to that: an observer built against some other registry // should serve that registry rather than quietly serving the global one. - // The gatherer has no such field to read, so it stays the default. + // + // Both halves have to follow it or it serves the wrong thing either way — + // registering its scrape counter into one registry while gathering + // another's metrics would be worse than not following it at all. There is + // no gatherer field to read, so it comes off the registerer, which is a + // *prometheus.Registry in every case this has: that type is both. // // nil-guarded like every sibling here — the pointer receiver this took to // clear a vet copylocks finding is also a receiver that can now be nil. @@ -150,7 +155,12 @@ func (obs *observer) Handler(string) http.Handler { return metricsHandler(prometheus.DefaultRegisterer, prometheus.DefaultGatherer) } - return metricsHandler(obs.registry, prometheus.DefaultGatherer) + gatherer := prometheus.DefaultGatherer + if own, ok := obs.registry.(prometheus.Gatherer); ok { + gatherer = own + } + + return metricsHandler(obs.registry, gatherer) } // metricsHandler serves the metrics route, negotiating OpenMetrics. diff --git a/server/http_exemplar_test.go b/server/http_exemplar_test.go index 949af092..9f068c4e 100644 --- a/server/http_exemplar_test.go +++ b/server/http_exemplar_test.go @@ -9,7 +9,6 @@ import ( "github.com/MapColonies/shigola/dict" "github.com/MapColonies/shigola/internal/faketracer" - "github.com/MapColonies/shigola/internal/log" "github.com/MapColonies/shigola/internal/ttools" "github.com/MapColonies/shigola/observability/prometheus" "github.com/MapColonies/shigola/server" @@ -64,14 +63,7 @@ func TestRequestExemplarNamesTheRequestSpan(t *testing.T) { root := faketracer.RootSpan(t, exporter) - exemplar := ttools.ExemplarLabels(t, promclient.DefaultGatherer, "shigola_api_duration_seconds", - map[string]string{"handler": exemplarHandlerLabel}) - - if got, want := exemplar[log.TraceIDKey], root.SpanContext.TraceID().String(); got != want { - t.Errorf("request exemplar trace_id = %q, want %q", got, want) - } - - if got, want := exemplar[log.SpanIDKey], root.SpanContext.SpanID().String(); got != want { - t.Errorf("request exemplar span_id = %q, want the request span %q", got, want) - } + ttools.AssertExemplar(t, promclient.DefaultGatherer, "shigola_api_duration_seconds", + map[string]string{"handler": exemplarHandlerLabel}, + root.SpanContext.TraceID().String(), root.SpanContext.SpanID().String()) } diff --git a/server/tracing_test.go b/server/tracing_test.go index edd0157a..197de7b5 100644 --- a/server/tracing_test.go +++ b/server/tracing_test.go @@ -30,7 +30,7 @@ const tracedTileURI = "/collections/test-map/tiles/WebMercatorQuad/10/3/2" // tracedTileKey is tracedTileURI as the cache addresses it — the whole map, so // no layer name, and tileRow/tileCol the other way round from X/Y. // -// seedDurableTier asserts it against the key a tier is actually asked for +// assertSeededKeyWasRead checks it against the key a tier is actually asked for // rather than trusting it: seeding the wrong key would leave the tile // unreadable and silently reintroduce the race it exists to remove. var tracedTileKey = &cache.Key{ @@ -43,7 +43,8 @@ var tracedTileKey = &cache.Key{ // twoTierCache builds hot → durable through cache.For, so the request walks the // same decorator stack it would in production. The tiers come back so a caller -// can seed one — see seededTwoTierCache. +// can seed one directly, which is how TestTracedRequestPublishesNoNewMetrics +// gets a warm cache without waiting on a detached write. func twoTierCache(t *testing.T, hotType, durableType string) (cache.Interface, *faketier.Tier, *faketier.Tier) { t.Helper() @@ -70,9 +71,10 @@ func twoTierCache(t *testing.T, hotType, durableType string) (cache.Interface, * } // assertSeededKeyWasRead fails if the tile a request looked for is not the one -// seedDurableTier seeded, which is the only way seeding could quietly stop -// working. -func assertSeededKeyWasRead(t *testing.T, calls []faketier.Call) { +// the caller seeded, which is the only way seeding could quietly stop working. +// +// tier names the tier whose calls these are, so a failure says where to look. +func assertSeededKeyWasRead(t *testing.T, tier string, calls []faketier.Call) { t.Helper() for _, call := range calls { @@ -81,8 +83,8 @@ func assertSeededKeyWasRead(t *testing.T, calls []faketier.Call) { } } - t.Fatalf("no tier was asked for %v; the seeded key is wrong and this test is racing a detached write again", - tracedTileKey.String()) + t.Fatalf("the %v tier was never asked for %v; the seeded key is wrong and this test is racing a detached write again", + tier, tracedTileKey.String()) } // TestTileRequestProducesOneSpanTree is the acceptance criterion end to end: a @@ -243,7 +245,7 @@ func TestTracedRequestPublishesNoNewMetrics(t *testing.T) { t.Fatalf("untraced request: %v", err) } - assertSeededKeyWasRead(t, hot.Calls()) + assertSeededKeyWasRead(t, "metrichot", hot.Calls()) before := ttools.MetricFamilyNames(t) httpBefore := map[string]float64{} From 6fc1b2948bf45e3a879a31477f8447fd33357cfe Mon Sep 17 00:00:00 2001 From: Niv Greenstein <88280771+NivGreenstein@users.noreply.github.com> Date: Mon, 14 Sep 2026 10:15:26 +0300 Subject: [PATCH 14/27] fix: the respelling reaches quantile labels, not just le MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The docs framed the OpenMetrics break as le-only, over shigola's four families. It is a property of the encoder, not of histograms: expfmt writes summary quantile labels through the same float formatter. So go_gc_duration_seconds — a Go runtime metric this package never touches and every Go process publishes — has quantile="0" respelled to "0.0" and quantile="1" to "1.0". A dashboard pinned to either was affected and the docs did not say so. TestRespelledQuantileBoundaries scrapes a real Go collector under both formats rather than reasoning about the encoder, the way the bucket list is already derived. Both READMEs and docs/tracing.md now say the break reaches past le and past this project. Handler nil-guards obs.registry as well as obs: New always sets it, but the value receiver this replaced could not have been nil either way, so the guard now covers both ways the zero value can arrive. CONTRIBUTING.md's trunk section is taken back off this branch. Correcting it was right — it told contributors to open pull requests against the rewound master — but it is its own piece of work, and the docs repo had already had exactly this done to it here (d8a8d5c). Only the docs-mapping rows, which this ticket does create, stay. The correction follows as its own branch. Co-Authored-By: Claude Opus 5 (1M context) --- CONTRIBUTING.md | 17 ++--- observability/prometheus/README.md | 12 ++- .../openmetrics_le_internal_test.go | 73 ++++++++++++++++--- observability/prometheus/prometheus.go | 5 +- tracing/README.md | 19 +++-- 5 files changed, 94 insertions(+), 32 deletions(-) diff --git a/CONTRIBUTING.md b/CONTRIBUTING.md index ea77fc74..f702e8bc 100644 --- a/CONTRIBUTING.md +++ b/CONTRIBUTING.md @@ -55,21 +55,16 @@ behaviour to this repository's maintainers. MapColonies tracks work on Shigola in the **MAPCO** Jira project, and a pull request title carries its issue key in parentheses — that is what makes the ticket findable from the pull request list and -from the squashed commit left on the trunk. Contributors without access to that tracker should +from the squashed commit left on `master`. Contributors without access to that tracker should reference the GitHub issue number instead; nothing here requires a Jira account. ## Making a change -**`development` is the trunk**, and pull requests are opened against it. There is no -release-candidate branch. +`master` is always the most recent state of the code, and pull requests are opened against it. There +is no release-candidate branch. -GitHub's default branch is still `master`, which is *not* the trunk: on 2026-09-07 it was rewound -to the initial commit, so a pull request merged there lands on a branch with none of the project's -history in it. `gh pr create` targets it unless `--base development` is passed, so pass that -explicitly rather than relying on the default. - -* **Never commit or push to `development`, nor to the stale `master`.** Branch as `/` — - `fix/cache-histogram-buckets`, `feat/ogc-tiles` — push the branch, and open a pull request. +* **Never commit or push to `master`.** Branch as `/` — `fix/cache-histogram-buckets`, + `feat/ogc-tiles` — push the branch, and open a pull request. * **Commit messages follow [Conventional Commits](https://www.conventionalcommits.org/):** `(): `, where type is one of `feat`, `fix`, `docs`, `chore`, `refactor`, `test`, `ci`, `perf`, `build`, `style`, `revert`. Subject in lowercase imperative, no @@ -96,7 +91,7 @@ explicitly rather than relying on the default. | `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 `development` ahead of yours. +other work lands on `master` ahead of yours. ### Not sure where to start? diff --git a/observability/prometheus/README.md b/observability/prometheus/README.md index 3d861b68..722b17ad 100644 --- a/observability/prometheus/README.md +++ b/observability/prometheus/README.md @@ -90,7 +90,17 @@ exemplars: `2.5` is untouched, because it already contains a `.`, and so are the megabyte boundaries, which render as `1.048576e+06` and `5.24288e+06`. `TestRespelledBucketBoundaries` derives this list from the bucket sets, so it -cannot drift from them. Anything matching an exact `le` needs checking. +cannot drift from them. + +**It is not only `le`, and not only Shigola's own metrics.** The respelling is a +property of the encoder rather than of histograms: it writes summary `quantile` +labels through the same float formatter. The Go runtime collector's +`go_gc_duration_seconds` is a summary, so `quantile="0"` becomes `quantile="0.0"` +and `quantile="1"` becomes `quantile="1.0"` — on a metric this package never +touches and that every Go process publishes. `TestRespelledQuantileBoundaries` +scrapes a real Go collector to keep that claim honest. + +Anything matching an exact `le` or `quantile` needs checking. ### Metrics exposed diff --git a/observability/prometheus/openmetrics_le_internal_test.go b/observability/prometheus/openmetrics_le_internal_test.go index c5dee24b..4d21eb0a 100644 --- a/observability/prometheus/openmetrics_le_internal_test.go +++ b/observability/prometheus/openmetrics_le_internal_test.go @@ -23,13 +23,17 @@ import ( // function's NaN and ±Inf cases. Nothing here knows the rule, so a change to it // shows up as a failure naming the boundary that moved. -// lePattern pulls the le label out of an exposition line. -var lePattern = regexp.MustCompile(`le="([^"]+)"`) +// lePattern and quantilePattern pull a bucket or quantile label out of an +// exposition line. +var ( + lePattern = regexp.MustCompile(`le="([^"]+)"`) + quantilePattern = regexp.MustCompile(`quantile="([^"]+)"`) +) -// scrapeLE serves a registry in one exposition format and returns the le label -// values it wrote, in bucket order. openMetrics picks the encoder; false is the -// classic text format this route served before exemplars. -func scrapeLE(t *testing.T, registry *prometheus.Registry, openMetrics bool) []string { +// scrapeLabel serves a registry in one exposition format and returns the values +// pattern captures, in the order they were written. openMetrics picks the +// encoder; false is the classic text format this route served before exemplars. +func scrapeLabel(t *testing.T, registry *prometheus.Registry, pattern *regexp.Regexp, openMetrics bool) []string { t.Helper() request := httptest.NewRequest(http.MethodGet, "/metrics", nil) @@ -43,12 +47,17 @@ func scrapeLE(t *testing.T, registry *prometheus.Registry, openMetrics bool) []s promhttp.HandlerFor(registry, promhttp.HandlerOpts{EnableOpenMetrics: openMetrics}). ServeHTTP(recorder, request) - var labels []string - for _, match := range lePattern.FindAllStringSubmatch(recorder.Body.String(), -1) { - labels = append(labels, match[1]) + return matches(pattern, recorder.Body.String()) +} + +// matches returns the first capture group of every match, in order. +func matches(pattern *regexp.Regexp, body string) []string { + var found []string + for _, match := range pattern.FindAllStringSubmatch(body, -1) { + found = append(found, match[1]) } - return labels + return found } // TestRespelledBucketBoundaries scrapes each bucket set under both exposition @@ -75,8 +84,8 @@ func TestRespelledBucketBoundaries(t *testing.T) { // One observation, so every bucket is written out. histogram.Observe(0) - classic := scrapeLE(t, registry, false) - openMetrics := scrapeLE(t, registry, true) + classic := scrapeLabel(t, registry, lePattern, false) + openMetrics := scrapeLabel(t, registry, lePattern, true) if len(classic) != len(openMetrics) { t.Fatalf("%d le labels classic, %d under OpenMetrics; the two are not comparable", @@ -143,3 +152,43 @@ func TestRespelledBucketBoundaries(t *testing.T) { t.Run(name, fn(tc)) } } + +// TestRespelledQuantileBoundaries is the half the bucket table misses. +// +// The respelling is a property of the OpenMetrics *encoder*, not of histograms: +// it writes summary quantile labels through the same float writer. So turning +// the format on also respells series this package never touches — including +// go_gc_duration_seconds, which every Go process publishes and which plenty of +// dashboards pin a quantile on. The docs said "le" and named only shigola's +// families until this test was written. +func TestRespelledQuantileBoundaries(t *testing.T) { + registry := prometheus.NewRegistry() + registry.MustRegister(prometheus.NewGoCollector()) + + classic := scrapeLabel(t, registry, quantilePattern, false) + openMetrics := scrapeLabel(t, registry, quantilePattern, true) + + if len(classic) == 0 { + t.Fatal("the Go collector published no quantile labels; this test proved nothing") + } + if len(classic) != len(openMetrics) { + t.Fatalf("%d quantile labels classic, %d under OpenMetrics", len(classic), len(openMetrics)) + } + + var changed []string + for i := range classic { + if classic[i] != openMetrics[i] { + changed = append(changed, classic[i]+" -> "+openMetrics[i]) + } + } + + want := []string{"0 -> 0.0", "1 -> 1.0"} + if len(changed) != len(want) { + t.Fatalf("respelled quantiles = %v, documented %v", changed, want) + } + for i := range changed { + if changed[i] != want[i] { + t.Errorf("respelled quantile %d = %q, documented %q", i, changed[i], want[i]) + } + } +} diff --git a/observability/prometheus/prometheus.go b/observability/prometheus/prometheus.go index 77884f6c..704fe3d9 100644 --- a/observability/prometheus/prometheus.go +++ b/observability/prometheus/prometheus.go @@ -151,7 +151,10 @@ func (obs *observer) Handler(string) http.Handler { // // nil-guarded like every sibling here — the pointer receiver this took to // clear a vet copylocks finding is also a receiver that can now be nil. - if obs == nil { + // obs.registry as well as obs: New always sets it, but the value receiver + // this replaced could not have been nil at all, so the guard covers both + // ways the zero value can now arrive. + if obs == nil || obs.registry == nil { return metricsHandler(prometheus.DefaultRegisterer, prometheus.DefaultGatherer) } diff --git a/tracing/README.md b/tracing/README.md index f275d5b1..01614a1f 100644 --- a/tracing/README.md +++ b/tracing/README.md @@ -315,13 +315,18 @@ Two consequences worth knowing: Anything pinning an exact `le`, such as a recording rule or a panel showing one bucket, has to be checked. - **Which boundaries, exactly, is deliberately not repeated here.** - `TestRespelledBucketBoundaries` derives the list by scraping both encoders, - and `observability/prometheus/README.md` § "Trace exemplars" states it for - operators. Two things about it are counterintuitive — `2.5` is untouched, and - the response-size families are affected despite carrying no exemplars — and a - third prose copy is how the previous version of this section came to name a - boundary that never changes at all. + **Which labels, exactly, is deliberately not repeated here.** + `TestRespelledBucketBoundaries` and `TestRespelledQuantileBoundaries` derive + the lists by scraping both encoders, and + `observability/prometheus/README.md` § "Trace exemplars" states them for + operators. A prose copy in a third place is how the previous version of this + section came to name a boundary that never changes at all. + + Two things about the scope surprise people. `2.5` is untouched, because it + already contains a `.`. And it reaches beyond `le` and beyond this project: + the encoder writes summary `quantile` labels through the same formatter, so + `go_gc_duration_seconds{quantile="0"}` — a Go runtime metric nothing here + touches — is respelled too. - **Pushed metrics are a different path, and an unverified one.** A `push_url` deployment never reaches the exposition format above: `push.New` defaults to From 3d82c7c03ab8fcf56a007acc0390b94cfb71598f Mon Sep 17 00:00:00 2001 From: Niv Greenstein <88280771+NivGreenstein@users.noreply.github.com> Date: Mon, 14 Sep 2026 10:49:06 +0300 Subject: [PATCH 15/27] test: cover cache writes and purges, and pin the detached-write span MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit observeDuration is wired into Get, Set and Purge, and the docs name all three spans, but every exemplar test observed a read. The table now has a write and a purge row. The write matters most, and it had no coverage at all: a detached write runs on the pool goroutine after its response is gone, and keeps its trace only because WritePool derives the context with WithoutCancel. TestDetachedWriteExemplar- NamesItsRequest asserts that, and it took two wrong shapes to get right — worth recording, because both looked correct and proved nothing. Asserting the whole-cache family passes with WithoutCancel removed: the detachment decorator sits inside the observability wrapper, so that observation is made synchronously on the response path where the live context is still in hand. Then asserting the tier exemplar against the tier span's own trace also passes, because a write that lost its context still gets a span — the root of a new orphaned trace, which an exemplar naming it still matches. The assertion has to be against the *request's* trace, taken from the whole-cache span. It now fails on the mutation, naming both traces. TierSpan takes the span name, so it can find a write as well as a read. Also from the review: one differ shared by both respelling tests rather than the comparison written twice, and the exposition formats are named constants instead of a bare bool. TestRespelledQuantileBoundaries uses a summary carrying the Go collector's objectives rather than the collector itself, whose constructor is deprecated in the vendored client and whose replacement is in a package this tree does not vendor — registering it to prove a fact about the encoder would have meant vendor churn on a ticket whose criteria turn on vendor/ being untouched. Co-Authored-By: Claude Opus 5 (1M context) --- atlas/cache_trace_exemplar_test.go | 68 ++++++++- internal/faketracer/faketracer.go | 9 +- .../prometheus/exemplar_internal_test.go | 46 ++++-- .../openmetrics_le_internal_test.go | 137 ++++++++++-------- 4 files changed, 186 insertions(+), 74 deletions(-) diff --git a/atlas/cache_trace_exemplar_test.go b/atlas/cache_trace_exemplar_test.go index 6a834660..4ad06a30 100644 --- a/atlas/cache_trace_exemplar_test.go +++ b/atlas/cache_trace_exemplar_test.go @@ -3,10 +3,12 @@ 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" @@ -85,7 +87,7 @@ func TestExemplarNamesTheSpanThatMeasuredIt(t *testing.T) { 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, "exhot1") + return faketracer.TierSpan(t, exporter, tracing.SpanTierGet, "exhot1") }, rejectCacheSpan: true, }, @@ -103,3 +105,67 @@ func TestExemplarNamesTheSpanThatMeasuredIt(t *testing.T) { 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()) +} diff --git a/internal/faketracer/faketracer.go b/internal/faketracer/faketracer.go index d08fcf7a..e1e9561d 100644 --- a/internal/faketracer/faketracer.go +++ b/internal/faketracer/faketracer.go @@ -126,7 +126,8 @@ func Int64Attr(span tracetest.SpanStub, key attribute.Key) int64 { return -1 } -// TierSpan returns the cache-tier span carrying the given tier name. +// TierSpan returns the span named name that carries the given tier — a read, +// a write or a purge on one tier of a chain. // // One caller today, and here anyway because the lookup is two facts about the // tracing package's own data rather than about any test: the span name a tier @@ -135,16 +136,16 @@ func Int64Attr(span tracetest.SpanStub, key attribute.Key) int64 { // // 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, tier string) tracetest.SpanStub { +func TierSpan(t *testing.T, exporter *tracetest.InMemoryExporter, name, tier string) tracetest.SpanStub { t.Helper() - for _, span := range SpansNamed(exporter, tracing.SpanTierGet) { + for _, span := range SpansNamed(exporter, name) { if StringAttr(span, tracing.AttrCacheTier) == tier { return span } } - t.Fatalf("no %v span carries tier %v", tracing.SpanTierGet, tier) + t.Fatalf("no %v span carries tier %v", name, tier) return tracetest.SpanStub{} } diff --git a/observability/prometheus/exemplar_internal_test.go b/observability/prometheus/exemplar_internal_test.go index 927a27fe..8a857220 100644 --- a/observability/prometheus/exemplar_internal_test.go +++ b/observability/prometheus/exemplar_internal_test.go @@ -25,9 +25,6 @@ import ( var exemplarKey = &tegolaCache.Key{MapName: "osm", Z: 6, X: 5, Y: 4} -// The label set a cache built with no observe-vars records a read under. -var readOpLabels = map[string]string{"sub_command": "get"} - // TestExemplarFromContext covers the three ways there is nothing to point at // and the one way there is. func TestExemplarFromContext(t *testing.T) { @@ -151,15 +148,32 @@ func TestDurationExemplars(t *testing.T) { } } - // cacheRead observes one tier read through the metric wrapper. - cacheRead := func(prefix string, ctx context.Context) func(*testing.T, *prometheus.Registry) (string, map[string]string) { + // cacheOp observes one cache operation through the metric wrapper. op names + // the sub_command the observation lands under, which is how the three are + // told apart in the exposition. + // + // The errors are ignored in all three: a miss, and two writes to a fake + // that cannot fail. The exemplar on the duration observation is the + // subject, and that is recorded either way. + cacheOp := func(prefix, op string, ctx context.Context) func(*testing.T, *prometheus.Registry) (string, map[string]string) { return func(t *testing.T, registry *prometheus.Registry) (string, map[string]string) { c := newCache(registry, prefix, nil, faketier.New("hot")) - //nolint:errcheck // a miss; the exemplar on the duration observation is the subject - c.Get(ctx, exemplarKey) + switch op { + case "get": + //nolint:errcheck + c.Get(ctx, exemplarKey) + case "set": + //nolint:errcheck + c.Set(ctx, exemplarKey, []byte("tile")) + case "purge": + //nolint:errcheck + c.Purge(ctx, exemplarKey) + default: + t.Fatalf("unknown cache op %q", op) + } - return prefix + "_duration_seconds", readOpLabels + return prefix + "_duration_seconds", map[string]string{"sub_command": op} } } @@ -187,11 +201,23 @@ func TestDurationExemplars(t *testing.T) { tests := map[string]tcase{ "a cache read in a sampled trace": { - observe: cacheRead("test_exemplar_cache", fakelog.TracedContext(true)), + observe: cacheOp("test_exemplar_cache", "get", fakelog.TracedContext(true)), traced: true, }, "a cache read outside any trace": { - observe: cacheRead("test_plain_cache", context.Background()), + observe: cacheOp("test_plain_cache", "get", context.Background()), + }, + // Set and Purge run through the same observeDuration, and the docs name + // all three spans — but every test here observed a read until these two + // rows existed. The write is the one that matters most: on the detached + // pool its observation outlives the response it belongs to. + "a cache write in a sampled trace": { + observe: cacheOp("test_exemplar_write", "set", fakelog.TracedContext(true)), + traced: true, + }, + "a cache purge in a sampled trace": { + observe: cacheOp("test_exemplar_purge", "purge", fakelog.TracedContext(true)), + traced: true, }, "a request in a sampled trace": { observe: request("test_exemplar_api", fakelog.TracedContext(true)), diff --git a/observability/prometheus/openmetrics_le_internal_test.go b/observability/prometheus/openmetrics_le_internal_test.go index 4d21eb0a..37afc1ba 100644 --- a/observability/prometheus/openmetrics_le_internal_test.go +++ b/observability/prometheus/openmetrics_le_internal_test.go @@ -4,6 +4,7 @@ import ( "net/http" "net/http/httptest" "regexp" + "strings" "testing" "github.com/prometheus/client_golang/prometheus" @@ -30,9 +31,15 @@ var ( quantilePattern = regexp.MustCompile(`quantile="([^"]+)"`) ) +// The two exposition formats, named so a call site says which it means rather +// than passing a bare true or false. +const ( + openMetricsText = true + classicText = false +) + // scrapeLabel serves a registry in one exposition format and returns the values -// pattern captures, in the order they were written. openMetrics picks the -// encoder; false is the classic text format this route served before exemplars. +// pattern captures, in the order they were written. func scrapeLabel(t *testing.T, registry *prometheus.Registry, pattern *regexp.Regexp, openMetrics bool) []string { t.Helper() @@ -60,6 +67,52 @@ func matches(pattern *regexp.Regexp, body string) []string { return found } +// respelled serves registry under both exposition formats, pairs the label +// values written by each, and returns the ones the two spell differently as +// "before -> after". +// +// The pairing is positional, which is why the lengths are checked first: the +// two encoders write the same samples in the same order, and a length mismatch +// means they no longer do, which would make every comparison below meaningless +// rather than merely wrong. +func respelled(t *testing.T, registry *prometheus.Registry, pattern *regexp.Regexp) []string { + t.Helper() + + classic := scrapeLabel(t, registry, pattern, classicText) + openMetrics := scrapeLabel(t, registry, pattern, openMetricsText) + + if len(classic) == 0 { + t.Fatal("no matching labels in the exposition; this test would prove nothing") + } + if len(classic) != len(openMetrics) { + t.Fatalf("%d labels classic, %d under OpenMetrics; the two are not comparable", + len(classic), len(openMetrics)) + } + + var changed []string + for i := range classic { + if classic[i] != openMetrics[i] { + changed = append(changed, classic[i]+" -> "+openMetrics[i]) + } + } + + return changed +} + +// assertRespelled compares what actually moved against what the docs say did. +func assertRespelled(t *testing.T, got, want []string) { + t.Helper() + + if len(got) != len(want) { + t.Fatalf("respelled = %v, documented %v", got, want) + } + for i := range got { + if got[i] != want[i] { + t.Errorf("respelled %d = %q, documented %q", i, got[i], want[i]) + } + } +} + // TestRespelledBucketBoundaries scrapes each bucket set under both exposition // formats and reports every boundary the two spell differently. func TestRespelledBucketBoundaries(t *testing.T) { @@ -84,36 +137,14 @@ func TestRespelledBucketBoundaries(t *testing.T) { // One observation, so every bucket is written out. histogram.Observe(0) - classic := scrapeLabel(t, registry, lePattern, false) - openMetrics := scrapeLabel(t, registry, lePattern, true) - - if len(classic) != len(openMetrics) { - t.Fatalf("%d le labels classic, %d under OpenMetrics; the two are not comparable", - len(classic), len(openMetrics)) - } - - var changed []string - unchanged := map[string]bool{} - for i := range classic { - if classic[i] != openMetrics[i] { - changed = append(changed, classic[i]+" -> "+openMetrics[i]) - continue - } - unchanged[classic[i]] = true - } - - if len(changed) != len(tc.respelled) { - t.Fatalf("respelled boundaries = %v, documented %v", changed, tc.respelled) - } - for i := range changed { - if changed[i] != tc.respelled[i] { - t.Errorf("respelled boundary %d = %q, documented %q", i, changed[i], tc.respelled[i]) - } - } + changed := respelled(t, registry, lePattern) + assertRespelled(t, changed, tc.respelled) for _, le := range tc.unchanged { - if !unchanged[le] { - t.Errorf("%v was documented as unchanged but the two formats spell it differently", le) + for _, entry := range changed { + if strings.HasPrefix(entry, le+" -> ") { + t.Errorf("%v was documented as unchanged but moved: %v", le, entry) + } } } } @@ -157,38 +188,26 @@ func TestRespelledBucketBoundaries(t *testing.T) { // // The respelling is a property of the OpenMetrics *encoder*, not of histograms: // it writes summary quantile labels through the same float writer. So turning -// the format on also respells series this package never touches — including +// the format on also respells series this package never touches — most visibly // go_gc_duration_seconds, which every Go process publishes and which plenty of // dashboards pin a quantile on. The docs said "le" and named only shigola's // families until this test was written. +// +// The summary here carries the Go collector's own objectives rather than +// registering the collector itself, whose constructor is deprecated in the +// vendored client and whose replacement lives in a package this tree does not +// vendor. Registering one to prove a fact about the encoder would have meant +// vendor churn on a ticket whose acceptance criteria turn on vendor/ being +// untouched. func TestRespelledQuantileBoundaries(t *testing.T) { registry := prometheus.NewRegistry() - registry.MustRegister(prometheus.NewGoCollector()) - - classic := scrapeLabel(t, registry, quantilePattern, false) - openMetrics := scrapeLabel(t, registry, quantilePattern, true) - - if len(classic) == 0 { - t.Fatal("the Go collector published no quantile labels; this test proved nothing") - } - if len(classic) != len(openMetrics) { - t.Fatalf("%d quantile labels classic, %d under OpenMetrics", len(classic), len(openMetrics)) - } - - var changed []string - for i := range classic { - if classic[i] != openMetrics[i] { - changed = append(changed, classic[i]+" -> "+openMetrics[i]) - } - } - - want := []string{"0 -> 0.0", "1 -> 1.0"} - if len(changed) != len(want) { - t.Fatalf("respelled quantiles = %v, documented %v", changed, want) - } - for i := range changed { - if changed[i] != want[i] { - t.Errorf("respelled quantile %d = %q, documented %q", i, changed[i], want[i]) - } - } + summary := prometheus.NewSummary(prometheus.SummaryOpts{ + Name: "test_quantile_seconds", + Objectives: map[float64]float64{0: 0, 0.25: 0.25, 0.5: 0.05, 0.75: 0.02, 1: 0}, + }) + registry.MustRegister(summary) + summary.Observe(0) + + assertRespelled(t, respelled(t, registry, quantilePattern), + []string{"0 -> 0.0", "1 -> 1.0"}) } From 20011b3c8566512f8c0739fc5faeee5ac14450fe Mon Sep 17 00:00:00 2001 From: Niv Greenstein <88280771+NivGreenstein@users.noreply.github.com> Date: Mon, 14 Sep 2026 13:38:22 +0300 Subject: [PATCH 16/27] fix(observability): keep Handler's registerer and gatherer on one registry MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Handler's own comment rules out serving a mismatched pair — "registering its scrape counter into one registry while gathering another's metrics would be worse than not following it at all" — and then the code did exactly that whenever the Gatherer assertion failed: the registerer followed obs.registry while the gatherer fell back to the package default. Either half alone is wrong, so fall back to both defaults or to neither. The assertion holds for every registry New can produce, so nothing observable changes; what changes is that the branch which does run no longer contradicts the paragraph above it. Co-Authored-By: Claude Opus 5 (1M context) --- observability/prometheus/prometheus.go | 13 +++++++++---- 1 file changed, 9 insertions(+), 4 deletions(-) diff --git a/observability/prometheus/prometheus.go b/observability/prometheus/prometheus.go index 704fe3d9..fff14c55 100644 --- a/observability/prometheus/prometheus.go +++ b/observability/prometheus/prometheus.go @@ -158,12 +158,17 @@ func (obs *observer) Handler(string) http.Handler { return metricsHandler(prometheus.DefaultRegisterer, prometheus.DefaultGatherer) } - gatherer := prometheus.DefaultGatherer - if own, ok := obs.registry.(prometheus.Gatherer); ok { - gatherer = own + // Both halves or neither, which is what the paragraph above rules out any + // middle ground for. A Registerer that cannot also gather leaves nothing to + // serve its own metrics from, and pairing it with the default gatherer + // would be exactly the mismatch described: the scrape counter landing in + // one registry while another's metrics go out on the wire. + own, ok := obs.registry.(prometheus.Gatherer) + if !ok { + return metricsHandler(prometheus.DefaultRegisterer, prometheus.DefaultGatherer) } - return metricsHandler(obs.registry, gatherer) + return metricsHandler(obs.registry, own) } // metricsHandler serves the metrics route, negotiating OpenMetrics. From 7ee9908ada82c6741756a346851b6720579e8d73 Mon Sep 17 00:00:00 2001 From: Niv Greenstein <88280771+NivGreenstein@users.noreply.github.com> Date: Mon, 14 Sep 2026 13:38:29 +0300 Subject: [PATCH 17/27] test(observability): scrape the metrics route through Handler, not its helper MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit TestExemplarReachesTheExposition called metricsHandler directly, which is the unexported helper rather than the entry point server.go mounts. The encoding is chosen in Handler, so the test asserted the exemplar reached an exposition nothing serves: replacing Handler's body with a plain promhttp.Handler() — the default, which leaves EnableOpenMetrics off — dropped every exemplar on the wire with the whole suite still green. It now goes through Handler and fails that mutation on the Content-Type, which is also the first thing that makes the observer's registry field load-bearing: it is what lets the production entry point be exercised against this test's own registry instead of the process-wide default. Co-Authored-By: Claude Opus 5 (1M context) --- .../prometheus/exemplar_internal_test.go | 15 ++++++++++++++- 1 file changed, 14 insertions(+), 1 deletion(-) diff --git a/observability/prometheus/exemplar_internal_test.go b/observability/prometheus/exemplar_internal_test.go index 8a857220..98068170 100644 --- a/observability/prometheus/exemplar_internal_test.go +++ b/observability/prometheus/exemplar_internal_test.go @@ -241,6 +241,16 @@ func TestDurationExemplars(t *testing.T) { // drops them silently. So this scrapes the handler the metrics route actually // serves, with the Accept header Prometheus sends, and looks for the exemplar // in the bytes. +// +// Through Handler, not through metricsHandler, which is the whole point of the +// distinction. Handler is what server.go mounts on the metrics route, and it is +// where EnableOpenMetrics is chosen; calling the unexported helper directly +// would assert the encoding of a handler nothing serves, and replacing +// Handler's body with a plain promhttp.Handler() — the default, which leaves +// OpenMetrics off — would drop every exemplar on the wire with this test still +// green. That is also what the observer's registry field is doing here: it is +// what lets the production entry point be exercised against a registry of this +// test's own rather than the process-wide default. func TestExemplarReachesTheExposition(t *testing.T) { registry := prometheus.NewRegistry() tier := faketier.New("hot") @@ -258,7 +268,10 @@ func TestExemplarReachesTheExposition(t *testing.T) { "application/openmetrics-text;version=0.0.1;q=0.75,"+ "text/plain;version=0.0.4;q=0.5,*/*;q=0.1") recorder := httptest.NewRecorder() - metricsHandler(registry, registry).ServeHTTP(recorder, request) + obs := &observer{registry: registry} + // The route name Handler is given is the one server.go passes it, and is + // ignored by every implementation; it is the mounting path, not a selector. + obs.Handler("/metrics").ServeHTTP(recorder, request) if contentType := recorder.Header().Get("Content-Type"); !strings.Contains(contentType, "openmetrics-text") { t.Fatalf("Content-Type = %q, want the OpenMetrics encoding that carries exemplars", contentType) From 9a1c3c6081f39ad586913f76e25147ffbef2412b Mon Sep 17 00:00:00 2001 From: Niv Greenstein <88280771+NivGreenstein@users.noreply.github.com> Date: Mon, 14 Sep 2026 13:38:36 +0300 Subject: [PATCH 18/27] docs: correct two claims about what the exemplar tests prove MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Both overstate their evidence, which is the failure mode this branch has already had to fix twice in comments. observability/prometheus/README.md said TestRespelledQuantileBoundaries "scrapes a real Go collector". It does not, deliberately: the collector's constructor is deprecated in the vendored client and its replacement is not vendored, so the test carries the collector's own objectives on a summary instead. Say that, and why. tracing/README.md said the two ordering tests "say which way round it went wrong". Only the atlas one does — a tier exemplar can go wrong exactly one way, so it names the inversion. The server one reports that no bucket carries an exemplar at all, because a request observed outside its own span has nothing to point at. Both fail; they do not fail alike. Co-Authored-By: Claude Opus 5 (1M context) --- observability/prometheus/README.md | 7 ++++++- tracing/README.md | 7 +++++-- 2 files changed, 11 insertions(+), 3 deletions(-) diff --git a/observability/prometheus/README.md b/observability/prometheus/README.md index 722b17ad..68a6470c 100644 --- a/observability/prometheus/README.md +++ b/observability/prometheus/README.md @@ -98,7 +98,12 @@ labels through the same float formatter. The Go runtime collector's `go_gc_duration_seconds` is a summary, so `quantile="0"` becomes `quantile="0.0"` and `quantile="1"` becomes `quantile="1.0"` — on a metric this package never touches and that every Go process publishes. `TestRespelledQuantileBoundaries` -scrapes a real Go collector to keep that claim honest. +keeps that claim honest by scraping a summary carrying the Go collector's own +objectives, rather than the collector itself: its constructor is deprecated in +the vendored client, and the replacement lives in a package this tree does not +vendor, so registering one to prove a fact about the encoder would have meant +vendor churn on a ticket whose acceptance criteria turn on `vendor/` being +untouched. Anything matching an exact `le` or `quantile` needs checking. diff --git a/tracing/README.md b/tracing/README.md index 01614a1f..d1f5c2ed 100644 --- a/tracing/README.md +++ b/tracing/README.md @@ -297,8 +297,11 @@ comment saying so. A slow bucket on the per-tier histogram therefore names the tier read that was slow, not the request as a whole. Inverting either order leaves the span tree unchanged, so it is pinned by the exemplar instead: `atlas.TestExemplarNamesTheSpanThatMeasuredIt` and -`server.TestRequestExemplarNamesTheRequestSpan` both fail on it, and say which -way round it went wrong. +`server.TestRequestExemplarNamesTheRequestSpan` both fail on it, though they +fail differently: the atlas one names the inversion, because a tier exemplar +can only go wrong by naming the cache-wide span, and the server one reports +that no bucket carries an exemplar at all, because a request observed outside +its own span has no trace to point at. **Nothing is attached outside a trace.** `exemplarFrom` returns nil, which is the client's own "no exemplar" signal, so an untraced observation is recorded From 71207214febddab460774f2f1651277cb6fc1d70 Mon Sep 17 00:00:00 2001 From: Niv Greenstein <88280771+NivGreenstein@users.noreply.github.com> Date: Mon, 14 Sep 2026 13:52:31 +0300 Subject: [PATCH 19/27] refactor(test): move the respelling differ into ttools MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit It was private to package prometheus, which quietly bounded what it could check to the bucket sets declared there — while the docs it backs describe every family the process publishes. provider/postgis declares its own duration buckets, so they were invisible to a test whose comment said it derived the list from the bucket sets. Shared here so the next family declared outside the observer can be pinned without copying the differ, which is how the docs got a hand-written list in the first place. Co-Authored-By: Claude Opus 5 (1M context) --- internal/ttools/openmetrics.go | 135 +++++++++++++++++ .../openmetrics_le_internal_test.go | 143 +++--------------- 2 files changed, 156 insertions(+), 122 deletions(-) create mode 100644 internal/ttools/openmetrics.go diff --git a/internal/ttools/openmetrics.go b/internal/ttools/openmetrics.go new file mode 100644 index 00000000..bc28c4a7 --- /dev/null +++ b/internal/ttools/openmetrics.go @@ -0,0 +1,135 @@ +package ttools + +import ( + "net/http" + "net/http/httptest" + "regexp" + "testing" + + "github.com/prometheus/client_golang/prometheus" + "github.com/prometheus/client_golang/prometheus/promhttp" +) + +// This file is the evidence for a claim the docs make and an operator acts on: +// which bucket boundaries are respelled by serving OpenMetrics, and therefore +// which `le` series change identity. Getting that list wrong understates an +// upgrade break — the first version of those docs named a boundary that is not +// affected at all, and the second missed two whole families — so it is derived +// rather than worked out by hand. +// +// Derived by *scraping both encoders* rather than by reimplementing the rule +// they apply. An earlier version copied expfmt's unexported +// writeOpenMetricsFloat, which put the docs one vendored change away from being +// wrong with the test still green; the copy also silently dropped that +// function's NaN and ±Inf cases. Nothing here knows the rule, so a change to it +// shows up as a failure naming the boundary that moved. +// +// It lives in ttools rather than beside the observer because the families it +// has to cover do not all live there. provider/postgis declares its own +// duration buckets, and a differ private to package prometheus could not see +// them — which is exactly how those two families came to be missing from the +// documented list while a test named "derives this from the bucket sets" stayed +// green. + +// LePattern and QuantilePattern pull a bucket or quantile label out of an +// exposition line. +var ( + LePattern = regexp.MustCompile(`le="([^"]+)"`) + QuantilePattern = regexp.MustCompile(`quantile="([^"]+)"`) +) + +// The two exposition formats, named so a call site says which it means rather +// than passing a bare true or false. +const ( + openMetricsText = true + classicText = false +) + +// scrapeLabel serves a gatherer in one exposition format and returns the values +// pattern captures, in the order they were written. +func scrapeLabel(t *testing.T, gatherer prometheus.Gatherer, pattern *regexp.Regexp, openMetrics bool) []string { + t.Helper() + + request := httptest.NewRequest(http.MethodGet, "/metrics", nil) + if openMetrics { + // The one Accept header that reaches the OpenMetrics encoder in this + // vendored expfmt, which negotiates version 0.0.1 only. + request.Header.Set("Accept", "application/openmetrics-text;version=0.0.1") + } + + recorder := httptest.NewRecorder() + promhttp.HandlerFor(gatherer, promhttp.HandlerOpts{EnableOpenMetrics: openMetrics}). + ServeHTTP(recorder, request) + + var found []string + for _, match := range pattern.FindAllStringSubmatch(recorder.Body.String(), -1) { + found = append(found, match[1]) + } + + return found +} + +// Respelled serves gatherer under both exposition formats, pairs the label +// values written by each, and returns the ones the two spell differently as +// "before -> after". +// +// The pairing is positional, which is why the lengths are checked first: the +// two encoders write the same samples in the same order, and a length mismatch +// means they no longer do, which would make every comparison below meaningless +// rather than merely wrong. +func Respelled(t *testing.T, gatherer prometheus.Gatherer, pattern *regexp.Regexp) []string { + t.Helper() + + classic := scrapeLabel(t, gatherer, pattern, classicText) + openMetrics := scrapeLabel(t, gatherer, pattern, openMetricsText) + + if len(classic) == 0 { + t.Fatal("no matching labels in the exposition; this test would prove nothing") + } + if len(classic) != len(openMetrics) { + t.Fatalf("%d labels classic, %d under OpenMetrics; the two are not comparable", + len(classic), len(openMetrics)) + } + + var changed []string + for i := range classic { + if classic[i] != openMetrics[i] { + changed = append(changed, classic[i]+" -> "+openMetrics[i]) + } + } + + return changed +} + +// RespelledBuckets is Respelled over one histogram's bucket set, which is what +// every caller but the summary case wants. +// +// The single observation is what makes every bucket appear in the exposition; +// without it there is nothing to compare. +func RespelledBuckets(t *testing.T, buckets []float64) []string { + t.Helper() + + registry := prometheus.NewRegistry() + histogram := prometheus.NewHistogram(prometheus.HistogramOpts{ + Name: "test_le_seconds", + Buckets: buckets, + }) + registry.MustRegister(histogram) + histogram.Observe(0) + + return Respelled(t, registry, LePattern) +} + +// AssertRespelled compares what actually moved against what the docs say did. +func AssertRespelled(t *testing.T, got, want []string) { + t.Helper() + + if len(got) != len(want) { + t.Fatalf("respelled = %v, documented %v", got, want) + } + for i := range got { + if got[i] != want[i] { + t.Errorf("respelled %d = %q, documented %q", i, got[i], want[i]) + } + } +} diff --git a/observability/prometheus/openmetrics_le_internal_test.go b/observability/prometheus/openmetrics_le_internal_test.go index 37afc1ba..bdf0f11f 100644 --- a/observability/prometheus/openmetrics_le_internal_test.go +++ b/observability/prometheus/openmetrics_le_internal_test.go @@ -1,117 +1,18 @@ package prometheus import ( - "net/http" - "net/http/httptest" - "regexp" "strings" "testing" "github.com/prometheus/client_golang/prometheus" - "github.com/prometheus/client_golang/prometheus/promhttp" -) - -// This file is the evidence for a claim the docs make and an operator acts on: -// which bucket boundaries are respelled by serving OpenMetrics, and therefore -// which `le` series change identity. Getting that list wrong understates an -// upgrade break — the first version of these docs named a boundary that is not -// affected at all — so it is derived rather than worked out by hand. -// -// Derived by *scraping both encoders* rather than by reimplementing the rule -// they apply. An earlier version of this test copied expfmt's unexported -// writeOpenMetricsFloat, which put the docs one vendored change away from being -// wrong with the test still green; the copy also silently dropped that -// function's NaN and ±Inf cases. Nothing here knows the rule, so a change to it -// shows up as a failure naming the boundary that moved. - -// lePattern and quantilePattern pull a bucket or quantile label out of an -// exposition line. -var ( - lePattern = regexp.MustCompile(`le="([^"]+)"`) - quantilePattern = regexp.MustCompile(`quantile="([^"]+)"`) -) -// The two exposition formats, named so a call site says which it means rather -// than passing a bare true or false. -const ( - openMetricsText = true - classicText = false + "github.com/MapColonies/shigola/internal/ttools" ) -// scrapeLabel serves a registry in one exposition format and returns the values -// pattern captures, in the order they were written. -func scrapeLabel(t *testing.T, registry *prometheus.Registry, pattern *regexp.Regexp, openMetrics bool) []string { - t.Helper() - - request := httptest.NewRequest(http.MethodGet, "/metrics", nil) - if openMetrics { - // The one Accept header that reaches the OpenMetrics encoder in this - // vendored expfmt, which negotiates version 0.0.1 only. - request.Header.Set("Accept", "application/openmetrics-text;version=0.0.1") - } - - recorder := httptest.NewRecorder() - promhttp.HandlerFor(registry, promhttp.HandlerOpts{EnableOpenMetrics: openMetrics}). - ServeHTTP(recorder, request) - - return matches(pattern, recorder.Body.String()) -} - -// matches returns the first capture group of every match, in order. -func matches(pattern *regexp.Regexp, body string) []string { - var found []string - for _, match := range pattern.FindAllStringSubmatch(body, -1) { - found = append(found, match[1]) - } - - return found -} - -// respelled serves registry under both exposition formats, pairs the label -// values written by each, and returns the ones the two spell differently as -// "before -> after". -// -// The pairing is positional, which is why the lengths are checked first: the -// two encoders write the same samples in the same order, and a length mismatch -// means they no longer do, which would make every comparison below meaningless -// rather than merely wrong. -func respelled(t *testing.T, registry *prometheus.Registry, pattern *regexp.Regexp) []string { - t.Helper() - - classic := scrapeLabel(t, registry, pattern, classicText) - openMetrics := scrapeLabel(t, registry, pattern, openMetricsText) - - if len(classic) == 0 { - t.Fatal("no matching labels in the exposition; this test would prove nothing") - } - if len(classic) != len(openMetrics) { - t.Fatalf("%d labels classic, %d under OpenMetrics; the two are not comparable", - len(classic), len(openMetrics)) - } - - var changed []string - for i := range classic { - if classic[i] != openMetrics[i] { - changed = append(changed, classic[i]+" -> "+openMetrics[i]) - } - } - - return changed -} - -// assertRespelled compares what actually moved against what the docs say did. -func assertRespelled(t *testing.T, got, want []string) { - t.Helper() - - if len(got) != len(want) { - t.Fatalf("respelled = %v, documented %v", got, want) - } - for i := range got { - if got[i] != want[i] { - t.Errorf("respelled %d = %q, documented %q", i, got[i], want[i]) - } - } -} +// The differ these tests use lives in internal/ttools, with the reasoning for +// deriving the list rather than restating the rule. It is shared because the +// families the docs cover are not all declared in this package: see +// provider/postgis's own row. // TestRespelledBucketBoundaries scrapes each bucket set under both exposition // formats and reports every boundary the two spell differently. @@ -128,17 +29,8 @@ func TestRespelledBucketBoundaries(t *testing.T) { fn := func(tc tcase) func(*testing.T) { return func(t *testing.T) { - registry := prometheus.NewRegistry() - histogram := prometheus.NewHistogram(prometheus.HistogramOpts{ - Name: "test_le_seconds", - Buckets: tc.buckets, - }) - registry.MustRegister(histogram) - // One observation, so every bucket is written out. - histogram.Observe(0) - - changed := respelled(t, registry, lePattern) - assertRespelled(t, changed, tc.respelled) + changed := ttools.RespelledBuckets(t, tc.buckets) + ttools.AssertRespelled(t, changed, tc.respelled) for _, le := range tc.unchanged { for _, entry := range changed { @@ -193,12 +85,19 @@ func TestRespelledBucketBoundaries(t *testing.T) { // dashboards pin a quantile on. The docs said "le" and named only shigola's // families until this test was written. // -// The summary here carries the Go collector's own objectives rather than -// registering the collector itself, whose constructor is deprecated in the -// vendored client and whose replacement lives in a package this tree does not -// vendor. Registering one to prove a fact about the encoder would have meant -// vendor churn on a ticket whose acceptance criteria turn on vendor/ being -// untouched. +// The fixture publishes the quantiles the Go collector publishes — 0, 0.25, +// 0.5, 0.75 and 1 — rather than registering the collector itself, whose +// constructor is deprecated in the vendored client and whose replacement lives +// in a package this tree does not vendor: registering one to prove a fact about +// the encoder would have meant vendor churn on a ticket whose acceptance +// criteria turn on vendor/ being untouched. +// +// A summary is the only way to publish a quantile label from this side, so the +// quantiles arrive here as Objectives. The Go collector reaches the same labels +// by another route — MustNewConstSummary over runtime.MemStats.PauseQuantiles, +// which has no objectives at all — and the epsilons below are therefore +// arbitrary. Only the label spelling is under test, and that is written by the +// encoder from the map keys. func TestRespelledQuantileBoundaries(t *testing.T) { registry := prometheus.NewRegistry() summary := prometheus.NewSummary(prometheus.SummaryOpts{ @@ -208,6 +107,6 @@ func TestRespelledQuantileBoundaries(t *testing.T) { registry.MustRegister(summary) summary.Observe(0) - assertRespelled(t, respelled(t, registry, quantilePattern), + ttools.AssertRespelled(t, ttools.Respelled(t, registry, ttools.QuantilePattern), []string{"0 -> 0.0", "1 -> 1.0"}) } From 935f2b586c702e464dcf2adf7b3b9f97b5c03e91 Mon Sep 17 00:00:00 2001 From: Niv Greenstein <88280771+NivGreenstein@users.noreply.github.com> Date: Mon, 14 Sep 2026 13:52:41 +0300 Subject: [PATCH 20/27] docs(observability): add the provider query families to the respelled table MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Serving OpenMetrics respells 1, 5 and 20 on shigola_mvt_provider_sql_query_seconds and shigola_provider_sql_query_seconds, changing the identity of every le series a dashboard pins on them. Neither family appeared in the documented list, which therefore understated the upgrade break for anyone running the PostGIS provider. Pinned rather than asserted: the boundaries move from a local inside Collectors to a package-level var so TestRespelledQueryBuckets can derive the row the same way the other four are derived. No database — what is under test is how the encoder writes the numbers, which matters because every other test in that package is gated behind RUN_POSTGIS_TESTS. tracing/README.md also claimed only the size histograms and counters go without an exemplar. These two are duration histograms, are observed inside their own query span, and still carry nothing: exemplarFrom lives in the Prometheus observer, and a provider importing it would defeat the noPrometheusObserver build tag. Recorded with the reason, not as an oversight. Co-Authored-By: Claude Opus 5 (1M context) --- observability/prometheus/README.md | 12 +++++-- .../postgis/openmetrics_le_internal_test.go | 34 +++++++++++++++++++ provider/postgis/postgis.go | 16 +++++++-- tracing/README.md | 16 +++++++-- 4 files changed, 69 insertions(+), 9 deletions(-) create mode 100644 provider/postgis/openmetrics_le_internal_test.go diff --git a/observability/prometheus/README.md b/observability/prometheus/README.md index 68a6470c..1c8e2970 100644 --- a/observability/prometheus/README.md +++ b/observability/prometheus/README.md @@ -86,11 +86,17 @@ exemplars: | `shigola_api_duration_seconds` | `1`, `5`, `10` | | `shigola_cache_response_size_bytes`, `shigola_cache_tier_response_size_bytes` | `1024`, `5120`, `25600`, `102400`, `256000`, `512000` | | `shigola_api_response_size_bytes` | `512000` | +| `shigola_mvt_provider_sql_query_seconds`, `shigola_provider_sql_query_seconds` | `1`, `5`, `20` | `2.5` is untouched, because it already contains a `.`, and so are the megabyte -boundaries, which render as `1.048576e+06` and `5.24288e+06`. -`TestRespelledBucketBoundaries` derives this list from the bucket sets, so it -cannot drift from them. +boundaries, which render as `1.048576e+06` and `5.24288e+06`; so is the provider +families' `.1`, which renders as `0.1`. + +`TestRespelledBucketBoundaries` derives the first four rows from the bucket sets +they name, and `postgis.TestRespelledQueryBuckets` derives the last, so none of +them can drift from the code. It takes two tests because the provider declares +its own boundaries: while the differ was private to this package it could not +see them, and that row was missing from this table for exactly as long. **It is not only `le`, and not only Shigola's own metrics.** The respelling is a property of the encoder rather than of histograms: it writes summary `quantile` diff --git a/provider/postgis/openmetrics_le_internal_test.go b/provider/postgis/openmetrics_le_internal_test.go new file mode 100644 index 00000000..6f9761a1 --- /dev/null +++ b/provider/postgis/openmetrics_le_internal_test.go @@ -0,0 +1,34 @@ +package postgis + +import ( + "testing" + + "github.com/MapColonies/shigola/internal/ttools" +) + +// TestRespelledQueryBuckets is this package's row in a table the docs keep. +// +// Serving OpenMetrics is what makes exemplars reach a scrape at all +// (MAPCO-11496), and the encoder respells any bucket boundary whose shortest +// rendering contains neither "." nor "e" — so `le="1"` becomes `le="1.0"`, a +// different series as far as Prometheus is concerned, and any dashboard panel +// or recording rule pinning an exact `le` stops matching. +// +// observability/prometheus has the same test over the families declared there, +// and the documented list of what moved was assembled from it alone. These two +// families were missed for exactly that reason: their buckets are declared +// here, so a differ private to that package could not see them while still +// reporting that it derived the list from the bucket sets. Hence a row here. +// +// No database: the boundaries are a package-level var, and what is under test +// is how the encoder writes them, not anything the provider does with them. +// That matters because every other test in this package is gated behind +// RUN_POSTGIS_TESTS and would not run in a normal `go test ./...`. +func TestRespelledQueryBuckets(t *testing.T) { + // shigola_mvt_provider_sql_query_seconds and + // shigola_provider_sql_query_seconds share these boundaries, so one row + // covers both. .1 is untouched: it renders as "0.1", which already has + // the "." the rule looks for. + ttools.AssertRespelled(t, ttools.RespelledBuckets(t, queryDurationBuckets), + []string{"1 -> 1.0", "5 -> 5.0", "20 -> 20.0"}) +} diff --git a/provider/postgis/postgis.go b/provider/postgis/postgis.go index 56d2b819..1644313d 100644 --- a/provider/postgis/postgis.go +++ b/provider/postgis/postgis.go @@ -182,6 +182,17 @@ func (p Provider) startQuerySpan(ctx context.Context, sql string) (context.Conte return ctx, span } +// queryDurationBuckets are the boundaries of the two provider query-duration +// histograms. +// +// Package-level rather than a local, so that a test can reach them: serving +// OpenMetrics respells any boundary whose shortest rendering contains neither +// "." nor "e", which changes the identity of the le series an operator's +// dashboards pin. 1, 5 and 20 are all in that set, and the documented list of +// what moved missed this whole family while it was a local in the function +// below. See internal/ttools.RespelledBuckets and TestRespelledQueryBuckets. +var queryDurationBuckets = []float64{.1, 1, 5, 20} + func (p *Provider) Collectors( prefix string, cfgFn func(configKey string) map[string]any, @@ -190,7 +201,6 @@ func (p *Provider) Collectors( return nil, nil } - buckets := []float64{.1, 1, 5, 20} c, err := p.pool.Collectors(prefix, cfgFn) if err != nil { return nil, err @@ -204,7 +214,7 @@ func (p *Provider) Collectors( prometheus.HistogramOpts{ Name: prefix + "_mvt_provider_sql_query_seconds", Help: "A histogram of query time for sql for mvt providers", - Buckets: buckets, + Buckets: queryDurationBuckets, ConstLabels: prometheus.Labels{"provider_name": p.name}, }, []string{"map_name", "z"}, @@ -214,7 +224,7 @@ func (p *Provider) Collectors( prometheus.HistogramOpts{ Name: prefix + "_provider_sql_query_seconds", Help: "A histogram of query time for sql for providers", - Buckets: buckets, + Buckets: queryDurationBuckets, ConstLabels: prometheus.Labels{"provider_name": p.name}, }, []string{"map_name", "layer_name", "z"}, diff --git a/tracing/README.md b/tracing/README.md index d1f5c2ed..bc3db832 100644 --- a/tracing/README.md +++ b/tracing/README.md @@ -263,9 +263,19 @@ pair of constants is what stops a rename from fixing one surface and breaking the other. Which observations carry one: `shigola_cache_duration_seconds`, -`shigola_cache_tier_duration_seconds` and `shigola_api_duration_seconds`. The -size histograms and the counters do not — the ticket asked for the duration -families, and an exemplar is worth having where there is a spike to click. +`shigola_cache_tier_duration_seconds` and `shigola_api_duration_seconds` — the +three MAPCO-11496 named. The size histograms and the counters do not, and +neither do `shigola_mvt_provider_sql_query_seconds` and +`shigola_provider_sql_query_seconds`, which *are* duration histograms and are +observed inside their own query span, so the trace is in hand at the point of +observation. + +The reason is a dependency rather than a judgement. `exemplarFrom` lives in +`observability/prometheus`, and a provider that imported it would defeat the +`noPrometheusObserver` build tag, which exists so the observer can be compiled +out entirely; nothing in `provider/` imports that package today. Attaching one +there means first giving `exemplarFrom` a neutral home, which is a larger change +than this ticket asked for and is worth its own. **The exposition format is not optional.** OpenMetrics is the only format that encodes exemplars; the classic Prometheus text format has no syntax for them and From 9eee5b17cfab74e56ae5cb34d96bf69739bf293d Mon Sep 17 00:00:00 2001 From: Niv Greenstein <88280771+NivGreenstein@users.noreply.github.com> Date: Mon, 14 Sep 2026 13:52:55 +0300 Subject: [PATCH 21/27] fix(observability): say so when the metrics route falls back to the default registry MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The branch that serves the default registry because the configured one cannot gather did it without a word. It is unreachable for anything New produces, so it guards against a panic rather than a real case — but silently serving a different registry's metrics than the caller configured is the same class of failure the exemplar label constants are commented against, and it presents as an inexplicably empty /metrics. Also moves ctx to the first parameter of the two closure builders in the exemplar table, per the context package's own convention. Co-Authored-By: Claude Opus 5 (1M context) --- .../prometheus/exemplar_internal_test.go | 16 ++++++++-------- observability/prometheus/prometheus.go | 8 ++++++++ 2 files changed, 16 insertions(+), 8 deletions(-) diff --git a/observability/prometheus/exemplar_internal_test.go b/observability/prometheus/exemplar_internal_test.go index 98068170..ef08f894 100644 --- a/observability/prometheus/exemplar_internal_test.go +++ b/observability/prometheus/exemplar_internal_test.go @@ -155,7 +155,7 @@ func TestDurationExemplars(t *testing.T) { // The errors are ignored in all three: a miss, and two writes to a fake // that cannot fail. The exemplar on the duration observation is the // subject, and that is recorded either way. - cacheOp := func(prefix, op string, ctx context.Context) func(*testing.T, *prometheus.Registry) (string, map[string]string) { + cacheOp := func(ctx context.Context, prefix, op string) func(*testing.T, *prometheus.Registry) (string, map[string]string) { return func(t *testing.T, registry *prometheus.Registry) (string, map[string]string) { c := newCache(registry, prefix, nil, faketier.New("hot")) @@ -181,7 +181,7 @@ func TestDurationExemplars(t *testing.T) { // context arrives on the request, which is how it arrives in production: // the tracing handler is installed outside the metrics one and has already // replaced the request by the time this runs. - request := func(prefix string, ctx context.Context) func(*testing.T, *prometheus.Registry) (string, map[string]string) { + request := func(ctx context.Context, prefix string) func(*testing.T, *prometheus.Registry) (string, map[string]string) { return func(t *testing.T, registry *prometheus.Registry) (string, map[string]string) { const route = "/collections/osm/tiles" @@ -201,30 +201,30 @@ func TestDurationExemplars(t *testing.T) { tests := map[string]tcase{ "a cache read in a sampled trace": { - observe: cacheOp("test_exemplar_cache", "get", fakelog.TracedContext(true)), + observe: cacheOp(fakelog.TracedContext(true), "test_exemplar_cache", "get"), traced: true, }, "a cache read outside any trace": { - observe: cacheOp("test_plain_cache", "get", context.Background()), + observe: cacheOp(context.Background(), "test_plain_cache", "get"), }, // Set and Purge run through the same observeDuration, and the docs name // all three spans — but every test here observed a read until these two // rows existed. The write is the one that matters most: on the detached // pool its observation outlives the response it belongs to. "a cache write in a sampled trace": { - observe: cacheOp("test_exemplar_write", "set", fakelog.TracedContext(true)), + observe: cacheOp(fakelog.TracedContext(true), "test_exemplar_write", "set"), traced: true, }, "a cache purge in a sampled trace": { - observe: cacheOp("test_exemplar_purge", "purge", fakelog.TracedContext(true)), + observe: cacheOp(fakelog.TracedContext(true), "test_exemplar_purge", "purge"), traced: true, }, "a request in a sampled trace": { - observe: request("test_exemplar_api", fakelog.TracedContext(true)), + observe: request(fakelog.TracedContext(true), "test_exemplar_api"), traced: true, }, "a request outside any trace": { - observe: request("test_plain_api", nil), + observe: request(nil, "test_plain_api"), }, } diff --git a/observability/prometheus/prometheus.go b/observability/prometheus/prometheus.go index fff14c55..503a4d1a 100644 --- a/observability/prometheus/prometheus.go +++ b/observability/prometheus/prometheus.go @@ -165,6 +165,14 @@ func (obs *observer) Handler(string) http.Handler { // one registry while another's metrics go out on the wire. own, ok := obs.registry.(prometheus.Gatherer) if !ok { + // Said out loud rather than swallowed. This is unreachable for every + // registry New can produce, so it exists to avoid a panic rather than + // to handle a real case — but serving a different registry's metrics + // than the one the caller configured is precisely the kind of silent + // substitution the exemplar label names are commented against, and an + // operator staring at an empty /metrics deserves the reason. + log.Warnf("prometheus: registry %T cannot gather; serving the default registry on the metrics route instead", obs.registry) + return metricsHandler(prometheus.DefaultRegisterer, prometheus.DefaultGatherer) } From f8a4dae51f45e6440872b0ab373f2b2de1efd38f Mon Sep 17 00:00:00 2001 From: Niv Greenstein <88280771+NivGreenstein@users.noreply.github.com> Date: Mon, 14 Sep 2026 14:02:38 +0300 Subject: [PATCH 22/27] docs(contributing): map the two docs pages this work left unrecorded The mapping table is what makes a source change reach its docs page, so a page deriving from a source with no row is a page that goes stale silently. docs/http-endpoints.md now describes the metrics route's exposition format, which observability/prometheus.metricsHandler owns, and had no row at all. docs/logging.md gained a paragraph deriving from tracing/README.md's metrics-correlation section, while its row named only the logs one. Co-Authored-By: Claude Opus 5 (1M context) --- CONTRIBUTING.md | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/CONTRIBUTING.md b/CONTRIBUTING.md index f702e8bc..7a4b2089 100644 --- a/CONTRIBUTING.md +++ b/CONTRIBUTING.md @@ -87,7 +87,8 @@ is no release-candidate branch. | `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 From db59284949201d0d5aaae4675bd6f8a0872bd78e Mon Sep 17 00:00:00 2001 From: Niv Greenstein <88280771+NivGreenstein@users.noreply.github.com> Date: Mon, 14 Sep 2026 14:02:48 +0300 Subject: [PATCH 23/27] docs(observability): state the le break unconditionally, and stop restating the push path MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Two corrections to the same section. The break is written up under trace exemplars in both files, which reads as though it follows from them. It does not: metricsHandler sets EnableOpenMetrics on every metrics route and never consults the tracing config, so an operator running the observer with tracing off — the default — gets the renamed series and no exemplars at all. tracing/README.md also carried the pushed-metrics mechanism near-verbatim from the observer's README. That paragraph is the one whose earlier prose copy asserted the opposite of what the code does and had to be corrected in three places at once, so it now lives in one place and is linked from the other. Co-Authored-By: Claude Opus 5 (1M context) --- observability/prometheus/README.md | 16 +++++++++++----- tracing/README.md | 13 ++++++------- 2 files changed, 17 insertions(+), 12 deletions(-) diff --git a/observability/prometheus/README.md b/observability/prometheus/README.md index 1c8e2970..7c49f8c8 100644 --- a/observability/prometheus/README.md +++ b/observability/prometheus/README.md @@ -74,11 +74,17 @@ business rather than anything this repo decides. Untested here either way. Note that `push_url` is documented above for ephemeral jobs such as `shigola cache seed`, which is not the latency-spike-to-trace workflow this section is about. -**The `le` label spelling changed.** Negotiating OpenMetrics respells a -boundary that renders as a whole number with a trailing `.0`, so `le="1"` is now `le="1.0"`, -which is a different series. The format is negotiated per scrape rather than -per family, so this reaches the size histograms too even though they carry no -exemplars: +**The `le` label spelling changed, whether or not you run tracing.** This +section sits under trace exemplars because they are the reason the format was +switched, but the switch itself is unconditional: `metricsHandler` sets +`EnableOpenMetrics` on every metrics route it serves and never consults the +tracing config. An operator running the observer with `[tracing]` off — the +default — gets this break and no exemplars. + +Negotiating OpenMetrics respells a boundary that renders as a whole number with +a trailing `.0`, so `le="1"` is now `le="1.0"`, which is a different series. The +format is negotiated per scrape rather than per family, so this reaches the size +histograms too even though they carry no exemplars: | Family | Respelled | |:---|:---| diff --git a/tracing/README.md b/tracing/README.md index bc3db832..db354281 100644 --- a/tracing/README.md +++ b/tracing/README.md @@ -342,13 +342,12 @@ Two consequences worth knowing: touches — is respelled too. - **Pushed metrics are a different path, and an unverified one.** A `push_url` - deployment never reaches the exposition format above: `push.New` defaults to - protobuf (`expfmt.FmtProtoDelim`) and nothing here overrides it. Protobuf - does carry exemplars — `(*histogram).Write` fills in `dto.Bucket.Exemplar` — - so they go out on the wire, and whether the Pushgateway stores and re-exposes - them is its business, not this repo's. Nothing here tests it. `push_url` is - in any case documented for ephemeral jobs such as `shigola cache seed`, - rather than for the serving path this section is about. + deployment never reaches the exposition format above, and the exemplars are + neither lost nor confirmed on the way. The mechanism is set out once, in + `observability/prometheus/README.md` § "On pushed metrics" — deliberately not + restated here, because this is the paragraph whose earlier prose copy stated + the opposite of what the code does and had to be corrected in three places at + once. ## Costs when disabled From 66231fe87257cbfd3e56b39853ad9a1b641b466e Mon Sep 17 00:00:00 2001 From: Niv Greenstein <88280771+NivGreenstein@users.noreply.github.com> Date: Mon, 14 Sep 2026 14:02:56 +0300 Subject: [PATCH 24/27] test(observability): check the unchanged boundaries before the fatal comparison MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The unchanged list names the boundaries that surprise by not moving, and its loop ran after AssertRespelled — which fails fatally on a length mismatch. A documented-unchanged boundary that starts moving *is* a length mismatch, so the specific message could only ever appear if some other boundary stopped moving in the same change. Reordered, so it says which boundary. Also drops the six per-row metric prefixes in TestDurationExemplars. They date from before each row got its own registry and now imply an isolation requirement that is not there; the comment says where the requirement is real, which is the atlas and server tests on the default registry. Co-Authored-By: Claude Opus 5 (1M context) --- .../prometheus/exemplar_internal_test.go | 29 +++++++++++++------ .../openmetrics_le_internal_test.go | 8 ++++- 2 files changed, 27 insertions(+), 10 deletions(-) diff --git a/observability/prometheus/exemplar_internal_test.go b/observability/prometheus/exemplar_internal_test.go index ef08f894..3198d302 100644 --- a/observability/prometheus/exemplar_internal_test.go +++ b/observability/prometheus/exemplar_internal_test.go @@ -134,6 +134,12 @@ func TestDurationExemplars(t *testing.T) { fn := func(tc tcase) func(*testing.T) { return func(t *testing.T) { + // A registry per row, which is why the two closures below can each + // use one fixed metric prefix. The exemplar tests in atlas and + // server need a name unique to each test because they go through + // the process-wide default registry, where one bucket's exemplar is + // overwritten by the next observation to land in it; nothing here + // is shared, so nothing here has to be. registry := prometheus.NewRegistry() family, labels := tc.observe(t, registry) @@ -155,8 +161,10 @@ func TestDurationExemplars(t *testing.T) { // The errors are ignored in all three: a miss, and two writes to a fake // that cannot fail. The exemplar on the duration observation is the // subject, and that is recorded either way. - cacheOp := func(ctx context.Context, prefix, op string) func(*testing.T, *prometheus.Registry) (string, map[string]string) { + cacheOp := func(ctx context.Context, op string) func(*testing.T, *prometheus.Registry) (string, map[string]string) { return func(t *testing.T, registry *prometheus.Registry) (string, map[string]string) { + const prefix = "test_cache" + c := newCache(registry, prefix, nil, faketier.New("hot")) switch op { @@ -181,9 +189,12 @@ func TestDurationExemplars(t *testing.T) { // context arrives on the request, which is how it arrives in production: // the tracing handler is installed outside the metrics one and has already // replaced the request by the time this runs. - request := func(ctx context.Context, prefix string) func(*testing.T, *prometheus.Registry) (string, map[string]string) { + request := func(ctx context.Context) func(*testing.T, *prometheus.Registry) (string, map[string]string) { return func(t *testing.T, registry *prometheus.Registry) (string, map[string]string) { - const route = "/collections/osm/tiles" + const ( + prefix = "test_api" + route = "/collections/osm/tiles" + ) handler := newHttpHandler(registry, prefix, "", nil) instrumented := handler.InstrumentedHttpHandler(http.MethodGet, route, @@ -201,30 +212,30 @@ func TestDurationExemplars(t *testing.T) { tests := map[string]tcase{ "a cache read in a sampled trace": { - observe: cacheOp(fakelog.TracedContext(true), "test_exemplar_cache", "get"), + observe: cacheOp(fakelog.TracedContext(true), "get"), traced: true, }, "a cache read outside any trace": { - observe: cacheOp(context.Background(), "test_plain_cache", "get"), + observe: cacheOp(context.Background(), "get"), }, // Set and Purge run through the same observeDuration, and the docs name // all three spans — but every test here observed a read until these two // rows existed. The write is the one that matters most: on the detached // pool its observation outlives the response it belongs to. "a cache write in a sampled trace": { - observe: cacheOp(fakelog.TracedContext(true), "test_exemplar_write", "set"), + observe: cacheOp(fakelog.TracedContext(true), "set"), traced: true, }, "a cache purge in a sampled trace": { - observe: cacheOp(fakelog.TracedContext(true), "test_exemplar_purge", "purge"), + observe: cacheOp(fakelog.TracedContext(true), "purge"), traced: true, }, "a request in a sampled trace": { - observe: request(fakelog.TracedContext(true), "test_exemplar_api"), + observe: request(fakelog.TracedContext(true)), traced: true, }, "a request outside any trace": { - observe: request(nil, "test_plain_api"), + observe: request(nil), }, } diff --git a/observability/prometheus/openmetrics_le_internal_test.go b/observability/prometheus/openmetrics_le_internal_test.go index bdf0f11f..38a3673c 100644 --- a/observability/prometheus/openmetrics_le_internal_test.go +++ b/observability/prometheus/openmetrics_le_internal_test.go @@ -30,8 +30,12 @@ func TestRespelledBucketBoundaries(t *testing.T) { fn := func(tc tcase) func(*testing.T) { return func(t *testing.T) { changed := ttools.RespelledBuckets(t, tc.buckets) - ttools.AssertRespelled(t, changed, tc.respelled) + // Before AssertRespelled, which fails fatally on a length + // mismatch. A documented-unchanged boundary that starts moving + // *is* a length mismatch, so checking afterwards would report the + // generic list difference and never the specific boundary — the + // one thing this loop exists to name. for _, le := range tc.unchanged { for _, entry := range changed { if strings.HasPrefix(entry, le+" -> ") { @@ -39,6 +43,8 @@ func TestRespelledBucketBoundaries(t *testing.T) { } } } + + ttools.AssertRespelled(t, changed, tc.respelled) } } From e91e346c9973964292ad78ff98a03a2b319180d3 Mon Sep 17 00:00:00 2001 From: Niv Greenstein <88280771+NivGreenstein@users.noreply.github.com> Date: Mon, 14 Sep 2026 14:14:04 +0300 Subject: [PATCH 25/27] fix(docs): shigola_provider_sql_query_seconds publishes nothing MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Correcting claims this branch added two commits ago. The family is constructed and returned as a collector, and nothing in the tree calls Observe on it: its layer_name label belongs to the feature-returning postgis provider removed in MAPCO-11487, and mvt_postgis records against shigola_mvt_provider_sql_query_seconds instead. A HistogramVec with no observed child emits no family, so it never reaches a scrape. So three statements were wrong. It was listed in the respelled-le table, which told operators to re-check series it has none of. It was named as a duration histogram "observed inside its own query span", which it is not. And the docs-site page said its latency was readable as that span's duration, when there is no such span. The mvt family's row is correct and stays — it is observed, and 1, 5 and 20 do move. The dead one is now annotated where it is documented rather than removed: deleting a registered collector is a separate change from describing it. Co-Authored-By: Claude Opus 5 (1M context) --- observability/prometheus/README.md | 9 ++++++++- provider/postgis/openmetrics_le_internal_test.go | 8 ++++---- provider/postgis/postgis.go | 10 +++++++++- tracing/README.md | 9 +++++---- 4 files changed, 26 insertions(+), 10 deletions(-) diff --git a/observability/prometheus/README.md b/observability/prometheus/README.md index 7c49f8c8..665aea36 100644 --- a/observability/prometheus/README.md +++ b/observability/prometheus/README.md @@ -92,7 +92,7 @@ histograms too even though they carry no exemplars: | `shigola_api_duration_seconds` | `1`, `5`, `10` | | `shigola_cache_response_size_bytes`, `shigola_cache_tier_response_size_bytes` | `1024`, `5120`, `25600`, `102400`, `256000`, `512000` | | `shigola_api_response_size_bytes` | `512000` | -| `shigola_mvt_provider_sql_query_seconds`, `shigola_provider_sql_query_seconds` | `1`, `5`, `20` | +| `shigola_mvt_provider_sql_query_seconds` | `1`, `5`, `20` | `2.5` is untouched, because it already contains a `.`, and so are the megabyte boundaries, which render as `1.048576e+06` and `5.24288e+06`; so is the provider @@ -287,6 +287,13 @@ A histogram of the query time for the SQLs for the mvt provider ##### shigola_provider_sql_query_seconds +**Publishes nothing today.** The histogram is constructed and registered, but +nothing observes it: its `layer_name` label belongs to the feature-returning +`postgis` provider removed in MAPCO-11487, and `mvt_postgis` records against +`shigola_mvt_provider_sql_query_seconds` instead. A `HistogramVec` with no +observed child emits no family, so this one never reaches a scrape — which is +also why it is absent from the respelled-`le` table above. + Labels: "map_name", "layer_name", and "z" Buckets: .1 second, 1 second, 5 seconds, and 20+ seconds diff --git a/provider/postgis/openmetrics_le_internal_test.go b/provider/postgis/openmetrics_le_internal_test.go index 6f9761a1..b57612ef 100644 --- a/provider/postgis/openmetrics_le_internal_test.go +++ b/provider/postgis/openmetrics_le_internal_test.go @@ -25,10 +25,10 @@ import ( // That matters because every other test in this package is gated behind // RUN_POSTGIS_TESTS and would not run in a normal `go test ./...`. func TestRespelledQueryBuckets(t *testing.T) { - // shigola_mvt_provider_sql_query_seconds and - // shigola_provider_sql_query_seconds share these boundaries, so one row - // covers both. .1 is untouched: it renders as "0.1", which already has - // the "." the rule looks for. + // These are the boundaries of shigola_mvt_provider_sql_query_seconds, the + // one family here that is actually observed — see queryDurationBuckets for + // why its sibling is not. .1 is untouched: it renders as "0.1", which + // already has the "." the rule looks for. ttools.AssertRespelled(t, ttools.RespelledBuckets(t, queryDurationBuckets), []string{"1 -> 1.0", "5 -> 5.0", "20 -> 20.0"}) } diff --git a/provider/postgis/postgis.go b/provider/postgis/postgis.go index 1644313d..eb47f963 100644 --- a/provider/postgis/postgis.go +++ b/provider/postgis/postgis.go @@ -182,9 +182,17 @@ func (p Provider) startQuerySpan(ctx context.Context, sql string) (context.Conte return ctx, span } -// queryDurationBuckets are the boundaries of the two provider query-duration +// queryDurationBuckets are the boundaries of the provider query-duration // histograms. // +// Two families are built from them, but only shigola_mvt_provider_sql_query_seconds +// is ever observed. shigola_provider_sql_query_seconds is constructed and +// returned as a collector and nothing calls Observe on it anywhere in the tree +// — its layer_name label is a feature-returning-provider concept, left behind +// when that provider was removed in MAPCO-11487. A HistogramVec with no +// observed child publishes no family, so that one reaches no exposition and +// has no le series to change. +// // Package-level rather than a local, so that a test can reach them: serving // OpenMetrics respells any boundary whose shortest rendering contains neither // "." nor "e", which changes the identity of the le series an operator's diff --git a/tracing/README.md b/tracing/README.md index db354281..08450716 100644 --- a/tracing/README.md +++ b/tracing/README.md @@ -265,10 +265,11 @@ the other. Which observations carry one: `shigola_cache_duration_seconds`, `shigola_cache_tier_duration_seconds` and `shigola_api_duration_seconds` — the three MAPCO-11496 named. The size histograms and the counters do not, and -neither do `shigola_mvt_provider_sql_query_seconds` and -`shigola_provider_sql_query_seconds`, which *are* duration histograms and are -observed inside their own query span, so the trace is in hand at the point of -observation. +neither does `shigola_mvt_provider_sql_query_seconds`, which *is* a duration +histogram and *is* observed inside its own query span, so the trace is in hand +at the point of observation. (Its sibling +`shigola_provider_sql_query_seconds` is registered but never observed, so it +publishes no series at all — see `observability/prometheus/README.md`.) The reason is a dependency rather than a judgement. `exemplarFrom` lives in `observability/prometheus`, and a provider that imported it would defeat the From 2a5868b5e38c3d1e6f3fd6ea1f3c1a8b37c15f99 Mon Sep 17 00:00:00 2001 From: Niv Greenstein <88280771+NivGreenstein@users.noreply.github.com> Date: Mon, 14 Sep 2026 14:14:12 +0300 Subject: [PATCH 26/27] refactor(test): correct two caller-count comments, and take a label not a regexp MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit TierSpan's comment said "one caller today"; it gained a second when the detached-write test was written and the comment did not follow. AssertExemplar said "three tests in three packages" — three packages is right, four call sites is the count, because atlas uses it twice. Respelled took a *regexp.Regexp and the package exported two compiled patterns to feed it. Both callers want one label's values, so it takes the label name and builds the pattern itself: the package stops promising it can differ on an arbitrary expression, and the call sites read Respelled(t, reg, "quantile"). Co-Authored-By: Claude Opus 5 (1M context) --- internal/faketracer/faketracer.go | 6 ++--- internal/ttools/metrics.go | 7 ++--- internal/ttools/openmetrics.go | 26 ++++++++++--------- .../openmetrics_le_internal_test.go | 2 +- 4 files changed, 22 insertions(+), 19 deletions(-) diff --git a/internal/faketracer/faketracer.go b/internal/faketracer/faketracer.go index e1e9561d..97a8752d 100644 --- a/internal/faketracer/faketracer.go +++ b/internal/faketracer/faketracer.go @@ -129,9 +129,9 @@ func Int64Attr(span tracetest.SpanStub, key attribute.Key) int64 { // TierSpan returns the span named name that carries the given tier — a read, // a write or a purge on one tier of a chain. // -// One caller today, and here anyway 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 +// 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 diff --git a/internal/ttools/metrics.go b/internal/ttools/metrics.go index f58c33e5..ceae4564 100644 --- a/internal/ttools/metrics.go +++ b/internal/ttools/metrics.go @@ -150,9 +150,10 @@ func HasLabels(pairs []*dto.LabelPair, want map[string]string) bool { // AssertExemplar checks that the named histogram's most recent exemplar points // at the given trace and span. // -// Shared because three tests in three packages make exactly this pair of -// comparisons — the prometheus observer's own against a fixed fixture, atlas's -// against the tier span the read produced, server's against the request span — +// Shared because tests in three packages make exactly this pair of comparisons +// — the prometheus observer's own against a fixed fixture, atlas's against the +// tier span the read produced and the span a detached write ran in, server's +// against the request span — // and the label names are the load-bearing part: log.TraceIDKey and // log.SpanIDKey are what Grafana is configured with, so a test spelling them // itself is a test that keeps passing after a rename that broke correlation. diff --git a/internal/ttools/openmetrics.go b/internal/ttools/openmetrics.go index bc28c4a7..a26d7a34 100644 --- a/internal/ttools/openmetrics.go +++ b/internal/ttools/openmetrics.go @@ -31,12 +31,14 @@ import ( // documented list while a test named "derives this from the bucket sets" stayed // green. -// LePattern and QuantilePattern pull a bucket or quantile label out of an -// exposition line. -var ( - LePattern = regexp.MustCompile(`le="([^"]+)"`) - QuantilePattern = regexp.MustCompile(`quantile="([^"]+)"`) -) +// labelPattern pulls the values of one label out of an exposition line. +// +// Built here rather than taken as a *regexp.Regexp parameter: the two callers +// want a bucket boundary or a summary quantile, and a function promising to +// differ on any regexp at all would be promising more than it is asked for. +func labelPattern(label string) *regexp.Regexp { + return regexp.MustCompile(label + `="([^"]+)"`) +} // The two exposition formats, named so a call site says which it means rather // than passing a bare true or false. @@ -47,7 +49,7 @@ const ( // scrapeLabel serves a gatherer in one exposition format and returns the values // pattern captures, in the order they were written. -func scrapeLabel(t *testing.T, gatherer prometheus.Gatherer, pattern *regexp.Regexp, openMetrics bool) []string { +func scrapeLabel(t *testing.T, gatherer prometheus.Gatherer, label string, openMetrics bool) []string { t.Helper() request := httptest.NewRequest(http.MethodGet, "/metrics", nil) @@ -62,7 +64,7 @@ func scrapeLabel(t *testing.T, gatherer prometheus.Gatherer, pattern *regexp.Reg ServeHTTP(recorder, request) var found []string - for _, match := range pattern.FindAllStringSubmatch(recorder.Body.String(), -1) { + for _, match := range labelPattern(label).FindAllStringSubmatch(recorder.Body.String(), -1) { found = append(found, match[1]) } @@ -77,11 +79,11 @@ func scrapeLabel(t *testing.T, gatherer prometheus.Gatherer, pattern *regexp.Reg // two encoders write the same samples in the same order, and a length mismatch // means they no longer do, which would make every comparison below meaningless // rather than merely wrong. -func Respelled(t *testing.T, gatherer prometheus.Gatherer, pattern *regexp.Regexp) []string { +func Respelled(t *testing.T, gatherer prometheus.Gatherer, label string) []string { t.Helper() - classic := scrapeLabel(t, gatherer, pattern, classicText) - openMetrics := scrapeLabel(t, gatherer, pattern, openMetricsText) + classic := scrapeLabel(t, gatherer, label, classicText) + openMetrics := scrapeLabel(t, gatherer, label, openMetricsText) if len(classic) == 0 { t.Fatal("no matching labels in the exposition; this test would prove nothing") @@ -117,7 +119,7 @@ func RespelledBuckets(t *testing.T, buckets []float64) []string { registry.MustRegister(histogram) histogram.Observe(0) - return Respelled(t, registry, LePattern) + return Respelled(t, registry, "le") } // AssertRespelled compares what actually moved against what the docs say did. diff --git a/observability/prometheus/openmetrics_le_internal_test.go b/observability/prometheus/openmetrics_le_internal_test.go index 38a3673c..1b0d3d52 100644 --- a/observability/prometheus/openmetrics_le_internal_test.go +++ b/observability/prometheus/openmetrics_le_internal_test.go @@ -113,6 +113,6 @@ func TestRespelledQuantileBoundaries(t *testing.T) { registry.MustRegister(summary) summary.Observe(0) - ttools.AssertRespelled(t, ttools.Respelled(t, registry, ttools.QuantilePattern), + ttools.AssertRespelled(t, ttools.Respelled(t, registry, "quantile"), []string{"0 -> 0.0", "1 -> 1.0"}) } From 81f28bded6cfefa1c7bc623f6c4d8837c91daec9 Mon Sep 17 00:00:00 2001 From: Niv Greenstein <88280771+NivGreenstein@users.noreply.github.com> Date: Mon, 14 Sep 2026 14:20:55 +0300 Subject: [PATCH 27/27] fix(docs): finish cutting the dead provider family from the prose The previous commit dropped shigola_provider_sql_query_seconds from the respelled table and left the sentence under it plural, still saying the provider *families* carry no exemplars and their le labels move regardless. One of them has no le labels, because it publishes no series. HistogramSample's comment claimed three tests in three packages, the same stale count corrected on AssertExemplar one commit ago. It has one external caller and one in-file one; the rationale now says what it actually shares. Co-Authored-By: Claude Opus 5 (1M context) --- internal/ttools/metrics.go | 6 +++--- observability/prometheus/README.md | 2 +- 2 files changed, 4 insertions(+), 4 deletions(-) diff --git a/internal/ttools/metrics.go b/internal/ttools/metrics.go index ceae4564..92676b36 100644 --- a/internal/ttools/metrics.go +++ b/internal/ttools/metrics.go @@ -43,9 +43,9 @@ func MetricFamilyNames(t *testing.T) []string { // HistogramSample returns the one sample of the named histogram family whose labels // include every pair in labels. // -// Shared for the reason MetricFamilyNames is: three tests in three packages -// read a histogram back out of a registry to assert what an observation -// recorded, and the family-then-label walk was otherwise written out in each. +// The family-then-label walk, in one place: ExemplarLabels starts from it, the +// observer's own untraced-observation assertion reads a sample count off it, +// and it was otherwise written out at each site that needed either. // // gatherer rather than the default registry, because both are needed: a test // that can build its own registry should, since the default one is diff --git a/observability/prometheus/README.md b/observability/prometheus/README.md index 665aea36..8b9555b0 100644 --- a/observability/prometheus/README.md +++ b/observability/prometheus/README.md @@ -96,7 +96,7 @@ histograms too even though they carry no exemplars: `2.5` is untouched, because it already contains a `.`, and so are the megabyte boundaries, which render as `1.048576e+06` and `5.24288e+06`; so is the provider -families' `.1`, which renders as `0.1`. +family's `.1`, which renders as `0.1`. `TestRespelledBucketBoundaries` derives the first four rows from the bucket sets they name, and `postgis.TestRespelledQueryBuckets` derives the last, so none of