Use pino for logs (#1086)

* Use pino for logs

* Use logger for info

* Add errorId to the logs

Author: nsarrazin

package-lock.json

@@ -69,6 +69,8 @@
 		"nanoid": "^4.0.2",
 		"openid-client": "^5.4.2",
 		"parquetjs": "^0.11.2",
+		"pino": "^9.0.0",
+		"pino-pretty": "^11.0.0",
 		"postcss": "^8.4.31",
 		"saslprep": "^1.0.3",
 		"satori": "^0.10.11",

package.json

@@ -12,6 +12,11 @@ declare global {
 			sessionId: string;
 			user?: User;
 		}
+
+		interface Error {
+			message: string;
+			errorId?: ReturnType<typeof crypto.randomUUID>;
+		}
 		// interface PageData {}
 		// interface Platform {}
 	}

src/app.d.ts

@@ -6,7 +6,7 @@ import {
 	MESSAGES_BEFORE_LOGIN,
 	PARQUET_EXPORT_SECRET,
 } from "$env/static/private";
-import type { Handle } from "@sveltejs/kit";
+import type { Handle, HandleServerError } from "@sveltejs/kit";
 import {
 	PUBLIC_GOOGLE_ANALYTICS_ID,
 	PUBLIC_ORIGIN,
@@ -21,6 +21,7 @@ import { addWeeks } from "date-fns";
 import { checkAndRunMigrations } from "$lib/migrations/migrations";
 import { building } from "$app/environment";
 import { refreshAssistantsCounts } from "$lib/assistantStats/refresh-assistants-counts";
+import { logger } from "$lib/server/logger";
 
 if (!building) {
 	await checkAndRunMigrations();
@@ -29,6 +30,31 @@ if (!building) {
 	}
 }
 
+export const handleError: HandleServerError = async ({ error, event }) => {
+	// handle 404
+	if (event.route.id === null) {
+		return {
+			message: `Page ${event.url.pathname} not found`,
+		};
+	}
+
+	const errorId = crypto.randomUUID();
+
+	logger.error({
+		locals: event.locals,
+		url: event.request.url,
+		params: event.params,
+		request: event.request,
+		error,
+		errorId,
+	});
+
+	return {
+		message: "An error occurred",
+		errorId,
+	};
+};
+
 export const handle: Handle = async ({ event, resolve }) => {
 	if (event.url.pathname.startsWith(`${base}/api/`) && EXPOSE_API !== "true") {
 		return new Response("API is disabled", { status: 403 });

src/hooks.server.ts

@@ -2,6 +2,7 @@ import { client, collections } from "$lib/server/database";
 import { acquireLock, refreshLock } from "$lib/migrations/lock";
 import type { ObjectId } from "mongodb";
 import { subDays } from "date-fns";
+import { logger } from "$lib/server/logger";
 
 const LOCK_KEY = "assistants.count";
 
@@ -53,8 +54,8 @@ async function refreshAssistantsCountsHelper() {
 			})
 		);
 	} catch (e) {
-		console.log("Refresh assistants counter failed!");
-		console.error(e);
+		logger.error("Refresh assistants counter failed!");
+		logger.error(e);
 	}
 }
 

src/lib/assistantStats/refresh-assistants-counts.ts

@@ -2,6 +2,7 @@ import { client, collections } from "$lib/server/database";
 import { migrations } from "./routines";
 import { acquireLock, releaseLock, isDBLocked, refreshLock } from "./lock";
 import { isHuggingChat } from "$lib/utils/isHuggingChat";
+import { logger } from "$lib/server/logger";
 
 const LOCK_KEY = "migrations";
 
