Test failure #66

New issue

Closed

opened 2026-07-25 17:34:36 +00:00 by Grandiras · 2 comments

Grandiras commented

2026-07-25 17:34:36 +00:00

Owner

[xUnit.net 00:00:31.27] ATProtoNet.Tests.Pds.PdsFederationEndpointTests.SubscribeRepos_StreamsLiveCommitEvents [FAIL]
[xUnit.net 00:00:31.27] System.OperationCanceledException : The operation was canceled.
[xUnit.net 00:00:31.27] Stack Trace:
[xUnit.net 00:00:31.28] at System.Threading.CancellationToken.ThrowOperationCanceledException()
[xUnit.net 00:00:31.28] at System.Threading.SemaphoreSlim.WaitUntilCountOrTimeoutAsync(TaskNode asyncWaiter, Int64 millisecondsTimeout, CancellationToken cancellationToken)
[xUnit.net 00:00:31.28] at Microsoft.AspNetCore.TestHost.TestWebSocket.ReceiverSenderBuffer.ReceiveAsync(CancellationToken cancellationToken)
[xUnit.net 00:00:31.28] at Microsoft.AspNetCore.TestHost.TestWebSocket.ReceiveAsync(ArraySegment1 buffer, CancellationToken cancellationToken) [xUnit.net 00:00:31.28] /workspace/Grandiras/ATProto.NET/tests/ATProtoNet.Tests/Pds/PdsFederationEndpointTests.cs(503,0): at ATProtoNet.Tests.Pds.PdsFederationEndpointTests.ReceiveFrameAsync(WebSocket socket, CancellationToken cancellationToken) [xUnit.net 00:00:31.28] /workspace/Grandiras/ATProto.NET/tests/ATProtoNet.Tests/Pds/PdsFederationEndpointTests.cs(437,0): at ATProtoNet.Tests.Pds.PdsFederationEndpointTests.SubscribeRepos_StreamsLiveCommitEvents() [xUnit.net 00:00:31.28] --- End of stack trace from previous location --- Failed ATProtoNet.Tests.Pds.PdsFederationEndpointTests.SubscribeRepos_StreamsLiveCommitEvents [30 s] Error Message: System.OperationCanceledException : The operation was canceled. Stack Trace: at System.Threading.CancellationToken.ThrowOperationCanceledException() at System.Threading.SemaphoreSlim.WaitUntilCountOrTimeoutAsync(TaskNode asyncWaiter, Int64 millisecondsTimeout, CancellationToken cancellationToken) at Microsoft.AspNetCore.TestHost.TestWebSocket.ReceiverSenderBuffer.ReceiveAsync(CancellationToken cancellationToken) at Microsoft.AspNetCore.TestHost.TestWebSocket.ReceiveAsync(ArraySegment1 buffer, CancellationToken cancellationToken)
at ATProtoNet.Tests.Pds.PdsFederationEndpointTests.ReceiveFrameAsync(WebSocket socket, CancellationToken cancellationToken) in /workspace/Grandiras/ATProto.NET/tests/ATProtoNet.Tests/Pds/PdsFederationEndpointTests.cs:line 503
at ATProtoNet.Tests.Pds.PdsFederationEndpointTests.SubscribeRepos_StreamsLiveCommitEvents() in /workspace/Grandiras/ATProto.NET/tests/ATProtoNet.Tests/Pds/PdsFederationEndpointTests.cs:line 437
--- End of stack trace from previous location ---

