fix(profiling): resolve web tags for descendants cached before promotion

The shared web-tags cache records "no web-server ancestor" for a span and
never revisits it, but that answer expires: plugins set `span.type` after
creating the span — TracingPlugin.startSpan activates it before addRequestTags
runs — so a child created in that window walks past an ancestor that is about
to become a web-server span, and caches a miss for a chain that is about to
have one.

Promotion can't find those descendants, since the walk only goes upwards. So a
promotion now bumps a generation counter, and an empty answer older than the
counter is walked again on the next lookup. Resolved answers are untouched (the
cached bag is the ancestor's live tag object), and a span with no parent is
stamped as permanently empty, since only its own promotion could change it and
onTagsUpdate already handles that. When a re-walk turns an empty answer into a
real one, the cache publishes resolvedCh for that span, the same announcement a
promoted span gets, so a consumer doesn't have to care which way the ancestry
appeared.

The counter lives on the trace, not in the module. A promotion can only
invalidate empty answers within its own trace, because the walk follows
`_parentId` through `_trace.started` and never leaves it — while a
process-global counter would have every HTTP request's promotion invalidate
empty answers in unrelated traces, making a long-lived non-web span re-walk its
chain once per request served elsewhere, from the storage-enter path.

Invalidation alone fixes nothing, because both consumers only ask the cache
while building their per-span state, and the spans this affects already have
theirs built. So each now asks again for state built from an empty answer:

- the OTEP-4947 writer re-checks on re-entry when a record was built with no
  web-server ancestor, and attaches the endpoint or enlists the record for the
  request's endpoint announcement. Guarded so a re-entrant announcement from
  inside the lookup can't append the endpoint twice.
- the wall profiler re-checks in #getProfilingContext when the snapshot it
  holds has no webTags, since #spanTagsUpdated only fires for a span promoted
  itself, never for descendants that walked past it beforehand.

Both re-checks cost two property reads plus, at most, the cache's own
generation compare — a walk only happens when a promotion in that trace has
actually invalidated something.

Two test-harness inaccuracies are fixed along the way, both of which had been
hiding behaviour rather than testing it: web-tags-cache.spec.js's makeSpan
returned a fresh object from context() per call, so spying on it counted calls
on a throwaway and the "walks the parent chain once" assertion held vacuously;
and wall.spec.js's makeChildSpan gave the child its own _trace object, so
parent and child were in different traces, which no real trace chunk is.

Reported by codex on #9210 and #9805.

Author: szegedi

packages/dd-trace/src/otel-thread-ctx.js

@@ -114,7 +114,14 @@ let clearContext
 
 function getOrBuildContext (span) {
   let cached = span[CachedSym]
-  if (cached !== undefined && cached.context !== undefined) return cached.context
+  if (cached !== undefined && cached.context !== undefined) {
+    // This record was built when the span had no web-server ancestor at all, so
+    // it never enlisted for an endpoint. Ask once more: webTagsCache re-walks an
+    // answer that a later promotion invalidated, and nothing else will tell us —
+    // the tags:update that promotes an ancestor is published for the ancestor.
+    if (cached.awaitingWebTags) attachEndpoint(span, cached)
+    return cached.context
+  }
   const spanContext = span.context()
   const traceId = Uint8Array.from(Buffer.from(spanContext.toTraceId(true), 'hex'))
   const spanId = Uint8Array.from(Buffer.from(spanContext.toSpanId(true), 'hex'))
@@ -137,10 +144,29 @@ function getOrBuildContext (span) {
     span[CachedSym] = cached
   }
   cached.context = new ThreadContext(traceId, spanId, attrs)
+  cached.awaitingWebTags = webTags === undefined
   if (endpoint === undefined) awaitEndpoint(webTags, cached)
   return cached.context
 }
 
+// Give a record its endpoint now that its span's web-server ancestry is known:
+// write the value if it has settled, otherwise enlist for the announcement that
+// it has. A no-op while the span still has no web-server ancestor.
+function attachEndpoint (span, cached) {
+  const webTags = webTagsCache.getCachedWebTags(span)
+  // The lookup above can announce the resolution synchronously, and the handler
+  // for that announcement lands right back here — so re-read the flag rather than
+  // appending a second copy of the endpoint.
+  if (webTags === undefined || !cached.awaitingWebTags) return
+  cached.awaitingWebTags = false
+  const endpoint = finalEndpoint(webTags)
+  if (endpoint === undefined) {
+    awaitEndpoint(webTags, cached)
+  } else {
+    appendEndpoint(cached.context, endpoint)
+  }
+}
+
 // Enlist a record built without an endpoint, so the resolution announcement for
 // its request fills it in.
 function awaitEndpoint (webTags, cached) {
@@ -231,21 +257,14 @@ function onEndpointResolved (span) {
   }
 }
 
-// A span whose record was built before it looked like a web-server span at all
-// has just been recognized as one, so it has no endpoint and never enlisted for
-// this request. Its ancestry can't have changed, only its own tags, so this is
-// only ever about the announced span's own record.
+// A span whose record was built before it had any web-server ancestry now has
+// some — either because the span itself was recognized as a web-server span, or
+// because an ancestor was and webTagsCache re-walked this span's empty answer.
 function onWebTagsResolved (span) {
   if (!started) return
   const cached = span[CachedSym]
   if (cached === undefined || cached.context === undefined) return
-  const webTags = webTagsCache.getCachedWebTags(span)
-  const endpoint = finalEndpoint(webTags)
-  if (endpoint === undefined) {
-    awaitEndpoint(webTags, cached)
-  } else {
-    appendEndpoint(cached.context, endpoint)
-  }
+  attachEndpoint(span, cached)
 }
 
 // Every otelThreadCtx member the writer calls, checked before it starts. Anything

packages/dd-trace/src/profiling/profilers/wall.js

@@ -273,6 +273,12 @@ class NativeWallProfiler {
 
       profilingContext = { spanId, rootSpanId, webTags }
       span[ProfilingContext] = profilingContext
+    } else if (this.#endpointCollectionEnabled && profilingContext.webTags === undefined) {
+      // Snapshotted before this span had a web-server ancestor. #spanTagsUpdated
+      // only fires for a span promoted to web-server itself, not for descendants
+      // that walked past it beforehand, so ask again — the shared cache re-walks
+      // an answer a later promotion invalidated and answers from cache otherwise.
+      profilingContext.webTags = webTagsCache.getCachedWebTags(span)
     }
     return profilingContext
   }

