Compare commits

...
Author SHA1 Message Date
adminandClaude 2544d57c79 Add logging to diagnose subscription write failures
After reconnect, data wasn't flowing. The StreamOneGame writes are
fire-and-forget (can't await inside lock), so failures were silent.

Added logging:
- [SUBSCRIBE] when StreamGameRequest is being sent
- [SUBSCRIBE] when write completes successfully
- [WRITE_FAILED] when _streamingCall is null
- [WRITE_FAILED] when RpcException occurs

Also added null check for _streamingCall in DoWithStreamingCall.

🤖 Generated with [Claude Code](https://claude.com/claude-code)

Co-Authored-By: Claude <noreply@anthropic.com>
2025-12-05 21:01:55 -08:00
adminandClaude c1f466348d Increase idle timeout from 30s to 300s to match main deadline
The 30-second idle timeout was triggering during normal game idle periods
(AI thinking, between turns, etc.) because no gRPC messages were being sent.
This caused a reconnect loop every 35 seconds:

1. connect_success
2. 15s: idle_warning (no gRPC messages, but HTTP/2 keepalive is fine)
3. 25s: idle_warning
4. 35s: idle_timeout - kills working connection
5. Immediate reconnect succeeds
6. Repeat...

The idle timeout is redundant with:
- HTTP/2 keepalive (15s) handling transport-level health
- 5-minute deadline catching truly dead connections

Set MaxIdleSeconds = 300 (same as deadline) to effectively disable
the idle timeout as a separate mechanism. Also updated warning
thresholds from 10s/20s to 2min/4min.

🤖 Generated with [Claude Code](https://claude.com/claude-code)

Co-Authored-By: Claude <noreply@anthropic.com>
2025-12-05 20:54:41 -08:00
@@ -28,8 +28,10 @@ namespace eagle {
public class PersistentClientConnection : IDisposable {
private const double TimeoutSeconds = 300.0;
// Idle timeout = 2x HTTP/2 keepalive interval (15s * 2 = 30s)
private const double MaxIdleSeconds = 30.0;
// Idle timeout - must be longer than potential idle periods in the game
// (AI thinking, between turns, etc.). Set equal to deadline since HTTP/2
// keepalive handles transport-level connection health.
private const double MaxIdleSeconds = 300.0;
private DateTime _lastResponseReceived = DateTime.UtcNow;
private int _lastIdleWarningLevel = 0; // 0=none, 1=10s warning, 2=20s warning
@@ -170,8 +172,16 @@ namespace eagle {
var request = new UpdateStreamRequest { StreamGameRequest = streamGameRequest };
DoWithStreamingCall(async (sc) => {
_remoteEagleClientLogger.LogLine(
$"[SUBSCRIBE] Sending StreamGameRequest for game {subscriber.GameId}, " +
$"unfilteredCount={subscriber.LastUnfilteredResultCount}");
// Note: This is fire-and-forget because we're often called from inside a lock.
// DoWithStreamingCall will log if the write fails.
_ = DoWithStreamingCall(async (sc) => {
await sc.RequestStream.WriteAsync(request);
_remoteEagleClientLogger.LogLine(
$"[SUBSCRIBE] StreamGameRequest sent successfully for game {subscriber.GameId}");
return true;
});
}
@@ -528,13 +538,23 @@ namespace eagle {
private delegate Task<bool> WithStreamingCallDelegate(
AsyncDuplexStreamingCall<UpdateStreamRequest, UpdateStreamResponse> call);
private async Task<bool> DoWithStreamingCall(WithStreamingCallDelegate action) {
var sc = _streamingCall;
if (sc == null) {
_remoteEagleClientLogger.LogLine(
"[WRITE_FAILED] _streamingCall is null, write skipped");
return false;
}
try {
return await action(_streamingCall);
return await action(sc);
} catch (RpcException e) {
if (e.StatusCode == StatusCode.Cancelled) {
// This is expected when the connection is closed.
_remoteEagleClientLogger.LogLine(
$"[WRITE_FAILED] RpcException Cancelled: {e.Message}");
return false;
} else {
_remoteEagleClientLogger.LogLine(
$"[WRITE_FAILED] RpcException {e.StatusCode}: {e.Message}");
throw;
}
}
@@ -797,17 +817,17 @@ namespace eagle {
var idleTime = (DateTime.UtcNow - _lastResponseReceived).TotalSeconds;
// Early warnings at 10s and 20s to help diagnose slow connections
if (idleTime > 20.0 && _lastIdleWarningLevel < 2) {
// Early warnings at 2min and 4min to help diagnose slow connections
if (idleTime > 240.0 && _lastIdleWarningLevel < 2) {
_lastIdleWarningLevel = 2;
_remoteEagleClientLogger.LogLine(
$"[IDLE_WARNING] No messages received in {idleTime:F1}s (timeout at {MaxIdleSeconds}s)");
LogConnectionEvent("idle_warning_20s", $"idle_time={idleTime:F1}s");
} else if (idleTime > 10.0 && _lastIdleWarningLevel < 1) {
LogConnectionEvent("idle_warning_4min", $"idle_time={idleTime:F1}s");
} else if (idleTime > 120.0 && _lastIdleWarningLevel < 1) {
_lastIdleWarningLevel = 1;
_remoteEagleClientLogger.LogLine(
$"[IDLE_WARNING] No messages received in {idleTime:F1}s (timeout at {MaxIdleSeconds}s)");
LogConnectionEvent("idle_warning_10s", $"idle_time={idleTime:F1}s");
LogConnectionEvent("idle_warning_2min", $"idle_time={idleTime:F1}s");
}
if (idleTime > MaxIdleSeconds) {