diff --git a/src/server/GameServer.ts b/src/server/GameServer.ts index 9210f7660..41d74a92b 100644 --- a/src/server/GameServer.ts +++ b/src/server/GameServer.ts @@ -24,7 +24,6 @@ import { GameType } from "../core/game/Game"; import { archive } from "./Archive"; import { Client } from "./Client"; import { gatekeeper } from "./Gatekeeper"; -import { slog } from "./StructuredLog"; export enum GamePhase { Lobby = "LOBBY", Active = "ACTIVE", @@ -99,19 +98,11 @@ export class GameServer { } public addClient(client: Client, lastTurn: number) { - this.log.info(`adding client ${client.clientID}`); - slog({ - logKey: "client_joined_game", - msg: `client ${client.clientID} (re)joining game ${this.id}`, - data: { - clientID: client.clientID, - clientIP: client.ip, - gameID: this.id, - isRejoin: lastTurn > 0, - }, + this.log.info("client (re)joining game", { clientID: client.clientID, persistentID: client.persistentID, - gameID: this.id, + clientIP: client.ip, + isRejoin: lastTurn > 0, }); if ( @@ -120,9 +111,10 @@ export class GameServer { (c) => c.ip == client.ip && c.clientID != client.clientID, ).length >= 3 ) { - this.log.info( - `cannot add client ${client.clientID}, already have 3 ips (${client.ip})`, - ); + this.log.warn("cannot add client, already have 3 ips", { + clientID: client.clientID, + clientIP: client.ip, + }); return; } @@ -156,6 +148,10 @@ export class GameServer { if (client.persistentID != clientMsg.persistentID) { this.log.warn( `Client ID ${clientMsg.clientID} sent incorrect id ${clientMsg.persistentID}, does not match persistent id ${client.persistentID}`, + { + clientID: clientMsg.clientID, + persistentID: clientMsg.persistentID, + }, ); return; } @@ -168,9 +164,10 @@ export class GameServer { if (clientMsg.gameID == this.id) { this.addIntent(clientMsg.intent); } else { - this.log.warn( - `${this.id}: client ${clientMsg.clientID} sent to wrong game`, - ); + this.log.warn("client sent to wrong game", { + clientID: clientMsg.clientID, + persistentID: clientMsg.persistentID, + }); } } if (clientMsg.type == "ping") { @@ -187,12 +184,18 @@ export class GameServer { } catch (error) { this.log.info( `error handline websocket request in game server: ${error}`, + { + clientID: client.clientID, + }, ); } }), ); client.ws.on("close", () => { - this.log.info(`${this.id}: client ${client.clientID} disconnected`); + this.log.info("client disconnected", { + clientID: client.clientID, + persistentID: client.persistentID, + }); this.activeClients = this.activeClients.filter( (c) => c.clientID != client.clientID, ); @@ -245,7 +248,10 @@ export class GameServer { const msg = JSON.stringify(prestartMsg.data); this.activeClients.forEach((c) => { - this.log.info(`${this.id}: sending prestart message to ${c.clientID}`); + this.log.info("sending prestart message", { + clientID: c.clientID, + persistentID: c.persistentID, + }); c.ws.send(msg); }); } @@ -276,7 +282,10 @@ export class GameServer { this.config.turnIntervalMs(), ); this.activeClients.forEach((c) => { - this.log.info(`${this.id}: sending start message to ${c.clientID}`); + this.log.info("sending start message", { + clientID: c.clientID, + persistentID: c.persistentID, + }); this.sendStartGameMsg(c.ws, 0); }); } @@ -327,10 +336,8 @@ export class GameServer { ); } catch (error) { this.log.info( - `error sending message for game ${this.id}, error ${error}`.substring( - 0, - 250, - ), + `error sending message for game: ${error.substring(0, 250)}`, + {}, ); return; } @@ -349,9 +356,7 @@ export class GameServer { client.ws.close(1000, "game has ended"); } }); - this.log.info( - `${this.id}: ending game ${this.id} with ${this.turns.length} turns`, - ); + this.log.info("ending game", { gameID: this.id, turns: this.turns.length }); try { if (this.allClients.size > 0) { const playerRecords: PlayerRecord[] = Array.from( @@ -376,7 +381,9 @@ export class GameServer { ), ); } else { - this.log.info(`${this.id}: no clients joined, not archiving game`); + this.log.info("no clients joined, not archiving game", { + gameID: this.id, + }); } } catch (error) { let errorDetails; @@ -408,9 +415,10 @@ export class GameServer { const alive = []; for (const client of this.activeClients) { if (now - client.lastPing > 60_000) { - this.log.info( - `${this.id}: no pings from ${client.clientID}, terminating connection`, - ); + this.log.info("no pings received, terminating connection", { + clientID: client.clientID, + persistentID: client.persistentID, + }); if (client.ws.readyState === WebSocket.OPEN) { client.ws.close(1000, "no heartbeats received, closing connection"); } @@ -420,7 +428,9 @@ export class GameServer { } this.activeClients = alive; if (now > this.createdAt + this.maxGameDuration) { - this.log.warn(`${this.id}: game past max duration ${this.id}`); + this.log.warn("game past max duration", { + gameID: this.id, + }); return GamePhase.Finished; } @@ -430,7 +440,9 @@ export class GameServer { if (this.gameConfig.gameType != GameType.Public) { if (this._hasStarted) { if (noActive && noRecentPings) { - this.log.info(`${this.id}: private game: ${this.id} complete`); + this.log.info("private game complete", { + gameID: this.id, + }); return GamePhase.Finished; } else { return GamePhase.Active; @@ -508,7 +520,10 @@ export class GameServer { totalActiveClients: this.activeClients.length, }); if (!serverDesync.success) { - this.log.warn(`failed to create desync message ${serverDesync.error}`); + this.log.warn("failed to create desync message", { + gameID: this.id, + error: serverDesync.error, + }); return; } @@ -518,7 +533,11 @@ export class GameServer { continue; } this.sentDesyncMessageClients.add(c.clientID); - this.log.info(`game: ${this.id}: sending desync to client ${c.clientID}`); + this.log.info("sending desync to client", { + gameID: this.id, + clientID: c.clientID, + persistentID: c.persistentID, + }); c.ws.send(desyncMsg); } } diff --git a/src/server/Master.ts b/src/server/Master.ts index 5062e4220..24a198cdd 100644 --- a/src/server/Master.ts +++ b/src/server/Master.ts @@ -24,7 +24,7 @@ const server = http.createServer(app); const metricsApp = express(); const metricsServer = http.createServer(metricsApp); -const log = logger.child({ component: "Master" }); +const log = logger.child({ comp: "m" }); const __filename = fileURLToPath(import.meta.url); const __dirname = path.dirname(__filename); diff --git a/src/server/StructuredLog.ts b/src/server/StructuredLog.ts deleted file mode 100644 index f15bfda94..000000000 --- a/src/server/StructuredLog.ts +++ /dev/null @@ -1,57 +0,0 @@ -import { ClientID, GameID, LogSeverity } from "../core/Schemas"; - -export interface slogMsg { - logKey: string; - msg: string; - data?: { - stack?: unknown; - clientID?: unknown; - clientIP?: unknown; - gameID?: unknown; - isRejoin?: unknown; - }; - severity?: LogSeverity; - gameID?: GameID; - clientID?: ClientID; - persistentID?: string; - stack?: string; // Added stack property -} - -export function slog(msg: slogMsg): void { - msg.severity = msg.severity ?? LogSeverity.Info; - - // Format stack trace if available - if (msg.stack) { - // Keep the stack trace in the log data - if (!msg.data) { - msg.data = { stack: msg.stack }; - } else if (typeof msg.data === "object") { - msg.data.stack = msg.stack; - } - } - - if (process.env.GAME_ENV == "dev") { - // Avoid blowing up the log during development. - if (msg.logKey == "client_console_log") { - return; - } - if (msg.severity != LogSeverity.Debug) { - console.log(msg.msg); - // Print stack trace in development for errors - if (msg.severity === LogSeverity.Error && msg.stack) { - console.error(msg.stack); - } - } - } else { - try { - console.log(JSON.stringify(msg)); - } catch (error) { - console.error("Failed to stringify log message:", error); - // Fallback to basic logging - console.log(`${msg.severity}: ${msg.msg}`); - if (msg.severity === LogSeverity.Error && msg.stack) { - console.error(msg.stack); - } - } - } -} diff --git a/src/server/Worker.ts b/src/server/Worker.ts index 5527cf52a..8a6d0ddd4 100644 --- a/src/server/Worker.ts +++ b/src/server/Worker.ts @@ -7,19 +7,18 @@ import { WebSocket, WebSocketServer } from "ws"; import { GameEnv } from "../core/configuration/Config"; import { getServerConfigFromServer } from "../core/configuration/ConfigLoader"; import { GameType } from "../core/game/Game"; -import { GameConfig, GameRecord, LogSeverity } from "../core/Schemas"; +import { GameConfig, GameRecord } from "../core/Schemas"; import { archive, readGameRecord } from "./Archive"; import { Client } from "./Client"; import { GameManager } from "./GameManager"; import { gatekeeper, LimiterType } from "./Gatekeeper"; import { logger } from "./Logger"; -import { slog } from "./StructuredLog"; import { metrics } from "./WorkerMetrics"; const config = getServerConfigFromServer(); const workerId = parseInt(process.env.WORKER_ID || "0"); -const log = logger.child({ component: `worker_${workerId}` }); +const log = logger.child({ comp: `w_${workerId}` }); // Worker setup export function startWorker() { @@ -340,7 +339,7 @@ export function startWorker() { // The load balancer will handle routing to this server based on path const PORT = config.workerPortByIndex(workerId); server.listen(PORT, () => { - log.info(`Worker ${workerId} running on http://localhost:${PORT}`); + log.info(`running on http://localhost:${PORT}`); log.info(`Handling requests with path prefix /w${workerId}/`); // Signal to the master process that this worker is ready if (process.send) { @@ -348,44 +347,22 @@ export function startWorker() { type: "WORKER_READY", workerId: workerId, }); - log.info(`Worker ${workerId} signaled ready state to master`); + log.info(`signaled ready state to master`); } }); // Global error handler app.use((err: Error, req: Request, res: Response, next: NextFunction) => { log.error(`Error in ${req.method} ${req.path}:`, err); - slog({ - logKey: "server_error", - msg: `Unhandled exception in ${req.method} ${req.path}: ${err.message}`, - severity: LogSeverity.Error, - stack: err.stack, - }); res.status(500).json({ error: "An unexpected error occurred" }); }); // Process-level error handlers process.on("uncaughtException", (err) => { - log.error(`Worker ${workerId} uncaught exception:`, err); - slog({ - logKey: "uncaught_exception", - msg: `Worker ${workerId} uncaught exception: ${err.message}`, - severity: LogSeverity.Error, - stack: err.stack, - }); + log.error(`uncaught exception:`, err); }); process.on("unhandledRejection", (reason, promise) => { - log.error( - `Worker ${workerId} unhandled rejection at:`, - promise, - "reason:", - reason, - ); - slog({ - logKey: "unhandled_rejection", - msg: `Worker ${workerId} unhandled promise rejection: ${reason}`, - severity: LogSeverity.Error, - }); + log.error(`unhandled rejection at:`, promise, "reason:", reason); }); }