Merge pull request #299 from codex-team/chore/logs-and-optimization

Update logs

Author: 7eliassen

app-config.yaml

@@ -28,6 +28,8 @@ logging:
   appServer: info
   database: info
   s3Storage: info
+  middlewares: info
+  policies: info
 
 s3:
   accessKeyId: 'secret'

eslint.config.mjs

@@ -77,6 +77,9 @@ export default [
       'n/no-unsupported-features/es-builtins': ['error', {
         version: '>=22.1.0',
       }],
+      'n/no-unsupported-features/node-builtins': ['error', {
+        version: '>=22.1.0',
+      }],
       '@typescript-eslint/naming-convention': ['error', {
         selector: 'property',
         format: ['camelCase', 'PascalCase'],

src/infrastructure/config/index.ts

@@ -91,6 +91,8 @@ export const LoggingConfig = z.object({
   appServer: LoggingLevel,
   database: LoggingLevel,
   s3Storage: LoggingLevel,
+  middlewares: LoggingLevel,
+  policies: LoggingLevel,
 });
 
 export type LoggingConfig = z.infer<typeof LoggingConfig>;
@@ -161,6 +163,8 @@ const defaultConfig: AppConfig = {
     appServer: 'info',
     database: 'info',
     s3Storage: 'info',
+    middlewares: 'info',
+    policies: 'info',
   },
   database: {
     dsn: 'postgres://user:pass@postgres/codex-notes',

src/infrastructure/logging/index.ts

@@ -2,6 +2,7 @@ import { pino } from 'pino';
 import * as process from 'process';
 import type { LoggingConfig } from '../config/index.js';
 import appConfig from '../config/index.js';
+import { getCurrentReqId } from './reqId.context.js';
 
 const loggerConfig = process.env['NODE_ENV'] === 'production'
   ? {}
@@ -16,11 +17,19 @@ const loggerConfig = process.env['NODE_ENV'] === 'production'
 
 const rootLogger = pino(loggerConfig);
 
+const loggerCache = new Map<keyof LoggingConfig, pino.Logger>();
+
 /**
  * Creates child logger and returns it.
  * @param moduleName - name of the module that is logging
  */
 export function getLogger(moduleName: keyof LoggingConfig): pino.Logger {
+  const cachedLogger = loggerCache.get(moduleName);
+
+  if (cachedLogger) {
+    return cachedLogger;
+  }
+
   const childLogger = rootLogger.child({
     module: moduleName,
   });
@@ -33,9 +42,29 @@ export function getLogger(moduleName: keyof LoggingConfig): pino.Logger {
 
   childLogger.level = logLevel;
 
+  loggerCache.set(moduleName, childLogger);
+
   return childLogger;
 }
 
+/**
+ * Creates a request-scoped logger that includes the request ID
+ * @param moduleName - name of the module that is logging
+ * @returns Logger instance with request ID context
+ */
+export function getRequestLogger(moduleName: keyof LoggingConfig): pino.Logger {
+  const baseLogger = getLogger(moduleName);
+  const reqId = getCurrentReqId();
+
+  if (reqId != null && reqId !== '') {
+    return baseLogger.child({
+      reqId,
+    });
+  }
+
+  return baseLogger;
+}
+
 const logger = getLogger('global');
 
 export default logger;

src/infrastructure/logging/reqId.context.ts

@@ -0,0 +1,24 @@
+import { AsyncLocalStorage } from 'node:async_hooks';
+
+/**
+ * Context for storing reqId within asynchronous operations
+ */
+interface RequestContext {
+  reqId?: string;
+}
+
+/**
+ * AsyncLocalStorage for storing request context
+ * Allows tying database logs to the corresponding request
+ */
+export const requestContextStorage = new AsyncLocalStorage<RequestContext>();
+
+/**
+ * Gets the current reqId from the execution context
+ * @returns reqId or undefined if context is not set
+ */
+export function getCurrentReqId(): string | undefined {
+  const context = requestContextStorage.getStore();
+
+  return context?.reqId;
+}

src/presentation/http/http-api.ts

@@ -9,6 +9,7 @@ import { fastifyOauth2 } from '@fastify/oauth2';
 import fastifySwagger from '@fastify/swagger';
 import fastifySwaggerUI from '@fastify/swagger-ui';
 import addUserIdResolver from '@presentation/http/middlewares/common/userIdResolver.js';
+import addReqIdContext from '@presentation/http/middlewares/common/reqIdContext.js';
 import cookie from '@fastify/cookie';
 import { notFound, forbidden, unauthorized, notAcceptable, domainError } from './decorators/index.js';
 import NoteRouter from '@presentation/http/router/note.js';
@@ -324,7 +325,8 @@ export default class HttpApi implements Api {
       throw new Error('Server is not initialized');
     }
 
-    addUserIdResolver(this.server, domainServices.authService, appServerLogger);
+    addReqIdContext(this.server);
+    addUserIdResolver(this.server, domainServices.authService);
   }
 
   /**

src/presentation/http/middlewares/common/reqIdContext.ts

@@ -0,0 +1,18 @@
+import type { FastifyInstance } from 'fastify';
+import { requestContextStorage } from '@infrastructure/logging/reqId.context.js';
+
+/**
+ * Adds middleware to set reqId context at the beginning of each request
+ * @param server - fastify instance
+ */
+export default function addReqIdContext(server: FastifyInstance): void {
+  /**
+   * Sets reqId context for all asynchronous operations within the request
+   * Uses 'onRequest' hook so context is available in all subsequent hooks and handlers
+   */
+  server.addHook('onRequest', (request, _reply, done) => {
+    requestContextStorage.run({ reqId: request.id }, () => {
+      done();
+    });
+  });
+}

src/presentation/http/middlewares/common/userIdResolver.ts

@@ -1,15 +1,14 @@
 import type { FastifyInstance } from 'fastify';
 import type AuthService from '@domain/service/auth.js';
-import type Logger from '@infrastructure/logging/index.js';
 import { notEmpty } from '@infrastructure/utils/empty.js';
+import { getRequestLogger } from '@infrastructure/logging/index.js';
 
 /**
  * Add middleware for resolve userId from Access Token and add it to request
  * @param server - fastify instance
  * @param authService - auth domain service
- * @param logger - logger instance
  */
-export default function addUserIdResolver(server: FastifyInstance, authService: AuthService, logger: typeof Logger): void {
+export default function addUserIdResolver(server: FastifyInstance, authService: AuthService): void {
   /**
    * Default userId value — null
    */
@@ -19,13 +18,15 @@ export default function addUserIdResolver(server: FastifyInstance, authService:
    * Resolve userId from Access Token on each request
    */
   server.addHook('preHandler', (request, _reply, done) => {
+    const logger = getRequestLogger('middlewares').child({ middleware: 'userIdResolver' });
     const authorizationHeader = request.headers.authorization;
 
     if (notEmpty(authorizationHeader)) {
       const token = authorizationHeader.replace('Bearer ', '');
 
       try {
         request.userId = authService.verifyAccessToken(token)['id'];
+        logger.debug('User ID resolved from Access Token');
       } catch (error) {
         logger.error('Invalid Access Token');
         logger.error(error);

src/presentation/http/middlewares/note/useNoteResolver.ts

@@ -3,7 +3,7 @@ import type NoteService from '@domain/service/note.js';
 import { notEmpty } from '@infrastructure/utils/empty.js';
 import { StatusCodes } from 'http-status-codes';
 import hasProperty from '@infrastructure/utils/hasProperty.js';
-import { getLogger } from '@infrastructure/logging/index.js';
+import { getRequestLogger } from '@infrastructure/logging/index.js';
 import type { Note, NotePublicId } from '@domain/entities/note.js';
 
 /**
@@ -18,11 +18,6 @@ export default function useNoteResolver(noteService: NoteService): {
    */
   noteResolver: preHandlerHookHandler;
 } {
-  /**
-   * Get logger instance
-   */
-  const logger = getLogger('appServer');
-
   /**
    * Search for Note by public id in passed payload and resolves a note by it
    * @param requestData - fastify request data. Can be query, params or body
@@ -40,6 +35,7 @@ export default function useNoteResolver(noteService: NoteService): {
 
   return {
     noteResolver: async function noteIdResolver(request, reply) {
+      const logger = getRequestLogger('middlewares').child({ middleware: 'noteResolver' });
       let note: Note | undefined;
 
       let statusCode = StatusCodes.NOT_ACCEPTABLE;
@@ -59,6 +55,7 @@ export default function useNoteResolver(noteService: NoteService): {
 
         if (note) {
           request.note = note;
+          logger.debug('Note resolved by public ID');
         } else {
           throw new Error('Note not found');
         }

src/presentation/http/middlewares/noteSettings/useMemberRoleResolver.ts

@@ -1,5 +1,5 @@
 import type { preHandlerHookHandler } from 'fastify';
-import { getLogger } from '@infrastructure/logging/index.js';
+import { getRequestLogger } from '@infrastructure/logging/index.js';
 import type NoteSettingsService from '@domain/service/noteSettings.js';
 import type { MemberRole } from '@domain/entities/team.js';
 import { isEmpty } from '@infrastructure/utils/empty.js';
@@ -16,13 +16,9 @@ export default function useMemberRoleResolver(noteSettingsService: NoteSettingsS
    */
   memberRoleResolver: preHandlerHookHandler;
 } {
-  /**
-   * Get logger instance
-   */
-  const logger = getLogger('appServer');
-
   return {
     memberRoleResolver: async function memberRoleResolver(request, reply) {
+      const logger = getRequestLogger('middlewares').child({ middleware: 'memberRoleResolver' });
       /** If MemberRole equals null, it means that user is not in the team or is not authenticated */
       let memberRole: MemberRole | undefined;
 
@@ -40,9 +36,14 @@ export default function useMemberRoleResolver(noteSettingsService: NoteSettingsS
 
         if (memberRole !== undefined) {
           request.memberRole = memberRole;
+          logger.debug('Member role resolved');
         }
       } catch (error) {
-        logger.error('Can not resolve Member role by note [id = ${request.note.id}] and user [id = ${request.userId}]');
+        if (request.note != null && request.userId != null) {
+          logger.error(`Cannot resolve Member role by note [id = ${request.note.id}] and user [id = ${request.userId}]`);
+        } else {
+          logger.error('Cannot resolve Member role - note or user ID not available');
+        }
         logger.error(error);
 
         await reply.notAcceptable('Team member not found');