Skip to content

Investigate flaky test#8041

Draft
justindbaur wants to merge 17 commits into
mainfrom
flaky-relay-push-logging
Draft

Investigate flaky test#8041
justindbaur wants to merge 17 commits into
mainfrom
flaky-relay-push-logging

Conversation

@justindbaur

Copy link
Copy Markdown
Member

Adds ITestOutputHelper and a DumpLogs helper that writes all captured log entries (including Debug/Info) before the assertion. xunit shows this output when the test fails, giving full context on what the RelayPushRegistrationService logged during the CI run.

Package lock files updated as a side effect of restore.

🎟️ Tracking

📔 Objective

📸 Screenshots

Adds ITestOutputHelper and a DumpLogs helper that writes all captured
log entries (including Debug/Info) before the assertion. xunit shows
this output when the test fails, giving full context on what the
RelayPushRegistrationService logged during the CI run.

Package lock files updated as a side effect of restore.
Copilot AI review requested due to automatic review settings July 22, 2026 14:24

Copilot AI left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Pull request overview

Improves diagnostics for a flaky integration test by capturing and emitting RelayPushRegistrationService logs via xUnit’s ITestOutputHelper, so CI failures include the full log context.

Changes:

  • Inject ITestOutputHelper into RelayPushRegistrationServiceTests.
  • Add a helper to dump captured logs to xUnit output and call it in the mobile registration test.

💡 Add Copilot custom instructions for smarter, more guided reviews. Learn how to get started.

Comment on lines +90 to +103
private void DumpLogs(string context)
{
var logs = _logCollector.GetSnapshot();
_output.WriteLine($"--- Captured logs ({context}): {logs.Count} entries ---");
foreach (var log in logs)
{
_output.WriteLine($"[{log.Level}] {log.Message}");
if (log.Exception is not null)
{
_output.WriteLine($" Exception: {log.Exception}");
}
}
_output.WriteLine("---");
}
Comment on lines 124 to 128
var logs = _logCollector.GetSnapshot();

DumpLogs("after CreateOrUpdateRegistrationAsync");

Assert.DoesNotContain(logs, l => l.Level >= LogLevel.Warning);
Replace NullLoggerFactory on the identity factory with FakeLogging so
the test can dump identity server logs alongside the SUT logs. If the
token request hangs, the identity server's own log output will now
appear in the xunit failure report.
Wrap the identity server's in-process TestHost handler with a
DelegatingHandler that logs two timestamps per token request:
  [identity→] when the request is sent
  [identity←] when the inner handler returns (headers ready, body still open)

If the server shows "Request finished 200" but [identity←] never appears,
the hang is in the TestHost pipeline itself. If [identity←] appears quickly
but the overall SendAsync still times out, HttpClient is stuck buffering the
response body from the TestHost pipe (ResponseContentRead mode).

Also lowers the identity client Timeout to 10 s by building the HttpClient
directly from Server.CreateHandler() instead of Identity.CreateClient().
LdClient tries to open a streaming connection to LaunchDarkly on the
first request to the identity TestServer. In CI, outbound packets to
LaunchDarkly are dropped (not refused), so the TCP handshake hangs for
~88 s (OS SYN-timeout) before the constructor can complete. This keeps
the TestHost response-body pipe writer open even though the server logs
"Request finished 200" within ~1 s, stalling the client's PipeReader
for the same duration until HttpClient's 10 s timeout fires.

Setting globalSettings:launchDarkly:sdkKey to null makes
LaunchDarklyClientProvider take the string.IsNullOrEmpty branch:
TestData.DataSource() + NoEvents — zero outbound network activity.
… LaunchDarkly hangs

Nulling the SDK key was insufficient — LdClient is still instantiated even in
offline/TestData mode and may attempt outbound diagnostic connections. Replacing
the IFeatureService registration with a no-op substitute prevents LdClient from
ever being constructed, eliminating the ~138 s CI hang caused by dropped TCP SYN
packets to LaunchDarkly endpoints.
…tance

The Bitwarden SDK registers OTLP metric and trace exporters by default
when not self-hosted. In CI those exporters attempt outbound TCP
connections to a collector endpoint that drops packets rather than
refusing them, causing a ~95 s SYN-timeout that stalls the TestHost
response pipeline — the same failure mode as the LaunchDarkly hang.

Setting OpenTelemetry:Enabled=false in the identity server's
configuration suppresses both AddOtlpExporter() calls before server
startup, eliminating the hang.
…token request

Add process-wide DiagnosticListener and ActivityListener subscriptions to
MobileData_ShouldNotLogIssues so that CI logs reveal exactly which outbound
TCP connection is causing the remaining hang.

- DiagnosticAllObserver subscribes to AllListeners (which replays already-
  active listeners on subscribe, capturing HttpHandlerDiagnosticListener
  even after app startup). Every outbound HTTP→/HTTP←/HTTP✗ event is logged
  with a timestamp relative to test start.
- ActivityListener covers all ActivitySource spans (url.full / http.url tags
  printed on start/stop), giving a timeline of identity server internals.
- Thread-pool polling now shares the same Stopwatch as the other diagnostics.
@justindbaur
justindbaur force-pushed the flaky-relay-push-logging branch from ee3db0b to 78c936c Compare July 23, 2026 19:07
…dentity tests

