This commit is contained in:
alma 2026-01-06 16:58:03 +01:00
parent 77ffdefba4
commit d0a4e6fd8d
6 changed files with 772 additions and 2 deletions

142
IMPLEMENTATION_SUMMARY.md Normal file
View File

@ -0,0 +1,142 @@
# Implementation Summary - Logging Improvements
**Date**: 2026-01-01
**Status**: ✅ Completed
---
## 📋 What Was Done
### 1. Impact Analysis Completed ✅
**File Created**: `SESSION_CALLBACK_LOGGING_IMPACT_ANALYSIS.md`
**Key Findings**:
- ✅ **No functional impact** on Keycloak, MinIO, or external services
- ✅ **Logging was added for debugging**, not functionality
- ✅ **Error logging will be preserved** (critical for troubleshooting)
- ✅ **Conditional logging recommended** (DEBUG_SESSION flag)
**Recommendation**:
- Proceed with conditional logging using `DEBUG_SESSION` environment variable
- Keep error logging always enabled
- Make success logging conditional
---
### 2. Mark-as-Read Logging Added ✅
**Files Modified**:
1. `app/api/notifications/[id]/read/route.ts`
2. `app/api/notifications/read-all/route.ts`
**Logging Added**:
- ✅ Entry logging (when endpoint is called)
- ✅ Authentication status logging
- ✅ User ID and notification ID logging
- ✅ Success/failure logging with duration
- ✅ Error logging with stack traces
- ✅ Timestamp logging
**Log Format**:
```
[NOTIFICATION_API] Mark as read endpoint called
[NOTIFICATION_API] Mark as read - Processing { userId, notificationId, timestamp }
[NOTIFICATION_API] Mark as read - Success { userId, notificationId, duration }
```
---
## 🔍 What to Look For in Logs
### When Mark-as-Read is Called
**Expected Logs**:
```
[NOTIFICATION_API] Mark as read endpoint called
[NOTIFICATION_API] Mark as read - Processing { userId: "...", notificationId: "...", timestamp: "..." }
[NOTIFICATION_API] Mark as read - Success { userId: "...", notificationId: "...", duration: "Xms" }
```
**If Authentication Fails**:
```
[NOTIFICATION_API] Mark as read - Authentication failed
```
**If Operation Fails**:
```
[NOTIFICATION_API] Mark as read - Failed { userId: "...", notificationId: "...", duration: "Xms" }
```
**If Error Occurs**:
```
[NOTIFICATION_API] Mark as read - Error { error: "...", stack: "...", duration: "Xms" }
```
---
## 📊 Next Steps
### Immediate (Ready to Test)
1. **Test Mark-as-Read Functionality**
- Mark a single notification as read
- Mark all notifications as read
- Check logs for the new logging statements
- Verify notification count updates correctly
2. **Monitor Logs**
- Watch for `[NOTIFICATION_API]` log entries
- Verify timing information
- Check for any errors
### Future (When Ready)
3. **Implement Conditional Session Callback Logging**
- Add `DEBUG_SESSION` environment variable support
- Update `app/api/auth/options.ts`
- Test in development and production
- Document in README
---
## 🎯 Testing Checklist
- [ ] Mark single notification as read → Check logs
- [ ] Mark all notifications as read → Check logs
- [ ] Verify notification count updates
- [ ] Check for any errors in logs
- [ ] Verify performance (duration logging)
- [ ] Test with invalid notification ID
- [ ] Test without authentication
---
## 📝 Files Changed
1. ✅ `app/api/notifications/[id]/read/route.ts` - Added comprehensive logging
2. ✅ `app/api/notifications/read-all/route.ts` - Added comprehensive logging
3. ✅ `SESSION_CALLBACK_LOGGING_IMPACT_ANALYSIS.md` - Created impact analysis
4. ✅ `IMPLEMENTATION_SUMMARY.md` - This file
---
## 🔧 Environment Variables
**No new environment variables required** for mark-as-read logging.
**Future**: `DEBUG_SESSION` will be needed for conditional session callback logging (not implemented yet).
---
## ✅ Status
**Mark-as-Read Logging**: ✅ **COMPLETE**
**Session Callback Impact Analysis**: ✅ **COMPLETE**
**Session Callback Conditional Logging**: ⏳ **PENDING** (awaiting approval)
---
**Generated**: 2026-01-01
**Ready for Testing**: ✅ Yes

