Skip to content
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.

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

WRLGS-11: Utils to timestamp stderr logs #167

Merged
merged 5 commits into from
Jun 28, 2024
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
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
37 changes: 37 additions & 0 deletions index.js
Original file line number Diff line number Diff line change
@@ -1,4 +1,5 @@
const API = require('./lib/api.js');
const stderrUtils = require('./lib/stderrUtils');

/*
* For convenience purposes, we provide an already instanciated API; so that
Expand All @@ -11,4 +12,40 @@ module.exports = {
Logger: werelogs.Logger,
configure: werelogs.reconfigure.bind(werelogs),
Werelogs: API,
/**
* Timestamp logs going to stderr
*
* @example <caption>Simplest usage</caption>
* ```
* const { stderrUtils } = require('werelogs');
* stderrUtils.catchAndTimestampStderr();
* ```
*
* @example <caption>Manage process exit</caption>
* ```
* const { stderrUtils } = require('werelogs');
* // set exitCode to null to keep process running on uncaughtException
* stderrUtils.catchAndTimestampStderr(undefined, null);
* // application init
* process.on('uncaughtException', (err) => {
* // custom handling, close connections, files
* this.worker.kill(); // or process.exit(1);
* });
* // Note you could use prependListener to execute your callback first
* // and then let stderrUtils exit the process.
* ```
*
* @example <caption>Custom listener</caption>
* ```
* const { stderrUtils } = require('werelogs');
* stderrUtils.catchAndTimestampWarning();
* // application init
* process.on('uncaughtException', (err, origin) => {
* stderrUtils.printErrorWithTimestamp(err, origin);
* // close and stop everything
* process.exit(1);
* });
* ```
*/
stderrUtils,
};
106 changes: 106 additions & 0 deletions lib/stderrUtils.js
Original file line number Diff line number Diff line change
@@ -0,0 +1,106 @@
/**
* @returns {string} a timestamp in ISO format YYYY-MM-DDThh:mm:ss.sssZ
*/
const defaultTimestamp = () => new Date().toISOString();

/**
* Prints on stderr a timestamp, the origin and the error
*
* If no other instructions are needed on uncaughtException,
* consider using `catchAndTimestampStderr` directly.
*
* @example
* process.on('uncaughtException', (err, origin) => {
* printErrorWithTimestamp(err, origin);
* // server.close();
* // file.close();
* process.nextTick(() => process.exit(1));
* });
* // Don't forget to timestamp warning
* catchAndTimestampWarning();
* @param {Error} err see process event uncaughtException
* @param {uncaughtException|unhandledRejection} origin see process event
* @param {string} [date=`defaultTimestamp()`] Date to print
* @returns {boolean} see process.stderr.write
*/
function printErrorWithTimestamp(
err, origin, date = defaultTimestamp(),
) {
return process.stderr.write(`${date}: ${origin}:\n${err.stack}\n`);
Copy link
Contributor

Choose a reason for hiding this comment

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

If we plan to crash the process, why not logging with fatal level here?

Copy link
Contributor Author

Choose a reason for hiding this comment

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

Those are stderr logs, there is no Logger to format those logs as json.

I copied what's done there: https://github.com/scality/cloudserver/pull/5406/files#diff-e727e4bdf3657fd1d798edcd6b099d6e092f8573cba266154583a746bba0f346R7

And we decided for now we don't want to change the format completely, we want functions to encapsulate the logic and later if we need to we could change the format in those functions and just bump in all components

Copy link
Contributor Author

Choose a reason for hiding this comment

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

We try not to change the behavior too much for now, we just need to include the timestamp in stderr for the CS

}

/**
* Prefer using `catchAndTimestampStderr` instead of this function.
*
* Adds listener for uncaughtException to print with timestamp.
*
* If you want to manage the end of the process, you can set exitCode to null.
* Or use `printErrorWithTimestamp` in your own uncaughtException listener.
*
* @param {Function} [dateFct=`defaultTimestamp`] Fct returning a formatted date
* @param {*} [exitCode=1] On uncaughtException, if not null, `process.exit`
* will be called with this value
* @returns {undefined}
*/
function catchAndTimestampUncaughtException(
dateFct = defaultTimestamp, exitCode = 1,
) {
process.on('uncaughtException', (err, origin) => {
printErrorWithTimestamp(err, origin, dateFct());
if (exitCode !== null) {
process.nextTick(() => process.exit(exitCode));
}
});
}
Comment on lines +45 to +54
Copy link
Contributor

Choose a reason for hiding this comment

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

Would it make sense not to stop the process if we pass a flag? Example: https://github.com/scality/vault2/blob/6a0c2cf3de174f5f339f1379227fbe87b0e99ce7/lib/vaultd.js#L30

Copy link
Contributor Author

Choose a reason for hiding this comment

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

I think it should be the default behavior to stop the process.

Most processes don't have any listener on this.
I plan to use simply:

require('werelogs').stderrUtils.catchAndTimestampStderr();

Some processes have, like cloudserver when it does not exit all the time and could end in undefined behavior.


