From d4e229c17665b66656415d777b95f0806834c389 Mon Sep 17 00:00:00 2001 From: Emilien Mantel Date: Mon, 5 Oct 2026 17:38:41 +0200 Subject: [PATCH] :sparkles: Give background cache refreshes a trace of their own A refresh of an expired listing or dataroom list runs after the request has answered from the expired entry, yet its API spans were children of that request span: they outlived their parent and read as if the request had waited for them. Each background refresh now opens a root span, cache.refresh, linked to the request that triggered it (retyc.cache.name, plus retyc.dataroom.id for a folder listing). A request that joins a running refresh and waits for it gets a link to that trace instead; a fetch the request starts itself stays in its trace. Co-Authored-By: Claude Opus 5.5 --- CLAUDE.md | 8 +- cmd/tracing_privacy_test.go | 300 ++++++++++++++++++++++++++++++++++++ cmd/webdav.go | 96 ++++++++++-- doc/webdav.md | 11 +- 4 files changed, 399 insertions(+), 16 deletions(-) diff --git a/CLAUDE.md b/CLAUDE.md index d08cced..08060f6 100644 --- a/CLAUDE.md +++ b/CLAUDE.md @@ -556,7 +556,13 @@ Span model: span: `webdav serve` opens `retyc webdav serve init` (child of `TRACEPARENT`, ended once the port is bound) then one root `WEBDAV ` per request (`instrumentWebdav`, `WithNewRoot`, incoming `traceparent` - ignored); `mcp serve` opens one root `MCP ` per call; `toolErr` + ignored), and one root `cache.refresh` per background refresh of an expired + listing or dataroom list (`startRefreshSpan`: `WithNewRoot` + a link to the + request that triggered it, `retyc.cache.name`, `retyc.dataroom.id` for + nodes), never a child of the request span it would outlive. A fetch the + request starts itself stays in its trace; a request that waits for a + background refresh it joined gets a link to it (`linkRefresh`); + `mcp serve` opens one root `MCP ` per call; `toolErr` records the failure on that span; - API calls: `telemetry.RoundTripper` (installed by `cmd.apiTransport()` on every `api.New`, and by `newHTTPClient` for the OIDC client: discovery, diff --git a/cmd/tracing_privacy_test.go b/cmd/tracing_privacy_test.go index 6555dca..5e44939 100644 --- a/cmd/tracing_privacy_test.go +++ b/cmd/tracing_privacy_test.go @@ -3,16 +3,22 @@ package cmd import ( "context" "errors" + "fmt" "net/http" "net/http/httptest" + "os" "strings" + "sync/atomic" "testing" + "time" "github.com/retyc/retyc-cli/internal/service" "github.com/retyc/retyc-cli/internal/telemetry" "github.com/retyc/retyc-cli/internal/telemetry/telemetrytest" "github.com/spf13/cobra" + "go.opentelemetry.io/otel/codes" "go.opentelemetry.io/otel/sdk/trace/tracetest" + "go.opentelemetry.io/otel/trace" ) const sentinel = "SENTINEL-do-not-export" @@ -121,3 +127,297 @@ func TestNewHTTPClient_TracesRoundTrips(t *testing.T) { } assertNoSentinel(t, spans) } + +// A background refresh of an expired listing runs after the request answered: +// it gets a root span of its own, linked to that request, with the API work as +// its children. A miss the request waits for stays in the request's trace. +func TestListNodes_BackgroundRefreshHasItsOwnTrace(t *testing.T) { + exp := telemetrytest.Install(t) + var calls atomic.Int32 + fetchSpans := make(chan trace.SpanContext, 4) + fs := &webdavFS{ + listFn: func(ctx context.Context, _, _ string) ([]service.DataroomNodeInfo, error) { + calls.Add(1) + fetchSpans <- trace.SpanFromContext(ctx).SpanContext() + + return []service.DataroomNodeInfo{{ID: "n1", Name: sentinel, Type: "file"}}, nil + }, + cacheTTL: time.Minute, cacheMaxStale: 5 * time.Minute, + } + + reqCtx, reqSpan := telemetry.Tracer().Start(context.Background(), "WEBDAV PROPFIND") + if _, err := fs.listNodes(reqCtx, "dr1", "/"+sentinel); err != nil { // miss: waited for + t.Fatal(err) + } + if got := <-fetchSpans; got.SpanID() != reqSpan.SpanContext().SpanID() { + t.Errorf("a miss the request waits for must run in the request span, got %v", got) + } + ageNodeCache(fs, dataroomURI("dr1", "/"+sentinel), 2*time.Minute) + if _, err := fs.listNodes(reqCtx, "dr1", "/"+sentinel); err != nil { // stale: background refresh + t.Fatal(err) + } + reqSpan.End() + refreshCtx := <-fetchSpans + waitNodeID(t, fs, "/"+sentinel, "n1") + for calls.Load() < 2 { + time.Sleep(time.Millisecond) + } + + var refresh *tracetest.SpanStub + deadline := time.Now().Add(2 * time.Second) + for refresh == nil { + for _, s := range exp.GetSpans() { + if s.Name == "cache.refresh" { + refresh = &s + + break + } + } + if refresh == nil && time.Now().After(deadline) { + t.Fatal("no cache.refresh span exported") + } + time.Sleep(time.Millisecond) + } + if refresh.Parent.IsValid() { + t.Errorf("cache.refresh has parent %v, want a root span", refresh.Parent) + } + if refresh.SpanContext.TraceID() == reqSpan.SpanContext().TraceID() { + t.Error("cache.refresh shares the request's trace") + } + if refreshCtx.SpanID() != refresh.SpanContext.SpanID() { + t.Error("the refresh's API work does not run under the cache.refresh span") + } + if len(refresh.Links) != 1 || refresh.Links[0].SpanContext.SpanID() != reqSpan.SpanContext().SpanID() { + t.Errorf("cache.refresh links = %+v, want one link to the request span", refresh.Links) + } + attrs := map[string]string{} + for _, kv := range refresh.Attributes { + attrs[string(kv.Key)] = kv.Value.String() + } + if attrs["retyc.cache.name"] != "nodes" || attrs["retyc.dataroom.id"] != "dr1" { + t.Errorf("cache.refresh attributes = %v", attrs) + } + assertNoSentinel(t, exp.GetSpans()) +} + +// The dataroom list's background refresh gets its own trace too; the first +// fetch, which the request waits for, stays in the request's trace. +func TestDataroomCache_BackgroundRefreshHasItsOwnTrace(t *testing.T) { + exp := telemetrytest.Install(t) + fetchSpans := make(chan trace.SpanContext, 4) + cache := newDataroomCache(func(ctx context.Context) ([]dataroomCacheItem, error) { + fetchSpans <- trace.SpanFromContext(ctx).SpanContext() + + return []dataroomCacheItem{{id: "id-1", title: sentinel}}, nil + }) + + reqCtx, reqSpan := telemetry.Tracer().Start(context.Background(), "WEBDAV PROPFIND") + if _, err := cache.idForName(reqCtx, sentinel); err != nil { + t.Fatal(err) + } + if got := <-fetchSpans; got.SpanID() != reqSpan.SpanContext().SpanID() { + t.Errorf("the first fetch must run in the request span, got %v", got) + } + ageDataroomCache(cache) + if _, err := cache.idForName(reqCtx, sentinel); err != nil { + t.Fatal(err) + } + reqSpan.End() + refreshCtx := <-fetchSpans + + var refresh *tracetest.SpanStub + deadline := time.Now().Add(2 * time.Second) + for refresh == nil { + for _, s := range exp.GetSpans() { + if s.Name == "cache.refresh" { + refresh = &s + + break + } + } + if refresh == nil && time.Now().After(deadline) { + t.Fatal("no cache.refresh span exported") + } + time.Sleep(time.Millisecond) + } + if refresh.Parent.IsValid() || refreshCtx.SpanID() != refresh.SpanContext.SpanID() { + t.Errorf("cache.refresh: parent %v, fetch span %v, want a root span running the fetch", refresh.Parent, refreshCtx) + } + if len(refresh.Links) != 1 || refresh.Links[0].SpanContext.SpanID() != reqSpan.SpanContext().SpanID() { + t.Errorf("cache.refresh links = %+v, want one link to the request span", refresh.Links) + } + if name := spanAttr(refresh, "retyc.cache.name"); name != "datarooms" { + t.Errorf("retyc.cache.name = %q, want datarooms", name) + } + assertNoSentinel(t, exp.GetSpans()) +} + +// spanAttr returns the value of the attribute key on s, "" when absent. +func spanAttr(s *tracetest.SpanStub, key string) string { + for _, kv := range s.Attributes { + if string(kv.Key) == key { + return kv.Value.String() + } + } + + return "" +} + +// waitRefreshSpan returns the first cache.refresh span exported. +func waitRefreshSpan(t *testing.T, exp *tracetest.InMemoryExporter) *tracetest.SpanStub { + t.Helper() + deadline := time.Now().Add(2 * time.Second) + for { + for _, s := range exp.GetSpans() { + if s.Name == "cache.refresh" { + return &s + } + } + if time.Now().After(deadline) { + t.Fatal("no cache.refresh span exported") + } + time.Sleep(time.Millisecond) + } +} + +// A failed background refresh is recorded as an error by type only: its +// message (a name, a path) never reaches the span. +func TestListNodes_FailedRefreshSpanCarriesNoMessage(t *testing.T) { + exp := telemetrytest.Install(t) + var calls atomic.Int32 + fs := &webdavFS{ + listFn: func(context.Context, string, string) ([]service.DataroomNodeInfo, error) { + if calls.Add(1) > 1 { + return nil, fmt.Errorf("listing %s: %w", sentinel, os.ErrNotExist) + } + + return []service.DataroomNodeInfo{{ID: "n1", Name: "a", Type: "file"}}, nil + }, + cacheTTL: time.Minute, cacheMaxStale: 5 * time.Minute, + } + ctx := context.Background() + if _, err := fs.listNodes(ctx, "dr1", "/"+sentinel); err != nil { + t.Fatal(err) + } + ageNodeCache(fs, dataroomURI("dr1", "/"+sentinel), 2*time.Minute) + if _, err := fs.listNodes(ctx, "dr1", "/"+sentinel); err != nil { + t.Fatal(err) + } + + refresh := waitRefreshSpan(t, exp) + if refresh.Status.Code != codes.Error || refresh.Status.Description != "" { + t.Errorf("status = %+v, want Error with no description", refresh.Status) + } + if spanAttr(refresh, "error.type") == "" { + t.Error("error.type not set on the failed refresh") + } + assertNoSentinel(t, exp.GetSpans()) +} + +// The dataroom list's failed refresh carries no message either. +func TestDataroomCache_FailedRefreshSpanCarriesNoMessage(t *testing.T) { + exp := telemetrytest.Install(t) + var calls atomic.Int32 + cache := newDataroomCache(func(context.Context) ([]dataroomCacheItem, error) { + if calls.Add(1) > 1 { + return nil, errors.New("listing " + sentinel) + } + + return []dataroomCacheItem{{id: "id-1", title: "Alpha"}}, nil + }) + ctx := context.Background() + if _, err := cache.idForName(ctx, "Alpha"); err != nil { + t.Fatal(err) + } + ageDataroomCache(cache) + if _, err := cache.idForName(ctx, "Alpha"); err != nil { + t.Fatal(err) + } + + refresh := waitRefreshSpan(t, exp) + if refresh.Status.Code != codes.Error || spanAttr(refresh, "error.type") == "" { + t.Errorf("status = %+v, error.type = %q, want Error with a type", refresh.Status, spanAttr(refresh, "error.type")) + } + assertNoSentinel(t, exp.GetSpans()) +} + +// A request that joins a background refresh and waits for it (a name missing +// from the expired listing) gets a link to the refresh's trace: the API work +// it waited for is there, not in its own trace. +func TestFindListedNode_JoinedRefreshIsLinked(t *testing.T) { + exp := telemetrytest.Install(t) + var calls atomic.Int32 + fs := &webdavFS{ + listFn: func(context.Context, string, string) ([]service.DataroomNodeInfo, error) { + nodes := []service.DataroomNodeInfo{{ID: "old", Name: "a", Type: "file"}} + if calls.Add(1) > 1 { + nodes = append(nodes, service.DataroomNodeInfo{ID: "new", Name: "b", Type: "file"}) + } + + return nodes, nil + }, + cacheTTL: time.Minute, cacheMaxStale: 5 * time.Minute, + } + // Every slot taken: the background refresh stays queued until request B + // joins it, so B is certain to wait for it. + fs.refreshSlots = make(chan struct{}, 1) + fs.refreshSlots <- struct{}{} + ctx := context.Background() + if _, err := fs.listNodes(ctx, "dr1", "/"); err != nil { + t.Fatal(err) + } + ageNodeCache(fs, "retyc://dr1/", 2*time.Minute) + + ctxA, spanA := telemetry.Tracer().Start(ctx, "WEBDAV PROPFIND") + if _, err := fs.listNodes(ctxA, "dr1", "/"); err != nil { // queues the refresh + t.Fatal(err) + } + spanA.End() + ctxB, spanB := telemetry.Tracer().Start(ctx, "WEBDAV GET") + if n, err := fs.findListedNode(ctxB, "dr1", "/", "b"); err != nil || n.ID != "new" { + t.Fatalf("findListedNode(b) = (%+v, %v)", n, err) + } + spanB.End() + + refresh := waitRefreshSpan(t, exp) + var b *tracetest.SpanStub + for _, s := range exp.GetSpans() { + if s.Name == "WEBDAV GET" { + b = &s + } + } + if b == nil { + t.Fatal("request B span not exported") + } + if len(b.Links) != 1 || b.Links[0].SpanContext.SpanID() != refresh.SpanContext.SpanID() { + t.Errorf("request B links = %+v, want one link to cache.refresh", b.Links) + } +} + +// Waiting on a dataroom list fetch links the request to it only when the +// fetch ran as a background refresh. +func TestDataroomFetch_WaitLinksBackgroundRefresh(t *testing.T) { + exp := telemetrytest.Install(t) + _, refreshSpan := telemetry.Tracer().Start(context.Background(), "cache.refresh") + refreshSpan.End() + + done := make(chan struct{}) + close(done) + ctx, span := telemetry.Tracer().Start(context.Background(), "WEBDAV PROPFIND") + if _, err := (&dataroomFetch{done: done, refresh: refreshSpan.SpanContext()}).wait(ctx); err != nil { + t.Fatal(err) + } + if _, err := (&dataroomFetch{done: done}).wait(ctx); err != nil { // foreground: no link + t.Fatal(err) + } + span.End() + + for _, s := range exp.GetSpans() { + if s.Name != "WEBDAV PROPFIND" { + continue + } + if len(s.Links) != 1 || s.Links[0].SpanContext.SpanID() != refreshSpan.SpanContext().SpanID() { + t.Errorf("links = %+v, want one link to the refresh", s.Links) + } + } +} diff --git a/cmd/webdav.go b/cmd/webdav.go index 170ceff..565b44a 100644 --- a/cmd/webdav.go +++ b/cmd/webdav.go @@ -223,6 +223,33 @@ func orDetachedFetchTimeout(d time.Duration) time.Duration { return detachedFetchTimeout } +// linkRefresh links the request span of ctx to the cache.refresh trace of a +// background refresh it waited for (a lookup that joined it: a name missing +// from the expired listing, an entry past max stale): the API work the request +// waited for lives in that other trace. An invalid refresh (the fetch was not +// a background one) adds nothing. +func linkRefresh(ctx context.Context, refresh trace.SpanContext) { + if refresh.IsValid() { + trace.SpanFromContext(ctx).AddLink(trace.Link{SpanContext: refresh}) + } +} + +// startRefreshSpan opens the root span of a background cache refresh, named +// "cache.refresh", linked to the request whose lookup triggered it. +// +// The refresh runs after that request has answered from the expired entry: as +// a child of the request span it would outlive its parent, and read as if the +// request had waited for it. A trace of its own keeps the request's duration +// honest, and the link still leads from one to the other. cache is the +// retyc.cache.name of the entry (nodes, datarooms), never a path or a title. +func startRefreshSpan(ctx context.Context, link trace.Link, cache string) (context.Context, trace.Span) { + return telemetry.Tracer().Start(ctx, "cache.refresh", + trace.WithNewRoot(), + trace.WithLinks(link), + trace.WithSpanKind(trace.SpanKindInternal), + trace.WithAttributes(telemetry.AttrCacheName.String(cache))) +} + // dataroomCache is a thread-safe, TTL-based cache mapping dataroom display names to IDs. // // An expired list is served for up to maxStale more while a single background @@ -245,10 +272,14 @@ type dataroomCache struct { // dataroomFetch is a fetch of the list shared by every caller that needs it // while it runs. entry and err are written once, before done is closed. +// +// refresh is the span context of the fetch's own trace when it runs as a +// background refresh (see startRefreshSpan), invalid otherwise. type dataroomFetch struct { - done chan struct{} - entry *dataroomCacheEntry - err error + done chan struct{} + entry *dataroomCacheEntry + err error + refresh trace.SpanContext } // newDataroomCache returns a cache with the default webdav.cache settings; @@ -291,9 +322,10 @@ func (c *dataroomCache) resolve(ctx context.Context) (*dataroomCacheEntry, error return e, nil } - f := c.fetchLocked(ctx) + servable := c.servable(e) + f := c.fetchLocked(ctx, servable) c.mu.Unlock() - if c.servable(e) { + if servable { return e, nil } @@ -309,7 +341,7 @@ func (c *dataroomCache) refreshed(ctx context.Context) (*dataroomCacheEntry, err return e, nil } - f := c.fetchLocked(ctx) + f := c.fetchLocked(ctx, false) c.mu.Unlock() return f.wait(ctx) @@ -318,6 +350,8 @@ func (c *dataroomCache) refreshed(ctx context.Context) (*dataroomCacheEntry, err func (f *dataroomFetch) wait(ctx context.Context) (*dataroomCacheEntry, error) { select { case <-f.done: + linkRefresh(ctx, f.refresh) + return f.entry, f.err case <-ctx.Done(): return nil, ctx.Err() @@ -326,19 +360,32 @@ func (f *dataroomFetch) wait(ctx context.Context) (*dataroomCacheEntry, error) { // fetchLocked returns the fetch in flight, or starts one. The fetch outlives // the request that started it (it serves every waiter); a failed one leaves -// the stale list in place, and the next request starts another. The caller -// holds c.mu. -func (c *dataroomCache) fetchLocked(ctx context.Context) *dataroomFetch { +// the stale list in place, and the next request starts another. background +// is true when the caller serves the expired list instead of waiting: the +// fetch then gets a trace of its own (see startRefreshSpan). The caller holds +// c.mu. +func (c *dataroomCache) fetchLocked(ctx context.Context, background bool) *dataroomFetch { if c.incoming != nil { return c.incoming } f := &dataroomFetch{done: make(chan struct{})} c.incoming = f + link := trace.LinkFromContext(ctx) go func() { metrics.WebdavDataroomCacheRefreshes.Inc() - fctx, cancel := context.WithTimeout(context.WithoutCancel(ctx), orDetachedFetchTimeout(c.fetchTimeout)) + fctx := context.WithoutCancel(ctx) + var span trace.Span + if background { + fctx, span = startRefreshSpan(fctx, link, "datarooms") + f.refresh = span.SpanContext() + } + fctx, cancel := context.WithTimeout(fctx, orDetachedFetchTimeout(c.fetchTimeout)) items, err := c.fetchFn(fctx) cancel() + if span != nil { + telemetry.RecordError(span, err) + span.End() + } var e *dataroomCacheEntry if err == nil { e = newDataroomCacheEntry(items) @@ -748,12 +795,16 @@ type nodeCacheEntry struct { // (through promote) so the fetch starts at once: a request never waits behind // the refresh queue, and a refresh holding a slot never waits for one held by // another refresh queued behind it. +// +// refresh is the span context of the fetch's own trace when it runs as a +// background refresh (see startRefreshSpan), invalid otherwise. type nodeFetch struct { done chan struct{} promoted chan struct{} once sync.Once nodes []service.DataroomNodeInfo err error + refresh trace.SpanContext } // promote lets a queued background refresh start without a refresh slot. @@ -1128,6 +1179,8 @@ func (fs *webdavFS) listNodesRefreshed(ctx context.Context, drID, nodePath strin func (f *nodeFetch) wait(ctx context.Context) ([]service.DataroomNodeInfo, error) { select { case <-f.done: + linkRefresh(ctx, f.refresh) + return f.nodes, f.err case <-ctx.Done(): return nil, ctx.Err() @@ -1178,8 +1231,10 @@ func recordNodeCacheLookup(ctx context.Context, result string) { // nodeFetchLocked returns the listing of uri in flight, or starts one. A // background fetch (refresh of an expired listing) waits for a refresh slot -// unless a request joins it; a request's fetch promotes any fetch it joins. -// The caller holds nodeMu. +// unless a request joins it, and gets a trace of its own (startRefreshSpan); a +// request's fetch promotes any fetch it joins. A fetch the request starts +// itself runs in its trace; a background one it joins is linked from its span +// once done (linkRefresh). The caller holds nodeMu. // // The fetch is shared by every caller of this URI: it is detached from the // request that started it, so one aborted PROPFIND cannot fail the others. A @@ -1212,21 +1267,36 @@ func (fs *webdavFS) nodeFetchLocked(ctx context.Context, drID, nodePath, uri str fetch = fs.fetchNodes } detached := context.WithoutCancel(ctx) + link := trace.LinkFromContext(ctx) go func() { select { case slots <- struct{}{}: defer func() { <-slots }() case <-f.promoted: } + // The span starts once the fetch leaves the refresh queue: it + // measures the API work, and the time spent queued behind + // api.concurrency.list shows as the gap after the linked request. + fctx := detached + var span trace.Span + if background { + fctx, span = startRefreshSpan(fctx, link, "nodes") + span.SetAttributes(telemetry.AttrDataroomID.String(drID)) + f.refresh = span.SpanContext() + } // The generation is read when the fetch starts, not when it was // queued: a mutation made through this server before that is in the // API's answer, so only one landing during the fetch must discard it. fs.nodeMu.Lock() gen := fs.nodeGen[uri] fs.nodeMu.Unlock() - fctx, cancel := context.WithTimeout(detached, orDetachedFetchTimeout(fs.fetchTimeout)) + fctx, cancel := context.WithTimeout(fctx, orDetachedFetchTimeout(fs.fetchTimeout)) f.nodes, f.err = fetch(fctx, drID, nodePath) cancel() + if span != nil { + telemetry.RecordError(span, f.err) + span.End() + } fs.nodeMu.Lock() delete(fs.nodeInflight, uri) diff --git a/doc/webdav.md b/doc/webdav.md index a335742..b71004e 100644 --- a/doc/webdav.md +++ b/doc/webdav.md @@ -299,8 +299,15 @@ startup span (`retyc webdav serve init`: login check, key unlock as a parented to `TRACEPARENT` when set, then one new trace per request, named `WEBDAV `, with the API calls, the per-chunk `crypto.encrypt` / `crypto.decrypt` spans and the cache events it caused (`cache.lookup`, with -`retyc.cache.stale=true` for an expired listing served while refreshed; the -refresh itself shows as a later API call of that trace). Upload calls carry +`retyc.cache.stale=true` for an expired listing served while refreshed). The +background refresh of such a listing is not part of the request's trace: it +runs after the request has answered, as a trace of its own, `cache.refresh` +(`retyc.cache.name` `nodes` or `datarooms`, plus `retyc.dataroom.id` for a +folder listing), carrying the API calls and a span link back to the request +that triggered it. A listing the request fetches itself (nothing cached, or +past `max_stale`) stays in the request's trace; when a request has to wait for a +background refresh already running (a name missing from the expired listing), +its span gets a link to that `cache.refresh` trace instead. Upload calls carry `retyc.upload.unsafe_write`, telling whether the API was asked to store the chunk in the background; a chunk download retried on a 404 shows as successive calls of the same route. Requests are