From c1ab0d5f819b4514d969a2e4f078ee53fb0758f9 Mon Sep 17 00:00:00 2001 From: alma Date: Wed, 7 Jan 2026 10:32:42 +0100 Subject: [PATCH] Refactor Logging BIG --- CAPROVER_NGINX_FIX.md | 1 + NGINX_HEADER_SIZE_FIX.md | 1 + app/api/auth/options.ts | 113 ++--- caprover-nginx-template-fixed.conf | 1 + lib/logger.ts | 42 ++ lib/services/email-service.ts | 468 +++++++++++++----- .../notifications/leantime-adapter.ts | 303 ++++++++---- .../notifications/notification-service.ts | 236 ++++++--- nginx-config-fix.conf | 1 + 9 files changed, 827 insertions(+), 339 deletions(-) create mode 100644 lib/logger.ts diff --git a/CAPROVER_NGINX_FIX.md b/CAPROVER_NGINX_FIX.md index 1781503b..76d2b8e4 100644 --- a/CAPROVER_NGINX_FIX.md +++ b/CAPROVER_NGINX_FIX.md @@ -160,3 +160,4 @@ Si vous modifiez le template CapRover directement, **vos modifications seront é **Document créé le** : $(date) **Priorité** : HAUTE - Résout l'erreur 502 + diff --git a/NGINX_HEADER_SIZE_FIX.md b/NGINX_HEADER_SIZE_FIX.md index a87abc53..c66d9fe6 100644 --- a/NGINX_HEADER_SIZE_FIX.md +++ b/NGINX_HEADER_SIZE_FIX.md @@ -153,3 +153,4 @@ Nginx a une limite par défaut de 4KB pour les headers de réponse. Quand Next.j **Document créé le** : $(date) **Priorité** : HAUTE - C'est la cause de l'erreur 502 + diff --git a/app/api/auth/options.ts b/app/api/auth/options.ts index 874cca26..1e3cb0fe 100644 --- a/app/api/auth/options.ts +++ b/app/api/auth/options.ts @@ -1,6 +1,7 @@ import NextAuth, { NextAuthOptions } from "next-auth"; import KeycloakProvider from "next-auth/providers/keycloak"; import { jwtDecode } from "jwt-decode"; +import { logger } from "@/lib/logger"; interface KeycloakProfile { sub: string; @@ -106,7 +107,7 @@ async function refreshAccessToken(token: ExtendedJWT) { errorDescription.includes('Session not active') || errorDescription.includes('Token is not active') || errorDescription.includes('Session expired')) { - console.log("Keycloak session invalidated, marking token for removal"); + logger.info("Keycloak session invalidated, marking token for removal"); // Return token with specific error to trigger session invalidation return { ...token, @@ -120,7 +121,7 @@ async function refreshAccessToken(token: ExtendedJWT) { // Refresh token expiré (inactivité prolongée) if (errorType === 'invalid_grant' && errorDescription.includes('Refresh token expired')) { - console.log("Refresh token expired, user needs to re-authenticate"); + logger.info("Refresh token expired, user needs to re-authenticate"); return { ...token, error: "RefreshTokenExpired", @@ -143,7 +144,10 @@ async function refreshAccessToken(token: ExtendedJWT) { error: undefined, // Clear any previous errors }; } catch (error: any) { - console.error("Error refreshing access token:", error); + logger.error("Error refreshing access token", { + error: error instanceof Error ? error.message : String(error), + errorType: error?.error, + }); // Check if it's an invalid_grant error (session invalidated) if (error?.error === 'invalid_grant' || @@ -184,25 +188,15 @@ export const authOptions: NextAuthOptions = { } }, profile(profile) { - console.log('=== KEYCLOAK PROFILE CALLBACK ==='); - console.log('Profile keys:', Object.keys(profile)); - console.log('Has realm_access:', !!profile.realm_access); - console.log('Has groups:', !!profile.groups); - console.log('Groups:', profile.groups); - // Note: realm_access.roles might not be in ID token // Roles will be extracted from access token in JWT callback const roles = profile.realm_access?.roles || []; - console.log('Profile callback raw roles (from ID token):', roles); // Clean up roles by removing ROLE_ prefix and converting to lowercase - const cleanRoles = roles.map((role: string) => + const cleanRoles = roles.map((role: string) => role.replace(/^ROLE_/, '').toLowerCase() ); - console.log('Profile callback cleaned roles:', cleanRoles); - console.log('==================================='); - return { id: profile.sub, name: profile.name ?? profile.preferred_username, @@ -264,10 +258,6 @@ export const authOptions: NextAuthOptions = { async jwt({ token, account, profile }) { // Initial sign-in: account and profile are present if (account && profile) { - console.log('=== JWT CALLBACK - INITIAL SIGN-IN ==='); - console.log('Has account:', !!account); - console.log('Has profile:', !!profile); - console.log('Has access_token:', !!account.access_token); const keycloakProfile = profile as KeycloakProfile; @@ -278,40 +268,31 @@ export const authOptions: NextAuthOptions = { // First, try to get roles from profile (ID token) - may be empty if (keycloakProfile.realm_access?.roles) { roles = keycloakProfile.realm_access.roles; - console.log('Roles from profile (ID token):', roles); } // If no roles in profile, try to decode access token if (roles.length === 0 && account.access_token) { try { const decodedAccessToken = jwtDecode(account.access_token); - console.log('Decoded access token keys:', Object.keys(decodedAccessToken)); - console.log('Decoded access token realm_access:', decodedAccessToken.realm_access); if (decodedAccessToken.realm_access?.roles) { roles = decodedAccessToken.realm_access.roles; - console.log('✅ Roles extracted from access token:', roles); - } else { - console.log('⚠️ No realm_access.roles in access token'); } } catch (error) { - console.error('❌ Error decoding access token for roles:', error); + logger.error('Error decoding access token for roles', { + error: error instanceof Error ? error.message : String(error), + }); } } // If still no roles, try groups as fallback (some Keycloak configs use groups instead) if (roles.length === 0 && keycloakProfile.groups && Array.isArray(keycloakProfile.groups)) { - console.log('⚠️ No roles found, using groups as fallback:', keycloakProfile.groups); - // Use groups as roles (they might be the actual roles in this Keycloak setup) roles = keycloakProfile.groups; } - const cleanRoles = roles.map((role: string) => + const cleanRoles = roles.map((role: string) => role.replace(/^ROLE_/, '').toLowerCase() ); - - console.log('✅ Final cleaned roles:', cleanRoles); - console.log('====================================='); token.accessToken = account.access_token ?? ''; token.refreshToken = account.refresh_token ?? ''; @@ -327,14 +308,6 @@ export const authOptions: NextAuthOptions = { token.email = keycloakProfile.email ?? null; token.name = keycloakProfile.name ?? keycloakProfile.preferred_username ?? null; - console.log('JWT token populated:', { - hasSub: !!token.sub, - hasEmail: !!token.email, - hasName: !!token.name, - hasUsername: !!token.username, - rolesCount: cleanRoles.length, - }); - // Return immediately on initial sign-in - don't try to refresh tokens we just received return token; } @@ -351,7 +324,9 @@ export const authOptions: NextAuthOptions = { token.role = cleanRoles; } } catch (error) { - console.error('Error decoding token:', error); + logger.error('Error decoding token for roles', { + error: error instanceof Error ? error.message : String(error), + }); } } @@ -404,25 +379,21 @@ export const authOptions: NextAuthOptions = { }, async session({ session, token }) { try { - console.log('=== SESSION CALLBACK START ==='); - console.log('Token error:', token.error); - console.log('Has accessToken:', !!token.accessToken); - console.log('Has refreshToken:', !!token.refreshToken); - console.log('Token role:', token.role); - console.log('Token sub:', token.sub); - console.log('Token email:', token.email); - console.log('Token name:', token.name); - console.log('Token username:', token.username); - + // Minimal structured trace without leaking full token contents + logger.debug('[SESSION_CALLBACK] Start', { + hasError: !!token.error, + hasAccessToken: !!token.accessToken, + hasRefreshToken: !!token.refreshToken, + }); // If session was invalidated or tokens are missing, return null to sign out if (token.error === "SessionNotActive" || token.error === "NoRefreshToken" || !token.accessToken || !token.refreshToken) { - console.log("❌ Session invalidated or tokens missing, user will be signed out", { + logger.info("[SESSION_CALLBACK] Session invalidated or tokens missing, user will be signed out", { error: token.error, hasAccessToken: !!token.accessToken, - hasRefreshToken: !!token.refreshToken + hasRefreshToken: !!token.refreshToken, }); // Return null to make NextAuth treat user as unauthenticated @@ -434,20 +405,17 @@ export const authOptions: NextAuthOptions = { // For other errors, throw to trigger error handling if (token.error) { - console.error("❌ Token error, throwing:", token.error); + logger.error("Token error in session callback", { error: token.error }); throw new Error(token.error as string); } const userRoles = Array.isArray(token.role) ? token.role : []; - console.log('User roles for session:', userRoles); - // Validate required fields if (!token.sub) { - console.error('❌ Missing token.sub (user ID)'); + logger.error('Missing token.sub (user ID) in session callback'); throw new Error('Missing user ID in token'); } - console.log('Creating session user object...'); session.user = { id: token.sub as string, email: (token.email ?? null) as string | null, @@ -460,28 +428,24 @@ export const authOptions: NextAuthOptions = { nextcloudInitialized: false, }; - console.log('Setting session tokens...'); session.accessToken = token.accessToken as string | undefined; session.idToken = token.idToken as string | undefined; session.refreshToken = token.refreshToken as string | undefined; - console.log('✅ Session created successfully'); - console.log('Session user id:', session.user.id); - console.log('Session user email:', session.user.email); - console.log('Session user roles:', session.user.role); - console.log('=== SESSION CALLBACK END ==='); + logger.debug('[SESSION_CALLBACK] Session created', { + userId: session.user.id, + hasEmail: !!session.user.email, + rolesCount: session.user.role.length, + }); return session; } catch (error) { - console.error('❌❌❌ CRITICAL ERROR IN SESSION CALLBACK ❌❌❌'); - console.error('Error type:', error instanceof Error ? error.constructor.name : typeof error); - console.error('Error message:', error instanceof Error ? error.message : String(error)); - console.error('Error stack:', error instanceof Error ? error.stack : 'No stack trace'); - console.error('Token state:', { + logger.error('Critical error in session callback', { + errorType: error instanceof Error ? error.constructor.name : typeof error, + message: error instanceof Error ? error.message : String(error), hasSub: !!token.sub, hasEmail: !!token.email, hasAccessToken: !!token.accessToken, hasRefreshToken: !!token.refreshToken, - role: token.role, }); // Re-throw to let NextAuth handle it throw error; @@ -496,14 +460,15 @@ export const authOptions: NextAuthOptions = { // Add error handling events events: { async signIn({ user, account, profile }) { - console.log('=== NEXTAUTH SIGNIN EVENT ==='); - console.log('User:', user?.id, user?.email); - console.log('Account:', account?.provider); - console.log('Profile:', profile?.sub); + logger.info('[NEXTAUTH] Sign-in event', { + userId: user?.id, + emailPresent: !!user?.email, + provider: account?.provider, + }); // Don't return anything - NextAuth events should return void }, async signOut() { - console.log('=== NEXTAUTH SIGNOUT EVENT ==='); + logger.info('[NEXTAUTH] Sign-out event'); }, // Note: 'error' event doesn't exist in NextAuth EventCallbacks // Errors are handled in callbacks and pages.error diff --git a/caprover-nginx-template-fixed.conf b/caprover-nginx-template-fixed.conf index 6d17e923..4de76e89 100644 --- a/caprover-nginx-template-fixed.conf +++ b/caprover-nginx-template-fixed.conf @@ -134,3 +134,4 @@ server { } } + diff --git a/lib/logger.ts b/lib/logger.ts new file mode 100644 index 00000000..8fdd57b1 --- /dev/null +++ b/lib/logger.ts @@ -0,0 +1,42 @@ +const isProd = process.env.NODE_ENV === 'production'; + +type LogLevel = 'debug' | 'info' | 'warn' | 'error'; + +// Simple environment-aware logger so we can keep useful errors +// while silencing noisy debug logs in production. +export const logger = { + debug: (...args: any[]) => { + if (!isProd) { + console.debug(...args); + } + }, + info: (...args: any[]) => { + if (!isProd) { + console.info(...args); + } + }, + warn: (...args: any[]) => { + // Warnings are generally safe but can be noisy; hide in prod by default. + if (!isProd) { + console.warn(...args); + } + }, + error: (...args: any[]) => { + // Always log errors; callers must avoid passing secrets / full payloads. + console.error(...args); + }, + log: (level: LogLevel, ...args: any[]) => { + switch (level) { + case 'debug': + return logger.debug(...args); + case 'info': + return logger.info(...args); + case 'warn': + return logger.warn(...args); + case 'error': + return logger.error(...args); + } + }, +}; + + diff --git a/lib/services/email-service.ts b/lib/services/email-service.ts index cd85cdd1..f2c2108d 100644 --- a/lib/services/email-service.ts +++ b/lib/services/email-service.ts @@ -23,6 +23,7 @@ import { createXOAuth2Token, refreshAccessToken as refreshMicrosoftAccessToken } import { MailCredentials } from '@prisma/client'; import Redis from 'ioredis'; import { getRedisClient } from '../redis'; +import { logger } from '@/lib/logger'; // Define EmailCredentials interface with OAuth properties interface EmailCredentialsExtended extends EmailCredentials { @@ -82,7 +83,12 @@ setInterval(() => { // If we've been collecting metrics for more than an hour, log and reset if (now - lastMetricsReset > 60 * 60 * 1000) { - console.log(`[IMAP METRICS] Total requests: ${totalConnectionRequests}, New connections: ${totalNewConnections}, Reused: ${totalReuseConnections}, Errors: ${totalConnectionErrors}, Success rate: ${((totalReuseConnections + totalNewConnections) / totalConnectionRequests * 100).toFixed(2)}%`); + logger.debug('[IMAP METRICS] Summary', { + totalRequests: totalConnectionRequests, + newConnections: totalNewConnections, + reusedConnections: totalReuseConnections, + errors: totalConnectionErrors, + }); totalConnectionRequests = 0; totalNewConnections = 0; totalReuseConnections = 0; @@ -121,18 +127,30 @@ setInterval(() => { // Only close connections idle for too long if (now - lastUsed > CONNECTION_TIMEOUT) { - console.log(`Closing idle IMAP connection for ${key} (idle for ${Math.round((now - lastUsed)/1000)}s)`); + logger.debug('[IMAP] Closing idle connection', { + key, + idleSeconds: Math.round((now - lastUsed) / 1000), + }); try { if (connectionPool[key].client.usable) { connectionPool[key].client.logout().catch(err => { - console.error(`Error closing idle connection for ${key}:`, err); + logger.error('[IMAP] Error closing idle connection', { + key, + error: err instanceof Error ? err.message : String(err), + }); }); } } catch (error) { - console.error(`Error checking connection status for ${key}:`, error); + logger.error('[IMAP] Error checking connection status', { + key, + error: error instanceof Error ? error.message : String(error), + }); } finally { delete connectionPool[key]; - console.log(`Removed idle connection for ${key} from pool (pool size: ${Object.keys(connectionPool).length})`); + logger.debug('[IMAP] Removed idle connection from pool', { + key, + poolSize: Object.keys(connectionPool).length, + }); } } }); @@ -146,7 +164,12 @@ setInterval(() => { const connectingCount = connectionKeys.filter(key => connectionPool[key].isConnecting).length; - console.log(`[IMAP POOL] Size: ${connectionKeys.length}, Active: ${activeCount}, Connecting: ${connectingCount}, Max: ${MAX_POOL_SIZE}`); + logger.debug('[IMAP POOL] Status', { + size: connectionKeys.length, + active: activeCount, + connecting: connectingCount, + max: MAX_POOL_SIZE, + }); }, CONNECTION_CHECK_INTERVAL); /** @@ -160,17 +183,23 @@ export async function getImapConnection( const startTime = Date.now(); totalConnectionRequests++; - console.log(`Getting IMAP connection for user ${userId}${accountId ? ` account ${accountId}` : ''}`); + logger.debug('[IMAP] getImapConnection called', { + userId, + accountId: accountId ?? 'default', + }); // Special handling for 'default' accountId - find the first available account if (!accountId || accountId === 'default') { - console.log(`No specific account provided or 'default' requested, trying to find first account for user ${userId}`); + logger.debug('[IMAP] Resolving default accountId', { userId }); // Try getting the account ID from cache to avoid database query const sessionData = await getCachedImapSession(userId); if (sessionData && sessionData.defaultAccountId) { accountId = sessionData.defaultAccountId; - console.log(`Using cached default account ID: ${accountId}`); + logger.debug('[IMAP] Using cached default account ID', { + userId, + accountId, + }); } else { // Query to find all accounts for this user const accounts = await prisma.mailCredentials.findMany({ @@ -181,7 +210,11 @@ export async function getImapConnection( if (accounts && accounts.length > 0) { const firstAccount = accounts[0]; - console.log(`Using first available account: ${firstAccount.id} (${firstAccount.email})`); + logger.debug('[IMAP] Using first available account from DB', { + userId, + accountId: firstAccount.id, + email: firstAccount.email, + }); accountId = firstAccount.id; // Cache default account ID for future use @@ -213,15 +246,21 @@ export async function getImapConnection( // If a connection is being established, wait for it if (connection.isConnecting && connection.connectionPromise) { - console.log(`Connection in progress for ${connectionKey}, waiting for existing connection`); + logger.debug('[IMAP] Waiting for existing connection', { connectionKey }); try { const client = await connection.connectionPromise; connection.lastUsed = Date.now(); totalReuseConnections++; - console.log(`[IMAP] Reused pending connection for ${connectionKey} in ${Date.now() - startTime}ms`); + logger.debug('[IMAP] Reused pending connection', { + connectionKey, + durationMs: Date.now() - startTime, + }); return client; } catch (error) { - console.error(`Error waiting for connection for ${connectionKey}:`, error); + logger.error('[IMAP] Error waiting for existing connection', { + connectionKey, + error: error instanceof Error ? error.message : String(error), + }); // Fall through to create new connection } } @@ -232,40 +271,49 @@ export async function getImapConnection( if (connection.client && connection.client.usable) { // Touch the connection to mark it as recently used connection.lastUsed = Date.now(); - console.log(`Reusing existing IMAP connection for ${connectionKey}`); + logger.debug('[IMAP] Reusing existing connection', { connectionKey }); // Update session data in Redis await updateSessionData(userId, accountId); totalReuseConnections++; - console.log(`[IMAP] Successfully reused connection for ${connectionKey} in ${Date.now() - startTime}ms`); + logger.debug('[IMAP] Successfully reused connection', { + connectionKey, + durationMs: Date.now() - startTime, + }); return connection.client; } else { - console.log(`Existing connection for ${connectionKey} not usable, recreating`); + logger.debug('[IMAP] Existing connection not usable, recreating', { + connectionKey, + }); // Will create a new connection below } } catch (error) { - console.warn(`Error checking existing connection for ${connectionKey}:`, error); + logger.warn('[IMAP] Error checking existing connection', { + connectionKey, + error: error instanceof Error ? error.message : String(error), + }); // Will create a new connection below } } // If we get here, we need a new connection - console.log(`Creating new IMAP connection for ${connectionKey}`); + logger.debug('[IMAP] Creating new connection', { connectionKey }); // First try to get credentials from Redis cache let credentials = await getCachedEmailCredentials(userId, accountId); - console.log(`Retrieved credentials from Redis cache for ${userId}:${accountId}:`, credentials ? { - email: credentials.email, - hasPassword: !!credentials.password, - useOAuth: !!credentials.useOAuth, - hasAccessToken: !!credentials.accessToken, - hasRefreshToken: !!credentials.refreshToken - } : 'No credentials found in cache'); + logger.debug('[IMAP] Retrieved credentials from Redis cache', { + userId, + accountId, + found: !!credentials, + }); // If not in cache, get from database and cache them if (!credentials) { - console.log(`Credentials not found in cache for ${userId}${accountId ? ` account ${accountId}` : ''}, attempting database lookup`); + logger.debug('[IMAP] Credentials not found in cache, querying database', { + userId, + accountId, + }); // Fetch directly from database const dbCredentials = await prisma.mailCredentials.findFirst({ @@ -278,15 +326,19 @@ export async function getImapConnection( }); if (!dbCredentials) { - console.error(`No credentials found for user ${userId}${accountId ? ` account ${accountId}` : ''}`); + logger.error('[IMAP] No credentials found for user', { + userId, + accountId, + }); totalConnectionErrors++; throw new Error('Email account credentials not found'); } - console.log(`Database lookup returned credentials for ${dbCredentials.email}:`, { + logger.debug('[IMAP] Database lookup returned credentials', { + userId, + accountId, email: dbCredentials.email, hasPassword: !!dbCredentials.password, - fields: Object.keys(dbCredentials) }); // Create our credentials object from database data @@ -315,7 +367,9 @@ export async function getImapConnection( // MICROSOFT FIX: Detect Microsoft accounts by hostname and set OAuth flag if (extendedCreds.host === 'outlook.office365.com') { - console.log(`Microsoft account detected (${extendedCreds.email}), setting useOAuth=true`); + logger.debug('[IMAP] Microsoft account detected, enabling OAuth', { + email: extendedCreds.email, + }); extendedCreds.useOAuth = true; // If we have no password but useOAuth is true, we need to make sure refresh token exists in Redis @@ -324,7 +378,9 @@ export async function getImapConnection( try { const cachedCreds = await getCachedEmailCredentials(userId, accountId); if (cachedCreds && cachedCreds.refreshToken) { - console.log(`Found refresh token in Redis for ${extendedCreds.email}, will use it`); + logger.debug('[IMAP] Found refresh token in Redis for account', { + email: extendedCreds.email, + }); extendedCreds.refreshToken = cachedCreds.refreshToken; extendedCreds.accessToken = cachedCreds.accessToken; extendedCreds.tokenExpiry = cachedCreds.tokenExpiry; @@ -332,34 +388,52 @@ export async function getImapConnection( // Make sure we cache these credentials again with the tokens await cacheEmailCredentials(userId, accountId, extendedCreds); } else { - console.warn(`No refresh token found for ${extendedCreds.email} in Redis cache`); + logger.warn('[IMAP] No refresh token found in Redis cache', { + email: extendedCreds.email, + }); } } catch (err) { - console.error(`Error retrieving cached credentials for ${extendedCreds.email}:`, err); + logger.error('[IMAP] Error retrieving cached credentials', { + email: extendedCreds.email, + error: err instanceof Error ? err.message : String(err), + }); } } } // If using OAuth, ensure we have a fresh token if (extendedCreds.useOAuth) { - console.log(`Account is configured to use OAuth`); + logger.debug('[IMAP] Account configured to use OAuth', { + email: extendedCreds.email, + }); if (!extendedCreds.accessToken) { - console.error(`OAuth is enabled but no access token for account ${extendedCreds.email}`); + logger.error('[IMAP] OAuth enabled but no access token', { + email: extendedCreds.email, + }); } try { - console.log(`Ensuring fresh token for OAuth account ${extendedCreds.email}`); + logger.debug('[IMAP] Ensuring fresh token for OAuth account', { + email: extendedCreds.email, + }); const { accessToken, success } = await ensureFreshToken(userId, extendedCreds.email); if (success && accessToken) { extendedCreds.accessToken = accessToken; - console.log(`Successfully refreshed token for ${extendedCreds.email}`); + logger.debug('[IMAP] Successfully refreshed token', { + email: extendedCreds.email, + }); } else { - console.error(`Failed to refresh token for ${extendedCreds.email}`); + logger.error('[IMAP] Failed to refresh token', { + email: extendedCreds.email, + }); } } catch (err) { - console.error(`Error refreshing token for ${extendedCreds.email}:`, err); + logger.error('[IMAP] Error refreshing token', { + email: extendedCreds.email, + error: err instanceof Error ? err.message : String(err), + }); } } @@ -373,7 +447,10 @@ export async function getImapConnection( // PERFORMANCE FIX: Add connection timeout to prevent hanging connections let connectionTimeout: NodeJS.Timeout | null = setTimeout(() => { - console.error(`[IMAP] Connection for ${connectionKey} timed out after 60 seconds`); + logger.error('[IMAP] Connection timed out', { + connectionKey, + timeoutMs: 60000, + }); if (connectionPool[connectionKey]?.isConnecting) { delete connectionPool[connectionKey]; totalConnectionErrors++; @@ -396,11 +473,17 @@ export async function getImapConnection( // Update session data updateSessionData(userId, accountId).catch(err => { - console.error(`Failed to update session data: ${err.message}`); + logger.error('[IMAP] Failed to update session data', { + error: err instanceof Error ? err.message : String(err), + }); }); totalNewConnections++; - console.log(`[IMAP] Created new connection for ${connectionKey} in ${Date.now() - startTime}ms (attempt #${connectionPool[connectionKey].connectionAttempts})`); + logger.debug('[IMAP] Created new connection', { + connectionKey, + durationMs: Date.now() - startTime, + attempts: connectionPool[connectionKey].connectionAttempts, + }); return client; }) .catch(error => { @@ -411,7 +494,10 @@ export async function getImapConnection( } // Handle connection error - console.error(`Failed to create IMAP connection for ${connectionKey}:`, error); + logger.error('[IMAP] Failed to create connection', { + connectionKey, + error: error instanceof Error ? error.message : String(error), + }); delete connectionPool[connectionKey]; totalConnectionErrors++; throw error; @@ -430,7 +516,7 @@ async function createImapConnection(credentials: EmailCredentials, connectionKey // Cast to extended type const extendedCreds = credentials as EmailCredentialsExtended; - console.log(`Creating IMAP connection with credentials:`, { + logger.debug('[IMAP] Creating ImapFlow client with credentials metadata', { email: extendedCreds.email, host: extendedCreds.host, port: extendedCreds.port, @@ -438,14 +524,14 @@ async function createImapConnection(credentials: EmailCredentials, connectionKey useOAuth: !!extendedCreds.useOAuth, hasAccessToken: !!extendedCreds.accessToken, hasRefreshToken: !!extendedCreds.refreshToken, - hasTokenExpiry: !!extendedCreds.tokenExpiry + hasTokenExpiry: !!extendedCreds.tokenExpiry, }); let authParams: any; // Check if we have valid OAuth tokens if (extendedCreds.useOAuth && extendedCreds.accessToken) { - console.log(`Using XOAUTH2 authentication for ${connectionKey} (OAuth enabled)`); + logger.debug('[IMAP] Using XOAUTH2 authentication', { connectionKey }); // Set auth parameters for ImapFlow authParams = { @@ -453,25 +539,29 @@ async function createImapConnection(credentials: EmailCredentials, connectionKey accessToken: extendedCreds.accessToken }; - console.log(`XOAUTH2 auth configured for ${connectionKey}`); + logger.debug('[IMAP] XOAUTH2 auth configured', { connectionKey }); } else if (extendedCreds.password) { // Use regular password authentication - console.log(`Using password authentication for ${connectionKey} (OAuth not enabled or no token)`); + logger.debug('[IMAP] Using password authentication', { connectionKey }); authParams = { user: extendedCreds.email, pass: extendedCreds.password }; } else { // No authentication method available - console.error(`No authentication method found for ${connectionKey}:`, { + logger.error('[IMAP] No authentication method found for connection', { + connectionKey, hasPassword: !!extendedCreds.password, useOAuth: !!extendedCreds.useOAuth, - hasAccessToken: !!extendedCreds.accessToken + hasAccessToken: !!extendedCreds.accessToken, }); throw new Error(`No authentication method available for ${connectionKey} - need either password or OAuth token`); } - console.log(`Creating ImapFlow client for ${connectionKey} with authentication type: ${extendedCreds.useOAuth ? 'OAuth' : 'Password'}`); + logger.debug('[IMAP] Creating ImapFlow client', { + connectionKey, + authType: extendedCreds.useOAuth ? 'OAuth' : 'Password', + }); const client = new ImapFlow({ host: extendedCreds.host, @@ -487,17 +577,26 @@ async function createImapConnection(credentials: EmailCredentials, connectionKey }); try { - console.log(`Connecting to IMAP server: ${extendedCreds.host}:${extendedCreds.port}`); + logger.debug('[IMAP] Connecting to server', { + host: extendedCreds.host, + port: extendedCreds.port, + }); await client.connect(); - console.log(`Successfully connected to IMAP server for ${connectionKey}`); + logger.debug('[IMAP] Connected to server', { connectionKey }); } catch (error) { - console.error(`Failed to connect to IMAP server for ${connectionKey}:`, error); + logger.error('[IMAP] Failed to connect to server', { + connectionKey, + error: error instanceof Error ? error.message : String(error), + }); throw error; } // Add error handler client.on('error', (err) => { - console.error(`IMAP connection error for ${connectionKey}:`, err); + logger.error('[IMAP] Connection error', { + connectionKey, + error: err instanceof Error ? err.message : String(err), + }); // Remove from pool on error if (connectionPool[connectionKey]) { delete connectionPool[connectionKey]; @@ -577,7 +676,10 @@ export async function saveUserEmailCredentials( accountId: string, credentials: EmailCredentials ): Promise { - console.log('Saving credentials for user:', userId, 'account:', accountId); + logger.debug('[EMAIL] Saving credentials for user', { + userId, + accountId, + }); if (!credentials) { throw new Error('No credentials provided'); @@ -615,16 +717,14 @@ export async function saveUserEmailCredentials( }; try { - console.log('Saving credentials to database:', { - ...dbCredentials, - password: dbCredentials.password ? '***' : null, - }); - - console.log('OAuth data will be saved to both Prisma and Redis:', { + logger.debug('[EMAIL] Saving credentials to database', { + userId, + accountId, + email: dbCredentials.email, + hasPassword: !!dbCredentials.password, hasOAuth: !!oauthData.useOAuth, hasAccessToken: !!oauthData.accessToken, hasRefreshToken: !!oauthData.refreshToken, - tokenExpiry: oauthData.tokenExpiry ? new Date(oauthData.tokenExpiry).toISOString() : null }); // Save to database using the unique constraint on [userId, email] @@ -655,9 +755,16 @@ export async function saveUserEmailCredentials( // Cache the full credentials including OAuth tokens await cacheEmailCredentials(userId, accountId, fullCreds); - console.log('Successfully saved credentials to database and cached full data with OAuth tokens'); + logger.debug('[EMAIL] Saved credentials and cached full data', { + userId, + accountId, + }); } catch (error) { - console.error('Error saving credentials:', error); + logger.error('[EMAIL] Error saving credentials', { + userId, + accountId, + error: error instanceof Error ? error.message : String(error), + }); throw error; } } @@ -684,7 +791,14 @@ export async function getEmails( checkOnly: boolean = false ): Promise { // Normalize folder name and handle account ID - console.log(`[getEmails] Processing request for folder: ${folder}, normalized to ${folder}, account: ${accountId || 'default'}, checkOnly: ${checkOnly}`); + logger.debug('[EMAIL] getEmails called', { + userId, + folder, + page, + perPage, + accountId: accountId || 'default', + checkOnly, + }); try { // The getImapConnection function already handles 'default' accountId by finding the first available account @@ -697,7 +811,10 @@ export async function getEmails( // Attempt to select the mailbox try { const mailboxInfo = await client.mailboxOpen(folder); - console.log(`Opened mailbox ${folder} with ${mailboxInfo.exists} messages`); + logger.debug('[EMAIL] Opened mailbox', { + folder, + totalMessages: mailboxInfo.exists, + }); // Get list of all mailboxes for UI const mailboxes = await getMailboxes(client, resolvedAccountId); @@ -737,11 +854,13 @@ export async function getEmails( // If checkOnly mode, we just fetch the most recent email's ID to compare if (checkOnly) { - console.log(`[getEmails] checkOnly mode: fetching only the most recent email ID`); + logger.debug('[EMAIL] getEmails in checkOnly mode', { + folder, + accountId: resolvedAccountId, + }); // Get the most recent message (highest sequence number) const lastMessageSequence = totalEmails.toString(); - console.log(`[getEmails] Fetching latest message with sequence: ${lastMessageSequence}`); const messages = await client.fetch(lastMessageSequence, { uid: true @@ -752,7 +871,11 @@ export async function getEmails( newestEmailId = message.uid; } - console.log(`[getEmails] Latest email UID: ${newestEmailId}`); + logger.debug('[EMAIL] Latest email UID', { + folder, + accountId: resolvedAccountId, + newestEmailId, + }); // Return minimal result with just the newest email ID return { @@ -770,7 +893,12 @@ export async function getEmails( // Calculate message range for pagination const start = Math.max(1, totalEmails - (page * perPage) + 1); const end = Math.max(1, totalEmails - ((page - 1) * perPage)); - console.log(`Fetching messages ${start}:${end} from ${folder} for account ${resolvedAccountId}`); + logger.debug('[EMAIL] Fetching messages range', { + folder, + accountId: resolvedAccountId, + start, + end, + }); // Fetch messages const messages = await client.fetch(`${start}:${end}`, { @@ -849,11 +977,21 @@ export async function getEmails( return result; } catch (error) { - console.error('Error fetching emails:', error); + logger.error('[EMAIL] Error fetching emails (inner)', { + userId, + folder, + accountId: resolvedAccountId, + error: error instanceof Error ? error.message : String(error), + }); throw error; } } catch (error) { - console.error('Error fetching emails:', error); + logger.error('[EMAIL] Error fetching emails (outer)', { + userId, + folder, + accountId: accountId || 'default', + error: error instanceof Error ? error.message : String(error), + }); throw error; } } @@ -904,16 +1042,29 @@ export async function getEmailContent( // Normalize folder name by removing account prefix if present const normalizedFolder = folder.includes(':') ? folder.split(':')[1] : folder; - console.log(`[getEmailContent] Fetching email ${emailId} from folder ${normalizedFolder}, account ${effectiveAccountId}`); + logger.debug('[EMAIL] getEmailContent called', { + userId, + emailId, + folder: normalizedFolder, + accountId: effectiveAccountId, + }); // Use normalized folder name and effective account ID for cache key const cachedEmail = await getCachedEmailContent(userId, effectiveAccountId, emailId); if (cachedEmail) { - console.log(`Using cached email content for ${userId}:${effectiveAccountId}:${emailId}`); + logger.debug('[EMAIL] Using cached email content', { + userId, + accountId: effectiveAccountId, + emailId, + }); return cachedEmail; } - console.log(`Cache miss for email content ${userId}:${effectiveAccountId}:${emailId}, fetching from IMAP`); + logger.debug('[EMAIL] Cache miss for email content, fetching from IMAP', { + userId, + accountId: effectiveAccountId, + emailId, + }); const client = await getImapConnection(userId, effectiveAccountId); @@ -921,7 +1072,11 @@ export async function getEmailContent( await client.mailboxOpen(normalizedFolder); // Log connection details with account context - console.log(`[DEBUG] Fetching email ${emailId} from folder ${normalizedFolder} for account ${effectiveAccountId}`); + logger.debug('[EMAIL] Fetching email from folder', { + emailId, + folder: normalizedFolder, + accountId: effectiveAccountId, + }); // Open mailbox with error handling const mailbox = await client.mailboxOpen(normalizedFolder); @@ -930,13 +1085,22 @@ export async function getEmailContent( } // Log mailbox status with account context - console.log(`[DEBUG] Mailbox ${normalizedFolder} opened for account ${effectiveAccountId}, total messages: ${mailbox.exists}`); + logger.debug('[EMAIL] Mailbox opened', { + folder: normalizedFolder, + accountId: effectiveAccountId, + totalMessages: mailbox.exists, + }); // Get the UIDVALIDITY and UIDNEXT values const uidValidity = mailbox.uidValidity; const uidNext = mailbox.uidNext; - console.log(`[DEBUG] Mailbox UIDVALIDITY: ${uidValidity}, UIDNEXT: ${uidNext} for account ${effectiveAccountId}`); + logger.debug('[EMAIL] Mailbox UID metadata', { + folder: normalizedFolder, + accountId: effectiveAccountId, + uidValidity, + uidNext, + }); // Validate UID exists in mailbox if (numericId >= uidNext) { @@ -950,7 +1114,11 @@ export async function getEmailContent( } const sequenceNumber = searchResult[0]; - console.log(`[DEBUG] Found sequence number ${sequenceNumber} for UID ${numericId} in account ${effectiveAccountId}`); + logger.debug('[EMAIL] Found sequence number for UID', { + accountId: effectiveAccountId, + uid: numericId, + sequenceNumber, + }); // Now fetch using the sequence number with error handling let message; @@ -962,7 +1130,10 @@ export async function getEmailContent( size: true }); } catch (fetchError) { - console.error(`Error fetching message with sequence ${sequenceNumber}:`, fetchError); + logger.error('[EMAIL] Error fetching message by sequence', { + sequenceNumber, + error: fetchError instanceof Error ? fetchError.message : String(fetchError), + }); throw new Error(`Failed to fetch email: ${fetchError instanceof Error ? fetchError.message : 'Unknown error'}`); } @@ -990,7 +1161,10 @@ export async function getEmailContent( keepCidLinks: true }); } catch (parseError) { - console.error(`Error parsing email content for ${emailId}:`, parseError); + logger.error('[EMAIL] Error parsing email content', { + emailId, + error: parseError instanceof Error ? parseError.message : String(parseError), + }); throw new Error(`Failed to parse email content: ${parseError instanceof Error ? parseError.message : 'Unknown error'}`); } @@ -1039,13 +1213,12 @@ export async function getEmailContent( return email; } catch (error) { - console.error('[ERROR] Email fetch failed:', { + logger.error('[EMAIL] Email fetch failed', { userId, emailId, folder: normalizedFolder, accountId: effectiveAccountId, error: error instanceof Error ? error.message : 'Unknown error', - details: error instanceof Error ? error.stack : undefined }); throw error; } finally { @@ -1076,7 +1249,13 @@ export async function markEmailReadStatus( // Normalize folder name by removing account prefix if present const normalizedFolder = folder.includes(':') ? folder.split(':')[1] : folder; - console.log(`[markEmailReadStatus] Marking email ${emailId} as ${isRead ? 'read' : 'unread'} in folder ${normalizedFolder}, account ${effectiveAccountId}`); + logger.debug('[EMAIL] markEmailReadStatus called', { + userId, + emailId, + isRead, + folder: normalizedFolder, + accountId: effectiveAccountId, + }); const client = await getImapConnection(userId, effectiveAccountId); @@ -1097,13 +1276,22 @@ export async function markEmailReadStatus( return true; } catch (error) { - console.error(`Error marking email ${emailId} as ${isRead ? 'read' : 'unread'} in folder ${normalizedFolder}, account ${effectiveAccountId}:`, error); + logger.error('[EMAIL] Error marking email read status', { + userId, + emailId, + isRead, + folder: normalizedFolder, + accountId: effectiveAccountId, + error: error instanceof Error ? error.message : String(error), + }); return false; } finally { try { await client.mailboxClose(); } catch (error) { - console.error('Error closing mailbox:', error); + logger.error('[EMAIL] Error closing mailbox after markEmailReadStatus', { + error: error instanceof Error ? error.message : String(error), + }); } } } @@ -1127,7 +1315,13 @@ export async function toggleEmailFlag( // Normalize folder name by removing account prefix if present const normalizedFolder = folder.includes(':') ? folder.split(':')[1] : folder; - console.log(`[toggleEmailFlag] Marking email ${emailId} as ${flagged ? 'flagged' : 'unflagged'} in folder ${normalizedFolder}, account ${effectiveAccountId}`); + logger.debug('[EMAIL] toggleEmailFlag called', { + userId, + emailId, + flagged, + folder: normalizedFolder, + accountId: effectiveAccountId, + }); const client = await getImapConnection(userId, effectiveAccountId); @@ -1145,13 +1339,22 @@ export async function toggleEmailFlag( return true; } catch (error) { - console.error(`Error toggling flag for email ${emailId} in folder ${normalizedFolder}, account ${effectiveAccountId}:`, error); + logger.error('[EMAIL] Error toggling email flag', { + userId, + emailId, + flagged, + folder: normalizedFolder, + accountId: effectiveAccountId, + error: error instanceof Error ? error.message : String(error), + }); return false; } finally { try { await client.mailboxClose(); } catch (error) { - console.error('Error closing mailbox:', error); + logger.error('[EMAIL] Error closing mailbox after toggleEmailFlag', { + error: error instanceof Error ? error.message : String(error), + }); } } } @@ -1265,7 +1468,9 @@ export async function getMailboxes(client: ImapFlow, accountId?: string): Promis // For backward compatibility, return unprefixed names when no accountId return mailboxes.map(mailbox => mailbox.path); } catch (error) { - console.error('Error fetching mailboxes:', error); + logger.error('[EMAIL] Error fetching mailboxes', { + error: error instanceof Error ? error.message : String(error), + }); // Return empty array on error to avoid showing incorrect folders return []; } @@ -1283,22 +1488,31 @@ export async function testEmailConnection(credentials: EmailCredentials): Promis // Cast to extended type to use OAuth properties const extendedCreds = credentials as EmailCredentialsExtended; - console.log('Testing connection with:', { - ...extendedCreds, - password: extendedCreds.password ? '***' : undefined, - accessToken: extendedCreds.accessToken ? '***' : undefined, - refreshToken: extendedCreds.refreshToken ? '***' : undefined + logger.debug('[EMAIL] Testing connection with credentials metadata', { + email: extendedCreds.email, + host: extendedCreds.host, + port: extendedCreds.port, + hasPassword: !!extendedCreds.password, + useOAuth: !!extendedCreds.useOAuth, + hasAccessToken: !!extendedCreds.accessToken, + hasRefreshToken: !!extendedCreds.refreshToken, }); // Test IMAP connection try { - console.log(`Testing IMAP connection to ${extendedCreds.host}:${extendedCreds.port} for ${extendedCreds.email}`); + logger.debug('[EMAIL] Testing IMAP connection', { + email: extendedCreds.email, + host: extendedCreds.host, + port: extendedCreds.port, + }); // Configure auth based on whether we're using OAuth or password let authParams: any; if (extendedCreds.useOAuth && extendedCreds.accessToken) { - console.log('Using XOAUTH2 authentication mechanism'); + logger.debug('[EMAIL] Using XOAUTH2 authentication mechanism', { + email: extendedCreds.email, + }); // For OAuth, pass the accessToken directly to ImapFlow authParams = { @@ -1306,10 +1520,14 @@ export async function testEmailConnection(credentials: EmailCredentials): Promis accessToken: extendedCreds.accessToken }; - // Log the token length to verify it exists - console.log(`Access token available (length: ${extendedCreds.accessToken.length})`); + // Log the token length to verify it exists (without value) + logger.debug('[EMAIL] Access token present for test', { + email: extendedCreds.email, + }); } else { - console.log('Using password authentication mechanism'); + logger.debug('[EMAIL] Using password authentication mechanism', { + email: extendedCreds.email, + }); authParams = { user: extendedCreds.email, pass: extendedCreds.password @@ -1327,21 +1545,31 @@ export async function testEmailConnection(credentials: EmailCredentials): Promis } }); - console.log('Attempting to connect to IMAP server...'); + logger.debug('[EMAIL] Attempting to connect to IMAP server for test', { + email: extendedCreds.email, + }); await client.connect(); - console.log('IMAP connection successful! Getting mailboxes...'); + logger.debug('[EMAIL] IMAP connection successful! Getting mailboxes...', { + email: extendedCreds.email, + }); const folders = await getMailboxes(client); await client.logout(); - console.log(`IMAP connection successful for ${extendedCreds.email}`); - console.log(`Found ${folders.length} folders:`, folders); + logger.debug('[EMAIL] IMAP connection successful for test', { + email: extendedCreds.email, + folderCount: folders.length, + }); // Test SMTP connection if SMTP settings are provided let smtpSuccess = false; if (extendedCreds.smtp_host && extendedCreds.smtp_port) { try { - console.log(`Testing SMTP connection to ${extendedCreds.smtp_host}:${extendedCreds.smtp_port}`); + logger.debug('[EMAIL] Testing SMTP connection', { + email: extendedCreds.email, + host: extendedCreds.smtp_host, + port: extendedCreds.smtp_port, + }); // Configure SMTP auth based on OAuth or password const smtpAuth = extendedCreds.useOAuth && extendedCreds.accessToken @@ -1366,10 +1594,15 @@ export async function testEmailConnection(credentials: EmailCredentials): Promis } as nodemailer.TransportOptions); await transporter.verify(); - console.log(`SMTP connection successful for ${extendedCreds.email}`); + logger.debug('[EMAIL] SMTP connection successful', { + email: extendedCreds.email, + }); smtpSuccess = true; } catch (smtpError) { - console.error(`SMTP connection failed for ${extendedCreds.email}:`, smtpError); + logger.error('[EMAIL] SMTP connection failed', { + email: extendedCreds.email, + error: smtpError instanceof Error ? smtpError.message : String(smtpError), + }); return { imap: true, smtp: false, @@ -1385,7 +1618,10 @@ export async function testEmailConnection(credentials: EmailCredentials): Promis folders }; } catch (error) { - console.error(`IMAP connection failed for ${extendedCreds.email}:`, error); + logger.error('[EMAIL] IMAP connection failed', { + email: extendedCreds.email, + error: error instanceof Error ? error.message : String(error), + }); return { imap: false, error: `IMAP connection failed: ${error instanceof Error ? error.message : 'Unknown error'}` @@ -1405,7 +1641,9 @@ export async function forceRecacheUserCredentials(userId: string): Promise { - console.log(`[LEANTIME_ADAPTER] getNotifications called for userId: ${userId}, page: ${page}, limit: ${limit}`); + logger.debug('[LEANTIME_ADAPTER] getNotifications called', { + userId, + page, + limit, + }); try { // Get the user's email directly from the session const email = await this.getUserEmail(); - console.log(`[LEANTIME_ADAPTER] Retrieved email from session:`, email || 'null'); if (!email) { - console.error('[LEANTIME_ADAPTER] Could not get user email from session'); + logger.error('[LEANTIME_ADAPTER] Could not get user email from session'); return []; } const leantimeUserId = await this.getLeantimeUserId(email); - console.log(`[LEANTIME_ADAPTER] Retrieved Leantime userId for email ${email}:`, leantimeUserId || 'null'); if (!leantimeUserId) { - console.error('[LEANTIME_ADAPTER] User not found in Leantime:', email); + logger.error('[LEANTIME_ADAPTER] User not found in Leantime', { + emailHash: Buffer.from(email.toLowerCase()).toString('base64').slice(0, 12), + }); return []; } @@ -74,7 +84,6 @@ export class LeantimeAdapter implements NotificationAdapter { const limitEnd = limit; // Make request to Leantime API using the correct jsonrpc method - console.log('[LEANTIME_ADAPTER] Sending request to get all notifications'); const jsonRpcBody = { jsonrpc: '2.0', method: 'leantime.rpc.Notifications.Notifications.getAllNotifications', @@ -87,7 +96,6 @@ export class LeantimeAdapter implements NotificationAdapter { }, id: 1 }; - console.log('[LEANTIME_ADAPTER] Request body:', JSON.stringify(jsonRpcBody)); const response = await fetch(`${this.apiUrl}/api/jsonrpc`, { method: 'POST', @@ -98,55 +106,56 @@ export class LeantimeAdapter implements NotificationAdapter { body: JSON.stringify(jsonRpcBody) }); - console.log('[LEANTIME_ADAPTER] Response status:', response.status); + logger.debug('[LEANTIME_ADAPTER] getNotifications response status', { + status: response.status, + }); if (!response.ok) { const errorText = await response.text(); - console.error('[LEANTIME_ADAPTER] Failed to fetch Leantime notifications:', { + logger.error('[LEANTIME_ADAPTER] Failed to fetch Leantime notifications', { status: response.status, - body: errorText.substring(0, 200) + (errorText.length > 200 ? '...' : '') + bodyPreview: errorText.substring(0, 200), }); return []; } const responseText = await response.text(); - console.log('[LEANTIME_ADAPTER] Raw response (truncated):', responseText.substring(0, 200) + (responseText.length > 200 ? '...' : '')); - const data = JSON.parse(responseText); - console.log('[LEANTIME_ADAPTER] Parsed response data:', { - hasResult: !!data.result, - resultIsArray: Array.isArray(data.result), - resultLength: Array.isArray(data.result) ? data.result.length : 'n/a', - error: data.error - }); if (!data.result || !Array.isArray(data.result)) { if (data.error) { - console.error(`[LEANTIME_ADAPTER] API error: ${data.error.message || JSON.stringify(data.error)}`); + logger.error('[LEANTIME_ADAPTER] API error in getNotifications', { + message: data.error.message, + code: data.error.code, + }); } else { - console.error('[LEANTIME_ADAPTER] Invalid response format from Leantime notifications API'); + logger.error('[LEANTIME_ADAPTER] Invalid response format from Leantime notifications API'); } return []; } const notifications = this.transformNotifications(data.result, userId); - console.log('[LEANTIME_ADAPTER] Transformed notifications count:', notifications.length); + logger.debug('[LEANTIME_ADAPTER] Transformed notifications count', { + count: notifications.length, + }); return notifications; } catch (error) { - console.error('[LEANTIME_ADAPTER] Error fetching Leantime notifications:', error); + logger.error('[LEANTIME_ADAPTER] Error fetching Leantime notifications', { + error: error instanceof Error ? error.message : String(error), + }); return []; } } async getNotificationCount(userId: string): Promise { - console.log(`[LEANTIME_ADAPTER] getNotificationCount called for userId: ${userId}`); + logger.debug('[LEANTIME_ADAPTER] getNotificationCount called', { userId }); try { // Fetch notifications directly from API for accurate counting (bypassing cache) // Fetch up to 1000 notifications to get accurate count const email = await this.getUserEmail(); if (!email) { - console.error('[LEANTIME_ADAPTER] Could not get user email for count'); + logger.error('[LEANTIME_ADAPTER] Could not get user email for count'); return { total: 0, unread: 0, @@ -161,7 +170,7 @@ export class LeantimeAdapter implements NotificationAdapter { const leantimeUserId = await this.getLeantimeUserId(email); if (!leantimeUserId) { - console.error('[LEANTIME_ADAPTER] Could not get Leantime user ID for count'); + logger.error('[LEANTIME_ADAPTER] Could not get Leantime user ID for count'); return { total: 0, unread: 0, @@ -198,7 +207,9 @@ export class LeantimeAdapter implements NotificationAdapter { }); if (!response.ok) { - console.error(`[LEANTIME_ADAPTER] Failed to fetch notifications for count: HTTP ${response.status}`); + logger.error('[LEANTIME_ADAPTER] Failed to fetch notifications for count', { + status: response.status, + }); return { total: 0, unread: 0, @@ -214,7 +225,9 @@ export class LeantimeAdapter implements NotificationAdapter { const data = await response.json(); if (data.error || !Array.isArray(data.result)) { - console.error('[LEANTIME_ADAPTER] Error or invalid response for count:', data.error); + logger.error('[LEANTIME_ADAPTER] Error or invalid response for count', { + error: data.error, + }); return { total: 0, unread: 0, @@ -237,12 +250,10 @@ export class LeantimeAdapter implements NotificationAdapter { const hasMore = totalCount === 1000; // If we got exactly 1000, there might be more - console.log('[LEANTIME_ADAPTER] Notification counts:', { + logger.debug('[LEANTIME_ADAPTER] Notification counts', { total: totalCount, unread: unreadCount, - read: totalCount - unreadCount, hasMore: hasMore, - note: hasMore ? 'WARNING: May have more than 1000 notifications total' : 'OK' }); return { @@ -256,7 +267,9 @@ export class LeantimeAdapter implements NotificationAdapter { } }; } catch (error) { - console.error('[LEANTIME_ADAPTER] Error fetching notification count:', error); + logger.error('[LEANTIME_ADAPTER] Error fetching notification count', { + error: error instanceof Error ? error.message : String(error), + }); return { total: 0, unread: 0, @@ -271,7 +284,10 @@ export class LeantimeAdapter implements NotificationAdapter { } async markAsRead(userId: string, notificationId: string): Promise { - console.log(`[LEANTIME_ADAPTER] markAsRead called for ${notificationId}`); + logger.debug('[LEANTIME_ADAPTER] markAsRead called', { + userId, + notificationId, + }); try { // Extract the source ID from our compound ID @@ -280,13 +296,15 @@ export class LeantimeAdapter implements NotificationAdapter { // Get user email and ID const email = await this.getUserEmail(); if (!email) { - console.error('[LEANTIME_ADAPTER] Could not get user email from session'); + logger.error('[LEANTIME_ADAPTER] Could not get user email from session'); return false; } const leantimeUserId = await this.getLeantimeUserId(email); if (!leantimeUserId) { - console.error('[LEANTIME_ADAPTER] User not found in Leantime:', email); + logger.error('[LEANTIME_ADAPTER] User not found in Leantime', { + emailHash: Buffer.from(email.toLowerCase()).toString('base64').slice(0, 12), + }); return false; } @@ -302,8 +320,6 @@ export class LeantimeAdapter implements NotificationAdapter { id: 1 }; - console.log(`[LEANTIME_ADAPTER] markAsRead - Request body:`, JSON.stringify(jsonRpcBody)); - const response = await fetch(`${this.apiUrl}/api/jsonrpc`, { method: 'POST', headers: { @@ -313,35 +329,45 @@ export class LeantimeAdapter implements NotificationAdapter { body: JSON.stringify(jsonRpcBody) }); - console.log(`[LEANTIME_ADAPTER] markAsRead - Response status: ${response.status}`); + logger.debug('[LEANTIME_ADAPTER] markAsRead response status', { + status: response.status, + }); if (!response.ok) { const errorText = await response.text(); - console.error(`[LEANTIME_ADAPTER] markAsRead - HTTP Error ${response.status}:`, errorText.substring(0, 500)); + logger.error('[LEANTIME_ADAPTER] markAsRead HTTP error', { + status: response.status, + bodyPreview: errorText.substring(0, 200), + }); return false; } const responseText = await response.text(); - console.log(`[LEANTIME_ADAPTER] markAsRead - Response body:`, responseText.substring(0, 200)); let data; try { data = JSON.parse(responseText); } catch (parseError) { - console.error(`[LEANTIME_ADAPTER] markAsRead - Failed to parse response:`, parseError); + logger.error('[LEANTIME_ADAPTER] markAsRead failed to parse response', { + error: parseError instanceof Error ? parseError.message : String(parseError), + }); return false; } if (data.error) { - console.error(`[LEANTIME_ADAPTER] markAsRead - API Error:`, data.error); + logger.error('[LEANTIME_ADAPTER] markAsRead API error', { + error: data.error, + }); return false; } const success = data.result === true || data.result === "true" || !!data.result; - console.log(`[LEANTIME_ADAPTER] markAsRead - Success: ${success}`); + logger.debug('[LEANTIME_ADAPTER] markAsRead success', { success }); return success; } catch (error) { - console.error('[LEANTIME_ADAPTER] Error marking notification as read:', error); + logger.error('[LEANTIME_ADAPTER] Error marking notification as read', { + error: error instanceof Error ? error.message : String(error), + }); return false; } } @@ -349,35 +375,32 @@ export class LeantimeAdapter implements NotificationAdapter { async markAllAsRead(userId: string): Promise { // CRITICAL: This should ALWAYS appear if method is called // Using multiple logging methods to ensure visibility - process.stdout.write(`\n[LEANTIME_ADAPTER] ===== markAllAsRead START =====\n`); - console.log(`[LEANTIME_ADAPTER] ===== markAllAsRead START =====`); - console.error(`[LEANTIME_ADAPTER] ===== markAllAsRead START (via console.error) =====`); - console.log(`[LEANTIME_ADAPTER] markAllAsRead called for userId: ${userId}`); - console.log(`[LEANTIME_ADAPTER] API URL: ${this.apiUrl}`); - console.log(`[LEANTIME_ADAPTER] Has API Token: ${!!this.apiToken}`); + logger.info('[LEANTIME_ADAPTER] markAllAsRead START', { + userId, + hasApiUrl: !!this.apiUrl, + hasApiToken: !!this.apiToken, + }); try { // Get user email and ID const email = await this.getUserEmail(); if (!email) { - console.error('[LEANTIME_ADAPTER] markAllAsRead - Could not get user email from session'); + logger.error('[LEANTIME_ADAPTER] markAllAsRead could not get user email from session'); return false; } - console.log(`[LEANTIME_ADAPTER] markAllAsRead - User email: ${email}`); const leantimeUserId = await this.getLeantimeUserId(email); if (!leantimeUserId) { - console.error('[LEANTIME_ADAPTER] markAllAsRead - User not found in Leantime:', email); + logger.error('[LEANTIME_ADAPTER] markAllAsRead user not found in Leantime', { + emailHash: Buffer.from(email.toLowerCase()).toString('base64').slice(0, 12), + }); return false; } - console.log(`[LEANTIME_ADAPTER] markAllAsRead - Leantime user ID: ${leantimeUserId}`); // Leantime doesn't have a "mark all as read" method, so we need to: // 1. Fetch all unread notifications directly from API (bypassing any cache) // 2. Mark each one individually using markNotificationRead - console.log(`[LEANTIME_ADAPTER] markAllAsRead - Fetching all unread notifications directly from API`); - // Fetch all notifications directly from API (up to 1000) to get fresh data (not cached) const jsonRpcBody = { jsonrpc: '2.0', @@ -392,7 +415,6 @@ export class LeantimeAdapter implements NotificationAdapter { id: 1 }; - console.log(`[LEANTIME_ADAPTER] markAllAsRead - Fetching notifications from API`); const fetchResponse = await fetch(`${this.apiUrl}/api/jsonrpc`, { method: 'POST', headers: { @@ -403,13 +425,17 @@ export class LeantimeAdapter implements NotificationAdapter { }); if (!fetchResponse.ok) { - console.error(`[LEANTIME_ADAPTER] markAllAsRead - Failed to fetch notifications: HTTP ${fetchResponse.status}`); + logger.error('[LEANTIME_ADAPTER] markAllAsRead failed to fetch notifications', { + status: fetchResponse.status, + }); return false; } const fetchData = await fetchResponse.json(); if (fetchData.error) { - console.error(`[LEANTIME_ADAPTER] markAllAsRead - Error fetching notifications:`, fetchData.error); + logger.error('[LEANTIME_ADAPTER] markAllAsRead error fetching notifications', { + error: fetchData.error, + }); return false; } @@ -419,10 +445,13 @@ export class LeantimeAdapter implements NotificationAdapter { .filter((n: any) => n.read === 0 || n.read === false || n.read === '0') .map((n: any) => ({ id: n.id, sourceId: String(n.id) })); - console.log(`[LEANTIME_ADAPTER] markAllAsRead - Found ${unreadNotifications.length} unread notifications to mark (from ${rawNotifications.length} total)`); + logger.info('[LEANTIME_ADAPTER] markAllAsRead unread notifications', { + unreadCount: unreadNotifications.length, + total: rawNotifications.length, + }); if (unreadNotifications.length === 0) { - console.log(`[LEANTIME_ADAPTER] markAllAsRead - No unread notifications, returning success`); + logger.info('[LEANTIME_ADAPTER] markAllAsRead no unread notifications'); return true; } @@ -458,12 +487,20 @@ export class LeantimeAdapter implements NotificationAdapter { }); if (!response.ok) { - console.error(`[LEANTIME_ADAPTER] markAllAsRead - Failed to mark notification ${notificationId}: HTTP ${response.status}`); + logger.error('[LEANTIME_ADAPTER] markAllAsRead failed to mark notification', { + notificationId, + status: response.status, + }); // Retry on server errors (5xx) or rate limiting (429) if ((response.status >= 500 || response.status === 429) && retryCount < MAX_RETRIES) { const delay = Math.min(1000 * Math.pow(2, retryCount), 2000); // Exponential backoff, max 2s - console.log(`[LEANTIME_ADAPTER] Retrying notification ${notificationId} in ${delay}ms (attempt ${retryCount + 1}/${MAX_RETRIES})`); + logger.debug('[LEANTIME_ADAPTER] Retrying notification after HTTP error', { + notificationId, + delay, + attempt: retryCount + 1, + maxRetries: MAX_RETRIES, + }); await new Promise(resolve => setTimeout(resolve, delay)); return markSingleNotification(notificationId, retryCount + 1); } @@ -474,12 +511,20 @@ export class LeantimeAdapter implements NotificationAdapter { const data = await response.json(); if (data.error) { - console.error(`[LEANTIME_ADAPTER] markAllAsRead - Error marking notification ${notificationId}:`, data.error); + logger.error('[LEANTIME_ADAPTER] markAllAsRead JSON-RPC error marking notification', { + notificationId, + error: data.error, + }); // Retry on certain JSON-RPC errors if (retryCount < MAX_RETRIES && (data.error.code === -32603 || data.error.code === -32000)) { const delay = Math.min(1000 * Math.pow(2, retryCount), 2000); - console.log(`[LEANTIME_ADAPTER] Retrying notification ${notificationId} after error in ${delay}ms`); + logger.debug('[LEANTIME_ADAPTER] Retrying notification after JSON-RPC error', { + notificationId, + delay, + attempt: retryCount + 1, + maxRetries: MAX_RETRIES, + }); await new Promise(resolve => setTimeout(resolve, delay)); return markSingleNotification(notificationId, retryCount + 1); } @@ -489,12 +534,20 @@ export class LeantimeAdapter implements NotificationAdapter { return data.result === true || data.result === "true" || !!data.result; } catch (error) { - console.error(`[LEANTIME_ADAPTER] markAllAsRead - Exception marking notification ${notificationId}:`, error); + logger.error('[LEANTIME_ADAPTER] markAllAsRead exception marking notification', { + notificationId, + error: error instanceof Error ? error.message : String(error), + }); // Retry on network errors if (retryCount < MAX_RETRIES && error instanceof Error) { const delay = Math.min(1000 * Math.pow(2, retryCount), 2000); - console.log(`[LEANTIME_ADAPTER] Retrying notification ${notificationId} after network error in ${delay}ms`); + logger.debug('[LEANTIME_ADAPTER] Retrying notification after network error', { + notificationId, + delay, + attempt: retryCount + 1, + maxRetries: MAX_RETRIES, + }); await new Promise(resolve => setTimeout(resolve, delay)); return markSingleNotification(notificationId, retryCount + 1); } @@ -511,7 +564,10 @@ export class LeantimeAdapter implements NotificationAdapter { }) .filter((id: number | null): id is number => id !== null); - console.log(`[LEANTIME_ADAPTER] markAllAsRead - Processing ${notificationIds.length} notifications in batches of ${BATCH_SIZE}`); + logger.info('[LEANTIME_ADAPTER] markAllAsRead processing notifications', { + count: notificationIds.length, + batchSize: BATCH_SIZE, + }); // Split into batches for (let i = 0; i < notificationIds.length; i += BATCH_SIZE) { @@ -519,7 +575,11 @@ export class LeantimeAdapter implements NotificationAdapter { const batchNumber = Math.floor(i / BATCH_SIZE) + 1; const totalBatches = Math.ceil(notificationIds.length / BATCH_SIZE); - console.log(`[LEANTIME_ADAPTER] markAllAsRead - Processing batch ${batchNumber}/${totalBatches} (${batch.length} notifications)`); + logger.debug('[LEANTIME_ADAPTER] markAllAsRead processing batch', { + batchNumber, + totalBatches, + batchSize: batch.length, + }); // Process batch in parallel const batchResults = await Promise.all( @@ -543,7 +603,9 @@ export class LeantimeAdapter implements NotificationAdapter { // Retry failed notifications once more if (failedNotifications.length > 0 && failedNotifications.length < notificationIds.length) { - console.log(`[LEANTIME_ADAPTER] markAllAsRead - Retrying ${failedNotifications.length} failed notifications`); + logger.info('[LEANTIME_ADAPTER] markAllAsRead retrying failed notifications', { + failedCount: failedNotifications.length, + }); const retryResults = await Promise.all( failedNotifications.map(async (notificationId) => { @@ -557,19 +619,25 @@ export class LeantimeAdapter implements NotificationAdapter { ); } - console.log(`[LEANTIME_ADAPTER] markAllAsRead - Final results: ${successCount} succeeded, ${failureCount} failed out of ${notificationIds.length} total`); + logger.info('[LEANTIME_ADAPTER] markAllAsRead final results', { + successCount, + failureCount, + total: notificationIds.length, + }); // Consider it successful if majority were marked (at least 80% success rate) const successRate = notificationIds.length > 0 ? successCount / notificationIds.length : 0; const success = successRate >= 0.8; - console.log(`[LEANTIME_ADAPTER] markAllAsRead - Success rate: ${(successRate * 100).toFixed(1)}%, Overall success: ${success}`); - console.log(`[LEANTIME_ADAPTER] ===== markAllAsRead END (success: ${success}) =====`); + logger.info('[LEANTIME_ADAPTER] markAllAsRead END', { + successRate, + success, + }); return success; } catch (error) { - console.error('[LEANTIME_ADAPTER] markAllAsRead - Exception:', error); - console.error('[LEANTIME_ADAPTER] markAllAsRead - Error stack:', error instanceof Error ? error.stack : 'No stack'); - console.error(`[LEANTIME_ADAPTER] ===== markAllAsRead END (exception) =====`); + logger.error('[LEANTIME_ADAPTER] markAllAsRead exception', { + error: error instanceof Error ? error.message : String(error), + }); return false; } } @@ -634,11 +702,13 @@ export class LeantimeAdapter implements NotificationAdapter { const redis = getRedisClient(); const cachedEmail = await redis.get(emailCacheKey); if (cachedEmail) { - console.log(`[LEANTIME_ADAPTER] Found cached email for user ${userId}`); + logger.debug('[LEANTIME_ADAPTER] Found cached email for user', { userId }); return cachedEmail; } } catch (cacheError) { - console.warn('[LEANTIME_ADAPTER] Error checking email cache, will fetch from session:', cacheError); + logger.warn('[LEANTIME_ADAPTER] Error checking email cache, will fetch from session', { + error: cacheError instanceof Error ? cacheError.message : String(cacheError), + }); } // Get from session @@ -652,14 +722,18 @@ export class LeantimeAdapter implements NotificationAdapter { try { const redis = getRedisClient(); await redis.set(emailCacheKey, email, 'EX', LeantimeAdapter.USER_EMAIL_CACHE_TTL); - console.log(`[LEANTIME_ADAPTER] Cached email for user ${userId} (TTL: ${LeantimeAdapter.USER_EMAIL_CACHE_TTL}s)`); + logger.debug('[LEANTIME_ADAPTER] Cached user email', { userId }); } catch (cacheError) { - console.warn('[LEANTIME_ADAPTER] Failed to cache email (non-fatal):', cacheError); + logger.warn('[LEANTIME_ADAPTER] Failed to cache email (non-fatal)', { + error: cacheError instanceof Error ? cacheError.message : String(cacheError), + }); } return email; } catch (error) { - console.error('[LEANTIME_ADAPTER] Error getting user email from session:', error); + logger.error('[LEANTIME_ADAPTER] Error getting user email from session', { + error: error instanceof Error ? error.message : String(error), + }); return null; } } @@ -671,7 +745,7 @@ export class LeantimeAdapter implements NotificationAdapter { try { if (!this.apiToken) { - console.error('[LEANTIME_ADAPTER] No API token available for getLeantimeUserId'); + logger.error('[LEANTIME_ADAPTER] No API token available for getLeantimeUserId'); return null; } @@ -682,18 +756,27 @@ export class LeantimeAdapter implements NotificationAdapter { if (cachedUserId) { const userId = parseInt(cachedUserId, 10); if (!isNaN(userId)) { - console.log(`[LEANTIME_ADAPTER] Found cached Leantime user ID for ${email}: ${userId}`); + logger.debug('[LEANTIME_ADAPTER] Found cached Leantime user ID', { + emailHash: Buffer.from(email.toLowerCase()).toString('base64').slice(0, 12), + userId, + }); return userId; } } } catch (cacheError) { - console.warn('[LEANTIME_ADAPTER] Error checking cache for user ID, will fetch from API:', cacheError); + logger.warn('[LEANTIME_ADAPTER] Error checking cache for user ID, will fetch from API', { + error: cacheError instanceof Error ? cacheError.message : String(cacheError), + }); } // Fetch from API with retry logic const fetchWithRetry = async (attempt: number): Promise => { try { - console.log(`[LEANTIME_ADAPTER] Fetching Leantime user ID for ${email} (attempt ${attempt + 1}/${MAX_RETRIES + 1})`); + logger.debug('[LEANTIME_ADAPTER] Fetching Leantime user ID', { + emailHash: Buffer.from(email.toLowerCase()).toString('base64').slice(0, 12), + attempt: attempt + 1, + maxRetries: MAX_RETRIES, + }); const response = await fetch(`${this.apiUrl}/api/jsonrpc`, { method: 'POST', @@ -710,12 +793,18 @@ export class LeantimeAdapter implements NotificationAdapter { if (!response.ok) { const errorText = await response.text(); - console.error(`[LEANTIME_ADAPTER] API error (HTTP ${response.status}):`, errorText.substring(0, 200)); + logger.error('[LEANTIME_ADAPTER] User lookup API HTTP error', { + status: response.status, + bodyPreview: errorText.substring(0, 200), + }); // Retry on server errors (5xx) or rate limiting (429) if ((response.status >= 500 || response.status === 429) && attempt < MAX_RETRIES) { const delay = Math.min(1000 * Math.pow(2, attempt), 5000); // Exponential backoff, max 5s - console.log(`[LEANTIME_ADAPTER] Retrying in ${delay}ms...`); + logger.debug('[LEANTIME_ADAPTER] Retrying user lookup after HTTP error', { + attempt: attempt + 1, + delay, + }); await new Promise(resolve => setTimeout(resolve, delay)); return fetchWithRetry(attempt + 1); } @@ -725,11 +814,16 @@ export class LeantimeAdapter implements NotificationAdapter { const data = await response.json(); if (data.error) { - console.error('[LEANTIME_ADAPTER] JSON-RPC error:', data.error); + logger.error('[LEANTIME_ADAPTER] User lookup JSON-RPC error', { + error: data.error, + }); // Retry on certain errors if (attempt < MAX_RETRIES && (data.error.code === -32603 || data.error.code === -32000)) { const delay = Math.min(1000 * Math.pow(2, attempt), 5000); - console.log(`[LEANTIME_ADAPTER] Retrying after error in ${delay}ms...`); + logger.debug('[LEANTIME_ADAPTER] Retrying user lookup after JSON-RPC error', { + attempt: attempt + 1, + delay, + }); await new Promise(resolve => setTimeout(resolve, delay)); return fetchWithRetry(attempt + 1); } @@ -737,7 +831,7 @@ export class LeantimeAdapter implements NotificationAdapter { } if (!data.result || !Array.isArray(data.result)) { - console.error('[LEANTIME_ADAPTER] Invalid response format:', data); + logger.error('[LEANTIME_ADAPTER] Invalid user lookup response format'); return null; } @@ -758,9 +852,14 @@ export class LeantimeAdapter implements NotificationAdapter { try { const redis = getRedisClient(); await redis.set(CACHE_KEY, userId.toString(), 'EX', LeantimeAdapter.USER_ID_CACHE_TTL); - console.log(`[LEANTIME_ADAPTER] Cached Leantime user ID for ${email}: ${userId} (TTL: ${LeantimeAdapter.USER_ID_CACHE_TTL}s)`); + logger.debug('[LEANTIME_ADAPTER] Cached Leantime user ID', { + emailHash: Buffer.from(email.toLowerCase()).toString('base64').slice(0, 12), + userId, + }); } catch (cacheError) { - console.warn('[LEANTIME_ADAPTER] Failed to cache user ID (non-fatal):', cacheError); + logger.warn('[LEANTIME_ADAPTER] Failed to cache user ID (non-fatal)', { + error: cacheError instanceof Error ? cacheError.message : String(cacheError), + }); // Continue even if caching fails } @@ -768,15 +867,23 @@ export class LeantimeAdapter implements NotificationAdapter { } } - console.warn(`[LEANTIME_ADAPTER] User not found in Leantime for email: ${email}`); + logger.warn('[LEANTIME_ADAPTER] User not found in Leantime', { + emailHash: Buffer.from(email.toLowerCase()).toString('base64').slice(0, 12), + }); return null; } catch (error) { - console.error(`[LEANTIME_ADAPTER] Error fetching user ID (attempt ${attempt + 1}):`, error); + logger.error('[LEANTIME_ADAPTER] Error fetching user ID', { + attempt: attempt + 1, + error: error instanceof Error ? error.message : String(error), + }); // Retry on network errors if (attempt < MAX_RETRIES && error instanceof Error) { const delay = Math.min(1000 * Math.pow(2, attempt), 5000); - console.log(`[LEANTIME_ADAPTER] Retrying after network error in ${delay}ms...`); + logger.debug('[LEANTIME_ADAPTER] Retrying user lookup after network error', { + attempt: attempt + 1, + delay, + }); await new Promise(resolve => setTimeout(resolve, delay)); return fetchWithRetry(attempt + 1); } @@ -787,7 +894,9 @@ export class LeantimeAdapter implements NotificationAdapter { return await fetchWithRetry(retryCount); } catch (error) { - console.error('[LEANTIME_ADAPTER] Fatal error getting Leantime user ID:', error); + logger.error('[LEANTIME_ADAPTER] Fatal error getting Leantime user ID', { + error: error instanceof Error ? error.message : String(error), + }); return null; } } diff --git a/lib/services/notifications/notification-service.ts b/lib/services/notifications/notification-service.ts index f0fe0749..3bd26380 100644 --- a/lib/services/notifications/notification-service.ts +++ b/lib/services/notifications/notification-service.ts @@ -2,6 +2,7 @@ import { Notification, NotificationCount } from '@/lib/types/notification'; import { NotificationAdapter } from './notification-adapter.interface'; import { LeantimeAdapter } from './leantime-adapter'; import { getRedisClient } from '@/lib/redis'; +import { logger } from '@/lib/logger'; export class NotificationService { private adapters: Map = new Map(); @@ -17,7 +18,7 @@ export class NotificationService { private static REFRESH_LOCK_TTL = 30; // 30 seconds constructor() { - console.log('[NOTIFICATION_SERVICE] Initializing notification service'); + logger.debug('[NOTIFICATION_SERVICE] Initializing notification service'); // Register adapters this.registerAdapter(new LeantimeAdapter()); @@ -28,7 +29,9 @@ export class NotificationService { // this.registerAdapter(new DolibarrAdapter()); // this.registerAdapter(new MoodleAdapter()); - console.log('[NOTIFICATION_SERVICE] Registered adapters:', Array.from(this.adapters.keys())); + logger.debug('[NOTIFICATION_SERVICE] Registered adapters', { + adapters: Array.from(this.adapters.keys()), + }); } /** @@ -36,7 +39,7 @@ export class NotificationService { */ public static getInstance(): NotificationService { if (!NotificationService.instance) { - console.log('[NOTIFICATION_SERVICE] Creating new notification service instance'); + logger.debug('[NOTIFICATION_SERVICE] Creating new notification service instance'); NotificationService.instance = new NotificationService(); } return NotificationService.instance; @@ -47,14 +50,20 @@ export class NotificationService { */ private registerAdapter(adapter: NotificationAdapter): void { this.adapters.set(adapter.sourceName, adapter); - console.log(`[NOTIFICATION_SERVICE] Registered notification adapter: ${adapter.sourceName}`); + logger.debug('[NOTIFICATION_SERVICE] Registered notification adapter', { + adapter: adapter.sourceName, + }); } /** * Get all notifications for a user from all configured sources */ async getNotifications(userId: string, page = 1, limit = 20): Promise { - console.log(`[NOTIFICATION_SERVICE] getNotifications called for user ${userId}, page ${page}, limit ${limit}`); + logger.debug('[NOTIFICATION_SERVICE] getNotifications called', { + userId, + page, + limit, + }); const redis = getRedisClient(); const cacheKey = NotificationService.NOTIFICATIONS_LIST_CACHE_KEY(userId, page, limit); @@ -62,7 +71,9 @@ export class NotificationService { try { const cachedData = await redis.get(cacheKey); if (cachedData) { - console.log(`[NOTIFICATION_SERVICE] Using cached notifications for user ${userId}`); + logger.debug('[NOTIFICATION_SERVICE] Using cached notifications', { + userId, + }); // Schedule background refresh if TTL is less than half the original value const ttl = await redis.ttl(cacheKey); @@ -78,29 +89,50 @@ export class NotificationService { } // No cached data, fetch from all adapters - console.log(`[NOTIFICATION_SERVICE] Fetching notifications for user ${userId} from ${this.adapters.size} adapters`); + logger.debug('[NOTIFICATION_SERVICE] Fetching notifications from adapters', { + userId, + adapterCount: this.adapters.size, + }); const allNotifications: Notification[] = []; const adapterEntries = Array.from(this.adapters.entries()); - console.log(`[NOTIFICATION_SERVICE] Available adapters: ${adapterEntries.map(([name]) => name).join(', ')}`); + logger.debug('[NOTIFICATION_SERVICE] Available adapters', { + adapters: adapterEntries.map(([name]) => name), + }); const promises = adapterEntries.map(async ([name, adapter]) => { - console.log(`[NOTIFICATION_SERVICE] Checking if adapter ${name} is configured`); + logger.debug('[NOTIFICATION_SERVICE] Checking adapter configuration', { + adapter: name, + }); try { const configured = await adapter.isConfigured(); - console.log(`[NOTIFICATION_SERVICE] Adapter ${name} is configured: ${configured}`); + logger.debug('[NOTIFICATION_SERVICE] Adapter configuration result', { + adapter: name, + configured, + }); if (configured) { - console.log(`[NOTIFICATION_SERVICE] Fetching notifications from ${name} for user ${userId}`); + logger.debug('[NOTIFICATION_SERVICE] Fetching notifications from adapter', { + adapter: name, + userId, + }); const notifications = await adapter.getNotifications(userId, page, limit); - console.log(`[NOTIFICATION_SERVICE] Got ${notifications.length} notifications from ${name}`); + logger.debug('[NOTIFICATION_SERVICE] Adapter notifications fetched', { + adapter: name, + count: notifications.length, + }); return notifications; } else { - console.log(`[NOTIFICATION_SERVICE] Skipping adapter ${name} as it is not configured`); + logger.debug('[NOTIFICATION_SERVICE] Skipping adapter (not configured)', { + adapter: name, + }); return []; } } catch (error) { - console.error(`[NOTIFICATION_SERVICE] Error fetching notifications from ${name}:`, error); + logger.error('[NOTIFICATION_SERVICE] Error fetching notifications from adapter', { + adapter: name, + error: error instanceof Error ? error.message : String(error), + }); return []; } }); @@ -110,13 +142,18 @@ export class NotificationService { // Combine all notifications results.forEach((notifications, index) => { const adapterName = adapterEntries[index][0]; - console.log(`[NOTIFICATION_SERVICE] Adding ${notifications.length} notifications from ${adapterName}`); + logger.debug('[NOTIFICATION_SERVICE] Adding notifications from adapter', { + adapter: adapterName, + count: notifications.length, + }); allNotifications.push(...notifications); }); // Sort by timestamp (newest first) allNotifications.sort((a, b) => b.timestamp.getTime() - a.timestamp.getTime()); - console.log(`[NOTIFICATION_SERVICE] Total notifications after sorting: ${allNotifications.length}`); + logger.debug('[NOTIFICATION_SERVICE] Notifications sorted', { + total: allNotifications.length, + }); // Store in cache try { @@ -126,9 +163,14 @@ export class NotificationService { 'EX', NotificationService.LIST_CACHE_TTL ); - console.log(`[NOTIFICATION_SERVICE] Cached ${allNotifications.length} notifications for user ${userId}`); + logger.debug('[NOTIFICATION_SERVICE] Cached notifications', { + userId, + count: allNotifications.length, + }); } catch (error) { - console.error('[NOTIFICATION_SERVICE] Error caching notifications:', error); + logger.error('[NOTIFICATION_SERVICE] Error caching notifications', { + error: error instanceof Error ? error.message : String(error), + }); } return allNotifications; @@ -138,7 +180,7 @@ export class NotificationService { * Get notification counts for a user */ async getNotificationCount(userId: string): Promise { - console.log(`[NOTIFICATION_SERVICE] getNotificationCount called for user ${userId}`); + logger.debug('[NOTIFICATION_SERVICE] getNotificationCount called', { userId }); const redis = getRedisClient(); const cacheKey = NotificationService.NOTIFICATION_COUNT_CACHE_KEY(userId); @@ -146,7 +188,7 @@ export class NotificationService { try { const cachedData = await redis.get(cacheKey); if (cachedData) { - console.log(`[NOTIFICATION_SERVICE] Using cached notification counts for user ${userId}`); + logger.debug('[NOTIFICATION_SERVICE] Using cached notification counts', { userId }); // Background refresh is now handled by unified refresh system // Cache TTL is aligned with refresh interval (30s) @@ -158,7 +200,10 @@ export class NotificationService { } // No cached data, fetch counts from all adapters - console.log(`[NOTIFICATION_SERVICE] Fetching notification counts for user ${userId} from ${this.adapters.size} adapters`); + logger.debug('[NOTIFICATION_SERVICE] Fetching notification counts from adapters', { + userId, + adapterCount: this.adapters.size, + }); const aggregatedCount: NotificationCount = { total: 0, @@ -167,25 +212,44 @@ export class NotificationService { }; const adapterEntries = Array.from(this.adapters.entries()); - console.log(`[NOTIFICATION_SERVICE] Available adapters for count: ${adapterEntries.map(([name]) => name).join(', ')}`); + logger.debug('[NOTIFICATION_SERVICE] Available adapters for count', { + adapters: adapterEntries.map(([name]) => name), + }); const promises = adapterEntries.map(async ([name, adapter]) => { - console.log(`[NOTIFICATION_SERVICE] Checking if adapter ${name} is configured for count`); + logger.debug('[NOTIFICATION_SERVICE] Checking adapter configuration for count', { + adapter: name, + }); try { const configured = await adapter.isConfigured(); - console.log(`[NOTIFICATION_SERVICE] Adapter ${name} is configured for count: ${configured}`); + logger.debug('[NOTIFICATION_SERVICE] Adapter configuration result for count', { + adapter: name, + configured, + }); if (configured) { - console.log(`[NOTIFICATION_SERVICE] Fetching notification count from ${name} for user ${userId}`); + logger.debug('[NOTIFICATION_SERVICE] Fetching notification count from adapter', { + adapter: name, + userId, + }); const count = await adapter.getNotificationCount(userId); - console.log(`[NOTIFICATION_SERVICE] Got count from ${name}:`, count); + logger.debug('[NOTIFICATION_SERVICE] Adapter count fetched', { + adapter: name, + total: count.total, + unread: count.unread, + }); return count; } else { - console.log(`[NOTIFICATION_SERVICE] Skipping adapter ${name} for count as it is not configured`); + logger.debug('[NOTIFICATION_SERVICE] Skipping adapter for count (not configured)', { + adapter: name, + }); return null; } } catch (error) { - console.error(`[NOTIFICATION_SERVICE] Error fetching notification count from ${name}:`, error); + logger.error('[NOTIFICATION_SERVICE] Error fetching notification count from adapter', { + adapter: name, + error: error instanceof Error ? error.message : String(error), + }); return null; } }); @@ -197,7 +261,11 @@ export class NotificationService { if (!count) return; const adapterName = adapterEntries[index][0]; - console.log(`[NOTIFICATION_SERVICE] Adding counts from ${adapterName}: total=${count.total}, unread=${count.unread}`); + logger.debug('[NOTIFICATION_SERVICE] Adding counts from adapter', { + adapter: adapterName, + total: count.total, + unread: count.unread, + }); aggregatedCount.total += count.total; aggregatedCount.unread += count.unread; @@ -208,7 +276,11 @@ export class NotificationService { }); }); - console.log(`[NOTIFICATION_SERVICE] Aggregated counts for user ${userId}:`, aggregatedCount); + logger.debug('[NOTIFICATION_SERVICE] Aggregated counts', { + userId, + total: aggregatedCount.total, + unread: aggregatedCount.unread, + }); // Store in cache try { @@ -218,9 +290,15 @@ export class NotificationService { 'EX', NotificationService.COUNT_CACHE_TTL ); - console.log(`[NOTIFICATION_SERVICE] Cached notification counts for user ${userId}`); + logger.debug('[NOTIFICATION_SERVICE] Cached notification counts', { + userId, + total: aggregatedCount.total, + unread: aggregatedCount.unread, + }); } catch (error) { - console.error('[NOTIFICATION_SERVICE] Error caching notification counts:', error); + logger.error('[NOTIFICATION_SERVICE] Error caching notification counts', { + error: error instanceof Error ? error.message : String(error), + }); } return aggregatedCount; @@ -235,7 +313,9 @@ export class NotificationService { const sourceId = idParts.join('-'); // Reconstruct the ID in case it has hyphens if (!source || !this.adapters.has(source)) { - console.log(`[NOTIFICATION_SERVICE] markAsRead - Invalid source or adapter not found: ${source}`); + logger.warn('[NOTIFICATION_SERVICE] markAsRead invalid source or adapter not found', { + source, + }); // Still invalidate cache to ensure fresh data await this.invalidateCache(userId); return false; @@ -246,15 +326,24 @@ export class NotificationService { try { success = await adapter.markAsRead(userId, notificationId); - console.log(`[NOTIFICATION_SERVICE] markAsRead - Result: ${success} for notification ${notificationId}`); + logger.debug('[NOTIFICATION_SERVICE] markAsRead result', { + userId, + notificationId, + success, + }); } catch (error) { - console.error(`[NOTIFICATION_SERVICE] markAsRead - Error:`, error); + logger.error('[NOTIFICATION_SERVICE] markAsRead error', { + error: error instanceof Error ? error.message : String(error), + }); success = false; } // Always invalidate cache after marking attempt (even on failure) // This ensures fresh data on next fetch, even if the operation partially failed - console.log(`[NOTIFICATION_SERVICE] markAsRead - Invalidating cache for user ${userId} (success: ${success})`); + logger.debug('[NOTIFICATION_SERVICE] markAsRead invalidating cache', { + userId, + success, + }); await this.invalidateCache(userId); return success; @@ -264,45 +353,67 @@ export class NotificationService { * Mark all notifications from all sources as read */ async markAllAsRead(userId: string): Promise { - console.log(`[NOTIFICATION_SERVICE] markAllAsRead called for user ${userId}`); - console.log(`[NOTIFICATION_SERVICE] Available adapters: ${Array.from(this.adapters.keys()).join(', ')}`); + logger.debug('[NOTIFICATION_SERVICE] markAllAsRead called', { + userId, + adapters: Array.from(this.adapters.keys()), + }); const promises = Array.from(this.adapters.values()) .map(async (adapter) => { const adapterName = adapter.sourceName; - console.log(`[NOTIFICATION_SERVICE] Processing adapter: ${adapterName}`); + logger.debug('[NOTIFICATION_SERVICE] markAllAsRead processing adapter', { + adapter: adapterName, + }); try { const configured = await adapter.isConfigured(); - console.log(`[NOTIFICATION_SERVICE] Adapter ${adapterName} is configured: ${configured}`); + logger.debug('[NOTIFICATION_SERVICE] markAllAsRead adapter configuration', { + adapter: adapterName, + configured, + }); if (!configured) { - console.log(`[NOTIFICATION_SERVICE] Skipping ${adapterName} - not configured`); + logger.debug('[NOTIFICATION_SERVICE] markAllAsRead skipping adapter (not configured)', { + adapter: adapterName, + }); return true; // Not configured, so nothing to mark (treat as success) } - console.log(`[NOTIFICATION_SERVICE] Calling markAllAsRead on adapter ${adapterName}`); + logger.debug('[NOTIFICATION_SERVICE] Calling markAllAsRead on adapter', { + adapter: adapterName, + }); const result = await adapter.markAllAsRead(userId); - console.log(`[NOTIFICATION_SERVICE] Adapter ${adapterName} markAllAsRead result: ${result}`); + logger.debug('[NOTIFICATION_SERVICE] Adapter markAllAsRead result', { + adapter: adapterName, + result, + }); return result; } catch (error) { - console.error(`[NOTIFICATION_SERVICE] Error marking all notifications as read for ${adapterName}:`, error); - console.error(`[NOTIFICATION_SERVICE] Error stack:`, error instanceof Error ? error.stack : 'No stack'); + logger.error('[NOTIFICATION_SERVICE] Error marking all notifications as read for adapter', { + adapter: adapterName, + error: error instanceof Error ? error.message : String(error), + }); return false; } }); const results = await Promise.all(promises); - console.log(`[NOTIFICATION_SERVICE] markAllAsRead results:`, results); - const success = results.every(result => result); const anySuccess = results.some(result => result); - console.log(`[NOTIFICATION_SERVICE] markAllAsRead overall success: ${success}, any success: ${anySuccess}`); + logger.debug('[NOTIFICATION_SERVICE] markAllAsRead results', { + results, + success, + anySuccess, + }); // Always invalidate cache after marking attempt (even on failure) // This ensures fresh data on next fetch, even if the operation failed // The user might have marked some notifications manually, or the operation might have partially succeeded - console.log(`[NOTIFICATION_SERVICE] Invalidating caches for user ${userId} (anySuccess: ${anySuccess}, overallSuccess: ${success})`); + logger.debug('[NOTIFICATION_SERVICE] markAllAsRead invalidating caches', { + userId, + anySuccess, + success, + }); await this.invalidateCache(userId); return success; @@ -333,15 +444,19 @@ export class NotificationService { 100 ); cursor = nextCursor; - + if (keys.length > 0) { await redis.del(...keys); } } while (cursor !== "0"); - console.log(`[NOTIFICATION_SERVICE] Invalidated notification caches for user ${userId}`); + logger.debug('[NOTIFICATION_SERVICE] Invalidated notification caches', { + userId, + }); } catch (error) { - console.error('Error invalidating notification caches:', error); + logger.error('[NOTIFICATION_SERVICE] Error invalidating notification caches', { + error: error instanceof Error ? error.message : String(error), + }); } } @@ -380,12 +495,16 @@ export class NotificationService { // If refreshed in the last minute, skip if (now - lastRefreshTime < 60000) { - console.log(`[NOTIFICATION_SERVICE] Skipping background refresh for user ${userId} - refreshed recently`); + logger.debug('[NOTIFICATION_SERVICE] Skipping background refresh (recently refreshed)', { + userId, + }); return; } } - console.log(`[NOTIFICATION_SERVICE] Background refresh started for user ${userId}`); + logger.debug('[NOTIFICATION_SERVICE] Background refresh started', { + userId, + }); // Set last refresh time await redis.set(refreshKey, Date.now().toString(), 'EX', 120); // 2 minute TTL @@ -394,9 +513,14 @@ export class NotificationService { await this.getNotificationCount(userId); await this.getNotifications(userId, 1, 20); - console.log(`[NOTIFICATION_SERVICE] Background refresh completed for user ${userId}`); + logger.debug('[NOTIFICATION_SERVICE] Background refresh completed', { + userId, + }); } catch (error) { - console.error(`[NOTIFICATION_SERVICE] Background refresh failed for user ${userId}:`, error); + logger.error('[NOTIFICATION_SERVICE] Background refresh failed', { + userId, + error: error instanceof Error ? error.message : String(error), + }); } finally { // Release the lock await redis.del(lockKey).catch(() => {}); diff --git a/nginx-config-fix.conf b/nginx-config-fix.conf index 0eb84564..f4f7e20e 100644 --- a/nginx-config-fix.conf +++ b/nginx-config-fix.conf @@ -30,3 +30,4 @@ server { # ... reste de votre config ... } +