feat(telemetry): span the transition pipeline end to end, and remove the redundancy it exposed - #920
Merged
Merged
Conversation
Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
…gging Extract SetStepError(Activity?, string) on PipelineStepActivityHelper so TransitionExecutor's two error paths (failed StepOutcome, unhandled exception) route through a directly-testable helper instead of inline SetStatus calls. Behavior unchanged. Adds unit coverage for the error paths and for StepOutcome.Stop() -> "stop" tagging, both previously unverified. Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
… always on Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
…rses no-compile-span decision) Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
…g scripts Wrap the three undelimited script-execution call sites (ResourceLockStep key resolution, SubflowStarter input mapping, SubflowOutputMappingService output mapping) with ScriptActivityHelper.StartExecuteActivity, tagging vnext.script.kind as lockKey / subflowInputMapping / subflowOutputMapping respectively. Task mappings remain unwrapped since Task.PrepareInput/ ProcessOutput already delimit them. Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
…unnel Adds Lock.Acquire around InstanceStatusLock.AcquireAsync (vnext.lock.key, vnext.lock.acquired, vnext.lock.lease_seconds) and Lock.Release around TransitionLockScope.DisposeAsync (vnext.lock.key). Contention (no handle acquired) is tagged vnext.lock.acquired=false without an error span status, since contention is an expected outcome, not a failure. Pure additions — the single-attempt TryAcquireLockAsync semantics, comment block, logger calls, and TransitionLockScope construction are unchanged. Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
…eFactory funnel TransitionLockScopeFactory.AcquireAsync constructs handle-bearing TransitionLockScope instances whose DisposeAsync already emits Lock.Release, but the factory's own acquire path emitted no matching Lock.Acquire — every successful acquisition on the auto-chain-budget lock funnel produced an orphan Release span. Wraps the whole AcquireAsync call (not each internal retry attempt) in one Lock.Acquire span, tagged with the factory's lease seconds up front and vnext.lock.acquired=true/false on the acquired/exhausted exit paths respectively; no error status on contention, matching InstanceStatusLock's existing behavior. Pure addition — loop, backoff, logger calls and TransitionLockScope construction are unchanged. Also fixes InstanceStatusLockActivityTests to filter observed spans by lock key (not just DisplayName): the BBT.Workflow.Pipeline ActivitySource is process-wide, and adding a second test class on the same source exposed cross-talk under xUnit's parallel test execution. Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
Wraps TransitionContextFactory.CreateAsync's railway chain in a Transition.LoadContext span, its instance rehydration hop in an Instance.Load span, and TransitionValidationService.ValidateAsync in a Transition.Validate span. All three close on both success and failure, setting Error status only on failure; CreateAsync becomes async to hold the span across the whole chain. Behavior of the railway chain is unchanged. Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
…funnel Adds StartAppendActivity, an extracted internal helper on InstanceDataWriteService, starting an Instance.AppendData span tagged with vnext.data.version and vnext.data.size_bytes around AppendAsync and AppendExplicitAsync. Size is the UTF-8 byte count of the normalized JSON, never the payload content itself. Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
…isibility Verified the three cache-span claims from the trace-span-tree design spec: IsVerbose gating and diagnostic category were failing (fixed in CacheActivityHelper, following the Task 3 PipelineStepActivityHelper precedent), while L1-hit tagging and L2 read-duration visibility already held. Added docs/runtime/trace-span-tree.md as the full span-name -> source -> tags reference, the AdditionalSources same-commit registration rule, and the note on the 2026-08-25 reversal of the script-perf "no compile span" decision, linked from docs/README.md's reading path. Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
…ompile span starts Script.Compile is started with an explicit parent context, so its own Activity.Parent is null. Resolving the accumulator target lazily from Activity.Current after that span became current made the ancestor walk terminate on the compile span itself, silently relocating the vnext.script.compile.* tags and script.compile event off the task span. CompileCoreAsync now captures FindTargetActivity()'s result before starting the span and threads it through every Record call explicitly. Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
InstanceStatusLock (status) and TransitionLockScopeFactory (chain) produce identical Lock.Acquire/Lock.Release spans with no way to tell which funnel emitted them. TransitionLockScope now carries its kind and tags it on both the Acquire span and the Release span at Dispose. Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
…vnext.script.key trace-span-tree.md claimed rule/condition/view/event call sites exist for Script.Execute; only lockKey, subflowInputMapping and subflowOutputMapping actually do (verified against every StartExecuteActivity call site). Also documents the new vnext.lock.kind tag on Lock.Acquire/Lock.Release and the new vnext.script.key tag on Script.Compile's miss path, plus the controller ruling that Script.Execute intentionally carries no script-identity tag. Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
Cache.Get/{key}, Lock.Acquire/{key} and Lock.Release/{key} put the subject of
the operation in the span name, so a trace tree shows which component was read
and which key a hop contended on without opening the span. The cache.key /
vnext.lock.key tags stay for querying. A keyless cache operation (warmup,
batch) keeps its bare operation name.
Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
…transition/{key} node
The job span IS the APM transaction, so it now carries the transition key:
TransitionJob.Execute/{key}. That makes the [Trace]-aspect span underneath it
(renamed to transition/{key} by EnrichTelemetry) pure indirection between the
transaction and its step spans, so the aspect and the rename are both removed.
Side benefit: the shape no longer depends on PostSharp weaving being active --
with weaving off the rename used to land on the ambient job/server span.
A chained hop is a different transition under the same transaction, so
TransitionPipeline opens a Transition.{key} group span from hop 2 onwards --
which also gives EnrichTelemetry a per-hop span to tag instead of every hop
overwriting the transaction's tags.
Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
A transition runs ~20 steps but most of them only check an applicability guard and continue: no lock taken, no task run, no data written. Each still produced a zero-duration span, which is the bulk of a transition's span count and the noise that hides the steps that actually did something. Steps now report StepOutcome.ContinueNoWork() from their guards, and PipelineStepActivityHelper drops the span by clearing Recorded -- the same mechanism Aether's BusinessSpanFilterProcessor uses, so exporters skip it while it stays valid in-process. Flow control is unchanged: NoWork behaves exactly like Continue. Deliberately still recorded: RunAutomaticTransitionsStep's no-winner exit (it evaluated rules -- scripts ran) and every post-work return. Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
…naming and no-op steps Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
…itionExecutor Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
Trace-driven analysis of c4cd78d3 (25 transactions, 665 spans): inventory of repeated flow/schema/instance reads, four root causes with code references, and a ranked list of what is worth fixing. Records the cold-start caveat and the finding that script compilation, not component reads, dominates this trace. Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
The interface was added for a SchemaValidationAttribute aspect (d680b4a); that aspect was deleted in 23a7acb and the ambient holder outlived it, leaving two writers, three readers and ~15 test doubles behind. Every reader already had the definition available from its caller: - InstanceCommandAppService's memo compared the KEY only, so a request pinning a version silently got whatever the scope held. Deleted; the component cache already answers a repeat read in-process. - PostCommitParentMutationService takes it from PostCommitParentSnapshot, which is built where context.Workflow is in hand. A definition is immutable and cache-backed, so unlike the parent aggregate it crosses the lock handoff safely. - InstanceDataWriteService takes it as an argument; callers that never had a workflow in scope pass null and keep skipping master-schema validation exactly as before. That silent skip is now visible per call site instead of hidden. Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
…per layer A transition resolved its flow three times: at intake, again when the runner opened the workflow scope, and again in the pipeline's context factory. Each resolution paid a generation-token round trip (~3.7ms) plus a full deserialize of the definition from the L1 byte cache (0.5-1.7ms for a flow) -- 68 flow reads for 3 distinct flows in the analysed trace. WorkflowExecutionContext now carries the definition resolved for its OWN Domain/WorkflowKey/WorkflowVersion. Because the value only ever comes from a resolution made with those same three fields, a consumer asking with them cannot get a different definition than it would have loaded itself, so no version-spelling comparison is needed. The scope helper takes the context as a carrier: it reuses a carried definition and otherwise publishes its own load onto it, keeping the load inside the schema scope where a cache miss may reach the database. Transport-only: [JsonIgnore] and absent from TransitionJobPayload, so a job re-entry resolves fresh rather than inheriting a definition across a hop. Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
Every transition request validated its payload twice: once at intake and again at the execution entry. Both resolved the schema component and ran the validator over the same bytes, and the intake built a full TransitionExecutionContext to do it -- which it then threw away. Validation now belongs to the execution entry, which is where the 400-before-any-side-effect guarantee actually lives: the async strategy validates before it flips Busy and enqueues, the sync pipeline before it admits. The intake's Busy fast-fail is a different check and is untouched. START keeps validating early -- it has to, before the instance row is persisted -- and says so with WorkflowExecutionContext.PayloadSchemaValidated so the entry below runs policy only. A job re-entry (IsPreReserved) skips the schema for the same reason: the accept already validated that payload. Both markers are transport-only and never cross a hop. Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
…gregate The intake loaded the full instance (AsSplitQuery + two includes, ~20ms) purely to build the validation context it no longer needs. Everything left in the intake -- the dispatch context and the response headers -- reads Id/Flow/FlowVersion/Key, which the admission projection above it already carries. The execution entry loads the aggregate for real, in its own scope and DbContext; that copy could never have been handed across the boundary anyway, so the intake load was a second round trip for nothing. The two answers the aggregate load used to produce are reproduced from the projection: InstanceNotFound verbatim (same code and message as GetResultAsync -- WorkflowErrors.InstanceNotFound is a DIFFERENT code despite its name), and the terminal rejection via a new InstanceExecutionSnapshot.IsTerminal, which counts Faulted and Passive as terminal exactly as Instance.IsCompleted does. Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
…-start or per-request Ran the money-transfer flow twice against one warm orchestration process (no restart between runs) and compared Script.Compile/* spans in Elastic. All 6 script identities exercised (including the RequirePushRule and ExecutionSucceededRule auto-transition rules) compiled exactly once, in run 1 only; run 2 showed 100% cache hits. Verdict: cold start, not an unstable cache key -- the follow-on parallelization task should be skipped.
Fix-wave from the final whole-plan code review, conditional on merge:
1. script-compile-measurement-2026-08-27.md: the measurement only
exercised the plain compile path. money-transfer (the flow used) has
no `helpers` in any component JSON, so the helper-set compile path
(ConditionalWeakTable-memoized, ~2s cold cost per the perf docs) was
never exercised. Cold-start verdict stands for the plain path only.
2. trace-span-tree.md: ScriptCode.TraceIdentity is a readable label, not
a unique key. `Location` is component-relative, not domain/flow
namespaced — confirmed two real collisions in vnext-example today
(./src/AlwaysTrueRule.csx across subflow-orchestration vs.
chain-busy/contract-signing; ./src/UserSessionMapping.csx across
account-opening's Extension vs. its Workflow). Documented the
existing mitigation: vnext.script.key still disambiguates precisely
on the miss path, since it is the evaluator's actual cache key.
3. ScriptCode.cs / ScriptActivityHelper.cs: the "allocation-free" wording
no longer held literally — $"Script.Compile/{identity}" is built
unconditionally before StartActivity, so it allocates even with no
listener attached. Corrected the wording (identity itself costs
nothing to obtain; the span-name interpolation is the one small
allocation) without restructuring the code.
Also: added a comment at AutoConditionEvaluator's
GetOrBuildScriptContextAsync call site (invoked once per candidate
transition in RunAutomaticTransitionsStep's foreach) pointing at
IncrementCounterTag's unsynchronized read-modify-write, so a future
parallelization of that loop doesn't silently race the memo-hit counter.
Documentation and comments only — no behavior change, no test change.
Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Two repos, one chain. vnext gains a span per hook invocation (landing under Uow.Commit for DurablePostCommit mode, since CompositeUnitOfWork invokes OnCompleted handlers inside CommitAsync — verified at CompositeUnitOfWork.cs:313). Aether — change USER-APPROVED 2026-08-27, recorded in the spec — persists the drop's trace identity into OutboxMessage.ExtraProperties and re-parents Outbox.Process into it, mirroring what the inbox's EventTraceScope already does. The analysis found more already working than expected: TraceParent is stamped on payloads at publish, and all 10 inbox handlers re-join the originating trace via EventTraceScope — the outbox worker hop was the only unlinked node. The plan is honest about the packaging gap: vnext consumes Aether from nuget.org only, so the Aether half is unit-test-pinned now and live-verifiable only after the next Aether release; the verification task records that gate in the docs instead of claiming it. Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Wraps HookedDistributedEventBus.ExecuteHooksAsync's invoker loop with a
per-hook EventHook.{name} span (source BBT.Workflow.Instances.Events),
tagged with the event name, full hook name, and hook mode, and error
status on failure/throw. The span parents implicitly to whatever is
ambient (Uow.Commit for DurablePostCommit, Events.PublishDeferred for
HandledOrFallback), so a hook's own remote calls attribute to it
instead of the surrounding commit. Adds the Execution host's missing
AdditionalSources entry and documents the new span.
…er release gate
Adds docs/runtime/event-trace-chain.md: the full publish -> hook ->
outbox -> handle chain, which repo owns which span, live Elastic
evidence for Task 1's EventHook.{name} spans (DurablePostCommit
parented under Uow.Commit, HandledOrFallback under
Events.PublishDeferred, tags confirmed, EventTraceScope regression
guard confirmed via a shared trace id with the inbox worker's
{Event}.Handle span), and an honest release-gate section for Task 2
(outbox.message_id / Outbox.Process re-parenting) which is not yet
observable since vnext consumes Aether 1.0.36 from nuget.org. Also
reports the one thing that did not verify: no HttpClient/Dapr span
was seen as a direct child of a hook span in this run, because
FuturePayTests' subflows are all same-domain and
IInstanceCommandGateway routes them in-process.
Links the new page from docs/runtime/trace-span-tree.md.
Starting the per-hook span with an explicit parent context (Activity.Current?.Context) left Activity.Parent null, and GetBaggageItem walks Parent — so baggage set on the ambient activity (e.g. RootInstanceId) silently vanished inside every hook, even though the span's displayed ParentId still matched. Use the implicit-parent overload instead: same parenting, intact baggage chain. Strengthens the hook-span parentage test to assert baggage is visible inside the hook (not just that ParentId matches), and fixes a stray "Immediate" left over from an earlier EventHookMode naming pass in the event-hook-trace spec doc. Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
…e.Load gap
Five tasks. Discovery's ~400 lines of bulk-cache/ETag machinery come out and every
cross-domain resolution asks the registry directly, wrapped in one
Discovery.Resolve/{domain} span that surfaces at all 32 call sites via ambient
parenting. Registration stays in the hosted service but is guarded by a
non-blocking TryAcquireLockAsync whose lease is deliberately NOT released on
success -- replicas start seconds apart, so releasing would let the next one
re-register and defeat the guard. Timeout 30s -> 5s, since it now sits in front of
every hop rather than a rare miss.
The Instance.Load question is answered by measurement rather than reasoning: over
300 live spans the gap is ~entirely LEADING (mean lead 0.60ms, trail 0.03ms),
which refutes the materialization hypothesis. Db.SELECT is command-level
instrumentation, so the parent is measured correctly and the children simply do
not cover the pre-command window. Task 5 names that window and documents how to
read both outcomes.
Accepted risk recorded in the spec: the state function resolves cross-domain
subflows on every long-poll, replacing ~1 discovery call per 5 minutes with one
per poll. The new span makes the real rate measurable.
Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
The bulk domain cache's staleness risk (routing to a moved or dead endpoint for up to 5 minutes) is not worth its latency saving. GetEndpointAsync now queries the discovery registry directly on every call; RefreshBulkCacheAsync and all ETag/bulk-cache machinery are removed from IDomainDiscoveryResolver and DomainDiscoveryResolver. The utility refresh endpoint becomes a deprecated no-op (route kept for existing runbooks), and the discovery-init hosted service no longer calls the removed RefreshBulkCacheAsync.
DomainDiscoveryResolver.GetEndpointAsync is called from 32 sites (trigger
task executors, RemoteInstance*AppServices, RemoteAuthorizeAppService,
RemoteRelatedInstanceReader) but had no span of its own — the discovery
HTTP call showed up as an unattributed HttpClient span wherever it
happened to be ambient. Now every resolution opens a Discovery.Resolve/
{domain} span, tagged with vnext.discovery.domain and
vnext.discovery.endpoint_kind, error-statused on disabled discovery, 404,
and transport failures.
Reuses PipelineStepActivityHelper.ActivitySource (BBT.Workflow.Pipeline)
rather than declaring a new one: it is already registered in every host's
Telemetry:Tracing:AdditionalSources, so the span cannot be silently
invisible for lack of registration. Started with the implicit-parent
overload (name + kind only) — an explicit Activity.Current?.Context leaves
Activity.Parent null and severs the baggage chain, the exact bug just
fixed for the event-hook span on this branch.
Extends DomainDiscoveryResolverTests (from the prior cache-removal task)
with a span-focused test class covering: exactly one span per resolution,
domain/endpoint-kind tags, error status on a 404, and parenting to the
ambient activity. Widened CreateSut/SuccessResponse/RoutingHandler to
internal so the new test class can share them.
Documents the new span row in docs/runtime/trace-span-tree.md, noting
that discovery is queried on every resolution (no cache), so this span's
rate is the true cross-domain resolution rate.
Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
- pin no-release-on-success against DisposeAsync too, not just ReleaseAsync - skip the lock entirely when discovery is disabled, so a disabled pod cannot strand the once-per-rollout lease during an Enabled:false->true rollout - replace the remaining raw logger.LogInformation/LogCritical in RunAsync with WorkflowLogs entries (50012-50015), matching the region's convention
Wraps WithDetailsAsync() in EfCoreInstanceRepository's three identifier finders with an Instance.Query.Prepare span, splitting Instance.Load's leading gap (mean 0.60ms, p90 2.40ms, max 88ms across 300 live spans) into DbContext/connection acquisition versus everything else. Db.SELECT only starts at CommandExecuting, so that window was previously anonymous. Uses PipelineStepActivityHelper.ActivitySource.StartActivity directly with the implicit-parent overload (same pattern as DomainDiscoveryResolver) rather than StartOperationActivity, which passes an explicit parent context and severs the baggage chain. Adds a unit test pinning the span's nesting under Instance.Load, and documents how to read the measurement in docs/runtime/trace-span-tree.md.
…pted risks Final review found the spec's worst-case discovery timing wrong: the retry backoff is exponential (1s/2s/4s), and client.Timeout wraps the whole retry sequence since the timeout policy is registered outermost. Corrects the "Decisions taken" bullet to say the 5s bound caps the entire sequence (not per-attempt), notes .Or<TimeoutRejectedException>() in the retry policy is now dead code, and that MaxRetryAttempts is effectively decorative under the 5s outer bound. Adds a matching comment next to the AddPolicyHandler chain. Also records two previously-undocumented accepted risks: an open circuit breaker now silently serves parent transitions instead of subflow ones on every cross-domain long-poll (InstanceQueryAppService.cs:574), and the parked TryAcquireLockAsync null-ambiguity finding plus the reviewer's proposed (not implemented) vnext-only alternative, left for approval. No behavior, policy value, retry count, or test changed.
… transition path Removes T+H+1 SELECTs from a normal task-carrying transition (T = tasks persisting output, H = hooks with tasks): - The three task hooks (OnExecute/OnExit/OnEntry) ran GetSuccessfulTaskIdsAsync unconditionally, but a transition record inserted by this very pipeline run cannot have journal rows — the same fresh-record signal that already skips the per-task probe now skips the per-hook bulk query too. Retries (reused record) still query, and the fresh path no longer lets one hook's completed task ids leak into another hook's bypass list. - FinalizeTransitionStep re-read the transition record (jsonb bodies included) although CreateTransitionRecordStep had already put it on the context: the carried record is used first, the read-only lookup stays as the resume/recovery fallback. Item keys move to WellKnownItems constants. After the set-based completion UPDATE the tracked entry is marked Unchanged so an ambient SaveChanges cannot issue a duplicate UPDATE. - A strategy append whose planned version differs from the head starts a NEW semantic-version line, so its VersionNo is 1 by definition — the MAX(VersionNo) query now runs only for same-version appends and the explicit-version path, which can genuinely extend an old line. - FlowTimeoutJobHandler's post-pipeline instance re-read fed the removed prometheus timeout metric and nothing else — a cartesian full-detail load per timeout with no remaining consumer. Deleted. Suites match the known baseline (zero new failures). Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
…swered Two gaps in the cache-aside path. The write-back after a read miss went through a private helper that emitted nothing, so the distributed write was folded anonymously into the Cache.Get that missed -- and because that write's failure is deliberately swallowed (a cache that cannot be written is still a correct read), a persistently unwritable cache left no trace at all outside the log. It now gets a Cache.Write span, error-statused on failure. The name is deliberately not Cache.Set: that one is a caller publishing, this is traffic the read path creates for itself. Second, which layer answered a read had to be inferred from a cache.hit + cache.l1.hit combination. cache.source states it outright -- l1, l2 or backend -- at every exit of both read paths. A negative counts as l2: the distributed store is what told us the version does not exist. Also fixes a latent defect this work exposed. CacheActivityHelperTests asserted Assert.Single over a process-wide ActivityListener, so any cache span emitted by a concurrently-running test landed in its list. It passed only because nothing else emitted cache spans; the new tests do. Both suites now anchor each test to its own root activity and filter on the trace id. Application.Tests 16 failures and Domain.Tests 27 -- identical to the pre-change baselines, no new failing name. Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
A Preprod fault (trace 7873ad4e6c7a9db31c3b6401cd2c54fc) surfaced when two extensions on one workflow referenced the same task: both executions wrote under the same task-derived variable name and the parallel merge rejected the second. The decisive finding is why the obvious fix is wrong. Deduplicating a shared task looks right until you read OnExecuteTask: it carries Mapping and ErrorBoundary per ENTRY while Task is only a Reference, so two extensions can share a task definition and apply different output mappings. Their outputs are supposed to differ -- collapsing them would hand one extension the other's data. The conflicting values are correct; the shared variable NAME is the defect. The defect is also wider than the crash. ExtractExtensionResponse reads the output by task key and files it under the extension key, so two extensions sharing a task can never produce distinct output even without parallelism, and FindFailedExtensionKey misattributes failures for the same reason. The sequential write path overwrites silently, which means the parallel merge is the only thing that catches any of this -- luck, not design. Task 1 is an inventory that can stop the plan: moving where an extension task's output is filed is only safe if nothing reads it by task key, and the spec requires that be verified rather than assumed. Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Task 1 of the extension-response-key plan: searched vnext-example .csx, this repo's docs/ai-docs, vnext-docs, in-repo C# reads, and .claude/rules for anything reading an Extension task's TaskResponse/OutputResponse by task-derived key. Found none. FunctionAppService reads these dictionaries by task key too and is documented for authors, but belongs to a different TaskExecutionOrigin whose call site the planned fix does not touch - flagged as an implementation caution, not a blocker.
TaskEngineExecutionOptions gains ResponseVariableKey (null = derive from the task key, as today). TaskExecutorBase's two derivation points (SetOutputResponse for Extension-trigger OutputResponse, and UpdateScriptContextWithResponse for TaskResponse — the site the Preprod crash traced back to) now honor it when set, threaded through TaskExecutorContext.ResponseVariableKey. Gated strictly on the opt-in option, never on TaskTrigger.Extension: custom Functions also run with that trigger and read their task output by task key, so branching on the trigger would silently break them. Every existing caller leaves the option null and is byte-identical. TaskCoordinator.ExecuteWithDetailsAsync gains an optional per-task Func<OnExecuteTask, TaskEngineExecutionOptions, TaskEngineExecutionOptions> refiner, applied after the existing duplicate-task-key JournalTaskKey disambiguation so the two compose. Chosen over a task+options pairs overload because it fits the internal per-Order grouping without threading tuples through the parallel execution path, and it naturally supports two extensions sharing one task key, since each extension's distinct OnExecuteTask instance can still resolve to a distinct key. Lays the seam for a follow-up task to wire the extension path so two extensions referencing the same task no longer clobber each other's TaskResponse/OutputResponse entry.
Two extensions on one workflow could reference the same task while applying different Mapping/Order. OnExecuteTask carries Mapping and ErrorBoundary per entry, but Task is only a Reference, so their outputs are supposed to differ. Filing both under the shared task-derived variable name let the second extension silently overwrite the first's entry (sequential orders), or collide during the parallel branch merge with InvalidOperationException: "Parallel tasks produced conflicting output for key '...'" (same order) - the Preprod fault from trace 7873ad4e6c7a9db31c3b6401cd2c54fc. InstanceExtensionService now calls ITaskCoordinatorExtended. ExecuteWithDetailsAsync with a per-task optionsRefiner that sets TaskEngineExecutionOptions.ResponseVariableKey to the owning extension's own variable name, and reads/attributes responses by that same key. FindFailedExtensionKey is fixed the same way, since a task-keyed check could misattribute a failure to a successful sibling extension sharing the same task. Deliberately NOT gated on TaskTrigger.Extension: FunctionAppService shares that trigger for custom functions and must keep reading output by task key, so only InstanceExtensionService sets the new option. Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
…rence Review round 1 finding: WorkflowValidator has no uniqueness check on Extensions, so a workflow can legally list the same extension reference twice. FetchExtensionsFromReferencesAsync resolves references in parallel, and CacheSet's in-flight resolution coalescing hands both fetches the SAME Extension instance (hence the same OnExecuteTask instance, no equality override) - a genuine duplicate dictionary key. ToDictionary threw ArgumentException on that key, regressing a read that worked before the response-key fix (pre-fix, both executions produced identical values and the merge's equivalence check accepted them). responseKeyByTask is now built with a last-wins loop instead of ToDictionary, and the optionsRefiner reads it via TryGetValue (degrading to null / today's task-key behavior) instead of the indexer, removing a second latent KeyNotFoundException. Adds a regression test that hands the same Extension instance twice and asserts the read still succeeds; verified it fails with the production ArgumentException against the old ToDictionary shape. Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
…n hook
Two extensions sharing one task Reference is a documented, intentional
pattern after the extension-response-key fix: each extension carries its
own Mapping/ErrorBoundary and files its output under its own
ResponseVariableKey, so the writes never collide. The warning's remedy
("give the entries distinct orders") targets a journal-key collision that
cannot happen here either — ExtensionTaskPersistenceStrategy never
persists an InstanceTask row for Extension-origin executions, so there is
no journal entry for JournalTaskKey's "#0"/"#1" suffixing to disambiguate.
Every other hook (onExecute/onEntry/onExit) still warns with the current
remedy, where a repeated key remains almost certainly a copy-paste mistake.
…t fixed No page documented extensions under docs/domain/ or docs/runtime/, so this adds docs/domain/extensions.md rather than extending an existing one, and links it from docs/README.md's Reading Path (item 26). Records: two extensions may legitimately share a task definition; each carries its own Mapping/ErrorBoundary (OnExecuteTask), so their outputs are expected to differ; each extension's output is filed under its own key (TaskEngineExecutionOptions.ResponseVariableKey), never the task's; and the Preprod fault (trace 7873ad4e6c7a9db31c3b6401cd2c54fc) this shape once caused, so the next reader recognizes task-sharing as fixed, not broken. No deprecations.json entry: Task 1's inventory found no consumer reading an Extension task's response by task key (docs/runtime/extension-response-key-inventory.md, verdict SAFE).
Final whole-plan review of the extension-response-key fix surfaced three gaps: - TaskCoordinator suppressed DuplicateTaskKeyAtSameOrder on TaskTrigger.Extension, but custom functions share that same trigger (TaskExecutionOrigin.Function) and have no per-entry response-key override to save a genuinely duplicated task key. Gate on TaskExecutionOrigin.Extension instead, so a multi-task function still gets the diagnostic. docs/domain/extensions.md corrected to match. - InstanceExtensionService's last-wins responseKeyByTask build silently tolerated the SAME extension reference listed twice (a real bug shape distinct from two different extensions sharing a task) with no diagnostic at all. Added WorkflowLogs.DuplicateExtensionReference (EventId 20102), fired from the loop that already detects the collision for free, with the correct remedy for this shape (remove the duplicate reference - distinct orders does not help, the sequential path overwrites regardless of order). - The optionsRefiner's TryGetValue-miss fallback (ResponseVariableKey -> null) is unreachable today but degrades to silent data loss if it ever fires. Added WorkflowLogs.ExtensionResponseKeyMappingMissing (EventId 20103) on that branch. Extended TaskCoordinatorDuplicateTaskKeyTests with a Function-origin case (fails against the old trigger-based gate) and InstanceExtensionServiceTests with duplicate-reference-warns / distinct-extensions-silent cases. Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
… feature/trace-span-tree
|
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.




What this is
Two threads that turned out to be the same thread.
The first was the ask: make every time-consuming mechanism visible in the trace tree. Before this, a transition showed as a transaction with a handful of spans under it, and everything that actually cost time — validation, context load, task input/invoke/output compilation, subflow mapping, locks, component reads — happened inside gaps. A reader could see that a hop took 400 ms and had no way to learn where it went.
The second thread was what the spans then showed. With the tree filled in, a single business request turned out to resolve the same workflow definition 3+ times per hop, load the same instance twice, validate the same payload schema twice, and build a fully populated
TransitionExecutionContextonly to throw it away. So the second half of this PR removes that redundancy — which was only findable because of the first half.Spans added
Named so the tree reads without opening anything: the subject is in the span name, details are tags.
Step.{Name}vnext.step.order/vnext.step.outcomeTransition.LoadContext,Instance.LoadTransition.Validate,Transition.ValidatePolicyTask.Invoke,Invoke.{taskType}/{taskKey},CacheAside.{Read,Write}/{key}Script.Compile,Script.Execute,Script.ResolveHelpersCache.Get/{key},Cache.GenerationGet/{key}Lock.Acquire/{lockKey},Lock.Release/{lockKey}vnext.lock.kind=status|chainInstance.AppendData,Uow.Commit,Events.PublishDeferredTransition.Continuation/{mode},Transition.SettleFanOut.Item[i]Three refinements worth calling out because they change what a reader sees:
StepOutcome.ContinueNoWork()clearsRecorded, so a profile-excluded or short-circuited step leaves no row. A 20-row tree of mostly no-ops is worse than a 6-row tree of real ones.TransitionJob.Execute/{key}), which made thetransition/{key}child node redundant — it is gone.All of this is always on, not gated behind Verbose. That works without touching Aether because
BusinessSpanFilterProcessorsuppresses only[-prefixed DisplayNames at export — verified, not assumed.Behavior changes a reviewer should actually check
These are the risky parts. Everything above is additive; these are not.
IWorkflowContextis gone. It was added for aSchemaValidationAttributeaspect ind680b4a6; that aspect was deleted in23a7acbfand the context has been orphaned since — 2 writers, 3 readers, ~15 test doubles. Its three readers now take the workflow from their caller:PostCommitParentMutationServicefromPostCommitParentSnapshot,InstanceDataWriteServicefrom aWorkflow?parameter, andInstanceCommandAppService's own memo is deleted outright — it compared onlyKey, so a pinned-version request could silently get a different version back.A resolved workflow is carried instead of re-resolved.
WorkflowExecutionContext.ResolvedWorkflowis[JsonIgnore]transport-only state. No version guard is needed and the reason is worth understanding before reviewing: the carried definition was resolved from the same context object'sDomain/WorkflowKey/WorkflowVersion, and the consumer asks with exactly those fields. The deleted memo was wrong precisely because it lacked that property.Intake admits from the projection, not the aggregate. The full
GetActiveAsyncinInstanceCommandAppServiceexisted only to build a context for a validation thatAsyncTransitionStrategyalready performs before enqueue. Both are gone; admission now readsInstanceExecutionSnapshot. Two things guard this and both are pinned by tests:InstanceExecutionSnapshot.IsTerminalwas added becauseInstance.IsCompletedcounts Faulted and Passive too and the snapshot'sIsCompleteddid not (a faulted instance would have been admitted), and theInstanceNotFounderror is reproduced verbatim — my first version returnedInstance:100013where the repository returnsInstance:100017, and a test caught it.Payload-schema validation has a single owner. The sync path gained the schema check it never had, conditioned on
!context.IsPreReserved— the same "validated at accept" invariant already documented inTransitionPipeline.GenerationMemoSecondsnow defaults to 5, not 0. This one is a policy decision, not a tuning change, and it is the only item here that trades correctness for latency: the memo caches the token, so a bump written by another pod stays invisible on this pod for up to 5 s. L1 does not share this exposure — an L1 key embeds the token, so L1 cannot go stale. Set it to 0 where a publish must be cluster-visible immediately.Measurements
From one business request traced end to end (
2dc8b6b7, 39 transactions, warm runtime):SyncTransitionStrategythat no child span accounted for: 976 ms → 14 ms. Residual unattributed across all transaction roots is 266 ms (9.7%), most of it the HTTP entry and job dispatch edges.l1=false— 148 Redis round trips. This is what motivated item 5 and it is what the L1 warm-up phase will target next.amorphie-contract45.5%, component cache reads 21.1%, DB (commit + instance load) 9.4%, locks 0.9%.The lock number is the one to notice: 0.9% of wall clock across 28 transitions is the busy-as-mutex design behaving as intended, and it is now measurable rather than argued.
Config
AdditionalSourcesextended across both hosts and both workers — without it the newActivitySources produce spans that are never exported, which is a silent failure. The localetc/dockercollector filter was renamed and broadened tofilter/dapr-internals. The orchestration host'sComponentCache.GenerationMemoSeconds: 0override is removed now that the default carries the intended value.Testing
dotnet build vnext.slnclean. Full suite run and the failing-test name set compared against the master baseline (master carries 191 pre-existing failures, mostlyAmbientServiceProviderleakage across parallel collections) — no branch-only failures. New tests cover the carried-workflow path, schema-validation ownership, snapshot admission including the not-found/Faulted/Passive/Busy matrix, and the continuation/settle/generation spans.Not done
vnext-docs/docs/components/tasks/fan-out.md:530still saysFanOut.Itemis verbose-only. Stale since3255c457, different repo.🤖 Generated with Claude Code