packages/dd-trace/src/web-tags-cache.js

@@ -40,13 +40,40 @@ const dc = require('dc-polyfill')
 const { finalEndpoint, isWebServerSpan, getStartedSpans } = require('./profiling/webspan-utils')
 
 // Fields on the cache entry:
-//   resolved:      true once the parent-chain walk has run.
-//   webTags:       the resolved tag bag, or undefined when the walk came up
-//                  empty (no web-server span found in the started-spans chain).
-//   endpointFinal: true once this span is a web-server span whose endpoint name
-//                  has settled and endpointResolvedCh has been published for it.
+//   resolved:       true once the parent-chain walk has run.
+//   webTags:        the resolved tag bag, or undefined when the walk came up
+//                   empty (no web-server span found in the started-spans chain).
+//   missGeneration: for an empty answer, the generation it was computed at, or
+//                   PERMANENT_MISS when no later promotion can change it.
+//   endpointFinal:  true once this span is a web-server span whose endpoint name
+//                   has settled and endpointResolvedCh has been published for it.
 const CachedSym = Symbol('WebTagsCache')
 
+// A resolved answer is permanent, but an empty one is not: plugins commonly set
+// `span.type` after creating the span (TracingPlugin.startSpan activates the span
+// before addRequestTags runs), so a descendant that looked itself up in that
+// window recorded "no web-server ancestor" for a chain that is about to have
+// one. Promoting the ancestor can't find those descendants — the walk only goes
+// upwards — so instead a promotion bumps a counter, and an empty answer older
+// than the counter gets walked again on the next lookup.
+//
+// The counter lives on the trace rather than in this module, because a promotion
+// can only invalidate empty answers within its own trace: the walk follows
+// `_parentId` through `_trace.started` and never leaves it. A process-global
+// counter would make every HTTP request's promotion invalidate empty answers in
+// unrelated traces, and consumers re-check from storage-enter — so a long-lived
+// non-web span would re-walk its chain once per request served elsewhere.
+const GenerationSym = Symbol('WebTagsCache.generation')
+
+// Stamp for an empty answer no promotion can change: a span with no parent can
+// only gain web-server tags on itself, and onTagsUpdate already handles that.
+// Never equal to a generation, which starts at 0 and only grows.
+const PERMANENT_MISS = -1
+
+function traceGeneration (trace) {
+  return trace[GenerationSym] ?? 0
+}
+
 const tagsUpdateCh = dc.channel('dd-trace:span:tags:update')
 const resolvedCh = dc.channel('dd-trace:web-tags:resolved')
 const endpointResolvedCh = dc.channel('dd-trace:web-tags:endpoint-resolved')
