Skip to content

Commit 1d39505

Browse files
davidkellydavidkelly
committed
NCBC-4163 Another stability pass on unit tests
Motivation ========== Several unit tests intermittently fail on our CI. We need to get these as deterministic as possible, given the nature of the CI system Modification ============ Add internal ForceFlush() to ThresholdTraceListener so Test_Logs can trigger report generation directly. The test is now fully synchronous since Start(), ActivityStopped, and ForceFlush are all synchronous. Rewrite LightweightStopwatchTests to verify the struct's contract (non-negative, consistent, monotonic, restart resets) using SpinWait instead of Task.Delay with fixed timing bounds. Remove Task.Delay from InFlightOperationSetTests assertions. The returned tasks are structurally incomplete (semaphore full / Task.WhenAll on pending CompletionTasks), so IsCompleted can be asserted immediately. Results ======= All 25 tests pass deterministically with zero timing dependencies. No test skips required. Change-Id: Ic6cde6e4ef93718342d57ce4c7322dd52796e0dc Reviewed-on: https://review.couchbase.org/c/couchbase-net-client/+/241904 Reviewed-by: Emilien Bevierre <emilien.bevierre@couchbase.com> Tested-by: Build Bot <build@couchbase.com>
1 parent 34ae40d commit 1d39505

4 files changed

Lines changed: 74 additions & 100 deletions

File tree

‎src/Couchbase/Core/Diagnostics/Tracing/ThresholdTracing/ThresholdTraceListener.cs‎

Lines changed: 6 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -98,6 +98,12 @@ public sealed override void Start()
9898
Listener.ShouldListenTo = s => s.Name == RequestTracer.ActivitySourceName;
9999
}
100100

