From c6656db352973d6aea24cb1a3c76adf042b25446 Mon Sep 17 00:00:00 2001 From: James M Snell Date: Wed, 20 Jan 2016 11:38:35 -0800 Subject: [PATCH] process: add 'warning' event and process.emitWarning() In several places throughout the code we write directly to stderr to report warnings (deprecation, possible eventemitter memory leak). The current design of simply dumping the text to stderr is less than ideal. This PR introduces a new "process warnings" mechanism that emits 'warning' events on the global process object. These are invoked with a `warning` argument whose value is an Error object. By default, these warnings will be printed to stderr. This can be suppressed using the `--no-warnings` and `--no-deprecation` command line flags. For warnings, the 'warning' event will still be emitted by the process, allowing applications to handle the warnings in custom ways. The existing `--no-deprecation` flag will continue to supress all deprecation output generated by the core lib. The `--trace-warnings` command line flag will tell Node.js to print the full stack trace of warnings as part of the default handling. The existing `--no-deprecation`, `--throw-deprecation` and `--trace-deprecation` flags continue to work as they currently do, but the exact output of the warning message is modified to occur on process.nextTick(). The stack trace for the warnings and deprecations preserve and point to the correct call site. A new `process.emitWarning()` API is provided to permit userland to emit warnings and deprecations using the same consistent mechanism. Test cases and documentation are included. PR-URL: https://github.com/nodejs/node/pull/4782 Reviewed-By: Rod Vagg Reviewed-By: Wyatt Preul Reviewed-By: Jeremiah Senkpiel --- doc/api/cli.markdown | 7 + doc/api/process.markdown | 204 +++++++++++++++++++- doc/node.1 | 8 + lib/events.js | 12 +- lib/internal/bootstrap_node.js | 1 + lib/internal/process/warning.js | 49 +++++ lib/internal/util.js | 30 +-- node.gyp | 1 + src/node.cc | 18 ++ test/fixtures/warnings.js | 3 + test/parallel/test-global-console-exists.js | 29 +-- test/parallel/test-process-emitwarning.js | 29 +++ test/sequential/test-deprecation-flags.js | 23 ++- test/sequential/test-process-warnings.js | 33 ++++ 14 files changed, 393 insertions(+), 54 deletions(-) create mode 100644 lib/internal/process/warning.js create mode 100644 test/fixtures/warnings.js create mode 100644 test/parallel/test-process-emitwarning.js create mode 100644 test/sequential/test-process-warnings.js diff --git a/doc/api/cli.markdown b/doc/api/cli.markdown index 2910c782d2..52e3f2709c 100644 --- a/doc/api/cli.markdown +++ b/doc/api/cli.markdown @@ -76,6 +76,13 @@ Print stack traces for deprecations. Throw errors for deprecations. +### `--no-warnings` + +Silence all process warnings (including deprecations). + +### `--trace-warnings` + +Print stack traces for process warnings (including deprecations). ### `--trace-sync-io` diff --git a/doc/api/process.markdown b/doc/api/process.markdown index d9bd8cc452..2e65e6a4b1 100644 --- a/doc/api/process.markdown +++ b/doc/api/process.markdown @@ -186,6 +186,120 @@ this, you can either attach a dummy `.catch(() => { })` handler to `resource.loaded`, preventing the `'unhandledRejection'` event from being emitted, or you can use the [`'rejectionHandled'`][] event. +## Event: 'warning' + +Emitted whenever Node.js emits a process warning. + +A process warning is similar to an error in that it describes exceptional +conditions that are being brought to the user's attention. However, warnings +are not part of the normal Node.js and JavaScript error handling flow. +Node.js can emit warnings whenever it detects bad coding practices that could +lead to sub-optimal application performance, bugs or security vulnerabilities. + +The event handler for `'warning'` events is called with a single `warning` +argument whose value is an `Error` object. There are three key properties that +describe the warning: + +* `name` - The name of the warning (currently `Warning` by default). +* `message` - A system-provided description of the warning. +* `stack` - A stack trace to the location in the code where the warning was + issued. + +```js +process.on('warning', (warning) => { + console.warn(warning.name); // Print the warning name + console.warn(warning.message); // Print the warning message + console.warn(warning.stack); // Print the stack trace +}); +``` + +By default, Node.js will print process warnings to `stderr`. The `--no-warnings` +command-line option can be used to suppress the default console output but the +`'warning'` event will still be emitted by the `process` object. + +The following example illustrates the warning that is printed to `stderr` when +too many listeners have been added to an event + +``` +$ node +> event.defaultMaxListeners = 1; +> process.on('foo', () => {}); +> process.on('foo', () => {}); +> (node:38638) Warning: Possible EventEmitter memory leak detected. 2 foo +... listeners added. Use emitter.setMaxListeners() to increase limit +``` + +In contrast, the following example turns off the default warning output and +adds a custom handler to the `'warning'` event: + +``` +$ node --no-warnings +> var p = process.on('warning', (warning) => console.warn('Do not do that!')); +> event.defaultMaxListeners = 1; +> process.on('foo', () => {}); +> process.on('foo', () => {}); +> Do not do that! +``` + +The `--trace-warnings` command-line option can be used to have the default +console output for warnings include the full stack trace of the warning. + +### Emitting custom warnings + +The [`process.emitWarning()`][process_emit_warning] method can be used to issue +custom or application specific warnings. + +```js +// Emit a warning using a string... +process.emitWarning('Something happened!'); + // Prints: (node 12345) Warning: Something happened! + +// Emit a warning using an object... +process.emitWarning('Something Happened!', 'CustomWarning'); + // Prints: (node 12345) CustomWarning: Something happened! + +// Emit a warning using a custom Error object... +class CustomWarning extends Error { + constructor(message) { + super(message); + this.name = 'CustomWarning'; + Error.captureStackTrace(this, CustomWarning); + } +} +const myWarning = new CustomWarning('Something happened!'); +process.emitWarning(myWarning); + // Prints: (node 12345) CustomWarning: Something happened! +``` + +### Emitting custom deprecation warnings + +Custom deprecation warnings can be emitted by setting the `name` of a custom +warning to `DeprecationWarning`. For instance: + +```js +process.emitWarning('This API is deprecated', 'DeprecationWarning'); +``` + +Or, + +```js +const err = new Error('This API is deprecated'); +err.name = 'DeprecationWarning'; +process.emitWarning(err); +``` + +Launching Node.js using the `--throw-deprecation` command line flag will +cause custom deprecation warnings to be thrown as exceptions. + +Using the `--trace-deprecation` command line flag will cause the custom +deprecation to be printed to `stderr` along with the stack trace. + +Using the `--no-deprecation` command line flag will suppress all reporting +of the custom deprecation. + +The `*-deprecation` command line flags only affect warnings that use the name +`DeprecationWarning`. + ## Exit Codes Node.js will normally exit with a `0` status code when no more async @@ -457,6 +571,92 @@ console.log(process.env.TEST); // => undefined ``` +## process.emitWarning(warning[, name][, ctor]) + +* `warning` {String | Error} The warning to emit. +* `name` {String} When `warning` is a String, `name` is the name to use + for the warning. Default: `Warning`. +* `ctor` {Function} When `warning` is a String, `ctor` is an optional + function used to limit the generated stack trace. Default + `process.emitWarning` + +The `process.emitWarning()` method can be used to emit custom or application +specific process warnings. These can be listened for by adding a handler to the +[`process.on('warning')`][process_warning] event. + +```js +// Emit a warning using a string... +process.emitWarning('Something happened!'); + // Emits: (node: 56338) Warning: Something happened! +``` + +``` +// Emit a warning using a string and a name... +process.emitWarning('Something Happened!', 'CustomWarning'); + // Emits: (node:56338) CustomWarning: Something Happened! +``` + +In each of the previous examples, an `Error` object is generated internally by +`process.emitWarning()` and passed through to the +[`process.on('warning')`][process_warning] event. + +``` +process.on('warning', (warning) => { + console.warn(warning.name); + console.warn(warning.message); + console.warn(warning.stack); +}); +``` + +If `warning` is passed as an `Error` object, it will be passed through to the +`process.on('warning')` event handler unmodified (and the optional `name` +and `ctor` arguments will be ignored): + +``` +// Emit a warning using an Error object... +const myWarning = new Error('Warning! Something happened!'); +myWarning.name = 'CustomWarning'; + +process.emitWarning(myWarning); + // Emits: (node:56338) CustomWarning: Warning! Something Happened! +``` + +A `TypeError` is thrown if `warning` is anything other than a string or `Error` +object. + +Note that while process warnings use `Error` objects, the process warning +mechanism is **not** a replacement for normal error handling mechanisms. + +The following additional handling is implemented if the warning `name` is +`DeprecationWarning`: + +* If the `--throw-deprecation` command-line flag is used, the deprecation + warning is thrown as an exception rather than being emitted as an event. +* If the `--no-deprecation` command-line flag is used, the deprecation + warning is suppressed. +* If the `--trace-deprecation` command-line flag is used, the deprecation + warning is printed to `stderr` along with the full stack trace. + +### Avoiding duplicate warnings + +As a best practice, warnings should be emitted only once per process. To do +so, it is recommended to place the `emitWarning()` behind a simple boolean +flag as illustrated in the example below: + +``` +var warned = false; +function emitMyWarning() { + if (!warned) { + process.emitWarning('Only warn once!'); + warned = true; + } +} +emitMyWarning(); + // Emits: (node: 56339) Warning: Only warn once! +emitMyWarning(); + // Emits nothing +``` + ## process.execArgv This is the set of Node.js-specific command line options from the @@ -1098,4 +1298,6 @@ Will print something like: [Signal Events]: #process_signal_events [Stream compatibility]: stream.html#stream_compatibility_with_older_node_js_versions [the tty docs]: tty.html#tty_tty -[`JSON.stringify()`]: https://developer.mozilla.org/en-US/docs/Web/JavaScript/Reference/Global_Objects/JSON/stringify \ No newline at end of file +[`JSON.stringify()`]: https://developer.mozilla.org/en-US/docs/Web/JavaScript/Reference/Global_Objects/JSON/stringify +[process_warning]: #process_event_warning +[process_emit_warning]: #process_emitwarning_warning_name_ctor diff --git a/doc/node.1 b/doc/node.1 index 7785ef4fe4..3a74477b6c 100644 --- a/doc/node.1 +++ b/doc/node.1 @@ -78,6 +78,14 @@ Print stack traces for deprecations. .BR \-\-throw\-deprecation Throw errors for deprecations. +.TP +.BR \-\-no\-warnings +Silence all process warnings (including deprecations). + +.TP +.BR \-\-trace\-warnings +Print stack traces for process warnings (including deprecations). + .TP .BR \-\-trace\-sync\-io Prints a stack trace whenever synchronous I/O is detected after the first turn diff --git a/lib/events.js b/lib/events.js index 7103ec393f..a67de552f1 100644 --- a/lib/events.js +++ b/lib/events.js @@ -1,6 +1,5 @@ 'use strict'; -var internalUtil; var domain; function EventEmitter() { @@ -246,14 +245,9 @@ EventEmitter.prototype.addListener = function addListener(type, listener) { m = $getMaxListeners(this); if (m && m > 0 && existing.length > m) { existing.warned = true; - if (!internalUtil) - internalUtil = require('internal/util'); - - internalUtil.error('warning: possible EventEmitter memory ' + - 'leak detected. %d %s listeners added. ' + - 'Use emitter.setMaxListeners() to increase limit.', - existing.length, type); - console.trace(); + process.emitWarning('Possible EventEmitter memory leak detected. ' + + `${existing.length} ${type} listeners added. ` + + 'Use emitter.setMaxListeners() to increase limit'); } } } diff --git a/lib/internal/bootstrap_node.js b/lib/internal/bootstrap_node.js index 0a688a1b0f..e4fd8d7dec 100644 --- a/lib/internal/bootstrap_node.js +++ b/lib/internal/bootstrap_node.js @@ -47,6 +47,7 @@ _process.setup_hrtime(); _process.setupConfig(NativeModule._source); + NativeModule.require('internal/process/warning').setup(); NativeModule.require('internal/process/next_tick').setup(); NativeModule.require('internal/process/stdio').setup(); _process.setupKillAndExit(); diff --git a/lib/internal/process/warning.js b/lib/internal/process/warning.js new file mode 100644 index 0000000000..4087eb0d28 --- /dev/null +++ b/lib/internal/process/warning.js @@ -0,0 +1,49 @@ +'use strict'; + +const traceWarnings = process.traceProcessWarnings; +const noDeprecation = process.noDeprecation; +const traceDeprecation = process.traceDeprecation; +const throwDeprecation = process.throwDeprecation; +const prefix = `(${process.release.name}:${process.pid}) `; + +exports.setup = setupProcessWarnings; + +function setupProcessWarnings() { + if (!process.noProcessWarnings) { + process.on('warning', (warning) => { + if (!(warning instanceof Error)) return; + const isDeprecation = warning.name === 'DeprecationWarning'; + if (isDeprecation && noDeprecation) return; + const trace = traceWarnings || (isDeprecation && traceDeprecation); + if (trace && warning.stack) { + console.error(`${prefix}${warning.stack}`); + } else { + var toString = warning.toString; + if (typeof toString !== 'function') + toString = Error.prototype.toString; + console.error(`${prefix}${toString.apply(warning)}`); + } + }); + } + + // process.emitWarning(error) + // process.emitWarning(str[, name][, ctor]) + process.emitWarning = function(warning, name, ctor) { + if (typeof name === 'function') { + ctor = name; + name = 'Warning'; + } + if (warning === undefined || typeof warning === 'string') { + warning = new Error(warning); + warning.name = name || 'Warning'; + Error.captureStackTrace(warning, ctor || process.emitWarning); + } + if (!(warning instanceof Error)) { + throw new TypeError('\'warning\' must be an Error object or string.'); + } + if (throwDeprecation && warning.name === 'DeprecationWarning') + throw warning; + else + process.nextTick(() => process.emit('warning', warning)); + }; +} diff --git a/lib/internal/util.js b/lib/internal/util.js index a9e77c658f..56398ccf9d 100644 --- a/lib/internal/util.js +++ b/lib/internal/util.js @@ -2,6 +2,7 @@ const binding = process.binding('util'); const prefix = `(${process.release.name}:${process.pid}) `; +const noDeprecation = process.noDeprecation; exports.getHiddenValue = binding.getHiddenValue; exports.setHiddenValue = binding.setHiddenValue; @@ -9,13 +10,17 @@ exports.setHiddenValue = binding.setHiddenValue; // All the internal deprecations have to use this function only, as this will // prepend the prefix to the actual message. exports.deprecate = function(fn, msg) { - return exports._deprecate(fn, `${prefix}${msg}`); + return exports._deprecate(fn, msg); }; // All the internal deprecations have to use this function only, as this will // prepend the prefix to the actual message. -exports.printDeprecationMessage = function(msg, warned) { - return exports._printDeprecationMessage(`${prefix}${msg}`, warned); +exports.printDeprecationMessage = function(msg, warned, ctor) { + if (warned || noDeprecation) + return true; + process.emitWarning(msg, 'DeprecationWarning', + ctor || exports.printDeprecationMessage); + return true; }; exports.error = function(msg) { @@ -35,23 +40,6 @@ exports.trace = function(msg) { console.trace(`${prefix}${msg}`); }; -exports._printDeprecationMessage = function(msg, warned) { - if (process.noDeprecation) - return true; - - if (warned) - return warned; - - if (process.throwDeprecation) - throw new Error(msg); - else if (process.traceDeprecation) - console.trace(msg.startsWith(prefix) ? msg.replace(prefix, '') : msg); - else - console.error(msg); - - return true; -}; - // Mark that a method should not be used. // Returns a modified function which warns once by default. // If --no-deprecation is set, then it is a no-op. @@ -69,7 +57,7 @@ exports._deprecate = function(fn, msg) { var warned = false; function deprecated() { - warned = exports._printDeprecationMessage(msg, warned); + warned = exports.printDeprecationMessage(msg, warned, deprecated); return fn.apply(this, arguments); } diff --git a/node.gyp b/node.gyp index 0eeebfcad4..510e8d89cb 100644 --- a/node.gyp +++ b/node.gyp @@ -78,6 +78,7 @@ 'lib/internal/process/next_tick.js', 'lib/internal/process/promises.js', 'lib/internal/process/stdio.js', + 'lib/internal/process/warning.js', 'lib/internal/process.js', 'lib/internal/readline.js', 'lib/internal/repl.js', diff --git a/src/node.cc b/src/node.cc index f9a0519e43..f0858744ee 100644 --- a/src/node.cc +++ b/src/node.cc @@ -172,6 +172,10 @@ bool enable_fips_crypto = false; bool force_fips_crypto = false; #endif +// true if process warnings should be suppressed +bool no_process_warnings = false; +bool trace_warnings = false; + // process-relative uptime base, initialized at start-up static double prog_start_time; static bool debugger_running; @@ -3053,6 +3057,14 @@ void SetupProcessObject(Environment* env, READONLY_PROPERTY(process, "noDeprecation", True(env->isolate())); } + if (no_process_warnings) { + READONLY_PROPERTY(process, "noProcessWarnings", True(env->isolate())); + } + + if (trace_warnings) { + READONLY_PROPERTY(process, "traceProcessWarnings", True(env->isolate())); + } + // --throw-deprecation if (throw_deprecation) { READONLY_PROPERTY(process, "throwDeprecation", True(env->isolate())); @@ -3311,6 +3323,8 @@ static void PrintHelp() { " --trace-deprecation show stack traces on deprecations\n" " --throw-deprecation throw an exception anytime a deprecated " "function is used\n" + " --no-warnings silence all process warnings\n" + " --trace-warnings show stack traces on process warnings\n" " --trace-sync-io show stack trace when use of sync IO\n" " is detected after the first tick\n" " --track-heap-objects track heap object allocations for heap " @@ -3449,6 +3463,10 @@ static void ParseArgs(int* argc, force_repl = true; } else if (strcmp(arg, "--no-deprecation") == 0) { no_deprecation = true; + } else if (strcmp(arg, "--no-warnings") == 0) { + no_process_warnings = true; + } else if (strcmp(arg, "--trace-warnings") == 0) { + trace_warnings = true; } else if (strcmp(arg, "--trace-deprecation") == 0) { trace_deprecation = true; } else if (strcmp(arg, "--trace-sync-io") == 0) { diff --git a/test/fixtures/warnings.js b/test/fixtures/warnings.js new file mode 100644 index 0000000000..2b2939442d --- /dev/null +++ b/test/fixtures/warnings.js @@ -0,0 +1,3 @@ +'use strict'; + +process.emitWarning('a bad practice warning'); diff --git a/test/parallel/test-global-console-exists.js b/test/parallel/test-global-console-exists.js index 1a13ffec29..32e640cc52 100644 --- a/test/parallel/test-global-console-exists.js +++ b/test/parallel/test-global-console-exists.js @@ -4,18 +4,29 @@ 'use strict'; +const common = require('../common'); const assert = require('assert'); const EventEmitter = require('events'); const leak_warning = /EventEmitter memory leak detected\. 2 hello listeners/; var write_calls = 0; -process.stderr.write = function(data) { + +process.on('warning', (warning) => { + // This will be called after the default internal + // process warning handler is called. The default + // process warning writes to the console, which will + // invoke the monkeypatched process.stderr.write + // below. + assert.strictEqual(write_calls, 1); + EventEmitter.defaultMaxListeners = old_default; + // when we get here, we should be done +}); + +process.stderr.write = (data) => { if (write_calls === 0) assert.ok(data.match(leak_warning)); - else if (write_calls === 1) - assert.ok(data.match(/Trace/)); else - assert.ok(false, 'stderr.write should be called only twice'); + common.fail('stderr.write should be called only once'); write_calls++; }; @@ -24,13 +35,9 @@ const old_default = EventEmitter.defaultMaxListeners; EventEmitter.defaultMaxListeners = 1; const e = new EventEmitter(); -e.on('hello', function() {}); -e.on('hello', function() {}); +e.on('hello', () => {}); +e.on('hello', () => {}); -// TODO: figure out how to validate console. Currently, +// TODO: Figure out how to validate console. Currently, // there is no obvious way of validating that console // exists here exactly when it should. - -assert.equal(write_calls, 2); - -EventEmitter.defaultMaxListeners = old_default; diff --git a/test/parallel/test-process-emitwarning.js b/test/parallel/test-process-emitwarning.js new file mode 100644 index 0000000000..33547377bb --- /dev/null +++ b/test/parallel/test-process-emitwarning.js @@ -0,0 +1,29 @@ +// Flags: --no-warnings +// The flag suppresses stderr output but the warning event will still emit +'use strict'; + +const common = require('../common'); +const assert = require('assert'); +const util = require('util'); + +process.on('warning', common.mustCall((warning) => { + assert(warning); + assert(/^(Warning|CustomWarning)/.test(warning.name)); + assert(warning.message, 'A Warning'); +}, 3)); + +process.emitWarning('A Warning'); +process.emitWarning('A Warning', 'CustomWarning'); + +function CustomWarning() { + Error.call(this); + this.name = 'CustomWarning'; + this.message = 'A Warning'; + Error.captureStackTrace(this, CustomWarning); +} +util.inherits(CustomWarning, Error); +process.emitWarning(new CustomWarning()); + +// TypeError is thrown on invalid output +assert.throws(() => process.emitWarning(1), TypeError); +assert.throws(() => process.emitWarning({}), TypeError); diff --git a/test/sequential/test-deprecation-flags.js b/test/sequential/test-deprecation-flags.js index 1b9521001e..35a443c2bb 100644 --- a/test/sequential/test-deprecation-flags.js +++ b/test/sequential/test-deprecation-flags.js @@ -1,16 +1,16 @@ 'use strict'; require('../common'); -var assert = require('assert'); -var execFile = require('child_process').execFile; -var depmod = require.resolve('../fixtures/deprecated.js'); -var node = process.execPath; +const assert = require('assert'); +const execFile = require('child_process').execFile; +const depmod = require.resolve('../fixtures/deprecated.js'); +const node = process.execPath; -var depUserland = +const depUserland = require.resolve('../fixtures/deprecated-userland-function.js'); -var normal = [depmod]; -var noDep = ['--no-deprecation', depmod]; -var traceDep = ['--trace-deprecation', depmod]; +const normal = [depmod]; +const noDep = ['--no-deprecation', depmod]; +const traceDep = ['--trace-deprecation', depmod]; execFile(node, normal, function(er, stdout, stderr) { console.error('normal: show deprecation warning'); @@ -34,9 +34,8 @@ execFile(node, traceDep, function(er, stdout, stderr) { assert.equal(stdout, ''); var stack = stderr.trim().split('\n'); // just check the top and bottom. - assert.equal(stack[0], - 'Trace: util.debug is deprecated. Use console.error instead.'); - assert.equal(stack.pop(), 'DEBUG: This is deprecated'); + assert(/util.debug is deprecated. Use console.error instead./.test(stack[1])); + assert(/DEBUG: This is deprecated/.test(stack[0])); console.log('trace ok'); }); @@ -44,6 +43,6 @@ execFile(node, [depUserland], function(er, stdout, stderr) { console.error('normal: testing deprecated userland function'); assert.equal(er, null); assert.equal(stdout, ''); - assert.equal(0, stderr.indexOf('deprecatedFunction is deprecated.')); + assert(/deprecatedFunction is deprecated/.test(stderr)); console.error('normal: ok'); }); diff --git a/test/sequential/test-process-warnings.js b/test/sequential/test-process-warnings.js new file mode 100644 index 0000000000..75efd53504 --- /dev/null +++ b/test/sequential/test-process-warnings.js @@ -0,0 +1,33 @@ +'use strict'; + +require('../common'); +const assert = require('assert'); +const execFile = require('child_process').execFile; +const warnmod = require.resolve('../fixtures/warnings.js'); +const node = process.execPath; + +const normal = [warnmod]; +const noWarn = ['--no-warnings', warnmod]; +const traceWarn = ['--trace-warnings', warnmod]; + +execFile(node, normal, function(er, stdout, stderr) { + // Show Process Warnings + assert.equal(er, null); + assert.equal(stdout, ''); + assert(/^\(.+\)\sWarning: a bad practice warning/.test(stderr)); +}); + +execFile(node, noWarn, function(er, stdout, stderr) { + // Hide Process Warnings + assert.equal(er, null); + assert.equal(stdout, ''); + assert(!/^\(.+\)\sWarning: a bad practice warning/.test(stderr)); +}); + +execFile(node, traceWarn, function(er, stdout, stderr) { + // Show Warning Trace + assert.equal(er, null); + assert.equal(stdout, ''); + assert(/^\(.+\)\sWarning: a bad practice warning/.test(stderr)); + assert(/at Object\.\\s\(.+warnings.js:3:9\)/.test(stderr)); +});