add extensive [chessdebug] logging across all chess layers

Uses Log.d("chessdebug", ...) via quartz's multiplatform Log utility (android.util.Log on Android, println on Desktop) for proper logcat integration. Layers instrumented: - [Reconstructor] state reconstruction, move replay, desync detection - [Collector/CollectorMgr] event ingestion, dedup, routing - [GameLoader] game loading, live state conversion - [Lobby] challenges, moves, resign, spectating, polling refresh - [Polling] polling cycles, focused mode - [Broadcaster] relay connections, event send/confirm - [LiveGame] move validation, opponent moves, head event tracking - [AndroidVM] incoming event parsing from subscriptions Filter with: adb logcat | grep chessdebug
2026-03-24 14:18:01 +01:00
parent da53001e65
commit 944fbcd000
8 changed files with 159 additions and 18 deletions
@@ -25,6 +25,7 @@ import com.vitorpamplona.quartz.nip64Chess.jester.JesterEvent
 import com.vitorpamplona.quartz.nip64Chess.jester.JesterGameEvents
 import com.vitorpamplona.quartz.nip64Chess.jester.JesterProtocol
 import com.vitorpamplona.quartz.nip64Chess.jester.toJesterEvent
+import com.vitorpamplona.quartz.utils.Log
 import kotlinx.coroutines.flow.MutableStateFlow
 import kotlinx.coroutines.flow.StateFlow
 import kotlinx.coroutines.flow.asStateFlow
