chore: replace console.log with structured logging (#141)

- Add startup logger (utils/logger.ts) with LOG_LEVEL support
- Add ServiceLogger type for scheduler functions
- Replace all console.log calls with leveled log methods
- Downgrade verbose scheduler info logs to debug level
- Remove unnecessary console.log in auth plugin
This commit is contained in:
Daniel Volz
2026-02-08 22:09:27 +01:00
committed by GitHub
parent ffcd8983b4
commit b07b586eef
8 changed files with 122 additions and 79 deletions
+25 -25
View File
@@ -3,7 +3,7 @@ import { resolve } from "node:path";
import { type Client, createClient } from "@libsql/client";
import dotenv from "dotenv";
import { drizzle } from "drizzle-orm/libsql";
import { log } from "../utils/logger.js";
// Import utilities from db-utils (side-effect-free)
import {
ensureDataDirectory,
@@ -40,34 +40,34 @@ dotenv.config({ path: envPath });
// Use absolute path to ensure it works in Docker
const { dataDir, dbPath, url } = getDbPaths();
console.log(`[DB] Data directory: ${dataDir}`);
console.log(`[DB] Database path: ${dbPath}`);
console.log(`[DB] Database URL: ${url}`);
log.debug(`[DB] Data directory: ${dataDir}`);
log.debug(`[DB] Database path: ${dbPath}`);
log.debug(`[DB] Database URL: ${url}`);
// Ensure data directory exists and is writable
const dirResult = ensureDataDirectory(dataDir);
if (!dirResult.success) {
console.error(`[DB] ERROR: Cannot access data directory: ${dirResult.error}`);
console.error(`[DB] Please ensure the volume mount has correct permissions.`);
console.error(`[DB] Try running on host: sudo chown -R 1000:1000 ${dataDir}`);
log.error(`[DB] ERROR: Cannot access data directory: ${dirResult.error}`);
log.error(`[DB] Please ensure the volume mount has correct permissions.`);
log.error(`[DB] Try running on host: sudo chown -R 1000:1000 ${dataDir}`);
process.exit(1);
} else {
console.log(`[DB] Data directory is writable`);
log.debug(`[DB] Data directory is writable`);
// Log directory stats
const stats = statSync(dataDir);
console.log(`[DB] Directory permissions: ${stats.mode.toString(8)}`);
console.log(`[DB] Directory UID: ${stats.uid}, GID: ${stats.gid}`);
console.log(`[DB] Write test successful`);
log.debug(`[DB] Directory permissions: ${stats.mode.toString(8)}`);
log.debug(`[DB] Directory UID: ${stats.uid}, GID: ${stats.gid}`);
log.debug(`[DB] Write test successful`);
}
let client: Client;
try {
client = createClient({ url });
console.log(`[DB] Database client created successfully`);
log.debug(`[DB] Database client created successfully`);
} catch (err: any) {
console.error(`[DB] ERROR: Failed to create database client: ${err.message}`);
console.error(`[DB] Database path: ${dbPath}`);
log.error(`[DB] ERROR: Failed to create database client: ${err.message}`);
log.error(`[DB] Database path: ${dbPath}`);
process.exit(1);
}
@@ -76,46 +76,46 @@ export const db = drizzle(client);
// Auto-run migrations (self-healing database)
async function runMigrations() {
// Run drizzle-kit generated migrations
console.log(`[DB] Running drizzle migrations...`);
log.info(`[DB] Running migrations...`);
const migrateResult = await runDrizzleMigrations(db);
if (!migrateResult.success) {
console.error(`[DB] Migration error:`, migrateResult.error);
log.error(`[DB] Migration error: ${migrateResult.error}`);
} else if (migrateResult.warning) {
console.log(`[DB] Migration warning:`, migrateResult.warning);
log.warn(`[DB] Migration warning: ${migrateResult.warning}`);
} else {
console.log(`[DB] Drizzle migrations completed`);
log.debug(`[DB] Drizzle migrations completed`);
}
// Run ALTER TABLE migrations for backward compatibility
const alterResult = await runAlterMigrations(client);
if (alterResult.errors.length > 0) {
alterResult.errors.forEach((err) => console.error(`[DB] ALTER migration error:`, err));
alterResult.errors.forEach((err) => log.error(`[DB] ALTER migration error: ${err}`));
}
console.log(`[DB] Tables verified/created`);
log.debug(`[DB] Tables verified/created`);
// Repair dose IDs with trailing hyphens (from frontend takenBy bug)
const trailingResult = await repairTrailingHyphenDoseIds(client);
if (trailingResult.repaired > 0) {
console.log(`[DB] Repaired ${trailingResult.repaired} dose IDs with trailing hyphens`);
log.info(`[DB] Repaired ${trailingResult.repaired} dose IDs with trailing hyphens`);
}
if (trailingResult.errors.length > 0) {
trailingResult.errors.forEach((err) => console.error(`[DB] Trailing-hyphen repair error:`, err));
trailingResult.errors.forEach((err) => log.error(`[DB] Trailing-hyphen repair error: ${err}`));
}
// Repair orphaned dose tracking IDs from past schedule changes
const repairResult = await repairOrphanedDoseIds(client);
if (repairResult.repaired > 0) {
console.log(`[DB] Repaired ${repairResult.repaired} orphaned dose tracking IDs`);
log.info(`[DB] Repaired ${repairResult.repaired} orphaned dose tracking IDs`);
}
if (repairResult.errors.length > 0) {
repairResult.errors.forEach((err) => console.error(`[DB] Dose repair error:`, err));
repairResult.errors.forEach((err) => log.error(`[DB] Dose repair error: ${err}`));
}
// If auth is disabled, ensure a default user exists (ID=1)
const authEnabled = process.env.AUTH_ENABLED === "true";
const created = await ensureDefaultUser(client, authEnabled);
if (created) {
console.log(`[DB] Created default user for auth-disabled mode`);
log.info(`[DB] Created default user for auth-disabled mode`);
}
}
+5 -5
View File
@@ -63,17 +63,17 @@ export function getStatementPreview(stmt: string, maxLength: number = 50): strin
const url = "file:./data/medassist-ng.db";
async function main() {
console.log("Starting database setup...");
console.log("Database URL:", url);
console.log("Migrations folder:", migrationsFolder);
console.log("[DB] Starting database setup...");
console.log("[DB] Database URL:", url);
console.log("[DB] Migrations folder:", migrationsFolder);
const client = createClient({ url });
const db = drizzle(client);
console.log("Running drizzle migrations...");
console.log("[DB] Running drizzle migrations...");
await migrate(db, { migrationsFolder });
console.log("Database setup complete!");
console.log("[DB] Database setup complete!");
process.exit(0);
}
+5 -1
View File
@@ -126,9 +126,11 @@ export async function createApp(options?: {
// Server initialization (runs on import)
// =============================================================================
import { log } from "./utils/logger.js";
// Wait for database migrations before anything else
await migrationsReady;
console.log("[DB] Migrations complete, starting server...");
log.info("[DB] Migrations complete, starting server...");
// Ensure images directory exists
const imagesDir = ensureImagesDirectory();
@@ -197,12 +199,14 @@ const start = async () => {
// Start the automatic reminder scheduler
startReminderScheduler({
info: (msg) => app.log.info(msg),
debug: (msg) => app.log.debug(msg),
error: (msg) => app.log.error(msg),
});
// Start the intake reminder scheduler (checks every minute)
startIntakeReminderScheduler({
info: (msg) => app.log.info(msg),
debug: (msg) => app.log.debug(msg),
error: (msg) => app.log.error(msg),
});
} catch (err) {
-1
View File
@@ -37,7 +37,6 @@ export async function getAnonymousUserId(): Promise<number> {
`);
anonymousUserVerified = true;
console.log(`Created anonymous user with fixed ID ${ANONYMOUS_USER_ID} for no-auth mode`);
return ANONYMOUS_USER_ID;
}
+4 -4
View File
@@ -201,7 +201,7 @@ export async function oidcRoutes(app: FastifyInstance) {
});
// Set cookies (use app's centralized cookie options)
console.log(
request.log.debug(
`[OIDC] Setting cookies for user ${user.username}, NODE_ENV=${env.NODE_ENV}, secure=${app.config.cookieOptions.secure}`
);
setAuthCookies(app, reply, accessToken, refreshToken);
@@ -241,12 +241,12 @@ async function findOrCreateOIDCUser(
if (existingByUsername.authProvider === "local" && !existingByUsername.oidcSubject) {
// Local user exists without SSO - link this OIDC account to existing user
await db.update(users).set({ oidcSubject: oidcSubject }).where(eq(users.id, existingByUsername.id));
console.log(`[OIDC] Linked OIDC to existing local user: ${username}`);
// Linked OIDC to existing local user
return { id: existingByUsername.id, username: existingByUsername.username };
} else if (existingByUsername.oidcSubject && existingByUsername.oidcSubject !== oidcSubject) {
// User already has a DIFFERENT OIDC subject - create new user with suffix
username = `${username}_sso`;
console.log(`[OIDC] Username collision (different OIDC subject), using: ${username}`);
// Username collision (different OIDC subject), use suffixed name
}
}
@@ -268,7 +268,7 @@ async function findOrCreateOIDCUser(
})
.returning({ id: users.id, username: users.username });
console.log(`[OIDC] Created new user: ${newUser.username} (ID: ${newUser.id})`);
// New OIDC user created
return newUser;
}
@@ -7,6 +7,7 @@ import { getDataDir } from "../db/db-utils.js";
import { doseTracking, medications } from "../db/schema.js";
import { getDateLocale, getTranslations, type Language, t } from "../i18n/translations.js";
import { getAllUserSettings, sendShoutrrrNotification, type UserSettings } from "../routes/settings.js";
import type { ServiceLogger } from "../utils/logger.js";
// Import shared utilities
import {
cleanOldIntakeReminders,
@@ -210,21 +211,18 @@ ${tr.intakeReminder.footer}`;
}
}
async function checkAndSendIntakeReminders(logger: {
info: (msg: string) => void;
error: (msg: string) => void;
}): Promise<void> {
logger.info(`[IntakeReminder] Checking for intake reminders...`);
async function checkAndSendIntakeReminders(logger: ServiceLogger): Promise<void> {
logger.debug(`[IntakeReminder] Checking for intake reminders...`);
// Get all user settings to iterate over each user
const allUserSettings = await getAllUserSettings();
if (allUserSettings.length === 0) {
logger.info(`[IntakeReminder] No users with settings found`);
logger.debug(`[IntakeReminder] No users with settings found`);
return; // No users with settings
}
logger.info(`[IntakeReminder] Found ${allUserSettings.length} users to check`);
logger.debug(`[IntakeReminder] Found ${allUserSettings.length} users to check`);
for (const userSettings of allUserSettings) {
await checkAndSendIntakeRemindersForUser(userSettings, logger);
@@ -233,12 +231,12 @@ async function checkAndSendIntakeReminders(logger: {
async function checkAndSendIntakeRemindersForUser(
settings: UserSettings & { userId: number },
logger: { info: (msg: string) => void; error: (msg: string) => void }
logger: ServiceLogger
): Promise<void> {
const language = settings.language;
const tr = getTranslations(language);
logger.info(
logger.debug(
`[IntakeReminder] Checking user ${settings.userId} - repeat:${settings.repeatRemindersEnabled} skip:${settings.skipRemindersForTakenDoses}`
);
@@ -247,13 +245,13 @@ async function checkAndSendIntakeRemindersForUser(
const shoutrrrEnabled = settings.shoutrrrEnabled && settings.shoutrrrUrl && settings.shoutrrrIntakeReminders;
if (!emailEnabled && !shoutrrrEnabled) {
logger.info(
logger.debug(
`[IntakeReminder] User ${settings.userId}: No intake notifications enabled (email:${emailEnabled}, shoutrrr:${shoutrrrEnabled})`
);
return; // No intake reminder notifications enabled for this user
}
logger.info(
logger.debug(
`[IntakeReminder] User ${settings.userId}: Notifications enabled (email:${emailEnabled}, shoutrrr:${shoutrrrEnabled})`
);
@@ -266,11 +264,13 @@ async function checkAndSendIntakeRemindersForUser(
const medsWithReminders = rows.filter((row) => row.intakeRemindersEnabled);
if (medsWithReminders.length === 0) {
logger.info(`[IntakeReminder] User ${settings.userId}: No medications have reminders enabled`);
logger.debug(`[IntakeReminder] User ${settings.userId}: No medications have reminders enabled`);
return; // No medications have reminders enabled for this user
}
logger.info(`[IntakeReminder] User ${settings.userId}: Found ${medsWithReminders.length} medications with reminders`);
logger.debug(
`[IntakeReminder] User ${settings.userId}: Found ${medsWithReminders.length} medications with reminders`
);
const state = loadIntakeReminderState();
const allUpcoming: (UpcomingIntake & { medicationId: number; blisterIndex: number })[] = [];
@@ -285,7 +285,7 @@ async function checkAndSendIntakeRemindersForUser(
const todayEnd = new Date(now.toLocaleString("en-US", { timeZone: tz }));
todayEnd.setHours(23, 59, 59, 999);
logger.info(
logger.debug(
`[IntakeReminder] User ${settings.userId}: Today range: ${todayStart.toISOString()} to ${todayEnd.toISOString()}`
);
@@ -300,7 +300,7 @@ async function checkAndSendIntakeRemindersForUser(
// Medication-level takenBy (for fallback/display purposes)
const medicationTakenBy = parseTakenByJson(med.takenByJson);
logger.info(
logger.debug(
`[IntakeReminder] User ${settings.userId}: Processing medication "${med.name}" with ${intakes.length} intakes`
);
@@ -308,7 +308,7 @@ async function checkAndSendIntakeRemindersForUser(
const intakesWithReminders = intakes.filter((intake, idx) => {
const hasReminder = intake.intakeRemindersEnabled || med.intakeRemindersEnabled;
if (!hasReminder) {
logger.info(`[IntakeReminder] User ${settings.userId}: Intake ${idx} has reminders disabled, skipping`);
logger.debug(`[IntakeReminder] User ${settings.userId}: Intake ${idx} has reminders disabled, skipping`);
}
return hasReminder;
});
@@ -316,7 +316,7 @@ async function checkAndSendIntakeRemindersForUser(
// Process each intake separately to track blisterIndex
intakesWithReminders.forEach((intake, blisterIndex) => {
const actualIndex = intakes.indexOf(intake); // Get the actual index in original array
logger.info(
logger.debug(
`[IntakeReminder] User ${settings.userId}: Intake ${actualIndex} - start: ${intake.start}, every: ${intake.every} days, usage: ${intake.usage}, takenBy: ${intake.takenBy || "(none)"}`
);
@@ -333,7 +333,7 @@ async function checkAndSendIntakeRemindersForUser(
med.id,
med.doseUnit ?? "mg"
);
logger.info(
logger.debug(
`[IntakeReminder] User ${settings.userId}: Intake ${actualIndex} found ${upcomingIntakes.length} upcoming intakes (reminder window)`
);
@@ -358,13 +358,13 @@ async function checkAndSendIntakeRemindersForUser(
med.id,
med.doseUnit ?? "mg"
);
logger.info(
logger.debug(
`[IntakeReminder] User ${settings.userId}: Intake ${actualIndex} - all today's intakes: ${allTodaysIntakes.length}, times: ${allTodaysIntakes.map((i) => i.intakeTime.toISOString()).join(", ")}`
);
const missedIntakes = allTodaysIntakes.filter(
(todayIntake) => todayIntake.intakeTime.getTime() < now.getTime()
);
logger.info(
logger.debug(
`[IntakeReminder] User ${settings.userId}: Intake ${actualIndex} found ${missedIntakes.length} missed intakes (past intake time)`
);
@@ -383,10 +383,10 @@ async function checkAndSendIntakeRemindersForUser(
});
}
logger.info(`[IntakeReminder] User ${settings.userId}: Total ${allUpcoming.length} intakes for today`);
logger.debug(`[IntakeReminder] User ${settings.userId}: Total ${allUpcoming.length} intakes for today`);
if (allUpcoming.length === 0) {
logger.info(`[IntakeReminder] User ${settings.userId}: No intakes for today`);
logger.debug(`[IntakeReminder] User ${settings.userId}: No intakes for today`);
return; // No upcoming intakes for today
}
@@ -419,13 +419,13 @@ async function checkAndSendIntakeRemindersForUser(
sendCount: 0,
advanceSent: false,
};
logger.info(
logger.debug(
`[IntakeReminder] User ${settings.userId}: Seeding state for past "${intake.medName}" at ${intake.intakeTimeStr} (no notification — first detection)`
);
} else {
// Upcoming - this is advance reminder (no counter)
remindersToSend.push({ ...intake, currentSendCount: 0, maxReminders, isAdvanceReminder: true });
logger.info(
logger.debug(
`[IntakeReminder] User ${settings.userId}: Advance reminder for "${intake.medName}" at ${intake.intakeTimeStr}`
);
}
@@ -440,13 +440,13 @@ async function checkAndSendIntakeRemindersForUser(
if (currentNaggingCount >= maxReminders) {
// Max nagging reminders reached - stop
logger.info(
logger.debug(
`[IntakeReminder] User ${settings.userId}: Max nagging (${maxReminders}) reached for "${intake.medName}" at ${intake.intakeTimeStr}`
);
} else if (timeSinceLastReminder >= intervalMs) {
const nextSendCount = currentNaggingCount + 1;
remindersToSend.push({ ...intake, currentSendCount: nextSendCount, maxReminders, isAdvanceReminder: false });
logger.info(
logger.debug(
`[IntakeReminder] User ${settings.userId}: Nagging reminder for "${intake.medName}" at ${intake.intakeTimeStr} (${nextSendCount}/${maxReminders})`
);
}
@@ -486,7 +486,7 @@ async function checkAndSendIntakeRemindersForUser(
const doseId = `${intake.medicationId}-${intake.blisterIndex}-${dateOnlyMs}-${intake.takenBy}`;
const isTaken = takenDoseIds.has(doseId);
if (isTaken) {
logger.info(
logger.debug(
`[IntakeReminder] User ${settings.userId}: Skipping "${intake.medName}" - dose ${doseId} already taken`
);
}
@@ -496,7 +496,7 @@ async function checkAndSendIntakeRemindersForUser(
const doseId = `${intake.medicationId}-${intake.blisterIndex}-${dateOnlyMs}`;
const isTaken = takenDoseIds.has(doseId);
if (isTaken) {
logger.info(
logger.debug(
`[IntakeReminder] User ${settings.userId}: Skipping "${intake.medName}" - dose ${doseId} already taken`
);
}
@@ -505,7 +505,7 @@ async function checkAndSendIntakeRemindersForUser(
});
if (remindersToSend.length === 0) {
logger.info(`[IntakeReminder] User ${settings.userId}: All doses taken, skipping reminders`);
logger.debug(`[IntakeReminder] User ${settings.userId}: All doses taken, skipping reminders`);
return;
}
}
@@ -679,10 +679,7 @@ async function checkAndSendIntakeRemindersForUser(
let intakeCheckInterval: NodeJS.Timeout | null = null;
export function startIntakeReminderScheduler(logger: {
info: (msg: string) => void;
error: (msg: string) => void;
}): void {
export function startIntakeReminderScheduler(logger: ServiceLogger): void {
logger.info(`[IntakeReminder] Starting intake reminder scheduler (checks every minute)...`);
// Run immediately on start
+7 -10
View File
@@ -7,7 +7,7 @@ import { getDataDir } from "../db/db-utils.js";
import { medications, userSettings } from "../db/schema.js";
import { getTranslations, type Language, t } from "../i18n/translations.js";
import { getAllUserSettings, sendShoutrrrNotification, type UserSettings } from "../routes/settings.js";
import type { ServiceLogger } from "../utils/logger.js";
// Import shared utilities
import {
type Blister,
@@ -236,15 +236,12 @@ ${tr.stockReminder.footer}${isRepeatDaily ? `\n\n${tr.stockReminder.repeatDailyN
}
}
async function checkAndSendReminder(logger: {
info: (msg: string) => void;
error: (msg: string) => void;
}): Promise<void> {
async function checkAndSendReminder(logger: ServiceLogger): Promise<void> {
// Get all user settings to iterate over each user
const allUserSettings = await getAllUserSettings();
if (allUserSettings.length === 0) {
logger.info("[Reminder] No users with settings found");
logger.debug("[Reminder] No users with settings found");
return;
}
@@ -255,7 +252,7 @@ async function checkAndSendReminder(logger: {
async function checkAndSendReminderForUser(
settings: UserSettings & { userId: number },
logger: { info: (msg: string) => void; error: (msg: string) => void }
logger: ServiceLogger
): Promise<void> {
const language = settings.language;
const tr = getTranslations(language);
@@ -377,7 +374,7 @@ async function checkAndSendReminderForUser(
let schedulerTimeout: NodeJS.Timeout | null = null;
function scheduleNextCheck(logger: { info: (msg: string) => void; error: (msg: string) => void }): void {
function scheduleNextCheck(logger: ServiceLogger): void {
const msUntilNext = getMsUntilNextCheck(REMINDER_HOUR);
const nextTime = getNextScheduledTime(REMINDER_HOUR);
@@ -388,7 +385,7 @@ function scheduleNextCheck(logger: { info: (msg: string) => void; error: (msg: s
nextScheduledCheck: nextTime.toISOString(),
});
logger.info(
logger.debug(
`[Reminder] Next check scheduled for ${formatInTimezone(nextTime)} (${getTimezone()}) (in ${Math.round(msUntilNext / 1000 / 60)} minutes)`
);
@@ -399,7 +396,7 @@ function scheduleNextCheck(logger: { info: (msg: string) => void; error: (msg: s
}, msUntilNext);
}
export function startReminderScheduler(logger: { info: (msg: string) => void; error: (msg: string) => void }): void {
export function startReminderScheduler(logger: ServiceLogger): void {
logger.info(`[Reminder] Starting reminder scheduler (timezone: ${getTimezone()})...`);
// Check if we need to run immediately (missed today's check)
+46
View File
@@ -0,0 +1,46 @@
/**
* Simple startup logger that respects LOG_LEVEL environment variable.
* Used for code that runs before Fastify is initialized (db/client.ts, migrations).
* Once Fastify is running, use app.log instead.
*/
const LOG_LEVELS: Record<string, number> = {
silent: 60,
fatal: 60,
error: 50,
warn: 40,
info: 30,
debug: 20,
trace: 10,
};
function getLevel(): number {
const envLevel = (process.env.LOG_LEVEL || "info").toLowerCase();
return LOG_LEVELS[envLevel] ?? LOG_LEVELS.info;
}
function shouldLog(level: string): boolean {
return LOG_LEVELS[level] >= getLevel();
}
export const log = {
debug(msg: string): void {
if (shouldLog("debug")) console.log(msg);
},
info(msg: string): void {
if (shouldLog("info")) console.log(msg);
},
warn(msg: string): void {
if (shouldLog("warn")) console.warn(msg);
},
error(msg: string): void {
if (shouldLog("error")) console.error(msg);
},
};
/** Logger interface for services that receive a logger from the caller */
export type ServiceLogger = {
info: (msg: string) => void;
debug: (msg: string) => void;
error: (msg: string) => void;
};