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
fix: export audit records whether or not their trace was sampled - #181
Audit records were being dropped from AppEvents under load. The Azure Monitor distro defaults EnableTraceBasedLogsSampler to true, which means a log record is exported only if its request's trace was sampled. Traces are rate-limited to about 5 a second by default. All four audit record types are logged inside the request's trace, so under sustained load a proportion of requests silently lost their records. The docs don't state this default for the distro, so I verified it from the 1.6.0 package: EnableTraceBasedLogsSampler=True, TracesPerSecond=5, SamplingRatio=1.
The fix is one line in Program.cs:EnableTraceBasedLogsSampler = false. It's pinned inside LoggingFilterTests.WithAConnectionStringConfigured_TheExporterBranchIsActuallyWiredUp. A negative control proves the assertion catches the regression: with the flag set back to true, the test fails.
It's verified by behaviour, not only by the option's value. A throwaway probe pointed the exporter at a local listener with trace sampling at 0%:
under the default, 0 of 5 in-request logs arrived;
with the switch off, 5 of 5 arrived;
AzureMonitor__EnableTraceBasedLogsSampler is not bound, so no environment variable overrides the switch;
a sampled-out request's log carries no sampleRate, so count() over AppEvents stays an exact audit count however far trace sampling is later reduced.
This is a prerequisite for #94's tracing work. That issue planned 10% trace sampling, which would have lost about 90% of the audit trail under the default.
Why the assertion isn't a test of its own
A separate test that composed a second exporter-configured host, and resolved only these options, hung whichever test ran next in the serialised IntegrationTestCollection. Every later member of the collection stalled behind it. It reproduced three times: 622 of 723 tests completed, the hung test process was still alive the next morning, and the per-test output showed my test passing in 91 ms and the next one never finishing. Folding the assertion into the existing exporter test, which fully builds and then disposes the same host, fixed it. The full suite then passed three times in a row, in about 10 seconds each.
Pre-PR review
I ran pr-review-toolkit's code-reviewer and comment-analyzer on this change.
The code reviewer found no defects. It wrote and ran the export probe described above.
The comment analyser's findings are all applied, in 4c3ba84:
My original note said "turn SamplingRatio freely". That was a trap: TracesPerSecond takes precedence over SamplingRatio, so percentage sampling also needs TracesPerSecond = null.
The note named only two of the four affected record types.
ACCESS.md and README.md presented the trail as complete since 2026-09-25. Both now carry the caveat.
The ACCESS.md coverage check counts records in 15-minute bins, and a bin with rows can't prove that a particular record isn't missing. The runbook now says so.
Breaking changes
None. More log records are exported than before, namely those from unsampled requests. At current traffic that is a small ingest increase.
Test plan
dotnet test VitallyMcp.sln -c Release passes locally: 723 passed. Debug also passes, and the full suite passed three consecutive times without hanging.
CI is green on this PR
Manual smoke test against a real Vitally tenant: not applicable, since the change is exporter configuration. The live check comes after deploy: from then on, every tool-call breadcrumb in ContainerAppConsoleLogs should have a matching VitallyToolCall row in AppEvents by correlation id.
EU:
US:
Documentation
CLAUDE.md reflects the change. It records the control, the precedence trap, how to measure the pre-fix gap (measurable from 2026-09-26 by joining breadcrumbs to AppEvents, unknowable for the day before), and a one-line note in the failure-records block.
README.md reflects the change: both "complete since 2026-09-25" claims are qualified.
The Azure Monitor distro defaults EnableTraceBasedLogsSampler to true
(verified from the 1.6.0 package; its .NET docs do not state it), so a
log record is exported only if its trace was sampled. Audit records are
logged inside the request's trace and traces are rate-limited to 5 a
second by default, so under load VitallyToolCall / VitallyUpstreamCall
records were silently never written to AppEvents. Setting it false
decouples the audit trail from trace sampling, which is what makes
#94's reduced sampling safe.
Pinned inside the existing exporter-branch test rather than a test of
its own: a second exporter-configured host that resolved only the
options hung the next test in the serialised collection, reproducibly.
Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01APL79rWv4GzNinRr7Cpex8
- TracesPerSecond (default 5) takes precedence over SamplingRatio, so
"turn SamplingRatio freely" silently did nothing; percentage sampling
needs TracesPerSecond = null too, and OTEL_TRACES_SAMPLER* override both.
- All four audit record types were affected, not two; the sampler is
adaptive, so a proportion of requests lost records, not "every request
past the fifth"; the breadcrumb persisted only from 2026-09-26.
- The pre-#178 gap is measurable from 2026-09-26 by joining breadcrumbs
to AppEvents on correlation id; unknowable only for 09-25 to 09-26.
- ACCESS.md and README.md presented the trail as complete since
2026-09-25; both now carry the caveat, and the ACCESS.md coverage
check notes that a bin with rows cannot prove an individual record.
- The design spec's tracing item and phase-6 row record the dependency.
- Records the export probe that verified the fix by behaviour.
Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01APL79rWv4GzNinRr7Cpex8
Copilot on #181 said AzureMonitorExporter__EnableTraceBasedLogsSampler is
bound after the distro copies its options and could re-enable the
filtering. Probed in both directions against 1.6.0 at 0% trace sampling:
code false + that key true still exported 20/20 in-request logs; code
default + that key false still exported 0/20. The key is not read, so no
PostConfigure guard is added; CLAUDE.md now names both keys and the probe.
Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01APL79rWv4GzNinRr7Cpex8
The parenthetical reverses the sampling limit: five per second is approximately the number of traces retained, not the number left unsampled. The unsampled request rate depends on traffic and can be much higher, so this currently understates the possible historical audit gap.
Copilot's "previously missed" finding on #181: the README parenthetical
read as though about 5 requests a second lost their audit records, when
5 a second is roughly what the trace sampler retained. The traffic above
that rate, which can be far higher, is what could lose its records.
Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01APL79rWv4GzNinRr7Cpex8
The past-tense deployment boundary is not established yet: the PR's own test plan says the live check occurs after deployment. Describe affected releases rather than implying #178 is already live, otherwise this incident runbook can incorrectly tell an operator that the stronger coverage guarantee is active.
This issue also appears on line 273 of the same file.
This states that #178 has already been deployed, but the PR's test plan explicitly leaves the post-deploy live check outstanding. Because merging and deploying are separate here, this would make the configuration reference overstate the live audit guarantee until rollout. Phrase it in terms of deployments/releases that contain #178 instead of asserting that rollout has happened.
This issue also appears on line 230 of the same file.
Copilot's "previously missed" findings on #181: ACCESS.md and README.md
said "since #178 deployed" in the past tense, but merging and deploying
are separate here, so between merge and the next release the prose would
claim a guarantee production did not yet have. They now describe the
boundary as whether a release containing #178 was serving the window,
and tell the reader to check which image served it.
Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01APL79rWv4GzNinRr7Cpex8
…cache hits, and trace MCP calls (#182)
## Summary
- **Phase 6 of #94: performance.** The parts:
- **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.
- **MCP SDK spans** exported at 10% head sampling. That needs
`SamplingRatio = 0.1F` *and* `TracesPerSecond = null`, because the
latter overrides the former. It is safe only because #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:
- 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
- [x] `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.
- [ ] EU:
- [ ] US:
## Documentation
- [x] `CLAUDE.md` reflects the change: a new *Metrics and tracing*
section, plus the rate-limit handler, the `LogAction` fields, the #178
paragraph and the test coverage list.
- [x] `README.md` reflects the change: the action row in the audit table
gains `duration`.
- [ ] `CHANGELOG.md` updated under `[Unreleased]`: not done, as on #177
and #181.
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.
## Linked issues
Closes#94
🤖 Generated with [Claude Code](https://claude.com/claude-code)
https://claude.ai/code/session_01APL79rWv4GzNinRr7Cpex8
---------
Co-authored-by: Claude Opus 5.5 <noreply@anthropic.com>
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.
Summary
AppEventsunder load. The Azure Monitor distro defaultsEnableTraceBasedLogsSamplertotrue, which means a log record is exported only if its request's trace was sampled. Traces are rate-limited to about 5 a second by default. All four audit record types are logged inside the request's trace, so under sustained load a proportion of requests silently lost their records. The docs don't state this default for the distro, so I verified it from the 1.6.0 package:EnableTraceBasedLogsSampler=True,TracesPerSecond=5,SamplingRatio=1.Program.cs:EnableTraceBasedLogsSampler = false. It's pinned insideLoggingFilterTests.WithAConnectionStringConfigured_TheExporterBranchIsActuallyWiredUp. A negative control proves the assertion catches the regression: with the flag set back totrue, the test fails.AzureMonitor__EnableTraceBasedLogsSampleris not bound, so no environment variable overrides the switch;sampleRate, socount()overAppEventsstays an exact audit count however far trace sampling is later reduced.This is a prerequisite for #94's tracing work. That issue planned 10% trace sampling, which would have lost about 90% of the audit trail under the default.
Why the assertion isn't a test of its own
A separate test that composed a second exporter-configured host, and resolved only these options, hung whichever test ran next in the serialised
IntegrationTestCollection. Every later member of the collection stalled behind it. It reproduced three times: 622 of 723 tests completed, the hung test process was still alive the next morning, and the per-test output showed my test passing in 91 ms and the next one never finishing. Folding the assertion into the existing exporter test, which fully builds and then disposes the same host, fixed it. The full suite then passed three times in a row, in about 10 seconds each.Pre-PR review
I ran
pr-review-toolkit's code-reviewer and comment-analyzer on this change.4c3ba84:SamplingRatiofreely". That was a trap:TracesPerSecondtakes precedence overSamplingRatio, so percentage sampling also needsTracesPerSecond = null.ACCESS.mdandREADME.mdpresented the trail as complete since 2026-09-25. Both now carry the caveat.Breaking changes
Test plan
dotnet test VitallyMcp.sln -c Releasepasses locally: 723 passed. Debug also passes, and the full suite passed three consecutive times without hanging.ContainerAppConsoleLogsshould have a matchingVitallyToolCallrow inAppEventsby correlation id.Documentation
CLAUDE.mdreflects the change. It records the control, the precedence trap, how to measure the pre-fix gap (measurable from 2026-09-26 by joining breadcrumbs toAppEvents, unknowable for the day before), and a one-line note in the failure-records block.README.mdreflects the change: both "complete since 2026-09-25" claims are qualified.CHANGELOG.mdupdated under[Unreleased]: not done. As on feat: log tool-call, upstream and Key Vault failures server-side #177, recent PRs haven't maintained it.The design spec's tracing item and phase-6 row now record the dependency. I also added a comment on #94 with the two sampling corrections.
Linked issues
Closes #178
🤖 Generated with Claude Code
https://claude.ai/code/session_01APL79rWv4GzNinRr7Cpex8