You signed in with another tab or window. Reload to refresh your session.You signed out in another tab or window. Reload to refresh your session.You switched accounts on another tab or window. Reload to refresh your session.Dismiss alert
{{ message }}
Repository navigation
feat: measure upstream durations, count rate limits, truncations and cache hits, and trace MCP calls - #182
Upstream-call duration on the VitallyUpstreamCall audit record, as AuditDurationMs. It is unsampled and joins the tool-call record by correlation id.
A VitallyMcp meter with four counters: rate-limit retries, rate-limit exhaustion, auto-pager truncations, and cache hits and misses for the API key, group membership and OIDC discovery.
Spans are sanitised before export by SpanSanitisingProcessor. Probes of SDK 2.2.0 found caller text reaching spans by seven routes:
the failed call's error text, copied into StatusDescription;
invented tool names;
unknown method and notification names;
prompt names;
resource URIs;
request ids.
The MCP branch is therefore built on allowlists: SDK-defined methods, registered tools and a fixed set of tag keys, with the span name rebuilt from the cleaned values. A test asserts that it runs ahead of Live Metrics and the exporter.
The SDK's meter is deliberately not registered. Its gen_ai.tool.name dimension carries caller-invented tool names, unsampled, and a processor cannot rewrite metric tags. Per-tool latency is already in AppEvents.
What the issue got wrong, verified here
Issue said
Actually
ActivitySource ModelContextProtocol
Experimental.ModelContextProtocol in 2.2.0. Registering the issue's name would have silently captured nothing
"Errors at 100%"
Not achievable with head sampling, which decides before the outcome is known
The slow-requests diagnosis was "reasoned, not measured"
It was measured, as whole-request times. Corrected on the issue
I also corrected one of my own claims from the issue thread: the OTEL_TRACES_SAMPLER* environment variables do not override the code's sampling in distro 1.6.0.
Pre-PR review
pr-review-toolkit ran twice. The first pass used code-reviewer, pr-test-analyzer and comment-analyzer; the re-run used code-reviewer and comment-analyzer. Everything that survived verification is fixed (ea1bc61, d541da3, 848e226). The findings that mattered:
Caller text in spans, by the seven routes above, found across both runs. The first sanitiser was a blocklist, and the re-run found four routes it missed, hence the allowlist.
The SDK meter's cardinality.
Tests that passed with the bug present:
two calls could not tell a hit/miss swap apart;
the duration test accepted the -1 sentinel;
the PII gate never looked at StatusDescription.
A test-isolation leak. Inside the suite, disposing the exporter test's WebApplicationFactory did not dispose its TracerProvider. The provider stayed subscribed and sanitised later tests' spans, which failed the PII test intermittently. The test now disposes the providers explicitly, a post-dispose guard catches a recurrence, and TelemetryRedactionTests joined the serialised collection. Why only some orderings exposed it was not established.
Prose claims about what the signals measure. CLAUDE.md now carries three reading caveats: calls that throw have no duration; the group-membership hit rate is inflated by repeat checks within a request; the OIDC hit rate looks healthy during an outage. It also gives sum(ItemCount) guidance for the sampled tables.
Not addressed: caller-typed path segments in AppDependencies remain an open gap, as already recorded in CLAUDE.md. The composed PII test's scope is MCP and ASP.NET Core spans, because the harness creates no HttpClient dependency spans.
Breaking changes
Trace volume drops. Sampling moves from about 5 traces a second, effectively every trace at this server's volume, to 10%. AppRequests and AppDependencies counts must now use sum(ItemCount). Audit records and logs are unaffected.
Test plan
dotnet test VitallyMcp.sln -c Release passes locally: 743 passed, 0 failed. Debug also passes, plus three further consecutive full Debug runs.
CI is green on this PR
Manual smoke test against a real Vitally tenant: not done. The live check after deploy is that AuditDurationMs appears on VitallyUpstreamCall rows, the VitallyMcp meter shows in AppMetrics, and sampled MCP spans in AppRequests carry unrecognised for an invented tool name. The design spec's phase table marks phase 6 "built, not yet verified in Azure" until then.
Both design specs are updated, including the phase table and the data map. The stale Program.cs:176 and Program.cs:134 line references in CLAUDE.md, two runbooks and the Terraform README now name the code they point at.
…cache hits, and trace MCP calls (#94)
Phase 6 of #94.
- LogAction carries durationMs (send to body read, 429 waits included),
as a named AppEvents dimension; -1 when unmeasured, never 0.
- VitallyMetrics, one Meter "VitallyMcp" via IMeterFactory:
vitally.ratelimit.retries / .exhausted, vitally.autopager.truncations
(tagged with the fixed defaults key, never the caller-built path, which
can carry an account id), vitally.cache.lookups by cache and hit/miss
for the API key, group membership and OIDC discovery.
- The MCP SDK's ActivitySource and meter, plus ours, registered with the
exporter. The SDK's source is "Experimental.ModelContextProtocol" in
2.2.0, not the "ModelContextProtocol" the issue gave; a composed test
found that, since a wrong name registers silently and captures nothing.
- 10% head sampling: SamplingRatio 0.1 AND TracesPerSecond null, since
the latter overrides the former. Safe only because of #178.
- PII gate: a composed test captures every span during a tool call and
asserts no attribute carries the argument (negative control: the tool
name, which a span does carry, fails it).
Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01APL79rWv4GzNinRr7Cpex8
- CLAUDE.md: a "Metrics and tracing" section (signals, the
Experimental.-prefixed SDK names, fixed-value-only metric tags,
10% sampling and why TracesPerSecond must be null, the span PII
gate); the rate-limit handler, LogAction's fields and the test
coverage list now mention the counters and duration.
- ACCESS.md: the action record carries a duration.
- Both design specs: phase 6 marked done; the superseded spec's
ActivitySource name corrected, as its own warning anticipated.
Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01APL79rWv4GzNinRr7Cpex8
… from pre-PR review (#94)
- SpanSanitisingProcessor: clears every span's StatusDescription (the
MCP SDK copies a failed call's whole error text there, caller input
and Vitally body included); on MCP spans rewrites an unregistered
gen_ai.tool.name and the span name to "unrecognised" and drops the
caller-chosen jsonrpc.request.id. The composed test now runs it over
real SDK spans from three calls, with controls proving the caller
text reached the raw spans and that the scan sees attributes.
- The MCP SDK meter is no longer registered: its gen_ai.tool.name
dimension carries invented names, unsampled, and a processor cannot
rewrite metric tags. Pinned as NOT registered.
- The exporter test disposes its TracerProvider/MeterProvider
explicitly: the factory's disposal does not, so the provider stayed
subscribed and sanitised later tests' spans. A post-dispose guard
catches a recurrence; TelemetryRedactionTests joins the serialised
collection so the guard cannot flake.
- Tests: cache counters use three calls (two hid a hit/miss swap);
the duration test asserts a real elapsed time (the -1 sentinel is a
long too); a stale Graph serve is pinned as a miss; the composed
injection test covers the Graph resolver as well.
Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01APL79rWv4GzNinRr7Cpex8
- The "slow requests" diagnosis WAS measured (whole-request times from
Request finished lines, since suppressed by #143); what is new is the
per-upstream-call breakdown.
- OTEL_TRACES_SAMPLER* are not a runtime lever in distro 1.6.0: probed,
not honoured. Change sampling in Program.cs.
- Reading caveats: durations are missing for calls that throw and are
gated by Audit settings; the group_membership hit rate counts lookups
and is inflated by repeat checks per request; the OIDC hit rate looks
healthy during an outage; sampled tables need sum(ItemCount).
- The 429 counters say how often the limit is exceeded, not how close
the server runs; "a log line cannot be trended" was overstated.
- The SDK meter is unregistered and why; the span sanitiser's three
routes; the injection test's real scope; the exporter test's explicit
provider disposal.
- Spec phase table: 5 done, 6 built but not verified in Azure, 8 unblocked
once 6 deploys; superseded spec's second source-name mention corrected;
README's action row gains duration.
- Stale Program.cs:176 / :134 line references replaced with the symbols
they point at, in CLAUDE.md, two runbooks and the Terraform README.
Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01APL79rWv4GzNinRr7Cpex8
From the pre-PR re-run:
- SpanSanitisingProcessor's MCP branch is now allowlist-based. A probe
found four more caller-text routes the first version missed: an
unknown method or notification (span name and mcp.method.name),
prompts/get (gen_ai.prompt.name, span name) and resources/read
(mcp.resource.uri). The method is kept only if the SDK defines it
(read from RequestMethods/NotificationMethods), every MCP tag not on
AllowedMcpTags is dropped, and the span name is rebuilt from the
cleaned values. The composed test drives all seven routes with a
control for each; disabling the allowlist fails it.
- The exporter test now asserts both redaction processors precede Live
Metrics and the batch exporter in the chain - true today, but a
distro implementation detail.
- Prose: phase 6 adds an UNSAMPLED per-upstream breakdown (sampled
dependency spans existed since #147) and reduced span coverage; the
duration also starts after the API key is resolved; spec's
"reasoned, not measured" corrected; AppRequests row added to the data
map; superseded spec's redaction gate annotated; the provider-leak note
qualified as in-suite only; assorted wording.
Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01APL79rWv4GzNinRr7Cpex8
From Copilot's review of #182:
- RateLimitRetry moved after Task.Delay, so a timeout or cancelled caller
during the backoff no longer counts a retry that was never sent.
Pinned by DoesNotCountARetry_ThatIsCancelledDuringTheBackoff.
- PerformanceMetricsTests' remark no longer repeats the corrected
"reasoned rather than measured" claim.
Also from CodeQL's notes: XML summaries on the two VitallyMetrics
methods (and PagerTruncated's parameter now says what it receives), and
the sanitiser's tag loop filters explicitly with Where.
Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01APL79rWv4GzNinRr7Cpex8
Cache miss metric overstates that an external round-trip occurred
CLAUDE.md:1022
A cache miss is recorded immediately after TryGetValue fails, before the Key Vault, Graph, or OIDC operation runs. A pre-cancelled request or credential failure can therefore emit a miss without any network round-trip, so saying the round-trip “happened” overstates what this metric establishes; describe it as the cache not answering and an external lookup being required/attempted.
…p happened (#94)
Copilot's previously-missed finding on #182: the miss is counted after
TryGetValue fails and before the external call, so a pre-cancelled request
or a credential failure records a miss with no network round-trip.
Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01APL79rWv4GzNinRr7Cpex8
The reason will be displayed to describe this comment to others. Learn more.
Copilot review overview
🔵 Needs a closer look
The telemetry and sampling changes affect production observability and data exposure, and live Azure verification remains outstanding.
Review effort: Balanced Findings: None
Previously missed (1)
In code that hasn't changed since last review
Document zero duration for sub-millisecond measurements
VitallyMcp/AuditLogger.cs:126
The documentation says a measured duration is never 0, but the implementation casts TotalMilliseconds to long, so any valid sub-millisecond call is recorded as 0. Please describe 0 as a possible rounded measurement and reserve only -1 for “not measured.”
…is unmeasured (#94)
Copilot's previously-missed finding on #182: the duration is truncated to
whole milliseconds, so the doc's 'never 0' read as excluding a genuine
sub-millisecond call.
Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01APL79rWv4GzNinRr7Cpex8
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
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.
![github-advanced-security[bot]](https://avatars.githubusercontent.com/in/57789?s=60&v=4){kind=small}
Summary
Phase 6 of ops: log failures and measure performance — the server currently reports almost neither #94: performance. The parts:
VitallyUpstreamCallaudit record, asAuditDurationMs. It is unsampled and joins the tool-call record by correlation id.VitallyMcpmeter with four counters: rate-limit retries, rate-limit exhaustion, auto-pager truncations, and cache hits and misses for the API key, group membership and OIDC discovery.SamplingRatio = 0.1FandTracesPerSecond = null, because the latter overrides the former. It is safe only because fix: audit records are dropped from AppEvents whenever their trace is not sampled #178 decoupled the audit records from trace sampling.Spans are sanitised before export by
SpanSanitisingProcessor. Probes of SDK 2.2.0 found caller text reaching spans by seven routes:StatusDescription;The MCP branch is therefore built on allowlists: SDK-defined methods, registered tools and a fixed set of tag keys, with the span name rebuilt from the cleaned values. A test asserts that it runs ahead of Live Metrics and the exporter.
The SDK's meter is deliberately not registered. Its
gen_ai.tool.namedimension carries caller-invented tool names, unsampled, and a processor cannot rewrite metric tags. Per-tool latency is already inAppEvents.What the issue got wrong, verified here
ModelContextProtocolExperimental.ModelContextProtocolin 2.2.0. Registering the issue's name would have silently captured nothingI also corrected one of my own claims from the issue thread: the
OTEL_TRACES_SAMPLER*environment variables do not override the code's sampling in distro 1.6.0.Pre-PR review
pr-review-toolkitran twice. The first pass used code-reviewer, pr-test-analyzer and comment-analyzer; the re-run used code-reviewer and comment-analyzer. Everything that survived verification is fixed (ea1bc61,d541da3,848e226). The findings that mattered:-1sentinel;StatusDescription.WebApplicationFactorydid not dispose itsTracerProvider. The provider stayed subscribed and sanitised later tests' spans, which failed the PII test intermittently. The test now disposes the providers explicitly, a post-dispose guard catches a recurrence, andTelemetryRedactionTestsjoined the serialised collection. Why only some orderings exposed it was not established.sum(ItemCount)guidance for the sampled tables.Not addressed: caller-typed path segments in
AppDependenciesremain an open gap, as already recorded in CLAUDE.md. The composed PII test's scope is MCP and ASP.NET Core spans, because the harness creates noHttpClientdependency spans.Breaking changes
AppRequestsandAppDependenciescounts must now usesum(ItemCount). Audit records and logs are unaffected.Test plan
dotnet test VitallyMcp.sln -c Releasepasses locally: 743 passed, 0 failed. Debug also passes, plus three further consecutive full Debug runs.AuditDurationMsappears onVitallyUpstreamCallrows, theVitallyMcpmeter shows inAppMetrics, and sampled MCP spans inAppRequestscarryunrecognisedfor an invented tool name. The design spec's phase table marks phase 6 "built, not yet verified in Azure" until then.Documentation
CLAUDE.mdreflects the change: a new Metrics and tracing section, plus the rate-limit handler, theLogActionfields, the fix: audit records are dropped from AppEvents whenever their trace is not sampled #178 paragraph and the test coverage list.README.mdreflects the change: the action row in the audit table gainsduration.CHANGELOG.mdupdated under[Unreleased]: not done, as on feat: log tool-call, upstream and Key Vault failures server-side #177 and fix: export audit records whether or not their trace was sampled #181.Both design specs are updated, including the phase table and the data map. The stale
Program.cs:176andProgram.cs:134line references in CLAUDE.md, two runbooks and the Terraform README now name the code they point at.Linked issues
Closes #94
🤖 Generated with Claude Code
https://claude.ai/code/session_01APL79rWv4GzNinRr7Cpex8