remove slog, use winston instead.

This commit is contained in:
Evan
2025-04-12 17:54:36 -07:00
parent e793179fbf
commit 58b151f585
4 changed files with 62 additions and 123 deletions
+55 -36
View File
@@ -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);
}
}
+1 -1
View File
@@ -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);
-57
View File
@@ -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);
}
}
}
}
+6 -29
View File
@@ -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);
});
}