feat: monitoring + logging with sentry and pino

This commit is contained in:
2026-03-13 22:33:54 +01:00
parent 77b2fd9e92
commit 9fa365ba9e
29 changed files with 690 additions and 117 deletions

1
src/app.d.ts vendored
View File

@@ -6,6 +6,7 @@ declare global {
interface Locals {
user?: User & { role: string };
session?: Session;
requestId?: string;
}
interface Error {

14
src/hooks.client.ts Normal file
View File

@@ -0,0 +1,14 @@
// src/hooks.client.ts
import * as Sentry from '@sentry/sveltekit';
import type { HandleClientError } from '@sveltejs/kit';
Sentry.init({
dsn: import.meta.env.PUBLIC_SENTRY_DSN,
tracesSampleRate: 0.2,
replaysSessionSampleRate: 0,
replaysOnErrorSampleRate: 0.5,
environment: import.meta.env.MODE,
sendDefaultPii: true
});
export const handleError: HandleClientError = Sentry.handleErrorWithSentry();

View File

@@ -1,6 +1,8 @@
// src/hooks.server.ts
import type { Handle, HandleServerError } from '@sveltejs/kit';
import { sequence } from '@sveltejs/kit/hooks';
import { building } from '$app/environment';
import * as Sentry from '@sentry/sveltekit';
import { auth } from '$lib/server/auth';
import { svelteKitHandler } from 'better-auth/svelte-kit';
import { db } from '$lib/server/db';
@@ -8,27 +10,64 @@ import { user as userTable } from '$lib/server/db/auth.schema';
import { eq } from 'drizzle-orm';
import { ensureRootAdminRole } from '$lib/server/permissions';
import { checkRateLimit } from '$lib/server/rate-limit';
import { log } from '$lib/server/logger';
import { metrics } from '$lib/server/metrics';
// ── Initialize the IRC DM handler once on server startup ──
// This runs when the module is first imported (server boot).
// The dynamic import prevents build-time issues if bancho.js isn't available.
if (!building) {
import('$lib/server/bancho/dm-handler')
.then(({ initDMHandler }) => initDMHandler())
.catch((err) => console.warn('[Hooks] DM handler init skipped:', err.message));
.catch((err) => log.dm.warn({ err: err.message }, 'DM handler init skipped'));
process.on('unhandledRejection', (reason) => {
console.error('[Unhandled Rejection]', reason);
log.http.error({ err: reason }, 'Unhandled rejection');
});
process.on('uncaughtException', (err) => {
console.error('[Uncaught Exception]', err);
log.http.fatal({ err }, 'Uncaught exception');
});
}
// ── Request logging middleware ──
const handleRequestLogging: Handle = async ({ event, resolve }) => {
const requestId = crypto.randomUUID();
const start = performance.now();
event.locals.requestId = requestId;
const response = await resolve(event);
const duration = Math.round(performance.now() - start);
const userId = event.locals.user?.id;
log.http.info(
{
requestId,
method: event.request.method,
path: event.url.pathname,
status: response.status,
duration,
userId: userId ?? null,
ip: event.getClientAddress()
},
`${event.request.method} ${event.url.pathname} ${response.status} ${duration}ms`
);
metrics.requestCount++;
metrics.totalResponseTime += duration;
if (duration > 1000) {
log.http.warn({ requestId, path: event.url.pathname, duration }, 'Slow request');
metrics.slowRequests++;
}
response.headers.set('X-Request-Id', requestId);
return response;
};
// ── Auth + rate limiting ──
const handleBetterAuth: Handle = async ({ event, resolve }) => {
// ── Rate limiting for API routes ──
// 200 req/min per IP — high enough for legit use, stops bots/scrapers.
// Rate limiting for API routes: 600 req/min per IP
if (event.url.pathname.startsWith('/api/')) {
const ip = event.getClientAddress();
const { ok, retryAfter } = checkRateLimit(`api:${ip}`, 600, 60_000);
@@ -45,14 +84,12 @@ const handleBetterAuth: Handle = async ({ event, resolve }) => {
if (session) {
event.locals.session = session.session;
// Load fresh role from DB (better-auth doesn't include custom columns)
const dbUser = await db.query.user.findFirst({
where: eq(userTable.id, session.user.id)
});
let role = dbUser?.role ?? 'player';
// Auto-promote root admin if env var is set and they're not admin yet
if (dbUser) {
role = await ensureRootAdminRole({
id: dbUser.id,
@@ -70,18 +107,23 @@ const handleBetterAuth: Handle = async ({ event, resolve }) => {
return svelteKitHandler({ event, resolve, auth, building });
};
export const handle: Handle = handleBetterAuth;
export const handle: Handle = sequence(
Sentry.sentryHandle(),
handleRequestLogging,
handleBetterAuth
);
// ── Global server error handler ──
// Catches unhandled errors from load functions, API routes, etc.
// Logs context for debugging; returns a safe message to the client.
export const handleError: HandleServerError = ({ error, event }) => {
export const handleError: HandleServerError = Sentry.handleErrorWithSentry(({ error, event }) => {
const err = error instanceof Error ? error : new Error(String(error));
console.error('[Server Error]', {
message: err.message,
path: event.url.pathname,
method: event.request.method,
stack: err.stack
});
log.http.error(
{
err,
requestId: event.locals.requestId,
path: event.url.pathname,
method: event.request.method
},
'Unhandled server error'
);
return { message: 'An unexpected error occurred.' };
};
});

View File

@@ -0,0 +1,8 @@
import * as Sentry from '@sentry/sveltekit';
Sentry.init({
dsn: process.env.PUBLIC_SENTRY_DSN,
tracesSampleRate: 0.2,
environment: process.env.NODE_ENV ?? 'development',
sendDefaultPii: true
});

View File

@@ -1,4 +1,5 @@
// src/lib/server/auth.ts
import { log } from '$lib/server/logger';
import { betterAuth } from 'better-auth/minimal';
import { drizzleAdapter } from 'better-auth/adapters/drizzle';
import { sveltekitCookies } from 'better-auth/svelte-kit';
@@ -54,7 +55,7 @@ export const auth = betterAuth({
initialElo: elo,
osuRankAtSeed: osuRank
});
console.log(`[Auth] Seeded ${user.name} with ${elo} ELO (rank #${osuRank ?? 'unknown'})`);
log.auth.info({ name: user.name, elo, osuRank }, 'seeded new user rating');
}
}
}
@@ -91,7 +92,7 @@ export const auth = betterAuth({
});
const data = await res.json();
if (!res.ok) {
console.error('osu! token exchange failed:', data);
log.auth.error({ data }, 'osu! token exchange failed');
throw new Error('Token exchange failed');
}
return {

View File

@@ -1,4 +1,5 @@
import { env } from '$env/dynamic/private';
import { log } from '$lib/server/logger';
function sleep(ms: number) {
return new Promise<void>((r) => setTimeout(r, ms));
@@ -40,12 +41,12 @@ export async function getClient() {
// ── Lifecycle logging ──
client.on('disconnected', () => {
console.warn('[Bancho] Disconnected from IRC');
log.bancho.warn('Disconnected from IRC');
stopKeepalive();
});
client.on('error', (err: any) => {
console.error('[Bancho] IRC error:', err?.message ?? err);
log.bancho.error({ err }, 'IRC error');
});
// ── DM listener: route private messages to dmHandler ──
@@ -62,21 +63,21 @@ export async function getClient() {
client.on('connected', async () => {
if (initialConnect) {
initialConnect = false;
console.log('[Bancho] Connected as', env.OSU_IRC_USERNAME);
log.bancho.info({ username: env.OSU_IRC_USERNAME }, 'Connected to IRC');
startKeepalive();
return;
}
reconnecting = true;
console.log('[Bancho] Reconnected — re-joining', lobbies.size, 'active lobby channels');
log.bancho.info({ lobbyCount: lobbies.size }, 'Reconnected, re-joining lobby channels');
startKeepalive();
for (const [matchId, lobby] of lobbies.entries()) {
try {
await lobby._rejoinChannel(client);
console.log(`[Bancho] Re-joined channel for match ${matchId}`);
log.bancho.info({ matchId }, 'Re-joined lobby channel');
} catch (err: any) {
console.error(`[Bancho] Failed to re-join channel for match ${matchId}:`, err.message);
log.bancho.error({ err, matchId }, 'Failed to re-join lobby channel');
lobby._dead = true;
}
}
@@ -260,13 +261,16 @@ export class TournamentLobby {
score: parseInt(scoreMatch[2].replace(/,/g, '')),
passed: scoreMatch[3] === 'PASSED'
});
console.log(`[Bancho] Score: ${scoreMatch[1].trim()} = ${scoreMatch[2]}`);
log.bancho.info(
{ username: scoreMatch[1].trim(), score: scoreMatch[2] },
'Player score received'
);
return;
}
// Game finished
if (text.includes('The match has finished!')) {
console.log('[Bancho] Game finished. Scores:', this.collectedScores);
log.bancho.info({ scores: this.collectedScores }, 'Game finished');
this.gameInProgress = false;
this.readyPlayers.clear();
if (this.matchFinishedResolve) {
@@ -282,7 +286,7 @@ export class TournamentLobby {
if (rollMatch) {
const username = rollMatch[1].trim();
const value = parseInt(rollMatch[2]);
console.log(`[Bancho] Roll: ${username} = ${value}`);
log.bancho.info({ username, value }, 'Roll result');
if (this.onRollResult) {
this.onRollResult(username, value);
}
@@ -293,7 +297,7 @@ export class TournamentLobby {
const joinMatch = text.match(/^(.+?) joined in slot \d+/);
if (joinMatch) {
const username = joinMatch[1].trim();
console.log(`[Bancho] Player joined: ${username}`);
log.bancho.info({ username }, 'Player joined');
this.inLobby.add(username);
this.readyPlayers.delete(username);
if (this.onPlayerJoined) {
@@ -306,7 +310,7 @@ export class TournamentLobby {
const leftMatch = text.match(/^(.+?) left the game\./);
if (leftMatch) {
const username = leftMatch[1].trim();
console.log(`[Bancho] Player left: ${username}`);
log.bancho.info({ username }, 'Player left');
this.inLobby.delete(username);
this.readyPlayers.delete(username);
return;
@@ -328,7 +332,7 @@ export class TournamentLobby {
// All players ready
if (text.includes('All players are ready')) {
console.log('[Bancho] All players ready');
log.bancho.info('All players ready');
for (const u of this.inLobby) this.readyPlayers.add(u);
if (this.allReadyResolve) {
this.allReadyResolve();
@@ -346,7 +350,7 @@ export class TournamentLobby {
// Room closed
if (text.includes('Closed the match')) {
console.log(`[Bancho] Room ${this.channelName} was closed`);
log.bancho.info({ channel: this.channelName }, 'Room closed');
this._dead = true;
return;
}
@@ -359,7 +363,7 @@ export class TournamentLobby {
const category = pickMatch[1].toUpperCase();
const num = pickMatch[2] ? parseInt(pickMatch[2]) : 1;
const label = `${category}${num}`;
console.log(`[Bancho] Pick command from ${sender}: ${label}`);
log.bancho.info({ sender, label }, 'Pick command received');
if (this.onPickCommand) {
this.onPickCommand(sender, label);
}
@@ -382,7 +386,7 @@ export class TournamentLobby {
this.ensureAlive();
if (reconnecting) {
console.log(`[Bancho] Waiting for reconnect before sending to ${this.channelName}...`);
log.bancho.info({ channel: this.channelName }, 'Waiting for reconnect before sending');
const start = Date.now();
while (reconnecting && Date.now() - start < 10_000) {
await sleep(500);
@@ -392,7 +396,7 @@ export class TournamentLobby {
}
}
console.log(`[Bancho] ${this.channelName} > ${cmd}`);
log.bancho.debug({ channel: this.channelName, cmd }, 'Sending IRC command');
await this.channel.sendMessage(cmd);
}
@@ -426,12 +430,12 @@ export class TournamentLobby {
async close() {
try {
if (this._dead) {
console.log(`[Bancho] Lobby ${this.channelName} already dead, skipping close`);
log.bancho.info({ channel: this.channelName }, 'Lobby already dead, skipping close');
return;
}
await this.send('!mp close');
} catch (err: any) {
console.warn(`[Bancho] Failed to close ${this.channelName}:`, err.message);
log.bancho.warn({ err, channel: this.channelName }, 'Failed to close lobby');
}
}
@@ -480,7 +484,7 @@ const lobbies = new Map<string, TournamentLobby>();
export function getLobby(matchId: string) {
const lobby = lobbies.get(matchId);
if (lobby?._dead) {
console.warn(`[Bancho] Lobby for match ${matchId} is dead, removing from registry`);
log.bancho.warn({ matchId }, 'Lobby is dead, removing from registry');
lobbies.delete(matchId);
return undefined;
}
@@ -522,12 +526,12 @@ export function getActiveLobbyCount(): number {
}
export async function closeAllLobbies() {
console.log(`[Bancho] Closing all ${lobbies.size} active lobbies...`);
log.bancho.info({ lobbyCount: lobbies.size }, 'Closing all active lobbies');
for (const [matchId, lobby] of lobbies.entries()) {
try {
await lobby.close();
} catch (err: any) {
console.warn(`[Bancho] Failed to close lobby ${matchId}:`, err.message);
log.bancho.warn({ err, matchId }, 'Failed to close lobby');
}
lobbies.delete(matchId);
}

View File

@@ -9,6 +9,7 @@
* Initialized once on server startup via hooks.server.ts.
*/
import { log } from '$lib/server/logger';
import { db } from '$lib/server/db';
import { user, playerRating, teamMember, team, matchInvite } from '$lib/server/db/schema';
import { eq, and, inArray } from 'drizzle-orm';
@@ -30,7 +31,7 @@ export async function initDMHandler() {
try {
await getClient();
} catch (err: any) {
console.error('[DM] Failed to connect IRC for DM handler:', err.message);
log.dm.error({ err }, 'failed to connect IRC for DM handler');
return;
}
@@ -77,12 +78,12 @@ export async function initDMHandler() {
);
}
} catch (err: any) {
console.error(`[DM] Error handling "${text}" from ${ircUsername}:`, err.message);
log.dm.error({ err, ircUsername, text }, 'error handling command');
await sendDM(ircUsername, `Error: ${err.message}`).catch(() => {});
}
});
console.log('[DM] DM command handler initialized');
log.dm.info('DM command handler initialized');
}
// ── Resolve IRC username → DB user ──────────────────────────────────────

View File

@@ -2,11 +2,47 @@ import * as schema from './schema';
import { building } from '$app/environment';
import { drizzle } from 'drizzle-orm/bun-sql';
import { env } from '$env/dynamic/private';
import { log } from '$lib/server/logger';
import { metrics } from '$lib/server/metrics';
const SLOW_QUERY_THRESHOLD_MS = 100;
function createDb() {
if (building) return null!;
if (!env.DATABASE_URL) throw new Error('DATABASE_URL is not set');
return drizzle(env.DATABASE_URL, { schema });
return drizzle(env.DATABASE_URL, {
schema,
logger: {
logQuery(query: string, params: unknown[]) {
log.db.debug({ query: query.slice(0, 300) }, 'Query');
}
}
});
}
export const db = createDb();
/**
* Wraps a database operation with timing. Logs slow queries (>100ms)
* and updates metrics counters.
*
* Usage:
* const users = await timedQuery('getUsers', () => db.query.user.findMany());
*/
export async function timedQuery<T>(label: string, fn: () => Promise<T>): Promise<T> {
const start = performance.now();
try {
const result = await fn();
const duration = Math.round(performance.now() - start);
metrics.totalQueries++;
metrics.totalQueryTime += duration;
if (duration > SLOW_QUERY_THRESHOLD_MS) {
log.db.warn({ label, duration }, 'Slow query');
metrics.slowQueries++;
}
return result;
} catch (err) {
log.db.error({ err, label }, 'Query failed');
throw err;
}
}

View File

@@ -1,3 +1,4 @@
import { log } from '$lib/server/logger';
import { env } from '$env/dynamic/private';
import { Client, GatewayIntentBits, EmbedBuilder, type TextChannel } from 'discord.js';
@@ -58,7 +59,7 @@ export async function notifyMatchCreated(match: {
await channel.send({ embeds: [embed] });
} catch (err: any) {
console.error('[Discord] Failed to send match created notification:', err.message);
log.discord.error({ err }, 'failed to send match created notification');
}
}
@@ -87,6 +88,6 @@ export async function notifyMatchFinished(match: {
await channel.send({ embeds: [embed] });
} catch (err: any) {
console.error('[Discord] Failed to send match finished notification:', err.message);
log.discord.error({ err }, 'failed to send match finished notification');
}
}

51
src/lib/server/logger.ts Normal file
View File

@@ -0,0 +1,51 @@
// src/lib/server/logger.ts
import pino from 'pino';
import { building } from '$app/environment';
const isProduction = !building && process.env.NODE_ENV === 'production';
const transport = building
? undefined
: isProduction
? pino.transport({
targets: [
{ target: 'pino/file', options: { destination: 1 } },
{
target: 'pino/file',
options: { destination: '/var/log/app/app.log', mkdir: true }
}
]
})
: pino.transport({
target: 'pino-pretty',
options: { colorize: true, translateTime: 'HH:MM:ss' }
});
export const logger = pino(
{
level: isProduction ? 'info' : 'debug',
base: { service: 'vash-esports' },
serializers: pino.stdSerializers,
redact: ['req.headers.authorization', 'req.headers.cookie']
},
transport
);
// Child loggers per subsystem — maps to existing [Tag] prefixes
export const log = {
auth: logger.child({ subsystem: 'auth' }),
bancho: logger.child({ subsystem: 'bancho' }),
orchestrator: logger.child({ subsystem: 'orchestrator' }),
queue: logger.child({ subsystem: 'queue' }),
discord: logger.child({ subsystem: 'discord' }),
dm: logger.child({ subsystem: 'dm' }),
r2: logger.child({ subsystem: 'r2' }),
db: logger.child({ subsystem: 'db' }),
osu: logger.child({ subsystem: 'osu' }),
match: logger.child({ subsystem: 'match' }),
invites: logger.child({ subsystem: 'invites' }),
rating: logger.child({ subsystem: 'rating' }),
admin: logger.child({ subsystem: 'admin' }),
timeout: logger.child({ subsystem: 'timeout' }),
http: logger.child({ subsystem: 'http' })
};

View File

@@ -1,3 +1,4 @@
import { log } from '$lib/server/logger';
import { dev } from '$app/environment';
import { db } from '$lib/server/db';
import { matchInvite, teamMember } from '$lib/server/db/schema';
@@ -145,10 +146,10 @@ export async function acceptInvite(inviteId: string, userId: string) {
try {
const { initMatchLobby } = await import('./orchestrator');
initMatchLobby(created.id).catch((err) => {
console.error('[Invites] IRC lobby creation failed:', err.message);
log.invites.error({ err, matchId: created.id }, 'IRC lobby creation failed');
});
} catch (err: any) {
console.error('[Invites] Failed to import orchestrator:', err.message);
log.invites.error({ err }, 'failed to import orchestrator');
}
}

View File

@@ -5,6 +5,7 @@ import { MATCH_STATES, GAME_STATES, type MatchConfig } from './types';
import { submitRoll, pickMap, submitGameScores, cancelMatch } from './engine';
import { getMatchFull } from './helpers';
import { env } from '$env/dynamic/private';
import { log } from '$lib/server/logger';
// matchId → lowercase usernames of all expected players
const expectedPlayers = new Map<string, Set<string>>();
@@ -40,7 +41,7 @@ function setMatchTimeout(matchId: string, phase: string, ms: number, fn: () => v
clearMatchTimeout(matchId, phase);
matchTimeouts.set(key, setTimeout(fn, ms));
const secs = Math.round(ms / 1000);
console.log(`[Timeout] Set ${phase} timeout for match ${matchId} (${secs}s)`);
log.timeout.info({ matchId, phase, secs }, 'Timeout armed');
}
function clearMatchTimeout(matchId: string, phase: string) {
@@ -49,7 +50,7 @@ function clearMatchTimeout(matchId: string, phase: string) {
if (t) {
clearTimeout(t);
matchTimeouts.delete(key);
console.log(`[Timeout] Cleared ${phase} timeout for match ${matchId}`);
log.timeout.info({ matchId, phase }, 'Timeout cleared');
}
}
@@ -67,7 +68,7 @@ function clearAllMatchTimeouts(matchId: string) {
* marks the match CANCELLED in the database.
*/
async function timeoutMatch(matchId: string, reason: string) {
console.warn(`[Orchestrator] Match ${matchId} timed out: ${reason}`);
log.orchestrator.warn({ matchId, reason }, 'Match timed out');
clearAllMatchTimeouts(matchId);
const lobby = getLobby(matchId);
@@ -88,7 +89,7 @@ async function timeoutMatch(matchId: string, reason: string) {
try {
await cancelMatch(matchId);
} catch (err: any) {
console.error(`[Orchestrator] Failed to cancel timed-out match ${matchId}:`, err.message);
log.orchestrator.error({ err, matchId }, 'Failed to cancel timed-out match');
}
}
@@ -136,9 +137,7 @@ export function onMatchStateChange(matchId: string, newState: string) {
for (const p of unrolled) {
const autoRoll = Math.floor(Math.random() * 100) + 1;
await submitRoll(matchId, p.id, autoRoll);
console.log(
`[Timeout] Auto-rolled ${autoRoll} for ${p.team.name} in match ${matchId}`
);
log.timeout.info({ matchId, team: p.team.name, roll: autoRoll }, 'Auto-rolled');
if (lobby?.isAlive) {
await lobby.chat(`${p.team.name} auto-rolled ${autoRoll}`);
}
@@ -180,7 +179,7 @@ export function onMatchStateChange(matchId: string, newState: string) {
}
}
} catch (err: any) {
console.error(`[Timeout] Auto-roll failed for match ${matchId}:`, err.message);
log.timeout.error({ err, matchId }, 'Auto-roll failed');
await timeoutMatch(matchId, 'Auto-roll failed — match cancelled.');
}
});
@@ -226,14 +225,14 @@ export function onMatchStateChange(matchId: string, newState: string) {
`⏰ Pick timed out — auto-picking ${slotLabel} for ${picker?.team.name}`
);
}
console.log(`[Timeout] Auto-picked ${slotLabel} for match ${matchId}`);
log.timeout.info({ matchId, slotLabel }, 'Auto-picked map');
const game = await pickMap(matchId, picker!.id, randomSlot.id);
playPickedMap(matchId, game.id).catch((err) =>
console.error('[Timeout] Auto-pick play failed:', err.message)
log.timeout.error({ err, matchId }, 'Auto-pick play failed')
);
} catch (err: any) {
console.error(`[Timeout] Auto-pick failed for match ${matchId}:`, err.message);
log.timeout.error({ err, matchId }, 'Auto-pick failed');
await timeoutMatch(matchId, 'Auto-pick failed — match cancelled.');
}
});
@@ -260,10 +259,7 @@ export async function initMatchLobby(matchId: string) {
// Check lobby limit
const activeCount = getActiveLobbyCount();
if (activeCount >= MAX_LOBBIES) {
console.error(
`[Orchestrator] Cannot create lobby: ${activeCount}/${MAX_LOBBIES} lobbies active. ` +
`Close some matches first.`
);
log.orchestrator.error({ activeCount, maxLobbies: MAX_LOBBIES }, 'Lobby limit reached');
throw new Error(
`Lobby limit reached (${activeCount}/${MAX_LOBBIES}). Close or finish existing matches first.`
);
@@ -272,10 +268,10 @@ export async function initMatchLobby(matchId: string) {
const lobby = new TournamentLobby();
const lobbyName = `VASH: (${m.participants[0]?.team.name}) vs (${m.participants[1]?.team.name})`;
console.log(`[Orchestrator] Creating lobby: ${lobbyName}`);
log.orchestrator.info({ matchId, lobbyName }, 'Creating lobby');
const { matchId: osuId, channel } = await lobby.create(lobbyName);
console.log(`[Orchestrator] Created ${channel} (osu mp/${osuId})`);
log.orchestrator.info({ matchId, channel, osuMatchId: osuId }, 'Lobby created');
setLobby(matchId, lobby);
@@ -305,7 +301,7 @@ export async function initMatchLobby(matchId: string) {
if (u?.name && !invited.has(u.name.toLowerCase())) {
await lobby.invite(u.name);
invited.add(u.name.toLowerCase());
console.log(`[Orchestrator] Invited ${u.name}`);
log.orchestrator.info({ matchId, player: u.name }, 'Invited player');
await sleep(300);
}
}
@@ -398,7 +394,7 @@ function setupChatHandlers(matchId: string, lobby: TournamentLobby) {
}
}
} catch (err: any) {
console.error('[Orchestrator] Player join handler error:', err.message);
log.orchestrator.error({ err, matchId }, 'Player join handler error');
}
};
@@ -437,7 +433,7 @@ function setupChatHandlers(matchId: string, lobby: TournamentLobby) {
const isLastRoll = m.participants.filter((p) => p.rollValue === null).length === 1;
await submitRoll(matchId, targetParticipant.id, value);
console.log(`[Orchestrator] IRC roll: ${username} = ${value}`);
log.orchestrator.info({ matchId, username, roll: value }, 'IRC roll received');
// Check if all rolled → announce pick order or tie
const updated = await getMatchFull(matchId);
@@ -478,7 +474,7 @@ function setupChatHandlers(matchId: string, lobby: TournamentLobby) {
);
}
} catch (err: any) {
console.error('[Orchestrator] IRC roll error:', err.message);
log.orchestrator.error({ err, matchId }, 'IRC roll error');
}
};
@@ -553,14 +549,14 @@ function setupChatHandlers(matchId: string, lobby: TournamentLobby) {
}
const game = await pickMap(matchId, expectedPicker!.id, slot.id);
console.log(`[Orchestrator] IRC pick: ${username} picked ${slotLabel}`);
log.orchestrator.info({ matchId, username, slotLabel }, 'IRC pick received');
// Picking timeout is cleared inside playPickedMap
playPickedMap(matchId, game.id).catch((err) =>
console.error('[Orchestrator] IRC play failed:', err.message)
log.orchestrator.error({ err, matchId }, 'IRC play failed')
);
} catch (err: any) {
console.error('[Orchestrator] IRC pick error:', err.message);
log.orchestrator.error({ err, matchId }, 'IRC pick error');
await lobby.chat(`Error: ${err.message}`).catch(() => {});
}
};
@@ -576,12 +572,12 @@ export async function playPickedMap(matchId: string, matchGameId: string) {
const lobby = getLobby(matchId);
if (!lobby) {
console.warn('[Orchestrator] No IRC lobby for', matchId, '— skipping IRC');
log.orchestrator.warn({ matchId }, 'No IRC lobby — skipping IRC');
return;
}
if (!lobby.isAlive) {
console.warn('[Orchestrator] Lobby for', matchId, 'is dead — removing');
log.orchestrator.warn({ matchId }, 'Lobby is dead — removing');
removeLobby(matchId);
return;
}
@@ -616,16 +612,16 @@ export async function playPickedMap(matchId: string, matchGameId: string) {
const currentLobby = getLobby(matchId);
if (currentLobby?.gameInProgress) {
// Game is running — scores will come in eventually
console.log(`[Timeout] Ready timeout fired but game is in progress for ${matchId}, ignoring`);
log.timeout.info({ matchId }, 'Ready timeout fired but game in progress, ignoring');
return;
}
console.log(`[Timeout] Ready timed out for match ${matchId} — force starting`);
log.timeout.info({ matchId }, 'Ready timed out — force starting');
if (currentLobby?.isAlive) {
try {
await currentLobby.chat('⏰ Ready timed out — force starting in 10s!');
await currentLobby.startGame(10);
} catch (err: any) {
console.error(`[Timeout] Force start failed for match ${matchId}:`, err.message);
log.timeout.error({ err, matchId }, 'Force start failed');
}
}
});
@@ -638,7 +634,7 @@ export async function playPickedMap(matchId: string, matchGameId: string) {
await lobby.chat('All ready — starting in 5s!');
await lobby.startGame(5);
} catch (err: any) {
console.warn('[Orchestrator] Ready timeout:', err.message);
log.orchestrator.warn({ err, matchId }, 'Ready timeout');
try {
await lobby.chat('Timed out waiting for ready. Game will force start soon!');
} catch {
@@ -646,14 +642,14 @@ export async function playPickedMap(matchId: string, matchGameId: string) {
}
// Still set up score collection — force start will trigger the game
collectScores(matchId, matchGameId, lobby).catch((err) =>
console.error('[Orchestrator] Score collection failed:', err)
log.orchestrator.error({ err, matchId }, 'Score collection failed')
);
return;
}
// Non-blocking: wait for scores then process
collectScores(matchId, matchGameId, lobby).catch((err) =>
console.error('[Orchestrator] Score collection failed:', err)
log.orchestrator.error({ err, matchId }, 'Score collection failed')
);
}
@@ -681,7 +677,10 @@ async function collectScores(matchId: string, matchGameId: string, lobby: Tourna
// Game finished → disarm the ready timeout if it's still ticking
clearMatchTimeout(matchId, 'ready');
console.log(`[Orchestrator] Scores for game ${matchGameId}:`, ircScores);
log.orchestrator.info(
{ matchId, matchGameId, scoreCount: ircScores.length },
'Scores received from IRC'
);
// Map IRC usernames → matchParticipantPlayer IDs
const m = await getMatchFull(matchId);
@@ -727,7 +726,7 @@ async function collectScores(matchId: string, matchGameId: string, lobby: Tourna
}
if (scores.length === 0) {
console.warn('[Orchestrator] No scores matched any IRC usernames');
log.orchestrator.warn({ matchId, matchGameId }, 'No scores matched any IRC usernames');
return;
}
@@ -755,20 +754,25 @@ async function collectScores(matchId: string, matchGameId: string, lobby: Tourna
osuScoreMap.set(os.user_id, os);
}
console.log(
`[Orchestrator] osu! API returned ${osuGame.scores.length} scores for beatmap ${beatmapId}. ` +
`Player map has ${playerOsuIdMap.size} entries.`
log.orchestrator.info(
{
matchGameId,
beatmapId,
apiScores: osuGame.scores.length,
mappedPlayers: playerOsuIdMap.size
},
'osu! API scores retrieved'
);
for (const s of scores) {
const playerOsuId = playerOsuIdMap.get(s.playerId);
if (playerOsuId === undefined) {
console.warn(`[Orchestrator] No osu account ID for player ${s.playerId}`);
log.orchestrator.warn({ playerId: s.playerId }, 'No osu account ID for player');
continue;
}
const osuScore = osuScoreMap.get(playerOsuId);
if (!osuScore) {
console.warn(`[Orchestrator] No osu! API score for osu user ${playerOsuId}`);
log.orchestrator.warn({ osuUserId: playerOsuId }, 'No osu! API score for user');
continue;
}
@@ -785,13 +789,13 @@ async function collectScores(matchId: string, matchGameId: string, lobby: Tourna
);
}
}
console.log(`[Orchestrator] Enriched scores from osu! API for game ${matchGameId}`);
log.orchestrator.info({ matchGameId }, 'Enriched scores from osu! API');
} else {
console.warn(`[Orchestrator] No scores in osu! API game event for beatmap ${beatmapId}`);
log.orchestrator.warn({ beatmapId }, 'No scores in osu! API game event');
}
}
} catch (err: any) {
console.warn('[Orchestrator] Failed to enrich scores from osu! API:', err.message);
log.orchestrator.warn({ err, matchId }, 'Failed to enrich scores from osu! API');
}
}
@@ -875,7 +879,7 @@ async function collectScores(matchId: string, matchGameId: string, lobby: Tourna
const game = await pickMap(matchId, picker!.id, tbSlots[0].id);
playPickedMap(matchId, game.id).catch((err) =>
console.error('[Orchestrator] TB auto-pick play failed:', err.message)
log.orchestrator.error({ err, matchId }, 'TB auto-pick play failed')
);
return;
} else if (tbSlots.length > 1) {

View File

@@ -1,3 +1,4 @@
import { log } from '$lib/server/logger';
import { db } from '$lib/server/db';
import {
match,
@@ -17,9 +18,7 @@ async function purgeExpiredQueueEntries() {
const deleted = await db.delete(matchQueue).where(lt(matchQueue.joinedAt, cutoff)).returning();
if (deleted.length > 0) {
console.log(
`[Queue] Purged ${deleted.length} expired queue entr${deleted.length === 1 ? 'y' : 'ies'}`
);
log.queue.info({ count: deleted.length }, 'purged expired queue entries');
}
}
@@ -165,10 +164,10 @@ async function tryMatchFromQueue() {
try {
const { initMatchLobby } = await import('./orchestrator');
initMatchLobby(created.id).catch((err) => {
console.error('[Queue] IRC lobby creation failed:', err.message);
log.queue.error({ err, matchId: created.id }, 'IRC lobby creation failed');
});
} catch (err: any) {
console.error('[Queue] Failed to import orchestrator:', err.message);
log.queue.error({ err }, 'failed to import orchestrator');
}
return created;

View File

@@ -1,3 +1,4 @@
import { log } from '$lib/server/logger';
import { db } from '$lib/server/db';
import { playerRating, matchParticipantPlayer } from '$lib/server/db/schema';
import { account } from '$lib/server/db/auth.schema';
@@ -32,7 +33,7 @@ export async function calculateInitialElo(
return { elo, osuRank: rank };
} catch (err) {
console.warn(`[Rating] Failed to fetch osu! rank for user ${userId}, defaulting to 1000:`, err);
log.rating.warn({ err, userId }, 'failed to fetch osu! rank, defaulting to 1000');
return { elo: 1000, osuRank: null };
}
}
@@ -55,7 +56,7 @@ export async function updateElo(participants: { id: string; teamId: string }[],
});
if (!rating) {
console.warn(`[ELO] No rating for user ${player.userId}, skipping`);
log.rating.warn({ userId: player.userId }, 'no rating found, skipping');
continue;
}

21
src/lib/server/metrics.ts Normal file
View File

@@ -0,0 +1,21 @@
// src/lib/server/metrics.ts
// In-memory counters for request and query stats.
// Resets on server restart — that's fine for a single-VM setup.
export const metrics = {
requestCount: 0,
totalResponseTime: 0,
slowRequests: 0,
slowQueries: 0,
totalQueries: 0,
totalQueryTime: 0,
startedAt: Date.now(),
get avgResponseTime() {
return this.requestCount > 0 ? Math.round(this.totalResponseTime / this.requestCount) : 0;
},
get avgQueryTime() {
return this.totalQueries > 0 ? Math.round(this.totalQueryTime / this.totalQueries) : 0;
}
};

View File

@@ -1,4 +1,5 @@
// src/lib/server/osu/api.ts
import { log } from '$lib/server/logger';
import { env } from '$env/dynamic/private';
import { db } from '$lib/server/db';
import { and, eq } from 'drizzle-orm';
@@ -113,7 +114,7 @@ export async function getBeatmap(beatmapId: string | number) {
// If fetch fails, try returning stale (expired) cached data
const stale = getStale(cacheKey);
if (stale) {
console.warn(`[osu! API] Failed to fetch beatmap ${beatmapId}, returning stale cache`);
log.osu.warn({ beatmapId }, 'fetch failed, returning stale cache');
return stale;
}
throw err; // No stale data either — propagate the error

View File

@@ -1,3 +1,4 @@
import { log } from '$lib/server/logger';
import { env } from '$env/dynamic/private';
type S3ClientType = import('bun').S3Client;
@@ -66,13 +67,13 @@ export async function proxyImage(osuUrl: string): Promise<string | null> {
if (!res.ok) throw new Error(`fetch ${osuUrl} → ${res.status}`);
const contentType = res.headers.get('content-type') ?? 'image/jpeg';
await file.write(res, { type: contentType });
console.log(`[R2] uploaded ${key}`);
log.r2.info({ key }, 'uploaded');
}
knownKeys.add(key);
return cdnUrl;
} catch (err: unknown) {
console.error('[R2] proxyImage failed for', key, '—', err instanceof Error ? err.message : err);
log.r2.error({ err, key }, 'proxyImage failed');
return null;
}
}

View File

@@ -1,4 +1,5 @@
// src/routes/(app)/admin/+page.server.ts
import { log } from '$lib/server/logger';
import { db } from '$lib/server/db';
import { user } from '$lib/server/db/auth.schema';
import {
@@ -193,7 +194,7 @@ export const actions: Actions = {
});
}
console.log(`[Admin] Reset ${u.name}: rank #${rank ?? 'unranked'} → ${elo} ELO`);
log.admin.info({ name: u.name, rank, elo }, 'reset user rating');
updated++;
}

View File

@@ -1,3 +1,4 @@
import { log } from '$lib/server/logger';
import { db } from '$lib/server/db';
import { mappool, mappoolSlot } from '$lib/server/db/schema';
import { eq, and, asc } from 'drizzle-orm';
@@ -151,7 +152,7 @@ export const actions: Actions = {
coverUrl = await proxyImage(beatmap.beatmapset.covers['card@2x']);
listCoverUrl = await proxyImage(beatmap.beatmapset.covers['list@2x']);
} catch (err: any) {
console.warn('[Mappool] Failed to proxy covers to R2:', err.message);
log.osu.warn({ err, beatmapId }, 'failed to proxy covers to R2');
}
await db.insert(mappoolSlot).values({
@@ -346,7 +347,7 @@ export const actions: Actions = {
coverUrl = await proxyImage(beatmap.beatmapset.covers['card@2x']);
listCoverUrl = await proxyImage(beatmap.beatmapset.covers['list@2x']);
} catch (err: any) {
console.warn('[Mappool] Failed to proxy covers to R2:', err.message);
log.osu.warn({ err, beatmapId }, 'failed to proxy covers to R2');
}
await db.insert(mappoolSlot).values({

View File

@@ -1,3 +1,4 @@
import { log } from '$lib/server/logger';
import { db } from '$lib/server/db';
import { match, teamMember } from '$lib/server/db/schema';
import { redirect } from '@sveltejs/kit';
@@ -93,7 +94,7 @@ export const actions: Actions = {
const mappoolId = form.get('mappool')?.toString();
const bestOf = parseInt(form.get('bestOf')?.toString() ?? '7');
console.log('[Matches] CREATE:', { name, team1Id, team2Id, mappoolId, bestOf });
log.match.info({ name, team1Id, team2Id, mappoolId, bestOf }, 'creating match');
if (!team1Id || !team2Id || !mappoolId) {
return { error: 'All fields are required' };
@@ -108,15 +109,15 @@ export const actions: Actions = {
teams: [team1Id, team2Id],
createdBy: locals.user!.id
});
console.log('[Matches] Created:', result.id);
log.match.info({ matchId: result.id }, 'match created');
} catch (e: any) {
console.error('[Matches] Error:', e);
log.match.error({ err: e }, 'failed to create match');
return { error: e.message };
}
// Create IRC lobby in background
initMatchLobby(result.id).catch((err) => {
console.error('[Matches] IRC lobby failed:', err.message);
log.match.error({ err, matchId: result.id }, 'IRC lobby failed');
});
redirect(303, `/matches/${result.id}`);
@@ -168,7 +169,7 @@ export const actions: Actions = {
});
return { inviteSuccess: true };
} catch (e: any) {
console.error('[Matches] Invite error:', e);
log.match.error({ err: e }, 'invite creation failed');
return { error: e.message };
}
}

View File

@@ -1,3 +1,4 @@
import { log } from '$lib/server/logger';
import { user } from '$lib/server/db/schema';
import { db } from '$lib/server/db';
import { mappoolSlot } from '$lib/server/db/schema';
@@ -258,7 +259,7 @@ export const actions: Actions = {
// Set map + mods in IRC lobby and start game (background)
playPickedMap(params.id, game.id).catch((err) =>
console.error('[Match] IRC play failed:', err.message)
log.match.error({ err, matchId: params.id, gameId: game.id }, 'IRC play failed')
);
return { picked: true, gameId: game.id };

View File

@@ -0,0 +1,33 @@
import { json, error } from '@sveltejs/kit';
import { dev } from '$app/environment';
import { metrics } from '$lib/server/metrics';
import type { RequestHandler } from './$types';
export const GET: RequestHandler = async ({ locals }) => {
// In production, require admin role
if (!dev) {
if (!locals.user || locals.user.role !== 'admin') {
throw error(403, 'Forbidden');
}
}
return json({
uptime: Math.round(process.uptime()),
startedAt: new Date(metrics.startedAt).toISOString(),
requests: {
total: metrics.requestCount,
avgResponseMs: metrics.avgResponseTime,
slowRequests: metrics.slowRequests
},
database: {
totalQueries: metrics.totalQueries,
slowQueries: metrics.slowQueries,
avgQueryMs: metrics.avgQueryTime
},
memory: {
heapUsedMB: Math.round(process.memoryUsage().heapUsed / 1024 / 1024),
heapTotalMB: Math.round(process.memoryUsage().heapTotal / 1024 / 1024),
rssMB: Math.round(process.memoryUsage().rss / 1024 / 1024)
}
});
};