From dd2d71175dae11ece235d17b2301b7d4e537271a Mon Sep 17 00:00:00 2001 From: Mickael Bourgois Date: Mon, 24 Jun 2024 09:52:00 +0200 Subject: [PATCH 1/5] WRLGS-11: Generic function for timestamp in stderr --- index.js | 37 ++++++++++++++++ lib/stderrUtils.js | 106 +++++++++++++++++++++++++++++++++++++++++++++ 2 files changed, 143 insertions(+) create mode 100644 lib/stderrUtils.js diff --git a/index.js b/index.js index 95b4001..9cbb0ea 100644 --- a/index.js +++ b/index.js @@ -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 @@ -11,4 +12,40 @@ module.exports = { Logger: werelogs.Logger, configure: werelogs.reconfigure.bind(werelogs), Werelogs: API, + /** + * Timestamp logs going to stderr + * + * @example Simplest usage + * ``` + * const { stderrUtils } = require('werelogs'); + * stderrUtils.catchAndTimestampStderr(); + * ``` + * + * @example Manage process exit + * ``` + * 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 Custom listener + * ``` + * 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, }; diff --git a/lib/stderrUtils.js b/lib/stderrUtils.js new file mode 100644 index 0000000..df3e1e0 --- /dev/null +++ b/lib/stderrUtils.js @@ -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`); +} + +/** + * 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)); + } + }); +} + +/** + * 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, +}; From da2224fbf7766f38812d980bc8183f8fd7bbc8ad Mon Sep 17 00:00:00 2001 From: Mickael Bourgois Date: Wed, 26 Jun 2024 14:58:30 +0200 Subject: [PATCH 2/5] WRLGS-11: Test stderrUtils --- .../unit/fixtures/stderrUtils/catchStderr.js | 17 ++ .../stderrUtils/catchUncaughtException.js | 23 ++ .../unit/fixtures/stderrUtils/catchWarning.js | 38 +++ tests/unit/stderrUtils.js | 276 ++++++++++++++++++ 4 files changed, 354 insertions(+) create mode 100755 tests/unit/fixtures/stderrUtils/catchStderr.js create mode 100755 tests/unit/fixtures/stderrUtils/catchUncaughtException.js create mode 100755 tests/unit/fixtures/stderrUtils/catchWarning.js create mode 100644 tests/unit/stderrUtils.js diff --git a/tests/unit/fixtures/stderrUtils/catchStderr.js b/tests/unit/fixtures/stderrUtils/catchStderr.js new file mode 100755 index 0000000..9262e9c --- /dev/null +++ b/tests/unit/fixtures/stderrUtils/catchStderr.js @@ -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'); + diff --git a/tests/unit/fixtures/stderrUtils/catchUncaughtException.js b/tests/unit/fixtures/stderrUtils/catchUncaughtException.js new file mode 100755 index 0000000..1271a6b --- /dev/null +++ b/tests/unit/fixtures/stderrUtils/catchUncaughtException.js @@ -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'); +} diff --git a/tests/unit/fixtures/stderrUtils/catchWarning.js b/tests/unit/fixtures/stderrUtils/catchWarning.js new file mode 100755 index 0000000..75fc865 --- /dev/null +++ b/tests/unit/fixtures/stderrUtils/catchWarning.js @@ -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. (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. (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 +*/ diff --git a/tests/unit/stderrUtils.js b/tests/unit/stderrUtils.js new file mode 100644 index 0000000..4f8a5bb --- /dev/null +++ b/tests/unit/stderrUtils.js @@ -0,0 +1,276 @@ +const assert = require('assert'); +const { execFile } = require('child_process'); + +const stderrUtils = require('../../lib/stderrUtils'); + +/** Simple regex for ISO YYYY-MM-DDThh:mm:ss.sssZ */ +// eslint-disable-next-line max-len +const defaultDateRegex = /\d{4}-[01]\d-[0-3]\dT[0-2]\d:[0-5]\d:[0-5]\d\.\d+(?:[+-][0-2]\d:[0-5]\d|Z)/; + +// eslint-disable-next-line valid-jsdoc +/** another format: Tue, 31 Dec 2024 10:20:30 GMT */ +const customDate = () => new Date('2024-12-31T10:20:30.444Z').toUTCString(); + +describe('stderrUtils', () => { + const errStackRegex = /Error: TestingError\n(?:.*\sat\s.*\n)+/; + + describe('defaultTimestamp', () => { + it('should match ISO format', () => { + assert.match(stderrUtils.defaultTimestamp(), defaultDateRegex); + }); + }); + + describe('printErrorWithTimestamp', () => { + let stderrText; + const originalStderrWrite = process.stderr.write; + const mockedStderrWrite = text => { stderrText = text; return true; }; + const err = new Error('TestingError'); + const origin = 'uncaughtException'; + + beforeEach(() => { + stderrText = undefined; + process.stderr.write = mockedStderrWrite; + }); + + afterEach(() => { + process.stderr.write = originalStderrWrite; + stderrText = undefined; + }); + + it( + 'should write to stderr with current date, origin and stacktrace', + () => { + const written = stderrUtils + .printErrorWithTimestamp(err, origin); + + assert.strictEqual(written, true); + const [firstLine, errStack] = stderrText.split(':\n'); + const [errDate, errOrigin] = firstLine.split(': '); + + assert.match(errDate, defaultDateRegex); + assert.strictEqual(errOrigin, origin); + assert.strictEqual(errStack, `${err.stack}\n`); + }, + ); + + it( + 'should write to stderr with custom date, origin and stacktrace', + () => { + const written = stderrUtils + .printErrorWithTimestamp(err, origin, customDate()); + + assert.strictEqual(written, true); + const [firstLine, errStack] = stderrText.split(':\n'); + const [errDate, errOrigin] = firstLine.split(': '); + + assert.strictEqual(errDate, customDate()); + assert.strictEqual(errOrigin, origin); + assert.strictEqual(errStack, `${err.stack}\n`); + }, + ); + }); + + const execOptions = { + cwd: __dirname, + // Subprocess should always stop alone + // But just in case, kill subprocess after 500ms. + // Leave enough time for `nyc` that runs slower. + timeout: 500, + }; + + // Execute in another process to notice the process exit + // Therefore, looks more like a functional test + + describe('catchAndTimestampUncaughtException', () => { + [ + { desc: 'with default date' }, + { desc: 'with custom date', date: customDate() }, + { desc: 'with custom exitCode 42', exitCode: 42 }, + { desc: 'without exit on uncaught exception', exitCode: null }, + { desc: 'for unhandled promise', promise: true }, + ].forEach(({ + desc, date, exitCode, promise, + }) => describe(desc, () => { + let err; + let stdout; + let stderr; + let errStack; + let errDate; + let errOrigin; + + before('run process catchUncaughtException', done => { + execFile( + './fixtures/stderrUtils/catchUncaughtException.js', + [`${date}`, `${exitCode}`, `${promise}`], + execOptions, + (subErr, subStdout, subStderr) => { + err = subErr; + stdout = subStdout; + stderr = subStderr; + let firstLine; + [firstLine, errStack] = stderr.split(':\n'); + [errDate, errOrigin] = firstLine.split(': '); + done(); + }, + ); + }); + + if (exitCode === null) { + it('should not be an error (or timeout)', + () => assert.ifError(err)); + it('should have stdout (printed after uncaught exception)', + () => assert.match(stdout, + /^.*EXECUTED AFTER UNCAUGHT EXCEPTION(?:.|\n)*$/)); + } else { + it('should be an error', + () => assert.ok(err)); + it(`should have exitCode ${exitCode || 1}`, + () => assert.strictEqual(err.code, exitCode || 1)); + it('should have empty stdout', + () => assert.strictEqual(stdout, '')); + } + + it('should have stderr', + () => assert.ok(stderr)); + it('should have date in stderr first line', + () => (date + ? assert.strictEqual(errDate, date) + : assert.match(errDate, defaultDateRegex))); + + it('should have origin in stderr first line', + () => (promise === true + ? assert.strictEqual(errOrigin, 'unhandledRejection') + : assert.strictEqual(errOrigin, 'uncaughtException'))); + + if (!promise) { + it('should have stack trace on stderr', + () => assert.match(errStack, errStackRegex)); + } + })); + }); + + describe('catchAndTimestampWarning (also tests node onWarning)', () => { + [ + { desc: 'with default date' }, + { desc: 'with custom date', date: customDate() }, + { desc: 'with deprecation warning', name: 'DeprecationWarning' }, + { + desc: 'with custom warning', + name: 'CUSTOM', + code: 'TEST01', + detail: 'Some additional detail', + }, + ].forEach(({ + desc, date, name, code, detail, + }) => describe(desc, () => { + let err; + let stdout; + let stderr; + + before('run process catchWarning', done => { + execFile( + './fixtures/stderrUtils/catchWarning.js', + [`${date}`, `${name}`, `${code}`, `${detail}`], + execOptions, + (subErr, subStdout, subStderr) => { + err = subErr; + stdout = subStdout; + stderr = subStderr; + done(); + }, + ); + }); + + it('should not be an error (or timeout)', + () => assert.ifError(err)); + it('should have empty stdout', + () => assert.strictEqual(stdout, '')); + it('should have stderr', + () => assert.ok(stderr)); + it('should have message on stderr first line, then stack trace', + () => assert.match(stderr, + /^.*TestWarningMessage\n(?:\s+at\s.*\n)+/)); + + if (code) { + it('should have code on stderr first line', + () => assert.match(stderr, new RegExp(`^.*[${code}]`))); + } + + if (name) { + it('should have name on stderr first line', + () => assert.match(stderr, new RegExp(`^.*${name}:`))); + } + + if (detail) { + it('should have detail on stderr', + () => assert.match(stderr, new RegExp(`.*${detail}.*`))); + } + + it(`should have ${date ? 'custom' : 'default'} date on stderr`, + () => assert.match(stderr, new RegExp( + `\nAbove Warning Date: ${ + date || defaultDateRegex.source}\n`, + ))); + })); + }); + + describe('catchAndTimestampStderr', () => { + [ + { desc: 'with default date' }, + { desc: 'with custom date', date: customDate() }, + { desc: 'with exit code', exitCode: 42 }, + + ].forEach(({ + desc, date, exitCode, + }) => describe(desc, () => { + let err; + let stdout; + let stderr; + + before('run process catchStderr', done => { + execFile( + './fixtures/stderrUtils/catchStderr.js', + [`${date}`, `${exitCode}`], + execOptions, + (subErr, subStdout, subStderr) => { + err = subErr; + stdout = subStdout; + stderr = subStderr; + done(); + }, + ); + }); + + it('should be an error', + () => assert.ok(err)); + it(`should have exitCode ${exitCode || 1}`, + () => assert.strictEqual(err.code, exitCode || 1)); + it('should have empty stdout', + () => assert.strictEqual(stdout, '')); + + it('should have stderr', + () => assert.ok(stderr)); + + // 2024-06-26T15:04:55.364Z: uncaughtException: + // Error: TestingError + // at Object. (catchStderr.js:16:7) + // at node:internal/main/run_main_module:22:47 + it('should have error date, origin and stacktrace in stderr', + () => assert.match(stderr, + new RegExp(`${date || defaultDateRegex.source + }: uncaughtException:\n${errStackRegex.source}`))); + + // (node:171245) Warning: TestWarningMessage + // at Object. (catchStderr.js:14:9) + // at node:internal/main/run_main_module:22:47 + // Above Warning Date: 2024-06-26T15:04:55.365Z + it('should have warning with stacktrace in stderr', () => { + const trace = 'Warning: TestWarningMessage\n(?:\\s+at\\s.*\n)+'; + const detail = `(?:.|\n)*?(?<=\n)Above Warning Date: ${ + date || defaultDateRegex.source}\n`; + assert.match(stderr, + new RegExp(`${trace}${detail}`)); + }); + })); + }); +}); From 68df3de3e928e2c78918a13c06b636b17df2e8f9 Mon Sep 17 00:00:00 2001 From: Mickael Bourgois Date: Wed, 26 Jun 2024 21:05:57 +0200 Subject: [PATCH 3/5] WRLGS-11: update dev deps for nyc coverage --- yarn.lock | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/yarn.lock b/yarn.lock index dae0cd2..a3389db 100644 --- a/yarn.lock +++ b/yarn.lock @@ -520,9 +520,9 @@ camelcase@^6.0.0: integrity sha512-c7wVvbw3f37nuobQNtgsgG9POC9qMbNuMQmTCqZv23b6MIz0fcYpBiOlv9gEN/hdLdnZTDQhg6e9Dq5M1vKvfg== caniuse-lite@^1.0.30001259: - version "1.0.30001261" - resolved "https://registry.yarnpkg.com/caniuse-lite/-/caniuse-lite-1.0.30001261.tgz#96d89813c076ea061209a4e040d8dcf0c66a1d01" - integrity sha512-vM8D9Uvp7bHIN0fZ2KQ4wnmYFpJo/Etb4Vwsuc+ka0tfGDHvOPrFm6S/7CCNLSOkAUjenT2HnUPESdOIL91FaA== + version "1.0.30001637" + resolved "https://registry.npmjs.org/caniuse-lite/-/caniuse-lite-1.0.30001637.tgz" + integrity sha512-1x0qRI1mD1o9e+7mBI7XtzFAP4XszbHaVWsMiGbSPLYekKTJF7K+FNk6AsXH4sUpc+qrsI3pVgf1Jdl/uGkuSQ== catharsis@^0.8.11: version "0.8.11" From b40a74ea3921cbdc45075f13d2e4a3d76d5a94fd Mon Sep 17 00:00:00 2001 From: Mickael Bourgois Date: Fri, 28 Jun 2024 11:57:54 +0200 Subject: [PATCH 4/5] WRLGS-11: Fix coverage test in latest branch nyc coverage seems to slow down the process on first run The slow seems to vary between branches (due to nyc version) --- tests/unit/stderrUtils.js | 39 ++++++++++++++++++++++++++++++++++++--- 1 file changed, 36 insertions(+), 3 deletions(-) diff --git a/tests/unit/stderrUtils.js b/tests/unit/stderrUtils.js index 4f8a5bb..007ab2f 100644 --- a/tests/unit/stderrUtils.js +++ b/tests/unit/stderrUtils.js @@ -80,6 +80,9 @@ describe('stderrUtils', () => { // Execute in another process to notice the process exit // Therefore, looks more like a functional test + const timeoutHint = (ms, retries) => + `Test fixture process timed out after ${ms}ms with ${retries} retries.\n` + + 'Due to nyc coverage first run slowing down process.\nIncrease execOptions.timeout to fix'; describe('catchAndTimestampUncaughtException', () => { [ @@ -91,6 +94,8 @@ describe('stderrUtils', () => { ].forEach(({ desc, date, exitCode, promise, }) => describe(desc, () => { + /** for before all hook that doesn't support this.retries */ + let retries = 4; let err; let stdout; let stderr; @@ -98,12 +103,20 @@ describe('stderrUtils', () => { let errDate; let errOrigin; - before('run process catchUncaughtException', done => { + before('run process catchUncaughtException', function beforeAllHook(done) { execFile( './fixtures/stderrUtils/catchUncaughtException.js', [`${date}`, `${exitCode}`, `${promise}`], execOptions, (subErr, subStdout, subStderr) => { + if (subErr?.killed) { + retries--; + if (retries <= 0) { + assert.fail(timeoutHint(execOptions.timeout, retries)); + } + execOptions.timeout *= 2; + return beforeAllHook(done); + } err = subErr; stdout = subStdout; stderr = subStderr; @@ -163,16 +176,26 @@ describe('stderrUtils', () => { ].forEach(({ desc, date, name, code, detail, }) => describe(desc, () => { + /** for before all hook that doesn't support this.retries */ + let retries = 4; let err; let stdout; let stderr; - before('run process catchWarning', done => { + before('run process catchWarning', function beforeAllHook(done) { execFile( './fixtures/stderrUtils/catchWarning.js', [`${date}`, `${name}`, `${code}`, `${detail}`], execOptions, (subErr, subStdout, subStderr) => { + if (subErr?.killed) { + retries--; + if (retries <= 0) { + assert.fail(timeoutHint(execOptions.timeout, retries)); + } + execOptions.timeout *= 2; + return beforeAllHook(done); + } err = subErr; stdout = subStdout; stderr = subStderr; @@ -223,16 +246,26 @@ describe('stderrUtils', () => { ].forEach(({ desc, date, exitCode, }) => describe(desc, () => { + /** for before all hook that doesn't support this.retries */ + let retries = 4; let err; let stdout; let stderr; - before('run process catchStderr', done => { + before('run process catchStderr', function beforeAllHook(done) { execFile( './fixtures/stderrUtils/catchStderr.js', [`${date}`, `${exitCode}`], execOptions, (subErr, subStdout, subStderr) => { + if (subErr?.killed) { + retries--; + if (retries <= 0) { + assert.fail(timeoutHint(execOptions.timeout, retries)); + } + execOptions.timeout *= 2; + return beforeAllHook(done); + } err = subErr; stdout = subStdout; stderr = subStderr; From 4984e5be3cc385b5b2ebd2f3b5d2ab226f1ef4a2 Mon Sep 17 00:00:00 2001 From: Mickael Bourgois Date: Wed, 26 Jun 2024 20:14:40 +0200 Subject: [PATCH 5/5] WRLGS-11: Fix and bump package version All tags from 7.4.10 and 7.10.1.0 to 7.10.4.10 are all the same commit 23dfe7c --- package.json | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/package.json b/package.json index fd28787..3969fac 100644 --- a/package.json +++ b/package.json @@ -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": {