239
LOG_ANALYSIS_FEEDBACK.md Normal file
View File

@ -0,0 +1,239 @@
# Log Analysis & Feedback Report
**Date**: 2026-01-01
**Log File**: `log`
**Analysis Scope**: Application startup, notifications, session management, API calls
---
## 🔴 Critical Issues
### 1. Excessive Session Callback Logging (HIGH PRIORITY)
**Problem**:
- **10+ session callbacks** triggered in a short period
- Each `getServerSession()` call triggers verbose logging
- Logs show `=== SESSION CALLBACK START ===` and `=== SESSION CALLBACK END ===` repeatedly
**Root Cause**:
- Every API route calls `getServerSession(authOptions)`
- Root layout (`app/layout.tsx`) also calls it
- Session callback has extensive logging (lines 407-415 in `app/api/auth/options.ts`)
**Impact**:
- ⚠️ **Performance**: Unnecessary logging overhead on every request
- ⚠️ **Log Noise**: Makes it hard to find actual issues
- ⚠️ **Debugging**: Difficult to identify real problems
**Recommendation**:
```typescript
// In app/api/auth/options.ts, line 405-415
async session({ session, token }) {
try {
// Only log in development or when there's an error
if (process.env.NODE_ENV === 'development' || token.error) {
console.log('=== SESSION CALLBACK START ===');
console.log('Token error:', token.error);
// ... rest of logging
}
// Or use a debug flag
const DEBUG_SESSION = process.env.DEBUG_SESSION === 'true';
if (DEBUG_SESSION) {
console.log('=== SESSION CALLBACK START ===');
// ... logging
}
// ... rest of callback
}
}
```
**Priority**: 🔴 **HIGH** - Should be fixed immediately
---
### 2. Missing markAsRead/markAllAsRead Logs
**Problem**:
- No API calls to `/api/notifications/[id]/read` or `/api/notifications/read-all` in the log
- User reported notification count not updating after marking as read
**Possible Causes**:
1. User didn't actually mark notifications as read during this log session
2. API calls are failing silently (network errors, CORS, etc.)
3. Client-side code isn't calling the API correctly
4. API routes aren't logging their calls
**Investigation Steps**:
1. Add logging to mark-as-read API routes:
```typescript
// In app/api/notifications/[id]/read/route.ts
export async function POST(request: Request, context: { params: Promise<{ id: string }> }) {
console.log('[NOTIFICATION_API] Mark as read called', { id: context.params?.id });
// ... rest of code
}
```
2. Check browser console for client-side errors
3. Verify network tab shows the API calls being made
4. Test the mark-as-read functionality while monitoring logs
**Priority**: 🟡 **MEDIUM** - Needs investigation
---
## ✅ Positive Observations
### 1. Notification Service Working Correctly
- ✅ Service initialized properly
- ✅ Count fetched: **100 total, 66 unread**
- ✅ List fetched: **20 notifications**
- ✅ Caching working: `Cached notification counts for user`
- ✅ Leantime adapter functioning correctly
### 2. Infrastructure Healthy
- ✅ Redis connection successful
- ✅ Database queries working (Prisma)
- ✅ IMAP connection successful (633ms)
- ✅ External APIs responding (News, Leantime, Rocket.Chat)
### 3. Data Flow
- ✅ Session creation successful
- ✅ User authentication working
- ✅ Token refresh logic functioning
- ✅ OAuth token management working
---
## 📊 Performance Metrics from Log
| Metric | Value | Status |
|--------|-------|--------|
| Redis Connection | ✅ Success | Good |
| IMAP Connection Time | 633ms | Acceptable |
| Notification Count Fetch | ✅ Success | Good |
| Notification List Fetch | ✅ Success | Good |
| Session Callbacks | 10+ in short period | ⚠️ Too many |
| Database Queries | ✅ Working | Good |
---
## 🔧 Recommended Actions
### Immediate (This Week)
1. **Reduce Session Callback Logging**
- Add environment-based conditional logging
- Only log errors or use `DEBUG_SESSION` flag
- **File**: `app/api/auth/options.ts`
2. **Add Logging to Mark-as-Read Endpoints**
- Add console.log to track when mark-as-read is called
- Log success/failure
- **Files**:
- `app/api/notifications/[id]/read/route.ts`
- `app/api/notifications/read-all/route.ts`
3. **Test Notification Mark-as-Read Flow**
- Monitor logs while marking notifications as read
- Verify API calls are being made
- Check if cache invalidation is working
### Short Term (Next Sprint)
4. **Implement Request Deduplication**
- Use the `request-deduplication` utility
- Prevent duplicate API calls
- **Already planned in unified refresh system**
5. **Add Performance Monitoring**
- Track API call frequency
- Monitor session callback frequency
- Alert on excessive calls
6. **Optimize Session Access**
- Consider caching session data
- Reduce redundant `getServerSession()` calls
- Use session context where possible
---
## 🐛 Potential Issues Not Visible in Log
### 1. Client-Side Errors
- Browser console errors not captured in server logs
- Network request failures
- React component errors
### 2. Cache Invalidation
- No logs showing cache invalidation after mark-as-read
- May need to verify `invalidateCache()` is being called
### 3. Race Conditions
- Multiple simultaneous API calls
- State update conflicts
- Not visible in single-threaded log
---
## 📝 Log Patterns Analysis
### Session Callback Pattern
```
=== SESSION CALLBACK START ===
Token error: undefined
Has accessToken: true
Has refreshToken: true
Token role: [...]
Token sub: 203cbc91-61ab-47a2-95d2-b5e1159327d7
Token email: a.tmiri@clm.foundation
...
✅ Session created successfully
=== SESSION CALLBACK END ===
```
**Frequency**: Every API call that uses `getServerSession()`
**Recommendation**: Reduce to error-only logging
---
### Notification Service Pattern
```
[NOTIFICATION_SERVICE] getNotificationCount called for user ...
[LEANTIME_ADAPTER] getNotificationCount called for userId: ...
[LEANTIME_ADAPTER] Notification counts: { total: 100, unread: 66 }
[NOTIFICATION_SERVICE] Cached notification counts for user ...
```
**Status**: ✅ Working correctly
---
## 🎯 Next Steps
1. **Immediate**: Fix session callback logging (5 minutes)
2. **Today**: Add logging to mark-as-read endpoints (10 minutes)
3. **This Week**: Test notification mark-as-read flow end-to-end
4. **Next Sprint**: Implement unified refresh system (already planned)
---
## 📌 Summary
**Overall Assessment**: ✅ **System is functioning correctly**
**Main Concerns**:
1. Excessive logging causing performance overhead
2. Missing visibility into mark-as-read operations
3. Need to verify notification count update flow
**Confidence Level**: 🟢 **HIGH** - Core functionality working, minor optimizations needed
---
**Generated**: 2026-01-01
**Analyst**: AI Code Assistant
**Next Review**: After implementing fixes