@@ -88,14 +89,20 @@ class ChessEventCollector(
     * @return true if the event was added, false if already exists or invalid
     */
    fun addEvent(event: JesterEvent): Boolean {
-        if (processedEventIds.contains(event.id)) return false
+        if (processedEventIds.contains(event.id)) {
+            Log.d("chessdebug", "[Collector] DEDUP: event ${event.id.take(8)} already processed for game ${startEventId.take(8)}")
+            return false
+        }

        // Check if this event belongs to our game
        val eventStartId = event.startEventId()
        val isStartEvent = event.isStartEvent() && event.id == startEventId
        val isMoveEvent = event.isMoveEvent() && eventStartId == startEventId

-        if (!isStartEvent && !isMoveEvent) return false
+        if (!isStartEvent && !isMoveEvent) {
+            Log.d("chessdebug", "[Collector] REJECTED: event ${event.id.take(8)} not for game ${startEventId.take(8)} (isStart=$isStartEvent, isMove=$isMoveEvent, eventStartId=${eventStartId?.take(8)})")
+            return false
+        }

        return if (isStartEvent) {
            addStartEvent(event)
@@ -129,6 +136,7 @@ class ChessEventCollector(
        if (_startEvent.compareAndSet(null, event)) {
            processedEventIds.add(event.id)
            incrementEventCount()
+            Log.d("chessdebug", "[Collector] START event added: id=${event.id.take(8)}, pubkey=${event.pubKey.take(8)}, createdAt=${event.createdAt}")
            return true
        }
        return false
@@ -148,6 +156,7 @@ class ChessEventCollector(
        if (moves.putIfAbsent(event.id, event) == null) {
            processedEventIds.add(event.id)
            incrementEventCount()
+            Log.d("chessdebug", "[Collector] MOVE event added: id=${event.id.take(8)}, pubkey=${event.pubKey.take(8)}, move=${event.move()}, historySize=${event.history().size}, fen=${event.fen()?.take(30)}, result=${event.result()}, totalMoves=${moves.size}")
            return true
        }
        return false
@@ -254,13 +263,22 @@ class ChessEventCollectorManager {
    fun addEvent(event: JesterEvent): Boolean {
        // For start events, create collector with event ID
        if (event.isStartEvent()) {
+            Log.d("chessdebug", "[CollectorMgr] Routing START event ${event.id.take(8)} from ${event.pubKey.take(8)}")
            val collector = getOrCreate(event.id)
            return collector.addEvent(event)
        }

        // For move events, find the collector by startEventId
-        val startId = event.startEventId() ?: return false
-        val collector = collectors[startId] ?: return false
+        val startId =
+            event.startEventId() ?: run {
+                Log.d("chessdebug", "[CollectorMgr] REJECTED: move event ${event.id.take(8)} has no startEventId")
+                return false
+            }
+        val collector =
+            collectors[startId] ?: run {
+                Log.d("chessdebug", "[CollectorMgr] REJECTED: no collector for game ${startId.take(8)} (active games: ${collectors.keys.map { it.take(8) }})")
+                return false
+            }
        return collector.addEvent(event)
    }
 }
@@ -20,6 +20,7 @@
 */
 package com.vitorpamplona.amethyst.commons.chess

+import com.vitorpamplona.quartz.utils.Log
 import kotlinx.coroutines.CoroutineScope
 import kotlinx.coroutines.Job
 import kotlinx.coroutines.delay
@@ -167,8 +168,10 @@ class ChessPollingDelegate(
     */
    fun start() {
        if (_isPolling.value) {
+            Log.d("chessdebug", "[Polling] start: already polling, skipping")
            return
        }
+        Log.d("chessdebug", "[Polling] start: gameInterval=${config.activeGamePollInterval}ms, challengeInterval=${config.challengePollInterval}ms")
        _isPolling.value = true

        // Poll for active games
@@ -177,10 +180,11 @@ class ChessPollingDelegate(
                while (isActive) {
                    val gameIds = getEffectiveGameIds()
                    if (gameIds.isNotEmpty()) {
+                        Log.d("chessdebug", "[Polling] polling ${gameIds.size} games: ${gameIds.map { it.take(8) }}, focused=${_focusedGameId.value?.take(8)}")
                        try {
                            onRefreshGames(gameIds)
-                        } catch (_: Exception) {
-                            // Error during refresh - continue polling
+                        } catch (e: Exception) {
+                            Log.d("chessdebug", "[Polling] ERROR during game refresh: ${e.message}")
                        }
                    }
                    delay(config.activeGamePollInterval)
@@ -28,6 +28,7 @@ import com.vitorpamplona.quartz.nip64Chess.ReconstructedGameState
 import com.vitorpamplona.quartz.nip64Chess.ReconstructionResult
 import com.vitorpamplona.quartz.nip64Chess.ViewerRole
 import com.vitorpamplona.quartz.nip64Chess.jester.JesterGameEvents
+import com.vitorpamplona.quartz.utils.Log

 /**
 * Converts a ReconstructedGameState (from ChessStateReconstructor) into a
@@ -63,7 +64,10 @@ object ChessGameLoader {
        result: ReconstructionResult,
        viewerPubkey: String,
    ): LiveChessGameState? {
-        if (result !is ReconstructionResult.Success) return null
+        if (result !is ReconstructionResult.Success) {
+            Log.d("chessdebug", "[GameLoader] toLiveGameState: reconstruction was not successful")
+            return null
+        }

        val state = result.state
        val engine = result.engine
@@ -75,6 +79,8 @@ object ChessGameLoader {
                ViewerRole.SPECTATOR -> viewerPubkey to (state.blackPubkey ?: "")
            }

+        Log.d("chessdebug", "[GameLoader] toLiveGameState: game=${state.startEventId.take(8)}, role=${state.viewerRole}, color=${state.playerColor}, isSpectator=${state.viewerRole == ViewerRole.SPECTATOR}, isPending=${state.isPendingChallenge}, moves=${state.moveHistory.size}")
+
        return LiveChessGameState(
            startEventId = state.startEventId,
            playerPubkey = playerPubkey,
@@ -91,9 +97,9 @@ object ChessGameLoader {

            // Mark finished if the game has ended
            if (state.isFinished() && state.gameStatus is com.vitorpamplona.quartz.nip64Chess.GameStatus.Finished) {
-                gameState.markAsFinished(
-                    (state.gameStatus as com.vitorpamplona.quartz.nip64Chess.GameStatus.Finished).result,
-                )
+                val gameResult = (state.gameStatus as com.vitorpamplona.quartz.nip64Chess.GameStatus.Finished).result
+                Log.d("chessdebug", "[GameLoader] Marking game ${state.startEventId.take(8)} as finished: $gameResult")
+                gameState.markAsFinished(gameResult)
            }

            // Handle pending draw offer
@@ -115,19 +121,23 @@ object ChessGameLoader {
        events: JesterGameEvents,
        viewerPubkey: String,
    ): LoadGameResult {
+        Log.d("chessdebug", "[GameLoader] loadGame: startEvent=${events.startEvent?.id?.take(8)}, moves=${events.moves.size}, viewer=${viewerPubkey.take(8)}")
        val result = ChessStateReconstructor.reconstruct(events, viewerPubkey)

        return when (result) {
            is ReconstructionResult.Success -> {
                val liveState = toLiveGameState(result, viewerPubkey)
                if (liveState != null) {
+                    Log.d("chessdebug", "[GameLoader] loadGame SUCCESS: game=${result.state.startEventId.take(8)}, status=${result.state.gameStatus}")
                    LoadGameResult.Success(liveState, result.state)
                } else {
+                    Log.d("chessdebug", "[GameLoader] loadGame FAILED: could not convert to live state")
                    LoadGameResult.Error("Failed to convert reconstructed state to live state")
                }
            }

            is ReconstructionResult.Error -> {
+                Log.d("chessdebug", "[GameLoader] loadGame ERROR: ${result.message}")
                LoadGameResult.Error(result.message)
            }
        }
@@ -149,6 +159,7 @@ object ChessGameLoader {
        playerColor: Color,
        isPendingChallenge: Boolean = false,
    ): LiveChessGameState {
+        Log.d("chessdebug", "[GameLoader] createNewGame: game=${startEventId.take(8)}, player=${playerPubkey.take(8)}, opponent=${opponentPubkey.take(8)}, color=$playerColor, isPending=$isPendingChallenge")
        val engine = ChessEngine()
        engine.reset()

@@ -28,6 +28,7 @@ import com.vitorpamplona.quartz.nip64Chess.GameStatus
 import com.vitorpamplona.quartz.nip64Chess.PieceType
 import com.vitorpamplona.quartz.nip64Chess.jester.JesterEvent
 import com.vitorpamplona.quartz.nip64Chess.jester.JesterGameEvents
+import com.vitorpamplona.quartz.utils.Log
 import com.vitorpamplona.quartz.utils.TimeUtils
 import kotlinx.coroutines.CoroutineScope
 import kotlinx.coroutines.Dispatchers
@@ -187,6 +188,7 @@ class ChessLobbyLogic(
     * Called by platform subscription callbacks for real-time updates.
     */
    fun handleIncomingEvent(event: JesterEvent) {
+        Log.d("chessdebug", "[Lobby] handleIncomingEvent: id=${event.id.take(8)}, pubkey=${event.pubKey.take(8)}, isStart=${event.isStartEvent()}, isMove=${event.isMoveEvent()}, createdAt=${event.createdAt}")
        when {
            event.isStartEvent() -> handleStartEvent(event)
            event.isMoveEvent() -> handleMoveEvent(event)
@@ -197,6 +199,8 @@ class ChessLobbyLogic(
        val startEventId = event.id
        val challengerColor = event.playerColor() ?: Color.WHITE

+        Log.d("chessdebug", "[Lobby] handleStartEvent: game=${startEventId.take(8)}, challenger=${event.pubKey.take(8)}, color=$challengerColor, opponent=${event.opponentPubkey()?.take(8)}")
+
        val challenge =
            ChessChallenge(
                eventId = event.id,
@@ -212,12 +216,26 @@ class ChessLobbyLogic(
    }

    private fun handleMoveEvent(event: JesterEvent) {
-        val startEventId = event.startEventId() ?: return
-        val san = event.move() ?: return
-        val fen = event.fen() ?: return
+        val startEventId =
+            event.startEventId() ?: run {
+                Log.d("chessdebug", "[Lobby] handleMoveEvent: REJECTED - no startEventId for event ${event.id.take(8)}")
+                return
+            }
+        val san =
+            event.move() ?: run {
+                Log.d("chessdebug", "[Lobby] handleMoveEvent: REJECTED - no move in event ${event.id.take(8)}")
+                return
+            }
+        val fen =
+            event.fen() ?: run {
+                Log.d("chessdebug", "[Lobby] handleMoveEvent: REJECTED - no FEN in event ${event.id.take(8)}")
+                return
+            }
        val history = event.history()
        val moveNumber = history.size

+        Log.d("chessdebug", "[Lobby] handleMoveEvent: game=${startEventId.take(8)}, move=$san, moveNumber=$moveNumber, from=${event.pubKey.take(8)}, result=${event.result()}")
+
        // Check if this is our game (we're either the author or tagged as opponent)
        val opponentFromTag = event.opponentPubkey()
        val isOurGame = event.pubKey == userPubkey || opponentFromTag == userPubkey
@@ -227,11 +245,15 @@ class ChessLobbyLogic(
        // If this is our game but we haven't loaded it yet, load it now
        // This happens when someone accepts our challenge (makes first move)
        if (gameState == null && isOurGame) {
+            Log.d("chessdebug", "[Lobby] handleMoveEvent: game ${startEventId.take(8)} not loaded but is ours - calling handleGameAccepted")
            handleGameAccepted(startEventId)
            return // handleGameAccepted will load the game and poll for events
        }

-        if (gameState == null) return
+        if (gameState == null) {
+            Log.d("chessdebug", "[Lobby] handleMoveEvent: game ${startEventId.take(8)} not loaded and not ours - ignoring")
+            return
+        }

        // Check for game end
        val result = event.result()
@@ -244,6 +266,7 @@ class ChessLobbyLogic(
                    else -> null
                }
            if (gameResult != null) {
+                Log.d("chessdebug", "[Lobby] handleMoveEvent: game ${startEventId.take(8)} ENDED: $result, termination=${event.termination()}")
                gameState.markAsFinished(gameResult)
                state.moveToCompleted(startEventId, result, event.termination())
                pollingDelegate.removeGameId(startEventId)
@@ -253,9 +276,12 @@ class ChessLobbyLogic(

        // Only apply opponent moves optimistically
        if (event.pubKey != userPubkey) {
+            Log.d("chessdebug", "[Lobby] handleMoveEvent: applying opponent move $san (move #$moveNumber) to game ${startEventId.take(8)}")
            gameState.applyOpponentMove(san, fen, moveNumber)
            // Update head event ID for move linking
            gameState.updateHeadEventId(event.id)
+        } else {
+            Log.d("chessdebug", "[Lobby] handleMoveEvent: skipping own move $san for game ${startEventId.take(8)}")
        }
    }

@@ -268,6 +294,7 @@ class ChessLobbyLogic(
        playerColor: Color = Color.WHITE,
        timeControl: String? = null, // Not supported in Jester, kept for API compatibility
    ) {
+        Log.d("chessdebug", "[Lobby] createChallenge: opponent=${opponentPubkey?.take(8)}, color=$playerColor")
        scope.launch(Dispatchers.Default) {
            state.setBroadcastStatus(
                ChessBroadcastStatus.Broadcasting(
@@ -280,6 +307,7 @@ class ChessLobbyLogic(
            val startEventId = retryWithBackoffResult { publisher.publishStart(playerColor, opponentPubkey) }

            if (startEventId != null) {
+                Log.d("chessdebug", "[Lobby] createChallenge SUCCESS: startEventId=${startEventId.take(8)}")
                // Add challenge to local state - shows in "Your Challenges" section
                val challenge =
                    ChessChallenge(
@@ -302,6 +330,7 @@ class ChessLobbyLogic(
                state.setBroadcastStatus(ChessBroadcastStatus.Idle)
                state.setError(null)
            } else {
+                Log.d("chessdebug", "[Lobby] createChallenge FAILED: publish returned null")
                state.setBroadcastStatus(
                    ChessBroadcastStatus.Failed("Challenge", "Failed to publish"),
                )
@@ -317,6 +346,7 @@ class ChessLobbyLogic(
     * In Jester protocol, acceptance is implicit - we just track the game locally.
     */
    fun acceptChallenge(challenge: ChessChallenge) {
+        Log.d("chessdebug", "[Lobby] acceptChallenge: game=${challenge.gameId.take(8)}, challenger=${challenge.challengerPubkey.take(8)}, color=${challenge.challengerColor.opposite()}")
        // Mark as accepted SYNCHRONOUSLY before launching coroutine
        // This prevents race where navigation happens before coroutine runs,
        // which would cause loadGame() to incorrectly mark as spectator
@@ -378,14 +408,17 @@ class ChessLobbyLogic(
     * When we detect our challenge was accepted (opponent made first move), load game from relays.
     */
    fun handleGameAccepted(startEventId: String) {
+        Log.d("chessdebug", "[Lobby] handleGameAccepted: game ${startEventId.take(8)} - fetching from relays")
        scope.launch(Dispatchers.Default) {
            state.setBroadcastStatus(ChessBroadcastStatus.Syncing(0f))

            val events = fetcher.fetchGameEvents(startEventId)
+            Log.d("chessdebug", "[Lobby] handleGameAccepted: fetched ${events.moves.size} moves for game ${startEventId.take(8)}")
            val result = ChessGameLoader.loadGame(events, userPubkey)

            when (result) {
                is LoadGameResult.Success -> {
+                    Log.d("chessdebug", "[Lobby] handleGameAccepted SUCCESS: game ${startEventId.take(8)}, role=${result.reconstructedState.viewerRole}")
                    state.addActiveGame(startEventId, result.liveState)
                    pollingDelegate.addGameId(startEventId)
                    state.setBroadcastStatus(ChessBroadcastStatus.Idle)
@@ -393,6 +426,7 @@ class ChessLobbyLogic(
                }

                is LoadGameResult.Error -> {
+                    Log.d("chessdebug", "[Lobby] handleGameAccepted FAILED: game ${startEventId.take(8)}, error=${result.message}")
                    state.setError("Failed to load game: ${result.message}")
                    state.setBroadcastStatus(ChessBroadcastStatus.Idle)
                }
@@ -409,9 +443,15 @@ class ChessLobbyLogic(
        from: String,
        to: String,
    ) {
-        val gameState = state.getGameState(startEventId) ?: return
+        Log.d("chessdebug", "[Lobby] publishMove: game=${startEventId.take(8)}, from=$from, to=$to")
+        val gameState =
+            state.getGameState(startEventId) ?: run {
+                Log.d("chessdebug", "[Lobby] publishMove: REJECTED - no game state for ${startEventId.take(8)}")
+                return
+            }

        if (state.isSpectating(startEventId)) {
+            Log.d("chessdebug", "[Lobby] publishMove: REJECTED - spectating game ${startEventId.take(8)}")
            state.setError("Cannot move while spectating")
            return
        }
@@ -419,7 +459,13 @@ class ChessLobbyLogic(
        // Parse promotion suffix from `to` if present (e.g., "e8q" -> "e8" + QUEEN)
        val (actualTo, promotion) = parsePromotionFromTo(to)

-        val moveResult = gameState.makeMove(from, actualTo, promotion) ?: return
+        val moveResult =
+            gameState.makeMove(from, actualTo, promotion) ?: run {
+                Log.d("chessdebug", "[Lobby] publishMove: REJECTED - makeMove returned null for $from->$actualTo in game ${startEventId.take(8)}")
+                return
+            }
+
+        Log.d("chessdebug", "[Lobby] publishMove: move validated: san=${moveResult.san}, fen=${moveResult.fen.take(30)}, history=${moveResult.history.size} moves, headEvent=${moveResult.headEventId.take(8)}")

        scope.launch(Dispatchers.Default) {
            state.setBroadcastStatus(
@@ -433,6 +479,7 @@ class ChessLobbyLogic(
            val newEventId = retryWithBackoffResult { publisher.publishMove(moveResult) }

            if (newEventId != null) {
+                Log.d("chessdebug", "[Lobby] publishMove SUCCESS: newEventId=${newEventId.take(8)} for game ${startEventId.take(8)}")
                // Update head event ID for next move linking
                gameState.updateHeadEventId(newEventId)

@@ -451,6 +498,7 @@ class ChessLobbyLogic(
                )
                state.setError(null)
            } else {
+                Log.d("chessdebug", "[Lobby] publishMove FAILED: reverting move ${moveResult.san} for game ${startEventId.take(8)}")
                // Revert the move since publishing failed
                gameState.undoLastMove()

@@ -463,6 +511,7 @@ class ChessLobbyLogic(
    }

    fun resign(startEventId: String) {
+        Log.d("chessdebug", "[Lobby] resign: game=${startEventId.take(8)}")
        val gameState = state.getGameState(startEventId) ?: return

        if (state.isSpectating(startEventId)) {
@@ -511,6 +560,7 @@ class ChessLobbyLogic(
    }

    fun loadGameAsSpectator(startEventId: String) {
+        Log.d("chessdebug", "[Lobby] loadGameAsSpectator: game=${startEventId.take(8)}")
        scope.launch(Dispatchers.Default) {
            state.setBroadcastStatus(ChessBroadcastStatus.Syncing(0f))

@@ -536,9 +586,11 @@ class ChessLobbyLogic(
    }

    fun loadGame(startEventId: String) {
+        Log.d("chessdebug", "[Lobby] loadGame: game=${startEventId.take(8)}")
        scope.launch(Dispatchers.Default) {
            // Don't load if game already exists or was accepted (acceptChallenge will handle it)
            if (state.getGameState(startEventId) != null || state.wasAccepted(startEventId)) {
+                Log.d("chessdebug", "[Lobby] loadGame: skipping - already exists or was accepted for ${startEventId.take(8)}")
                return@launch
            }

@@ -584,6 +636,7 @@ class ChessLobbyLogic(
    }

    private suspend fun refreshGame(startEventId: String) {
+        Log.d("chessdebug", "[Lobby] refreshGame: fetching game ${startEventId.take(8)} from relays")
        val events = fetcher.fetchGameEvents(startEventId)

        val result = ChessGameLoader.loadGame(events, userPubkey)
@@ -593,14 +646,17 @@ class ChessLobbyLogic(
                // Check status FIRST to avoid briefly emitting a finished game through activeGames
                val gameStatus = result.liveState.gameStatus.value
                if (gameStatus is GameStatus.Finished) {
+                    Log.d("chessdebug", "[Lobby] refreshGame: game ${startEventId.take(8)} is FINISHED (${(gameStatus as GameStatus.Finished).result}), moving to completed")
                    state.moveToCompleted(startEventId, gameStatus.result.notation, null)
                    pollingDelegate.removeGameId(startEventId)
                } else {
+                    Log.d("chessdebug", "[Lobby] refreshGame: game ${startEventId.take(8)} updated, moves=${result.liveState.moveHistory.value.size}, isPlayerTurn=${result.liveState.isPlayerTurn()}")
                    state.replaceGameState(startEventId, result.liveState)
                }
            }

            is LoadGameResult.Error -> {
+                Log.d("chessdebug", "[Lobby] refreshGame: ERROR for game ${startEventId.take(8)}: ${result.message}")
                // Don't overwrite error for periodic refresh failures
            }
        }
@@ -28,6 +28,7 @@ import com.vitorpamplona.quartz.nip01Core.relay.client.single.newSubId
 import com.vitorpamplona.quartz.nip01Core.relay.filters.Filter
 import com.vitorpamplona.quartz.nip01Core.relay.normalizer.NormalizedRelayUrl
 import com.vitorpamplona.quartz.nip64Chess.jester.JesterProtocol
+import com.vitorpamplona.quartz.utils.Log
 import kotlinx.coroutines.delay

 /**
@@ -67,11 +68,15 @@ class ChessEventBroadcaster(
        val targetRelays = ChessConfig.CHESS_RELAYS.map { NormalizedRelayUrl(it) }.toSet()
        val subId = newSubId()

+        Log.d("chessdebug", "[Broadcaster] broadcast: event=${event.id.take(8)}, kind=${event.kind}, targetRelays=${targetRelays.map { it.url }}")
+
        // Step 1: Check which relays are already connected
        val initialConnected = client.connectedRelaysFlow().value
        val alreadyConnected = targetRelays.intersect(initialConnected)
        val needsConnection = targetRelays - alreadyConnected

+        Log.d("chessdebug", "[Broadcaster] connected=${alreadyConnected.map { it.url }}, needsConnection=${needsConnection.map { it.url }}")
+
        // Step 2: If some relays need connection, open a subscription to trigger it
        if (needsConnection.isNotEmpty()) {
            // Use a valid filter with recent since timestamp to trigger connection
@@ -110,8 +115,11 @@ class ChessEventBroadcaster(
        }

        // Step 3: Send the event and wait for OK responses
+        Log.d("chessdebug", "[Broadcaster] sending event ${event.id.take(8)} and waiting for OK (timeout=${timeoutSeconds}s)")
        val success = client.sendAndWaitForResponse(event, targetRelays, timeoutSeconds)

+        Log.d("chessdebug", "[Broadcaster] broadcast result: success=$success for event ${event.id.take(8)}")
+
        // Note: sendAndWaitForResponse only returns aggregate success (any relay accepted)
        // We don't have per-relay results, so relayResults is empty
        return BroadcastResult(