feat: logs pass (#57)

* refactor: added many logs

* feat: added operationId to http log

package.json

@@ -46,7 +46,7 @@
     "@apidevtools/json-schema-ref-parser": "^11.5.4",
     "@godaddy/terminus": "^4.12.1",
     "@map-colonies/error-express-handler": "^2.1.0",
-    "@map-colonies/express-access-log-middleware": "^2.0.1",
+    "@map-colonies/express-access-log-middleware": "^2.1.0",
     "@map-colonies/js-logger": "^1.0.1",
     "@map-colonies/openapi-express-viewer": "^3.0.0",
     "@map-colonies/read-pkg": "0.0.1",
@@ -69,6 +69,7 @@
     "express-openapi-validator": "^5.0.4",
     "http-status-codes": "^2.2.0",
     "json-pointer": "0.6.2",
+    "lodash": "^4.17.21",
     "pg": "^8.11.5",
     "reflect-metadata": "^0.1.13",
     "tsyringe": "^4.8.0"
@@ -87,6 +88,7 @@
     "@types/express": "^4.17.17",
     "@types/jest": "^29.5.2",
     "@types/json-pointer": "^1.0.34",
+    "@types/lodash": "^4.17.12",
     "@types/multer": "^1.4.7",
     "@types/pg": "^8.11.5",
     "@types/supertest": "^2.0.12",

src/common/logger.ts

@@ -0,0 +1,60 @@
+import { AsyncLocalStorage } from 'node:async_hooks';
+import type { IncomingMessage, ServerResponse } from 'node:http';
+import { get } from 'lodash';
+import jsLogger, { Logger, LoggerOptions } from '@map-colonies/js-logger';
+import { getOtelMixin } from '@map-colonies/telemetry';
+import { NextFunction, Request, Response } from 'express';
+import { DependencyContainer } from 'tsyringe';
+import { SERVICES } from './constants';
+import { IConfig } from './interfaces';
+
+const logContext = new AsyncLocalStorage<object>();
+
+export function addOperationIdToLog(req: IncomingMessage, res: ServerResponse, loggableObject: Record<string, unknown>): unknown {
+  const operationId = get(req, 'openapi.schema.operationId') as string | undefined;
+  if (operationId !== undefined) {
+    loggableObject['operationId'] = operationId;
+  }
+  return loggableObject;
+}
+
+export function enrichLogContext(values: object): void {
+  const store = logContext.getStore();
+  if (store) {
+    Object.assign(store, values);
+  }
+}
+
+export function loggerFactory(container: DependencyContainer): Logger {
+  const config = container.resolve<IConfig>(SERVICES.CONFIG);
+  const loggerConfig = config.get<LoggerOptions>('telemetry.logger');
+
+  const logger = jsLogger({
+    ...loggerConfig,
+    mixin: (mergeObj, level) => {
+      const otelMixin = getOtelMixin();
+      const store = logContext.getStore();
+      return { ...otelMixin(mergeObj, level), ...store };
+    },
+  });
+
+  return logger;
+}
+
+export function logContextInjectionMiddleware(req: Request, res: Response, next: NextFunction): void {
+  logContext.run({}, () => {
+    next();
+  });
+}
+
+export function logEnrichmentParamMiddlewareFactory(
+  logEntry: string
+): (req: Request, res: Response, next: NextFunction, paramValue: unknown) => void {
+  return function (req: Request, res: Response, next: NextFunction, paramValue: unknown): void {
+    // eslint-disable-next-line @typescript-eslint/strict-boolean-expressions
+    if (paramValue) {
+      enrichLogContext({ [logEntry]: paramValue });
+    }
+    next();
+  };
+}

src/configs/controllers/configController.ts

@@ -16,6 +16,7 @@ import {
   SortQueryRepeatError,
 } from '../models/errors';
 import { SchemaNotFoundError } from '../../schemas/models/errors';
+import { enrichLogContext } from '../../common/logger';
 
 function configMapper(config: Config): components['schemas']['config'] {
   return {
@@ -111,6 +112,8 @@ export class ConfigController {
 
   public postConfig: TypedRequestHandler<'/config', 'post'> = async (req, res, next) => {
     try {
+      enrichLogContext({ configName: req.body.configName, version: req.body.version, schemaId: req.body.schemaId });
+
       await this.manager.createConfig(req.body);
       return res.status(httpStatus.CREATED).json();
     } catch (error) {

src/configs/models/configManager.ts

@@ -6,6 +6,7 @@ import { parseISO } from 'date-fns';
 import type { Prettify } from '../../common/interfaces';
 import { ConfigRepository, ConfigSearchParams, SqlPaginationParams } from '../repositories/configRepository';
 import { SERVICES } from '../../common/constants';
+import { enrichLogContext } from '../../common/logger';
 import { paths, components } from '../../openapiTypes';
 import { Config, SortOption } from './config';
 import { Validator } from './configValidator';
@@ -24,29 +25,39 @@ export class ConfigManager {
 
   public async getConfig(name: string, version?: number, shouldDereferenceConfig?: boolean): Promise<Config> {
     if (shouldDereferenceConfig !== true) {
+      this.logger.debug('Retrieving config from the database with unresolved refs');
       const config = await this.configRepository.getConfig(name, version);
 
       if (!config) {
         throw new ConfigNotFoundError('Config not found');
       }
+
+      enrichLogContext({ resolvedConfigVersion: config.version });
       return config;
     }
 
+    this.logger.debug('Retrieving config from the database with resolved refs');
+
     const res = await this.configRepository.getConfigRecursive(name, version);
     if (!res) {
       throw new ConfigNotFoundError('Config not found');
     }
 
+    enrichLogContext({ resolvedConfigVersion: res[0].version });
+
     const [config, refs] = res;
 
     if (refs.length > 0) {
+      this.logger.debug('Resolving refs for config', { refCount: refs.length });
       this.replaceRefs(config.config, refs);
     }
 
     return config;
   }
 
   public async getConfigs(options?: GetConfigOptions): Promise<{ configs: Config[]; totalCount: number }> {
+    this.logger.debug('Preparing search params and retrieving configs from the database');
+
     const searchParams: ConfigSearchParams = {};
     let paginationParams: SqlPaginationParams = {};
     let sortParams: SortOption[] = [];
@@ -75,6 +86,9 @@ export class ConfigManager {
   }
 
   public async createConfig(config: Omit<components['schemas']['config'], 'createdAt' | 'createdBy'>): Promise<void> {
+    this.logger.debug('Creating a new config');
+
+    this.logger.debug('fetching latest config with same name for validations');
     const latestConfig = await this.configRepository.getConfig(config.configName);
 
     if (!latestConfig && config.version !== 1) {
@@ -106,6 +120,7 @@ export class ConfigManager {
     }
 
     if (latestConfig !== undefined) {
+      this.logger.debug('a config with the same name already exists, incrementing version');
       config.version++;
     }
 
@@ -119,6 +134,7 @@ export class ConfigManager {
    * @throws {ConfigValidationError} If the config reference is not valid.
    */
   private listConfigRefs(config: components['schemas']['config']['config']): ConfigReference[] {
+    this.logger.debug('Listing all the config references in the config object');
     const refs: ConfigReference[] = [];
 
     pointer.walk(config, (val, key) => {
@@ -143,19 +159,24 @@ export class ConfigManager {
    * @throws {ConfigValidationError} If the configuration is not valid.
    */
   private replaceRefs(obj: JsonObject, refs: Awaited<ReturnType<typeof this.configRepository.getAllConfigRefs>>): void {
+    this.logger.debug('Replacing all the references in the object with the corresponding values');
+
     // the input is not an object or an array so we don't need to do anything
     if (!Array.isArray(obj) && typeof obj !== 'object') {
+      this.logger.debug('The object is not an object or an array, skipping');
       return;
     }
 
     const paths = new Map<string, ConfigReference>();
 
+    this.logger.debug('Finding all the references in the object');
     // find all the references in the object
     pointer.walk(obj, (val, key) => {
       if (key.endsWith('$ref/configName')) {
         const refPath = key.slice(0, key.lastIndexOf('/'));
         const ref = pointer.get(obj, refPath) as unknown;
         if (!this.configValidator.validateRef(ref)) {
+          this.logger.debug('The reference in the following path is not valid', { refPath });
           throw new ConfigValidationError(`The reference in the following path ${refPath} is not valid`);
         }
 
@@ -164,6 +185,7 @@ export class ConfigManager {
     });
 
     for (const [path, ref] of paths) {
+      this.logger.debug('Replacing the reference in the object', { refPath: path, referenceObject: ref });
       const config = refs.find((r) => r.configName === ref.configName && (ref.version === 'latest' || r.version === ref.version));
       if (!config) {
         throw new Error(`could not find ref in db: ${JSON.stringify(ref)}`);
@@ -182,6 +204,7 @@ export class ConfigManager {
       }
 
       if (path === '') {
+        this.logger.debug('The reference is in the root of the object, replacing the object with the reference');
         Object.assign(obj, replacementValue);
         return;
       }

src/configs/models/configValidator.ts

@@ -1,17 +1,22 @@
 import { readFileSync } from 'node:fs';
 import Ajv, { AnySchemaObject, ErrorObject, ValidateFunction } from 'ajv/dist/2019';
-import { injectable } from 'tsyringe';
+import { inject, injectable } from 'tsyringe';
 import addFormats from 'ajv-formats';
+import { Logger } from '@map-colonies/js-logger';
 import betterAjvErrors, { type IOutputError } from '@sidvind/better-ajv-errors';
 import { SchemaManager } from '../../schemas/models/schemaManager';
+import { SERVICES } from '../../common/constants';
 import { ConfigReference, configReferenceSchema } from './configReference';
 
 @injectable()
 export class Validator {
   private readonly ajv: Ajv;
   private readonly ajvRefValidator: ValidateFunction;
 
-  public constructor(private readonly schemaManager: SchemaManager) {
+  public constructor(
+    private readonly schemaManager: SchemaManager,
+    @inject(SERVICES.LOGGER) private readonly logger: Logger
+  ) {
     const draft7MetaSchema = JSON.parse(
       readFileSync(require.resolve('ajv/dist/refs/json-schema-draft-07.json'), { encoding: 'utf-8' })
     ) as AnySchemaObject;
@@ -31,6 +36,7 @@ export class Validator {
   }
 
   public async isValid(schemaId: string, data: unknown): Promise<[boolean, IOutputError[]?]> {
+    this.logger.info('Validating config data', { schemaId });
     const validate = await this.ajv.compileAsync(await this.schemaManager.getSchema(schemaId));
     const valid = validate(data);
 

src/configs/repositories/configRepository.ts

@@ -1,6 +1,7 @@
-import { Logger, SQL, SQLWrapper, and, asc, desc, eq, gt, isNull, lt, or, sql } from 'drizzle-orm';
+import { SQL, SQLWrapper, and, asc, desc, eq, gt, isNull, lt, or, sql } from 'drizzle-orm';
 import { inject, scoped, Lifecycle } from 'tsyringe';
 import { toDate } from 'date-fns-tz';
+import { Logger } from '@map-colonies/js-logger';
 import { SERVICES } from '../../common/constants';
 import type { Drizzle } from '../../db/createConnection';
 import { type Config, type NewConfig, type NewConfigRef, configs, configsRefs, SortOption } from '../models/config';
@@ -70,6 +71,7 @@ export class ConfigRepository {
   ) {}
 
   public async getAllConfigRefs(refs: ConfigReference[]): Promise<ConfigRefResponse[]> {
+    this.logger.debug('Retrieving all config references', { refCount: refs.length });
     const refsForSql = refs.map((ref) => ({ configName: ref.configName, version: ref.version === 'latest' ? null : ref.version }));
     // query to transform the input into a postgresql recordset so it can be joined with the data
     const inputCTE = sql`
@@ -153,17 +155,20 @@ export class ConfigRepository {
     }));
 
     await this.drizzle.transaction(async (tx) => {
+      this.logger.debug('Inserting the config into the database');
       await tx
         .insert(configs)
         .values({ ...configData, isLatest: true })
         .execute();
 
       if (dbRefs.length > 0) {
+        this.logger.debug('Inserting the config references into the database');
         await tx.insert(configsRefs).values(dbRefs).execute();
       }
 
       // set the previous version of the config to not be the latest if a previous version exists
       if (config.version !== 1) {
+        this.logger.debug('Setting the previous version of the config to not be the latest');
         await tx
           .update(configs)
           .set({ isLatest: false })
@@ -181,6 +186,7 @@ export class ConfigRepository {
    * @returns A Promise that resolves to the retrieved configuration, or undefined if not found.
    */
   public async getConfig(name: string, version?: number): Promise<Config | undefined> {
+    this.logger.debug('Retrieving the config from the database without resolving references');
     const comparators = [eq(configs.configName, name)];
 
     if (version !== undefined) {
@@ -208,6 +214,7 @@ export class ConfigRepository {
    * @returns A promise that resolves to an array containing the configuration and its references, or undefined if not found.
    */
   public async getConfigRecursive(name: string, version?: number): Promise<[Config, ConfigRefResponse[]] | undefined> {
+    this.logger.debug('Retrieving config and its references from the database');
     // const maxVersion = maxVersionQueryBuilder(this.drizzle, name);
 
     const versionOperator = version !== undefined ? eq(configs.version, version) : eq(configs.isLatest, true);
@@ -246,6 +253,7 @@ export class ConfigRepository {
 
     const configResult = res.rows.shift();
     if (!configResult) {
+      this.logger.debug('No config found with the specified name and version');
       return undefined;
     }
 
@@ -274,6 +282,7 @@ export class ConfigRepository {
     paginationParams: SqlPaginationParams = { limit: 1, offset: 0 },
     sortingParams: SortOption[] = []
   ): Promise<{ configs: Config[]; totalCount: number }> {
+    this.logger.debug('Retrieving configs with filters from the database');
     const filterParams: SQLWrapper[] = this.getFilterParams(searchParams);
 
     const orderByParams = sortingParams.map((sort) => (sort.order === 'asc' ? asc(configs[sort.field]) : desc(configs[sort.field])));
@@ -298,6 +307,7 @@ export class ConfigRepository {
     const configsResult = await configsQuery.execute();
 
     if (configsResult.length === 0) {
+      this.logger.debug('No configs found with the specified filters');
       return { configs: [], totalCount: 0 };
     }
 
@@ -317,6 +327,7 @@ export class ConfigRepository {
   }
 
   private getFilterParams(searchParams: ConfigSearchParams): SQLWrapper[] {
+    this.logger.debug('Building SQL filter params for the config search');
     const filterParams: SQLWrapper[] = [];
 
     if (searchParams.q !== undefined && searchParams.q !== '') {

src/configs/routes/configRouter.ts

@@ -1,11 +1,15 @@
 import { Router } from 'express';
 import { FactoryFunction } from 'tsyringe';
 import { ConfigController } from '../controllers/configController';
+import { logEnrichmentParamMiddlewareFactory } from '../../common/logger';
 
 export const configRouterFactory: FactoryFunction<Router> = (dependencyContainer) => {
   const router = Router();
   const controller = dependencyContainer.resolve(ConfigController);
 
+  router.param('name', logEnrichmentParamMiddlewareFactory('configName'));
+  router.param('version', logEnrichmentParamMiddlewareFactory('version'));
+
   router.get('/', controller.getConfigs);
   router.post('/', controller.postConfig);
   router.get('/:name', controller.getConfigByName);

src/containerConfig.ts

@@ -1,9 +1,8 @@
 import config from 'config';
-import { getOtelMixin } from '@map-colonies/telemetry';
 import { trace, metrics as OtelMetrics } from '@opentelemetry/api';
 import { DependencyContainer } from 'tsyringe/dist/typings/types';
-import jsLogger, { LoggerOptions } from '@map-colonies/js-logger';
 import { instancePerContainerCachingFactory } from 'tsyringe';
+import type { Pool } from 'pg';
 import { Metrics } from '@map-colonies/telemetry';
 import { SERVICES, SERVICE_NAME } from './common/constants';
 import { tracing } from './common/tracing';
@@ -12,27 +11,30 @@ import { InjectionObject, registerDependencies } from './common/dependencyRegist
 import { CAPABILITIES_ROUTER_SYMBOL, capabilitiesRouterFactory } from './capabilities/routes/capabilitiesRouter';
 import { CONFIG_ROUTER_SYMBOL, configRouterFactory } from './configs/routes/configRouter';
 import { initConnection, createDrizzle, createConnectionOptions, DbConfig } from './db/createConnection';
+import { loggerFactory } from './common/logger';
 
 export interface RegisterOptions {
   override?: InjectionObject<unknown>[];
   useChild?: boolean;
 }
 
 export async function registerExternalValues(options?: RegisterOptions): Promise<DependencyContainer> {
-  const loggerConfig = config.get<LoggerOptions>('telemetry.logger');
-  const logger = jsLogger({ ...loggerConfig, prettyPrint: loggerConfig.prettyPrint, mixin: getOtelMixin() });
-
   const metrics = new Metrics();
   metrics.start();
 
   tracing.start();
   const tracer = trace.getTracer(SERVICE_NAME);
 
-  const pool = await initConnection(createConnectionOptions(config.get<DbConfig>('db')));
+  let pool: Pool;
+  try {
+    pool = await initConnection(createConnectionOptions(config.get<DbConfig>('db')));
+  } catch (error) {
+    throw new Error(`Failed to connect to the database`, { cause: error });
+  }
 
   const dependencies: InjectionObject<unknown>[] = [
     { token: SERVICES.CONFIG, provider: { useValue: config } },
-    { token: SERVICES.LOGGER, provider: { useValue: logger } },
+    { token: SERVICES.LOGGER, provider: { useFactory: instancePerContainerCachingFactory(loggerFactory) } },
     { token: SERVICES.TRACER, provider: { useValue: tracer } },
     { token: SERVICES.METER, provider: { useValue: OtelMetrics.getMeterProvider().getMeter(SERVICE_NAME) } },
     { token: SCHEMA_ROUTER_SYMBOL, provider: { useFactory: schemaRouterFactory } },