fix: add comprehensive database/cache logging and update Grafana dashboard

rui-typelets · rui-typelets · commit 5931c0f5f3e6 · 2025-11-22T15:34:44.000-05:00
diff --git a/src/lib/logger.ts b/src/lib/logger.ts
@@ -376,12 +376,11 @@ class Logger {
       userId: userId || "anonymous",
     };
 
-    // Log slow queries at info level (visible in production)
+    // Log all queries at info level for production visibility
     if (duration > 1000) {
       this.warn(`[DB] Slow query: ${operation} ${table} took ${duration}ms`, meta);
     } else {
-      // Fast queries only logged in debug (dev-only)
-      this.debug(`[DB] ${operation} ${table}`, meta);
+      this.info(`[DB] ${operation} ${table}`, meta);
     }
   }
 
@@ -464,8 +463,8 @@ class Logger {
       meta.keyCount = keyCount;
     }
 
-    // Log at debug level
-    this.debug(`[CACHE] ${operation}${hit !== undefined ? (hit ? " HIT" : " MISS") : ""}`, meta);
+    // Log at info level for production visibility
+    this.info(`[CACHE] ${operation}${hit !== undefined ? (hit ? " HIT" : " MISS") : ""}`, meta);
   }
 
   cacheError(operation: string, key: string, error: Error): void {
diff --git a/src/routes/notes/actions.ts b/src/routes/notes/actions.ts
@@ -4,6 +4,7 @@ import { db, notes } from "../../db";
 import { eq, and } from "drizzle-orm";
 import { noteSchema, noteIdParamSchema } from "../../lib/openapi-schemas";
 import { invalidateNoteCounts } from "../../lib/cache";
+import { logger } from "../../lib/logger";
 
 const actionsRouter = new OpenAPIHono();
 
@@ -40,14 +41,17 @@ actionsRouter.openapi(starNoteRoute, async (c) => {
   const userId = c.get("userId");
   const { id: noteId } = c.req.valid("param");
 
+  const selectStart = Date.now();
   const existingNote = await db.query.notes.findFirst({
     where: and(eq(notes.id, noteId), eq(notes.userId, userId)),
   });
+  logger.databaseQuery("select", "notes", Date.now() - selectStart, userId);
 
   if (!existingNote) {
     throw new HTTPException(404, { message: "Note not found" });
   }
 
+  const updateStart = Date.now();
   const [updatedNote] = await db
     .update(notes)
     .set({
@@ -56,6 +60,7 @@ actionsRouter.openapi(starNoteRoute, async (c) => {
     })
     .where(eq(notes.id, noteId))
     .returning();
+  logger.databaseQuery("update", "notes", Date.now() - updateStart, userId);
 
   // Invalidate counts cache for the note's folder hierarchy
   await invalidateNoteCounts(userId, existingNote.folderId);
@@ -96,14 +101,17 @@ actionsRouter.openapi(restoreNoteRoute, async (c) => {
   const userId = c.get("userId");
   const { id: noteId } = c.req.valid("param");
 
+  const selectStart = Date.now();
   const existingNote = await db.query.notes.findFirst({
     where: and(eq(notes.id, noteId), eq(notes.userId, userId)),
   });
+  logger.databaseQuery("select", "notes", Date.now() - selectStart, userId);
 
   if (!existingNote) {
     throw new HTTPException(404, { message: "Note not found" });
   }
 
+  const updateStart = Date.now();
   const [restoredNote] = await db
     .update(notes)
     .set({
@@ -113,6 +121,7 @@ actionsRouter.openapi(restoreNoteRoute, async (c) => {
     })
     .where(eq(notes.id, noteId))
     .returning();
+  logger.databaseQuery("update", "notes", Date.now() - updateStart, userId);
 
   // Invalidate counts cache for the note's folder hierarchy
   await invalidateNoteCounts(userId, existingNote.folderId);
@@ -156,9 +165,11 @@ actionsRouter.openapi(hideNoteRoute, async (c) => {
   const userId = c.get("userId");
   const { id: noteId } = c.req.valid("param");
 
+  const selectStart = Date.now();
   const existingNote = await db.query.notes.findFirst({
     where: and(eq(notes.id, noteId), eq(notes.userId, userId)),
   });
+  logger.databaseQuery("select", "notes", Date.now() - selectStart, userId);
 
   if (!existingNote) {
     throw new HTTPException(404, { message: "Note not found" });
@@ -168,6 +179,7 @@ actionsRouter.openapi(hideNoteRoute, async (c) => {
     throw new HTTPException(400, { message: "Note is already hidden" });
   }
 
+  const updateStart = Date.now();
   const [hiddenNote] = await db
     .update(notes)
     .set({
@@ -177,6 +189,7 @@ actionsRouter.openapi(hideNoteRoute, async (c) => {
     })
     .where(eq(notes.id, noteId))
     .returning();
+  logger.databaseQuery("update", "notes", Date.now() - updateStart, userId);
 
   // Invalidate counts cache for the note's folder hierarchy
   await invalidateNoteCounts(userId, existingNote.folderId);
@@ -220,9 +233,11 @@ actionsRouter.openapi(unhideNoteRoute, async (c) => {
   const userId = c.get("userId");
   const { id: noteId } = c.req.valid("param");
 
+  const selectStart = Date.now();
   const existingNote = await db.query.notes.findFirst({
     where: and(eq(notes.id, noteId), eq(notes.userId, userId)),
   });
+  logger.databaseQuery("select", "notes", Date.now() - selectStart, userId);
 
   if (!existingNote) {
     throw new HTTPException(404, { message: "Note not found" });
@@ -232,6 +247,7 @@ actionsRouter.openapi(unhideNoteRoute, async (c) => {
     throw new HTTPException(400, { message: "Note is not hidden" });
   }
 
+  const updateStart = Date.now();
   const [unhiddenNote] = await db
     .update(notes)
     .set({
@@ -241,6 +257,7 @@ actionsRouter.openapi(unhideNoteRoute, async (c) => {
     })
     .where(eq(notes.id, noteId))
     .returning();
+  logger.databaseQuery("update", "notes", Date.now() - updateStart, userId);
 
   // Invalidate counts cache for the note's folder hierarchy
   await invalidateNoteCounts(userId, existingNote.folderId);
diff --git a/src/routes/notes/counts.ts b/src/routes/notes/counts.ts
@@ -4,6 +4,7 @@ import { eq, and, isNull, sql } from "drizzle-orm";
 import { getCache, setCache } from "../../lib/cache";
 import { CacheKeys, CacheTTL } from "../../lib/cache-keys";
 import { z } from "@hono/zod-openapi";
+import { logger } from "../../lib/logger";
 
 const countsRouter = new OpenAPIHono();
 
@@ -18,6 +19,7 @@ async function getAllDescendantFolderIds(
     return [];
   }
 
+  const queryStart = Date.now();
   // Use a recursive CTE to get all descendants in a single query
   const result = await db.execute<{ id: string }>(sql`
     WITH RECURSIVE folder_tree AS (
@@ -40,6 +42,7 @@ async function getAllDescendantFolderIds(
     )
     SELECT DISTINCT id FROM folder_tree
   `);
+  logger.databaseQuery("select_recursive", "folders", Date.now() - queryStart, userId);
 
   return (result as unknown as { id: string }[]).map((row) => row.id);
 }
@@ -58,6 +61,7 @@ async function getCountsForFolders(
     return { all: 0, starred: 0, archived: 0, trash: 0 };
   }
 
+  const queryStart = Date.now();
   // Get all counts in a single query using conditional aggregation
   const result = await db.execute<{
     all_count: string;
@@ -77,6 +81,7 @@ async function getCountsForFolders(
         sql`, `
       )})
   `);
+  logger.databaseQuery("count_aggregate", "notes", Date.now() - queryStart, userId);
 
   const rows = result as unknown as {
     all_count: string;
@@ -96,6 +101,7 @@ async function getCountsForFolders(
 // Cache warming function - call this after note/folder operations to keep cache fresh
 export async function warmNotesCountsCache(userId: string): Promise<void> {
   // Get total counts for all user's notes using single query
+  const totalCountsStart = Date.now();
   const totalCountsResult = await db.execute<{
     all_count: string;
     starred_count: string;
@@ -110,6 +116,7 @@ export async function warmNotesCountsCache(userId: string): Promise<void> {
     FROM notes
     WHERE user_id = ${userId}
   `);
+  logger.databaseQuery("count_aggregate", "notes", Date.now() - totalCountsStart, userId);
 
   const totalCountsRows = totalCountsResult as unknown as {
     all_count: string;
@@ -120,10 +127,12 @@ export async function warmNotesCountsCache(userId: string): Promise<void> {
   const totalCounts = totalCountsRows[0];
 
   // Get root-level folders (no parent)
+  const foldersStart = Date.now();
   const rootFolders = await db.query.folders.findMany({
     where: and(eq(folders.userId, userId), isNull(folders.parentId)),
     columns: { id: true },
   });
+  logger.databaseQuery("select", "folders", Date.now() - foldersStart, userId);
 
   const folderCounts: Record<
     string,
@@ -252,10 +261,12 @@ const getNotesCountsHandler: RouteHandler<typeof getNotesCountsRoute> = async (c
       }
 
       // Get direct children of the specified folder
+      const childFoldersStart = Date.now();
       const childFolders = await db.query.folders.findMany({
         where: and(eq(folders.parentId, folderId), eq(folders.userId, userId)),
         columns: { id: true },
       });
+      logger.databaseQuery("select", "folders", Date.now() - childFoldersStart, userId);
 
       if (childFolders.length === 0) {
         // No child folders, return empty object
@@ -327,6 +338,7 @@ const getNotesCountsHandler: RouteHandler<typeof getNotesCountsRoute> = async (c
     }
 
     // Get total counts for all user's notes using single query
+    const totalCountsStart = Date.now();
     const totalCountsResult = await db.execute<{
       all_count: string;
       starred_count: string;
@@ -341,6 +353,7 @@ const getNotesCountsHandler: RouteHandler<typeof getNotesCountsRoute> = async (c
       FROM notes
       WHERE user_id = ${userId}
     `);
+    logger.databaseQuery("count_aggregate", "notes", Date.now() - totalCountsStart, userId);
 
     const totalCountsRows = totalCountsResult as unknown as {
       all_count: string;
@@ -351,10 +364,12 @@ const getNotesCountsHandler: RouteHandler<typeof getNotesCountsRoute> = async (c
     const totalCounts = totalCountsRows[0];
 
     // Get root-level folders (no parent)
+    const rootFoldersStart = Date.now();
     const rootFolders = await db.query.folders.findMany({
       where: and(eq(folders.userId, userId), isNull(folders.parentId)),
       columns: { id: true },
     });
+    logger.databaseQuery("select", "folders", Date.now() - rootFoldersStart, userId);
 
     const folderCounts: Record<
       string,
diff --git a/src/routes/notes/crud.ts b/src/routes/notes/crud.ts
@@ -13,6 +13,7 @@ import {
   noteIdParamSchema,
 } from "../../lib/openapi-schemas";
 import { invalidateNoteCounts, invalidateNoteCountsForMove } from "../../lib/cache";
+import { logger } from "../../lib/logger";
 
 const crudRouter = new OpenAPIHono();
 
@@ -91,12 +92,15 @@ const listNotesHandler: RouteHandler<typeof listNotesRoute> = async (c) => {
 
   const whereClause = conditions.length > 1 ? and(...conditions) : conditions[0];
 
+  const countStart = Date.now();
   const [{ total }] = await db.select({ total: count() }).from(notes).where(whereClause);
+  logger.databaseQuery("count", "notes", Date.now() - countStart, userId);
 
   const page = query.page || 1;
   const limit = query.limit || 20;
   const offset = (page - 1) * limit;
 
+  const selectStart = Date.now();
   const userNotes = await db.query.notes.findMany({
     where: whereClause,
     orderBy: [desc(notes.updatedAt)],
@@ -122,6 +126,7 @@ const listNotesHandler: RouteHandler<typeof listNotesRoute> = async (c) => {
       },
     },
   });
+  logger.databaseQuery("select", "notes", Date.now() - selectStart, userId);
 
   // Add attachment counts to notes
   const notesWithAttachmentCount = userNotes.map((note) => ({
@@ -207,12 +212,14 @@ crudRouter.openapi(getNoteRoute, async (c) => {
   const userId = c.get("userId");
   const { id: noteId } = c.req.valid("param");
 
+  const selectStart = Date.now();
   const note = await db.query.notes.findFirst({
     where: and(eq(notes.id, noteId), eq(notes.userId, userId)),
     with: {
       folder: true,
     },
   });
+  logger.databaseQuery("select", "notes", Date.now() - selectStart, userId);
 
   if (!note) {
     throw new HTTPException(404, { message: "Note not found" });
@@ -279,13 +286,15 @@ const createNoteHandler: RouteHandler<typeof createNoteRoute> = async (c) => {
     salt?: string;
   };
 
+  const insertStart = Date.now();
   const [newNote] = await db
     .insert(notes)
     .values({
       ...validatedData,
       userId,
     })
     .returning();
+  logger.databaseQuery("insert", "notes", Date.now() - insertStart, userId);
 
   // Invalidate counts cache for the user and all ancestor folders
   await invalidateNoteCounts(userId, validatedData.folderId ?? null);
@@ -388,14 +397,17 @@ crudRouter.openapi(updateNoteRoute, async (c) => {
   const data = await c.req.json();
   const validatedData = updateNoteSchema.parse(data);
 
+  const selectStart = Date.now();
   const existingNote = await db.query.notes.findFirst({
     where: and(eq(notes.id, noteId), eq(notes.userId, userId)),
   });
+  logger.databaseQuery("select", "notes", Date.now() - selectStart, userId);
 
   if (!existingNote) {
     throw new HTTPException(404, { message: "Note not found" });
   }
 
+  const updateStart = Date.now();
   const [updatedNote] = await db
     .update(notes)
     .set({
@@ -404,6 +416,7 @@ crudRouter.openapi(updateNoteRoute, async (c) => {
     })
     .where(eq(notes.id, noteId))
     .returning();
+  logger.databaseQuery("update", "notes", Date.now() - updateStart, userId);
 
   // Invalidate counts cache - check if note moved between folders
   const oldFolderId = existingNote.folderId;
@@ -454,14 +467,17 @@ crudRouter.openapi(deleteNoteRoute, async (c) => {
   const userId = c.get("userId");
   const { id: noteId } = c.req.valid("param");
 
+  const selectStart = Date.now();
   const existingNote = await db.query.notes.findFirst({
     where: and(eq(notes.id, noteId), eq(notes.userId, userId)),
   });
+  logger.databaseQuery("select", "notes", Date.now() - selectStart, userId);
 
   if (!existingNote) {
     throw new HTTPException(404, { message: "Note not found" });
   }
 
+  const updateStart = Date.now();
   const [deletedNote] = await db
     .update(notes)
     .set({
@@ -470,6 +486,7 @@ crudRouter.openapi(deleteNoteRoute, async (c) => {
     })
     .where(eq(notes.id, noteId))
     .returning();
+  logger.databaseQuery("update", "notes", Date.now() - updateStart, userId);
 
   // Invalidate counts cache for the note's folder hierarchy
   await invalidateNoteCounts(userId, existingNote.folderId);
diff --git a/src/routes/notes/trash.ts b/src/routes/notes/trash.ts
@@ -4,6 +4,7 @@ import { db, notes } from "../../db";
 import { eq, and, count } from "drizzle-orm";
 import { emptyTrashResponseSchema } from "../../lib/openapi-schemas";
 import { deleteCachePattern } from "../../lib/cache";
+import { logger } from "../../lib/logger";
 
 const trashRouter = new OpenAPIHono();
 
@@ -38,12 +39,16 @@ trashRouter.openapi(emptyTrashRoute, async (c) => {
   try {
     const userId = c.get("userId");
 
+    const countStart = Date.now();
     const [{ total }] = await db
       .select({ total: count() })
       .from(notes)
       .where(and(eq(notes.userId, userId), eq(notes.deleted, true)));
+    logger.databaseQuery("count", "notes", Date.now() - countStart, userId);
 
+    const deleteStart = Date.now();
     await db.delete(notes).where(and(eq(notes.userId, userId), eq(notes.deleted, true)));
+    logger.databaseQuery("delete", "notes", Date.now() - deleteStart, userId);
 
     // Invalidate all note counts cache for this user (global and all folders)
     await deleteCachePattern(`notes:${userId}:*`);
diff --git a/src/routes/users/crud.ts b/src/routes/users/crud.ts

Original file line number	Diff line number	Diff line change
`@@ -376,12 +376,11 @@ class Logger {`
`376`	`376`	`userId: userId \|\| "anonymous",`
`377`	`377`	`};`
`378`	`378`
`379`		`- // Log slow queries at info level (visible in production)`
	`379`	`+ // Log all queries at info level for production visibility`
`380`	`380`	`if (duration > 1000) {`
`381`	`381`	this.warn(`[DB] Slow query: ${operation} ${table} took ${duration}ms`, meta);
`382`	`382`	`} else {`
`383`		`- // Fast queries only logged in debug (dev-only)`
`384`		- this.debug(`[DB] ${operation} ${table}`, meta);
	`383`	+ this.info(`[DB] ${operation} ${table}`, meta);
`385`	`384`	`}`
`386`	`385`	`}`
`387`	`386`
`@@ -464,8 +463,8 @@ class Logger {`
`464`	`463`	`meta.keyCount = keyCount;`
`465`	`464`	`}`
`466`	`465`
`467`		`- // Log at debug level`
`468`		- this.debug(`[CACHE] ${operation}${hit !== undefined ? (hit ? " HIT" : " MISS") : ""}`, meta);
	`466`	`+ // Log at info level for production visibility`
	`467`	+ this.info(`[CACHE] ${operation}${hit !== undefined ? (hit ? " HIT" : " MISS") : ""}`, meta);
`469`	`468`	`}`
`470`	`469`
`471`	`470`	`cacheError(operation: string, key: string, error: Error): void {`