@@ -14,7 +15,7 @@ export async function checkAndRunMigrations() {
 	// check if all migrations have already been run
 	const migrationResults = await collections.migrationResults.find().toArray();
 
-	console.log("[MIGRATIONS] Begin check...");
+	logger.info("[MIGRATIONS] Begin check...");
 
 	// connect to the database
 	const connectedClient = await client.connect();
@@ -23,7 +24,7 @@ export async function checkAndRunMigrations() {
 
 	if (!lockId) {
 		// another instance already has the lock, so we exit early
-		console.log(
+		logger.info(
 			"[MIGRATIONS] Another instance already has the lock. Waiting for DB to be unlocked."
 		);
 
@@ -50,21 +51,21 @@ export async function checkAndRunMigrations() {
 
 		// check if the migration has already been applied
 		if (!shouldRun) {
-			console.log(`[MIGRATIONS] "${migration.name}" already applied. Skipping...`);
+			logger.info(`[MIGRATIONS] "${migration.name}" already applied. Skipping...`);
 		} else {
 			// check the modifiers to see if some cases match
 			if (
 				(migration.runForHuggingChat === "only" && !isHuggingChat) ||
 				(migration.runForHuggingChat === "never" && isHuggingChat)
 			) {
-				console.log(
+				logger.info(
 					`[MIGRATIONS] "${migration.name}" should not be applied for this run. Skipping...`
 				);
 				continue;
 			}
 
 			// otherwise all is good and we can run the migration
-			console.log(
+			logger.info(
 				`[MIGRATIONS] "${migration.name}" ${
 					migration.runEveryTime ? "should run every time" : "not applied yet"
 				}. Applying...`
@@ -89,8 +90,8 @@ export async function checkAndRunMigrations() {
 					result = await migration.up(connectedClient);
 				});
 			} catch (e) {
-				console.log(`[MIGRATION[]  "${migration.name}" failed!`);
-				console.error(e);
+				logger.info(`[MIGRATIONS]  "${migration.name}" failed!`);
+				logger.error(e);
 			} finally {
 				await session.endSession();
 			}
@@ -108,7 +109,7 @@ export async function checkAndRunMigrations() {
 		}
 	}
 
-	console.log("[MIGRATIONS] All migrations applied. Releasing lock");
+	logger.info("[MIGRATIONS] All migrations applied. Releasing lock");
 
 	clearInterval(refreshInterval);
 	await releaseLock(LOCK_KEY, lockId);

src/lib/migrations/migrations.ts

@@ -2,6 +2,7 @@
 
 import { setTimeout } from "node:timers/promises";
 import { collections } from "./database";
+import { logger } from "$lib/server/logger";
 
 let closed = false;
 process.on("SIGINT", () => {
@@ -21,7 +22,7 @@ async function maintainAbortedGenerations() {
 				aborts.map(({ conversationId, createdAt }) => [conversationId.toString(), createdAt])
 			);
 		} catch (err) {
-			console.error(err);
+			logger.error(err);
 		}
 	}
 }

src/lib/server/abortedGenerations.ts

@@ -18,6 +18,7 @@ import { dev } from "$app/environment";
 import type { Cookies } from "@sveltejs/kit";
 import { collections } from "./database";
 import JSON5 from "json5";
+import { logger } from "$lib/server/logger";
 
 export interface OIDCSettings {
 	redirectURI: string;
@@ -151,7 +152,7 @@ export async function validateAndParseCsrfToken(
 			return { redirectUrl: data.redirectUrl };
 		}
 	} catch (e) {
-		console.error(e);
+		logger.error(e);
 	}
 	return null;
 }

src/lib/server/auth.ts

@@ -13,6 +13,7 @@ import type { ConversationStats } from "$lib/types/ConversationStats";
 import type { MigrationResult } from "$lib/types/MigrationResult";
 import type { Semaphore } from "$lib/types/Semaphore";
 import type { AssistantStats } from "$lib/types/AssistantStats";
+import { logger } from "$lib/server/logger";
 
 if (!MONGODB_URL) {
 	throw new Error(
@@ -25,7 +26,7 @@ const client = new MongoClient(MONGODB_URL, {
 	directConnection: MONGODB_DIRECT_CONNECTION === "true",
 });
 
-export const connectPromise = client.connect().catch(console.error);
+export const connectPromise = client.connect().catch(logger.error);
 
 export function getCollections(mongoClient: MongoClient) {
 	const db = mongoClient.db(MONGODB_DB_NAME + (import.meta.env.MODE === "test" ? "-test" : ""));
@@ -89,25 +90,25 @@ client.on("open", () => {
 			{ sessionId: 1, updatedAt: -1 },
 			{ partialFilterExpression: { sessionId: { $exists: true } } }
 		)
-		.catch(console.error);
+		.catch(logger.error);
 	conversations
 		.createIndex(
 			{ userId: 1, updatedAt: -1 },
 			{ partialFilterExpression: { userId: { $exists: true } } }
 		)
-		.catch(console.error);
+		.catch(logger.error);
 	conversations
 		.createIndex(
 			{ "message.id": 1, "message.ancestors": 1 },
 			{ partialFilterExpression: { userId: { $exists: true } } }
 		)
-		.catch(console.error);
+		.catch(logger.error);
 	// To do stats on conversations
-	conversations.createIndex({ updatedAt: 1 }).catch(console.error);
+	conversations.createIndex({ updatedAt: 1 }).catch(logger.error);
 	// Not strictly necessary, could use _id, but more convenient. Also for stats
-	conversations.createIndex({ createdAt: 1 }).catch(console.error);
+	conversations.createIndex({ createdAt: 1 }).catch(logger.error);
 	// To do stats on conversation messages
-	conversations.createIndex({ "messages.createdAt": 1 }, { sparse: true }).catch(console.error);
+	conversations.createIndex({ "messages.createdAt": 1 }, { sparse: true }).catch(logger.error);
 	// Unique index for stats
 	conversationStats
 		.createIndex(
@@ -120,42 +121,42 @@ client.on("open", () => {
 			},
 			{ unique: true }
 		)
-		.catch(console.error);
+		.catch(logger.error);
 	// Allow easy check of last computed stat for given type/dateField
 	conversationStats
 		.createIndex({
 			type: 1,
 			"date.field": 1,
 			"date.at": 1,
 		})
-		.catch(console.error);
-	abortedGenerations.createIndex({ updatedAt: 1 }, { expireAfterSeconds: 30 }).catch(console.error);
-	abortedGenerations.createIndex({ conversationId: 1 }, { unique: true }).catch(console.error);
-	sharedConversations.createIndex({ hash: 1 }, { unique: true }).catch(console.error);
-	settings.createIndex({ sessionId: 1 }, { unique: true, sparse: true }).catch(console.error);
-	settings.createIndex({ userId: 1 }, { unique: true, sparse: true }).catch(console.error);
-	settings.createIndex({ assistants: 1 }).catch(console.error);
-	users.createIndex({ hfUserId: 1 }, { unique: true }).catch(console.error);
-	users.createIndex({ sessionId: 1 }, { unique: true, sparse: true }).catch(console.error);
+		.catch(logger.error);
+	abortedGenerations.createIndex({ updatedAt: 1 }, { expireAfterSeconds: 30 }).catch(logger.error);
+	abortedGenerations.createIndex({ conversationId: 1 }, { unique: true }).catch(logger.error);
+	sharedConversations.createIndex({ hash: 1 }, { unique: true }).catch(logger.error);
+	settings.createIndex({ sessionId: 1 }, { unique: true, sparse: true }).catch(logger.error);
+	settings.createIndex({ userId: 1 }, { unique: true, sparse: true }).catch(logger.error);
+	settings.createIndex({ assistants: 1 }).catch(logger.error);
+	users.createIndex({ hfUserId: 1 }, { unique: true }).catch(logger.error);
+	users.createIndex({ sessionId: 1 }, { unique: true, sparse: true }).catch(logger.error);
 	// No unicity because due to renames & outdated info from oauth provider, there may be the same username on different users
-	users.createIndex({ username: 1 }).catch(console.error);
-	messageEvents.createIndex({ createdAt: 1 }, { expireAfterSeconds: 60 }).catch(console.error);
-	sessions.createIndex({ expiresAt: 1 }, { expireAfterSeconds: 0 }).catch(console.error);
-	sessions.createIndex({ sessionId: 1 }, { unique: true }).catch(console.error);
-	assistants.createIndex({ createdById: 1, userCount: -1 }).catch(console.error);
-	assistants.createIndex({ userCount: 1 }).catch(console.error);
-	assistants.createIndex({ featured: 1, userCount: -1 }).catch(console.error);
-	assistants.createIndex({ modelId: 1, userCount: -1 }).catch(console.error);
-	assistants.createIndex({ searchTokens: 1 }).catch(console.error);
-	assistants.createIndex({ last24HoursCount: 1 }).catch(console.error);
+	users.createIndex({ username: 1 }).catch(logger.error);
+	messageEvents.createIndex({ createdAt: 1 }, { expireAfterSeconds: 60 }).catch(logger.error);
+	sessions.createIndex({ expiresAt: 1 }, { expireAfterSeconds: 0 }).catch(logger.error);
+	sessions.createIndex({ sessionId: 1 }, { unique: true }).catch(logger.error);
+	assistants.createIndex({ createdById: 1, userCount: -1 }).catch(logger.error);
+	assistants.createIndex({ userCount: 1 }).catch(logger.error);
+	assistants.createIndex({ featured: 1, userCount: -1 }).catch(logger.error);
+	assistants.createIndex({ modelId: 1, userCount: -1 }).catch(logger.error);
+	assistants.createIndex({ searchTokens: 1 }).catch(logger.error);
+	assistants.createIndex({ last24HoursCount: 1 }).catch(logger.error);
 	assistantStats
 		// Order of keys is important for the queries
 		.createIndex({ "date.span": 1, "date.at": 1, assistantId: 1 }, { unique: true })
-		.catch(console.error);
-	reports.createIndex({ assistantId: 1 }).catch(console.error);
-	reports.createIndex({ createdBy: 1, assistantId: 1 }).catch(console.error);
+		.catch(logger.error);
+	reports.createIndex({ assistantId: 1 }).catch(logger.error);
+	reports.createIndex({ createdBy: 1, assistantId: 1 }).catch(logger.error);
 
 	// Unique index for semaphore and migration results
-	semaphores.createIndex({ key: 1 }, { unique: true }).catch(console.error);
-	semaphores.createIndex({ createdAt: 1 }, { expireAfterSeconds: 60 }).catch(console.error);
+	semaphores.createIndex({ key: 1 }, { unique: true }).catch(logger.error);
+	semaphores.createIndex({ createdAt: 1 }, { expireAfterSeconds: 60 }).catch(logger.error);
 });

src/lib/server/database.ts

@@ -2,6 +2,7 @@ import { z } from "zod";
 import type { EmbeddingEndpoint, Embedding } from "../embeddingEndpoints";
 import { chunk } from "$lib/utils/chunk";
 import { HF_TOKEN } from "$env/static/private";
+import { logger } from "$lib/server/logger";
 
 export const embeddingEndpointHfApiSchema = z.object({
 	weight: z.number().int().positive().default(1),
@@ -35,8 +36,8 @@ export async function embeddingEndpointHfApi(
 				});
 
 				if (!response.ok) {
-					console.log(await response.text());
-					console.error("Failed to get embeddings from Hugging Face API", response);
+					logger.error(await response.text());
+					logger.error("Failed to get embeddings from Hugging Face API", response);
 					return [];
 				}