101+
/// <summary>
102+
/// Immediately generates and logs any pending threshold report.
103+
/// Exposed for unit testing to avoid Timer/ThreadPool scheduling dependencies.
104+
/// </summary>
105+
internal void ForceFlush() => GenerateAndLogReport(this);
106+
101107
public override void Dispose()
102108
{
103109
if (Interlocked.Exchange(ref _disposed, 1) == 1)

‎tests/Couchbase.UnitTests/Core/Diagnostics/Tracing/ThresholdTracerTests.cs‎

Lines changed: 10 additions & 16 deletions
Original file line numberDiff line numberDiff line change
@@ -15,8 +15,8 @@
1515

1616
namespace Couchbase.UnitTests.Core.Diagnostics.Tracing
1717
{
18-
// ThresholdTraceListener uses static ThresholdServiceQueue.CoreQueues, so tests using it
19-
// must not run in parallel to avoid one test's timer draining another test's data.
18+
// Tests using ThresholdTraceListener share a static ActivitySource, so they
19+
// must not run in parallel to avoid listener interference.
2020
[Collection("NonParallel")]
2121
public class ThresholdTracerTests : IDisposable
2222
{
@@ -123,35 +123,29 @@ public void TestChild()
123123
}
124124

125125
[Fact]
126-
public async Task Test_Logs()
126+
public void Test_Logs()
127127
{
128+
// This test is fully synchronous: Start() registers the listener immediately,
129+
// ActivityStopped fires synchronously during span Dispose, and ForceFlush()
130+
// triggers report generation without depending on Timer/ThreadPool scheduling.
128131
var loggerFactory = new LoggingMeterTests.LoggingMeterTestFactory();
129132
using var tracer = new RequestTracer();
130133
using var listener = new ThresholdTraceListener(loggerFactory, new ThresholdOptions
131134
{
132-
EmitInterval = TimeSpan.FromMilliseconds(100),
135+
EmitInterval = TimeSpan.FromHours(1), // disabled; we flush manually
133136
KvThreshold = TimeSpan.Zero
134137
});
135138
tracer.Start(listener);
136-
// Delay to insure the tracer is registered with the ActivitySource
137-
await Task.Delay(100);
138139

139140
using (var parentSpan = tracer.RequestSpan("get"))
140141
{
141142
parentSpan.SetAttribute(OuterRequestSpans.Attributes.Service, OuterRequestSpans.ServiceSpan.Kv.Name);
142-
await Task.Delay(10); // Ensure span duration exceeds threshold
143143
}
144144

145-
// Brief yield to allow ActivityStopped callback to complete before polling
146-
await Task.Yield();
147-
148-
string report = null;
149-
// Use async polling instead of SpinWait to avoid starving background tasks on overloaded CI
150-
var finished = await AsyncTestHelper.WaitForConditionAsync(
151-
() => loggerFactory.LoggedData.TryTake(out report),
152-
timeout: TimeSpan.FromSeconds(30));
153-
Assert.True(finished, userMessage: "Did not find a log entry for threshold data.");
145+
listener.ForceFlush();
154146

147+
Assert.True(loggerFactory.LoggedData.TryTake(out var report),
148+
"Did not find a log entry for threshold data.");
155149
Assert.NotNull(report);
156150
Assert.StartsWith("{", report);
157151

‎tests/Couchbase.UnitTests/Core/IO/Connections/InFlightOperationSetTests.cs‎

Lines changed: 5 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -11,6 +11,9 @@
1111

1212
namespace Couchbase.UnitTests.Core.IO.Connections
1313
{
14+
// Assertions on IsCompleted are made without Task.Delay or Task.Yield because the
15+
// async methods use SemaphoreSlim.WaitAsync / Task.WhenAll internally, which return
16+
// structurally incomplete tasks when their preconditions are not met.
1417
public class InFlightOperationSetTests
1518
{
1619
#region AddAsync
@@ -47,8 +50,7 @@ public async Task AddAsync_PastMaximum_Waits()
4750
// Act
4851

4952
var addTask = set.AddAsync(state);
50-
await Task.Delay(10);
51-
Assert.False(addTask.IsCompleted);
53+
Assert.False(addTask.IsCompleted); // semaphore is full
5254

5355
Assert.True(set.TryRemove(6, out _));
5456

@@ -227,13 +229,10 @@ public async Task WaitForAllOperationsAsync_WithStates_WaitsOnAll()
227229

228230
var task = set.WaitForAllOperationsAsync(TimeSpan.FromSeconds(10));
229231

230-
// Assert
231-
232-
await Task.Delay(10);
232+
// See class comment — these are structurally incomplete (no states completed yet)
233233
Assert.False(task.IsCompleted, userMessage: "Task should not be complete before any states are complete.");
234234

235235
state1.Complete(SlicedMemoryOwner<byte>.Empty);
236-
await Task.Delay(10);
237236
Assert.False(task.IsCompleted, userMessage: "Task should not be complete before all states are complete");
238237

239238
state2.Complete(SlicedMemoryOwner<byte>.Empty);

‎tests/Couchbase.UnitTests/Utils/LightweightStopwatchTests.cs‎

Lines changed: 53 additions & 78 deletions
Original file line numberDiff line numberDiff line change
@@ -7,124 +7,99 @@
77

88
namespace Couchbase.UnitTests.Utils
99
{
10-
[Collection("NonParallel")]
10+
// Tests verify the wrapper's contract (non-negative, consistent, monotonic, restart resets)
11+
// without Task.Delay or fixed timing bounds. SpinWait is used only to advance the clock
12+
// by at least one tick, which is deterministic regardless of machine load.
1113
public class LightweightStopwatchTests
1214
{
13-
#region Elapsed
15+
#region StartNew / Elapsed
1416

1517
[Fact]
16-
public void Elapsed_AfterStart_LowValue()
18+
public void StartNew_Elapsed_IsNonNegative()
1719
{
18-
// Arrange
20+
var sw = LightweightStopwatch.StartNew();
1921

20-
var stopwatch = LightweightStopwatch.StartNew();
21-
22-
// Act
23-
24-
var result = stopwatch.Elapsed;
25-
26-
// Assert
27-
28-
Assert.True(result < TimeSpan.FromSeconds(1));
22+
Assert.True(sw.Elapsed >= TimeSpan.Zero);
2923
}
3024

31-
[Fact(Skip="Inconsistent behavior in underprovisioned Jenkins.")]
32-
public void Elapsed_AfterSleep_ApproximateValue()
25+
[Fact]
26+
public void StartNew_ElapsedMilliseconds_IsNonNegative()
3327
{
34-
// Arrange
35-
36-
var oldSw = Stopwatch.StartNew();
37-
var stopwatch = LightweightStopwatch.StartNew();
28+
var sw = LightweightStopwatch.StartNew();
3829

39-
// Act
40-
41-
SpinWait.SpinUntil(() => oldSw.ElapsedMilliseconds >= 1000);
42-
var result = stopwatch.ElapsedMilliseconds;
43-
var oldResult = oldSw.ElapsedMilliseconds;
44-
oldSw.Stop();
45-
46-
// Assert
47-
Assert.InRange(result, oldResult - 250, oldResult + 250);
30+
Assert.True(sw.ElapsedMilliseconds >= 0);
4831
}
4932

50-
#endregion
51-
52-
#region ElapsedMilliseconds
53-
5433
[Fact]
55-
public void ElapsedMilliseconds_AfterStart_LowValue()
34+
public void StartNew_ElapsedMilliseconds_IsLow()
5635
{
57-
// Arrange
58-
59-
var stopwatch = LightweightStopwatch.StartNew();
36+
var sw = LightweightStopwatch.StartNew();
6037

61-
// Act
62-
63-
var result = stopwatch.ElapsedMilliseconds;
64-
65-
// Assert
66-
67-
Assert.True(result < 1000);
38+
Assert.True(sw.ElapsedMilliseconds < 1000,
39+
$"ElapsedMilliseconds should be near zero immediately after StartNew, was {sw.ElapsedMilliseconds}");
6840
}
6941

70-
[Fact(Skip="Inconsistent behavior in underprovisioned Jenkins.")]
71-
public async Task ElapsedMilliseconds_AfterSleep_ApproximateValue()
42+
[Fact]
43+
public void Elapsed_And_ElapsedMilliseconds_AreConsistent()
7244
{
73-
// Arrange
45+
var sw = LightweightStopwatch.StartNew();
46+
SpinWait.SpinUntil(() => sw.ElapsedMilliseconds > 0);
7447

75-
var stopwatch = LightweightStopwatch.StartNew();
48+
var elapsedMs = sw.ElapsedMilliseconds;
49+
var elapsedTimeSpanMs = (long)sw.Elapsed.TotalMilliseconds;
7650

77-
// Act
51+
// They should agree within a small tolerance (one could tick between reads)
52+
Assert.True(Math.Abs(elapsedTimeSpanMs - elapsedMs) < 50,
53+
$"Elapsed ({elapsedTimeSpanMs}ms) and ElapsedMilliseconds ({elapsedMs}ms) should be consistent");
54+
}
7855

79-
await Task.Delay(TimeSpan.FromMilliseconds(1000));
80-
var result = stopwatch.ElapsedMilliseconds;
56+
[Fact]
57+
public void Elapsed_IsMonotonicallyIncreasing()
58+
{
59+
var sw = LightweightStopwatch.StartNew();
60+
var first = sw.ElapsedMilliseconds;
61+
SpinWait.SpinUntil(() => sw.ElapsedMilliseconds > first);
62+
var second = sw.ElapsedMilliseconds;
8163

82-
// Assert
83-
Assert.InRange(result, 750, 3000);
64+
Assert.True(second > first,
65+
$"Expected second reading ({second}) > first reading ({first})");
8466
}
8567

8668
#endregion
8769

8870
#region Restart
8971

9072
[Fact]
91-
public async Task Restart_AfterStart_LowValue()
73+
public void Restart_ResetsElapsed()
9274
{
93-
// Arrange
94-
95-
var stopwatch = LightweightStopwatch.StartNew();
96-
await Task.Delay(1000);
97-
Assert.True(stopwatch.ElapsedMilliseconds > 500);
98-
99-
// Act
75+
var sw = LightweightStopwatch.StartNew();
10076

101-
stopwatch.Restart();
102-
var result = stopwatch.ElapsedMilliseconds;
77+
// Ensure elapsed advances past zero
78+
SpinWait.SpinUntil(() => sw.ElapsedMilliseconds > 0);
79+
var before = sw.ElapsedMilliseconds;
80+
Assert.True(before > 0);
10381

104-
// Assert
82+
sw.Restart();
83+
var after = sw.ElapsedMilliseconds;
10584

106-
Assert.True(result < 1000);
85+
Assert.True(after < before,
86+
$"After Restart, ElapsedMilliseconds ({after}) should be less than before ({before})");
10787
}
10888

10989
[Fact]
110-
public async Task Restart_AfterSleep_ApproximateValue()
90+
public void Restart_ElapsedContinuesToAdvance()
11191
{
112-
// Arrange
113-
await Task.Yield();
114-
115-
var stopwatch = LightweightStopwatch.StartNew();
116-
await Task.Delay(TimeSpan.FromMilliseconds(1000));
117-
Assert.True(stopwatch.ElapsedMilliseconds > 500);
118-
119-
// Act
92+
var sw = LightweightStopwatch.StartNew();
93+
SpinWait.SpinUntil(() => sw.ElapsedMilliseconds > 0);
12094

121-
stopwatch.Restart();
122-
await Task.Delay(TimeSpan.FromMilliseconds(1000));
123-
var result = stopwatch.ElapsedMilliseconds;
95+
sw.Restart();
12496

125-
// Assert
97+
// After restart, it should still be advancing
98+
var afterRestart = sw.ElapsedMilliseconds;
99+
SpinWait.SpinUntil(() => sw.ElapsedMilliseconds > afterRestart);
126100

127-
Assert.True(result > 500);
101+
Assert.True(sw.ElapsedMilliseconds > afterRestart,
102+
"Stopwatch should continue to advance after Restart");
128103
}
129104

130105
#endregion

0 commit comments

Comments
 (0)