/**
* Forces the use of `--trace-warnings` and adds a date in warning.detail
* The warning will be printed by the default `onWarning`
*
* @param {string} [dateFct=`defaultTimestamp`] Fct returning a formatted date
* @returns {undefined}
*/
function catchAndTimestampWarning(dateFct = defaultTimestamp) {
process.traceProcessWarnings = true;
// must be executed first, before the default `onWarning`
process.prependListener('warning', warning => {
if (warning.detail) {
// eslint-disable-next-line no-param-reassign
warning.detail += `\nAbove Warning Date: ${dateFct()}`;
} else {
// eslint-disable-next-line no-param-reassign
warning.detail = `Above Warning Date: ${dateFct()}`;
}
});
}

/**
* Adds listener for uncaughtException and warning to print them with timestamp.
*
* If you want to manage the end of the process, you can set exitCode to null.
* Or use `printErrorWithTimestamp` in your own uncaughtException listener.
*
* @example
* const { stderrUtils } = require('werelogs');
* // first instruction in your index.js or entrypoint
* stderrUtils.catchAndTimestampStderr();
*
* @param {Function} [dateFct=`defaultTimestamp`] Fct returning a formatted date
* @param {*} [exitCode=1] On uncaughtException, if not null, `process.exit`
* will be called with this value
* @returns {undefined}
*/
function catchAndTimestampStderr(
dateFct = defaultTimestamp, exitCode = 1,
) {
catchAndTimestampUncaughtException(dateFct, exitCode);
catchAndTimestampWarning(dateFct);
}

module.exports = {
defaultTimestamp,
printErrorWithTimestamp,
catchAndTimestampUncaughtException,
catchAndTimestampWarning,
catchAndTimestampStderr,
};
2 changes: 1 addition & 1 deletion package.json
Original file line number Diff line number Diff line change
Expand Up @@ -3,7 +3,7 @@
"engines": {
"node": ">=10"
},
"version": "7.4.1",
"version": "7.10.5",
"description": "An efficient raw JSON logging library aimed at micro-services architectures.",
"main": "index.js",
"scripts": {
Expand Down
17 changes: 17 additions & 0 deletions tests/unit/fixtures/stderrUtils/catchStderr.js
Original file line number Diff line number Diff line change
@@ -0,0 +1,17 @@
#!/usr/bin/env node
// Convert string args into primitive value
const fromStr = (str, primitive) => (str === `${primitive}` ? primitive : str);
const date = fromStr(process.argv[2], undefined);
const exitCode = fromStr(fromStr(process.argv[3], null), undefined);

const { stderrUtils } = require('../../../../index');

stderrUtils.catchAndTimestampStderr(
date ? () => date : undefined,
exitCode,
);

process.emitWarning('TestWarningMessage');
// This will print warning after printing error before exit
throw new Error('TestingError');

23 changes: 23 additions & 0 deletions tests/unit/fixtures/stderrUtils/catchUncaughtException.js
Original file line number Diff line number Diff line change
@@ -0,0 +1,23 @@
#!/usr/bin/env node
// Convert string args into primitive value
const fromStr = (str, primitive) => (str === `${primitive}` ? primitive : str);
const date = fromStr(process.argv[2], undefined);
const exitCode = fromStr(fromStr(process.argv[3], null), undefined);
const promise = fromStr(process.argv[4], true);

const { stderrUtils } = require('../../../../index');

stderrUtils.catchAndTimestampUncaughtException(
date ? () => date : undefined,
exitCode,
);

// Executed if process does not exit, process is in undefined behavior (bad)
// eslint-disable-next-line no-console
setTimeout(() => console.log('EXECUTED AFTER UNCAUGHT EXCEPTION'), 1);

if (promise === true) {
Promise.reject();
} else {
throw new Error('TestingError');
}
38 changes: 38 additions & 0 deletions tests/unit/fixtures/stderrUtils/catchWarning.js
Original file line number Diff line number Diff line change
@@ -0,0 +1,38 @@
#!/usr/bin/env node
// Convert string args into primitive value
const fromStr = (str, primitive) => (str === `${primitive}` ? primitive : str);
const date = fromStr(process.argv[2], undefined);
const name = fromStr(process.argv[3], undefined);
const code = fromStr(process.argv[4], undefined);
const detail = fromStr(process.argv[5], undefined);

const { stderrUtils } = require('../../../../index');

stderrUtils.catchAndTimestampWarning(
date ? () => date : undefined,
);

const warning = new Error('TestWarningMessage');

if (name) warning.name = name;
if (code) warning.code = code;
if (detail) warning.detail = detail;

process.emitWarning(warning);

/*
Examples:

(node:203831) Error: TestWarningMessage
at Object.<anonymous> (catchWarning.js:15:17)
...
at node:internal/main/run_main_module:22:47
Above Warning Date: 2024-06-26T16:32:55.505Z

(node:205151) [TEST01] CUSTOM: TestWarningMessage
at Object.<anonymous> (catchWarning.js:15:17)
...
at node:internal/main/run_main_module:22:47
Some additional detail
Above Warning Date: Tue, 31 Dec 2024 10:20:30 GMT
*/
Loading
Loading