From 0f8a4ebc2c8004b0555ff2535073d3319781f2d6 Mon Sep 17 00:00:00 2001 From: Patrick Date: Fri, 11 Jul 2025 05:10:46 +0200 Subject: [PATCH] started implementation of logging --- src/hooks.server.ts | 30 ++++--- src/lib/server/auth.ts | 6 -- src/lib/server/docstore.ts | 11 ++- src/lib/server/log.config.json | 22 +++++ src/lib/server/log.ts | 137 ++++++++++++++++++++++++++++++++ src/lib/server/session_store.ts | 17 +++- src/routes/+page.server.ts | 21 ++++- 7 files changed, 218 insertions(+), 26 deletions(-) create mode 100644 src/lib/server/log.config.json create mode 100644 src/lib/server/log.ts diff --git a/src/hooks.server.ts b/src/hooks.server.ts index 7c053f4..42ab891 100644 --- a/src/hooks.server.ts +++ b/src/hooks.server.ts @@ -4,44 +4,50 @@ import { error, redirect } from "@sveltejs/kit"; import SessionStore from "$lib/server/session_store" import { init_db, close_db, get_user } from "$lib/server/database"; +import Logs from "$lib/server/log"; + async function init() { + Logs.process.info("Initializing server"); + if (process.env.APP_USER_DATA_PATH == null) { - console.log("APP_USER_DATA_PATH is not defined. Exiting."); - process.exit(-1); + throw new Error("APP_USER_DATA_PATH is not defined. Exiting."); } if (process.env.APP_TMP_USER_DATA_PATH == null) { - console.log("APP_TMP_USER_DATA_PATH is not defined. Exiting."); - process.exit(-1); + throw new Error("APP_TMP_USER_DATA_PATH is not defined. Exiting."); } await init_db(); - console.log("started"); + Logs.process.info("Initializing of server complete") } function deinit() { close_db(); - console.log('exit'); } -await init(); - process.on('exit', (_) => { deinit(); + Logs.process.info("Exiting server") process.exit(0); }); process.on('SIGINT', (_) => { - console.log("SIGINT") + Logs.process.info("Received SIGINT, shutting down") process.exit(0); }) +process.on("uncaughtExceptionMonitor", (error, origin) => { + Logs.process.fatal(`Encountered uncaught exception (origin: ${origin}): ${error.name}${error.cause ? (" caused by "+error.cause) : ""}: ${error.message} `) +}) + +await init(); + export let handle: Handle = async function ({ event, resolve }) { - console.log("incoming ", event.request.method, " request to: ", event.url.href, " (route id: ", event.route.id, ")"); + Logs.route.debug(`incoming ${event.request.method} request to: ${event.url.href} (route id: ${event.route.id})`); event.setHeaders({ //"Strict-Transport-Security": "max-age=63072000; includeSubdomains; preload", @@ -50,15 +56,15 @@ export let handle: Handle = async function ({ event, resolve }) { "Referrer-Policy": "strict-origin-when-cross-origin" }) + console.log(event.url.href) if (event.route.id == null) { + Logs.route.info(`Tried to access a route which does not exist: ${event.url.href}`) return error(404, "This page does not exist."); } const token = event.cookies.get("session_id") const user = SessionStore.get_user_by_access_token(token ?? "") - console.log("tried access with token: ", token) - if (!token || !user) { if (event.request.method == "POST" && event.route.id != "/login") { return error(401, "Invalid Session"); diff --git a/src/lib/server/auth.ts b/src/lib/server/auth.ts index 618ec35..c66da1a 100644 --- a/src/lib/server/auth.ts +++ b/src/lib/server/auth.ts @@ -7,13 +7,7 @@ export async function authorize_password(username: string, password: string): Pr const user = get_user_by_name(username); const password_hash = user?.password ?? ""; - console.log("Username: ", username); - console.log("Password: ", password); - - console.log(user); - const res = await Bun.password.verify(password, password_hash, "bcrypt"); - console.log("hash res:", res); return res ? user : null; } diff --git a/src/lib/server/docstore.ts b/src/lib/server/docstore.ts index e8c8644..4601d48 100644 --- a/src/lib/server/docstore.ts +++ b/src/lib/server/docstore.ts @@ -1,6 +1,7 @@ import b from "bun"; import fs from "node:fs/promises" +import Logs from "$lib/server/log" import { User } from "$lib/server/database"; import { MONTHS, toInt, padInt, parseDate, calculateDuration, isoToLocalDate, month_of, weekday_of } from "$lib/util" @@ -85,6 +86,8 @@ const GENDER_END: Map = new Map(Object.entries({ let locked_users: Set = new Set(); export async function getAllFiles(user: User) { + Logs.documents.debug(`Requested all files for user id ${user.id}`) + const path = `${DOCUMENTS_PATH}/user-${user.id}`; let file_names = (await fs.readdir(path, { recursive: true }).catch((_) => { @@ -165,7 +168,8 @@ async function _runProtocted(f: Function, user: User, ...args: any[]) { if (locked_users.has(user.id)) { throw new UserBusyException(`Cannot generate pdf for user: ` ,user.id); } - + + Logs.documents.debug(`Locking user ${user.id}`) locked_users.add(user.id); try { @@ -174,6 +178,7 @@ async function _runProtocted(f: Function, user: User, ...args: any[]) { throw e; } finally { locked_users.delete(user.id); + Logs.documents.debug(`Unlocking user ${user.id}`) } } @@ -186,6 +191,8 @@ async function _generateRecordPDF(user: User, year: number, month: number, overr throw new FileExistsException(`${path}/${file_pref}.pdf`); } + Logs.documents.info(`Generating Record PDF ${year}-${month} for user id ${user.id}`) + fs.mkdir(path, { recursive: true }); let gen_path = await _genLatexRec(user, file_pref, year, month); @@ -205,6 +212,8 @@ async function _generateEstimatePDF(user: User, year: number, quarter: number, o throw new FileExistsException(`${path}/${file_pref}.pdf`); } + Logs.documents.info(`Generating Estimate PDF ${year}/Quarter ${quarter} for user id ${user.id}`) + fs.mkdir(path, { recursive: true }); let gen_path = await _genLatexEst(user, file_pref, year, quarter); diff --git a/src/lib/server/log.config.json b/src/lib/server/log.config.json new file mode 100644 index 0000000..6b6f0fb --- /dev/null +++ b/src/lib/server/log.config.json @@ -0,0 +1,22 @@ +{ + "process": { + "tag": "process", + "console": "stdout" + }, + "db": { + "tag": "database", + "console": "stdout" + }, + "user": { + "tag": "user", + "console": "stdout" + }, + "documents": { + "tag": "documents" + }, + "route": { + "tag": "routing", + "severity": "debug", + "console": "stdout" + } +} diff --git a/src/lib/server/log.ts b/src/lib/server/log.ts new file mode 100644 index 0000000..12ef7e6 --- /dev/null +++ b/src/lib/server/log.ts @@ -0,0 +1,137 @@ +import Bun from "bun"; +import fs from "node:fs"; + +enum LogSeverity { + FATAL = 0, + ERROR = 1, + WARN = 2, + INFO = 3, + DEBUG = 4, +} + +const ConsoleTypeValues = ["none", "stdout", "stderr"] as const; +type ConsoleTypes = typeof ConsoleTypeValues[number] + +interface LogConfig { + tag: string + severity?: keyof typeof LogSeverity | number + logfile?: string + console?: ConsoleTypes +} + +const DEFAULT_DIRECTORY = (process.env.APP_LOG_PATH ?? "./logs") +const _startTime = new Date() + +class Logger { + + readonly tag: string + logSeverity: LogSeverity = LogSeverity.INFO; + console: ConsoleTypes + + private _file: Bun.BunFile; + private _fileWriter: Bun.FileSink; + + //constructor(tag: string, dir: string = DEFAULT_DIRECTORY, filename: string = "log-" + _startTime.toISOString(), logSeverity = LogSeverity.INFO) { + constructor(config: LogConfig) { + this.tag = config.tag + this.logSeverity = __severityFromStrNum(config.severity) + this.console = config.console ?? "none" + + fs.mkdirSync(DEFAULT_DIRECTORY, { recursive: true }); + + this._file = Bun.file(DEFAULT_DIRECTORY + "/" + (config.logfile ?? ("logs-"+__dateToISO8601Str(_startTime)+".txt"))) + this._fileWriter = this._file.writer(); + } + + async log(severity: LogSeverity, message: string) { + if (severity <= this.logSeverity) { + const line = `[${new Date().toISOString()}] [${this.tag}] ${LogSeverity[severity]}: ${message}\n` + + if (this.console !== "none") { + Bun[this.console].write(line) + } + this._fileWriter.write(line) + this._fileWriter.flush() + } + } + + async fatal(message: string) { this.log(LogSeverity.FATAL, message) } + async error(message: string) { this.log(LogSeverity.ERROR, message) } + async warn(message: string) { this.log(LogSeverity.WARN, message) } + async info(message: string) { this.log(LogSeverity.INFO, message) } + async debug(message: string) { this.log(LogSeverity.DEBUG, message) } +} + +function __severityFromStrNum(severity?: string|number): LogSeverity { + if (severity == null) { + return LogSeverity.INFO + } + + switch (typeof severity) { + case "string": { + for (const key in LogSeverity) { + if (severity.toUpperCase() == key) { + return LogSeverity[key as keyof typeof LogSeverity]; + } + } + } break; + case "number": { + for (const [key, value] of Object.entries(LogSeverity)) { + if (severity === value) { + return LogSeverity[key as keyof typeof LogSeverity]; + } + } + } break; + } + + throw new Error("Failed to configure Logger: Encountered an invalid value for severity") + return LogSeverity.INFO; +} + +function __dateToISO8601Str(date: Date) { + const pad = (n: number, width = 2) => String(n).padStart(width, '0'); + + const year = date.getFullYear(); + const month = pad(date.getMonth() + 1); + const day = pad(date.getDate()); + const hours = pad(date.getHours()); + const minutes = pad(date.getMinutes()); + const seconds = pad(date.getSeconds()); + const milliseconds = pad(date.getMilliseconds(), 3); // Ensure 3 digits + + return `${year}-${month}-${day}_${hours}-${minutes}-${seconds}.${milliseconds}`; +} + +import raw from "./log.config.json"; +const configs = raw as const; + +type ConfigMap = Record + +const __validate_config = (config: unknown): config is ConfigMap => { + if (typeof config !== "object" || config === null) throw new Error("Failed to configure Logger: Root of JSON is not an object"); + + for (const [key, value] of Object.entries(config)) { + if (typeof value !== "object") + throw new Error("Failed to configure Logger: Encountered a value which is not an object. Value of '" + key + "' is of type " + typeof value); + if (value == null) + throw new Error("Failed to configure Logger: Encountered a null value for key '" + key + "'"); + + if (typeof (value as any).tag !== "string") + throw new Error("Failed to configure Logger: value of tag for '" + key + "' is not a string"); + if (value.severity != null && !(typeof (value as any).severity === "string" || typeof (value as any).severity === "number")) + throw new Error("Failed to configure Logger: severity of key '" + key + "' is not a string or number (is " + typeof value.severity + ")"); + if (value.logfile != null && typeof (value as any).logfile !== "string") + throw new Error("Failed to configure Logger: logfile of key '" + key + "' is not a string (is " + typeof value.logfile + ")"); + if (value.console != null && (typeof (value as any).console !== "string" || !ConsoleTypeValues.includes((value as any).console))) + throw new Error("Failed to configure Logger: value for console for '" + key + "' is not any of " + ConsoleTypeValues.toString()) + } + + return true; +}; + +export type LoggerMapKeys = keyof typeof configs; +const Logs = (__validate_config(configs) ? Object.fromEntries( + Object.entries(configs).map(([key, config]) => [key, new Logger(config)]) +) : {}) as Record + +export default Logs; diff --git a/src/lib/server/session_store.ts b/src/lib/server/session_store.ts index ed6504b..2d2f4f0 100644 --- a/src/lib/server/session_store.ts +++ b/src/lib/server/session_store.ts @@ -1,7 +1,8 @@ -import type { User } from "$lib/server/database"; - import Crypto from "node:crypto"; +import type { User } from "$lib/server/database"; +import Logs from "$lib/server/log" + interface UserSession { user: User; last_active: Date; @@ -37,6 +38,8 @@ const active_session_tokens = new Map(); function issue_access_token_for_user(user: User, expiry_date: Date): string { + Logs.user.info(`Issuing access token for user id ${user.id}. Expiry date: ${expiry_date.toISOString()}`) + let user_session = active_users.get(user.id); if (user_session === undefined) { user_session = { @@ -90,7 +93,7 @@ function logout_user_session(token: string): boolean { const token_info = active_session_tokens.get(token); if (!token_info) { - console.log("this shouldn't happen."); + Logs.user.warn(`Failed to logout user by token, because token does not exist`); return false; } @@ -100,12 +103,15 @@ function logout_user_session(token: string): boolean { } async function __clean_session_store() { - console.log("cleaning sessions"); + + let cleaned_user_sessions = 0 + let cleaned_active_users = 0 const active_users_session = new Set(); active_session_tokens.forEach((token_info, token, token_map) => { if (token_info.expiry_time.getTime() < Date.now()) { token_map.delete(token); + cleaned_user_sessions += 1 } else { active_users_session.add(token_info.user_id); } @@ -114,8 +120,11 @@ async function __clean_session_store() { active_users.forEach((user_info, user_id, user_map) => { if (user_info.last_active.getTime() + 15*60*1000 < Date.now() && !active_users.has(user_id)) { user_map.delete(user_id) + cleaned_active_users += 1 } }); + + Logs.user.info(`Cleaned ${cleaned_user_sessions} inactive session tokens and ${cleaned_active_users} inactive users`) } export default class SessionStore { diff --git a/src/routes/+page.server.ts b/src/routes/+page.server.ts index c9e6a9c..8bbbfa9 100644 --- a/src/routes/+page.server.ts +++ b/src/routes/+page.server.ts @@ -6,11 +6,13 @@ import type { RecordEntry, EstimatesEntry } from "$lib/db_types"; import { fail, redirect } from '@sveltejs/kit'; +import Logs from "$lib/server/log" import { toInt, parseDate, isTimeValidHHMM } from "$lib/util" import { getRecordFiles } from "$lib/server/docstore"; export const load: PageServerLoad = async ({ locals }) => { if (!locals.user) { + Logs.route.warn("An unauthorized user tried to access the record page") return fail(403, { message: "Unauthorized user" }); } @@ -62,6 +64,7 @@ export const load: PageServerLoad = async ({ locals }) => { export const actions = { new_entry: async ({locals, request}) => { if (!locals.user) { + Logs.route.warn("An unauthorized user tried to add a new record") return fail(403, { message: "Unauthorized user" }) } @@ -113,20 +116,25 @@ export const actions = { return_obj.get("end")!.status = invalid; } - if ([...return_obj.values()].some((v) => { return v.status != ok; })) { + let invalid_values = [...return_obj.entries()].filter(([_, v]) => { return v.status != ok; }).map(([key, value]) => `${key}: ${value.status}`) + if (invalid_values.length > 0) { + Logs.user.info(`User id ${locals.user.id} failed to add a new record. Failed: ${invalid_values.join(", ")}`) return fail(400, { new_entry: return_obj }); } let res = locals.user.insert_entry(date, start, end, comment); if (!res) { + Logs.user.error(`Failed to add new entry for user id ${locals.user.id} to database.`) return fail(500, { }) } - + + Logs.user.info(`User id ${locals.user.id} created a new record`) return { success: true, new_entry: return_obj }; }, edit_entry: async ({locals, request}) => { if (!locals.user) { + Logs.route.warn("An unauthorized user tried to edit a record") return fail(403, { message: "Unauthorized user" }) } @@ -189,7 +197,9 @@ export const actions = { return_obj.get("end")!.status = invalid; } - if ([...return_obj.values()].some((v) => { return v.status != ok; })) { + let invalid_values = [...return_obj.entries()].filter(([_, v]) => { return v.status != ok; }).map(([key, value]) => `${key}: ${value.status}`) + if (invalid_values.length > 0) { + Logs.user.info(`User id ${locals.user.id} failed to edit an entry. Failed: ${invalid_values.join(", ")}`) return fail(400, { edit_entry: return_obj }); } @@ -216,6 +226,7 @@ export const actions = { } if (!res) { + Logs.user.error(`Failed to edit an entry for user id ${locals.user.id} in database.`) return fail(500, { }) } @@ -224,6 +235,7 @@ export const actions = { }, remove_entry: async ({ locals, request })=> { if (!locals.user) { + Logs.route.warn("An unauthorized user tried to delete a record") return fail(403, { message: "Unauthorized user" }) } @@ -232,11 +244,13 @@ export const actions = { let id = data.get("id") as string; if (id == null) { + Logs.user.info(`User id ${locals.user.id} failed to remove an entry. Failed: id is missing`) return fail(400, { id: id }); } let user_id = toInt(id); if (isNaN(user_id)) { + Logs.user.info(`User id ${locals.user.id} failed to remove an entry. Failed: id is not a Number`) return fail(400, { id: id }); } @@ -251,6 +265,7 @@ export const actions = { } if (!res) { + Logs.user.error(`Failed to remove an entry for user id ${locals.user.id} from database.`) return fail(500, { }); }