diff --git a/amethyst/src/main/java/com/vitorpamplona/amethyst/ui/screen/loggedIn/chess/ChessViewModelNew.kt b/amethyst/src/main/java/com/vitorpamplona/amethyst/ui/screen/loggedIn/chess/ChessViewModelNew.kt index 97711b9e3e..00ec7b0674 100644 --- a/amethyst/src/main/java/com/vitorpamplona/amethyst/ui/screen/loggedIn/chess/ChessViewModelNew.kt +++ b/amethyst/src/main/java/com/vitorpamplona/amethyst/ui/screen/loggedIn/chess/ChessViewModelNew.kt @@ -36,6 +36,7 @@ import com.vitorpamplona.quartz.nip64Chess.Color import com.vitorpamplona.quartz.nip64Chess.LiveChessGameState import com.vitorpamplona.quartz.nip64Chess.jester.JesterProtocol import com.vitorpamplona.quartz.nip64Chess.jester.toJesterEvent +import com.vitorpamplona.quartz.utils.Log import kotlinx.coroutines.flow.StateFlow /** @@ -94,6 +95,7 @@ class ChessViewModelNew( // ============================================ init { + Log.d("chessdebug", "[AndroidVM] init: instanceId=$instanceId, userPubkey=${account.userProfile().pubkeyHex.take(8)}") logic.startPolling() } @@ -132,7 +134,12 @@ class ChessViewModelNew( fun handleIncomingEvent(event: Event) { if (event.kind != JesterProtocol.KIND) return - val jesterEvent = event.toJesterEvent() ?: return + val jesterEvent = + event.toJesterEvent() ?: run { + Log.d("chessdebug", "[AndroidVM] handleIncomingEvent: failed to parse kind ${event.kind} event ${event.id.take(8)} as JesterEvent") + return + } + Log.d("chessdebug", "[AndroidVM] handleIncomingEvent: id=${event.id.take(8)}, pubkey=${event.pubKey.take(8)}, isStart=${jesterEvent.isStartEvent()}, isMove=${jesterEvent.isMoveEvent()}") logic.handleIncomingEvent(jesterEvent) } diff --git a/commons/src/commonMain/kotlin/com/vitorpamplona/amethyst/commons/chess/ChessEventCollector.kt b/commons/src/commonMain/kotlin/com/vitorpamplona/amethyst/commons/chess/ChessEventCollector.kt index 8a4575f3f8..297557d662 100644 --- a/commons/src/commonMain/kotlin/com/vitorpamplona/amethyst/commons/chess/ChessEventCollector.kt +++ b/commons/src/commonMain/kotlin/com/vitorpamplona/amethyst/commons/chess/ChessEventCollector.kt @@ -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) } } diff --git a/commons/src/commonMain/kotlin/com/vitorpamplona/amethyst/commons/chess/ChessEventPolling.kt b/commons/src/commonMain/kotlin/com/vitorpamplona/amethyst/commons/chess/ChessEventPolling.kt index f73db65d9b..91a46df5c8 100644 --- a/commons/src/commonMain/kotlin/com/vitorpamplona/amethyst/commons/chess/ChessEventPolling.kt +++ b/commons/src/commonMain/kotlin/com/vitorpamplona/amethyst/commons/chess/ChessEventPolling.kt @@ -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) diff --git a/commons/src/commonMain/kotlin/com/vitorpamplona/amethyst/commons/chess/ChessGameLoader.kt b/commons/src/commonMain/kotlin/com/vitorpamplona/amethyst/commons/chess/ChessGameLoader.kt index ea66317914..40dd68cc14 100644 --- a/commons/src/commonMain/kotlin/com/vitorpamplona/amethyst/commons/chess/ChessGameLoader.kt +++ b/commons/src/commonMain/kotlin/com/vitorpamplona/amethyst/commons/chess/ChessGameLoader.kt @@ -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() diff --git a/commons/src/commonMain/kotlin/com/vitorpamplona/amethyst/commons/chess/ChessLobbyLogic.kt b/commons/src/commonMain/kotlin/com/vitorpamplona/amethyst/commons/chess/ChessLobbyLogic.kt index 1530bb3dca..d839285d1d 100644 --- a/commons/src/commonMain/kotlin/com/vitorpamplona/amethyst/commons/chess/ChessLobbyLogic.kt +++ b/commons/src/commonMain/kotlin/com/vitorpamplona/amethyst/commons/chess/ChessLobbyLogic.kt @@ -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 } } diff --git a/commons/src/jvmAndroid/kotlin/com/vitorpamplona/amethyst/commons/chess/ChessEventBroadcaster.kt b/commons/src/jvmAndroid/kotlin/com/vitorpamplona/amethyst/commons/chess/ChessEventBroadcaster.kt index 59c37d4df2..2a95a84452 100644 --- a/commons/src/jvmAndroid/kotlin/com/vitorpamplona/amethyst/commons/chess/ChessEventBroadcaster.kt +++ b/commons/src/jvmAndroid/kotlin/com/vitorpamplona/amethyst/commons/chess/ChessEventBroadcaster.kt @@ -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( diff --git a/quartz/src/commonMain/kotlin/com/vitorpamplona/quartz/nip64Chess/ChessStateReconstructor.kt b/quartz/src/commonMain/kotlin/com/vitorpamplona/quartz/nip64Chess/ChessStateReconstructor.kt index 4dd69fbd45..297ca80d66 100644 --- a/quartz/src/commonMain/kotlin/com/vitorpamplona/quartz/nip64Chess/ChessStateReconstructor.kt +++ b/quartz/src/commonMain/kotlin/com/vitorpamplona/quartz/nip64Chess/ChessStateReconstructor.kt @@ -22,6 +22,7 @@ package com.vitorpamplona.quartz.nip64Chess import androidx.compose.runtime.Immutable import com.vitorpamplona.quartz.nip64Chess.jester.JesterGameEvents +import com.vitorpamplona.quartz.utils.Log /** * Deterministic chess state reconstruction from Jester protocol events. @@ -59,16 +60,23 @@ object ChessStateReconstructor { events: JesterGameEvents, viewerPubkey: String, ): ReconstructionResult { + Log.d("chessdebug", "[Reconstructor] reconstruct() called: viewerPubkey=${viewerPubkey.take(8)}, startEvent=${events.startEvent?.id?.take(8)}, moveCount=${events.moves.size}") + // Step 1: Get start event (required for player info) val startEvent = events.startEvent - ?: return ReconstructionResult.Error("No start event found") + ?: run { + Log.d("chessdebug", "[Reconstructor] ERROR: No start event found") + return ReconstructionResult.Error("No start event found") + } val startEventId = startEvent.id val challengerPubkey = startEvent.pubKey val challengerColor = startEvent.playerColor() ?: Color.WHITE val challengedPubkey = startEvent.opponentPubkey() + Log.d("chessdebug", "[Reconstructor] startEventId=${startEventId.take(8)}, challenger=${challengerPubkey.take(8)}, challengerColor=$challengerColor, challengedPubkey=${challengedPubkey?.take(8)}") + // In Jester, we determine opponent from the p-tag or from move events // For open challenges, we need to find who made the first move val opponentFromMoves = @@ -77,6 +85,7 @@ object ChessStateReconstructor { ?.pubKey val actualOpponent = challengedPubkey ?: opponentFromMoves + Log.d("chessdebug", "[Reconstructor] opponentFromMoves=${opponentFromMoves?.take(8)}, actualOpponent=${actualOpponent?.take(8)}") // Determine players based on challenger's color choice val (whitePubkey, blackPubkey) = @@ -108,6 +117,8 @@ object ChessStateReconstructor { ViewerRole.SPECTATOR -> blackPubkey ?: "" // For spectators, "opponent" is black } + Log.d("chessdebug", "[Reconstructor] white=${whitePubkey?.take(8)}, black=${blackPubkey?.take(8)}, viewerRole=$viewerRole, playerColor=$playerColor") + // Check if game is pending (no moves yet AND viewer is the challenger) // If viewer accepted someone else's challenge, the game is NOT pending val isChallenger = viewerPubkey == startEvent.pubKey @@ -118,6 +129,11 @@ object ChessStateReconstructor { val latestMove = events.latestMove() val history = latestMove?.history() ?: emptyList() + Log.d("chessdebug", "[Reconstructor] latestMove=${latestMove?.id?.take(8)}, historySize=${history.size}, isPendingChallenge=$isPendingChallenge") + if (history.isNotEmpty()) { + Log.d("chessdebug", "[Reconstructor] history: ${history.joinToString(" ")}") + } + // Track applied moves val appliedMoveNumbers = mutableSetOf() var isDesynced = false @@ -131,8 +147,10 @@ object ChessStateReconstructor { } else { // Move failed - game might be desynced isDesynced = true + Log.d("chessdebug", "[Reconstructor] DESYNC: move #$moveNumber '$san' failed: ${result.error}") // Try to recover by loading the FEN from latest move if available latestMove?.fen()?.let { fen -> + Log.d("chessdebug", "[Reconstructor] Recovering with FEN: $fen") engine.loadFen(fen) } break @@ -144,6 +162,7 @@ object ChessStateReconstructor { val currentFen = engine.getFen() if (!fenPositionsMatch(currentFen, expectedFen)) { isDesynced = true + Log.d("chessdebug", "[Reconstructor] FEN MISMATCH: current=$currentFen, expected=$expectedFen") engine.loadFen(expectedFen) } } @@ -154,17 +173,20 @@ object ChessStateReconstructor { when { gameResult != null -> { val result = parseGameResult(gameResult) + Log.d("chessdebug", "[Reconstructor] Game finished from result tag: $gameResult -> $result") GameStatus.Finished(result) } engine.isCheckmate() -> { val winner = engine.getSideToMove().opposite() + Log.d("chessdebug", "[Reconstructor] Checkmate detected, winner=$winner") GameStatus.Finished( if (winner == Color.WHITE) GameResult.WHITE_WINS else GameResult.BLACK_WINS, ) } engine.isStalemate() -> { + Log.d("chessdebug", "[Reconstructor] Stalemate detected") GameStatus.Finished(GameResult.DRAW) } @@ -197,6 +219,8 @@ object ChessStateReconstructor { timeControl = null, // Not supported in Jester ) + Log.d("chessdebug", "[Reconstructor] Result: status=$gameStatus, appliedMoves=${appliedMoveNumbers.size}, isDesynced=$isDesynced, headEvent=${headEventId.take(8)}") + return ReconstructionResult.Success(state, engine) } diff --git a/quartz/src/commonMain/kotlin/com/vitorpamplona/quartz/nip64Chess/LiveChessGameState.kt b/quartz/src/commonMain/kotlin/com/vitorpamplona/quartz/nip64Chess/LiveChessGameState.kt index 7e0daed77f..7a49956ab7 100644 --- a/quartz/src/commonMain/kotlin/com/vitorpamplona/quartz/nip64Chess/LiveChessGameState.kt +++ b/quartz/src/commonMain/kotlin/com/vitorpamplona/quartz/nip64Chess/LiveChessGameState.kt @@ -20,6 +20,7 @@ */ package com.vitorpamplona.quartz.nip64Chess +import com.vitorpamplona.quartz.utils.Log import com.vitorpamplona.quartz.utils.TimeUtils import kotlinx.coroutines.flow.MutableStateFlow import kotlinx.coroutines.flow.StateFlow @@ -125,12 +126,15 @@ class LiveChessGameState( to: String, promotion: PieceType? = null, ): ChessMoveEvent? { + Log.d("chessdebug", "[LiveGame] makeMove: game=${startEventId.take(8)}, from=$from, to=$to, promotion=$promotion, isPlayerTurn=${isPlayerTurn()}, status=${_gameStatus.value}") if (!isPlayerTurn()) { + Log.d("chessdebug", "[LiveGame] makeMove REJECTED: not player's turn (sideToMove=${engine.getSideToMove()}, playerColor=$playerColor)") _lastError.value = "Not your turn" return null } if (_gameStatus.value != GameStatus.InProgress) { + Log.d("chessdebug", "[LiveGame] makeMove REJECTED: game not in progress (${_gameStatus.value})") _lastError.value = "Game is not in progress" return null } @@ -171,6 +175,7 @@ class LiveChessGameState( * @param newHeadEventId The ID of the newly published move event */ fun updateHeadEventId(newHeadEventId: String) { + Log.d("chessdebug", "[LiveGame] updateHeadEventId: game=${startEventId.take(8)}, old=${_headEventId.value.take(8)}, new=${newHeadEventId.take(8)}") _headEventId.value = newHeadEventId } @@ -204,8 +209,10 @@ class LiveChessGameState( fen: String, moveNumber: Int? = null, ): Boolean { + Log.d("chessdebug", "[LiveGame] applyOpponentMove: game=${startEventId.take(8)}, san=$san, moveNumber=$moveNumber, expectedMove=${_moveHistory.value.size + 1}") // Check for duplicate move if (moveNumber != null && receivedMoveNumbers.contains(moveNumber)) { + Log.d("chessdebug", "[LiveGame] applyOpponentMove: DUPLICATE move #$moveNumber, ignoring") // Already processed this move, ignore return true } @@ -213,12 +220,14 @@ class LiveChessGameState( // Check for out-of-order move val expectedMoveNumber = _moveHistory.value.size + 1 if (moveNumber != null && moveNumber > expectedMoveNumber) { + Log.d("chessdebug", "[LiveGame] applyOpponentMove: OUT-OF-ORDER move #$moveNumber (expected #$expectedMoveNumber), queuing") // Store for later processing pendingMoves[moveNumber] = san to fen return true } if (isPlayerTurn()) { + Log.d("chessdebug", "[LiveGame] applyOpponentMove: REJECTED - it's player's turn, not opponent's") _lastError.value = "Received move but it's not opponent's turn" return false } @@ -237,11 +246,13 @@ class LiveChessGameState( if (currentFen != fen) { // Positions don't match - desync detected _isDesynced.value = true + Log.d("chessdebug", "[LiveGame] applyOpponentMove: FEN MISMATCH after $san - current=$currentFen, expected=$fen") _lastError.value = "Position mismatch - syncing to opponent's position" // Load the opponent's FEN to stay in sync engine.loadFen(fen) } else { _isDesynced.value = false + Log.d("chessdebug", "[LiveGame] applyOpponentMove: SUCCESS - $san applied, totalMoves=${_moveHistory.value.size + 1}") } _currentPosition.value = engine.getPosition() @@ -260,6 +271,7 @@ class LiveChessGameState( return true } else { + Log.d("chessdebug", "[LiveGame] applyOpponentMove: INVALID move $san - ${result.error}") _lastError.value = "Invalid opponent move: $san" return false } @@ -512,6 +524,7 @@ class LiveChessGameState( * Used when loading a game from cache that already has an end event. */ fun markAsFinished(result: GameResult) { + Log.d("chessdebug", "[LiveGame] markAsFinished: game=${startEventId.take(8)}, result=$result") _gameStatus.value = GameStatus.Finished(result) }