View File

@ -0,0 +1,335 @@
# Session Callback Logging - Impact Analysis
**Date**: 2026-01-01
**Purpose**: Analyze the impact of reducing session callback logging on the multi-stack architecture
---
## 🏗️ Architecture Overview
### Stack Components
1. **Next.js Dashboard** (this application)
2. **Keycloak** (SSO/Authentication provider)
3. **MinIO** (Object storage for files)
4. **External Services** (Leantime, Rocket.Chat, News API, etc.)
### Integration Points
- **Keycloak**: OAuth2/OIDC provider, session tokens, role extraction
- **MinIO**: File storage (mission logos, attachments), S3-compatible API
- **External APIs**: All require authenticated session
---
## 📋 Current Session Callback Logging
### What's Being Logged
```typescript
// Lines 407-472 in app/api/auth/options.ts
- === SESSION CALLBACK START ===
- Token error status
- Access token presence
- Refresh token presence
- Token roles
- Token sub (user ID)
- Token email
- Token name
- Token username
- User roles for session
- Creating session user object
- Setting session tokens
- ✅ Session created successfully
- Session user details
- === SESSION CALLBACK END ===
```
### Why It Was Added
**Historical Context** (from `DEBUG_502_CALLBACK.md`):
- Added specifically to debug **502 errors** with Keycloak callbacks
- Critical for diagnosing authentication failures
- Helps identify when session callback doesn't execute
- Essential for troubleshooting SSO flow issues
---
## 🔍 Impact Analysis
### 1. Keycloak Integration Impact
**Dependencies**:
- ✅ **No functional impact**: Logging doesn't affect Keycloak authentication
- ⚠️ **Debugging impact**: Removing logs makes troubleshooting harder
- ✅ **Error logging preserved**: Critical errors still logged
**Keycloak Flow**:
```
1. User authenticates → Keycloak
2. Keycloak redirects → Next.js callback
3. JWT callback extracts tokens
4. Session callback builds session ← LOGGING HERE
5. Session used for all API calls
```
**Recommendation**:
- Keep error logging (always)
- Make success logging conditional (DEBUG_SESSION flag)
---
### 2. MinIO Integration Impact
**Dependencies**:
- ✅ **No direct dependency**: MinIO doesn't use session callback logs
- ✅ **Uses session for auth**: Session object used to verify user permissions
- ✅ **No impact**: Logging changes won't affect MinIO operations
**MinIO Flow**:
```
1. API route calls getServerSession()
2. Session callback executes (builds session)
3. Session used to verify user authentication
4. MinIO operations proceed with authenticated user
```
**Recommendation**:
- ✅ **Safe to reduce logging**: No impact on MinIO functionality
---
### 3. External Services Impact
**Services**:
- Leantime (project management)
- Rocket.Chat (messaging)
- News API
- Email/IMAP
**Dependencies**:
- ✅ **No functional impact**: Services don't read logs
- ✅ **Session still created**: Logging doesn't affect session creation
- ✅ **Authentication works**: Session object still valid
**Recommendation**:
- ✅ **Safe to reduce logging**: No impact on external services
---
### 4. Monitoring & Debugging Impact
**Current Usage**:
- Debugging 502 errors (Keycloak callbacks)
- Troubleshooting authentication issues
- Monitoring session creation frequency
- Identifying session callback failures
**Impact of Reducing Logging**:
- ⚠️ **Harder to debug**: Less visibility into session creation
- ✅ **Still debuggable**: Error logging preserved
- ✅ **Can enable on-demand**: DEBUG_SESSION flag for troubleshooting
**Recommendation**:
- Use conditional logging with DEBUG_SESSION flag
- Keep error logging always enabled
- Document how to enable debug logging
---
## ✅ Safe Implementation Strategy
### Phase 1: Conditional Logging (Recommended)
**Approach**: Make success logging conditional, keep error logging always
```typescript
async session({ session, token }) {
try {
// Always log errors
if (token.error) {
console.error("❌ Session callback error:", token.error);
}
// Conditional verbose logging
const DEBUG_SESSION = process.env.DEBUG_SESSION === 'true' ||
process.env.NODE_ENV === 'development';
if (DEBUG_SESSION) {
console.log('=== SESSION CALLBACK START ===');
console.log('Token error:', token.error);
console.log('Has accessToken:', !!token.accessToken);
// ... rest of verbose logging
}
// Always log critical errors
if (token.error === "SessionNotActive" ||
token.error === "NoRefreshToken" ||
!token.accessToken ||
!token.refreshToken) {
console.log("❌ Session invalidated or tokens missing", {
error: token.error,
hasAccessToken: !!token.accessToken,
hasRefreshToken: !!token.refreshToken
});
return null as any;
}
// ... rest of callback logic
if (DEBUG_SESSION) {
console.log('✅ Session created successfully');
console.log('Session user id:', session.user.id);
console.log('=== SESSION CALLBACK END ===');
}
return session;
} catch (error) {
// Always log critical errors
console.error('❌❌❌ CRITICAL ERROR IN SESSION CALLBACK ❌❌❌');
console.error('Error:', error);
throw error;
}
}
```
**Benefits**:
- ✅ Production: Minimal logging (errors only)
- ✅ Development: Full logging for debugging
- ✅ On-demand: Enable with DEBUG_SESSION=true
- ✅ No functional impact
---
### Phase 2: Environment-Based Logging
**Alternative**: Use NODE_ENV
```typescript
const isDevelopment = process.env.NODE_ENV === 'development';
if (isDevelopment || token.error) {
// Verbose logging
}
```
**Benefits**:
- ✅ Simple implementation
- ✅ Automatic in development
- ⚠️ Less flexible than DEBUG_SESSION flag
---
## 🎯 Recommended Approach
### Option 1: DEBUG_SESSION Flag (Best)
**Implementation**:
- Add `DEBUG_SESSION` environment variable
- Default: `false` (minimal logging)
- Set to `true` when debugging needed
**Usage**:
```bash
# Production (minimal logging)
DEBUG_SESSION=false npm start
# Debugging (verbose logging)
DEBUG_SESSION=true npm start
```
**Pros**:
- ✅ Flexible (can enable on-demand)
- ✅ Production-friendly (minimal logs)
- ✅ Debug-friendly (full logs when needed)
- ✅ No code changes needed to toggle
**Cons**:
- ⚠️ Requires environment variable management
---
### Option 2: NODE_ENV Based (Simpler)
**Implementation**:
- Use `NODE_ENV === 'development'` for verbose logging
- Always log errors
**Pros**:
- ✅ Simple (no new env vars)
- ✅ Automatic (works with existing setup)
**Cons**:
- ⚠️ Less flexible (can't enable in production easily)
---
## 📊 Risk Assessment
| Risk | Impact | Mitigation |
|------|--------|------------|
| **Lost debugging capability** | Medium | Keep error logging, add DEBUG_SESSION flag |
| **Harder to troubleshoot 502 errors** | Medium | Document how to enable debug logging |
| **Performance impact** | Low | Logging overhead is minimal |
| **Functional impact** | None | Logging doesn't affect functionality |
---
## ✅ Final Recommendation
### Implementation Plan
1. **Keep Error Logging Always**
- Critical errors always logged
- Session invalidation always logged
- Exception handling always logged
2. **Make Success Logging Conditional**
- Use `DEBUG_SESSION` environment variable
- Default: `false` (production-friendly)
- Can enable: `DEBUG_SESSION=true` (debugging)
3. **Document Debugging Process**
- Add to README or troubleshooting guide
- Explain when to enable DEBUG_SESSION
- Document what logs to look for
4. **Test in Staging**
- Verify error logging still works
- Test with DEBUG_SESSION=true
- Test with DEBUG_SESSION=false
---
## 🔧 Implementation Checklist
- [ ] Update `app/api/auth/options.ts` with conditional logging
- [ ] Add `DEBUG_SESSION` to environment variable documentation
- [ ] Test error logging (should always work)
- [ ] Test success logging with DEBUG_SESSION=true
- [ ] Test success logging with DEBUG_SESSION=false
- [ ] Verify Keycloak authentication still works
- [ ] Verify MinIO operations still work
- [ ] Verify external services still work
- [ ] Update troubleshooting documentation
---
## 📝 Summary
**Impact Level**: 🟢 **LOW RISK**
**Key Findings**:
1. ✅ No functional impact on Keycloak, MinIO, or external services
2. ✅ Logging was added for debugging, not functionality
3. ✅ Error logging preserved (critical for troubleshooting)
4. ✅ Conditional logging provides flexibility
**Recommendation**:
- ✅ **Proceed with conditional logging**
- ✅ **Use DEBUG_SESSION flag for flexibility**
- ✅ **Keep error logging always enabled**
**Confidence**: 🟢 **HIGH** - Safe to implement
---
**Generated**: 2026-01-01
**Next Step**: Implement conditional logging in `app/api/auth/options.ts`

View File

@ -8,10 +8,14 @@ export async function POST(
request: Request, request: Request,
context: { params: Promise<{ id: string }> } context: { params: Promise<{ id: string }> }
) { ) {
const startTime = Date.now();
try { try {
console.log('[NOTIFICATION_API] Mark as read endpoint called');
// Authenticate user // Authenticate user
const session = await getServerSession(authOptions); const session = await getServerSession(authOptions);
if (!session || !session.user?.id) { if (!session || !session.user?.id) {
console.log('[NOTIFICATION_API] Mark as read - Authentication failed');
return NextResponse.json( return NextResponse.json(
{ error: "Not authenticated" }, { error: "Not authenticated" },
{ status: 401 } { status: 401 }
@ -22,6 +26,7 @@ export async function POST(
const params = await context.params; const params = await context.params;
const id = params?.id; const id = params?.id;
if (!id) { if (!id) {
console.log('[NOTIFICATION_API] Mark as read - Missing notification ID');
return NextResponse.json( return NextResponse.json(
{ error: "Missing notification ID" }, { error: "Missing notification ID" },
{ status: 400 } { status: 400 }
@ -29,19 +34,43 @@ export async function POST(
} }
const userId = session.user.id; const userId = session.user.id;
console.log('[NOTIFICATION_API] Mark as read - Processing', {
userId,
notificationId: id,
timestamp: new Date().toISOString()
});
const notificationService = NotificationService.getInstance(); const notificationService = NotificationService.getInstance();
const success = await notificationService.markAsRead(userId, id); const success = await notificationService.markAsRead(userId, id);
const duration = Date.now() - startTime;
if (!success) { if (!success) {
console.log('[NOTIFICATION_API] Mark as read - Failed', {
userId,
notificationId: id,
duration: `${duration}ms`
});
return NextResponse.json( return NextResponse.json(
{ error: "Failed to mark notification as read" }, { error: "Failed to mark notification as read" },
{ status: 400 } { status: 400 }
); );
} }
console.log('[NOTIFICATION_API] Mark as read - Success', {
userId,
notificationId: id,
duration: `${duration}ms`
});
return NextResponse.json({ success: true }); return NextResponse.json({ success: true });
} catch (error: any) { } catch (error: any) {
console.error('Error marking notification as read:', error); const duration = Date.now() - startTime;
console.error('[NOTIFICATION_API] Mark as read - Error', {
error: error.message,
stack: error.stack,
duration: `${duration}ms`
});
return NextResponse.json( return NextResponse.json(
{ error: "Internal server error", message: error.message }, { error: "Internal server error", message: error.message },
{ status: 500 } { status: 500 }

View File

@ -5,10 +5,14 @@ import { NotificationService } from '@/lib/services/notifications/notification-s
// POST /api/notifications/read-all // POST /api/notifications/read-all
export async function POST(request: Request) { export async function POST(request: Request) {
const startTime = Date.now();
try { try {
console.log('[NOTIFICATION_API] Mark all as read endpoint called');
// Authenticate user // Authenticate user
const session = await getServerSession(authOptions); const session = await getServerSession(authOptions);
if (!session || !session.user?.id) { if (!session || !session.user?.id) {
console.log('[NOTIFICATION_API] Mark all as read - Authentication failed');
return NextResponse.json( return NextResponse.json(
{ error: "Not authenticated" }, { error: "Not authenticated" },
{ status: 401 } { status: 401 }
@ -16,19 +20,40 @@ export async function POST(request: Request) {
} }
const userId = session.user.id; const userId = session.user.id;
console.log('[NOTIFICATION_API] Mark all as read - Processing', {
userId,
timestamp: new Date().toISOString()
});
const notificationService = NotificationService.getInstance(); const notificationService = NotificationService.getInstance();
const success = await notificationService.markAllAsRead(userId); const success = await notificationService.markAllAsRead(userId);
const duration = Date.now() - startTime;
if (!success) { if (!success) {
console.log('[NOTIFICATION_API] Mark all as read - Failed', {
userId,
duration: `${duration}ms`
});
return NextResponse.json( return NextResponse.json(
{ error: "Failed to mark all notifications as read" }, { error: "Failed to mark all notifications as read" },
{ status: 400 } { status: 400 }
); );
} }
console.log('[NOTIFICATION_API] Mark all as read - Success', {
userId,
duration: `${duration}ms`
});
return NextResponse.json({ success: true }); return NextResponse.json({ success: true });
} catch (error: any) { } catch (error: any) {
console.error('Error marking all notifications as read:', error); const duration = Date.now() - startTime;
console.error('[NOTIFICATION_API] Mark all as read - Error', {
error: error.message,
stack: error.stack,
duration: `${duration}ms`
});
return NextResponse.json( return NextResponse.json(
{ error: "Internal server error", message: error.message }, { error: "Internal server error", message: error.message },
{ status: 500 } { status: 500 }

0
log Normal file
View File