[xUnit.net 00:00:31.27] ATProtoNet.Tests.Pds.PdsFederationEndpointTests.SubscribeRepos_StreamsLiveCommitEvents [FAIL] [xUnit.net 00:00:31.27] System.OperationCanceledException : The operation was canceled. [xUnit.net 00:00:31.27] Stack Trace: [xUnit.net 00:00:31.28] at System.Threading.CancellationToken.ThrowOperationCanceledException() [xUnit.net 00:00:31.28] at System.Threading.SemaphoreSlim.WaitUntilCountOrTimeoutAsync(TaskNode asyncWaiter, Int64 millisecondsTimeout, CancellationToken cancellationToken) [xUnit.net 00:00:31.28] at Microsoft.AspNetCore.TestHost.TestWebSocket.ReceiverSenderBuffer.ReceiveAsync(CancellationToken cancellationToken) [xUnit.net 00:00:31.28] at Microsoft.AspNetCore.TestHost.TestWebSocket.ReceiveAsync(ArraySegment`1 buffer, CancellationToken cancellationToken) [xUnit.net 00:00:31.28] /workspace/Grandiras/ATProto.NET/tests/ATProtoNet.Tests/Pds/PdsFederationEndpointTests.cs(503,0): at ATProtoNet.Tests.Pds.PdsFederationEndpointTests.ReceiveFrameAsync(WebSocket socket, CancellationToken cancellationToken) [xUnit.net 00:00:31.28] /workspace/Grandiras/ATProto.NET/tests/ATProtoNet.Tests/Pds/PdsFederationEndpointTests.cs(437,0): at ATProtoNet.Tests.Pds.PdsFederationEndpointTests.SubscribeRepos_StreamsLiveCommitEvents() [xUnit.net 00:00:31.28] --- End of stack trace from previous location --- Failed ATProtoNet.Tests.Pds.PdsFederationEndpointTests.SubscribeRepos_StreamsLiveCommitEvents [30 s] Error Message: System.OperationCanceledException : The operation was canceled. Stack Trace: at System.Threading.CancellationToken.ThrowOperationCanceledException() at System.Threading.SemaphoreSlim.WaitUntilCountOrTimeoutAsync(TaskNode asyncWaiter, Int64 millisecondsTimeout, CancellationToken cancellationToken) at Microsoft.AspNetCore.TestHost.TestWebSocket.ReceiverSenderBuffer.ReceiveAsync(CancellationToken cancellationToken) at Microsoft.AspNetCore.TestHost.TestWebSocket.ReceiveAsync(ArraySegment`1 buffer, CancellationToken cancellationToken) at ATProtoNet.Tests.Pds.PdsFederationEndpointTests.ReceiveFrameAsync(WebSocket socket, CancellationToken cancellationToken) in /workspace/Grandiras/ATProto.NET/tests/ATProtoNet.Tests/Pds/PdsFederationEndpointTests.cs:line 503 at ATProtoNet.Tests.Pds.PdsFederationEndpointTests.SubscribeRepos_StreamsLiveCommitEvents() in /workspace/Grandiras/ATProto.NET/tests/ATProtoNet.Tests/Pds/PdsFederationEndpointTests.cs:line 437 --- End of stack trace from previous location ---

claude-bot was assigned by Grandiras

2026-07-25 17:34:39 +00:00

claude-bot commented

2026-07-25 17:34:42 +00:00

Collaborator

🤖 On it — follow along in the action run; the reply will link the full session transcript.

📜 Live transcript — updating every ~5 minutes while the task runs.

