From 4147841b1e4d0c927516f8b4213f1782a89758b2 Mon Sep 17 00:00:00 2001 From: Stanislav Mishchyshyn Date: Wed, 27 Mar 2024 18:59:24 +0200 Subject: [PATCH 1/2] registry: fix error callstack in logs, fix log in rendered api endpoint --- registry/server/errorHandler/noticeError.ts | 12 +++---- .../templates/routes/getRenderedTemplate.ts | 5 ++- registry/server/util/helpers.ts | 9 ++++++ registry/server/util/logger.ts | 16 +++------- registry/tests/logging.spec.ts | 31 +++++++++++++++++-- 5 files changed, 49 insertions(+), 24 deletions(-) diff --git a/registry/server/errorHandler/noticeError.ts b/registry/server/errorHandler/noticeError.ts index 04cd3e60f..d776bd304 100644 --- a/registry/server/errorHandler/noticeError.ts +++ b/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; diff --git a/registry/server/templates/routes/getRenderedTemplate.ts b/registry/server/templates/routes/getRenderedTemplate.ts index 8c0ceae2e..0f98221ba 100644 --- a/registry/server/templates/routes/getRenderedTemplate.ts +++ b/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, @@ -30,3 +31,11 @@ export function defined(value: T | null | undefined): T { } return value; } + +export function setErrorData(error: Error, data: Record): 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 }); + } +} diff --git a/registry/server/util/logger.ts b/registry/server/util/logger.ts index 53d6f8ad2..6d50e09b0 100644 --- a/registry/server/util/logger.ts +++ b/registry/server/util/logger.ts @@ -1,7 +1,7 @@ import { Logger } from 'ilc-plugins-sdk'; import { getPluginManagerInstance } from './pluginManager'; import { storage, Store } from '../middleware/context'; -import errorExtender, { ExtendedError } from '@namecheap/error-extender'; +import { setErrorData } from './helpers'; type LogContext = Omit & { userId?: string; @@ -21,9 +21,7 @@ const loggerProxyHandler: ProxyHandler = { } const requestIdKey = getPluginManagerInstance().getReportingPlugin().requestIdLogLabel ?? 'operationId'; return function ( - ...args: - | [arg1: object | Error | ExtendedError, arg2: string | undefined, ...args: any[]] - | [arg1: string, ...args: any[]] + ...args: [arg1: object | Error, arg2: string | undefined, ...args: any[]] | [arg1: string, ...args: any[]] ) { const store = storage.getStore(); const [arg1, ...restArgs] = args; @@ -44,14 +42,8 @@ const loggerProxyHandler: ProxyHandler = { } if (arg1 instanceof Error) { - if ('data' in arg1 && typeof arg1['data'] === 'object' && arg1['data'] !== null) { - Object.assign(arg1['data'], logContext); - return originalMember.apply(target, args); - } else { - const ExtendedError = errorExtender(arg1.name); - const errorWithData = new ExtendedError({ message: arg1.message, data: logContext, cause: arg1 }); - return originalMember.call(target, errorWithData, ...restArgs); - } + setErrorData(arg1, logContext); + return originalMember.apply(target, args); } if (typeof arg1 === 'object' && arg1 !== null) { diff --git a/registry/tests/logging.spec.ts b/registry/tests/logging.spec.ts index 6e55a4641..a633d7961 100644 --- a/registry/tests/logging.spec.ts +++ b/registry/tests/logging.spec.ts @@ -80,7 +80,17 @@ describe('Logging', () => { await runScenario(logObjectHandler); sinon.assert.calledWith( errorLog, - sinon.match({ message: 'desc', data: sinon.match({ userId: 'root', operationId: sinon.match.string }) }), + sinon.match({ + message: 'desc', + stack: sinon.match.string, + data: { + userId: 'root', + operationId: sinon.match.string, + path: '/test', + clientIp: sinon.match.string, + domain: '127.0.0.1', + }, + }), ); }); @@ -88,7 +98,7 @@ describe('Logging', () => { const logObjectHandler: Handler = (req, res, next) => { const CustomError = errorExtender('Custom'); try { - getLogger().error(new CustomError({ message: 'desc' })); + getLogger().error(new CustomError({ message: 'desc', data: { a: 1 }, cause: new Error('cause') })); } catch (e) { console.log(e); } @@ -97,7 +107,22 @@ describe('Logging', () => { await runScenario(logObjectHandler); sinon.assert.calledWith( errorLog, - sinon.match({ message: 'desc', data: sinon.match({ userId: 'root', operationId: sinon.match.string }) }), + sinon.match({ + message: 'desc', + stack: sinon.match.string, + cause: sinon.match({ + message: 'cause', + stack: sinon.match.string, + }), + data: { + userId: 'root', + operationId: sinon.match.string, + path: '/test', + clientIp: sinon.match.string, + domain: '127.0.0.1', + a: 1, + }, + }), ); }); }); From e41fa926b04a9db24e76ffc3e53f30f28142b8db Mon Sep 17 00:00:00 2001 From: Stanislav Mishchyshyn Date: Wed, 27 Mar 2024 19:35:52 +0200 Subject: [PATCH 2/2] fix(ilc/server): add path and operationId to log --- ilc/server/app.js | 8 ++-- ilc/server/application/application.js | 2 +- ilc/server/context/context.js | 5 +- ilc/server/errorHandler/ErrorHandler.js | 48 +++++-------------- ilc/server/logger/accessLogger.js | 21 +++------ ilc/server/logger/accessLogger.spec.js | 61 +++++++++++++++++++++---- ilc/server/logger/enhanceLogger.js | 9 ++-- ilc/server/plugins/reportingPlugin.js | 8 ++-- ilc/server/utils/helpers.ts | 7 +++ 9 files changed, 94 insertions(+), 75 deletions(-) create mode 100644 ilc/server/utils/helpers.ts diff --git a/ilc/server/app.js b/ilc/server/app.js index aca5e921a..ecbff6814 100644 --- a/ilc/server/app.js +++ b/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); } }); diff --git a/ilc/server/application/application.js b/ilc/server/application/application.js index 21b500080..dade1f5a3 100644 --- a/ilc/server/application/application.js +++ b/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, diff --git a/ilc/server/context/context.js b/ilc/server/context/context.js index 88170ab44..4bdeac610 100644 --- a/ilc/server/context/context.js +++ b/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); }, diff --git a/ilc/server/errorHandler/ErrorHandler.js b/ilc/server/errorHandler/ErrorHandler.js index 8a51dfd9b..497981a7c 100644 --- a/ilc/server/errorHandler/ErrorHandler.js +++ b/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); } }; diff --git a/ilc/server/logger/accessLogger.js b/ilc/server/logger/accessLogger.js index 91f186f08..322816360 100644 --- a/ilc/server/logger/accessLogger.js +++ b/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) { diff --git a/ilc/server/logger/accessLogger.spec.js b/ilc/server/logger/accessLogger.spec.js index 16e455de5..0309d5088 100644 --- a/ilc/server/logger/accessLogger.spec.js +++ b/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', }, }; diff --git a/ilc/server/logger/enhanceLogger.js b/ilc/server/logger/enhanceLogger.js index bc150ec3b..bb72faba8 100644 --- a/ilc/server/logger/enhanceLogger.js +++ b/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,8 +10,9 @@ 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') { @@ -20,6 +20,7 @@ module.exports = (logger, { reqIdKey }) => { } if (arg1 instanceof Error) { + setErrorData(arg1, logContext); return origMethod.apply(target, args); } diff --git a/ilc/server/plugins/reportingPlugin.js b/ilc/server/plugins/reportingPlugin.js index f423fc9da..5574604d0 100644 --- a/ilc/server/plugins/reportingPlugin.js +++ b/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' }); } } diff --git a/ilc/server/utils/helpers.ts b/ilc/server/utils/helpers.ts new file mode 100644 index 000000000..77a61f628 --- /dev/null +++ b/ilc/server/utils/helpers.ts @@ -0,0 +1,7 @@ +export function setErrorData(error: Error, data: Record): 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 }); + } +}