UpdateConfiguration() adds to IWebHostBuilder.ConfigureAppConfiguration, which is
only visible in the DI IConfiguration (read by Startup.ConfigureServices). However,
UseBitwardenSdk() registers AddMetrics() via IHostBuilder.ConfigureServices, which
reads HostBuilderContext.Configuration — built exclusively from IHostBuilder.
ConfigureAppConfiguration sources. So OpenTelemetry:Enabled=false set via
UpdateConfiguration() was never seen by AddMetrics(), leaving OTLP exporters
registered despite the override.

Add UpdateHostConfiguration() / CreateHostBuilder() override to WebApplicationFactoryBase
so callers can inject in-memory configuration at the IHostBuilder level. Wire the
RelayPushRegistrationService test to use it for OpenTelemetry:Enabled=false.

Root cause of the ~136 s hang: gRPC channel exponential-backoff reconnection
(1 s → 2 s → 4 s → … → ~120 s max) when the OTLP collector endpoint on
localhost:4317 refuses or drops connections in CI.
When the ActivityListener sees an activity whose source name contains
"EntityFrameworkCore", print a truncated (120-char) snippet of the
db.statement tag on both Activity+ (start) and Activity- (stop) lines.

The tag is guaranteed to be populated by stop time; it may also already
be set as an initial tag at start time depending on the instrumentation
version. Either way, the stop line will always show the SQL so we can
identify exactly which query the identity server runs during the
/connect/token flow.
Comment on lines +149 to +153
foreach (var configure in _configureHostAppConfiguration)
{
var captured = configure;
builder?.ConfigureAppConfiguration((_, config) => captured(config));
}
@codecov

codecov Bot commented Jul 24, 2026

Copy link
Copy Markdown

Codecov Report

❌ Patch coverage is 60.00000% with 2 lines in your changes missing coverage. Please review.
✅ Project coverage is 62.49%. Comparing base (2bdd35a) to head (91aee12).
⚠️ Report is 16 commits behind head on main.

Files with missing lines Patch % Lines
src/Api/Program.cs 60.00% 2 Missing ⚠️
Additional details and impacted files
@@             Coverage Diff             @@
##             main    #8041       +/-   ##
===========================================
+ Coverage   14.96%   62.49%   +47.53%     
===========================================
  Files        1389     2300      +911     
  Lines       60360   100001    +39641     
  Branches     4793     8992     +4199     
===========================================
+ Hits         9030    62498    +53468     
+ Misses      51175    35332    -15843     
- Partials      155     2171     +2016     

☔ View full report in Codecov by Harness.
📢 Have feedback on the report? Share it here.

🚀 New features to boost your workflow:
  • ❄️ Test Analytics: Detect flaky tests, report on failures, and find test suite problems.
  • 📦 JS Bundle Analysis: Save yourself from yourself by tracking and limiting bundle sizes in JS merges.

Both tests were each creating a full ApiApplicationFactory (API +
identity TestHost startup), costing ~40 s per test in CI for ~80 s
total. Extracting the expensive server setup into
RelayPushRegistrationServiceFixture and using IClassFixture<T> means
both servers start once for the class and are shared across all test
methods, halving the overhead.

Also removes the 10 s timeout that was on the identity HttpClient as
a safety guard during the hang investigation — no longer needed now
that OTel and LaunchDarkly are properly suppressed.
Sharing a single HttpClient instance across test instances via the
fixture caused an InvalidOperationException: BaseIdentityClientService
sets HttpClient.BaseAddress in its constructor, which HttpClient
forbids after the first request has been sent.

Store the raw HttpMessageHandler in the fixture instead of the
HttpClient, and wrap it in a new HttpClient for each test constructor
invocation so BaseAddress can be set freely.
…s effect

WebApplicationFactory uses HostFactoryResolver to find a public static
CreateHostBuilder method on the entry point class. Without it, CreateHostBuilder()
returns null, and UpdateHostConfiguration calls are silently no-ops for the
API server. This caused OTel to remain enabled despite the test fixture
calling UpdateHostConfiguration("OpenTelemetry:Enabled", "false"), resulting
in the same 136s OTLP hang that was the original flakiness root cause.
… entry point

OTel OTLP exporters are now disabled for every test factory via
WebApplicationFactoryBase.CreateHostBuilder(), so no individual test fixture
needs to call UpdateHostConfiguration("OpenTelemetry:Enabled", "false").

ApiApplicationFactory and IdentityApplicationFactory are updated to use
WebApplicationFactory<Program> instead of WebApplicationFactory<Startup>.
TEntryPoint is only used for assembly discovery so behaviour is identical,
but Program is the correct modern entry-point type and aligns with
HostFactoryResolver's expectation.

The now-redundant UpdateHostConfiguration calls are removed from
RelayPushRegistrationServiceFixture.
// shared handlers in new HttpClient instances each time avoids the InvalidOperationException.
// disposeHandler: false — the handlers are owned by the fixture; disposing the per-test
// HttpClient must not dispose the shared underlying handler.
var cloudApiHttpClient = new HttpClient(fixture.CloudApiHandler, disposeHandler: false);
// disposeHandler: false — the handlers are owned by the fixture; disposing the per-test
// HttpClient must not dispose the shared underlying handler.
var cloudApiHttpClient = new HttpClient(fixture.CloudApiHandler, disposeHandler: false);
var cloudIdentityHttpClient = new HttpClient(fixture.IdentityBaseHandler, disposeHandler: false);
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

2 participants