Debug log stuff

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 (
     <Box sx={{ position: "relative", width: "100%" }}>
       <Paper

server/routes/games.ts

@@ -633,7 +633,8 @@ const getSession = (game: Game, id: string): Session => {
   /* 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<void> => {
     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<void> => {
       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) {
+        if (session.ping) {
-            session.lastPong = Date.now();
+          session.lastPong = Date.now();
-            const latency = session.lastPong - session.ping;
+          const latency = session.lastPong - session.ping;
-            // Only accept latency values that are within a reasonable window
+          // Only accept latency values that are within a reasonable window
-            // (e.g. 0 - 60s). Ignore stale or absurdly large stored ping
+          // (e.g. 0 - 60s). Ignore stale or absurdly large stored ping
-            // timestamps which can occur if session state was persisted or
+          // timestamps which can occur if session state was persisted or
-            // restored with an old ping value.
+          // restored with an old ping value.
-            if (latency >= 0 && latency < 60000) {
+          if (latency >= 0 && latency < 60000) {
-              console.log(`${short}: Latency: ${latency}ms`);
+            console.log(`${short}: Latency: ${latency}ms`);
-            } else {
+          } else {
-              console.warn(`${short}: Ignoring stale ping value; computed latency ${latency}ms`);
+            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(",") : "<none>"}`
         );
@@ -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 */
     }

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<string, TransientSessionState>();
   private games = new Map<string, TransientGameState>();
 
   // 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]);
   }
 }
 

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,