Skip to content

Defer log process. until I/O to avoid expensive op on filtered logs #174

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
bert-e merged 2 commits into from
Oct 31, 2025
Merged

Defer log process. until I/O to avoid expensive op on filtered logs #174

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
2 commits
Select commit Hold shift + click to select a range
5c325b2
Defer log process. until I/O to avoid expensive op on filtered logs
Seragonia Sep 8, 2025
99afdc0
Bump project version
Seragonia Sep 8, 2025
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
74 changes: 33 additions & 41 deletions lib/RequestLogger.js
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -423,82 +423,74 @@ 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,

@francoisferrand francoisferrand Sep 9, 2025 •
edited
Loading

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

we need to keep the objectCopy() here to ensure the fields appearing in the log cannot be affected by code happening after the log call : we need to perform a deep copy before returning...

@ghost ghost Sep 9, 2025

Copy link
Copy Markdown
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think that should be up to the caller: I cannot find places where what is logged changes after, this is very uncommon, yet has high CPU impact.

@francoisferrand francoisferrand Sep 9, 2025

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

that is the semantics of any logger : you log the value of the object when the call is made. Not respecting this will not break at every call hopefully, but creates a very significant risk that we don't log relevant data....and thus spend even more time debugging than if we did not have log at all.

An alternative would be to freeze() the object, but this would also cause significant (and breaking!) change on caller, as it may now crash if the variable is modified after being logged. So I don't think it should be used either.

Improving performance is good, but correctness and ease/safety of development matter as well : what is the real-life benefit of not copying the object? Is it really worth updating all logging calls and risking to have an issue with every new log line?

@ghost ghost Sep 10, 2025 •
edited by ghost
Loading

Copy link
Copy Markdown
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Thanks for the precision, I understand better as I thought the lack of deep copy was on purpose (we have this bug with the existing code!).

First, on performance, I measured 8% CPU impact on the visible side, and then, it greatly increases the GC pressure. It's hard to precisely measure that part, but it becomes visible when we remove the logs in most places, I can see half of GC duration is from logger. The logger should not be this impactful on the runtime environment... I think we agree on that. Under high load the GC would run up to 50, even 70% of the total duration, clearly a saturation.

On the safety side, I agree. However the original objectCopy was not a deep copy to begin with, but a shallow copy. We only copy the top level fields to recreate an object. This does not protect against object being edited in between. Here is an example script:

#!/usr/bin/env node

const werelogs = require('./index.js');

werelogs.configure({
    level: 'info',
    dump: 'error'
});

const logger = new werelogs.Logger('test-logger');
const requestLogger = logger.newRequestLogger();

const userSession = {
    userId: 12345,
    username: "john_doe", 
    permissions: {
        canRead: true,
        canWrite: false,
        canDelete: false
    },
    metadata: {
        loginTime: new Date().toISOString(),
        lastActivity: "browsing",
        flags: ["premium", "verified"]
    }
};

requestLogger.info('User session started', { session: userSession });

requestLogger.debug('Session details for debugging', { 
    sessionData: userSession,
    additionalInfo: "This debug log will be dumped on error"
});

userSession.username = "jane_doe_MUTATED";
userSession.permissions.canWrite = true;
userSession.permissions.canDelete = true;
userSession.metadata.lastActivity = "MUTATED_ACTIVITY";
userSession.metadata.flags.push("MUTATED_FLAG");

requestLogger.error('Something went wrong - dumping all logs!', {
    errorCode: 'TEST_ERROR',
    message: 'Check if the debug log above shows original or mutated values'
});

Here we log in info, then debug, then edit the object, and finally we log at the dump level: we see that the original object is mutated. Results:

{"name":"test-logger","session":{"userId":12345,"username":"john_doe","permissions":{"canRead":true,"canWrite":false,"canDelete":false},"metadata":{"loginTime":"2025-09-10T07:23:03.230Z","lastActivity":"browsing","flags":["premium","verified"]}},"time":1757488983230,"req_id":"29c710519945a971d51a","level":"info","message":"User session started","hostname":"william","pid":20275}
{"name":"test-logger","session":{"userId":12345,"username":"jane_doe_MUTATED","permissions":{"canRead":true,"canWrite":true,"canDelete":true},"metadata":{"loginTime":"2025-09-10T07:23:03.230Z","lastActivity":"MUTATED_ACTIVITY","flags":["premium","verified","MUTATED_FLAG"]}},"time":1757488983230,"req_id":"29c710519945a971d51a","level":"info","message":"User session started","hostname":"william","pid":20275}
{"name":"test-logger","sessionData":{"userId":12345,"username":"jane_doe_MUTATED","permissions":{"canRead":true,"canWrite":true,"canDelete":true},"metadata":{"loginTime":"2025-09-10T07:23:03.230Z","lastActivity":"MUTATED_ACTIVITY","flags":["premium","verified","MUTATED_FLAG"]}},"additionalInfo":"This debug log will be dumped on error","time":1757488983231,"req_id":"29c710519945a971d51a","level":"debug","message":"Session details for debugging","hostname":"william","pid":20275}
{"name":"test-logger","errorCode":"TEST_ERROR","message":"Something went wrong - dumping all logs!","time":1757488983231,"req_id":"29c710519945a971d51a","level":"error","hostname":"william","pid":20275}

I hope it's easy to read, but in short we can see the mutated object in both the re-printed info log, and the debug log that follows. This is not with the werelogs of this PR branch, but what we have in development/8.2.

So I make two observations:

  • Popular solutions like winston do not copy at all. They are as such affected by the same issue not yet resolved. So a valid concern indeed, and a real problem inherent with the nodejs language, as they also have a PR, not yet merged, as it has clear performance impacts.

  • We have this problem since the beginning in our code. But I cannot exclude that in some case, without knowing, we were looking at wrong logs... That's why in my head this was something done on purpose, as we never edit an object we log, or it's very rare. Now if we do not want that, then it's a real bug we want to fix indeed. So for our optimization I do not really see any solution, unless we make it explicit in the lib, that the object is not deep copied, and add an explicit flag if we want it to be deep copied... But not ideal and likely something a developer will miss.

@ghost ghost Sep 10, 2025

Copy link
Copy Markdown
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

WRLGS-18 was created

isEnd: isEnd || false,
};
this.entries.push(logEntry);

if (LogLevel.shouldLog(level, this.dumpThreshold)) {
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
Comment on lines +451 to +452

@welansari welansari Sep 8, 2025

Copy link
Copy Markdown

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

should we include other expected fields such as isEnd in this doc ?

* @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}`);
Expand Down
20 changes: 12 additions & 8 deletions lib/SimpleLogger.js
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -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
Expand Down Expand Up @@ -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) {
Expand Down
2 changes: 1 addition & 1 deletion package.json
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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": {
Expand Down