From 5c325b293ed71be7bc61c1e25a162ab4002feb54 Mon Sep 17 00:00:00 2001 From: williamlardier Date: Mon, 8 Sep 2025 15:57:30 +0200 Subject: [PATCH 1/2] Defer log process. until I/O to avoid expensive op on filtered logs Previously, all log entries underwent expensive processing (object cloning, serialization, timestamp generation) regardless of whether they would be output based on the configured log level. This caused significant CPU overhead when logging large objects at debug level in production environments where the log level is typically set higher (info/warn/error). Changes: - RequestLogger: Move object processing from log() to doLogIO() method - SimpleLogger: Add per-stream level checking before object operations - Store raw log data in buffer and defer expensive operations until actual I/O - Maintain existing dump behavior when error threshold is reached Issue: WRLGS-17 --- lib/RequestLogger.js | 74 ++++++++++++++++++++------------------------ lib/SimpleLogger.js | 20 +++++++----- 2 files changed, 45 insertions(+), 49 deletions(-) diff --git a/lib/RequestLogger.js b/lib/RequestLogger.js index 679d627..cb51681 100644 --- a/lib/RequestLogger.js +++ b/lib/RequestLogger.js @@ -423,35 +423,12 @@ class RequestLogger { ); return; } - const fields = objectCopy({}, this.fields, logFields || {}); - const endFlag = isEnd || false; - /* - * using Date.now() as it's faster than new Date(). logstash component - * uses this field to generate ISO 8601 timestamp - */ - if (fields.time === undefined) { - fields.time = Date.now(); - } - - // eslint-disable-next-line camelcase - fields.req_id = serializeUids(this.uids); - if (endFlag) { - if (this.elapsedTime !== null) { - // reset elapsedTime to avoid an infinite recursion - // while logging the error - this.elapsedTime = null; - this.error('RequestLogger.end() has been called more than once'); - } - this.elapsedTime = process.hrtime(this.startTime); - // eslint-disable-next-line camelcase - fields.elapsed_ms = this.elapsedTime[0] * 1000 - + this.elapsedTime[1] / 1000000; - } const logEntry = { level, - fields, msg, + logFields, + isEnd: isEnd || false, }; this.entries.push(logEntry); @@ -459,46 +436,61 @@ class RequestLogger { this.entries.forEach(entry => { this.doLogIO(entry); }); - this.entries = []; + this.entries = []; // Flush buffer after dumping } else if (LogLevel.shouldLog(level, this.logLevel)) { this.doLogIO(logEntry); } } /** - * This function transmits a log entry to the configured bunyan logger - * instance. This way, we can rely on bunyan for actual logging operations, - * and logging multiplexing, instead of managing that ourselves. + * This function assembles the final log object from a buffered entry + * and transmits it to the underlying bunyan logger instance for I/O. * * @private * - * @param {object} logEntry - The Logging entry to be passed to - * bunyan - * @param {string} logEntry.msg - The message to be logged - * @param {object} logEntry.fields - The data fields to associate to the - * log entry. - * + * @param {object} logEntry - The Logging entry to be processed. + * @param {string} logEntry.msg - The message to be logged * @returns {undefined} */ doLogIO(logEntry) { + const fields = objectCopy({}, this.fields, logEntry.logFields || {}); + + if (fields.time === undefined) { + fields.time = Date.now(); + } + + // eslint-disable-next-line camelcase + fields.req_id = serializeUids(this.uids); + if (logEntry.isEnd) { + if (this.elapsedTime !== null) { + // reset elapsedTime to avoid an infinite recursion + // while logging the error + this.elapsedTime = null; + this.error('RequestLogger.end() has been called more than once'); + } + this.elapsedTime = process.hrtime(this.startTime); + // eslint-disable-next-line camelcase + fields.elapsed_ms = this.elapsedTime[0] * 1000 + + this.elapsedTime[1] / 1000000; + } switch (logEntry.level) { case 'trace': - this.sLogger.trace(logEntry.fields, logEntry.msg); + this.sLogger.trace(fields, logEntry.msg); break; case 'debug': - this.sLogger.debug(logEntry.fields, logEntry.msg); + this.sLogger.debug(fields, logEntry.msg); break; case 'info': - this.sLogger.info(logEntry.fields, logEntry.msg); + this.sLogger.info(fields, logEntry.msg); break; case 'warn': - this.sLogger.warn(logEntry.fields, logEntry.msg); + this.sLogger.warn(fields, logEntry.msg); break; case 'error': - this.sLogger.error(logEntry.fields, logEntry.msg); + this.sLogger.error(fields, logEntry.msg); break; case 'fatal': - this.sLogger.fatal(logEntry.fields, logEntry.msg); + this.sLogger.fatal(fields, logEntry.msg); break; default: throw new Error(`Unexpected log level: ${logEntry.level}`); diff --git a/lib/SimpleLogger.js b/lib/SimpleLogger.js index 6755430..46e3e86 100644 --- a/lib/SimpleLogger.js +++ b/lib/SimpleLogger.js @@ -1,6 +1,7 @@ const os = require('os'); const safeJSONStringify = require('safe-json-stringify'); const fastJSONStringify = require('fast-safe-stringify'); +const LogLevel = require('./LogLevel'); /* * This function safely stringifies JSON. If an exception occcurs (due to @@ -64,15 +65,18 @@ class SimpleLogger { logMsg = message; logFields = fields || {}; } - // TODO - Protect these fields from being overwritten - logFields.level = level; - logFields.message = logMsg; - logFields.hostname = this.hostname; - logFields.pid = process.pid; - const safeString = safeStringify(logFields); - this.streams.forEach(s => s.stream - .write(`${safeString}\n`)); + this.streams.forEach(s => { + if (LogLevel.shouldLog(level, s.level)) { + const finalLogFields = { ...logFields }; + finalLogFields.level = level; + finalLogFields.message = logMsg; + finalLogFields.hostname = this.hostname; + finalLogFields.pid = process.pid; + const safeString = safeStringify(finalLogFields); + s.stream.write(`${safeString}\n`); + } + }); } info(fields, message) { From 99afdc0d355fe76263051564bb448a7ea83d5860 Mon Sep 17 00:00:00 2001 From: williamlardier Date: Mon, 8 Sep 2025 15:59:39 +0200 Subject: [PATCH 2/2] Bump project version Issue: WRLGS-17 --- package.json | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/package.json b/package.json index 57c97ae..0748614 100644 --- a/package.json +++ b/package.json @@ -3,7 +3,7 @@ "engines": { "node": ">=20" }, - "version": "8.2.2", + "version": "8.2.3", "description": "An efficient raw JSON logging library aimed at micro-services architectures.", "main": "index.js", "scripts": {