From 1a36c8096de2a9f879f3464e7e1803ce93884975 Mon Sep 17 00:00:00 2001 From: Assistant builder Date: Fri, 12 Jun 2026 07:17:04 +0000 Subject: [PATCH] Diagnostics: surface upstream WS close reason + break the null-spin loop MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The Pi journal showed 170 000 'upstream silent NxN' messages within one second — i.e. ReceiveJsonAsync was returning null in zero time, so the upstream WS to OpenAI was closed. The relay was spinning until idle watchdog (30 s) fired. Add IRealtimeUpstream.IsClosed + CloseReason, populated by OpenAIRealtimeUpstream from the close status / WS exception, and have PumpAsync stop on close and forward error code=upstream_closed message=close status= desc= to the device. Closes the spin AND gives us the OpenAI close reason. --- backend.tests/ScriptedRealtimeUpstream.cs | 2 ++ backend/DeviceHub/DeviceHubEndpoint.cs | 2 +- backend/Realtime/IRealtimeUpstream.cs | 4 ++++ backend/Realtime/OpenAIRealtimeUpstream.cs | 28 ++++++++++++++++++---- backend/Realtime/RealtimeSession.cs | 22 ++++++++++++++--- 5 files changed, 50 insertions(+), 8 deletions(-) diff --git a/backend.tests/ScriptedRealtimeUpstream.cs b/backend.tests/ScriptedRealtimeUpstream.cs index 5a332f4..631223b 100644 --- a/backend.tests/ScriptedRealtimeUpstream.cs +++ b/backend.tests/ScriptedRealtimeUpstream.cs @@ -13,6 +13,8 @@ public class ScriptedRealtimeUpstream : IRealtimeUpstream Channel.CreateUnbounded(new UnboundedChannelOptions { SingleWriter = true }); public IList Sent { get; } = new List(); + public bool IsClosed => _toRelay.Reader.Completion.IsCompleted; + public string? CloseReason => IsClosed ? "scripted upstream closed" : null; public Task SendJsonAsync(JsonObject envelope, CancellationToken ct) { diff --git a/backend/DeviceHub/DeviceHubEndpoint.cs b/backend/DeviceHub/DeviceHubEndpoint.cs index 5d655f6..32b9a63 100644 --- a/backend/DeviceHub/DeviceHubEndpoint.cs +++ b/backend/DeviceHub/DeviceHubEndpoint.cs @@ -179,7 +179,7 @@ public static class DeviceHubEndpoint // Bump on every backend change so we can verify a Coolify deploy landed // by looking at the hello_ack config.server_version field in the Pi journal. - public const string ServerVersion = "plan3-debug-2026-06-12-09"; + public const string ServerVersion = "plan3-debug-2026-06-12-09-closeprobe"; private static async Task SendHelloAckAsync(ActiveDevice active, Device device, CancellationToken ct) { diff --git a/backend/Realtime/IRealtimeUpstream.cs b/backend/Realtime/IRealtimeUpstream.cs index 9a5b11f..2b2a6ad 100644 --- a/backend/Realtime/IRealtimeUpstream.cs +++ b/backend/Realtime/IRealtimeUpstream.cs @@ -6,4 +6,8 @@ public interface IRealtimeUpstream : IAsyncDisposable { Task SendJsonAsync(JsonObject envelope, CancellationToken ct); Task ReceiveJsonAsync(CancellationToken ct); + // Once a receive returns null because the WebSocket transitioned out of + // the Open state, these surface why. Both stay null until that happens. + bool IsClosed { get; } + string? CloseReason { get; } } diff --git a/backend/Realtime/OpenAIRealtimeUpstream.cs b/backend/Realtime/OpenAIRealtimeUpstream.cs index 2720915..551b0f7 100644 --- a/backend/Realtime/OpenAIRealtimeUpstream.cs +++ b/backend/Realtime/OpenAIRealtimeUpstream.cs @@ -7,6 +7,10 @@ namespace backend.Realtime; public class OpenAIRealtimeUpstream : IRealtimeUpstream { private readonly ClientWebSocket _ws = new(); + private string? _closeReason; + + public bool IsClosed => _ws.State != WebSocketState.Open && _ws.State != WebSocketState.Connecting; + public string? CloseReason => _closeReason; public async Task ConnectAsync(string apiKey, string model, CancellationToken ct) { @@ -31,11 +35,27 @@ public class OpenAIRealtimeUpstream : IRealtimeUpstream while (true) { WebSocketReceiveResult result; - try { result = await _ws.ReceiveAsync(buffer, ct); } - catch (WebSocketException) { return null; } - catch (OperationCanceledException) { return null; } + try + { + result = await _ws.ReceiveAsync(buffer, ct); + } + catch (WebSocketException exc) + { + _closeReason ??= $"WebSocketException:{exc.WebSocketErrorCode}:{exc.Message}"; + return null; + } + catch (OperationCanceledException) + { + return null; + } - if (result.MessageType == WebSocketMessageType.Close) return null; + if (result.MessageType == WebSocketMessageType.Close) + { + var status = _ws.CloseStatus?.ToString() ?? ""; + var desc = _ws.CloseStatusDescription ?? ""; + _closeReason ??= $"close status={status} desc={desc}"; + return null; + } stream.Write(buffer, 0, result.Count); if (result.EndOfMessage) { diff --git a/backend/Realtime/RealtimeSession.cs b/backend/Realtime/RealtimeSession.cs index 9586dd1..4b27016 100644 --- a/backend/Realtime/RealtimeSession.cs +++ b/backend/Realtime/RealtimeSession.cs @@ -128,9 +128,25 @@ public class RealtimeSession if (evt is null && ct.IsCancellationRequested) return; if (evt is null) { - // Upstream has gone silent. Surface that to the device every - // ~2s so we can tell "OpenAI is up but emitting nothing" from - // "the upstream WS was closed" — Coolify logs aren't reachable. + // If the upstream WS is closed, stop spinning — surface the + // close reason to the device and bail with EndReason=Error. + if (_upstream.IsClosed) + { + var reason = _upstream.CloseReason ?? "upstream closed"; + _logger.LogWarning("upstream closed mid-session: {Reason}", reason); + await _output.WriteEnvelopeAsync(new JsonObject + { + ["type"] = "error", + ["code"] = "upstream_closed", + ["message"] = reason, + ["fatal"] = false, + }, ct); + _endReason = EndReason.Error; + return; + } + // Surface "alive but silent" every ~2s so we can tell that + // from "the upstream WS was closed". Coolify logs aren't + // reachable from the dev sandbox. if (++nullPolls % 8 == 0) { _logger.LogInformation("upstream silent ({Polls} x 250ms polls)", nullPolls);