diff --git a/cvmts/package.json b/cvmts/package.json index c559cff..f5a6b76 100644 --- a/cvmts/package.json +++ b/cvmts/package.json @@ -23,6 +23,7 @@ "msgpackr": "^1.10.2", "pino": "^9.3.1", "toml": "^3.0.0", + "uuid": "^13.0.0", "ws": "^8.17.1" }, "devDependencies": { diff --git a/cvmts/src/CollabVMServer.ts b/cvmts/src/CollabVMServer.ts index ec953e4..3378856 100644 --- a/cvmts/src/CollabVMServer.ts +++ b/cvmts/src/CollabVMServer.ts @@ -170,8 +170,9 @@ export default class CollabVMServer implements IProtocolMessageHandler { if (this.Config.geoip.enabled) { try { user.countryCode = this.geoipReader!.country(user.IP.address).country!.isoCode; + user.logger.info({event: "geoip/resolved", geoip: user.countryCode}); } catch (error) { - this.logger.warn(`Failed to get country code for ${user.IP.address}: ${(error as Error).message}`); + user.logger.warn({event: "geoip/unresolved", msg: `${(error as Error)}`}); } } @@ -179,9 +180,8 @@ export default class CollabVMServer implements IProtocolMessageHandler { try { user.processMessage(this, buf); } catch (err) { - this.logger.error({ - ip: user.IP.address, - username: user.username, + user.logger.error({ + event: "msg/general error", error_message: (err as Error).message }, 'Error in %s#processMessage.', Object.getPrototypeOf(user.protocol).constructor?.name); user.kick(); @@ -214,7 +214,7 @@ export default class CollabVMServer implements IProtocolMessageHandler { this.clients.splice(clientIndex, 1); - this.logger.info(`Disconnect From ${user.IP.address}${user.username ? ` with username ${user.username}` : ''}`); + user.logger.info({event: "user/disconnect"}); if (!user.username) return; if (this.TurnQueue.toArray().indexOf(user) !== -1) { var hadturn = this.TurnQueue.peek() === user; @@ -255,7 +255,7 @@ export default class CollabVMServer implements IProtocolMessageHandler { let res = await this.auth!.Authenticate(token, user); if (res.clientSuccess) { - this.logger.info(`${user.IP.address} logged in as ${res.username}`); + user.logger.info({ event: "user/auth/login", username: res.username }); user.sendLoginResponse(true, ''); let old = this.clients.find((c) => c.username === res.username); @@ -295,7 +295,7 @@ export default class CollabVMServer implements IProtocolMessageHandler { } } } catch (err) { - this.logger.error(`Error authenticating client ${user.IP.address}: ${(err as Error).message}`); + this.logger.error({event: "user/auth/internal error", msg: `${(err as Error).message}`}); user.sendLoginResponse(false, 'There was an internal error while authenticating. Please let a staff member know as soon as possible'); } @@ -330,12 +330,19 @@ export default class CollabVMServer implements IProtocolMessageHandler { } onTurnRequest(user: User, forfeit: boolean): void { + user.logger.trace({event: "turn/requested"}); if ((!this.turnsAllowed || this.Config.collabvm.turnwhitelist) && user.rank !== Rank.Admin && user.rank !== Rank.Moderator && !user.turnWhitelist) return; if (!this.authCheck(user, this.Config.auth.guestPermissions.turn)) return; - if (!user.TurnRateLimit.request()) return; - if (!user.connectedToNode) return; + if (!user.TurnRateLimit.request()) { + user.logger.warn({event: "turn/ratelimited"}); + return; + } + if (!user.connectedToNode) { + user.logger.warn({event: "turn/requested when not in queue"}) + return; + } if (forfeit == false) { var currentQueue = this.TurnQueue.toArray(); @@ -348,8 +355,12 @@ export default class CollabVMServer implements IProtocolMessageHandler { // Get the amount of users in the turn queue with the same IP as the user requesting a turn. let turns = currentQueue.filter((otheruser) => otheruser.IP.address == user.IP.address); // If it exceeds the limit set in the config, ignore the turn request. - if (turns.length + 1 > this.Config.collabvm.turnlimit.maximum) return; + if (turns.length + 1 > this.Config.collabvm.turnlimit.maximum) { + user.logger.warn({event: "turn/ignoring request due to turn limit"}); + return; + } } + user.logger.info({event: "turn/entering queue"}); this.TurnQueue.enqueue(user); if (this.TurnQueue.size === 1) this.nextTurn(); } else { @@ -360,10 +371,19 @@ export default class CollabVMServer implements IProtocolMessageHandler { } onVote(user: User, choice: number): void { - if (!this.VM.SnapshotsSupported()) return; + if (!this.VM.SnapshotsSupported()) { + user.logger.warn({event: "vote/voted without snapshots enabled"}); + return; + } if ((!this.turnsAllowed || this.Config.collabvm.turnwhitelist) && user.rank !== Rank.Admin && user.rank !== Rank.Moderator && !user.turnWhitelist) return; - if (!user.connectedToNode) return; - if (!user.VoteRateLimit.request()) return; + if (!user.connectedToNode) { + user.logger.warn({event: "vote/ratelimited"}); + return; + } + if (!user.VoteRateLimit.request()) { + user.logger.warn({event: "vote/voted but was ratelimited"}); + return; + } switch (choice) { case 1: if (!this.voteInProgress) { @@ -374,6 +394,7 @@ export default class CollabVMServer implements IProtocolMessageHandler { return; } + user.logger.info({event: "vote/user initiated a vote"}); this.startVote(); this.clients.forEach((c) => c.sendChatMessage('', `${user.username} has started a vote to reset the VM.`)); } @@ -383,6 +404,8 @@ export default class CollabVMServer implements IProtocolMessageHandler { if (user.IP.vote !== true) { this.clients.forEach((c) => c.sendChatMessage('', `${user.username} has voted yes.`)); } + + user.logger.info({event: "vote/yes"}); user.IP.vote = true; break; case 0: @@ -393,6 +416,8 @@ export default class CollabVMServer implements IProtocolMessageHandler { if (user.IP.vote !== false) { this.clients.forEach((c) => c.sendChatMessage('', `${user.username} has voted no.`)); } + + user.logger.info({event: "vote/no"}); user.IP.vote = false; break; default: @@ -455,16 +480,24 @@ export default class CollabVMServer implements IProtocolMessageHandler { } async onConnect(user: User, node: string) { + user.logger.info({event: "user/joined node", node}); return this.connectViewShared(user, node, undefined); } async onView(user: User, node: string, viewMode: number) { + user.logger.info({event: "user/entering view", node, viewMode}); return this.connectViewShared(user, node, viewMode); } onRename(user: User, newName: string | undefined): void { - if (!user.RenameRateLimit.request()) return; - if (user.connectedToNode && user.IP.muted) return; + if (!user.RenameRateLimit.request()) { + user.logger.warn({event: "rename/ratelimit"}); + return; + } + if (user.connectedToNode && user.IP.muted) { + user.logger.warn({event: "rename/attempted to rename while muted"}); + return; + } if (this.Config.auth.enabled && user.rank !== Rank.Unregistered) { user.sendChatMessage('', 'Go to your account settings to change your username.'); return; @@ -480,7 +513,10 @@ export default class CollabVMServer implements IProtocolMessageHandler { } onChat(user: User, message: string): void { - if (!user.username) return; + if (!user.username) { + user.logger.warn({event: "chat/dropped message without username", message}); + return; + } if (user.IP.muted) return; if (!this.authCheck(user, this.Config.auth.guestPermissions.chat)) return; @@ -489,6 +525,7 @@ export default class CollabVMServer implements IProtocolMessageHandler { if (msg.length > this.Config.collabvm.maxChatLength) msg = msg.substring(0, this.Config.collabvm.maxChatLength); if (msg.trim().length < 1) return; + user.logger.info({event: "chat/message", msg}); this.clients.forEach((c) => c.sendChatMessage(user.username!, msg)); this.ChatHistory.push({ user: user.username, msg: msg }); user.onChatMsgSent(); @@ -496,6 +533,7 @@ export default class CollabVMServer implements IProtocolMessageHandler { onKey(user: User, keysym: number, pressed: boolean): void { if (this.TurnQueue.peek() !== user && user.rank !== Rank.Admin) return; + user.logger.info({event: "key", keysym, pressed}); this.VM.GetDisplay()?.KeyboardEvent(keysym, pressed); } @@ -512,6 +550,7 @@ export default class CollabVMServer implements IProtocolMessageHandler { sha256.destroy(); if (this.Config.collabvm.turnwhitelist && pwdHash === this.Config.collabvm.turnpass) { + user.logger.info({event: "admin/granted turnpass"}) user.turnWhitelist = true; user.sendChatMessage('', 'You may now take turns.'); return; @@ -523,12 +562,15 @@ export default class CollabVMServer implements IProtocolMessageHandler { } if (pwdHash === this.Config.collabvm.adminpass) { + user.logger.info({event: "admin/granted adminpass"}) user.rank = Rank.Admin; user.sendAdminLoginResponse(true, undefined); } else if (this.Config.collabvm.moderatorEnabled && pwdHash === this.Config.collabvm.modpass) { + user.logger.info({event: "admin/granted modpass"}) user.rank = Rank.Moderator; user.sendAdminLoginResponse(true, this.ModPerms); } else { + user.logger.warn({event: "admin/failed login attempt"}) user.sendAdminLoginResponse(false, undefined); return; } @@ -750,10 +792,10 @@ export default class CollabVMServer implements IProtocolMessageHandler { client.sendSelfRename(status, client.username!, client.rank); if (hadName) { - this.logger.info(`Rename ${client.IP.address} from ${oldname} to ${client.username}`); + client.logger.info({event: "rename", from: oldname, to: client.username}); if (announce) this.clients.forEach((c) => c.sendRename(oldname, client.username!, client.rank)); } else { - this.logger.info(`Rename ${client.IP.address} to ${client.username}`); + client.logger.info({event: "rename", to: client.username}); if (announce) this.clients.forEach((c) => { c.sendAddUser([ @@ -825,8 +867,12 @@ export default class CollabVMServer implements IProtocolMessageHandler { c.sendTurnQueue(turntime, users); } }); - if (currentTurningUser) currentTurningUser.sendTurnQueue(turntime, users); + if (currentTurningUser) { + currentTurningUser.logger.info({event: "turn/held"}); + currentTurningUser.sendTurnQueue(turntime, users); + } } + private nextTurn() { clearInterval(this.TurnInterval); if (this.TurnQueue.size === 0) { @@ -838,18 +884,21 @@ export default class CollabVMServer implements IProtocolMessageHandler { } clearTurns() { + this.logger.info({event: "turn/clearing turn queue"}); clearInterval(this.TurnInterval); this.TurnQueue.clear(); this.sendTurnUpdate(); } bypassTurn(client: User) { + client.logger.info({event: "turn/bypassing"}); var a = this.TurnQueue.toArray().filter((c) => c !== client); this.TurnQueue = Queue.from([client, ...a]); this.nextTurn(); } endTurn(client: User) { + client.logger.info({event: "turn/ending"}); // I must have somehow accidentally removed this while scalpaling everything out if (this.indefiniteTurn === client) this.indefiniteTurn = null; var hasTurn = this.TurnQueue.peek() === client; @@ -956,6 +1005,7 @@ export default class CollabVMServer implements IProtocolMessageHandler { startVote() { if (this.voteInProgress) return; this.voteInProgress = true; + this.logger.info({event: "vote/start"}); this.clients.forEach((c) => c.sendVoteStarted()); this.voteTime = this.Config.collabvm.voteTime; this.voteInterval = setInterval(() => { diff --git a/cvmts/src/User.ts b/cvmts/src/User.ts index 44a3cab..f80f67b 100644 --- a/cvmts/src/User.ts +++ b/cvmts/src/User.ts @@ -5,7 +5,8 @@ import IConfig from './IConfig.js'; import RateLimiter from './RateLimiter.js'; import { NetworkClient } from './net/NetworkClient.js'; import { CollabVMCapabilities } from '@cvmts/collab-vm-1.2-binary-protocol'; -import pino from 'pino'; +import { pino, type Logger } from 'pino'; +import { v4 as uuid4 } from 'uuid'; import { BanManager } from './BanManager.js'; import { IProtocol, IProtocolMessageHandler, ListEntry, ProtocolAddUser, ProtocolChatHistory, ProtocolFlag, ProtocolRenameStatus, ProtocolUpgradeCapability, ScreenRect } from './protocol/Protocol.js'; import { TheProtocolManager } from './protocol/Manager.js'; @@ -15,7 +16,7 @@ export class User { nopSendInterval: NodeJS.Timeout; msgRecieveInterval: NodeJS.Timeout; nopRecieveTimeout?: NodeJS.Timeout; - username?: string; + private _username?: string; connectedToNode: boolean; viewMode: number; rank: Rank; @@ -34,8 +35,9 @@ export class User { RenameRateLimit: RateLimiter; TurnRateLimit: RateLimiter; VoteRateLimit: RateLimiter; + uuid: string; - private logger = pino({ name: 'CVMTS.User' }); + logger: Logger; constructor(socket: NetworkClient, protocol: string, ip: IPData, config: IConfig, username?: string, node?: string) { this.IP = ip; @@ -44,12 +46,19 @@ export class User { this.Config = config; this.socket = socket; this.msgsSent = 0; + this.uuid = uuid4(); + this.logger = pino().child({ + name: "CVMTS.User", + "uuid/user": this.uuid, + ip: ip.address, + }); this.Capabilities = new CollabVMCapabilities(); // All clients default to the Guacamole protocol. this.protocol = TheProtocolManager.getProtocol(protocol); this.socket.on('disconnect', () => { + this.logger.info({event: "user disconnected", username}); // Unref the ip data for this connection this.IP.Unref(); @@ -80,6 +89,7 @@ export class User { do { username = 'guest' + Utilities.Randint(10000, 99999); } while (existingUsers.indexOf(username) !== -1); + this.logger.info({event: "assign guest username"}); this.username = username; return username; } @@ -100,11 +110,13 @@ export class User { private onNoMsg() { this.sendNop(); this.nopRecieveTimeout = setTimeout(() => { + this.logger.info({event: "nop timeout"}); this.closeConnection(); }, 3000); } closeConnection() { + this.logger.info({event: "closing connection"}); this.socket.send(cvm.guacEncode('disconnect')); this.socket.close(); } @@ -124,6 +136,7 @@ export class User { } mute(permanent: boolean) { + this.logger.info({event: "mute", time_seconds: this.Config.collabvm.tempMuteTime, permanent}); this.IP.muted = true; this.sendMsg(cvm.guacEncode('chat', '', `You have been muted${permanent ? '' : ` for ${this.Config.collabvm.tempMuteTime} seconds`}.`)); if (!permanent) { @@ -131,13 +144,16 @@ export class User { this.IP.tempMuteExpireTimeout = setTimeout(() => this.unmute(), this.Config.collabvm.tempMuteTime * 1000); } } + unmute() { + this.logger.info({event: "unmute"}); clearTimeout(this.IP.tempMuteExpireTimeout); this.IP.muted = false; this.sendMsg(cvm.guacEncode('chat', '', 'You are no longer muted.')); } async ban(banmgr: BanManager) { + this.logger.info({event: "ban"}); // Prevent the user from taking turns or chatting, in case the ban command takes a while this.IP.muted = true; await banmgr.BanUser(this.IP.address, this.username || ''); @@ -145,6 +161,7 @@ export class User { } async kick() { + this.logger.info({event: "kick"}); this.sendMsg('10.disconnect;'); this.socket.close(); } @@ -166,6 +183,7 @@ export class User { } sendAuth(authServer: string): void { + this.logger.info({event: "sending auth", auth_server: authServer}); this.protocol.sendAuth(this, authServer); } @@ -260,6 +278,18 @@ export class User { sendScreenUpdate(rect: ScreenRect): void { this.protocol.sendScreenUpdate(this, rect); } + + get username(): string { + return this._username!; + } + + set username(updated: string) { + this.logger = this.logger.child({ + username: updated, + }); + + this._username = updated; + } } export enum Rank { diff --git a/cvmts/src/net/ws/WSClient.ts b/cvmts/src/net/ws/WSClient.ts index b79a465..64008b5 100644 --- a/cvmts/src/net/ws/WSClient.ts +++ b/cvmts/src/net/ws/WSClient.ts @@ -1,22 +1,30 @@ import { WebSocket } from 'ws'; import { NetworkClient } from '../NetworkClient.js'; import EventEmitter from 'events'; -import pino from 'pino'; +import { pino, type Logger } from 'pino'; export default class WSClient extends EventEmitter implements NetworkClient { socket: WebSocket; ip: string; + uuid: string; enforceTextOnly = true - private logger = pino({ name: "CVMTS.WebsocketClient" }); + private logger: Logger; - constructor(ws: WebSocket, ip: string) { + constructor(ws: WebSocket, ip: string, uuid: string) { super(); this.socket = ws; this.ip = ip; + this.uuid = uuid; + this.logger = pino().child({ + name: "CVMTS.WebsocketClient", + "uuid/websocket/client": uuid, + src_ip: ip, + }); this.socket.on('message', (buf: Buffer, isBinary: boolean) => { // Close the user's connection if they send a binary message // when we are not expecting them yet. if (isBinary && this.enforceTextOnly) { + this.logger.info({event: "received unexpected binary message"}); this.close(); return; } @@ -25,10 +33,11 @@ export default class WSClient extends EventEmitter implements NetworkClient { }); this.socket.on('error', (err: Error) => { - this.logger.error(err, 'WebSocket recv error'); + this.logger.error({event: "websocket recv error", msg: err}); }) this.socket.on('close', () => { + this.logger.info({event: "disconnecting client"}); this.emit('disconnect'); }); } @@ -42,12 +51,13 @@ export default class WSClient extends EventEmitter implements NetworkClient { } send(msg: string): Promise { + this.logger.trace({event: "outgoing message", msg}); return new Promise((res, rej) => { if (!this.isOpen()) return res(); this.socket.send(msg, (err) => { if (err) { - this.logger.error(err, 'WebSocket send error'); + this.logger.error({event: "websocket send error", msg: err}); this.close(); res(); return; @@ -58,12 +68,13 @@ export default class WSClient extends EventEmitter implements NetworkClient { } sendBinary(msg: Uint8Array): Promise { + this.logger.trace({event: "outgoing message", msg}); return new Promise((res, rej) => { if (!this.isOpen()) return res(); this.socket.send(msg, (err) => { if (err) { - this.logger.error(err, 'WebSocket send error'); + this.logger.error({event: "websocket send error", msg: err}); this.close(); res(); return; diff --git a/cvmts/src/net/ws/WSServer.ts b/cvmts/src/net/ws/WSServer.ts index 3fd7b67..d3f0dd5 100644 --- a/cvmts/src/net/ws/WSServer.ts +++ b/cvmts/src/net/ws/WSServer.ts @@ -8,8 +8,9 @@ import { isIP } from 'net'; import { IPDataManager } from '../../IPData.js'; import WSClient from './WSClient.js'; import { User } from '../../User.js'; -import pino from 'pino'; +import { pino, type Logger } from 'pino'; import { BanManager } from '../../BanManager.js'; +import { v4 as uuid4 } from 'uuid'; const kAllowedProtocols = [ "guacamole" // Regular ol' collabvm1 protocol @@ -20,17 +21,25 @@ export default class WSServer extends EventEmitter implements NetworkServer { private wsServer: WebSocketServer; private clients: WSClient[]; private Config: IConfig; - private logger = pino({ name: 'CVMTS.WSServer' }); + private logger: Logger; private banmgr: BanManager; + private uuid: string; constructor(config: IConfig, banmgr: BanManager) { super(); this.Config = config; this.clients = []; + this.uuid = uuid4(); + this.logger = pino().child({ + stream: 'CVMTS.WSServer', + "uuid/websocket/server": this.uuid, + node: config.collabvm.node, + }); this.httpServer = http.createServer(); this.wsServer = new WebSocketServer({ noServer: true, perMessageDeflate: false, clientTracking: false }); this.httpServer.on('upgrade', (req: http.IncomingMessage, socket: internal.Duplex, head: Buffer) => this.httpOnUpgrade(req, socket, head)); this.httpServer.on('request', (req, res) => { + this.logger.debug({ event: "request", path: req.url }); res.writeHead(426); res.write('This server only accepts WebSocket connections.'); res.end(); @@ -39,13 +48,33 @@ export default class WSServer extends EventEmitter implements NetworkServer { } start(): void { + this.logger.info({ + event: "websocket server starting", + host: this.Config.http.host, + port: this.Config.http.port, + }); this.httpServer.listen(this.Config.http.port, this.Config.http.host, () => { - this.logger.info(`WebSocket server listening on ${this.Config.http.host}:${this.Config.http.port}`); + this.logger.info({ + event: "websocket server started", + host: this.Config.http.host, + port: this.Config.http.port, + }); }); } stop(): void { - this.httpServer.close(); + this.logger.info({ + event: "websocket server stopping", + host: this.Config.http.host, + port: this.Config.http.port, + }); + this.httpServer.close(() => { + this.logger.info({ + event: "websocket server stopped", + host: this.Config.http.host, + port: this.Config.http.port, + }); + }); } private async httpOnUpgrade(req: http.IncomingMessage, socket: internal.Duplex, head: Buffer) { @@ -142,17 +171,34 @@ export default class WSServer extends EventEmitter implements NetworkServer { } private onConnection(ws: WebSocket, req: http.IncomingMessage, ip: string, protocol: string) { - let client = new WSClient(ws, ip); + const uuid = uuid4(); + const connectionId = { + "uuid/websocket/client": uuid, + src_ip: ip + }; + this.logger.info({ ...connectionId, event: "websocket client connecting" }); + + let client = new WSClient(ws, ip, uuid); this.clients.push(client); + let user = new User(client, protocol, IPDataManager.GetIPData(ip), this.Config); + this.logger.info({ + ...connectionId, + event: "websocket client connection bound to user", + "uuid/user": user.uuid + }); this.emit('connect', user); ws.on('error', (e) => { - this.logger.error(`${e} (caused by connection ${ip})`); + this.logger.error({ ...connectionId, event: "websocket connection error" }); ws.close(); }); - this.logger.info(`New WebSocket connection from ${user.IP.address}`); + ws.on('close', () => { + this.logger.error({ ...connectionId, event: "websocket connection closed" }); + }); + + this.logger.info({ ...connectionId, event: "websocket client connected" }); } } diff --git a/package.json b/package.json index 9678684..eeef6a5 100644 --- a/package.json +++ b/package.json @@ -12,6 +12,7 @@ "@types/jsbn": "^1.2.33", "@types/node": "^20.14.10", "parcel": "^2.12.0", + "pino-pretty": "^11.2.1", "prettier": "^3.3.3", "prettier-plugin-toml": "^2.0.1", "rimraf": "^6.0.1", diff --git a/yarn.lock b/yarn.lock index 5ac4e51..bd17507 100644 --- a/yarn.lock +++ b/yarn.lock @@ -92,6 +92,7 @@ __metadata: pino-pretty: "npm:^11.2.1" toml: "npm:^3.0.0" typescript: "npm:^5.4.4" + uuid: "npm:^13.0.0" ws: "npm:^8.17.1" languageName: unknown linkType: soft @@ -1778,6 +1779,7 @@ __metadata: "@types/jsbn": "npm:^1.2.33" "@types/node": "npm:^20.14.10" parcel: "npm:^2.12.0" + pino-pretty: "npm:^11.2.1" prettier: "npm:^3.3.3" prettier-plugin-toml: "npm:^2.0.1" rimraf: "npm:^6.0.1" @@ -3891,6 +3893,15 @@ __metadata: languageName: node linkType: hard +"uuid@npm:^13.0.0": + version: 13.0.0 + resolution: "uuid@npm:13.0.0" + bin: + uuid: dist-node/bin/uuid + checksum: 10c0/950e4c18d57fef6c69675344f5700a08af21e26b9eff2bf2180427564297368c538ea11ac9fb2e6528b17fc3966a9fd2c5049361b0b63c7d654f3c550c9b3d67 + languageName: node + linkType: hard + "verror@npm:1.10.0": version: 1.10.0 resolution: "verror@npm:1.10.0"