@@ -66,8 +93,14 @@ function getCache (span) {
 // the result on the span.
 function getCachedWebTags (span) {
   const cached = getCache(span)
-  if (cached.resolved) return cached.webTags
+  // A resolved answer is never revisited: the cached bag is the ancestor's live
+  // tag object, so later tag changes are already visible through it.
+  if (cached.resolved && cached.webTags !== undefined) return cached.webTags
   const spanContext = span.context()
+  if (cached.resolved && !isStaleMiss(cached, spanContext._trace)) return
+  // Distinguishes a first walk from re-walking an answer consumers have already
+  // seen and may have built something from.
+  const wasMiss = cached.resolved
   const tags = spanContext.getTags()
   let webTags
   if (isWebServerSpan(tags)) {
@@ -85,9 +118,25 @@ function getCachedWebTags (span) {
   }
   cached.webTags = webTags
   cached.resolved = true
+  if (webTags === undefined) {
+    cached.missGeneration = spanContext._parentId == null
+      ? PERMANENT_MISS
+      : traceGeneration(spanContext._trace)
+  } else if (wasMiss) {
+    // An empty answer turned into a real one. Consumers that snapshotted the
+    // empty one get the same announcement a promoted span gets, so neither has to
+    // special-case how the ancestry appeared.
+    resolvedCh.publish(span)
+  }
   return webTags
 }
 
+// Whether an empty answer predates a promotion in its own trace, and so has to be
+// walked again.
+function isStaleMiss (cached, trace) {
+  return cached.missGeneration !== PERMANENT_MISS && cached.missGeneration !== traceGeneration(trace)
+}
+
 // Own the tagsUpdate → transition promotion here. The dc subscribe
 // happens lazily via activate(); each active consumer bumps a refcount,
 // the last deactivate() removes the subscription. When idle, this module
@@ -97,10 +146,16 @@ function getCachedWebTags (span) {
 function onTagsUpdate (span) {
   const cached = span[CachedSym]
   if (cached === undefined || !cached.resolved) return
-  const tags = span.context().getTags()
+  const spanContext = span.context()
+  const tags = spanContext.getTags()
   if (cached.webTags === undefined) {
     if (!isWebServerSpan(tags)) return
     cached.webTags = tags
+    // This span may be the ancestor a descendant walked past before it counted as
+    // a web-server span, so every empty answer computed in this trace until now is
+    // suspect. Other traces can't have walked through it.
+    const trace = spanContext._trace
+    trace[GenerationSym] = traceGeneration(trace) + 1
     resolvedCh.publish(span)
   }
   // Endpoint finality is a property of the web-server span itself: for a

packages/dd-trace/test/otel-thread-ctx.spec.js

@@ -596,6 +596,81 @@ describe('otel-thread-ctx', () => {
       assert.equal(context.appendAttributes.firstCall.args[0][1], 'GET /x')
     })
 
+    it('appends the endpoint on re-entry to a record built with no web-server ancestor', () => {
+      // The record was built while the span had no web-server ancestry at all, so
+      // it never enlisted for a request. An ancestor being promoted afterwards is
+      // announced for the ancestor, not for this span, and webTagsCache only
+      // re-walks when asked — so re-entry is what has to notice.
+      const webTags = { 'span.type': 'web', 'http.method': 'GET', 'http.route': '/x' }
+      activeSpan = makeSpan({ tags: {} })
+      enterCh.publish()
+      const context = constructedContexts[0]
+      assert.strictEqual(context.attributes[1], undefined)
+
+      cachedWebTags.set(activeSpan, webTags)
+      enterCh.publish()
+      sinon.assert.calledOnce(context.appendAttributes)
+      assert.equal(context.appendAttributes.firstCall.args[0][1], 'GET /x')
+      assert.equal(constructedContexts.length, 1)
+    })
+
+    it('waits for the endpoint on re-entry when the ancestry resolves before the route', () => {
+      // Re-entry finds an ancestor but no settled endpoint yet, so the record has
+      // to join the request's waiting list — the announcement then names the
+      // ancestor, whose tag bag is the key it is waiting under.
+      const { parent, child, webTags } = makeWebSpanWithChild({ 'span.type': 'web', 'http.method': 'GET' })
+      activeSpan = child
+      enterCh.publish()
+      const context = constructedContexts[0]
+      assert.strictEqual(context.attributes[1], undefined)
+
+      cachedWebTags.set(child, webTags)
+      enterCh.publish()
+      sinon.assert.notCalled(context.appendAttributes)
+
+      webTags['http.route'] = '/x'
+      endpointResolvedCh.publish(parent)
+      sinon.assert.calledOnce(context.appendAttributes)
+      assert.equal(context.appendAttributes.firstCall.args[0][1], 'GET /x')
+    })
+
+    it('does not append twice when re-entry and the announcement coincide', () => {
+      // getCachedWebTags can publish the resolution synchronously, landing the
+      // announcement handler in the same code path the re-entry is running.
+      const webTags = { 'span.type': 'web', 'http.method': 'GET', 'http.route': '/x' }
+      activeSpan = makeSpan({ tags: {} })
+      enterCh.publish()
+      const context = constructedContexts[0]
+
+      cachedWebTags.set(activeSpan, webTags)
+      // As the real cache does: the lookup that turns an empty answer into a real
+      // one announces it, once, from inside the lookup.
+      let announced = false
+      webTagsCacheStub.getCachedWebTags = span => {
+        const tags = cachedWebTags.get(span)
+        if (tags !== undefined && !announced) {
+          announced = true
+          webTagsResolvedCh.publish(span)
+        }
+        return tags
+      }
+      enterCh.publish()
+      sinon.assert.calledOnce(context.appendAttributes)
+      assert.equal(context.appendAttributes.firstCall.args[0][1], 'GET /x')
+    })
+
+    it('stops re-asking once a record has its endpoint', () => {
+      const webTags = { 'span.type': 'web', 'http.method': 'GET', 'http.route': '/x' }
+      activeSpan = makeSpan({ tags: {} })
+      enterCh.publish()
+      cachedWebTags.set(activeSpan, webTags)
+      enterCh.publish()
+      const lookups = sinon.spy(webTagsCacheStub, 'getCachedWebTags')
+      enterCh.publish()
+      enterCh.publish()
+      sinon.assert.notCalled(lookups)
+    })
+
     it('endpoint announcements are a no-op for a span that has not been entered', () => {
       const { parent, webTags } = makeWebSpanWithChild(
         { 'span.type': 'web', 'http.method': 'GET', 'http.route': '/x' })

packages/dd-trace/test/profiling/profilers/wall.spec.js

@@ -804,15 +804,19 @@ describe('profilers/native/wall', () => {
     function makeChildSpan (webSpanId, webSpan) {
       const tags = { 'span.type': 'router' }
       const spanId = {}
+      // Shares the parent's _trace, as spans of one trace chunk do: it is the
+      // object holding the started-spans list the parent walk reads, and what the
+      // shared cache scopes its per-trace bookkeeping to.
+      const trace = webSpan.context()._trace
       const ctx = {
         _tags: tags,
         _spanId: spanId,
         _parentId: webSpanId,
-        _trace: { started: [webSpan] },
+        _trace: trace,
         getTags () { return this._tags },
       }
       const span = { context: () => ctx }
-      ctx._trace.started.push(span)
+      trace.started.push(span)
       return { span, tags }
     }
 
@@ -907,6 +911,36 @@ describe('profilers/native/wall', () => {
       profiler.stop()
     })
 
+    it('should refresh a child snapshot taken before its parent became a web span (ACF path)', () => {
+      // The reverse order of the test below: the child is activated first, so its
+      // snapshot records "no web-server ancestor". The parent's later promotion is
+      // announced for the parent, so #spanTagsUpdated never sees the child, and
+      // the endpoint label would be lost for the rest of the child's life.
+      const { span: webSpan, tags: webSpanTags, spanId: webSpanId } = makeWebSpan()
+      const { span: childSpan } = makeChildSpan(webSpanId, webSpan)
+
+      const profiler = makeWall(WallProfiler, {
+        endpointCollectionEnabled: true,
+        codeHotspotsEnabled: true,
+        asyncContextFrameEnabled: true,
+      })
+      profiler.start()
+
+      currentStore = { span: childSpan }
+      enterCh.publish()
+      const childCtx = localPprof.time.setContext.lastCall.args[0]
+      assert.strictEqual(childCtx.webTags, undefined)
+
+      webSpanTags['span.type'] = 'web'
+      tagsUpdateCh.publish(webSpan)
+
+      // Re-activating the child is what notices, via the shared cache's re-walk.
+      enterCh.publish()
+      assert.strictEqual(childCtx.webTags, webSpanTags)
+
+      profiler.stop()
+    })
+
     it('should propagate webTags to child spans after tags update resolves parent (ACF path)', () => {
       const { span: webSpan, tags: webSpanTags, spanId: webSpanId } = makeWebSpan()
       const { span: childSpan } = makeChildSpan(webSpanId, webSpan)