Add comprehensive timestamped logging for connection flow tracing

Adds a LogFlow() helper method that logs with precise timestamps in
HH:mm:ss.fff format. Uses LogFlow throughout the connection flow to
trace:
- Connection attempts and state transitions
- Subscription requests and acknowledgments
- Game updates (ActionResult, ShardokResult) with counts
- Heartbeat send/receive with sync status
- Sync mismatch detection
- Reconnect scheduling

Also removes debug Console.WriteLine statements and redundant UI
Debug.Log, replacing them with consistent LogFlow output.

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

Co-Authored-By: Claude Opus 4.5 <noreply@anthropic.com>

src/main/csharp/net/eagle0/clients/unity/eagle0/Assets/Eagle/EagleGameModel.cs

@@ -311,20 +311,36 @@ namespace eagle {
                     // Store server-reported game status for UI
                     if (updateItem.ActionResultResponse.ServerGameStatus != null) {
                         ServerStatus = updateItem.ActionResultResponse.ServerGameStatus;
+                        _connectionLogger.LogLine(
+                                $"[UPDATE] ServerGameStatus updated: {ServerStatus.Status}");
                     }
 
                     // Note: _lastUnfilteredResultCount is updated on the gRPC thread in
                     // UpdateResultCounts() before enqueueing. We don't update it here to avoid
                     // race conditions where a backlogged MainQueue update overwrites a newer count.
 
-                    if (updateItem.ActionResultResponse.ActionResultViews.Any() ||
-                        updateItem.ActionResultResponse.AvailableCommands == null ||
-                        updateItem.ActionResultResponse.AvailableCommands.Token !=
-                                _currentModel.CommandToken) {
+                    var hasResults = updateItem.ActionResultResponse.ActionResultViews.Any();
+                    var hasCommands = updateItem.ActionResultResponse.AvailableCommands != null;
+                    var incomingToken =
+                            hasCommands ? updateItem.ActionResultResponse.AvailableCommands.Token
+                                        : -1;
+                    var tokenMatches = hasCommands && incomingToken == _currentModel.CommandToken;
+
+                    _connectionLogger.LogLine(
+                            $"[UPDATE] hasResults={hasResults}, hasCommands={hasCommands}, " +
+                            $"incomingToken={incomingToken}, currentToken={_currentModel.CommandTokenString}, " +
+                            $"tokenMatches={tokenMatches}");
+
+                    if (hasResults || !hasCommands || !tokenMatches) {
                         HandleUpdates(updateItem.ActionResultResponse.ActionResultViews.ToList());
                         HandleAvailableCommands(updateItem.ActionResultResponse.AvailableCommands);
 
                         if (UpdateAction != null) UpdateAction.Invoke(_currentModel);
+                        _connectionLogger.LogLine(
+                                "[UPDATE] Processed update and invoked UpdateAction");
+                    } else {
+                        _connectionLogger.LogLine(
+                                "[UPDATE] SKIPPED - no results, has commands, token matches");
                     }
 
                     break;

src/main/csharp/net/eagle0/clients/unity/eagle0/Assets/Eagle/PersistentClientConnection.cs

@@ -44,6 +44,12 @@ namespace eagle {
 
         private readonly Logger _remoteEagleClientLogger = Logger.GetLogger("ConnectionLogger");
         private readonly Logger _timingsLogger = Logger.GetLogger("ConnectionLogger");
+
+        /// <summary>Timestamped log for connection flow tracing.</summary>
+        private void LogFlow(string message) {
+            var ts = DateTime.UtcNow.ToString("HH:mm:ss.fff");
+            _remoteEagleClientLogger.LogLine($"[FLOW {ts}] {message}");
+        }
         private volatile bool _isConnecting = false;
         private Timer _idleCheckTimer = null;
         private Timer _heartbeatTimer = null;
@@ -122,6 +128,7 @@ namespace eagle {
             _currentState = ConnectionState.Reconnecting;
             NextReconnectAttempt = DateTime.UtcNow.AddSeconds(backoffSeconds);
 
+            LogFlow($"SCHEDULE_RECONNECT reason={reason} backoff={backoffSeconds:F1}s attempt={_consecutiveFailures}");
             LogConnectionEvent(
                     "schedule_reconnect",
                     $"{reason}, backoff={backoffSeconds:F1}s, attempt={_consecutiveFailures}");
@@ -194,16 +201,14 @@ namespace eagle {
             var ackTcs = new TaskCompletionSource<SubscriptionAck>();
             lock (_pendingSubscriptionAcks) { _pendingSubscriptionAcks[gameId] = ackTcs; }
 
-            _remoteEagleClientLogger.LogLine(
-                    $"[SUBSCRIBE] Sending StreamGameRequest for game {gameId}, " +
-                    $"unfilteredCount={subscriber.LastUnfilteredResultCount}");
+            var shardokCount = shardokStatuses.Count();
+            LogFlow($"SUBSCRIBE game={gameId} unfilteredCount={subscriber.LastUnfilteredResultCount} shardokGames={shardokCount}");
 
             var sendSuccess = await DoWithStreamingCall(async (sc) => {
-                await sc.RequestStream.WriteAsync(request);
-                _remoteEagleClientLogger.LogLine(
-                        $"[SUBSCRIBE] StreamGameRequest sent successfully for game {gameId}");
-                return true;
-            });
+                                  await sc.RequestStream.WriteAsync(request).ConfigureAwait(false);
+                                  LogFlow($"SUBSCRIBE sent for game={gameId}");
+                                  return true;
+                              }).ConfigureAwait(false);
 
             if (!sendSuccess) {
                 // Write failed - clean up and return
@@ -217,7 +222,7 @@ namespace eagle {
             try {
                 var ackTask = ackTcs.Task;
                 var timeoutTask = Task.Delay(SubscriptionAckTimeoutMs, timeoutCts.Token);
-                var completedTask = await Task.WhenAny(ackTask, timeoutTask);
+                var completedTask = await Task.WhenAny(ackTask, timeoutTask).ConfigureAwait(false);
 
                 if (completedTask == timeoutTask) {
                     // Timeout waiting for ack
@@ -231,24 +236,15 @@ namespace eagle {
                 // Cancel the timeout task since ack was received
                 timeoutCts.Cancel();
 
-                var ack = await ackTask;
+                var ack = await ackTask.ConfigureAwait(false);
                 if (ack.Success) {
-                    _remoteEagleClientLogger.LogLine(
-                            $"[SUBSCRIBE] Subscription confirmed for game {gameId}, " +
-                            $"confirmedResultCount={ack.ConfirmedResultCount}");
-
-                    // Note: Shardok resync flags are cleared in EagleGameModel.HandleOneGameUpdate
-                    // AFTER updates are actually received, not here. This ensures that if the
-                    // connection drops between acknowledgment and update delivery, the resync
-                    // will be requested again on the next reconnect.
-
+                    LogFlow($"SUBSCRIBE_ACK game={gameId} success=true confirmedCount={ack.ConfirmedResultCount}");
                     return true;
                 } else {
+                    LogFlow($"SUBSCRIBE_ACK game={gameId} success=false error={ack.ErrorMessage}");
                     LogConnectionEvent(
                             "subscribe_ack_failed",
                             $"game={gameId}, error={ack.ErrorMessage}");
-                    _remoteEagleClientLogger.LogLine(
-                            $"[SUBSCRIBE] Server rejected subscription for game {gameId}: {ack.ErrorMessage}");
                     return false;
                 }
             } catch (OperationCanceledException) {
@@ -266,9 +262,11 @@ namespace eagle {
         }
 
         public async Task Connect() {
+            LogFlow($"Connect() called, state={_currentState}, failures={_consecutiveFailures}");
+
             // Prevent concurrent connection attempts
             if (_isConnecting) {
-                _remoteEagleClientLogger.LogLine($"Connect() skipped - already connecting");
+                LogFlow("Connect() skipped - already connecting");
                 return;
             }
 
@@ -286,6 +284,7 @@ namespace eagle {
                 _currentState = _consecutiveFailures > 0 ? ConnectionState.Reconnecting
                                                          : ConnectionState.Connecting;
                 NextReconnectAttempt = null;
+                LogFlow($"State -> {_currentState}");
                 LogConnectionEvent("connect_attempt");
 
                 // Dispose existing streaming call before creating new one
@@ -318,13 +317,19 @@ namespace eagle {
 
                     // Stream subscriptions OUTSIDE lock (can await)
                     // Set state to SubscriptionPending while waiting for acks
+                    LogFlow($"Stream created, {subscribersToStream.Count} subscribers to stream");
                     if (subscribersToStream.Any()) {
                         _currentState = ConnectionState.SubscriptionPending;
+                        LogFlow($"State -> {_currentState}");
                     }
 
                     bool allSucceeded = true;
                     foreach (var subscriber in subscribersToStream) {
-                        if (!await StreamOneGameAsync(subscriber)) { allSucceeded = false; }
+                        LogFlow($"Subscribing game {subscriber.GameId}...");
+                        if (!await StreamOneGameAsync(subscriber)) {
+                            LogFlow($"Subscription FAILED for game {subscriber.GameId}");
+                            allSucceeded = false;
+                        }
                     }
 
                     if (!allSucceeded) {
@@ -353,6 +358,7 @@ namespace eagle {
                     _lastSuccessfulConnect = DateTime.UtcNow;
                     _consecutiveFailures = 0;  // Reset backoff on successful connection
                     _currentState = ConnectionState.Connected;
+                    LogFlow($"State -> {_currentState} (all subscriptions succeeded)");
                     _circuitBreaker.RecordSuccess();
                     LogConnectionEvent("connect_success");
 
@@ -470,8 +476,8 @@ namespace eagle {
                                     break;
                                 }
                             }
-
-                            await PostRequest(nextCommand);
+                            // Note: PostRequest is called inside each case, not here
+                            // (removed duplicate PostRequest call that was causing double-posting)
                         }
                     }
 
@@ -570,16 +576,18 @@ namespace eagle {
 
         public async Task PostError(EagleGameId gameId, string errorMessage, string stackTrace) {
             await DoWithStreamingCall(async (streamingCall) => {
-                await streamingCall.RequestStream.WriteAsync(new UpdateStreamRequest {
-                    ErrorRequest =
-                            new ErrorRequest {
-                                ErrorMessage = errorMessage,
-                                GameId = gameId,
-                                StackTrace = stackTrace
-                            }
-                });
+                await streamingCall.RequestStream
+                        .WriteAsync(new UpdateStreamRequest {
+                            ErrorRequest =
+                                    new ErrorRequest {
+                                        ErrorMessage = errorMessage,
+                                        GameId = gameId,
+                                        StackTrace = stackTrace
+                                    }
+                        })
+                        .ConfigureAwait(false);
                 return true;
-            });
+            }).ConfigureAwait(false);
         }
 
         public void Unsubscribe(IClientConnectionSubscriber subscriber) {
@@ -591,10 +599,11 @@ namespace eagle {
                 lock (this) { _pendingCommands.Add(request); }
 
                 await DoWithStreamingCall(async (streamingCall) => {
-                    await streamingCall.RequestStream.WriteAsync(
-                            new UpdateStreamRequest { PostCommandRequest = request });
+                    await streamingCall.RequestStream
+                            .WriteAsync(new UpdateStreamRequest { PostCommandRequest = request })
+                            .ConfigureAwait(false);
                     return true;
-                });
+                }).ConfigureAwait(false);
                 lock (this) { _pendingCommands.Remove(request); }
             } catch (Exception e) { Console.WriteLine("Failed to post command: " + e); }
         }
@@ -675,8 +684,20 @@ namespace eagle {
                 AsyncDuplexStreamingCall<UpdateStreamRequest, UpdateStreamResponse> call);
         private async Task<bool> DoWithStreamingCall(WithStreamingCallDelegate action) {
             try {
-                return await action(_streamingCall);
-            } catch (RpcException e) {
+                var actionTask = action(_streamingCall);
+                var timeoutTask = Task.Delay(WriteTimeoutMs, _cancellationToken);
+
+                var completedTask =
+                        await Task.WhenAny(actionTask, timeoutTask).ConfigureAwait(false);
+
+                if (completedTask == timeoutTask) {
+                    _remoteEagleClientLogger.LogLine(
+                            "[WRITE] DoWithStreamingCall timed out - connection may be dead");
+                    return false;
+                }
+
+                return await actionTask.ConfigureAwait(false);
+            } catch (OperationCanceledException) { return false; } catch (RpcException e) {
                 if (e.StatusCode == StatusCode.Cancelled) {
                     // This is expected when the connection is closed.
                     return false;
@@ -686,6 +707,9 @@ namespace eagle {
             }
         }
 
+        // Timeout for WriteAsync to prevent ThreadPool exhaustion from blocked writes
+        private const int WriteTimeoutMs = 10000;
+
         public async Task<bool> SendUpdateStreamRequestAsync(UpdateStreamRequest request) {
             AsyncDuplexStreamingCall<UpdateStreamRequest, UpdateStreamResponse> sc = null;
             lock (this) {
@@ -694,8 +718,18 @@ namespace eagle {
             }
 
             try {
-                await sc.RequestStream.WriteAsync(request, _cancellationToken);
+                // Use timeout to prevent indefinite blocking on dead connections
+                using var timeoutCts =
+                        CancellationTokenSource.CreateLinkedTokenSource(_cancellationToken);
+                timeoutCts.CancelAfter(WriteTimeoutMs);
+
+                await sc.RequestStream.WriteAsync(request, timeoutCts.Token).ConfigureAwait(false);
                 return true;
+            } catch (OperationCanceledException) {
+                // Timeout or cancellation - connection is likely dead
+                _remoteEagleClientLogger.LogLine(
+                        "[WRITE] WriteAsync timed out or cancelled - connection may be dead");
+                return false;
             } catch (RpcException e) {
                 if (e.StatusCode == StatusCode.Cancelled) {
                     // This is expected when the connection is closed.
@@ -714,7 +748,7 @@ namespace eagle {
         private void HandleGameUpdate(GameUpdate gameUpdate, DateTime receivedTime) {
             switch (gameUpdate.GameUpdateDetailsCase) {
                 case GameUpdate.GameUpdateDetailsOneofCase.ErrorResponse:
-                    _remoteEagleClientLogger.LogLine("Got an error response!");
+                    LogFlow($"UPDATE ErrorResponse game={gameUpdate.GameId}");
                     MainQueue.Q.Enqueue(() => {
                         lock (this) { _subscribers.Remove(gameUpdate.GameId); }
                     });
@@ -722,7 +756,6 @@ namespace eagle {
 
                 case GameUpdate.GameUpdateDetailsOneofCase.StreamingTextResponse:
                     // Handle streaming text directly on gRPC thread - dictionary is thread-safe.
-                    // Listeners are notified later via ProcessPendingUpdates() on main thread.
                     var str = gameUpdate.StreamingTextResponse;
                     if (str != null) {
                         ClientTextProvider.Provider.HandleNewStreamingText(
@@ -731,15 +764,22 @@ namespace eagle {
                                 str.StartingByteCount,
                                 str.Completed);
                     }
-                    // No MainQueue enqueue needed - ProcessPendingUpdates handles listener
-                    // notification
                     break;
 
                 case GameUpdate.GameUpdateDetailsOneofCase.ActionResultResponse:
-                case GameUpdate.GameUpdateDetailsOneofCase.ShardokActionResultResponse:
-                    // Update result counts IMMEDIATELY on the gRPC thread, before enqueueing.
-                    // This ensures reconnects use accurate counts even when MainQueue is blocked
-                    // (e.g., when Unity is backgrounded).
+                    var arResp = gameUpdate.ActionResultResponse;
+                    var arCount = arResp.ActionResultViews?.Count ?? 0;
+                    var hasStartingState = gameUpdate.StartingState != null;
+                    var hasCommands = arResp.AvailableCommands != null;
+                    var cmdToken = hasCommands ? arResp.AvailableCommands.Token : -1;
+                    var cmdCount = hasCommands
+                                           ? arResp.AvailableCommands.CommandsByProvince?.Count ?? 0
+                                           : 0;
+                    var status = arResp.ServerGameStatus?.Status.ToString() ?? "null";
+                    LogFlow($"UPDATE ActionResult game={gameUpdate.GameId} actionResults={arCount} " +
+                            $"startingState={hasStartingState} hasCommands={hasCommands} " +
+                            $"token={cmdToken} cmdProvinces={cmdCount} status={status}");
+
                     lock (this) {
                         if (_subscribers.TryGetValue(gameUpdate.GameId, out var sub)) {
                             sub.UpdateResultCounts(gameUpdate);
@@ -755,19 +795,38 @@ namespace eagle {
                                 _subscribers.Remove(gameUpdate.GameId);
                             }
                         }
-
                         await TryPendingCommands();
+                    });
+                    break;
 
-                        var processTime = (DateTime.UtcNow - receivedTime).TotalMilliseconds;
-                        if (processTime > 100.0) {
-                            _timingsLogger.LogLine($"PROCESS {processTime} ms");
+                case GameUpdate.GameUpdateDetailsOneofCase.ShardokActionResultResponse:
+                    var shResp = gameUpdate.ShardokActionResultResponse;
+                    var shGames = shResp.ShardokGameResponses?.Count ?? 0;
+                    LogFlow($"UPDATE ShardokResult game={gameUpdate.GameId} shardokGames={shGames}");
+
+                    lock (this) {
+                        if (_subscribers.TryGetValue(gameUpdate.GameId, out var sub2)) {
+                            sub2.UpdateResultCounts(gameUpdate);
                         }
+                    }
+
+                    MainQueue.Q.Enqueue(async () => {
+                        IClientConnectionSubscriber subscriber;
+                        lock (this) {
+                            if (_subscribers.TryGetValue(gameUpdate.GameId, out subscriber)) {
+                                subscriber.ReceiveGameUpdate(gameUpdate);
+                            } else {
+                                _subscribers.Remove(gameUpdate.GameId);
+                            }
+                        }
+                        await TryPendingCommands();
                     });
                     break;
             }
         }
 
         private async void HandleStreamingCall() {
+            LogFlow("HandleStreamingCall STARTED");
             try {
                 AsyncDuplexStreamingCall<UpdateStreamRequest, UpdateStreamResponse> sc;
                 CancellationToken threadToken;
@@ -883,8 +942,10 @@ namespace eagle {
                     waitStartTime = DateTime.UtcNow;
                 }
 
-                _remoteEagleClientLogger.LogLine(
-                        "How did we get here? This is not my beautiful wife!");
+                // While loop exited normally (not via exception)
+                var scNull = sc == null;
+                var tokenCancelled = _currentThreadToken.IsCancellationRequested;
+                LogFlow($"HandleStreamingCall ENDED normally: sc_null={scNull} token_cancelled={tokenCancelled}");
             } catch (RpcException e) {
                 lock (this) {
                     _lastDisconnect = DateTime.UtcNow;
@@ -983,9 +1044,11 @@ namespace eagle {
                 Interval = 5000  // Check every 5 seconds
             };
             _idleCheckTimer.Elapsed += (sender, args) => {
-                // Log BEFORE callback to confirm timer is firing
-                Console.WriteLine($"[IDLE_TIMER] Elapsed at {DateTime.UtcNow:HH:mm:ss.fff}");
-                CheckForIdleTimeout();
+                try {
+                    CheckForIdleTimeout();
+                } catch (Exception e) {
+                    LogFlow($"IDLE_TIMER_ERROR {e.GetType().Name}: {e.Message}");
+                }
             };
             _idleCheckTimer.Enabled = true;
         }
@@ -1041,9 +1104,17 @@ namespace eagle {
             _heartbeatTimer =
                     new Timer { AutoReset = true, Interval = HeartbeatIntervalSeconds * 1000 };
             _heartbeatTimer.Elapsed += (sender, args) => {
-                // Log BEFORE Task.Run to confirm timer is firing
-                Console.WriteLine($"[HEARTBEAT_TIMER] Elapsed at {DateTime.UtcNow:HH:mm:ss.fff}");
-                Task.Run(() => SendHeartbeat());
+                try {
+                    Task.Run(async () => {
+                        try {
+                            await SendHeartbeat().ConfigureAwait(false);
+                        } catch (Exception e) {
+                            LogFlow($"HEARTBEAT_ERROR {e.GetType().Name}: {e.Message}");
+                        }
+                    });
+                } catch (Exception e) {
+                    LogFlow($"HEARTBEAT_TIMER_ERROR {e.GetType().Name}: {e.Message}");
+                }
             };
             _heartbeatTimer.Enabled = true;
         }
@@ -1057,15 +1128,14 @@ namespace eagle {
         }
 
         private async Task SendHeartbeat() {
-            _remoteEagleClientLogger.LogLine($"[HEARTBEAT] Timer fired, state={_currentState}");
+            LogFlow($"HEARTBEAT_START state={_currentState}");
 
             if (_cancellationToken.IsCancellationRequested) {
-                _remoteEagleClientLogger.LogLine("[HEARTBEAT] Skipped - cancellation requested");
+                LogFlow("HEARTBEAT_SKIP reason=cancellation_requested");
                 return;
             }
             if (_currentState != ConnectionState.Connected) {
-                _remoteEagleClientLogger.LogLine(
-                        $"[HEARTBEAT] Skipped - not connected (state={_currentState})");
+                LogFlow($"HEARTBEAT_SKIP reason=not_connected state={_currentState}");
                 return;
             }
 
@@ -1101,10 +1171,9 @@ namespace eagle {
                         ", ",
                         heartbeatRequest.GameSyncStatuses.Select(
                                 g => $"{g.GameId}:{g.UnfilteredResultCount}"));
-                _remoteEagleClientLogger.LogLine(
-                        $"[HEARTBEAT] Sent heartbeat with {heartbeatRequest.GameSyncStatuses.Count} games ({gameInfo})");
+                LogFlow($"HEARTBEAT_SENT games={heartbeatRequest.GameSyncStatuses.Count} ({gameInfo})");
             } else {
-                _remoteEagleClientLogger.LogLine("[HEARTBEAT] Failed to send - stream unavailable");
+                LogFlow("HEARTBEAT_FAILED stream_unavailable");
             }
         }
 
@@ -1113,31 +1182,19 @@ namespace eagle {
         private const double SyncMismatchGracePeriodSeconds = 60.0;
 
         private void HandleHeartbeatResponse(HeartbeatResponse response) {
-            _remoteEagleClientLogger.LogLine(
-                    $"[HEARTBEAT] Got response, server_timestamp={response.ServerTimestamp}");
+            LogFlow($"HEARTBEAT_RESPONSE server_ts={response.ServerTimestamp}");
 
             // Check for sync mismatches reported by server
             bool hasMismatch = false;
             foreach (var syncResult in response.GameSyncResults) {
                 if (!syncResult.EagleInSync) {
-                    _remoteEagleClientLogger.LogLine(
-                            $"[SYNC_MISMATCH] Game {syncResult.GameId}: Eagle out of sync, " +
-                            $"server has {syncResult.ServerUnfilteredResultCount} results");
-                    LogConnectionEvent(
-                            "sync_mismatch_eagle",
-                            $"game={syncResult.GameId}, server_count={syncResult.ServerUnfilteredResultCount}");
+                    LogFlow($"SYNC_MISMATCH game={syncResult.GameId} server_count={syncResult.ServerUnfilteredResultCount}");
                     hasMismatch = true;
                 }
 
                 foreach (var shardokResult in syncResult.ShardokSyncResults) {
                     if (!shardokResult.InSync) {
-                        _remoteEagleClientLogger.LogLine(
-                                $"[SYNC_MISMATCH] Game {syncResult.GameId}, Shardok {shardokResult.ShardokGameId}: " +
-                                $"out of sync, server has {shardokResult.ServerFilteredResultCount} results");
-                        LogConnectionEvent(
-                                "sync_mismatch_shardok",
-                                $"game={syncResult.GameId}, shardok={shardokResult.ShardokGameId}, " +
-                                        $"server_count={shardokResult.ServerFilteredResultCount}");
+                        LogFlow($"SYNC_MISMATCH game={syncResult.GameId} shardok={shardokResult.ShardokGameId} server_count={shardokResult.ServerFilteredResultCount}");
                         hasMismatch = true;
                     }
                 }