diff --git a/backend/src/db/client.ts b/backend/src/db/client.ts index f62e599..5c85e07 100644 --- a/backend/src/db/client.ts +++ b/backend/src/db/client.ts @@ -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`); } } diff --git a/backend/src/db/migrate.ts b/backend/src/db/migrate.ts index 425f8e9..079026f 100644 --- a/backend/src/db/migrate.ts +++ b/backend/src/db/migrate.ts @@ -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); } diff --git a/backend/src/index.ts b/backend/src/index.ts index 60a0242..3323039 100644 --- a/backend/src/index.ts +++ b/backend/src/index.ts @@ -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) { diff --git a/backend/src/plugins/auth.ts b/backend/src/plugins/auth.ts index a965bec..21626ae 100644 --- a/backend/src/plugins/auth.ts +++ b/backend/src/plugins/auth.ts @@ -37,7 +37,6 @@ export async function getAnonymousUserId(): Promise { `); anonymousUserVerified = true; - console.log(`Created anonymous user with fixed ID ${ANONYMOUS_USER_ID} for no-auth mode`); return ANONYMOUS_USER_ID; } diff --git a/backend/src/routes/oidc.ts b/backend/src/routes/oidc.ts index afad015..a9de5c9 100644 --- a/backend/src/routes/oidc.ts +++ b/backend/src/routes/oidc.ts @@ -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; } diff --git a/backend/src/services/intake-reminder-scheduler.ts b/backend/src/services/intake-reminder-scheduler.ts index cee3569..b0f6775 100644 --- a/backend/src/services/intake-reminder-scheduler.ts +++ b/backend/src/services/intake-reminder-scheduler.ts @@ -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 { - logger.info(`[IntakeReminder] Checking for intake reminders...`); +async function checkAndSendIntakeReminders(logger: ServiceLogger): Promise { + 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 { 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 diff --git a/backend/src/services/reminder-scheduler.ts b/backend/src/services/reminder-scheduler.ts index 7b20e5a..879eeec 100644 --- a/backend/src/services/reminder-scheduler.ts +++ b/backend/src/services/reminder-scheduler.ts @@ -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 { +async function checkAndSendReminder(logger: ServiceLogger): Promise { // 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 { 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) diff --git a/backend/src/utils/logger.ts b/backend/src/utils/logger.ts new file mode 100644 index 0000000..c70ce6e --- /dev/null +++ b/backend/src/utils/logger.ts @@ -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 = { + 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; +};