alma/NeahNew
1
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity

Refactor Logging BIG

Browse Source
This commit is contained in:
alma 2026-01-07 10:32:42 +01:00
parent 0394a77e49
commit c1ab0d5f81
9 changed files with 827 additions and 339 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

1
CAPROVER_NGINX_FIX.md
View File

@ -160,3 +160,4 @@ Si vous modifiez le template CapRover directement, **vos modifications seront é
**Document créé le** : $(date) **Document créé le** : $(date)
**Priorité** : HAUTE - Résout l'erreur 502 **Priorité** : HAUTE - Résout l'erreur 502

1
NGINX_HEADER_SIZE_FIX.md
View File

@ -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) **Document créé le** : $(date)
**Priorité** : HAUTE - C'est la cause de l'erreur 502 **Priorité** : HAUTE - C'est la cause de l'erreur 502

113
app/api/auth/options.ts
View File

@ -1,6 +1,7 @@
import NextAuth, { NextAuthOptions } from "next-auth"; import NextAuth, { NextAuthOptions } from "next-auth";
import KeycloakProvider from "next-auth/providers/keycloak"; import KeycloakProvider from "next-auth/providers/keycloak";
import { jwtDecode } from "jwt-decode"; import { jwtDecode } from "jwt-decode";
import { logger } from "@/lib/logger";
interface KeycloakProfile { interface KeycloakProfile {
sub: string; sub: string;
@ -106,7 +107,7 @@ async function refreshAccessToken(token: ExtendedJWT) {
errorDescription.includes('Session not active') || errorDescription.includes('Session not active') ||
errorDescription.includes('Token is not active') || errorDescription.includes('Token is not active') ||
errorDescription.includes('Session expired')) { 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 with specific error to trigger session invalidation
return { return {
...token, ...token,
@ -120,7 +121,7 @@ async function refreshAccessToken(token: ExtendedJWT) {
// Refresh token expiré (inactivité prolongée) // Refresh token expiré (inactivité prolongée)
if (errorType === 'invalid_grant' && if (errorType === 'invalid_grant' &&
errorDescription.includes('Refresh token expired')) { 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 { return {
...token, ...token,
error: "RefreshTokenExpired", error: "RefreshTokenExpired",
@ -143,7 +144,10 @@ async function refreshAccessToken(token: ExtendedJWT) {
error: undefined, // Clear any previous errors error: undefined, // Clear any previous errors
}; };
} catch (error: any) { } 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) // Check if it's an invalid_grant error (session invalidated)
if (error?.error === 'invalid_grant' || if (error?.error === 'invalid_grant' ||
@ -184,25 +188,15 @@ export const authOptions: NextAuthOptions = {
} }
}, },
profile(profile) { 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 // Note: realm_access.roles might not be in ID token
// Roles will be extracted from access token in JWT callback // Roles will be extracted from access token in JWT callback
const roles = profile.realm_access?.roles || []; 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 // 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() role.replace(/^ROLE_/, '').toLowerCase()
); );
console.log('Profile callback cleaned roles:', cleanRoles);
console.log('===================================');
return { return {
id: profile.sub, id: profile.sub,
name: profile.name ?? profile.preferred_username, name: profile.name ?? profile.preferred_username,
@ -264,10 +258,6 @@ export const authOptions: NextAuthOptions = {
async jwt({ token, account, profile }) { async jwt({ token, account, profile }) {
// Initial sign-in: account and profile are present // Initial sign-in: account and profile are present
if (account && profile) { 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; 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 // First, try to get roles from profile (ID token) - may be empty
if (keycloakProfile.realm_access?.roles) { if (keycloakProfile.realm_access?.roles) {
roles = 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 no roles in profile, try to decode access token
if (roles.length === 0 && account.access_token) { if (roles.length === 0 && account.access_token) {
try { try {
const decodedAccessToken = jwtDecode<DecodedToken>(account.access_token); const decodedAccessToken = jwtDecode<DecodedToken>(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) { if (decodedAccessToken.realm_access?.roles) {
roles = 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) { } 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 still no roles, try groups as fallback (some Keycloak configs use groups instead)
if (roles.length === 0 && keycloakProfile.groups && Array.isArray(keycloakProfile.groups)) { 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; roles = keycloakProfile.groups;
} }
const cleanRoles = roles.map((role: string) => const cleanRoles = roles.map((role: string) =>
role.replace(/^ROLE_/, '').toLowerCase() role.replace(/^ROLE_/, '').toLowerCase()
); );
console.log('✅ Final cleaned roles:', cleanRoles);
console.log('=====================================');
token.accessToken = account.access_token ?? ''; token.accessToken = account.access_token ?? '';
token.refreshToken = account.refresh_token ?? ''; token.refreshToken = account.refresh_token ?? '';
@ -327,14 +308,6 @@ export const authOptions: NextAuthOptions = {
token.email = keycloakProfile.email ?? null; token.email = keycloakProfile.email ?? null;
token.name = keycloakProfile.name ?? keycloakProfile.preferred_username ?? 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 immediately on initial sign-in - don't try to refresh tokens we just received
return token; return token;
} }
@ -351,7 +324,9 @@ export const authOptions: NextAuthOptions = {
token.role = cleanRoles; token.role = cleanRoles;
} }
} catch (error) { } 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 }) { async session({ session, token }) {
try { try {
console.log('=== SESSION CALLBACK START ==='); // Minimal structured trace without leaking full token contents
console.log('Token error:', token.error); logger.debug('[SESSION_CALLBACK] Start', {
console.log('Has accessToken:', !!token.accessToken); hasError: !!token.error,
console.log('Has refreshToken:', !!token.refreshToken); hasAccessToken: !!token.accessToken,
console.log('Token role:', token.role); hasRefreshToken: !!token.refreshToken,
console.log('Token sub:', token.sub); });
console.log('Token email:', token.email);
console.log('Token name:', token.name);
console.log('Token username:', token.username);
// If session was invalidated or tokens are missing, return null to sign out // If session was invalidated or tokens are missing, return null to sign out
if (token.error === "SessionNotActive" || if (token.error === "SessionNotActive" ||
token.error === "NoRefreshToken" || token.error === "NoRefreshToken" ||
!token.accessToken || !token.accessToken ||
!token.refreshToken) { !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, error: token.error,
hasAccessToken: !!token.accessToken, hasAccessToken: !!token.accessToken,
hasRefreshToken: !!token.refreshToken hasRefreshToken: !!token.refreshToken,
}); });
// Return null to make NextAuth treat user as unauthenticated // 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 // For other errors, throw to trigger error handling
if (token.error) { 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); throw new Error(token.error as string);
} }
const userRoles = Array.isArray(token.role) ? token.role : []; const userRoles = Array.isArray(token.role) ? token.role : [];
console.log('User roles for session:', userRoles);
// Validate required fields // Validate required fields
if (!token.sub) { 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'); throw new Error('Missing user ID in token');
} }
console.log('Creating session user object...');
session.user = { session.user = {
id: token.sub as string, id: token.sub as string,
email: (token.email ?? null) as string | null, email: (token.email ?? null) as string | null,
@ -460,28 +428,24 @@ export const authOptions: NextAuthOptions = {
nextcloudInitialized: false, nextcloudInitialized: false,
}; };
console.log('Setting session tokens...');
session.accessToken = token.accessToken as string | undefined; session.accessToken = token.accessToken as string | undefined;
session.idToken = token.idToken as string | undefined; session.idToken = token.idToken as string | undefined;
session.refreshToken = token.refreshToken as string | undefined; session.refreshToken = token.refreshToken as string | undefined;
console.log('✅ Session created successfully'); logger.debug('[SESSION_CALLBACK] Session created', {
console.log('Session user id:', session.user.id); userId: session.user.id,
console.log('Session user email:', session.user.email); hasEmail: !!session.user.email,
console.log('Session user roles:', session.user.role); rolesCount: session.user.role.length,
console.log('=== SESSION CALLBACK END ==='); });
return session; return session;
} catch (error) { } catch (error) {
console.error('❌❌❌ CRITICAL ERROR IN SESSION CALLBACK ❌❌❌'); logger.error('Critical error in session callback', {
console.error('Error type:', error instanceof Error ? error.constructor.name : typeof error); errorType: error instanceof Error ? error.constructor.name : typeof error,
console.error('Error message:', error instanceof Error ? error.message : String(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:', {
hasSub: !!token.sub, hasSub: !!token.sub,
hasEmail: !!token.email, hasEmail: !!token.email,
hasAccessToken: !!token.accessToken, hasAccessToken: !!token.accessToken,
hasRefreshToken: !!token.refreshToken, hasRefreshToken: !!token.refreshToken,
role: token.role,
}); });
// Re-throw to let NextAuth handle it // Re-throw to let NextAuth handle it
throw error; throw error;
@ -496,14 +460,15 @@ export const authOptions: NextAuthOptions = {
// Add error handling events // Add error handling events
events: { events: {
async signIn({ user, account, profile }) { async signIn({ user, account, profile }) {
console.log('=== NEXTAUTH SIGNIN EVENT ==='); logger.info('[NEXTAUTH] Sign-in event', {
console.log('User:', user?.id, user?.email); userId: user?.id,
console.log('Account:', account?.provider); emailPresent: !!user?.email,
console.log('Profile:', profile?.sub); provider: account?.provider,
});
// Don't return anything - NextAuth events should return void // Don't return anything - NextAuth events should return void
}, },
async signOut() { async signOut() {
console.log('=== NEXTAUTH SIGNOUT EVENT ==='); logger.info('[NEXTAUTH] Sign-out event');
}, },
// Note: 'error' event doesn't exist in NextAuth EventCallbacks // Note: 'error' event doesn't exist in NextAuth EventCallbacks
// Errors are handled in callbacks and pages.error // Errors are handled in callbacks and pages.error

1
caprover-nginx-template-fixed.conf
View File

@ -134,3 +134,4 @@ server {
} }
} }

42
lib/logger.ts Normal file
View File

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

468
lib/services/email-service.ts
View File

@ -23,6 +23,7 @@ import { createXOAuth2Token, refreshAccessToken as refreshMicrosoftAccessToken }
import { MailCredentials } from '@prisma/client'; import { MailCredentials } from '@prisma/client';
import Redis from 'ioredis'; import Redis from 'ioredis';
import { getRedisClient } from '../redis'; import { getRedisClient } from '../redis';
import { logger } from '@/lib/logger';
// Define EmailCredentials interface with OAuth properties // Define EmailCredentials interface with OAuth properties
interface EmailCredentialsExtended extends EmailCredentials { interface EmailCredentialsExtended extends EmailCredentials {
@ -82,7 +83,12 @@ setInterval(() => {
// If we've been collecting metrics for more than an hour, log and reset // If we've been collecting metrics for more than an hour, log and reset
if (now - lastMetricsReset > 60 * 60 * 1000) { 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; totalConnectionRequests = 0;
totalNewConnections = 0; totalNewConnections = 0;
totalReuseConnections = 0; totalReuseConnections = 0;
@ -121,18 +127,30 @@ setInterval(() => {
// Only close connections idle for too long // Only close connections idle for too long
if (now - lastUsed > CONNECTION_TIMEOUT) { 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 { try {
if (connectionPool[key].client.usable) { if (connectionPool[key].client.usable) {
connectionPool[key].client.logout().catch(err => { 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) { } 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 { } finally {
delete connectionPool[key]; 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; 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); }, CONNECTION_CHECK_INTERVAL);
/** /**
@ -160,17 +183,23 @@ export async function getImapConnection(
const startTime = Date.now(); const startTime = Date.now();
totalConnectionRequests++; 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 // Special handling for 'default' accountId - find the first available account
if (!accountId || accountId === 'default') { 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 // Try getting the account ID from cache to avoid database query
const sessionData = await getCachedImapSession(userId); const sessionData = await getCachedImapSession(userId);
if (sessionData && sessionData.defaultAccountId) { if (sessionData && sessionData.defaultAccountId) {
accountId = sessionData.defaultAccountId; accountId = sessionData.defaultAccountId;
console.log(`Using cached default account ID: ${accountId}`); logger.debug('[IMAP] Using cached default account ID', {
userId,
accountId,
});
} else { } else {
// Query to find all accounts for this user // Query to find all accounts for this user
const accounts = await prisma.mailCredentials.findMany({ const accounts = await prisma.mailCredentials.findMany({
@ -181,7 +210,11 @@ export async function getImapConnection(
if (accounts && accounts.length > 0) { if (accounts && accounts.length > 0) {
const firstAccount = accounts[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; accountId = firstAccount.id;
// Cache default account ID for future use // 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 a connection is being established, wait for it
if (connection.isConnecting && connection.connectionPromise) { 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 { try {
const client = await connection.connectionPromise; const client = await connection.connectionPromise;
connection.lastUsed = Date.now(); connection.lastUsed = Date.now();
totalReuseConnections++; 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; return client;
} catch (error) { } 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 // Fall through to create new connection
} }
} }
@ -232,40 +271,49 @@ export async function getImapConnection(
if (connection.client && connection.client.usable) { if (connection.client && connection.client.usable) {
// Touch the connection to mark it as recently used // Touch the connection to mark it as recently used
connection.lastUsed = Date.now(); connection.lastUsed = Date.now();
console.log(`Reusing existing IMAP connection for ${connectionKey}`); logger.debug('[IMAP] Reusing existing connection', { connectionKey });
// Update session data in Redis // Update session data in Redis
await updateSessionData(userId, accountId); await updateSessionData(userId, accountId);
totalReuseConnections++; 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; return connection.client;
} else { } 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 // Will create a new connection below
} }
} catch (error) { } 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 // Will create a new connection below
} }
} }
// If we get here, we need a new connection // 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 // First try to get credentials from Redis cache
let credentials = await getCachedEmailCredentials(userId, accountId); let credentials = await getCachedEmailCredentials(userId, accountId);
console.log(`Retrieved credentials from Redis cache for ${userId}:${accountId}:`, credentials ? { logger.debug('[IMAP] Retrieved credentials from Redis cache', {
email: credentials.email, userId,
hasPassword: !!credentials.password, accountId,
useOAuth: !!credentials.useOAuth, found: !!credentials,
hasAccessToken: !!credentials.accessToken, });
hasRefreshToken: !!credentials.refreshToken
} : 'No credentials found in cache');
// If not in cache, get from database and cache them // If not in cache, get from database and cache them
if (!credentials) { 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 // Fetch directly from database
const dbCredentials = await prisma.mailCredentials.findFirst({ const dbCredentials = await prisma.mailCredentials.findFirst({
@ -278,15 +326,19 @@ export async function getImapConnection(
}); });
if (!dbCredentials) { if (!dbCredentials) {
console.error(`No credentials found for user ${userId}${accountId ? ` account ${accountId}` : ''}`); logger.error('[IMAP] No credentials found for user', {
userId,
accountId,
});
totalConnectionErrors++; totalConnectionErrors++;
throw new Error('Email account credentials not found'); 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, email: dbCredentials.email,
hasPassword: !!dbCredentials.password, hasPassword: !!dbCredentials.password,
fields: Object.keys(dbCredentials)
}); });
// Create our credentials object from database data // 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 // MICROSOFT FIX: Detect Microsoft accounts by hostname and set OAuth flag
if (extendedCreds.host === 'outlook.office365.com') { 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; extendedCreds.useOAuth = true;
// If we have no password but useOAuth is true, we need to make sure refresh token exists in Redis // 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 { try {
const cachedCreds = await getCachedEmailCredentials(userId, accountId); const cachedCreds = await getCachedEmailCredentials(userId, accountId);
if (cachedCreds && cachedCreds.refreshToken) { 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.refreshToken = cachedCreds.refreshToken;
extendedCreds.accessToken = cachedCreds.accessToken; extendedCreds.accessToken = cachedCreds.accessToken;
extendedCreds.tokenExpiry = cachedCreds.tokenExpiry; extendedCreds.tokenExpiry = cachedCreds.tokenExpiry;
@ -332,34 +388,52 @@ export async function getImapConnection(
// Make sure we cache these credentials again with the tokens // Make sure we cache these credentials again with the tokens
await cacheEmailCredentials(userId, accountId, extendedCreds); await cacheEmailCredentials(userId, accountId, extendedCreds);
} else { } 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) { } 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 using OAuth, ensure we have a fresh token
if (extendedCreds.useOAuth) { 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) { 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 { 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); const { accessToken, success } = await ensureFreshToken(userId, extendedCreds.email);
if (success && accessToken) { if (success && accessToken) {
extendedCreds.accessToken = accessToken; extendedCreds.accessToken = accessToken;
console.log(`Successfully refreshed token for ${extendedCreds.email}`); logger.debug('[IMAP] Successfully refreshed token', {
email: extendedCreds.email,
});
} else { } else {
console.error(`Failed to refresh token for ${extendedCreds.email}`); logger.error('[IMAP] Failed to refresh token', {
email: extendedCreds.email,
});
} }
} catch (err) { } 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 // PERFORMANCE FIX: Add connection timeout to prevent hanging connections
let connectionTimeout: NodeJS.Timeout | null = setTimeout(() => { 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) { if (connectionPool[connectionKey]?.isConnecting) {
delete connectionPool[connectionKey]; delete connectionPool[connectionKey];
totalConnectionErrors++; totalConnectionErrors++;
@ -396,11 +473,17 @@ export async function getImapConnection(
// Update session data // Update session data
updateSessionData(userId, accountId).catch(err => { 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++; 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; return client;
}) })
.catch(error => { .catch(error => {
@ -411,7 +494,10 @@ export async function getImapConnection(
} }
// Handle connection error // 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]; delete connectionPool[connectionKey];
totalConnectionErrors++; totalConnectionErrors++;
throw error; throw error;
@ -430,7 +516,7 @@ async function createImapConnection(credentials: EmailCredentials, connectionKey
// Cast to extended type // Cast to extended type
const extendedCreds = credentials as EmailCredentialsExtended; const extendedCreds = credentials as EmailCredentialsExtended;
console.log(`Creating IMAP connection with credentials:`, { logger.debug('[IMAP] Creating ImapFlow client with credentials metadata', {
email: extendedCreds.email, email: extendedCreds.email,
host: extendedCreds.host, host: extendedCreds.host,
port: extendedCreds.port, port: extendedCreds.port,
@ -438,14 +524,14 @@ async function createImapConnection(credentials: EmailCredentials, connectionKey
useOAuth: !!extendedCreds.useOAuth, useOAuth: !!extendedCreds.useOAuth,
hasAccessToken: !!extendedCreds.accessToken, hasAccessToken: !!extendedCreds.accessToken,
hasRefreshToken: !!extendedCreds.refreshToken, hasRefreshToken: !!extendedCreds.refreshToken,
hasTokenExpiry: !!extendedCreds.tokenExpiry hasTokenExpiry: !!extendedCreds.tokenExpiry,
}); });
let authParams: any; let authParams: any;
// Check if we have valid OAuth tokens // Check if we have valid OAuth tokens
if (extendedCreds.useOAuth && extendedCreds.accessToken) { 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 // Set auth parameters for ImapFlow
authParams = { authParams = {
@ -453,25 +539,29 @@ async function createImapConnection(credentials: EmailCredentials, connectionKey
accessToken: extendedCreds.accessToken accessToken: extendedCreds.accessToken
}; };
console.log(`XOAUTH2 auth configured for ${connectionKey}`); logger.debug('[IMAP] XOAUTH2 auth configured', { connectionKey });
} else if (extendedCreds.password) { } else if (extendedCreds.password) {
// Use regular password authentication // 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 = { authParams = {
user: extendedCreds.email, user: extendedCreds.email,
pass: extendedCreds.password pass: extendedCreds.password
}; };
} else { } else {
// No authentication method available // 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, hasPassword: !!extendedCreds.password,
useOAuth: !!extendedCreds.useOAuth, useOAuth: !!extendedCreds.useOAuth,
hasAccessToken: !!extendedCreds.accessToken hasAccessToken: !!extendedCreds.accessToken,
}); });
throw new Error(`No authentication method available for ${connectionKey} - need either password or OAuth token`); 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({ const client = new ImapFlow({
host: extendedCreds.host, host: extendedCreds.host,
@ -487,17 +577,26 @@ async function createImapConnection(credentials: EmailCredentials, connectionKey
}); });
try { 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(); await client.connect();
console.log(`Successfully connected to IMAP server for ${connectionKey}`); logger.debug('[IMAP] Connected to server', { connectionKey });
} catch (error) { } 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; throw error;
} }
// Add error handler // Add error handler
client.on('error', (err) => { 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 // Remove from pool on error
if (connectionPool[connectionKey]) { if (connectionPool[connectionKey]) {
delete connectionPool[connectionKey]; delete connectionPool[connectionKey];
@ -577,7 +676,10 @@ export async function saveUserEmailCredentials(
accountId: string, accountId: string,
credentials: EmailCredentials credentials: EmailCredentials
): Promise<void> { ): Promise<void> {
console.log('Saving credentials for user:', userId, 'account:', accountId); logger.debug('[EMAIL] Saving credentials for user', {
userId,
accountId,
});
if (!credentials) { if (!credentials) {
throw new Error('No credentials provided'); throw new Error('No credentials provided');
@ -615,16 +717,14 @@ export async function saveUserEmailCredentials(
}; };
try { try {
console.log('Saving credentials to database:', { logger.debug('[EMAIL] Saving credentials to database', {
...dbCredentials, userId,
password: dbCredentials.password ? '***' : null, accountId,
}); email: dbCredentials.email,
hasPassword: !!dbCredentials.password,
console.log('OAuth data will be saved to both Prisma and Redis:', {
hasOAuth: !!oauthData.useOAuth, hasOAuth: !!oauthData.useOAuth,
hasAccessToken: !!oauthData.accessToken, hasAccessToken: !!oauthData.accessToken,
hasRefreshToken: !!oauthData.refreshToken, hasRefreshToken: !!oauthData.refreshToken,
tokenExpiry: oauthData.tokenExpiry ? new Date(oauthData.tokenExpiry).toISOString() : null
}); });
// Save to database using the unique constraint on [userId, email] // 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 // Cache the full credentials including OAuth tokens
await cacheEmailCredentials(userId, accountId, fullCreds); 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) { } 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; throw error;
} }
} }
@ -684,7 +791,14 @@ export async function getEmails(
checkOnly: boolean = false checkOnly: boolean = false
): Promise<EmailListResult> { ): Promise<EmailListResult> {
// Normalize folder name and handle account ID // 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 { try {
// The getImapConnection function already handles 'default' accountId by finding the first available account // 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 // Attempt to select the mailbox
try { try {
const mailboxInfo = await client.mailboxOpen(folder); 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 // Get list of all mailboxes for UI
const mailboxes = await getMailboxes(client, resolvedAccountId); 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 mode, we just fetch the most recent email's ID to compare
if (checkOnly) { 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) // Get the most recent message (highest sequence number)
const lastMessageSequence = totalEmails.toString(); const lastMessageSequence = totalEmails.toString();
console.log(`[getEmails] Fetching latest message with sequence: ${lastMessageSequence}`);
const messages = await client.fetch(lastMessageSequence, { const messages = await client.fetch(lastMessageSequence, {
uid: true uid: true
@ -752,7 +871,11 @@ export async function getEmails(
newestEmailId = message.uid; 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 minimal result with just the newest email ID
return { return {
@ -770,7 +893,12 @@ export async function getEmails(
// Calculate message range for pagination // Calculate message range for pagination
const start = Math.max(1, totalEmails - (page * perPage) + 1); const start = Math.max(1, totalEmails - (page * perPage) + 1);
const end = Math.max(1, totalEmails - ((page - 1) * perPage)); 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 // Fetch messages
const messages = await client.fetch(`${start}:${end}`, { const messages = await client.fetch(`${start}:${end}`, {
@ -849,11 +977,21 @@ export async function getEmails(
return result; return result;
} catch (error) { } 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; throw error;
} }
} catch (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; throw error;
} }
} }
@ -904,16 +1042,29 @@ export async function getEmailContent(
// Normalize folder name by removing account prefix if present // Normalize folder name by removing account prefix if present
const normalizedFolder = folder.includes(':') ? folder.split(':')[1] : folder; 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 // Use normalized folder name and effective account ID for cache key
const cachedEmail = await getCachedEmailContent(userId, effectiveAccountId, emailId); const cachedEmail = await getCachedEmailContent(userId, effectiveAccountId, emailId);
if (cachedEmail) { 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; 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); const client = await getImapConnection(userId, effectiveAccountId);
@ -921,7 +1072,11 @@ export async function getEmailContent(
await client.mailboxOpen(normalizedFolder); await client.mailboxOpen(normalizedFolder);
// Log connection details with account context // 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 // Open mailbox with error handling
const mailbox = await client.mailboxOpen(normalizedFolder); const mailbox = await client.mailboxOpen(normalizedFolder);
@ -930,13 +1085,22 @@ export async function getEmailContent(
} }
// Log mailbox status with account context // 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 // Get the UIDVALIDITY and UIDNEXT values
const uidValidity = mailbox.uidValidity; const uidValidity = mailbox.uidValidity;
const uidNext = mailbox.uidNext; 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 // Validate UID exists in mailbox
if (numericId >= uidNext) { if (numericId >= uidNext) {
@ -950,7 +1114,11 @@ export async function getEmailContent(
} }
const sequenceNumber = searchResult[0]; 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 // Now fetch using the sequence number with error handling
let message; let message;
@ -962,7 +1130,10 @@ export async function getEmailContent(
size: true size: true
}); });
} catch (fetchError) { } 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'}`); throw new Error(`Failed to fetch email: ${fetchError instanceof Error ? fetchError.message : 'Unknown error'}`);
} }
@ -990,7 +1161,10 @@ export async function getEmailContent(
keepCidLinks: true keepCidLinks: true
}); });
} catch (parseError) { } 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'}`); 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; return email;
} catch (error) { } catch (error) {
console.error('[ERROR] Email fetch failed:', { logger.error('[EMAIL] Email fetch failed', {
userId, userId,
emailId, emailId,
folder: normalizedFolder, folder: normalizedFolder,
accountId: effectiveAccountId, accountId: effectiveAccountId,
error: error instanceof Error ? error.message : 'Unknown error', error: error instanceof Error ? error.message : 'Unknown error',
details: error instanceof Error ? error.stack : undefined
}); });
throw error; throw error;
} finally { } finally {
@ -1076,7 +1249,13 @@ export async function markEmailReadStatus(
// Normalize folder name by removing account prefix if present // Normalize folder name by removing account prefix if present
const normalizedFolder = folder.includes(':') ? folder.split(':')[1] : folder; 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); const client = await getImapConnection(userId, effectiveAccountId);
@ -1097,13 +1276,22 @@ export async function markEmailReadStatus(
return true; return true;
} catch (error) { } 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; return false;
} finally { } finally {
try { try {
await client.mailboxClose(); await client.mailboxClose();
} catch (error) { } 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 // Normalize folder name by removing account prefix if present
const normalizedFolder = folder.includes(':') ? folder.split(':')[1] : folder; 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); const client = await getImapConnection(userId, effectiveAccountId);
@ -1145,13 +1339,22 @@ export async function toggleEmailFlag(
return true; return true;
} catch (error) { } 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; return false;
} finally { } finally {
try { try {
await client.mailboxClose(); await client.mailboxClose();
} catch (error) { } 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 // For backward compatibility, return unprefixed names when no accountId
return mailboxes.map(mailbox => mailbox.path); return mailboxes.map(mailbox => mailbox.path);
} catch (error) { } 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 empty array on error to avoid showing incorrect folders
return []; return [];
} }
@ -1283,22 +1488,31 @@ export async function testEmailConnection(credentials: EmailCredentials): Promis
// Cast to extended type to use OAuth properties // Cast to extended type to use OAuth properties
const extendedCreds = credentials as EmailCredentialsExtended; const extendedCreds = credentials as EmailCredentialsExtended;
console.log('Testing connection with:', { logger.debug('[EMAIL] Testing connection with credentials metadata', {
...extendedCreds, email: extendedCreds.email,
password: extendedCreds.password ? '***' : undefined, host: extendedCreds.host,
accessToken: extendedCreds.accessToken ? '***' : undefined, port: extendedCreds.port,
refreshToken: extendedCreds.refreshToken ? '***' : undefined hasPassword: !!extendedCreds.password,
useOAuth: !!extendedCreds.useOAuth,
hasAccessToken: !!extendedCreds.accessToken,
hasRefreshToken: !!extendedCreds.refreshToken,
}); });
// Test IMAP connection // Test IMAP connection
try { 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 // Configure auth based on whether we're using OAuth or password
let authParams: any; let authParams: any;
if (extendedCreds.useOAuth && extendedCreds.accessToken) { 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 // For OAuth, pass the accessToken directly to ImapFlow
authParams = { authParams = {
@ -1306,10 +1520,14 @@ export async function testEmailConnection(credentials: EmailCredentials): Promis
accessToken: extendedCreds.accessToken accessToken: extendedCreds.accessToken
}; };
// Log the token length to verify it exists // Log the token length to verify it exists (without value)
console.log(`Access token available (length: ${extendedCreds.accessToken.length})`); logger.debug('[EMAIL] Access token present for test', {
email: extendedCreds.email,
});
} else { } else {
console.log('Using password authentication mechanism'); logger.debug('[EMAIL] Using password authentication mechanism', {
email: extendedCreds.email,
});
authParams = { authParams = {
user: extendedCreds.email, user: extendedCreds.email,
pass: extendedCreds.password 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(); 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); const folders = await getMailboxes(client);
await client.logout(); await client.logout();
console.log(`IMAP connection successful for ${extendedCreds.email}`); logger.debug('[EMAIL] IMAP connection successful for test', {
console.log(`Found ${folders.length} folders:`, folders); email: extendedCreds.email,
folderCount: folders.length,
});
// Test SMTP connection if SMTP settings are provided // Test SMTP connection if SMTP settings are provided
let smtpSuccess = false; let smtpSuccess = false;
if (extendedCreds.smtp_host && extendedCreds.smtp_port) { if (extendedCreds.smtp_host && extendedCreds.smtp_port) {
try { 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 // Configure SMTP auth based on OAuth or password
const smtpAuth = extendedCreds.useOAuth && extendedCreds.accessToken const smtpAuth = extendedCreds.useOAuth && extendedCreds.accessToken
@ -1366,10 +1594,15 @@ export async function testEmailConnection(credentials: EmailCredentials): Promis
} as nodemailer.TransportOptions); } as nodemailer.TransportOptions);
await transporter.verify(); await transporter.verify();
console.log(`SMTP connection successful for ${extendedCreds.email}`); logger.debug('[EMAIL] SMTP connection successful', {
email: extendedCreds.email,
});
smtpSuccess = true; smtpSuccess = true;
} catch (smtpError) { } 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 { return {
imap: true, imap: true,
smtp: false, smtp: false,
@ -1385,7 +1618,10 @@ export async function testEmailConnection(credentials: EmailCredentials): Promis
folders folders
}; };
} catch (error) { } 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 { return {
imap: false, imap: false,
error: `IMAP connection failed: ${error instanceof Error ? error.message : 'Unknown error'}` error: `IMAP connection failed: ${error instanceof Error ? error.message : 'Unknown error'}`
@ -1405,7 +1641,9 @@ export async function forceRecacheUserCredentials(userId: string): Promise<boole
}); });
if (!accounts || accounts.length === 0) { if (!accounts || accounts.length === 0) {
console.log(`No email accounts found for user ${userId}`); logger.debug('[EMAIL] No email accounts found for user when recaching credentials', {
userId,
});
return false; return false;
} }
@ -1425,7 +1663,10 @@ export async function forceRecacheUserCredentials(userId: string): Promise<boole
}; };
await cacheEmailCredentials(userId, account.id, credentials); await cacheEmailCredentials(userId, account.id, credentials);
console.log(`Recached credentials for user ${userId}, account ${account.id}`); logger.debug('[EMAIL] Recached credentials for account', {
userId,
accountId: account.id,
});
// Invalidate other caches related to this account // Invalidate other caches related to this account
await invalidateFolderCache(userId, account.id, '*'); await invalidateFolderCache(userId, account.id, '*');
@ -1434,7 +1675,10 @@ export async function forceRecacheUserCredentials(userId: string): Promise<boole
return true; return true;
} catch (error) { } catch (error) {
console.error(`Error recaching credentials for user ${userId}:`, error); logger.error('[EMAIL] Error recaching credentials for user', {
userId,
error: error instanceof Error ? error.message : String(error),
});
return false; return false;
} }
} }

303
lib/services/notifications/leantime-adapter.ts
View File

@ -3,6 +3,7 @@ import { NotificationAdapter } from './notification-adapter.interface';
import { getServerSession } from 'next-auth'; import { getServerSession } from 'next-auth';
import { authOptions } from "@/app/api/auth/options"; import { authOptions } from "@/app/api/auth/options";
import { getRedisClient } from '@/lib/redis'; import { getRedisClient } from '@/lib/redis';
import { logger } from '@/lib/logger';
// Leantime notification type from their API // Leantime notification type from their API
interface LeantimeNotification { interface LeantimeNotification {
@ -30,7 +31,10 @@ export class LeantimeAdapter implements NotificationAdapter {
this.apiUrl = process.env.LEANTIME_API_URL || ''; this.apiUrl = process.env.LEANTIME_API_URL || '';
this.apiToken = process.env.LEANTIME_TOKEN || ''; this.apiToken = process.env.LEANTIME_TOKEN || '';
console.log('[LEANTIME_ADAPTER] Initialized with API URL and token'); logger.debug('[LEANTIME_ADAPTER] Initialized', {
hasApiUrl: !!this.apiUrl,
hasApiToken: !!this.apiToken,
});
} }
/** /**
@ -42,30 +46,36 @@ export class LeantimeAdapter implements NotificationAdapter {
const redis = getRedisClient(); const redis = getRedisClient();
const cacheKey = `${LeantimeAdapter.USER_ID_CACHE_KEY_PREFIX}${email.toLowerCase()}`; const cacheKey = `${LeantimeAdapter.USER_ID_CACHE_KEY_PREFIX}${email.toLowerCase()}`;
await redis.del(cacheKey); await redis.del(cacheKey);
console.log(`[LEANTIME_ADAPTER] Invalidated user ID cache for ${email}`); logger.info('[LEANTIME_ADAPTER] Invalidated user ID cache', {
emailHash: Buffer.from(email.toLowerCase()).toString('base64').slice(0, 12),
});
} catch (error) { } catch (error) {
console.error(`[LEANTIME_ADAPTER] Error invalidating user ID cache:`, error); console.error(`[LEANTIME_ADAPTER] Error invalidating user ID cache:`, error);
} }
} }
async getNotifications(userId: string, page = 1, limit = 20): Promise<Notification[]> { async getNotifications(userId: string, page = 1, limit = 20): Promise<Notification[]> {
console.log(`[LEANTIME_ADAPTER] getNotifications called for userId: ${userId}, page: ${page}, limit: ${limit}`); logger.debug('[LEANTIME_ADAPTER] getNotifications called', {
userId,
page,
limit,
});
try { try {
// Get the user's email directly from the session // Get the user's email directly from the session
const email = await this.getUserEmail(); const email = await this.getUserEmail();
console.log(`[LEANTIME_ADAPTER] Retrieved email from session:`, email || 'null');
if (!email) { 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 []; return [];
} }
const leantimeUserId = await this.getLeantimeUserId(email); const leantimeUserId = await this.getLeantimeUserId(email);
console.log(`[LEANTIME_ADAPTER] Retrieved Leantime userId for email ${email}:`, leantimeUserId || 'null');
if (!leantimeUserId) { 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 []; return [];
} }
@ -74,7 +84,6 @@ export class LeantimeAdapter implements NotificationAdapter {
const limitEnd = limit; const limitEnd = limit;
// Make request to Leantime API using the correct jsonrpc method // Make request to Leantime API using the correct jsonrpc method
console.log('[LEANTIME_ADAPTER] Sending request to get all notifications');
const jsonRpcBody = { const jsonRpcBody = {
jsonrpc: '2.0', jsonrpc: '2.0',
method: 'leantime.rpc.Notifications.Notifications.getAllNotifications', method: 'leantime.rpc.Notifications.Notifications.getAllNotifications',
@ -87,7 +96,6 @@ export class LeantimeAdapter implements NotificationAdapter {
}, },
id: 1 id: 1
}; };
console.log('[LEANTIME_ADAPTER] Request body:', JSON.stringify(jsonRpcBody));
const response = await fetch(`${this.apiUrl}/api/jsonrpc`, { const response = await fetch(`${this.apiUrl}/api/jsonrpc`, {
method: 'POST', method: 'POST',
@ -98,55 +106,56 @@ export class LeantimeAdapter implements NotificationAdapter {
body: JSON.stringify(jsonRpcBody) 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) { if (!response.ok) {
const errorText = await response.text(); 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, status: response.status,
body: errorText.substring(0, 200) + (errorText.length > 200 ? '...' : '') bodyPreview: errorText.substring(0, 200),
}); });
return []; return [];
} }
const responseText = await response.text(); const responseText = await response.text();
console.log('[LEANTIME_ADAPTER] Raw response (truncated):', responseText.substring(0, 200) + (responseText.length > 200 ? '...' : ''));
const data = JSON.parse(responseText); 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.result || !Array.isArray(data.result)) {
if (data.error) { 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 { } else {
console.error('[LEANTIME_ADAPTER] Invalid response format from Leantime notifications API'); logger.error('[LEANTIME_ADAPTER] Invalid response format from Leantime notifications API');
} }
return []; return [];
} }
const notifications = this.transformNotifications(data.result, userId); 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; return notifications;
} catch (error) { } 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 []; return [];
} }
} }
async getNotificationCount(userId: string): Promise<NotificationCount> { async getNotificationCount(userId: string): Promise<NotificationCount> {
console.log(`[LEANTIME_ADAPTER] getNotificationCount called for userId: ${userId}`); logger.debug('[LEANTIME_ADAPTER] getNotificationCount called', { userId });
try { try {
// Fetch notifications directly from API for accurate counting (bypassing cache) // Fetch notifications directly from API for accurate counting (bypassing cache)
// Fetch up to 1000 notifications to get accurate count // Fetch up to 1000 notifications to get accurate count
const email = await this.getUserEmail(); const email = await this.getUserEmail();
if (!email) { 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 { return {
total: 0, total: 0,
unread: 0, unread: 0,
@ -161,7 +170,7 @@ export class LeantimeAdapter implements NotificationAdapter {
const leantimeUserId = await this.getLeantimeUserId(email); const leantimeUserId = await this.getLeantimeUserId(email);
if (!leantimeUserId) { 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 { return {
total: 0, total: 0,
unread: 0, unread: 0,
@ -198,7 +207,9 @@ export class LeantimeAdapter implements NotificationAdapter {
}); });
if (!response.ok) { 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 { return {
total: 0, total: 0,
unread: 0, unread: 0,
@ -214,7 +225,9 @@ export class LeantimeAdapter implements NotificationAdapter {
const data = await response.json(); const data = await response.json();
if (data.error || !Array.isArray(data.result)) { 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 { return {
total: 0, total: 0,
unread: 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 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, total: totalCount,
unread: unreadCount, unread: unreadCount,
read: totalCount - unreadCount,
hasMore: hasMore, hasMore: hasMore,
note: hasMore ? 'WARNING: May have more than 1000 notifications total' : 'OK'
}); });
return { return {
@ -256,7 +267,9 @@ export class LeantimeAdapter implements NotificationAdapter {
} }
}; };
} catch (error) { } 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 { return {
total: 0, total: 0,
unread: 0, unread: 0,
@ -271,7 +284,10 @@ export class LeantimeAdapter implements NotificationAdapter {
} }
async markAsRead(userId: string, notificationId: string): Promise<boolean> { async markAsRead(userId: string, notificationId: string): Promise<boolean> {
console.log(`[LEANTIME_ADAPTER] markAsRead called for ${notificationId}`); logger.debug('[LEANTIME_ADAPTER] markAsRead called', {
userId,
notificationId,
});
try { try {
// Extract the source ID from our compound ID // Extract the source ID from our compound ID
@ -280,13 +296,15 @@ export class LeantimeAdapter implements NotificationAdapter {
// Get user email and ID // Get user email and ID
const email = await this.getUserEmail(); const email = await this.getUserEmail();
if (!email) { 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; return false;
} }
const leantimeUserId = await this.getLeantimeUserId(email); const leantimeUserId = await this.getLeantimeUserId(email);
if (!leantimeUserId) { 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; return false;
} }
@ -302,8 +320,6 @@ export class LeantimeAdapter implements NotificationAdapter {
id: 1 id: 1
}; };
console.log(`[LEANTIME_ADAPTER] markAsRead - Request body:`, JSON.stringify(jsonRpcBody));
const response = await fetch(`${this.apiUrl}/api/jsonrpc`, { const response = await fetch(`${this.apiUrl}/api/jsonrpc`, {
method: 'POST', method: 'POST',
headers: { headers: {
@ -313,35 +329,45 @@ export class LeantimeAdapter implements NotificationAdapter {
body: JSON.stringify(jsonRpcBody) 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) { if (!response.ok) {
const errorText = await response.text(); 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; return false;
} }
const responseText = await response.text(); const responseText = await response.text();
console.log(`[LEANTIME_ADAPTER] markAsRead - Response body:`, responseText.substring(0, 200));
let data; let data;
try { try {
data = JSON.parse(responseText); data = JSON.parse(responseText);
} catch (parseError) { } 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; return false;
} }
if (data.error) { if (data.error) {
console.error(`[LEANTIME_ADAPTER] markAsRead - API Error:`, data.error); logger.error('[LEANTIME_ADAPTER] markAsRead API error', {
error: data.error,
});
return false; return false;
} }
const success = data.result === true || data.result === "true" || !!data.result; 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; return success;
} catch (error) { } 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; return false;
} }
} }
@ -349,35 +375,32 @@ export class LeantimeAdapter implements NotificationAdapter {
async markAllAsRead(userId: string): Promise<boolean> { async markAllAsRead(userId: string): Promise<boolean> {
// CRITICAL: This should ALWAYS appear if method is called // CRITICAL: This should ALWAYS appear if method is called
// Using multiple logging methods to ensure visibility // Using multiple logging methods to ensure visibility
process.stdout.write(`\n[LEANTIME_ADAPTER] ===== markAllAsRead START =====\n`); logger.info('[LEANTIME_ADAPTER] markAllAsRead START', {
console.log(`[LEANTIME_ADAPTER] ===== markAllAsRead START =====`); userId,
console.error(`[LEANTIME_ADAPTER] ===== markAllAsRead START (via console.error) =====`); hasApiUrl: !!this.apiUrl,
console.log(`[LEANTIME_ADAPTER] markAllAsRead called for userId: ${userId}`); hasApiToken: !!this.apiToken,
console.log(`[LEANTIME_ADAPTER] API URL: ${this.apiUrl}`); });
console.log(`[LEANTIME_ADAPTER] Has API Token: ${!!this.apiToken}`);
try { try {
// Get user email and ID // Get user email and ID
const email = await this.getUserEmail(); const email = await this.getUserEmail();
if (!email) { 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; return false;
} }
console.log(`[LEANTIME_ADAPTER] markAllAsRead - User email: ${email}`);
const leantimeUserId = await this.getLeantimeUserId(email); const leantimeUserId = await this.getLeantimeUserId(email);
if (!leantimeUserId) { 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; 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: // 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) // 1. Fetch all unread notifications directly from API (bypassing any cache)
// 2. Mark each one individually using markNotificationRead // 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) // Fetch all notifications directly from API (up to 1000) to get fresh data (not cached)
const jsonRpcBody = { const jsonRpcBody = {
jsonrpc: '2.0', jsonrpc: '2.0',
@ -392,7 +415,6 @@ export class LeantimeAdapter implements NotificationAdapter {
id: 1 id: 1
}; };
console.log(`[LEANTIME_ADAPTER] markAllAsRead - Fetching notifications from API`);
const fetchResponse = await fetch(`${this.apiUrl}/api/jsonrpc`, { const fetchResponse = await fetch(`${this.apiUrl}/api/jsonrpc`, {
method: 'POST', method: 'POST',
headers: { headers: {
@ -403,13 +425,17 @@ export class LeantimeAdapter implements NotificationAdapter {
}); });
if (!fetchResponse.ok) { 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; return false;
} }
const fetchData = await fetchResponse.json(); const fetchData = await fetchResponse.json();
if (fetchData.error) { 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; return false;
} }
@ -419,10 +445,13 @@ export class LeantimeAdapter implements NotificationAdapter {
.filter((n: any) => n.read === 0 || n.read === false || n.read === '0') .filter((n: any) => n.read === 0 || n.read === false || n.read === '0')
.map((n: any) => ({ id: n.id, sourceId: String(n.id) })); .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) { if (unreadNotifications.length === 0) {
console.log(`[LEANTIME_ADAPTER] markAllAsRead - No unread notifications, returning success`); logger.info('[LEANTIME_ADAPTER] markAllAsRead no unread notifications');
return true; return true;
} }
@ -458,12 +487,20 @@ export class LeantimeAdapter implements NotificationAdapter {
}); });
if (!response.ok) { 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) // Retry on server errors (5xx) or rate limiting (429)
if ((response.status >= 500 || response.status === 429) && retryCount < MAX_RETRIES) { if ((response.status >= 500 || response.status === 429) && retryCount < MAX_RETRIES) {
const delay = Math.min(1000 * Math.pow(2, retryCount), 2000); // Exponential backoff, max 2s 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)); await new Promise(resolve => setTimeout(resolve, delay));
return markSingleNotification(notificationId, retryCount + 1); return markSingleNotification(notificationId, retryCount + 1);
} }
@ -474,12 +511,20 @@ export class LeantimeAdapter implements NotificationAdapter {
const data = await response.json(); const data = await response.json();
if (data.error) { 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 // Retry on certain JSON-RPC errors
if (retryCount < MAX_RETRIES && (data.error.code === -32603 || data.error.code === -32000)) { if (retryCount < MAX_RETRIES && (data.error.code === -32603 || data.error.code === -32000)) {
const delay = Math.min(1000 * Math.pow(2, retryCount), 2000); 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)); await new Promise(resolve => setTimeout(resolve, delay));
return markSingleNotification(notificationId, retryCount + 1); return markSingleNotification(notificationId, retryCount + 1);
} }
@ -489,12 +534,20 @@ export class LeantimeAdapter implements NotificationAdapter {
return data.result === true || data.result === "true" || !!data.result; return data.result === true || data.result === "true" || !!data.result;
} catch (error) { } 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 // Retry on network errors
if (retryCount < MAX_RETRIES && error instanceof Error) { if (retryCount < MAX_RETRIES && error instanceof Error) {
const delay = Math.min(1000 * Math.pow(2, retryCount), 2000); 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)); await new Promise(resolve => setTimeout(resolve, delay));
return markSingleNotification(notificationId, retryCount + 1); return markSingleNotification(notificationId, retryCount + 1);
} }
@ -511,7 +564,10 @@ export class LeantimeAdapter implements NotificationAdapter {
}) })
.filter((id: number | null): id is number => id !== null); .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 // Split into batches
for (let i = 0; i < notificationIds.length; i += BATCH_SIZE) { 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 batchNumber = Math.floor(i / BATCH_SIZE) + 1;
const totalBatches = Math.ceil(notificationIds.length / BATCH_SIZE); 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 // Process batch in parallel
const batchResults = await Promise.all( const batchResults = await Promise.all(
@ -543,7 +603,9 @@ export class LeantimeAdapter implements NotificationAdapter {
// Retry failed notifications once more // Retry failed notifications once more
if (failedNotifications.length > 0 && failedNotifications.length < notificationIds.length) { 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( const retryResults = await Promise.all(
failedNotifications.map(async (notificationId) => { 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) // Consider it successful if majority were marked (at least 80% success rate)
const successRate = notificationIds.length > 0 ? successCount / notificationIds.length : 0; const successRate = notificationIds.length > 0 ? successCount / notificationIds.length : 0;
const success = successRate >= 0.8; const success = successRate >= 0.8;
console.log(`[LEANTIME_ADAPTER] markAllAsRead - Success rate: ${(successRate * 100).toFixed(1)}%, Overall success: ${success}`); logger.info('[LEANTIME_ADAPTER] markAllAsRead END', {
console.log(`[LEANTIME_ADAPTER] ===== markAllAsRead END (success: ${success}) =====`); successRate,
success,
});
return success; return success;
} catch (error) { } catch (error) {
console.error('[LEANTIME_ADAPTER] markAllAsRead - Exception:', error); logger.error('[LEANTIME_ADAPTER] markAllAsRead exception', {
console.error('[LEANTIME_ADAPTER] markAllAsRead - Error stack:', error instanceof Error ? error.stack : 'No stack'); error: error instanceof Error ? error.message : String(error),
console.error(`[LEANTIME_ADAPTER] ===== markAllAsRead END (exception) =====`); });
return false; return false;
} }
} }
@ -634,11 +702,13 @@ export class LeantimeAdapter implements NotificationAdapter {
const redis = getRedisClient(); const redis = getRedisClient();
const cachedEmail = await redis.get(emailCacheKey); const cachedEmail = await redis.get(emailCacheKey);
if (cachedEmail) { if (cachedEmail) {
console.log(`[LEANTIME_ADAPTER] Found cached email for user ${userId}`); logger.debug('[LEANTIME_ADAPTER] Found cached email for user', { userId });
return cachedEmail; return cachedEmail;
} }
} catch (cacheError) { } 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 // Get from session
@ -652,14 +722,18 @@ export class LeantimeAdapter implements NotificationAdapter {
try { try {
const redis = getRedisClient(); const redis = getRedisClient();
await redis.set(emailCacheKey, email, 'EX', LeantimeAdapter.USER_EMAIL_CACHE_TTL); 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) { } 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; return email;
} catch (error) { } 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; return null;
} }
} }
@ -671,7 +745,7 @@ export class LeantimeAdapter implements NotificationAdapter {
try { try {
if (!this.apiToken) { 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; return null;
} }
@ -682,18 +756,27 @@ export class LeantimeAdapter implements NotificationAdapter {
if (cachedUserId) { if (cachedUserId) {
const userId = parseInt(cachedUserId, 10); const userId = parseInt(cachedUserId, 10);
if (!isNaN(userId)) { 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; return userId;
} }
} }
} catch (cacheError) { } 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 // Fetch from API with retry logic
const fetchWithRetry = async (attempt: number): Promise<number | null> => { const fetchWithRetry = async (attempt: number): Promise<number | null> => {
try { 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`, { const response = await fetch(`${this.apiUrl}/api/jsonrpc`, {
method: 'POST', method: 'POST',
@ -710,12 +793,18 @@ export class LeantimeAdapter implements NotificationAdapter {
if (!response.ok) { if (!response.ok) {
const errorText = await response.text(); 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) // Retry on server errors (5xx) or rate limiting (429)
if ((response.status >= 500 || response.status === 429) && attempt < MAX_RETRIES) { if ((response.status >= 500 || response.status === 429) && attempt < MAX_RETRIES) {
const delay = Math.min(1000 * Math.pow(2, attempt), 5000); // Exponential backoff, max 5s 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)); await new Promise(resolve => setTimeout(resolve, delay));
return fetchWithRetry(attempt + 1); return fetchWithRetry(attempt + 1);
} }
@ -725,11 +814,16 @@ export class LeantimeAdapter implements NotificationAdapter {
const data = await response.json(); const data = await response.json();
if (data.error) { 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 // Retry on certain errors
if (attempt < MAX_RETRIES && (data.error.code === -32603 || data.error.code === -32000)) { if (attempt < MAX_RETRIES && (data.error.code === -32603 || data.error.code === -32000)) {
const delay = Math.min(1000 * Math.pow(2, attempt), 5000); 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)); await new Promise(resolve => setTimeout(resolve, delay));
return fetchWithRetry(attempt + 1); return fetchWithRetry(attempt + 1);
} }
@ -737,7 +831,7 @@ export class LeantimeAdapter implements NotificationAdapter {
} }
if (!data.result || !Array.isArray(data.result)) { 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; return null;
} }
@ -758,9 +852,14 @@ export class LeantimeAdapter implements NotificationAdapter {
try { try {
const redis = getRedisClient(); const redis = getRedisClient();
await redis.set(CACHE_KEY, userId.toString(), 'EX', LeantimeAdapter.USER_ID_CACHE_TTL); 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) { } 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 // 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; return null;
} catch (error) { } 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 // Retry on network errors
if (attempt < MAX_RETRIES && error instanceof Error) { if (attempt < MAX_RETRIES && error instanceof Error) {
const delay = Math.min(1000 * Math.pow(2, attempt), 5000); 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)); await new Promise(resolve => setTimeout(resolve, delay));
return fetchWithRetry(attempt + 1); return fetchWithRetry(attempt + 1);
} }
@ -787,7 +894,9 @@ export class LeantimeAdapter implements NotificationAdapter {
return await fetchWithRetry(retryCount); return await fetchWithRetry(retryCount);
} catch (error) { } 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; return null;
} }
} }

236
lib/services/notifications/notification-service.ts
View File

@ -2,6 +2,7 @@ import { Notification, NotificationCount } from '@/lib/types/notification';
import { NotificationAdapter } from './notification-adapter.interface'; import { NotificationAdapter } from './notification-adapter.interface';
import { LeantimeAdapter } from './leantime-adapter'; import { LeantimeAdapter } from './leantime-adapter';
import { getRedisClient } from '@/lib/redis'; import { getRedisClient } from '@/lib/redis';
import { logger } from '@/lib/logger';
export class NotificationService { export class NotificationService {
private adapters: Map<string, NotificationAdapter> = new Map(); private adapters: Map<string, NotificationAdapter> = new Map();
@ -17,7 +18,7 @@ export class NotificationService {
private static REFRESH_LOCK_TTL = 30; // 30 seconds private static REFRESH_LOCK_TTL = 30; // 30 seconds
constructor() { constructor() {
console.log('[NOTIFICATION_SERVICE] Initializing notification service'); logger.debug('[NOTIFICATION_SERVICE] Initializing notification service');
// Register adapters // Register adapters
this.registerAdapter(new LeantimeAdapter()); this.registerAdapter(new LeantimeAdapter());
@ -28,7 +29,9 @@ export class NotificationService {
// this.registerAdapter(new DolibarrAdapter()); // this.registerAdapter(new DolibarrAdapter());
// this.registerAdapter(new MoodleAdapter()); // 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 { public static getInstance(): NotificationService {
if (!NotificationService.instance) { 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(); NotificationService.instance = new NotificationService();
} }
return NotificationService.instance; return NotificationService.instance;
@ -47,14 +50,20 @@ export class NotificationService {
*/ */
private registerAdapter(adapter: NotificationAdapter): void { private registerAdapter(adapter: NotificationAdapter): void {
this.adapters.set(adapter.sourceName, adapter); 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 * Get all notifications for a user from all configured sources
*/ */
async getNotifications(userId: string, page = 1, limit = 20): Promise<Notification[]> { async getNotifications(userId: string, page = 1, limit = 20): Promise<Notification[]> {
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 redis = getRedisClient();
const cacheKey = NotificationService.NOTIFICATIONS_LIST_CACHE_KEY(userId, page, limit); const cacheKey = NotificationService.NOTIFICATIONS_LIST_CACHE_KEY(userId, page, limit);
@ -62,7 +71,9 @@ export class NotificationService {
try { try {
const cachedData = await redis.get(cacheKey); const cachedData = await redis.get(cacheKey);
if (cachedData) { 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 // Schedule background refresh if TTL is less than half the original value
const ttl = await redis.ttl(cacheKey); const ttl = await redis.ttl(cacheKey);
@ -78,29 +89,50 @@ export class NotificationService {
} }
// No cached data, fetch from all adapters // 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 allNotifications: Notification[] = [];
const adapterEntries = Array.from(this.adapters.entries()); 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]) => { 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 { try {
const configured = await adapter.isConfigured(); 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) { 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); 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; return notifications;
} else { } else {
console.log(`[NOTIFICATION_SERVICE] Skipping adapter ${name} as it is not configured`); logger.debug('[NOTIFICATION_SERVICE] Skipping adapter (not configured)', {
adapter: name,
});
return []; return [];
} }
} catch (error) { } 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 []; return [];
} }
}); });
@ -110,13 +142,18 @@ export class NotificationService {
// Combine all notifications // Combine all notifications
results.forEach((notifications, index) => { results.forEach((notifications, index) => {
const adapterName = adapterEntries[index][0]; 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); allNotifications.push(...notifications);
}); });
// Sort by timestamp (newest first) // Sort by timestamp (newest first)
allNotifications.sort((a, b) => b.timestamp.getTime() - a.timestamp.getTime()); 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 // Store in cache
try { try {
@ -126,9 +163,14 @@ export class NotificationService {
'EX', 'EX',
NotificationService.LIST_CACHE_TTL 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) { } 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; return allNotifications;
@ -138,7 +180,7 @@ export class NotificationService {
* Get notification counts for a user * Get notification counts for a user
*/ */
async getNotificationCount(userId: string): Promise<NotificationCount> { async getNotificationCount(userId: string): Promise<NotificationCount> {
console.log(`[NOTIFICATION_SERVICE] getNotificationCount called for user ${userId}`); logger.debug('[NOTIFICATION_SERVICE] getNotificationCount called', { userId });
const redis = getRedisClient(); const redis = getRedisClient();
const cacheKey = NotificationService.NOTIFICATION_COUNT_CACHE_KEY(userId); const cacheKey = NotificationService.NOTIFICATION_COUNT_CACHE_KEY(userId);
@ -146,7 +188,7 @@ export class NotificationService {
try { try {
const cachedData = await redis.get(cacheKey); const cachedData = await redis.get(cacheKey);
if (cachedData) { 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 // Background refresh is now handled by unified refresh system
// Cache TTL is aligned with refresh interval (30s) // Cache TTL is aligned with refresh interval (30s)
@ -158,7 +200,10 @@ export class NotificationService {
} }
// No cached data, fetch counts from all adapters // 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 = { const aggregatedCount: NotificationCount = {
total: 0, total: 0,
@ -167,25 +212,44 @@ export class NotificationService {
}; };
const adapterEntries = Array.from(this.adapters.entries()); 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]) => { 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 { try {
const configured = await adapter.isConfigured(); 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) { 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); 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; return count;
} else { } 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; return null;
} }
} catch (error) { } 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; return null;
} }
}); });
@ -197,7 +261,11 @@ export class NotificationService {
if (!count) return; if (!count) return;
const adapterName = adapterEntries[index][0]; 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.total += count.total;
aggregatedCount.unread += count.unread; 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 // Store in cache
try { try {
@ -218,9 +290,15 @@ export class NotificationService {
'EX', 'EX',
NotificationService.COUNT_CACHE_TTL 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) { } 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; return aggregatedCount;
@ -235,7 +313,9 @@ export class NotificationService {
const sourceId = idParts.join('-'); // Reconstruct the ID in case it has hyphens const sourceId = idParts.join('-'); // Reconstruct the ID in case it has hyphens
if (!source || !this.adapters.has(source)) { 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 // Still invalidate cache to ensure fresh data
await this.invalidateCache(userId); await this.invalidateCache(userId);
return false; return false;
@ -246,15 +326,24 @@ export class NotificationService {
try { try {
success = await adapter.markAsRead(userId, notificationId); 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) { } 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; success = false;
} }
// Always invalidate cache after marking attempt (even on failure) // Always invalidate cache after marking attempt (even on failure)
// This ensures fresh data on next fetch, even if the operation partially failed // 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); await this.invalidateCache(userId);
return success; return success;
@ -264,45 +353,67 @@ export class NotificationService {
* Mark all notifications from all sources as read * Mark all notifications from all sources as read
*/ */
async markAllAsRead(userId: string): Promise<boolean> { async markAllAsRead(userId: string): Promise<boolean> {
console.log(`[NOTIFICATION_SERVICE] markAllAsRead called for user ${userId}`); logger.debug('[NOTIFICATION_SERVICE] markAllAsRead called', {
console.log(`[NOTIFICATION_SERVICE] Available adapters: ${Array.from(this.adapters.keys()).join(', ')}`); userId,
adapters: Array.from(this.adapters.keys()),
});
const promises = Array.from(this.adapters.values()) const promises = Array.from(this.adapters.values())
.map(async (adapter) => { .map(async (adapter) => {
const adapterName = adapter.sourceName; const adapterName = adapter.sourceName;
console.log(`[NOTIFICATION_SERVICE] Processing adapter: ${adapterName}`); logger.debug('[NOTIFICATION_SERVICE] markAllAsRead processing adapter', {
adapter: adapterName,
});
try { try {
const configured = await adapter.isConfigured(); 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) { 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) 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); 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; return result;
} catch (error) { } catch (error) {
console.error(`[NOTIFICATION_SERVICE] Error marking all notifications as read for ${adapterName}:`, error); logger.error('[NOTIFICATION_SERVICE] Error marking all notifications as read for adapter', {
console.error(`[NOTIFICATION_SERVICE] Error stack:`, error instanceof Error ? error.stack : 'No stack'); adapter: adapterName,
error: error instanceof Error ? error.message : String(error),
});
return false; return false;
} }
}); });
const results = await Promise.all(promises); const results = await Promise.all(promises);
console.log(`[NOTIFICATION_SERVICE] markAllAsRead results:`, results);
const success = results.every(result => result); const success = results.every(result => result);
const anySuccess = results.some(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) // Always invalidate cache after marking attempt (even on failure)
// This ensures fresh data on next fetch, even if the operation failed // 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 // 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); await this.invalidateCache(userId);
return success; return success;
@ -333,15 +444,19 @@ export class NotificationService {
100 100
); );
cursor = nextCursor; cursor = nextCursor;
if (keys.length > 0) { if (keys.length > 0) {
await redis.del(...keys); await redis.del(...keys);
} }
} while (cursor !== "0"); } while (cursor !== "0");
console.log(`[NOTIFICATION_SERVICE] Invalidated notification caches for user ${userId}`); logger.debug('[NOTIFICATION_SERVICE] Invalidated notification caches', {
userId,
});
} catch (error) { } 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 refreshed in the last minute, skip
if (now - lastRefreshTime < 60000) { 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; return;
} }
} }
console.log(`[NOTIFICATION_SERVICE] Background refresh started for user ${userId}`); logger.debug('[NOTIFICATION_SERVICE] Background refresh started', {
userId,
});
// Set last refresh time // Set last refresh time
await redis.set(refreshKey, Date.now().toString(), 'EX', 120); // 2 minute TTL 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.getNotificationCount(userId);
await this.getNotifications(userId, 1, 20); 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) { } 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 { } finally {
// Release the lock // Release the lock
await redis.del(lockKey).catch(() => {}); await redis.del(lockKey).catch(() => {});

1
nginx-config-fix.conf
View File

@ -30,3 +30,4 @@ server {
# ... reste de votre config ... # ... reste de votre config ...
} }