updated docker-compose

docker-compose.development.yml

@@ -1,3 +0,0 @@
-services:
-  application:
-    build: .

docker-compose.yml

@@ -5,11 +5,14 @@ volumes:
 
 services:
   application:
-    build: https://git.maschek.info/patrick/stundenaufzeichnung.git#main
+    build: 
+      context: .
+      dockerfile: Dockerfile
     ports: 
-      - 3000:3000
+      - 3000:3001
     volumes:
       - type: volume
         source: user-data
         target: /app-data
+    restart: always
         

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.");
+		throw new Error("APP_USER_DATA_PATH is not defined. Exiting.");
-		process.exit(-1);
 	}
 
 	if (process.env.APP_TMP_USER_DATA_PATH == null) {
-		console.log("APP_TMP_USER_DATA_PATH is not defined. Exiting.");
+		throw new Error("APP_TMP_USER_DATA_PATH is not defined. Exiting.");
-		process.exit(-1);
 	}
 	
 	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");

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;
 }

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<string, string> = new Map(Object.entries({
 let locked_users: Set<Number> = 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);

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"
+	}
+}

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<string, LogConfig>
+
+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<LoggerMapKeys, Logger>
+
+export default Logs;

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<string, TokenInfo>();
 
 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<number>();
 	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 {

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, { });
 		}