From 4218177bc7f1772af13a734b89ba7f0d2395288e Mon Sep 17 00:00:00 2001 From: James Ketrenos Date: Wed, 8 Oct 2025 17:01:50 -0700 Subject: [PATCH] Debug log stuff --- client/src/PlayerList.tsx | 25 +-------- server/routes/games.ts | 75 ++++++++++++++------------ server/routes/games/sessionState.ts | 17 +++--- server/routes/games/transientSchema.ts | 1 + 4 files changed, 51 insertions(+), 67 deletions(-) diff --git a/client/src/PlayerList.tsx b/client/src/PlayerList.tsx index 57f4c45..1ae5e90 100644 --- a/client/src/PlayerList.tsx +++ b/client/src/PlayerList.tsx @@ -36,18 +36,6 @@ const PlayerList: React.FC = () => { } }, [sendJsonMessage]); - // Debug logging - useEffect(() => { - console.log("player-list - Debug state:", { - session_id: session?.id, - session_name: session?.name, - players_count: players?.length, - players: players, - peers_keys: Object.keys(peers), - peers: peers, - }); - }, [players, peers, session]); - const sortPlayers = useCallback( (A: any, B: any) => { if (!session) { @@ -133,6 +121,7 @@ const PlayerList: React.FC = () => { break; } default: + console.log(`player-list - ignoring message: ${data.type}`); break; } }, [lastJsonMessage, session, sortPlayers, setPeers, setPlayers]); @@ -148,18 +137,6 @@ const PlayerList: React.FC = () => { }); }, [players, sendJsonMessage]); - // Debug logging - useEffect(() => { - console.log("player-list - Debug state:", { - session_id: session?.id, - session_name: session?.name, - players_count: players?.length, - players: players, - peers_keys: Object.keys(peers), - peers: peers, - }); - }, [players, peers, session]); - return ( { /* If this session is not yet in the game, add it and set the player's name */ if (!(id in game.sessions)) { game.sessions[id] = { - id: `[${id.substring(0, 8)}]`, + id: id, + short: `[${id.substring(0, 8)}]`, name: "", color: "", lastActive: Date.now(), @@ -664,12 +665,13 @@ const getSession = (game: Game, id: string): Session => { /* 60 minutes */ const age = Date.now() - (_session.lastActive || 0); if (age > 60 * 60 * 1000) { - console.log(`${_session.id}: Expiring old session ${_id}: ${age / (60 * 1000)} minutes`); + console.log(`${session.short}: Expiring old session ${_id}: ${age / (60 * 1000)} minutes`); delete game.sessions[_id]; transientState.clearSession(game.id, _id); } } + transientState.preserveSession(game.id, session.id, session); return game.sessions[id]!; }; @@ -2109,9 +2111,9 @@ const clearTimeNotice = (game: Game, session: Session): string | undefined => { const startTurnTimer = (game: Game, session: Session) => { const timeout = 90; if (!session.ws) { - console.log(`${session.id}: Aborting turn timer as ${session.name} is disconnected.`); + console.log(`${session.short}: Aborting turn timer as ${session.name} is disconnected.`); } else { - console.log(`${session.id}: (Re)setting turn timer for ${session.name} to ${timeout} seconds.`); + console.log(`${session.short}: (Re)setting turn timer for ${session.name} to ${timeout} seconds.`); } if (game.turnTimer) { clearTimeout(game.turnTimer); @@ -2121,7 +2123,7 @@ const startTurnTimer = (game: Game, session: Session) => { return; } game.turnTimer = setTimeout(() => { - console.log(`${session.id}: Turn timer expired for ${session.name}`); + console.log(`${session.short}: Turn timer expired for ${session.name}`); if (session.player) { session.player.turnNotice = "It is still your turn."; } @@ -2157,7 +2159,7 @@ const shuffle = (game: any, session: any): string | undefined => { return `Game already in progress (${game.turns} so far!) and cannot be shuffled.`; } shuffleBoard(game); - console.log(`${session.id}: Shuffled to new signature: ${game.signature}`); + console.log(`${session.short}: Shuffled to new signature: ${game.signature}`); sendUpdateToPlayers(game, { pipOrder: game.pipOrder, @@ -2656,9 +2658,9 @@ const placeSettlement = (game: Game, session: Session, index: number | string): banks.forEach((bank: any) => { const border = anyGame.borderOrder[Math.floor(bank / 3)], type = anyGame.borders?.[border]?.[bank % 3]; - console.log(`${session.id}: Bank ${bank} = ${type}`); + console.log(`${session.short}: Bank ${bank} = ${type}`); if (!type) { - console.log(`${session.id}: Bank ${bank}`); + console.log(`${session.short}: Bank ${bank}`); return; } bankType = type === "bank" ? "3 of anything for 1 resource" : `2 ${type} for 1 resource`; @@ -2700,7 +2702,7 @@ const placeSettlement = (game: Game, session: Session, index: number | string): banks2.forEach((bank: any) => { const border = anyGame.borderOrder[Math.floor(bank / 3)], type = anyGame.borders?.[border]?.[bank % 3]; - console.log(`${session.id}: Bank ${bank} = ${type}`); + console.log(`${session.short}: Bank ${bank} = ${type}`); if (!type) { return; } @@ -3342,7 +3344,7 @@ const ping = (session: Session) => { } session.ping = Date.now(); - console.log(`${session.id}: Sending ping to ${session.name}`); + console.log(`${session.short}: Sending ping to ${session.name}`); try { session.ws.send(JSON.stringify({ type: "ping", ping: session.ping })); @@ -3506,7 +3508,7 @@ const departLobby = (game: any, session: any, _color?: string): void => { } update.chat = game.chat; } else { - console.log(`${session.id}: departLobby - ${getName(session)} is ` + `being removed from ${game.id}'s sessions.`); + console.log(`${session.short}: departLobby - ${getName(session)} is ` + `being removed from ${game.id}'s sessions.`); for (let id in game.sessions) { if (game.sessions[id] === session) { delete game.sessions[id]; @@ -3603,9 +3605,9 @@ const queueSend = (session: any, message: any): void => { }; const sendGameToPlayer = (game: any, session: any): void => { - console.log(`${session.id}: -> sendGamePlayer:${getName(session)} - full game`); + console.log(`${session.short}: -> sendGamePlayer:${getName(session)} - full game`); if (!session.ws) { - console.log(`${session.id}: -> sendGamePlayer:: Currently no connection`); + console.log(`${session.short}: -> sendGamePlayer:: Currently no connection`); return; } @@ -3613,7 +3615,7 @@ const sendGameToPlayer = (game: any, session: any): void => { /* Only send empty name data to unnamed players */ if (!session.name) { - console.log(`${session.id}: -> sendGamePlayer:${getName(session)} - only sending empty name`); + console.log(`${session.short}: -> sendGamePlayer:${getName(session)} - only sending empty name`); update = { name: "" }; } else { update = getFilteredGameForPlayer(game, session); @@ -3661,7 +3663,7 @@ const sendUpdateToPlayers = async (game: any, update: any): Promise => { const session = game.sessions[key]; /* Only send player and game data to named players */ if (!session.name) { - console.log(`${session.id}: -> sendUpdateToPlayers:` + `${getName(session)} - only sending empty name`); + console.log(`${session.short}: -> sendUpdateToPlayers:` + `${getName(session)} - only sending empty name`); if (session.ws) { session.ws.send( JSON.stringify({ @@ -3673,7 +3675,7 @@ const sendUpdateToPlayers = async (game: any, update: any): Promise => { continue; } if (!session.ws) { - console.log(`${session.id}: -> sendUpdateToPlayers: ` + `Currently no connection.`); + console.log(`${session.short}: -> sendUpdateToPlayers: ` + `Currently no connection.`); } else { queueSend(session, message); } @@ -3684,7 +3686,7 @@ const sendUpdateToPlayer = async (game: any, session: any, update: any): Promise /* If this player does not have a name, *ONLY* send the name, regardless * of what is requested */ if (!session.name) { - console.log(`${session.id}: -> sendUpdateToPlayer:${getName(session)} - only sending empty name`); + console.log(`${session.short}: -> sendUpdateToPlayer:${getName(session)} - only sending empty name`); update = { name: "" }; } @@ -3700,10 +3702,10 @@ const sendUpdateToPlayer = async (game: any, session: any, update: any): Promise calculatePoints(game, update); if (debug.update) { - console.log(`${session.id}: -> sendUpdateToPlayer:${getName(session)} - `, update); + console.log(`${session.short}: -> sendUpdateToPlayer:${getName(session)} - `, update); } else { const keys = Object.getOwnPropertyNames(update); - console.log(`${session.id}: -> sendUpdateToPlayer:${getName(session)} - ${keys.join(",")}`); + console.log(`${session.short}: -> sendUpdateToPlayer:${getName(session)} - ${keys.join(",")}`); } const message = JSON.stringify({ @@ -3712,7 +3714,7 @@ const sendUpdateToPlayer = async (game: any, session: any, update: any): Promise }); if (!session.ws) { - console.log(`${session.id}: -> sendUpdateToPlayer: ` + `Currently no connection.`); + console.log(`${session.short}: -> sendUpdateToPlayer: ` + `Currently no connection.`); } else { queueSend(session, message); } @@ -4156,7 +4158,7 @@ router.ws("/ws/:id", async (ws, req) => { } } if (dead) { - console.log(`${session.id}: No more players in ${game.id}. ` + `Removing.`); + console.log(`${session.short}: No more players in ${game.id}. ` + `Removing.`); addChatMessage(game, null, `No more active players in game. ` + `It is being removed from the server.`); sendUpdateToPlayers(game, { chat: game.chat, @@ -4241,6 +4243,7 @@ router.ws("/ws/:id", async (ws, req) => { } session.live = true; session.lastActive = Date.now(); + session.short = short; let error: string | undefined; let warning: string | void | undefined; @@ -4288,19 +4291,19 @@ router.ws("/ws/:id", async (ws, req) => { } // Calculate latency if ping timestamp was sent - if (session.ping) { - session.lastPong = Date.now(); - const latency = session.lastPong - session.ping; - // Only accept latency values that are within a reasonable window - // (e.g. 0 - 60s). Ignore stale or absurdly large stored ping - // timestamps which can occur if session state was persisted or - // restored with an old ping value. - if (latency >= 0 && latency < 60000) { - console.log(`${short}: Latency: ${latency}ms`); - } else { - console.warn(`${short}: Ignoring stale ping value; computed latency ${latency}ms`); - } + if (session.ping) { + session.lastPong = Date.now(); + const latency = session.lastPong - session.ping; + // Only accept latency values that are within a reasonable window + // (e.g. 0 - 60s). Ignore stale or absurdly large stored ping + // timestamps which can occur if session state was persisted or + // restored with an old ping value. + if (latency >= 0 && latency < 60000) { + console.log(`${short}: Latency: ${latency}ms`); + } else { + console.warn(`${short}: Ignoring stale ping value; computed latency ${latency}ms`); } + } // No need to resetDisconnectCheck since it's non-functional break; @@ -4365,6 +4368,7 @@ router.ws("/ws/:id", async (ws, req) => { : data.data && Array.isArray(data.data.fields) ? (data.data.fields as string[]) : []; + console.log( `${short}: <- get:${getName(session)} ${requestedFields.length ? requestedFields.join(",") : ""}` ); @@ -4440,7 +4444,7 @@ router.ws("/ws/:id", async (ws, req) => { batchedUpdate.participants = getParticipants(game); break; case "color": - console.log(`${session.id}: -> Returning color as ${session.color} for ${getName(session)}`); + console.log(`${_session.short}: -> Returning color as ${session.color} for ${getName(session)}`); batchedUpdate.color = session.color; break; case "timestamp": @@ -4708,6 +4712,7 @@ router.ws("/ws/:id", async (ws, req) => { } session.live = true; session.lastActive = Date.now(); + session.short = short; // Ensure we only attempt to send the consolidated initial snapshot once // per session lifecycle. Tests and clients expect a single 'initial-game' // message when a socket first attaches. @@ -4873,7 +4878,7 @@ const sendInitialGameSnapshot = (game: Game, session: Session) => { const topKeys = Object.keys(snapshot || {}) .slice(0, 10) .join(","); - console.log(`${session.id}: sending initial-game snapshot keys: ${topKeys}`); + console.log(`${session.short}: sending initial-game snapshot keys: ${topKeys}`); } catch (e) { /* ignore logging errors */ } diff --git a/server/routes/games/sessionState.ts b/server/routes/games/sessionState.ts index ac66929..9919b1a 100644 --- a/server/routes/games/sessionState.ts +++ b/server/routes/games/sessionState.ts @@ -6,18 +6,19 @@ import { TRANSIENT_SESSION_KEYS, TRANSIENT_GAME_KEYS } from "./transientSchema"; +import { Game, Session } from "./types"; class TransientStateManager { private sessions = new Map(); private games = new Map(); // Session transient state - preserveSession(gameId: string, sessionId: string, session: any): void { + preserveSession(gameId: string, sessionId: string, session: Session): void { const key = `${gameId}:${sessionId}`; const transient: any = {}; // Automatically preserve all transient fields from schema - TRANSIENT_SESSION_KEYS.forEach(k => { + TRANSIENT_SESSION_KEYS.forEach((k) => { if (k in session) { transient[k] = session[k]; } @@ -26,7 +27,7 @@ class TransientStateManager { this.sessions.set(key, transient); } - restoreSession(gameId: string, sessionId: string, session: any): void { + restoreSession(gameId: string, sessionId: string, session: Session): void { const key = `${gameId}:${sessionId}`; const transient = this.sessions.get(key); if (transient) { @@ -49,11 +50,11 @@ class TransientStateManager { } // Game transient state - preserveGame(gameId: string, game: any): void { + preserveGame(gameId: string, game: Game): void { const transient: any = {}; // Automatically preserve all transient fields from schema - TRANSIENT_GAME_KEYS.forEach(k => { + TRANSIENT_GAME_KEYS.forEach((k) => { if (k in game) { transient[k] = game[k]; } @@ -62,7 +63,7 @@ class TransientStateManager { this.games.set(gameId, transient); } - restoreGame(gameId: string, game: any): void { + restoreGame(gameId: string, game: Game): void { const transient = this.games.get(gameId); if (transient) { Object.assign(game, transient); @@ -83,7 +84,7 @@ class TransientStateManager { */ stripSessionTransients(session: any): void { // Remove all transient fields automatically - TRANSIENT_SESSION_KEYS.forEach(key => delete session[key]); + TRANSIENT_SESSION_KEYS.forEach((key) => delete session[key]); // Remove player reference (runtime only) delete session.player; @@ -100,7 +101,7 @@ class TransientStateManager { * Automatically uses all keys from TRANSIENT_GAME_SCHEMA */ stripGameTransients(game: any): void { - TRANSIENT_GAME_KEYS.forEach(key => delete game[key]); + TRANSIENT_GAME_KEYS.forEach((key) => delete game[key]); } } diff --git a/server/routes/games/transientSchema.ts b/server/routes/games/transientSchema.ts index 81ba9c5..758a036 100644 --- a/server/routes/games/transientSchema.ts +++ b/server/routes/games/transientSchema.ts @@ -15,6 +15,7 @@ */ export const TRANSIENT_SESSION_SCHEMA = { ws: undefined as any, + short: undefined as string | undefined, keepAlive: undefined as NodeJS.Timeout | undefined, pingInterval: undefined as NodeJS.Timeout | undefined, lastPong: undefined as number | undefined,