Merge pull request #50 from ctrlcn/feature/logs

Adds more structured logs
This commit is contained in:
Ctrl
2025-11-22 17:13:29 +00:00
committed by GitHub
7 changed files with 184 additions and 35 deletions

View File

@@ -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": {

View File

@@ -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/not connected to node"});
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(() => {

View File

@@ -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();
}
@@ -260,6 +277,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 {

View File

@@ -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<void> {
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<void> {
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;

View File

@@ -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" });
}
}

View File

@@ -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",

View File

@@ -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"