refactor(logging): fix duplicate logging and add service visibility (#210)

asithade · web-flow · commit 1cb6ac829366 · 2025-12-16T15:27:40.000-06:00
* refactor(logging): migrate to singleton logger service - Created LoggerService singleton with WeakMap-based operation tracking - Prevents duplicate logs and memory leaks - CloudWatch-optimized structured JSON logging - Updated 10 controllers, 2 middleware, 7 services, 2 utils - Improved error handling with centralized error middleware logging - Removed redundant error logs before next(error) calls - Net reduction of 706 lines LFXV2-903 Generated with [Claude Code](https://claude.ai/code) Signed-off-by: Asitha de Silva <asithade@gmail.com> * refactor(logging): extend logger service for infrastructure operations Extended LoggerService to support both request-scoped and infrastructure operations by making req parameter optional. Migrated all 41 direct serverLogger calls across services, utilities, and routes to use the unified logger service pattern. Changes: - Extended LoggerService methods to accept Request | undefined - Migrated 11 request-scoped operations to pass req parameter - Migrated 30 infrastructure operations to use logger with undefined - Updated ai.service, user.service, project.service method signatures - Replaced serverLogger calls in nats, snowflake, lock-manager services - Updated CLAUDE.md with comprehensive logging documentation - Removed serverLogger imports from all service/utility files Benefits: - Unified logging interface for all operations - Better request correlation when context available - Consistent error handling with err field - Infrastructure operations now use same pattern LFXV2-903 Signed-off-by: Asitha de Silva <asithade@gmail.com> * docs(logging): update docs for infrastructure logging Updated logging-monitoring.md to reflect the new dual-mode logger service that supports both request-scoped and infrastructure operations. Added documentation for the new server-logger.ts file that breaks the circular dependency between server.ts and logger.service.ts. Changes: - Added logging architecture layers diagram showing server-logger.ts - Updated all method signatures to show req | undefined pattern - Added infrastructure logging examples for all methods - Documented circular dependency resolution - Clarified when to use request-scoped vs infrastructure logging LFXV2-903 Signed-off-by: Asitha de Silva <asithade@gmail.com> * refactor(meetings): move agenda generation to controller Moved AI agenda generation logic from inline route handler to MeetingController.generateAgenda method for better separation of concerns and consistency with other route patterns. Also improved logger usage in middleware and services: - auth.middleware: better error tracking with startTime - error-handler.middleware: use operation startTime when available - access-check.service: move startOperation before try block - etag.service: use debug instead of silent startOperation - persona-helper: use success/error instead of warning LFXV2-903 Signed-off-by: Asitha de Silva <asithade@gmail.com> * docs(logging): update architecture diagram for server-logger Updated CLAUDE.md logging architecture diagram to reflect the new server-logger.ts file that breaks the circular dependency between server.ts and logger.service.ts. LFXV2-903 Signed-off-by: Asitha de Silva <asithade@gmail.com> * fix: claude.md linting issues Signed-off-by: Asitha de Silva <asithade@gmail.com> * refactor(meetings): standardize generateAgenda error handling LFXV2-903 Use ServiceValidationError.fromFieldErrors() and next() for validation errors instead of manual 400 response, consistent with other controller methods. Provides field-level error details and centralized error handling through middleware. Signed-off-by: Asitha de Silva <asithade@gmail.com> * fix: linting issues for docs Signed-off-by: Asitha de Silva <asithade@gmail.com> * refactor(logging): fix duplicate logging and add service visibility - Added logger.info() method for significant business operations - Fixed 8 duplicate startOperation calls in meeting service - Added comprehensive logging to 7 methods without logging - Enhanced access-check service with debug logging - Updated CLAUDE.md with logging layer responsibility guidelines Pattern established: - Controllers: startOperation/success/error for HTTP operations - Services: debug for tracing, info for significant operations, warning for graceful errors Impact: Eliminated 32 duplicate log entries, added production visibility for V1→V2 transformations and data enrichment operations JIRA: LFXV2-903 Signed-off-by: Asitha de Silva <asithade@gmail.com> * refactor(logging): fix processRegistrantOperations error logging - Remove unused _startTime parameter from method signature - Add proper error logging for 403 and partial failure scenarios - Update all call sites to remove startTime parameter - Follow logging standards with err field and structured metadata Generated with [Claude Code](https://claude.ai/code) Signed-off-by: Asitha de Silva <asithade@gmail.com> --------- Signed-off-by: Asitha de Silva <asithade@gmail.com>
diff --git a/CLAUDE.md b/CLAUDE.md
@@ -129,6 +129,7 @@ logger.success(undefined, 'nats_connect', startTime, metadata);
 - `logger.startOperation(req|undefined, 'operation', metadata, options?)` → Returns startTime, logs at INFO (silent option available)
 - `logger.success(req|undefined, 'operation', startTime, metadata)` → Logs at INFO with duration
 - `logger.error(req|undefined, 'operation', startTime, error, metadata, options?)` → Logs at ERROR with 'err' field
+- `logger.info(req|undefined, 'operation', message, metadata)` → Logs at INFO for significant operations
 - `logger.warning(req|undefined, 'operation', message, metadata)` → Logs at WARN
 - `logger.validation(req|undefined, 'operation', errors[], metadata)` → Logs at ERROR with validation details
 - `logger.debug(req|undefined, 'operation', message, metadata)` → Logs at DEBUG
@@ -139,6 +140,34 @@ logger.success(undefined, 'nats_connect', startTime, metadata);
 - **Request-scoped** (pass `req`): Controllers, route handlers, service methods called from routes
 - **Infrastructure** (pass `undefined`): NATS connections, Snowflake pool, server startup/shutdown, scheduled jobs
 
+### Logging Layer Responsibility
+
+**Controllers (HTTP Boundary):**
+
+- ✅ **Always** use `logger.startOperation()` / `logger.success()` / `logger.error()` for HTTP operations
+- Operation names should match HTTP semantics (e.g., `get_meeting_rsvps`, `create_meeting`)
+- Duration represents full HTTP request → response cycle
+- One startOperation per HTTP endpoint
+
+**Services (Business Logic):**
+
+- ✅ **Always** use `logger.debug()` for step-by-step tracing
+- ✅ Use `logger.info()` for significant business operations visible in production:
+  - Data transformations (V1→V2 conversions)
+  - Data enrichment (adding project names, committee data)
+  - Complex multi-step orchestrations
+  - Operations with notable business impact
+- ✅ Use `logger.warning()` for recoverable errors when returning null/empty arrays
+- ❌ **Never** use `logger.startOperation()` with the same operation name as the calling controller
+- ❌ **Never** call `serverLogger` directly
+
+**Why This Pattern:**
+
+- Prevents duplicate logging (no double startOperation calls)
+- Clear separation: Controllers log HTTP, Services log business logic
+- Production visibility: INFO logs for significant operations, DEBUG for detailed tracing
+- Consistent duration semantics: HTTP duration in controllers, not inflated by double-counting
+
 ### Error Logging Standard
 
 **Always use `err` field** for proper error serialization:
@@ -165,27 +194,34 @@ req.log.error({ error: error }, 'message'); // Should use logger service
 
 ### Log Level Guidelines
 
-**INFO** - Business operation completions:
+**INFO** - Business operation completions and significant operations:
 
-- Successful data operations (created, updated, deleted, fetched)
-- Important state changes
-- Operation success with duration
+- **In Controllers**: HTTP operation success with duration (via `startOperation` / `success`)
+- **In Services**: Significant business operations visible in production (via `logger.info()`):
+  - Data transformations (V1→V2 conversions)
+  - Data enrichment (project names, committee data)
+  - Complex orchestrations
+  - Operations with notable business impact
 
 **WARN** - Recoverable issues:
 
-- Error conditions leading to exceptions
+- Error conditions with graceful degradation (returning null/empty arrays)
 - Data quality issues, user not found
 - Fallback behaviors, NATS failures with graceful handling
+- Service errors that don't propagate to controller
 
-**DEBUG** - Internal operations:
+**DEBUG** - Internal operations and tracing:
 
+- **In Services**: Step-by-step operation tracing
+- Method entry/exit with key parameters
 - Preparation steps (sanitizing, creating payload)
 - Internal lookups (NATS, database queries)
-- Intent statements (resolving, fetching)
+- Simple data fetches
 - Infrastructure operations (connections, pool state)
 
 **ERROR** - Critical failures:
 
+- **In Controllers**: HTTP operation failures (via `logger.error()` with startTime)
 - System failures, unhandled exceptions
 - Critical errors requiring immediate attention
 - Operations that cannot continue
@@ -246,25 +282,77 @@ export const getUser = async (req: Request, res: Response, next: NextFunction) =
 };
 ```
 
-**Service Method with Request Context:**
+**Service Method - Simple (DEBUG only):**
+
+```typescript
+public async getUserById(req: Request, userId: string): Promise<User> {
+  logger.debug(req, 'get_user_by_id', 'Fetching user from database', { userId });
+
+  const user = await this.database.findUser(userId);
+
+  return user;
+}
+```
+
+**Service Method - Complex (INFO + DEBUG):**
+
+```typescript
+public async getMeetings(req: Request, query: QueryParams): Promise<Meeting[]> {
+  logger.debug(req, 'get_meetings', 'Starting meeting fetch', { query });
+
+  const { resources } = await this.microserviceProxy.proxyRequest(...);
+
+  logger.debug(req, 'get_meetings', 'Fetched resources', { count: resources.length });
+
+  // Significant transformation - use INFO level for production visibility
+  if (isV1) {
+    logger.info(req, 'transform_v1_meetings', 'Transforming V1 meetings to V2 format', {
+      count: resources.length,
+    });
+    meetings = meetings.map(transformV1MeetingToV2);
+  }
+
+  // Enrichment step - DEBUG for tracing
+  logger.debug(req, 'get_meetings', 'Enriching with project names', { count: meetings.length });
+  meetings = await this.enrichWithProjects(req, meetings);
+
+  // Significant enrichment - use INFO level
+  if (meetings.some((m) => m.committees?.length > 0)) {
+    logger.info(req, 'enrich_committees', 'Enriching meetings with committee data', {
+      total_meetings: meetings.length,
+    });
+    meetings = await this.getMeetingCommittees(req, meetings);
+  }
+
+  logger.debug(req, 'get_meetings', 'Completed meeting fetch', { final_count: meetings.length });
+
+  return meetings;
+}
+```
+
+**Service Method - Graceful Error Handling:**
 
 ```typescript
-public async updateUser(req: Request, userId: string, data: UpdateData): Promise<User> {
-  const startTime = logger.startOperation(req, 'update_user', { userId });
+public async getPastMeetingRecording(req: Request, meetingUid: string): Promise<Recording | null> {
+  logger.debug(req, 'get_past_meeting_recording', 'Fetching recording', { meeting_uid: meetingUid });
 
   try {
-    // Validation
-    if (!data.email) {
-      logger.validation(req, 'update_user', ['Email required'], { userId });
-      throw new ValidationError('Email required');
+    const { resources } = await this.microserviceProxy.proxyRequest(...);
+
+    if (!resources || resources.length === 0) {
+      logger.warning(req, 'get_past_meeting_recording', 'No recording found', {
+        meeting_uid: meetingUid,
+      });
+      return null;
     }
 
-    const user = await this.performUpdate(userId, data);
-    logger.success(req, 'update_user', startTime, { userId, updatedFields: Object.keys(data) });
-    return user;
+    return resources[0].data;
   } catch (error) {
-    logger.error(req, 'update_user', startTime, error, { userId });
-    throw error;
+    logger.warning(req, 'get_past_meeting_recording', 'Failed to fetch recording, returning null', {
+      meeting_uid: meetingUid,
+      error: error instanceof Error ? error.message : 'Unknown error',
+    });
+    return null;
   }
 }
 ```
@@ -311,10 +399,18 @@ private async fetchFromNats(req: Request, slug: string): Promise<Project> {
 - [ ] Operation name in snake_case?
 - [ ] Sensitive data sanitized?
 
-**For operations with duration:**
+**For Controllers:**
 
-- [ ] Called `logger.startOperation()` and captured `startTime`?
+- [ ] Using `logger.startOperation()` for HTTP operations?
 - [ ] Calling `logger.success()` or `logger.error()` with `startTime`?
+- [ ] Not duplicating service-level logging?
+
+**For Services:**
+
+- [ ] Using `logger.debug()` for step-by-step tracing?
+- [ ] Using `logger.info()` for significant operations (transformations, enrichments)?
+- [ ] Using `logger.warning()` for graceful error handling (returning null/empty)?
+- [ ] NOT using `logger.startOperation()` if controller already logs the same operation?
 - [ ] Passing relevant metadata for debugging?
 - All shared types, interfaces, and constants are centralized in @lfx-one/shared package
 - **AI Service Integration**: Claude Sonnet 4 model via LiteLLM proxy for meeting agenda generation
diff --git a/apps/lfx-one/src/server/controllers/meeting.controller.ts b/apps/lfx-one/src/server/controllers/meeting.controller.ts
@@ -426,14 +426,8 @@ export class MeetingController {
 
       // Process registrants with fail-fast for 403 errors
       // This will stop the processing if a 403 error is encountered
-      const { results, shouldReturn } = await this.processRegistrantOperations(
-        req,
-        next,
-        startTime,
-        'add_meeting_registrants',
-        uid,
-        registrantData,
-        (registrant) => this.meetingService.addMeetingRegistrant(req, registrant)
+      const { results, shouldReturn } = await this.processRegistrantOperations(req, next, 'add_meeting_registrants', uid, registrantData, (registrant) =>
+        this.meetingService.addMeetingRegistrant(req, registrant)
       );
 
       // If the processing should return, return
@@ -527,7 +521,7 @@ export class MeetingController {
       }
 
       // Process updates with fail-fast for 403 errors
-      const { results, shouldReturn } = await this.processRegistrantOperations(req, next, startTime, 'update_meeting_registrants', uid, updateData, (update) =>
+      const { results, shouldReturn } = await this.processRegistrantOperations(req, next, 'update_meeting_registrants', uid, updateData, (update) =>
         this.meetingService.updateMeetingRegistrant(req, uid, update.uid, update.changes)
       );
 
@@ -616,14 +610,8 @@ export class MeetingController {
 
       // Process deletions with fail-fast for 403 errors
       // This will stop the processing if a 403 error is encountered
-      const { results, shouldReturn } = await this.processRegistrantOperations(
-        req,
-        next,
-        startTime,
-        'delete_meeting_registrants',
-        uid,
-        registrantsUid,
-        (registrantUid) => this.meetingService.deleteMeetingRegistrant(req, uid, registrantUid).then(() => registrantUid)
+      const { results, shouldReturn } = await this.processRegistrantOperations(req, next, 'delete_meeting_registrants', uid, registrantsUid, (registrantUid) =>
+        this.meetingService.deleteMeetingRegistrant(req, uid, registrantUid).then(() => registrantUid)
       );
 
       // If the processing should return, return
@@ -1232,7 +1220,6 @@ export class MeetingController {
   private async processRegistrantOperations<T, R>(
     req: Request,
     next: NextFunction,
-    _startTime: number,
     operationName: string,
     meetingUid: string,
     inputData: T[],
@@ -1268,12 +1255,24 @@ export class MeetingController {
       // Check if it's a 403 error - if so, fail fast
       // This will stop the processing if a 403 error is encountered
       if (error?.status === 403 || error?.statusCode === 403) {
+        logger.error(req, `${operationName}_batch_processing`, helperStartTime, error, {
+          meeting_uid: meetingUid,
+          batch_size: inputData.length,
+          error_type: '403_forbidden',
+        });
         // Send the error to the next middleware
         next(error);
         return { results: [], shouldReturn: true };
       }
 
-      // For other errors, continue processing the remaining items
+      // For other errors, log and continue processing the remaining items
+      logger.error(req, `${operationName}_batch_processing`, helperStartTime, error, {
+        meeting_uid: meetingUid,
+        batch_size: inputData.length,
+        error_type: 'partial_failure',
+        continuing: true,
+      });
+
       let results: PromiseSettledResult<R>[] = [{ status: 'rejected', reason: error }];
 
       if (inputData.length > 1) {
diff --git a/apps/lfx-one/src/server/services/access-check.service.ts b/apps/lfx-one/src/server/services/access-check.service.ts
@@ -165,6 +165,12 @@ export class AccessCheckService {
     resourceType: AccessCheckResourceType,
     accessType: AccessCheckAccessType = 'writer'
   ): Promise<T & { writer?: boolean }> {
+    logger.debug(req, 'add_access_to_resource', 'Adding access to resource', {
+      resource_type: resourceType,
+      resource_id: resource.uid,
+      access_type: accessType,
+    });
+
     const hasAccess = await this.checkSingleAccess(req, {
       resource: resourceType,
       id: resource.uid,
diff --git a/apps/lfx-one/src/server/services/logger.service.ts b/apps/lfx-one/src/server/services/logger.service.ts
@@ -360,6 +360,42 @@ export class LoggerService {
     );
   }
 
+  /**
+   * Logs info messages with operation context
+   * Use for significant business operations that should be visible in production
+   * @param req - Request object (optional - use undefined for infrastructure operations)
+   */
+  public info(req: Request | undefined, operation: string, message: string, metadata: Record<string, unknown> = {}): void {
+    // Extract err from metadata to place at top level for proper error serialization
+    const { err, ...rest } = metadata;
+
+    // Infrastructure logging (no request context)
+    if (!req) {
+      serverLogger.info(
+        {
+          operation,
+          status: 'info',
+          ...(err ? { err } : {}), // err at top level for Pino error serializer
+          ...(Object.keys(rest).length > 0 && { data: rest }),
+        },
+        `${this.formatOperation(operation)}: ${message}`
+      );
+      return;
+    }
+
+    // Request-scoped logging
+    req.log.info(
+      {
+        operation,
+        status: 'info',
+        request_id: req.id,
+        ...(err ? { err } : {}), // err at top level for Pino error serializer
+        ...(Object.keys(rest).length > 0 && { data: rest }),
+      },
+      `${this.formatOperation(operation)}: ${message}`
+    );
+  }
+
   /**
    * Logs debug messages with operation context
    * Use for detailed internal state, preparation steps, or verbose information
diff --git a/apps/lfx-one/src/server/services/meeting.service.ts b/apps/lfx-one/src/server/services/meeting.service.ts
