Merge pull request #584 from namecheap/bugfix/log-operationid

fix(ilc/server): add path and operationId to log

ilc/server/app.js

@@ -12,8 +12,6 @@ const reportingPluginManager = require('./plugins/reportingPlugin');
 const AccessLogger = require('./logger/accessLogger');
 const { isStaticFile, isHealthCheck } = require('./utils/utils');
 
-const accessLogger = new AccessLogger(config);
-
 /**
  * @param {Registry} registryService
  */
@@ -22,13 +20,13 @@ module.exports = (registryService, pluginManager, context) => {
 
     const appConfig = Application.getConfig(reportingPlugin);
     const logger = reportingPluginManager.getLogger();
-
+    const accessLogger = new AccessLogger(config, logger);
     const app = fastify(appConfig);
 
     const asyncResourceSymbol = Symbol('asyncResource');
 
     app.addHook('onRequest', (req, reply, done) => {
-        context.run({ request: req }, async () => {
+        context.run({ request: req, requestId: reportingPluginManager.getRequestId() ?? request.id }, async () => {
             try {
                 const asyncResource = new AsyncResource('fastify-request-context');
                 req[asyncResourceSymbol] = asyncResource;
@@ -85,7 +83,7 @@ module.exports = (registryService, pluginManager, context) => {
             });
             done();
         } catch (error) {
-            errorHandlingService.handleError(error);
+            errorHandlingService.noticeError(error);
         }
     });
 

ilc/server/application/application.js

@@ -1,6 +1,6 @@
 module.exports = class Application {
     static getConfig(reportPlugin) {
-        const loggerKeys = ['logger', 'requestIdLogLabel', 'genReqId'];
+        const loggerKeys = ['logger'];
         const appConfig = {
             trustProxy: false, // TODO: should be configurable via Registry,
             disableRequestLogging: true,

ilc/server/context/context.js

@@ -10,16 +10,15 @@ module.exports = {
          * @param {Function} callback
          * @returns {unknown}
          */
-        run({ request }, callback) {
+        run({ request, requestId }, callback) {
             const parsedUrl = parseUrl(request.raw);
             const store = new Map();
 
-            store.set('reqId', request.id);
             store.set('url', request.raw.url);
             store.set('protocol', request.raw.connection.encrypted ? 'https' : 'http');
             store.set('path', parsedUrl.pathname);
             store.set('domain', request.hostname);
-            store.set('appLogger', request.log);
+            store.set('requestId', requestId);
 
             return asyncLocalStorage.run(store, callback);
         },

ilc/server/errorHandler/ErrorHandler.js

@@ -5,6 +5,7 @@ const uuidv4 = require('uuid/v4');
 const extendError = require('@namecheap/error-extender');
 const config = require('config');
 const { readFileSync } = require('fs');
+const { setErrorData } = require('../utils/helpers');
 const ErrorHandlingError = extendError('ErrorHandlingError');
 
 const defaultErrorPage = fs.readFileSync(path.resolve(__dirname, '../assets/defaultErrorPage.html'), 'utf-8');
@@ -28,28 +29,13 @@ module.exports = class ErrorHandler {
      * @param {Object} [options]
      * @param {Boolean} options.reportError = true
      */
-    noticeError(err, errInfo = {}, options) {
-        const infoData = Object.assign({}, errInfo);
-        options = Object.assign(
-            {},
-            {
-                reportError: true,
-            },
-            options,
-        );
-
-        if (err.data === undefined) {
-            const ExtendedError = extendError(err.name);
-            err = new ExtendedError({ cause: err, data: infoData, message: err.message });
-        } else {
-            Object.assign(err.data, infoData);
-        }
-
-        if (options.reportError) {
-            this.#errorsService.noticeError(err, infoData);
+    noticeError(err, customAttributes = {}, { reportError = true } = {}) {
+        if (reportError) {
+            this.#errorsService.noticeError(err, { ...customAttributes });
+            setErrorData(err, customAttributes);
             this.#logger.error(err);
         } else {
-            err.data.localError = true;
+            setErrorData(err, { ...customAttributes, localError: true });
             this.#logger.warn(err);
         }
     }
@@ -66,17 +52,7 @@ module.exports = class ErrorHandler {
         }
 
         try {
-            this.noticeError(
-                err,
-                {
-                    reqId: req.id,
-                    errorId,
-                    domain: req.hostname,
-                    url: req.url,
-                },
-                { reportError: !req.ldeRelated },
-            );
-
+            this.noticeError(err, { errorId }, { reportError: !req.ldeRelated });
             const currentDomain = req.hostname;
             const locale = (req.raw || req).ilcState.locale;
             let data = await this.#registryService.getTemplate('500', { locale, forDomain: currentDomain });
@@ -86,14 +62,12 @@ module.exports = class ErrorHandler {
             nres.write(data);
             nres.end();
         } catch (causeErr) {
-            const e = new ErrorHandlingError({
+            const handlingError = new ErrorHandlingError({
+                message: 'Additional error in error handling',
                 cause: causeErr,
-                d: {
-                    errorId,
-                },
+                data: { errorId },
             });
-
-            this.#logger.error(e);
+            this.#logger.error(handlingError);
             this.#writeStaticError(nres);
         }
     };

ilc/server/logger/accessLogger.js

@@ -2,9 +2,11 @@ const { context } = require('../context/context');
 
 class AccessLogger {
     #ignoreUrls;
+    #logger;
 
-    constructor(config) {
+    constructor(config, logger) {
         this.#ignoreUrls = config.get('logger.accessLog.ignoreUrls').split(',');
+        this.#logger = logger;
     }
 
     logRequest(logData = {}) {
@@ -22,26 +24,17 @@ class AccessLogger {
         }
 
         const store = context.getStore();
-        const url = store.get('path');
+        const path = store.get('path');
 
-        const logger = store.get('appLogger');
-        if (!logger) {
+        if (!this.#logger) {
             throw new Error('Logger is not available');
         }
 
-        if (this.#shouldIgnoreUrl(url)) {
+        if (this.#shouldIgnoreUrl(path)) {
             return;
         }
 
-        const logContext = {
-            ...logData,
-            ...{
-                url,
-                domain: store.get('domain'),
-            },
-        };
-
-        logger.info(logContext, message);
+        this.#logger.info(logData, message);
     }
 
     #shouldIgnoreUrl(url) {

ilc/server/logger/accessLogger.spec.js

@@ -3,13 +3,60 @@ const { context } = require('../context/context');
 const sinon = require('sinon');
 
 describe('accessLogger', () => {
-    it('should ignore access logs based on path', function () {
+    const logger = {
+        info: sinon.stub(),
+    };
+    beforeEach(() => {
+        logger.info.resetHistory();
+    });
+
+    it('log request', function () {
         const localConfig = { get: sinon.stub().withArgs('logger.accessLog.ignoreUrls').returns('/test/ignored/') };
-        const accessLogger = new AccessLogger(localConfig);
 
-        const logger = {
-            info: sinon.stub(),
+        const accessLogger = new AccessLogger(localConfig, logger);
+        const request = {
+            request: {
+                raw: {
+                    url: '/test/1',
+                    connection: {
+                        encrypted: true,
+                    },
+                },
+            },
+        };
+
+        context.run(request, () => {
+            accessLogger.logRequest({ additional: true });
+        });
+
+        sinon.assert.calledOnceWithExactly(logger.info, { additional: true }, sinon.match.string);
+    });
+
+    it('log response', function () {
+        const localConfig = { get: sinon.stub().withArgs('logger.accessLog.ignoreUrls').returns('/test/ignored/') };
+
+        const accessLogger = new AccessLogger(localConfig, logger);
+        const request = {
+            request: {
+                raw: {
+                    url: '/test/1',
+                    connection: {
+                        encrypted: true,
+                    },
+                },
+            },
         };
+
+        context.run(request, () => {
+            accessLogger.logResponse({ additional: true });
+        });
+
+        sinon.assert.calledOnceWithExactly(logger.info, { additional: true }, sinon.match.string);
+    });
+
+    it('should ignore access logs based on path', function () {
+        const localConfig = { get: sinon.stub().withArgs('logger.accessLog.ignoreUrls').returns('/test/ignored/') };
+        const accessLogger = new AccessLogger(localConfig, logger);
         const request = {
             request: {
                 raw: {
@@ -19,7 +66,6 @@ describe('accessLogger', () => {
                     },
                 },
                 hostname: 'test-machine',
-                log: logger,
                 id: 'test1',
             },
         };
@@ -33,11 +79,11 @@ describe('accessLogger', () => {
 
     it('should ignore access logs based on path when url has query string', function () {
         const localConfig = { get: sinon.stub().withArgs('logger.accessLog.ignoreUrls').returns('/test/ignored/') };
-        const accessLogger = new AccessLogger(localConfig);
-
         const logger = {
             info: sinon.stub(),
         };
+        const accessLogger = new AccessLogger(localConfig, logger);
+
         const request = {
             request: {
                 raw: {
@@ -47,7 +93,6 @@ describe('accessLogger', () => {
                     },
                 },
                 hostname: 'test-machine',
-                log: logger,
                 id: 'test1',
             },
         };

ilc/server/logger/enhanceLogger.js

@@ -1,8 +1,7 @@
 const { context } = require('../context/context');
+const { setErrorData } = require('../utils/helpers');
 
-module.exports = (logger, { reqIdKey }) => {
-    const requestIdKey = reqIdKey || 'operationId';
-
+module.exports = (logger, { requestIdLogLabel }) => {
     const loggerProxyHandler = {
         get(target, prop) {
             const origMethod = target[prop];
@@ -11,15 +10,17 @@ module.exports = (logger, { reqIdKey }) => {
                     const store = context.getStore();
                     const [arg1] = args;
                     const logContext = {
-                        [requestIdKey]: store.get('reqId'),
+                        [requestIdLogLabel]: store.get('requestId'),
                         domain: store.get('domain'),
+                        path: store.get('path'),
                     };
 
                     if (arg1 === 'string') {
                         return origMethod.call(target, logContext, ...args);
                     }
 
                     if (arg1 instanceof Error) {
+                        setErrorData(arg1, logContext);
                         return origMethod.apply(target, args);
                     }
 

ilc/server/plugins/reportingPlugin.js

@@ -12,11 +12,13 @@ class ReportingPlugin {
         return this.#plugin;
     }
 
+    getRequestId() {
+        return this.#plugin.genReqId();
+    }
+
     getLogger() {
         const logger = this.#plugin.logger;
-        return enhanceLogger(logger, {
-            reqIdKey: this.#plugin.requestIdLogLabel || 'operationId',
-        });
+        return enhanceLogger(logger, { requestIdLogLabel: this.#plugin.requestIdLogLabel ?? 'requestId' });
     }
 }
 

ilc/server/utils/helpers.ts

@@ -0,0 +1,7 @@
+export function setErrorData(error: Error, data: Record<string, string | number | boolean>): void {
+    if ('data' in error && typeof error.data === 'object' && error.data !== null) {
+        Object.assign(error.data, data);
+    } else {
+        Object.defineProperty(error, 'data', { enumerable: true, writable: false, value: data });
+    }
+}

registry/server/errorHandler/noticeError.ts

@@ -1,13 +1,13 @@
 import newrelic from 'newrelic';
-import extendError from '@namecheap/error-extender';
+import { setErrorData } from '../util/helpers';
 import { getLogger } from '../util/logger';
 
-function noticeError(error: Error, errorInfo = {}): void {
-    const additionalInfo = Object.assign({}, errorInfo);
-    newrelic.noticeError(error, additionalInfo);
+type ErrorAttributes = { [key: string]: string | number | boolean };
 
-    const ExtendedError = extendError(error.name);
-    getLogger().error(new ExtendedError({ cause: error, data: additionalInfo, message: error.message }));
+export function noticeError(error: Error, customAttributes: ErrorAttributes = {}): void {
+    newrelic.noticeError(error, { ...customAttributes });
+    setErrorData(error, customAttributes);
+    getLogger().error(error);
 }
 
 export default noticeError;

registry/server/templates/routes/getRenderedTemplate.ts

@@ -1,6 +1,5 @@
 import { Request, Response } from 'express';
 import Joi from 'joi';
-import _, { LodashStubString } from 'lodash/fp';
 
 import noticeError from '../../errorHandler/noticeError';
 import db from '../../db';
@@ -101,7 +100,7 @@ async function getRenderedTemplate(req: Request<GetTemplateRenderedRequestParams
 
     try {
         const renderedTemplate = await renderTemplate(content);
-        res.status(200).send(_.assign(template, renderedTemplate));
+        res.status(200).send({ ...template, ...renderedTemplate });
     } catch (e) {
         if (e instanceof errors.FetchIncludeError) {
             res.status(500).send(e.message);
@@ -110,7 +109,7 @@ async function getRenderedTemplate(req: Request<GetTemplateRenderedRequestParams
             });
             return;
         } else {
-            console.error(`Error on render template "${templateName}"`, e);
+            getLogger().error(e as Error, `Error on render template "${templateName}"`);
             throw e;
         }
     }

registry/server/util/helpers.ts

@@ -1,5 +1,6 @@
 import Joi, { ValidationError } from 'joi';
 import _fp from 'lodash/fp';
+import { type ExtendedError } from '@namecheap/error-extender';
 
 export const joiErrorToResponse = _fp.compose<
     Array<Joi.ValidationError>,
@@ -30,3 +31,11 @@ export function defined<T>(value: T | null | undefined): T {
     }
     return value;
 }
+
+export function setErrorData(error: Error, data: Record<string, string | number | boolean>): void {
+    if ('data' in error && typeof error.data === 'object' && error.data !== null) {
+        Object.assign(error.data, data);
+    } else {
+        Object.defineProperty(error, 'data', { enumerable: true, writable: false, value: data });
+    }
+}