levelled up logging, albeit with a bit of verbosity...

This commit is contained in:
user
2026-03-01 04:36:17 +02:00
parent 596dcc78fc
commit 5bf1148a4f
6 changed files with 731 additions and 277 deletions

View File

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

View File

@@ -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({