🤖 On it — follow along in [the action run](https://git.grandiras.net/Grandiras/claude-bot/actions/runs/68); the reply will link the full session transcript. 📜 [Live transcript](https://git.grandiras.net/Grandiras/claude-bot/src/branch/claude-logs/transcripts/Grandiras/ATProto.NET/issue-66/run-68.md) — updating every ~5 minutes while the task runs.

claude-bot referenced this issue from a commit

2026-07-25 17:42:43 +00:00

fix: subscribe to the firehose before accepting the WebSocket

claude-bot referenced this issue from a pull request that will close it,

2026-07-25 17:43:10 +00:00

Claude: changes for issue #66 #67

claude-bot commented

2026-07-25 17:43:10 +00:00

Collaborator

Pushed branch claude/issue-66.

Root cause

Not a flaky test — a real race in the PDS firehose handler.

subscribeRepos accepted the WebSocket and then enumerated PdsSequencer.SubscribeAsync. Because that method is an async IAsyncEnumerable, its body — including the _subscribers.Add(...) registration — doesn't run until the first read. Meanwhile, with TestServer (and Kestrel), the client's ConnectAsync returns as soon as the server calls AcceptWebSocketAsync. That leaves a window where the peer believes it is connected and can already provoke events, but nothing is listening yet.

The test does exactly that: connect, then immediately createRecord. If the #commit is published in that window it lands in neither the replay snapshot (there is none — no cursor) nor the live channel, and the live-only subscriber waits out the full 30 s for a frame that is already gone.

Verification

I confirmed the mechanism rather than guessing. The test passes 8/8 in isolation, so I temporarily inserted await Task.Delay(500) between accept and subscribe — that reproduced the reported failure exactly: same OperationCanceledException, same ReceiveFrameAsync stack frame, same 30 s duration. With the fix and that same 500 ms delay still in place, all 26 PdsFederationEndpointTests pass, which is the real proof the window is closed.

Fix

Added PdsSequencer.Subscribe(cursor), which registers eagerly and returns a disposable PdsFirehoseSubscription. Events published between registering and the first read are buffered on its channel instead of dropped.
The handler now subscribes before AcceptWebSocketAsync, so "connected" and "receiving" become the same instant.
The subscription also carries CurrentSeq / OldestAvailableSeq snapshotted under the same lock as the registration, and the FutureCursor / OutdatedCursor checks now read those instead of re-reading the live sequencer. That closes a second, narrower TOCTOU where a publish racing the handshake could make a valid cursor look like a future one.
SubscribeAsync is unchanged and delegates to the new method — no breaking change; existing callers and the five existing SubscribeAsync tests still pass untouched.

Tests

Added four deterministic PdsSequencerTests covering the contract at the level where it can be asserted without timing: buffering across the registration→read gap, the snapshot not moving under a later publish, idempotent disposal, and rejecting double enumeration.

Full suite: 1398/1398 passing, Release config, three consecutive runs. Build has 0 errors and no new warnings.

One note on scope: I fixed the server rather than the test, because the same hole is reachable by a real relay — the test just happens to hit the timing reliably enough to expose it. A cursor-based relay would recover on reconnect, but a live-only subscriber silently loses the event.

⏱ 8m 7s · 44 turns · tokens: 61.0k in / 21.2k out (+2148.3k cache-read)
📜 Full session transcript
→ Opened PR: #67

Pushed branch **`claude/issue-66`**. ## Root cause Not a flaky test — a real race in the PDS firehose handler. `subscribeRepos` accepted the WebSocket and *then* enumerated `PdsSequencer.SubscribeAsync`. Because that method is an `async IAsyncEnumerable`, its body — including the `_subscribers.Add(...)` registration — doesn't run until the first read. Meanwhile, with `TestServer` (and Kestrel), the client's `ConnectAsync` returns as soon as the server calls `AcceptWebSocketAsync`. That leaves a window where the peer believes it is connected and can already provoke events, but nothing is listening yet. The test does exactly that: connect, then immediately `createRecord`. If the `#commit` is published in that window it lands in neither the replay snapshot (there is none — no cursor) nor the live channel, and the live-only subscriber waits out the full 30 s for a frame that is already gone. ## Verification I confirmed the mechanism rather than guessing. The test passes 8/8 in isolation, so I temporarily inserted `await Task.Delay(500)` between accept and subscribe — that reproduced the reported failure exactly: same `OperationCanceledException`, same `ReceiveFrameAsync` stack frame, same 30 s duration. With the fix and that same 500 ms delay still in place, all 26 `PdsFederationEndpointTests` pass, which is the real proof the window is closed. ## Fix - Added `PdsSequencer.Subscribe(cursor)`, which registers **eagerly** and returns a disposable `PdsFirehoseSubscription`. Events published between registering and the first read are buffered on its channel instead of dropped. - The handler now subscribes *before* `AcceptWebSocketAsync`, so "connected" and "receiving" become the same instant. - The subscription also carries `CurrentSeq` / `OldestAvailableSeq` snapshotted under the same lock as the registration, and the `FutureCursor` / `OutdatedCursor` checks now read those instead of re-reading the live sequencer. That closes a second, narrower TOCTOU where a publish racing the handshake could make a valid cursor look like a future one. - `SubscribeAsync` is unchanged and delegates to the new method — no breaking change; existing callers and the five existing `SubscribeAsync` tests still pass untouched. ## Tests Added four deterministic `PdsSequencerTests` covering the contract at the level where it can be asserted without timing: buffering across the registration→read gap, the snapshot not moving under a later publish, idempotent disposal, and rejecting double enumeration. Full suite: **1398/1398 passing**, Release config, three consecutive runs. Build has 0 errors and no new warnings. One note on scope: I fixed the server rather than the test, because the same hole is reachable by a real relay — the test just happens to hit the timing reliably enough to expose it. A cursor-based relay would recover on reconnect, but a live-only subscriber silently loses the event. --- ⏱ 8m 7s · 44 turns · tokens: 61.0k in / 21.2k out (+2148.3k cache-read) 📜 [Full session transcript](https://git.grandiras.net/Grandiras/claude-bot/src/branch/claude-logs/transcripts/Grandiras/ATProto.NET/issue-66/run-68.md) → Opened PR: https://git.grandiras.net/Grandiras/ATProto.NET/pulls/67

Grandiras closed this issue

2026-07-25 17:44:43 +00:00

Grandiras referenced this issue from a commit

2026-07-25 17:44:43 +00:00

Claude: changes for issue #66 (#67)