From 5bf1148a4f9edc3e79b6b9c7b37bbc46357ed616 Mon Sep 17 00:00:00 2001 From: user Date: Sun, 1 Mar 2026 04:36:17 +0200 Subject: [PATCH] levelled up logging, albeit with a bit of verbosity... --- packages/logger/index.ts | 122 ++++++++- packages/logic/domains/2fa/controller.ts | 65 ++++- packages/logic/domains/2fa/repository.ts | 231 +++++++++++++---- .../logic/domains/notifications/repository.ts | 187 +++++++++----- .../logic/domains/user/account.repository.ts | 160 ++++++------ packages/logic/domains/user/repository.ts | 243 ++++++++++++------ 6 files changed, 731 insertions(+), 277 deletions(-) diff --git a/packages/logger/index.ts b/packages/logger/index.ts index 8021f0a..da258cd 100644 --- a/packages/logger/index.ts +++ b/packages/logger/index.ts @@ -88,6 +88,126 @@ const logger = winston.createLogger({ const stream = { write: (message: string) => logger.http(message.trim()) }; +type LogLevel = keyof typeof levels; +type ErrorKind = "validation" | "auth" | "db" | "external" | "unknown"; +type FlowCtxLike = { + flowId: string; + userId?: string; + sessionId?: string; +}; + +const REDACTED_KEYS = new Set([ + "password", + "code", + "secret", + "token", + "verificationtoken", + "backupcodes", + "authorization", + "headers", + "hash", +]); + +function sanitizeMeta(input: Record) { + const sanitized = Object.fromEntries( + Object.entries(input).map(([key, value]) => { + if (value === undefined) { + return [key, undefined]; + } + const lowered = key.toLowerCase(); + if (REDACTED_KEYS.has(lowered)) { + return [key, "[REDACTED]"]; + } + return [key, value]; + }), + ); + + return Object.fromEntries( + Object.entries(sanitized).filter(([, value]) => value !== undefined), + ); +} + +function classifyError(error: unknown): ErrorKind { + if (!error) return "unknown"; + if (typeof error === "object" && error && "code" in error) { + const code = String((error as { code?: unknown }).code ?? "").toUpperCase(); + if (code.includes("AUTH") || code.includes("UNAUTHORIZED")) return "auth"; + if (code.includes("VALIDATION") || code.includes("INVALID")) return "validation"; + if (code.includes("DB") || code.includes("DATABASE")) return "db"; + } + return "unknown"; +} + +function errorMessage(error: unknown) { + if (error instanceof Error) return error.message; + if (typeof error === "string") return error; + if (error && typeof error === "object" && "message" in error) { + return String((error as { message?: unknown }).message ?? "Unknown error"); + } + return "Unknown error"; +} + +function writeLog(level: LogLevel, message: string, payload: Record) { + switch (level) { + case "error": + logger.error(message, payload); + return; + case "warn": + logger.warn(message, payload); + return; + case "debug": + logger.debug(message, payload); + return; + case "http": + logger.http(message, payload); + return; + default: + logger.info(message, payload); + } +} + +function logDomainEvent({ + level = "info", + event, + fctx, + durationMs, + error, + retryable, + meta, +}: { + level?: LogLevel; + event: string; + fctx: FlowCtxLike; + durationMs?: number; + error?: unknown; + retryable?: boolean; + meta?: Record; +}) { + const payload: Record = { + event, + flowId: fctx.flowId, + userId: fctx.userId, + sessionId: fctx.sessionId, + }; + + if (durationMs !== undefined) payload.duration_ms = durationMs; + if (retryable !== undefined) payload.retryable = retryable; + if (error !== undefined) { + payload.error_kind = classifyError(error); + payload.error_message = errorMessage(error); + if (error && typeof error === "object" && "code" in error) { + payload.error_code = String( + (error as { code?: unknown }).code ?? "UNKNOWN", + ); + } + } + if (meta) { + Object.assign(payload, sanitizeMeta(meta)); + } + + writeLog(level, event, payload); +} + function getError(payload: Err, error?: any) { logger.error(JSON.stringify({ payload, error }, null, 2)); return { @@ -100,4 +220,4 @@ function getError(payload: Err, error?: any) { } as Err; } -export { getError, logger, stream }; +export { getError, logDomainEvent, logger, stream }; diff --git a/packages/logic/domains/2fa/controller.ts b/packages/logic/domains/2fa/controller.ts index a436317..cdf1e2b 100644 --- a/packages/logic/domains/2fa/controller.ts +++ b/packages/logic/domains/2fa/controller.ts @@ -3,13 +3,13 @@ import { FlowExecCtx } from "@core/flow.execution.context"; import { UserRepository } from "@domains/user/repository"; import { getRedisInstance, Redis } from "@pkg/keystore"; import { TwofaRepository } from "./repository"; +import { logDomainEvent } from "@pkg/logger"; import { auth } from "../auth/config.base"; import type { TwoFaSession } from "./data"; import { User } from "@domains/user/data"; import { settings } from "@core/settings"; import { type Err } from "@pkg/result"; import { twofaErrors } from "./errors"; -import { logger } from "@pkg/logger"; import { db } from "@pkg/db"; export class TwofaController { @@ -33,7 +33,13 @@ export class TwofaController { isUserBanned(fctx: FlowExecCtx, userId: string) { return this.userRepo.isUserBanned(fctx, userId).orElse((error) => { - logger.error("Error checking user ban status:", error); + logDomainEvent({ + level: "error", + event: "security.twofa.user_ban_check.failed", + fctx, + error, + meta: { userId }, + }); return okAsync(false); }); } @@ -58,19 +64,34 @@ export class TwofaController { code: string, headers: Headers, ) { + const startedAt = Date.now(); + logDomainEvent({ + event: "security.twofa.verify_and_enable.started", + fctx, + meta: { userId: user.id }, + }); + return this.is2faEnabled(fctx, user.id) .andThen((enabled) => { if (enabled) { + logDomainEvent({ + level: "warn", + event: "security.twofa.verify_and_enable.failed", + fctx, + durationMs: Date.now() - startedAt, + error: { + code: "ALREADY_ENABLED", + message: "2FA already enabled", + }, + meta: { userId: user.id }, + }); return errAsync(twofaErrors.alreadyEnabled(fctx)); } return okAsync(undefined); }) - .andThen(() => { - logger.info(`Verifying 2fa for ${user.id} : ${code}`, { - flowId: fctx.flowId, - }); - return this.twofaRepo.verifyAndEnable2FA(fctx, user.id, code); - }) + .andThen(() => + this.twofaRepo.verifyAndEnable2FA(fctx, user.id, code), + ) .andThen((verified) => { if (verified) { return ResultAsync.combine([ @@ -82,8 +103,27 @@ export class TwofaController { fctx, user.id, ), - ]).map(() => true); + ]).map(() => { + logDomainEvent({ + event: "security.twofa.verify_and_enable.succeeded", + fctx, + durationMs: Date.now() - startedAt, + meta: { userId: user.id }, + }); + return true; + }); } + logDomainEvent({ + level: "warn", + event: "security.twofa.verify_and_enable.failed", + fctx, + durationMs: Date.now() - startedAt, + error: { + code: "INVALID_CODE", + message: "2FA code verification failed", + }, + meta: { userId: user.id }, + }); return okAsync(verified); }); } @@ -169,7 +209,12 @@ export class TwofaController { ) .map(() => undefined) .orElse((error) => { - logger.error("Error marking initial 2FA as complete:", error); + logDomainEvent({ + level: "error", + event: "security.twofa.mark_initial_verification.failed", + fctx: { flowId: crypto.randomUUID() }, + error, + }); return okAsync(undefined); }); } diff --git a/packages/logic/domains/2fa/repository.ts b/packages/logic/domains/2fa/repository.ts index b36a0e4..784b948 100644 --- a/packages/logic/domains/2fa/repository.ts +++ b/packages/logic/domains/2fa/repository.ts @@ -11,7 +11,7 @@ import { settings } from "@core/settings"; import type { Err } from "@pkg/result"; import { twofaErrors } from "./errors"; import { Redis } from "@pkg/keystore"; -import { logger } from "@pkg/logger"; +import { logDomainEvent, logger } from "@pkg/logger"; import { nanoid } from "nanoid"; type TwoFaSetup = { @@ -53,25 +53,49 @@ export class TwofaRepository { userId: string, returnUndefined?: boolean, ): ResultAsync { - logger.info("Getting user 2FA info", { ...fctx, userId }); + const startedAt = Date.now(); + logDomainEvent({ + event: "security.twofa.get_info.started", + fctx, + meta: { userId }, + }); return ResultAsync.fromPromise( this.db.query.twoFactor.findFirst({ where: eq(twoFactor.userId, userId), }), - () => twofaErrors.dbError(fctx, "Failed to query 2FA info"), + (error) => { + logDomainEvent({ + level: "error", + event: "security.twofa.get_info.failed", + fctx, + durationMs: Date.now() - startedAt, + error, + meta: { userId }, + }); + return twofaErrors.dbError(fctx, "Failed to query 2FA info"); + }, ).andThen((found) => { if (!found) { - logger.debug("2FA info not found for user", { - ...fctx, - userId, + logDomainEvent({ + level: "warn", + event: "security.twofa.get_info.failed", + fctx, + durationMs: Date.now() - startedAt, + error: { code: "NOT_FOUND", message: "2FA info not found" }, + meta: { userId }, }); if (returnUndefined) { return okAsync(undefined); } return errAsync(twofaErrors.notFound(fctx)); } - logger.info("2FA info retrieved successfully", { ...fctx, userId }); + logDomainEvent({ + event: "security.twofa.get_info.succeeded", + fctx, + durationMs: Date.now() - startedAt, + meta: { userId }, + }); return okAsync(found as TwoFactor); }); } @@ -105,7 +129,12 @@ export class TwofaRepository { userId: string, secret: string, ): ResultAsync { - logger.info("Starting 2FA setup", { ...fctx, userId }); + const startedAt = Date.now(); + logDomainEvent({ + event: "security.twofa.setup.started", + fctx, + meta: { userId }, + }); return ResultAsync.fromSafePromise( (async () => { @@ -124,16 +153,25 @@ export class TwofaRepository { this.EXPIRY_TIME, JSON.stringify(payload), ); - logger.info("Created temp 2FA session", { - ...fctx, - userId, - expiresIn: this.EXPIRY_TIME, + logDomainEvent({ + event: "security.twofa.setup.succeeded", + fctx, + durationMs: Date.now() - startedAt, + meta: { userId, expiresInSec: this.EXPIRY_TIME }, }); return secret; })(), - ).mapErr(() => - twofaErrors.dbError(fctx, "Setting to data store failed"), - ); + ).mapErr((error) => { + logDomainEvent({ + level: "error", + event: "security.twofa.setup.failed", + fctx, + durationMs: Date.now() - startedAt, + error, + meta: { userId }, + }); + return twofaErrors.dbError(fctx, "Setting to data store failed"); + }); } verifyAndEnable2FA( @@ -141,7 +179,12 @@ export class TwofaRepository { userId: string, code: string, ): ResultAsync { - logger.info("Verifying and enabling 2FA", { ...fctx, userId }); + const startedAt = Date.now(); + logDomainEvent({ + event: "security.twofa.verify_enable.started", + fctx, + meta: { userId }, + }); return ResultAsync.fromPromise( this.store.get(this.getKey(userId)), @@ -149,9 +192,16 @@ export class TwofaRepository { ) .andThen((payload) => { if (!payload) { - logger.error("Setup session not found", { - ...fctx, - userId, + logDomainEvent({ + level: "warn", + event: "security.twofa.verify_enable.failed", + fctx, + durationMs: Date.now() - startedAt, + error: { + code: "SETUP_NOT_FOUND", + message: "2FA setup session not found", + }, + meta: { userId }, }); return errAsync(twofaErrors.setupNotFound(fctx)); } @@ -161,10 +211,16 @@ export class TwofaRepository { const key = this.getKey(userId); if (payloadObj.tries >= this.MAX_SETUP_ATTEMPTS) { - logger.warn("Max setup attempts reached", { - ...fctx, - userId, - tries: payloadObj.tries, + logDomainEvent({ + level: "warn", + event: "security.twofa.verify_enable.failed", + fctx, + durationMs: Date.now() - startedAt, + error: { + code: "MAX_ATTEMPTS_REACHED", + message: "Max setup attempts reached", + }, + meta: { userId, attempts: payloadObj.tries }, }); return ResultAsync.fromPromise(this.store.del(key), () => twofaErrors.dbError( @@ -180,11 +236,20 @@ export class TwofaRepository { !this.checkTotp(payloadObj.secret, code) || code === payloadObj.lastUsedCode ) { - logger.warn("Invalid 2FA code during setup", { - ...fctx, - userId, - tries: payloadObj.tries + 1, - codeReused: code === payloadObj.lastUsedCode, + logDomainEvent({ + level: "warn", + event: "security.twofa.verify_enable.failed", + fctx, + durationMs: Date.now() - startedAt, + error: { + code: "INVALID_CODE", + message: "Invalid or replayed setup code", + }, + meta: { + userId, + attempts: payloadObj.tries + 1, + codeReused: code === payloadObj.lastUsedCode, + }, }); return ResultAsync.fromPromise( this.store.setex( @@ -232,9 +297,11 @@ export class TwofaRepository { ), ) .map(() => { - logger.info("2FA enabled successfully", { - ...fctx, - userId, + logDomainEvent({ + event: "security.twofa.verify_enable.succeeded", + fctx, + durationMs: Date.now() - startedAt, + meta: { userId }, }); return true; }); @@ -368,10 +435,11 @@ export class TwofaRepository { userAgent?: string; }, ): ResultAsync { - logger.info("Creating 2FA verification session", { - ...fctx, - userId: params.userId, - sessionId: params.sessionId, + const startedAt = Date.now(); + logDomainEvent({ + event: "security.twofa.create_session.started", + fctx, + meta: { userId: params.userId, sessionId: params.sessionId }, }); return ResultAsync.fromSafePromise( @@ -402,12 +470,29 @@ export class TwofaRepository { userAgent: params.userAgent, }) .returning(), - () => twofaErrors.dbError(fctx, "Failed to create 2FA session"), + (error) => { + logDomainEvent({ + level: "error", + event: "security.twofa.create_session.failed", + fctx, + durationMs: Date.now() - startedAt, + error, + meta: { userId: params.userId }, + }); + return twofaErrors.dbError( + fctx, + "Failed to create 2FA session", + ); + }, ).map(([session]) => { - logger.info("2FA verification session created", { - ...fctx, - sessionId: session.id, - userId: params.userId, + logDomainEvent({ + event: "security.twofa.create_session.succeeded", + fctx, + durationMs: Date.now() - startedAt, + meta: { + twofaSessionId: session.id, + userId: params.userId, + }, }); return session as TwoFaSession; }), @@ -418,7 +503,12 @@ export class TwofaRepository { fctx: FlowExecCtx, token: string, ): ResultAsync { - logger.debug("Getting 2FA session by token", { ...fctx }); + const startedAt = Date.now(); + logDomainEvent({ + level: "debug", + event: "security.twofa.get_session.started", + fctx, + }); return ResultAsync.fromPromise( this.db @@ -431,15 +521,36 @@ export class TwofaRepository { ), ) .limit(1), - () => twofaErrors.dbError(fctx, "Failed to query 2FA session"), + (error) => { + logDomainEvent({ + level: "error", + event: "security.twofa.get_session.failed", + fctx, + durationMs: Date.now() - startedAt, + error, + }); + return twofaErrors.dbError(fctx, "Failed to query 2FA session"); + }, ).map((result) => { if (!result.length) { - logger.warn("2FA session not found or expired", { ...fctx }); + logDomainEvent({ + level: "warn", + event: "security.twofa.get_session.failed", + fctx, + durationMs: Date.now() - startedAt, + error: { + code: "SESSION_NOT_FOUND", + message: "2FA session not found or expired", + }, + }); return null; } - logger.debug("2FA session found", { - ...fctx, - sessionId: result[0].id, + logDomainEvent({ + level: "debug", + event: "security.twofa.get_session.succeeded", + fctx, + durationMs: Date.now() - startedAt, + meta: { twofaSessionId: result[0].id }, }); return result[0] as TwoFaSession; }); @@ -547,17 +658,37 @@ export class TwofaRepository { } cleanupExpiredSessions(fctx: FlowExecCtx): ResultAsync { - logger.info("Cleaning up expired 2FA sessions", { ...fctx }); + const startedAt = Date.now(); + logDomainEvent({ + event: "security.twofa.cleanup_expired.started", + fctx, + }); return ResultAsync.fromPromise( this.db .delete(twofaSessions) .where(lt(twofaSessions.expiresAt, new Date())), - () => - twofaErrors.dbError(fctx, "Failed to cleanup expired sessions"), + (error) => { + logDomainEvent({ + level: "error", + event: "security.twofa.cleanup_expired.failed", + fctx, + durationMs: Date.now() - startedAt, + error, + }); + return twofaErrors.dbError( + fctx, + "Failed to cleanup expired sessions", + ); + }, ).map((result) => { const count = result.length || 0; - logger.info("Expired sessions cleaned up", { ...fctx, count }); + logDomainEvent({ + event: "security.twofa.cleanup_expired.succeeded", + fctx, + durationMs: Date.now() - startedAt, + meta: { count }, + }); return count; }); } diff --git a/packages/logic/domains/notifications/repository.ts b/packages/logic/domains/notifications/repository.ts index e121267..8578da3 100644 --- a/packages/logic/domains/notifications/repository.ts +++ b/packages/logic/domains/notifications/repository.ts @@ -10,7 +10,7 @@ import type { } from "./data"; import { type Err } from "@pkg/result"; import { notificationErrors } from "./errors"; -import { logger } from "@pkg/logger"; +import { logDomainEvent } from "@pkg/logger"; export class NotificationRepository { constructor(private db: Database) {} @@ -20,7 +20,20 @@ export class NotificationRepository { filters: NotificationFilters, pagination: PaginationOptions, ): ResultAsync { - logger.info("Getting notifications with filters", { ...fctx, filters }); + const startedAt = Date.now(); + logDomainEvent({ + event: "notifications.list.started", + fctx, + meta: { + hasSearch: Boolean(filters.search), + isRead: filters.isRead, + isArchived: filters.isArchived, + page: pagination.page, + pageSize: pagination.pageSize, + sortBy: pagination.sortBy, + sortOrder: pagination.sortOrder, + }, + }); const { userId, isRead, isArchived, type, category, priority, search } = filters; @@ -68,8 +81,11 @@ export class NotificationRepository { return ResultAsync.fromPromise( this.db.select({ count: count() }).from(notifications).where(whereClause), (error) => { - logger.error("Failed to get notifications count", { - ...fctx, + logDomainEvent({ + level: "error", + event: "notifications.list.failed", + fctx, + durationMs: Date.now() - startedAt, error, }); return notificationErrors.getNotificationsFailed( @@ -109,8 +125,11 @@ export class NotificationRepository { .limit(pageSize) .offset(offset), (error) => { - logger.error("Failed to get notifications data", { - ...fctx, + logDomainEvent({ + level: "error", + event: "notifications.list.failed", + fctx, + durationMs: Date.now() - startedAt, error, }); return notificationErrors.getNotificationsFailed( @@ -120,11 +139,15 @@ export class NotificationRepository { }, ).map((data) => { const totalPages = Math.ceil(total / pageSize); - logger.info("Retrieved notifications", { - ...fctx, - count: data.length, - page, - totalPages, + logDomainEvent({ + event: "notifications.list.succeeded", + fctx, + durationMs: Date.now() - startedAt, + meta: { + count: data.length, + page, + totalPages, + }, }); return { @@ -143,10 +166,11 @@ export class NotificationRepository { notificationIds: number[], userId: string, ): ResultAsync { - logger.info("Marking notifications as read", { - ...fctx, - notificationIds, - userId, + const startedAt = Date.now(); + logDomainEvent({ + event: "notifications.mark_read.started", + fctx, + meta: { userId, notificationCount: notificationIds.length }, }); return ResultAsync.fromPromise( @@ -164,8 +188,11 @@ export class NotificationRepository { ), ), (error) => { - logger.error("Failed to mark notifications as read", { - ...fctx, + logDomainEvent({ + level: "error", + event: "notifications.mark_read.failed", + fctx, + durationMs: Date.now() - startedAt, error, }); return notificationErrors.markAsReadFailed( @@ -174,9 +201,11 @@ export class NotificationRepository { ); }, ).map(() => { - logger.info("Notifications marked as read successfully", { - ...fctx, - notificationIds, + logDomainEvent({ + event: "notifications.mark_read.succeeded", + fctx, + durationMs: Date.now() - startedAt, + meta: { notificationCount: notificationIds.length }, }); return true; }); @@ -187,10 +216,11 @@ export class NotificationRepository { notificationIds: number[], userId: string, ): ResultAsync { - logger.info("Marking notifications as unread", { - ...fctx, - notificationIds, - userId, + const startedAt = Date.now(); + logDomainEvent({ + event: "notifications.mark_unread.started", + fctx, + meta: { userId, notificationCount: notificationIds.length }, }); return ResultAsync.fromPromise( @@ -208,8 +238,11 @@ export class NotificationRepository { ), ), (error) => { - logger.error("Failed to mark notifications as unread", { - ...fctx, + logDomainEvent({ + level: "error", + event: "notifications.mark_unread.failed", + fctx, + durationMs: Date.now() - startedAt, error, }); return notificationErrors.markAsUnreadFailed( @@ -218,9 +251,11 @@ export class NotificationRepository { ); }, ).map(() => { - logger.info("Notifications marked as unread successfully", { - ...fctx, - notificationIds, + logDomainEvent({ + event: "notifications.mark_unread.succeeded", + fctx, + durationMs: Date.now() - startedAt, + meta: { notificationCount: notificationIds.length }, }); return true; }); @@ -231,10 +266,11 @@ export class NotificationRepository { notificationIds: number[], userId: string, ): ResultAsync { - logger.info("Archiving notifications", { - ...fctx, - notificationIds, - userId, + const startedAt = Date.now(); + logDomainEvent({ + event: "notifications.archive.started", + fctx, + meta: { userId, notificationCount: notificationIds.length }, }); return ResultAsync.fromPromise( @@ -251,8 +287,11 @@ export class NotificationRepository { ), ), (error) => { - logger.error("Failed to archive notifications", { - ...fctx, + logDomainEvent({ + level: "error", + event: "notifications.archive.failed", + fctx, + durationMs: Date.now() - startedAt, error, }); return notificationErrors.archiveFailed( @@ -261,9 +300,11 @@ export class NotificationRepository { ); }, ).map(() => { - logger.info("Notifications archived successfully", { - ...fctx, - notificationIds, + logDomainEvent({ + event: "notifications.archive.succeeded", + fctx, + durationMs: Date.now() - startedAt, + meta: { notificationCount: notificationIds.length }, }); return true; }); @@ -274,10 +315,11 @@ export class NotificationRepository { notificationIds: number[], userId: string, ): ResultAsync { - logger.info("Unarchiving notifications", { - ...fctx, - notificationIds, - userId, + const startedAt = Date.now(); + logDomainEvent({ + event: "notifications.unarchive.started", + fctx, + meta: { userId, notificationCount: notificationIds.length }, }); return ResultAsync.fromPromise( @@ -294,8 +336,11 @@ export class NotificationRepository { ), ), (error) => { - logger.error("Failed to unarchive notifications", { - ...fctx, + logDomainEvent({ + level: "error", + event: "notifications.unarchive.failed", + fctx, + durationMs: Date.now() - startedAt, error, }); return notificationErrors.unarchiveFailed( @@ -304,9 +349,11 @@ export class NotificationRepository { ); }, ).map(() => { - logger.info("Notifications unarchived successfully", { - ...fctx, - notificationIds, + logDomainEvent({ + event: "notifications.unarchive.succeeded", + fctx, + durationMs: Date.now() - startedAt, + meta: { notificationCount: notificationIds.length }, }); return true; }); @@ -317,10 +364,11 @@ export class NotificationRepository { notificationIds: number[], userId: string, ): ResultAsync { - logger.info("Deleting notifications", { - ...fctx, - notificationIds, - userId, + const startedAt = Date.now(); + logDomainEvent({ + event: "notifications.delete.started", + fctx, + meta: { userId, notificationCount: notificationIds.length }, }); return ResultAsync.fromPromise( @@ -333,8 +381,11 @@ export class NotificationRepository { ), ), (error) => { - logger.error("Failed to delete notifications", { - ...fctx, + logDomainEvent({ + level: "error", + event: "notifications.delete.failed", + fctx, + durationMs: Date.now() - startedAt, error, }); return notificationErrors.deleteNotificationsFailed( @@ -343,9 +394,11 @@ export class NotificationRepository { ); }, ).map(() => { - logger.info("Notifications deleted successfully", { - ...fctx, - notificationIds, + logDomainEvent({ + event: "notifications.delete.succeeded", + fctx, + durationMs: Date.now() - startedAt, + meta: { notificationCount: notificationIds.length }, }); return true; }); @@ -355,7 +408,12 @@ export class NotificationRepository { fctx: FlowExecCtx, userId: string, ): ResultAsync { - logger.info("Getting unread count", { ...fctx, userId }); + const startedAt = Date.now(); + logDomainEvent({ + event: "notifications.unread_count.started", + fctx, + meta: { userId }, + }); return ResultAsync.fromPromise( this.db @@ -369,7 +427,13 @@ export class NotificationRepository { ), ), (error) => { - logger.error("Failed to get unread count", { ...fctx, error }); + logDomainEvent({ + level: "error", + event: "notifications.unread_count.failed", + fctx, + durationMs: Date.now() - startedAt, + error, + }); return notificationErrors.getUnreadCountFailed( fctx, error instanceof Error ? error.message : String(error), @@ -377,7 +441,12 @@ export class NotificationRepository { }, ).map((result) => { const count = result[0]?.count || 0; - logger.info("Retrieved unread count", { ...fctx, count }); + logDomainEvent({ + event: "notifications.unread_count.succeeded", + fctx, + durationMs: Date.now() - startedAt, + meta: { count }, + }); return count; }); } diff --git a/packages/logic/domains/user/account.repository.ts b/packages/logic/domains/user/account.repository.ts index ecb0fa8..91fa4d0 100644 --- a/packages/logic/domains/user/account.repository.ts +++ b/packages/logic/domains/user/account.repository.ts @@ -1,10 +1,10 @@ import { FlowExecCtx } from "@/core/flow.execution.context"; import { traceResultAsync } from "@core/observability"; import { ERROR_CODES, type Err } from "@pkg/result"; -import { getError, logger } from "@pkg/logger"; +import { getError, logDomainEvent } from "@pkg/logger"; import { auth } from "../auth/config.base"; import { account } from "@pkg/db/schema"; -import { ResultAsync } from "neverthrow"; +import { ResultAsync, errAsync, okAsync } from "neverthrow"; import { Database, eq } from "@pkg/db"; import { nanoid } from "nanoid"; @@ -40,9 +40,11 @@ export class AccountRepository { fctx, attributes: { "app.user.id": userId }, fn: () => { - logger.info("Checking if account exists for user", { - ...fctx, - userId, + const startedAt = Date.now(); + logDomainEvent({ + event: "account.ensure_exists.started", + fctx, + meta: { userId }, }); return ResultAsync.fromPromise( @@ -50,44 +52,40 @@ export class AccountRepository { where: eq(account.userId, userId), }), (error) => { - logger.error("Failed to check account existence", { - ...fctx, + logDomainEvent({ + level: "error", + event: "account.ensure_exists.failed", + fctx, + durationMs: Date.now() - startedAt, error, + meta: { userId }, }); return this.dbError( fctx, - error instanceof Error - ? error.message - : String(error), + error instanceof Error ? error.message : String(error), ); }, ).andThen((existingAccount) => { if (existingAccount) { - logger.info("Account already exists for user", { - ...fctx, - userId, + logDomainEvent({ + event: "account.ensure_exists.succeeded", + fctx, + durationMs: Date.now() - startedAt, + meta: { userId, existed: true }, }); - return ResultAsync.fromSafePromise( - Promise.resolve(true), - ); + return okAsync(true); } - logger.info( - "Account does not exist, creating new account for user", - { - ...fctx, - userId, - }, - ); - return ResultAsync.fromPromise( - auth.$context.then((ctx) => - ctx.password.hash(nanoid()), - ), + auth.$context.then((ctx) => ctx.password.hash(nanoid())), (error) => { - logger.error("Failed to hash password", { - ...fctx, + logDomainEvent({ + level: "error", + event: "account.ensure_exists.failed", + fctx, + durationMs: Date.now() - startedAt, error, + meta: { userId, stage: "hash_password" }, }); return this.dbError( fctx, @@ -106,16 +104,20 @@ export class AccountRepository { id: aid, accountId: userId, providerId: "credential", - userId: userId, + userId, password, createdAt: new Date(), updatedAt: new Date(), }) .execute(), (error) => { - logger.error("Failed to create account", { - ...fctx, + logDomainEvent({ + level: "error", + event: "account.ensure_exists.failed", + fctx, + durationMs: Date.now() - startedAt, error, + meta: { userId, stage: "create_account" }, }); return this.dbError( fctx, @@ -125,13 +127,12 @@ export class AccountRepository { ); }, ).map(() => { - logger.info( - "Account created successfully for user", - { - ...fctx, - userId, - }, - ); + logDomainEvent({ + event: "account.ensure_exists.succeeded", + fctx, + durationMs: Date.now() - startedAt, + meta: { userId, existed: false }, + }); return false; }); }); @@ -150,9 +151,11 @@ export class AccountRepository { fctx, attributes: { "app.user.id": userId }, fn: () => { - logger.info("Starting password rotation for user", { - ...fctx, - userId, + const startedAt = Date.now(); + logDomainEvent({ + event: "account.rotate_password.started", + fctx, + meta: { userId }, }); return ResultAsync.fromPromise( @@ -160,10 +163,14 @@ export class AccountRepository { where: eq(account.userId, userId), }), (error) => { - logger.error( - "Failed to check account existence for password rotation", - { ...fctx, error }, - ); + logDomainEvent({ + level: "error", + event: "account.rotate_password.failed", + fctx, + durationMs: Date.now() - startedAt, + error, + meta: { userId, stage: "check_exists" }, + }); return this.dbError( fctx, error instanceof Error @@ -173,29 +180,28 @@ export class AccountRepository { }, ).andThen((existingAccount) => { if (!existingAccount) { - logger.error("Account not found for user", { - ...fctx, - userId, + logDomainEvent({ + level: "warn", + event: "account.rotate_password.failed", + fctx, + durationMs: Date.now() - startedAt, + error: { code: "NOT_FOUND", message: "Account not found" }, + meta: { userId }, }); - return ResultAsync.fromSafePromise( - Promise.resolve(this.accountNotFound(fctx)), - ).andThen((err) => - ResultAsync.fromSafePromise(Promise.reject(err)), - ); + return errAsync(this.accountNotFound(fctx)); } return ResultAsync.fromPromise( - auth.$context.then((ctx) => - ctx.password.hash(password), - ), + auth.$context.then((ctx) => ctx.password.hash(password)), (error) => { - logger.error( - "Failed to hash password for rotation", - { - ...fctx, - error, - }, - ); + logDomainEvent({ + level: "error", + event: "account.rotate_password.failed", + fctx, + durationMs: Date.now() - startedAt, + error, + meta: { userId, stage: "hash_password" }, + }); return this.dbError( fctx, error instanceof Error @@ -204,10 +210,6 @@ export class AccountRepository { ); }, ).andThen((hashed) => { - logger.info("Updating user's password in database", { - ...fctx, - }); - return ResultAsync.fromPromise( this.db .update(account) @@ -216,9 +218,13 @@ export class AccountRepository { .returning() .execute(), (error) => { - logger.error("Failed to update password", { - ...fctx, + logDomainEvent({ + level: "error", + event: "account.rotate_password.failed", + fctx, + durationMs: Date.now() - startedAt, error, + meta: { userId, stage: "update_password" }, }); return this.dbError( fctx, @@ -227,14 +233,12 @@ export class AccountRepository { : String(error), ); }, - ).map((result) => { - logger.info( - "User's password updated successfully", - { ...fctx }, - ); - logger.debug("Password rotation result", { - ...fctx, - result, + ).map(() => { + logDomainEvent({ + event: "account.rotate_password.succeeded", + fctx, + durationMs: Date.now() - startedAt, + meta: { userId }, }); return password; }); diff --git a/packages/logic/domains/user/repository.ts b/packages/logic/domains/user/repository.ts index 2be5f9a..69eadeb 100644 --- a/packages/logic/domains/user/repository.ts +++ b/packages/logic/domains/user/repository.ts @@ -6,7 +6,7 @@ import { Database, eq } from "@pkg/db"; import { BanInfo, User } from "./data"; import { user } from "@pkg/db/schema"; import { userErrors } from "./errors"; -import { logger } from "@pkg/logger"; +import { logDomainEvent } from "@pkg/logger"; export class UserRepository { constructor(private db: Database) {} @@ -17,9 +17,11 @@ export class UserRepository { fctx, attributes: { "app.user.id": userId }, fn: () => { - logger.info("Getting user info for user", { - flowId: fctx.flowId, - userId, + const startedAt = Date.now(); + logDomainEvent({ + event: "user.get_info.started", + fctx, + meta: { userId }, }); return ResultAsync.fromPromise( @@ -27,9 +29,13 @@ export class UserRepository { where: eq(user.id, userId), }), (error) => { - logger.error("Failed to get user info", { - flowId: fctx.flowId, + logDomainEvent({ + level: "error", + event: "user.get_info.failed", + fctx, + durationMs: Date.now() - startedAt, error, + meta: { userId }, }); return userErrors.getUserInfoFailed( fctx, @@ -38,16 +44,22 @@ export class UserRepository { }, ).andThen((userData) => { if (!userData) { - logger.error("User not found with id", { - flowId: fctx.flowId, - userId, + logDomainEvent({ + level: "warn", + event: "user.get_info.failed", + fctx, + durationMs: Date.now() - startedAt, + error: { code: "NOT_FOUND", message: "User not found" }, + meta: { userId }, }); return errAsync(userErrors.userNotFound(fctx)); } - logger.info("User info retrieved successfully for user", { - flowId: fctx.flowId, - userId, + logDomainEvent({ + event: "user.get_info.succeeded", + fctx, + durationMs: Date.now() - startedAt, + meta: { userId }, }); return okAsync(userData as User); }); @@ -64,9 +76,10 @@ export class UserRepository { fctx, attributes: { "app.user.username": username }, fn: () => { - logger.info("Checking username availability", { - ...fctx, - username, + const startedAt = Date.now(); + logDomainEvent({ + event: "user.username_check.started", + fctx, }); return ResultAsync.fromPromise( @@ -74,8 +87,11 @@ export class UserRepository { where: eq(user.username, username), }), (error) => { - logger.error("Failed to check username availability", { - ...fctx, + logDomainEvent({ + level: "error", + event: "user.username_check.failed", + fctx, + durationMs: Date.now() - startedAt, error, }); return userErrors.usernameCheckFailed( @@ -85,10 +101,11 @@ export class UserRepository { }, ).map((existingUser) => { const isAvailable = !existingUser?.id; - logger.info("Username availability checked", { - ...fctx, - username, - isAvailable, + logDomainEvent({ + event: "user.username_check.succeeded", + fctx, + durationMs: Date.now() - startedAt, + meta: { isAvailable }, }); return isAvailable; }); @@ -105,9 +122,11 @@ export class UserRepository { fctx, attributes: { "app.user.id": userId }, fn: () => { - logger.info("Updating last 2FA verified timestamp for user", { - flowId: fctx.flowId, - userId, + const startedAt = Date.now(); + logDomainEvent({ + event: "user.update_last_2fa.started", + fctx, + meta: { userId }, }); return ResultAsync.fromPromise( @@ -117,25 +136,26 @@ export class UserRepository { .where(eq(user.id, userId)) .execute(), (error) => { - logger.error( - "Failed to update last 2FA verified timestamp", - { - ...fctx, - error, - }, - ); + logDomainEvent({ + level: "error", + event: "user.update_last_2fa.failed", + fctx, + durationMs: Date.now() - startedAt, + error, + meta: { userId }, + }); return userErrors.updateFailed( fctx, error instanceof Error ? error.message : String(error), ); }, ).map(() => { - logger.info( - "Last 2FA verified timestamp updated successfully", - { - ...fctx, - }, - ); + logDomainEvent({ + event: "user.update_last_2fa.succeeded", + fctx, + durationMs: Date.now() - startedAt, + meta: { userId }, + }); return true; }); }, @@ -153,11 +173,15 @@ export class UserRepository { fctx, attributes: { "app.user.id": userId }, fn: () => { - logger.info("Banning user", { - ...fctx, - userId, - banExpiresAt: banExpiresAt.toISOString(), - reason, + const startedAt = Date.now(); + logDomainEvent({ + event: "user.ban.started", + fctx, + meta: { + userId, + reasonLength: reason.length, + banExpiresAt: banExpiresAt.toISOString(), + }, }); return ResultAsync.fromPromise( @@ -171,17 +195,25 @@ export class UserRepository { .where(eq(user.id, userId)) .execute(), (error) => { - logger.error("Failed to ban user", { ...fctx, error }); + logDomainEvent({ + level: "error", + event: "user.ban.failed", + fctx, + durationMs: Date.now() - startedAt, + error, + meta: { userId }, + }); return userErrors.banOperationFailed( fctx, error instanceof Error ? error.message : String(error), ); }, ).map(() => { - logger.info("User has been banned", { - ...fctx, - userId, - banExpiresAt: banExpiresAt.toISOString(), + logDomainEvent({ + event: "user.ban.succeeded", + fctx, + durationMs: Date.now() - startedAt, + meta: { userId }, }); return true; }); @@ -195,7 +227,12 @@ export class UserRepository { fctx, attributes: { "app.user.id": userId }, fn: () => { - logger.info("Checking ban status for user", { ...fctx, userId }); + const startedAt = Date.now(); + logDomainEvent({ + event: "user.is_banned.started", + fctx, + meta: { userId }, + }); return ResultAsync.fromPromise( this.db.query.user.findFirst({ @@ -206,9 +243,13 @@ export class UserRepository { }, }), (error) => { - logger.error("Failed to check ban status", { - ...fctx, + logDomainEvent({ + level: "error", + event: "user.is_banned.failed", + fctx, + durationMs: Date.now() - startedAt, error, + meta: { userId }, }); return userErrors.dbError( fctx, @@ -217,29 +258,39 @@ export class UserRepository { }, ).andThen((userData) => { if (!userData) { - logger.error("User not found when checking ban status", { - ...fctx, + logDomainEvent({ + level: "warn", + event: "user.is_banned.failed", + fctx, + durationMs: Date.now() - startedAt, + error: { code: "NOT_FOUND", message: "User not found" }, + meta: { userId }, }); return errAsync(userErrors.userNotFound(fctx)); } if (!userData.banned) { - logger.info("User is not banned", { ...fctx, userId }); + logDomainEvent({ + event: "user.is_banned.succeeded", + fctx, + durationMs: Date.now() - startedAt, + meta: { userId, isBanned: false }, + }); return okAsync(false); } if (!userData.banExpires) { - logger.info("User is permanently banned", { ...fctx, userId }); + logDomainEvent({ + event: "user.is_banned.succeeded", + fctx, + durationMs: Date.now() - startedAt, + meta: { userId, isBanned: true, isPermanent: true }, + }); return okAsync(true); } const now = new Date(); if (userData.banExpires <= now) { - logger.info("User ban has expired, removing ban status", { - ...fctx, - userId, - }); - return ResultAsync.fromPromise( this.db .update(user) @@ -251,9 +302,13 @@ export class UserRepository { .where(eq(user.id, userId)) .execute(), (error) => { - logger.error("Failed to unban user after expiry", { - ...fctx, + logDomainEvent({ + level: "error", + event: "user.unban_after_expiry.failed", + fctx, + durationMs: Date.now() - startedAt, error, + meta: { userId }, }); return userErrors.unbanFailed( fctx, @@ -264,25 +319,36 @@ export class UserRepository { }, ) .map(() => { - logger.info("User has been unbanned after expiry", { - ...fctx, - userId, + logDomainEvent({ + event: "user.unban_after_expiry.succeeded", + fctx, + durationMs: Date.now() - startedAt, + meta: { userId }, }); return false; }) .orElse((error) => { - logger.error( - "Failed to unban user after expiry, still returning banned status", - { ...fctx, userId, error }, - ); + logDomainEvent({ + level: "warn", + event: "user.is_banned.succeeded", + fctx, + durationMs: Date.now() - startedAt, + error, + meta: { userId, degraded: true, isBanned: true }, + }); return okAsync(true); }); } - logger.info("User is banned", { - ...fctx, - userId, - banExpires: userData.banExpires.toISOString(), + logDomainEvent({ + event: "user.is_banned.succeeded", + fctx, + durationMs: Date.now() - startedAt, + meta: { + userId, + isBanned: true, + banExpires: userData.banExpires.toISOString(), + }, }); return okAsync(true); }); @@ -296,7 +362,12 @@ export class UserRepository { fctx, attributes: { "app.user.id": userId }, fn: () => { - logger.info("Getting ban info for user", { ...fctx, userId }); + const startedAt = Date.now(); + logDomainEvent({ + event: "user.ban_info.started", + fctx, + meta: { userId }, + }); return ResultAsync.fromPromise( this.db.query.user.findFirst({ @@ -304,7 +375,14 @@ export class UserRepository { columns: { banned: true, banReason: true, banExpires: true }, }), (error) => { - logger.error("Failed to get ban info", { ...fctx, error }); + logDomainEvent({ + level: "error", + event: "user.ban_info.failed", + fctx, + durationMs: Date.now() - startedAt, + error, + meta: { userId }, + }); return userErrors.getBanInfoFailed( fctx, error instanceof Error ? error.message : String(error), @@ -312,15 +390,22 @@ export class UserRepository { }, ).andThen((userData) => { if (!userData) { - logger.error("User not found when getting ban info", { - ...fctx, + logDomainEvent({ + level: "warn", + event: "user.ban_info.failed", + fctx, + durationMs: Date.now() - startedAt, + error: { code: "NOT_FOUND", message: "User not found" }, + meta: { userId }, }); return errAsync(userErrors.userNotFound(fctx)); } - logger.info("Ban info retrieved successfully for user", { - ...fctx, - userId, + logDomainEvent({ + event: "user.ban_info.succeeded", + fctx, + durationMs: Date.now() - startedAt, + meta: { userId, banned: userData.banned || false }, }); return okAsync({