diff --git a/lib/internal/console/constructor.js b/lib/internal/console/constructor.js index 913b80e6eb567c..c3488d40593acf 100644 --- a/lib/internal/console/constructor.js +++ b/lib/internal/console/constructor.js @@ -13,9 +13,6 @@ const { Boolean, ErrorCaptureStackTrace, FunctionPrototypeBind, - MathFloor, - Number, - NumberPrototypeToFixed, ObjectDefineProperties, ObjectDefineProperty, ObjectKeys, @@ -30,10 +27,8 @@ const { SafeSet, SafeWeakMap, StringPrototypeIncludes, - StringPrototypePadStart, StringPrototypeRepeat, StringPrototypeSlice, - StringPrototypeSplit, Symbol, SymbolHasInstance, SymbolToStringTag, @@ -63,19 +58,14 @@ const { isTypedArray, isSet, isMap, isSetIterator, isMapIterator, } = require('internal/util/types'); const { - CHAR_LOWERCASE_B: kTraceBegin, - CHAR_LOWERCASE_E: kTraceEnd, - CHAR_LOWERCASE_N: kTraceInstant, CHAR_UPPERCASE_C: kTraceCount, } = require('internal/constants'); const { styleText } = require('util'); const kCounts = Symbol('counts'); +const { time, timeLog, timeEnd, kNone } = require('internal/util/debuglog'); const kTraceConsoleCategory = 'node,node.console'; -const kSecond = 1000; -const kMinute = 60 * kSecond; -const kHour = 60 * kMinute; const kMaxGroupIndentation = 1000; // Lazy loaded for startup performance. @@ -101,6 +91,7 @@ const kBindStreamsEager = Symbol('kBindStreamsEager'); const kBindStreamsLazy = Symbol('kBindStreamsLazy'); const kUseStdout = Symbol('kUseStdout'); const kUseStderr = Symbol('kUseStderr'); +const kInternalTimeLogImpl = Symbol('kInternalTimeLogImpl'); const optionsMap = new SafeWeakMap(); function Console(options /* or: stdout, stderr, ignoreErrors = true */) { @@ -381,6 +372,14 @@ function createWriteErrorHandler(instance, streamSymbol) { }; } +function timeLogImpl(label, formatted, args) { + if (args === undefined) { + this.log('%s: %s', label, formatted); + } else { + this.log('%s: %s', label, formatted, ...new SafeArrayIterator(args)); + } +} + const consoleMethods = { log(...args) { this[kWriteToConsole](kUseStdout, this[kFormatForStdout](args)); @@ -404,31 +403,21 @@ const consoleMethods = { }, time(label = 'default') { - // Coerces everything other than Symbol to a string - label = `${label}`; - if (this._times.has(label)) { - process.emitWarning(`Label '${label}' already exists for console.time()`); - return; - } - trace(kTraceBegin, kTraceConsoleCategory, `time::${label}`, 0); - this._times.set(label, process.hrtime()); + time(this._times, kTraceConsoleCategory, 'console.time()', kNone, label, `time::${label}`); }, timeEnd(label = 'default') { - // Coerces everything other than Symbol to a string - label = `${label}`; - const found = timeLogImpl(this, 'timeEnd', label); - trace(kTraceEnd, kTraceConsoleCategory, `time::${label}`, 0); - if (found) { - this._times.delete(label); - } + if (this[kInternalTimeLogImpl] === undefined) + this[kInternalTimeLogImpl] = FunctionPrototypeBind(timeLogImpl, this); + + timeEnd(this._times, kTraceConsoleCategory, 'console.timeEnd()', kNone, this[kInternalTimeLogImpl], label, `time::${label}`); }, timeLog(label = 'default', ...data) { - // Coerces everything other than Symbol to a string - label = `${label}`; - timeLogImpl(this, 'timeLog', label, data); - trace(kTraceInstant, kTraceConsoleCategory, `time::${label}`, 0); + if (this[kInternalTimeLogImpl] === undefined) + this[kInternalTimeLogImpl] = FunctionPrototypeBind(timeLogImpl, this); + + timeLog(this._times, kTraceConsoleCategory, 'console.timeLog()', kNone, this[kInternalTimeLogImpl], label, `time::${label}`, data); }, trace: function trace(...args) { @@ -627,63 +616,6 @@ const consoleMethods = { }, }; -// Returns true if label was found -function timeLogImpl(self, name, label, data) { - const time = self._times.get(label); - if (time === undefined) { - process.emitWarning(`No such label '${label}' for console.${name}()`); - return false; - } - const duration = process.hrtime(time); - const ms = duration[0] * 1000 + duration[1] / 1e6; - - const formatted = formatTime(ms); - - if (data === undefined) { - self.log('%s: %s', label, formatted); - } else { - self.log('%s: %s', label, formatted, ...new SafeArrayIterator(data)); - } - return true; -} - -function pad(value) { - return StringPrototypePadStart(`${value}`, 2, '0'); -} - -function formatTime(ms) { - let hours = 0; - let minutes = 0; - let seconds = 0; - - if (ms >= kSecond) { - if (ms >= kMinute) { - if (ms >= kHour) { - hours = MathFloor(ms / kHour); - ms = ms % kHour; - } - minutes = MathFloor(ms / kMinute); - ms = ms % kMinute; - } - seconds = ms / kSecond; - } - - if (hours !== 0 || minutes !== 0) { - ({ 0: seconds, 1: ms } = StringPrototypeSplit( - NumberPrototypeToFixed(seconds, 3), - '.', - )); - const res = hours !== 0 ? `${hours}:${pad(minutes)}` : minutes; - return `${res}:${pad(seconds)}.${ms} (${hours !== 0 ? 'h:m' : ''}m:ss.mmm)`; - } - - if (seconds !== 0) { - return `${NumberPrototypeToFixed(seconds, 3)}s`; - } - - return `${Number(NumberPrototypeToFixed(ms, 3))}ms`; -} - const keyKey = 'Key'; const valuesKey = 'Values'; const indexKey = '(index)'; @@ -743,5 +675,4 @@ module.exports = { kBindStreamsLazy, kBindProperties, initializeGlobalConsole, - formatTime, // exported for tests }; diff --git a/lib/internal/main/repl.js b/lib/internal/main/repl.js index f7aa3a3e2602fa..823040321262f6 100644 --- a/lib/internal/main/repl.js +++ b/lib/internal/main/repl.js @@ -24,8 +24,7 @@ markBootstrapComplete(); if (process.env.NODE_REPL_EXTERNAL_MODULE) { require('internal/modules/cjs/loader') - .Module - ._load(process.env.NODE_REPL_EXTERNAL_MODULE, undefined, true); + .wrapModuleLoad(process.env.NODE_REPL_EXTERNAL_MODULE, undefined, true); } else { // --input-type flag not supported in REPL if (getOptionValue('--input-type')) { diff --git a/lib/internal/modules/cjs/loader.js b/lib/internal/modules/cjs/loader.js index 69041d154c6fa2..2c8584d2e1036e 100644 --- a/lib/internal/modules/cjs/loader.js +++ b/lib/internal/modules/cjs/loader.js @@ -108,6 +108,7 @@ module.exports = { initializeCJS, Module, wrapSafe, + wrapModuleLoad, kIsMainSymbol, kIsCachedByESMLoader, kRequiredModuleSymbol, @@ -181,6 +182,13 @@ const { isProxy, } = require('internal/util/types'); +const { debuglog, debugWithTimer } = require('internal/util/debuglog'); + +let { startTimer, endTimer } = debugWithTimer('module_timer', (start, end) => { + startTimer = start; + endTimer = end; +}); + const isWindows = process.platform === 'win32'; const relativeResolveCache = { __proto__: null }; @@ -189,6 +197,24 @@ let requireDepth = 0; let isPreloading = false; let statCache = null; +/** + * Internal method to add tracing capabilities for Module._load. + * + * See more {@link Module._load} + */ +function wrapModuleLoad(request, parent, isMain) { + const logLabel = `[${parent?.id || ''}] [${request}]`; + const traceLabel = `require('${request}')`; + + startTimer(logLabel, traceLabel); + + try { + return Module._load(request, parent, isMain); + } finally { + endTimer(logLabel, traceLabel); + } +} + /** * Get a path's properties, using an in-memory cache to minimize lookups. * @param {string} filename Absolute path to the file @@ -354,7 +380,7 @@ function setModuleParent(value) { this[kModuleParent] = value; } -let debug = require('internal/util/debuglog').debuglog('module', (fn) => { +let debug = debuglog('module', (fn) => { debug = fn; }); @@ -971,7 +997,7 @@ function getExportsForCircularRequire(module) { * 3. Otherwise, create a new module for the file and save it to the cache. * Then have it load the file contents before returning its exports object. * @param {string} request Specifier of module to load via `require` - * @param {string} parent Absolute path of the module importing the child + * @param {Module} parent Absolute path of the module importing the child * @param {boolean} isMain Whether the module is the main entry point */ Module._load = function(request, parent, isMain) { @@ -1268,7 +1294,7 @@ Module.prototype.require = function(id) { } requireDepth++; try { - return Module._load(id, this, /* isMain */ false); + return wrapModuleLoad(id, this, /* isMain */ false); } finally { requireDepth--; } diff --git a/lib/internal/modules/esm/translators.js b/lib/internal/modules/esm/translators.js index 89754b6453dbcc..ea6a9dbd8a9440 100644 --- a/lib/internal/modules/esm/translators.js +++ b/lib/internal/modules/esm/translators.js @@ -43,6 +43,7 @@ const { const { kIsCachedByESMLoader, Module: CJSModule, + wrapModuleLoad, kModuleSource, kModuleExport, kModuleExportNames, @@ -198,7 +199,7 @@ function loadCJSModule(module, source, url, filename, isMain) { importAttributes = { __proto__: null, type: 'json' }; break; case '.node': - return CJSModule._load(specifier, module); + return wrapModuleLoad(specifier, module); default: // fall through } @@ -290,7 +291,7 @@ translators.set('commonjs-sync', function requireCommonJS(url, source, isMain) { return createCJSModuleWrap(url, source, isMain, (module, source, url, filename, isMain) => { assert(module === CJSModule._cache[filename]); assert(!isMain); - CJSModule._load(filename, null, isMain); + wrapModuleLoad(filename, null, isMain); }); }); @@ -315,7 +316,7 @@ translators.set('commonjs', async function commonjsStrategy(url, source, // obtained by calling the monkey-patchable CJS loader. const cjsLoader = source == null ? (module, source, url, filename, isMain) => { assert(module === CJSModule._cache[filename]); - CJSModule._load(filename, undefined, isMain); + wrapModuleLoad(filename, undefined, isMain); } : loadCJSModule; try { diff --git a/lib/internal/modules/run_main.js b/lib/internal/modules/run_main.js index 7b26b67bfd4cd6..6c5601ed458b89 100644 --- a/lib/internal/modules/run_main.js +++ b/lib/internal/modules/run_main.js @@ -154,8 +154,8 @@ function executeUserEntryPoint(main = process.argv[1]) { // try to run the entry point via the CommonJS loader; and if that fails under certain conditions, retry as ESM. if (!useESMLoader) { const cjsLoader = require('internal/modules/cjs/loader'); - const { Module } = cjsLoader; - Module._load(main, null, true); + const { wrapModuleLoad } = cjsLoader; + wrapModuleLoad(main, null, true); } else { const mainPath = resolvedMain || main; if (mainURL === undefined) { diff --git a/lib/internal/util/debuglog.js b/lib/internal/util/debuglog.js index 854441216e67e5..e4a283d9faa767 100644 --- a/lib/internal/util/debuglog.js +++ b/lib/internal/util/debuglog.js @@ -1,15 +1,26 @@ 'use strict'; const { + MathFloor, + Number, + NumberPrototypeToFixed, ObjectDefineProperty, RegExp, RegExpPrototypeExec, SafeArrayIterator, + SafeMap, + StringPrototypePadStart, + StringPrototypeSplit, StringPrototypeToLowerCase, StringPrototypeToUpperCase, } = primordials; - +const { + CHAR_LOWERCASE_B: kTraceBegin, + CHAR_LOWERCASE_E: kTraceEnd, + CHAR_LOWERCASE_N: kTraceInstant, +} = require('internal/constants'); const { inspect, format, formatWithOptions } = require('internal/util/inspect'); +const { isTraceCategoryEnabled, trace } = internalBinding('trace_events'); // `debugImpls` and `testEnabled` are deliberately not initialized so any call // to `debuglog()` before `initializeDebugEnv()` is called will throw. @@ -51,7 +62,7 @@ function lazyUtilColors() { return utilColors; } -function debuglogImpl(enabled, set) { +function debuglogImpl(enabled, set, args) { if (debugImpls[set] === undefined) { if (enabled) { const pid = process.pid; @@ -115,7 +126,371 @@ function debuglog(set, cb) { return logger; } +function pad(value) { + return StringPrototypePadStart(`${value}`, 2, '0'); +} + +const kNone = 1 << 0; +const kSkipLog = 1 << 1; +const kSkipTrace = 1 << 2; + +const kSecond = 1000; +const kMinute = 60 * kSecond; +const kHour = 60 * kMinute; + +function formatTime(ms) { + let hours = 0; + let minutes = 0; + let seconds = 0; + + if (ms >= kSecond) { + if (ms >= kMinute) { + if (ms >= kHour) { + hours = MathFloor(ms / kHour); + ms = ms % kHour; + } + minutes = MathFloor(ms / kMinute); + ms = ms % kMinute; + } + seconds = ms / kSecond; + } + + if (hours !== 0 || minutes !== 0) { + ({ 0: seconds, 1: ms } = StringPrototypeSplit( + NumberPrototypeToFixed(seconds, 3), + '.', + )); + const res = hours !== 0 ? `${hours}:${pad(minutes)}` : minutes; + return `${res}:${pad(seconds)}.${ms} (${hours !== 0 ? 'h:m' : ''}m:ss.mmm)`; + } + + if (seconds !== 0) { + return `${NumberPrototypeToFixed(seconds, 3)}s`; + } + + return `${Number(NumberPrototypeToFixed(ms, 3))}ms`; +} + +function safeTraceLabel(label) { + return label.replace(/\\/g, '\\\\'); +} + +/** + * @typedef {(label: string, timeFormatted: string, args?: any[]) => void} LogImpl + */ + +/** + * Returns true if label was found + * @param {string} timesStore + * @param {string} implementation + * @param {LogImpl} logImp + * @param {string} label + * @param {any} args + * @returns {void} + */ +function timeLogImpl(timesStore, implementation, logImp, label, args) { + const time = timesStore.get(label); + if (time === undefined) { + process.emitWarning(`No such label '${label}' for ${implementation}`); + return; + } + + const duration = process.hrtime(time); + const ms = duration[0] * 1000 + duration[1] / 1e6; + + const formatted = formatTime(ms); + + if (args === undefined) { + logImp(label, formatted); + } else { + logImp(label, formatted, args); + } +} + +/** + * @param {SafeMap} timesStore + * @param {string} traceCategory + * @param {string} implementation + * @param {number} timerFlags + * @param {string} logLabel + * @param {string} traceLabel + * @returns {void} + */ +function time(timesStore, traceCategory, implementation, timerFlags, logLabel = 'default', traceLabel = undefined) { + // Coerces everything other than Symbol to a string + logLabel = `${logLabel}`; + + if (traceLabel !== undefined) { + traceLabel = `${traceLabel}`; + } else { + traceLabel = logLabel; + } + + if (timesStore.has(logLabel)) { + process.emitWarning(`Label '${logLabel}' already exists for ${implementation}`); + return; + } + + if ((timerFlags & kSkipTrace) === 0) { + traceLabel = safeTraceLabel(traceLabel); + trace(kTraceBegin, traceCategory, traceLabel, 0); + } + + timesStore.set(logLabel, process.hrtime()); +} + +/** + * @param {SafeMap} timesStore + * @param {string} traceCategory + * @param {string} implementation + * @param {number} timerFlags + * @param {LogImpl} logImpl + * @param {string} logLabel + * @param {string} traceLabel + * @returns {void} + */ +function timeEnd( + timesStore, + traceCategory, + implementation, + timerFlags, + logImpl, + logLabel = 'default', + traceLabel = undefined, +) { + // Coerces everything other than Symbol to a string + logLabel = `${logLabel}`; + + if (traceLabel !== undefined) { + traceLabel = `${traceLabel}`; + } else { + traceLabel = logLabel; + } + + if ((timerFlags & kSkipLog) === 0) { + timeLogImpl(timesStore, implementation, logImpl, logLabel); + } + + if ((timerFlags & kSkipTrace) === 0) { + traceLabel = safeTraceLabel(traceLabel); + trace(kTraceEnd, traceCategory, traceLabel, 0); + } + + timesStore.delete(logLabel); +} + +/** + * @param {SafeMap} timesStore + * @param {string} traceCategory + * @param {string} implementation + * @param {number} timerFlags + * @param {LogImpl} logImpl + * @param {string} logLabel + * @param {string} traceLabel + * @param {any[]} args + * @returns {void} + */ +function timeLog( + timesStore, + traceCategory, + implementation, + timerFlags, + logImpl, + logLabel = 'default', + traceLabel = undefined, + args, +) { + // Coerces everything other than Symbol to a string + logLabel = `${logLabel}`; + + if (traceLabel !== undefined) { + traceLabel = `${traceLabel}`; + } else { + traceLabel = logLabel; + } + + if ((timerFlags & kSkipLog) === 0) { + timeLogImpl(timesStore, implementation, logImpl, logLabel, args); + } + + if ((timerFlags & kSkipTrace) === 0) { + traceLabel = safeTraceLabel(traceLabel); + trace(kTraceInstant, traceCategory, traceLabel, 0); + } +} + +/** + * @type {Record} + */ +let tracesStores; + +/** + * @typedef {(logLabel: string, traceLabel?: string) => void} TimerStart + */ + +/** + * @typedef {(logLabel: string, traceLabel?: string) => void} TimerEnd + */ + +/** + * @typedef {(logLabel: string, traceLabel?: string, args?: any[]) => void} TimerLog + */ + +/** + * Debuglog with time fns and support for trace + * @param {string} set + * @param {(startTimer: TimerStart, endTimer: TimerEnd, logTimer: TimerLog) => void} cb + * @returns {{startTimer: TimerStart, endTimer: TimerEnd, logTimer: TimerLog}} + */ +function debugWithTimer(set, cb) { + set = StringPrototypeToUpperCase(set); + + if (tracesStores === undefined) { + tracesStores = { __proto__: null }; + } + + /** + * @type {LogImpl} + */ + function logImpl(label, timeFormatted, args) { + const pid = process.pid; + const colors = { colors: lazyUtilColors().shouldColorize(process.stderr) }; + const coloredPID = inspect(pid, colors); + + if (args === undefined) + process.stderr.write(format('%s %s %s: %s\n', set, coloredPID, label, timeFormatted)); + else + process.stderr.write( + format( + '%s %s %s: %s\n', + set, + coloredPID, + label, + timeFormatted, + ...new SafeArrayIterator(args), + ), + ); + } + + const kTraceCategory = `node,node.${StringPrototypeToLowerCase(set)}`; + let debugLogCategoryEnabled = false; + let traceCategoryEnabled = false; + let timerFlags = kNone; + + /** + * @type {TimerStart} + */ + function internalStartTimer(logLabel, traceLabel) { + time( + tracesStores[set], + kTraceCategory, + 'debuglog.time', + timerFlags, + logLabel, + traceLabel, + ); + } + + /** + * @type {TimerEnd} + */ + function internalEndTimer(logLabel, traceLabel) { + timeEnd( + tracesStores[set], + kTraceCategory, + 'debuglog.timeEnd', + timerFlags, + logImpl, + logLabel, + traceLabel, + ); + } + + /** + * @type {TimerLog} + */ + function internalLogTimer(logLabel, traceLabel, args) { + timeLog( + tracesStores[set], + kTraceCategory, + 'debuglog.timeLog', + timerFlags, + logImpl, + logLabel, + traceLabel, + args, + ); + } + + function init() { + if (tracesStores[set] === undefined) { + tracesStores[set] = new SafeMap(); + } + emitWarningIfNeeded(set); + debugLogCategoryEnabled = testEnabled(set); + traceCategoryEnabled = isTraceCategoryEnabled(kTraceCategory); + + if (!debugLogCategoryEnabled) { + timerFlags |= kSkipLog; + } + + if (!traceCategoryEnabled) { + timerFlags |= kSkipTrace; + } + + // TODO(H4ad): support traceCategory being enabled dynamically + if (debugLogCategoryEnabled || traceCategoryEnabled) + cb(internalStartTimer, internalEndTimer, internalLogTimer); + else + cb(noop, noop, noop); + } + + /** + * @type {TimerStart} + */ + const startTimer = (logLabel, traceLabel) => { + init(); + + if (debugLogCategoryEnabled || traceCategoryEnabled) + internalStartTimer(logLabel, traceLabel); + }; + + /** + * @type {TimerEnd} + */ + const endTimer = (logLabel, traceLabel) => { + init(); + + if (debugLogCategoryEnabled || traceCategoryEnabled) + internalEndTimer(logLabel, traceLabel); + }; + + /** + * @type {TimerLog} + */ + const logTimer = (logLabel, traceLabel, args) => { + init(); + + if (debugLogCategoryEnabled || traceCategoryEnabled) + internalLogTimer(logLabel, traceLabel, args); + }; + + return { + startTimer, + endTimer, + logTimer, + }; +} + module.exports = { + kNone, + kSkipLog, + kSkipTrace, + formatTime, + time, + timeEnd, + timeLog, debuglog, + debugWithTimer, initializeDebugEnv, }; diff --git a/test/fixtures/console/console.snapshot b/test/fixtures/console/console.snapshot index 9aabbe5c5f275a..4f1cb254811b6d 100644 --- a/test/fixtures/console/console.snapshot +++ b/test/fixtures/console/console.snapshot @@ -6,3 +6,4 @@ Trace: foo at * at * at * + at * diff --git a/test/fixtures/errors/force_colors.snapshot b/test/fixtures/errors/force_colors.snapshot index 3624d9f0804545..21410d492db861 100644 --- a/test/fixtures/errors/force_colors.snapshot +++ b/test/fixtures/errors/force_colors.snapshot @@ -10,5 +10,6 @@ Error: Should include grayed stack trace  at *  at *  at * + at * Node.js * diff --git a/test/fixtures/errors/promise_always_throw_unhandled.snapshot b/test/fixtures/errors/promise_always_throw_unhandled.snapshot index c97540f5499f87..cf42c69efdc372 100644 --- a/test/fixtures/errors/promise_always_throw_unhandled.snapshot +++ b/test/fixtures/errors/promise_always_throw_unhandled.snapshot @@ -12,5 +12,6 @@ Error: One at * at * at * + at * Node.js * diff --git a/test/fixtures/errors/promise_unhandled_warn_with_error.snapshot b/test/fixtures/errors/promise_unhandled_warn_with_error.snapshot index d7f1aa2f72007f..48e5da7c9aded5 100644 --- a/test/fixtures/errors/promise_unhandled_warn_with_error.snapshot +++ b/test/fixtures/errors/promise_unhandled_warn_with_error.snapshot @@ -6,5 +6,6 @@ at * at * at * + at * (Use `node --trace-warnings ...` to show where the warning was created) (node:*) UnhandledPromiseRejectionWarning: Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). To terminate the node process on unhandled promise rejection, use the CLI flag `--unhandled-rejections=strict` (see https:*nodejs.org*api*cli.html#cli_unhandled_rejections_mode). (rejection id: 1) diff --git a/test/fixtures/errors/unhandled_promise_trace_warnings.snapshot b/test/fixtures/errors/unhandled_promise_trace_warnings.snapshot index bf50fffd60c5ee..94c709b17788c4 100644 --- a/test/fixtures/errors/unhandled_promise_trace_warnings.snapshot +++ b/test/fixtures/errors/unhandled_promise_trace_warnings.snapshot @@ -10,6 +10,7 @@ at * at * at * + at * (node:*) Error: This was rejected at * at * @@ -18,6 +19,7 @@ at * at * at * + at * (node:*) PromiseRejectionHandledWarning: Promise rejection was handled asynchronously (rejection id: 1) at * at * diff --git a/test/fixtures/test-runner/output/abort.snapshot b/test/fixtures/test-runner/output/abort.snapshot index 1b758a2314c486..be0936bd763fbb 100644 --- a/test/fixtures/test-runner/output/abort.snapshot +++ b/test/fixtures/test-runner/output/abort.snapshot @@ -135,6 +135,7 @@ not ok 2 - promise abort signal * * * + * ... # Subtest: callback timeout signal # Subtest: ok 1 @@ -272,6 +273,7 @@ not ok 4 - callback abort signal * * * + * ... 1..4 # tests 22 diff --git a/test/fixtures/test-runner/output/abort_suite.snapshot b/test/fixtures/test-runner/output/abort_suite.snapshot index 30d48d236ff4a5..b3eb5d9126db26 100644 --- a/test/fixtures/test-runner/output/abort_suite.snapshot +++ b/test/fixtures/test-runner/output/abort_suite.snapshot @@ -137,6 +137,7 @@ not ok 2 - describe abort signal * * * + * ... 1..2 # tests 9 diff --git a/test/message/assert_throws_stack.out b/test/message/assert_throws_stack.out index 06eaa906442440..652a60532c68d5 100644 --- a/test/message/assert_throws_stack.out +++ b/test/message/assert_throws_stack.out @@ -15,6 +15,7 @@ AssertionError [ERR_ASSERTION]: Expected values to be strictly deep-equal: at * at * at * + at * at * { generatedMessage: true, code: 'ERR_ASSERTION', diff --git a/test/message/internal_assert.out b/test/message/internal_assert.out index 197b863bf6ae69..e4f67f650f938e 100644 --- a/test/message/internal_assert.out +++ b/test/message/internal_assert.out @@ -12,6 +12,7 @@ Please open an issue with this stack trace at https://github.com/nodejs/node/iss at * at * at * + at * at * { code: 'ERR_INTERNAL_ASSERTION' } diff --git a/test/message/internal_assert_fail.out b/test/message/internal_assert_fail.out index e6895691cda9c1..6a5916401bb7f6 100644 --- a/test/message/internal_assert_fail.out +++ b/test/message/internal_assert_fail.out @@ -13,6 +13,7 @@ Please open an issue with this stack trace at https://github.com/nodejs/node/iss at * at * at * + at * at * { code: 'ERR_INTERNAL_ASSERTION' } diff --git a/test/message/util-inspect-error-cause.out b/test/message/util-inspect-error-cause.out index 73f0a673d76e1f..344ace1bc94074 100644 --- a/test/message/util-inspect-error-cause.out +++ b/test/message/util-inspect-error-cause.out @@ -5,6 +5,7 @@ Error: Number error cause at * at * at * + at * at * { [cause]: 42 } @@ -15,6 +16,7 @@ Error: Object cause at * at * at * + at * at * { [cause]: { message: 'Unique', @@ -30,6 +32,7 @@ Error: undefined cause at * at * at * + at * at * { [cause]: undefined } @@ -40,6 +43,7 @@ Error: cause that throws at * at * at * + at * at * { [cause]: [Getter] } @@ -49,7 +53,7 @@ RangeError: New Stack Frames [cause]: FoobarError: Individual message at * *[90m at *[39m - *[90m ... 4 lines matching cause stack trace ...*[39m + *[90m ... 5 lines matching cause stack trace ...*[39m *[90m at *[39m { status: *[32m'Feeling good'*[39m, extraProperties: *[32m'Yes!'*[39m, @@ -61,17 +65,18 @@ RangeError: New Stack Frames *[90m at *[39m *[90m at *[39m *[90m at *[39m + *[90m at *[39m } } Error: Stack causes at * *[90m at *[39m -*[90m ... 4 lines matching cause stack trace ...*[39m +*[90m ... 5 lines matching cause stack trace ...*[39m *[90m at *[39m { [cause]: FoobarError: Individual message at * *[90m at *[39m - *[90m ... 4 lines matching cause stack trace ...*[39m + *[90m ... 5 lines matching cause stack trace ...*[39m *[90m at *[39m { status: *[32m'Feeling good'*[39m, extraProperties: *[32m'Yes!'*[39m, @@ -83,6 +88,7 @@ Error: Stack causes *[90m at *[39m *[90m at *[39m *[90m at *[39m + *[90m at *[39m } } RangeError: New Stack Frames @@ -91,12 +97,12 @@ RangeError: New Stack Frames [cause]: Error: Stack causes at * *[90m at *[39m - *[90m ... 4 lines matching cause stack trace ...*[39m + *[90m ... 5 lines matching cause stack trace ...*[39m *[90m at *[39m { [cause]: FoobarError: Individual message at * *[90m at *[39m - *[90m ... 4 lines matching cause stack trace ...*[39m + *[90m ... 5 lines matching cause stack trace ...*[39m *[90m at *[39m { status: *[32m'Feeling good'*[39m, extraProperties: *[32m'Yes!'*[39m, @@ -108,6 +114,7 @@ RangeError: New Stack Frames *[90m at *[39m *[90m at *[39m *[90m at *[39m + *[90m at *[39m } } } @@ -117,7 +124,7 @@ RangeError: New Stack Frames [cause]: FoobarError: Individual message at * at * - ... 4 lines matching cause stack trace ... + ... 5 lines matching cause stack trace ... at * { status: 'Feeling good', extraProperties: 'Yes!', @@ -129,17 +136,18 @@ RangeError: New Stack Frames at * at * at * + at * } } Error: Stack causes at * at * - ... 4 lines matching cause stack trace ... + ... 5 lines matching cause stack trace ... at * { [cause]: FoobarError: Individual message at * at * - ... 4 lines matching cause stack trace ... + ... 5 lines matching cause stack trace ... at * status: 'Feeling good', extraProperties: 'Yes!', @@ -151,6 +159,7 @@ Error: Stack causes at * at * at * + at * } } RangeError: New Stack Frames @@ -159,12 +168,12 @@ RangeError: New Stack Frames [cause]: Error: Stack causes at * at * - ... 4 lines matching cause stack trace ... + ... 5 lines matching cause stack trace ... at * { [cause]: FoobarError: Individual message at * at * - ... 4 lines matching cause stack trace ... + ... 5 lines matching cause stack trace ... at * { status: 'Feeling good', extraProperties: 'Yes!', @@ -176,6 +185,7 @@ RangeError: New Stack Frames at * at * at * + at * } } } diff --git a/test/message/util_inspect_error.out b/test/message/util_inspect_error.out index 644ccd58831ef7..31b65eb2e2bf3c 100644 --- a/test/message/util_inspect_error.out +++ b/test/message/util_inspect_error.out @@ -8,6 +8,7 @@ at * at * at * + at * nested: { err: Error: foo @@ -19,6 +20,7 @@ at * at * at * + at * { err: Error: foo bar @@ -29,6 +31,7 @@ at * at * at * + at * nested: { err: Error: foo bar @@ -39,6 +42,7 @@ at * at * at * + at * } } { Error: foo @@ -50,4 +54,5 @@ bar at * at * at * + at * foo: 'bar' } diff --git a/test/parallel/test-console-formatTime.js b/test/parallel/test-console-formatTime.js index 0420013c50e77c..6ce0b761c656a0 100644 --- a/test/parallel/test-console-formatTime.js +++ b/test/parallel/test-console-formatTime.js @@ -1,7 +1,7 @@ 'use strict'; // Flags: --expose-internals require('../common'); -const { formatTime } = require('internal/console/constructor'); +const { formatTime } = require('internal/util/debuglog'); const assert = require('assert'); assert.strictEqual(formatTime(100.0096), '100.01ms'); diff --git a/test/parallel/test-module-print-timing.mjs b/test/parallel/test-module-print-timing.mjs new file mode 100644 index 00000000000000..0cb7189d3114af --- /dev/null +++ b/test/parallel/test-module-print-timing.mjs @@ -0,0 +1,95 @@ +import '../common/index.mjs'; +import assert from 'node:assert'; +import { readFile } from 'node:fs/promises'; +import { it } from 'node:test'; +import tmpdir from '../common/tmpdir.js'; +import { spawnSyncAndAssert } from '../common/child_process.js'; + +tmpdir.refresh(); + +it('should print the timing information for cjs', () => { + const result = spawnSyncAndAssert(process.execPath, ['--eval', 'require("url");'], { + cwd: tmpdir.path, + env: { + ...process.env, + NODE_DEBUG: 'module_timer', + }, + }, { + stdout: '', + stderr: (result) => result.includes('MODULE_TIMER'), + }); + + const firstLine = result.stderr.split('\n').find((line) => line.includes('[url]')); + + assert.notStrictEqual(firstLine, undefined); + assert.ok(firstLine.includes('MODULE_TIMER'), `Not found MODULE_TIMER on ${firstLine}`); + assert.ok(firstLine.includes('[url]:'), `Not found [url]: on ${firstLine}`); + assert.ok(firstLine.endsWith('ms'), `Not found ms on ${firstLine}`); +}); + +it('should write tracing information for cjs', async () => { + const outputFile = tmpdir.resolve('output-trace.log'); + + spawnSyncAndAssert(process.execPath, [ + '--trace-event-categories', + 'node.module_timer', + '--trace-event-file-pattern', + outputFile, + '--eval', + 'require("url");', + ], { + cwd: tmpdir.path, + }, { + stdout: '', + stderr: '', + }); + + const expectedMimeTypes = ['b', 'e']; + const outputFileContent = await readFile(outputFile, 'utf-8'); + const outputFileJson = JSON.parse(outputFileContent).traceEvents; + const urlTraces = outputFileJson.filter((trace) => trace.name === "require('url')"); + + assert.strictEqual(urlTraces.length, 2); + + for (const trace of urlTraces) { + assert.strictEqual(trace.ph, expectedMimeTypes.shift()); + } +}); + +it('should write tracing & print logs for cjs', async () => { + const outputFile = tmpdir.resolve('output-trace-and-log.log'); + + const result = spawnSyncAndAssert(process.execPath, [ + '--trace-event-categories', + 'node.module_timer', + '--trace-event-file-pattern', + outputFile, + '--eval', + 'require("url");', + ], { + cwd: tmpdir.path, + env: { + ...process.env, + NODE_DEBUG: 'module_timer', + }, + }, { + stdout: '', + stderr: (result) => result.includes('MODULE_TIMER'), + }); + + const firstLine = result.stderr.split('\n').find((line) => line.includes('[url]')); + + assert.notStrictEqual(firstLine, undefined); + assert.ok(firstLine.includes('MODULE_TIMER'), `Not found MODULE_TIMER on ${firstLine}`); + assert.ok(firstLine.includes('[url]:'), `Not found [url]: on ${firstLine}`); + assert.ok(firstLine.endsWith('ms'), `Not found ms on ${firstLine}`); + + const expectedMimeTypes = ['b', 'e']; + const outputFileContent = await readFile(outputFile, 'utf-8'); + const outputFileJson = JSON.parse(outputFileContent).traceEvents; + const urlTraces = outputFileJson.filter((trace) => trace.name === "require('url')"); + + for (const trace of urlTraces) { + assert.strictEqual(trace.ph, expectedMimeTypes.shift()); + } +}); diff --git a/test/parallel/test-repl.js b/test/parallel/test-repl.js index 0d467e2b35dbdc..7f757837f7bdae 100644 --- a/test/parallel/test-repl.js +++ b/test/parallel/test-repl.js @@ -581,6 +581,7 @@ const errorTests = [ /^ {4}at .*/, /^ {4}at .*/, /^ {4}at .*/, + /^ {4}at .*/, " code: 'MODULE_NOT_FOUND',", " requireStack: [ '' ]", '}', diff --git a/test/parallel/test-trace-events-console.js b/test/parallel/test-trace-events-console.js index 4c9fa35cbafd6f..79ac37fc7d6570 100644 --- a/test/parallel/test-trace-events-console.js +++ b/test/parallel/test-trace-events-console.js @@ -10,6 +10,7 @@ const tmpdir = require('../common/tmpdir'); const names = [ 'time::foo', + 'time::\\winvalid_char', 'count::bar', ]; const expectedCounts = [ 1, 2, 0 ]; @@ -21,8 +22,10 @@ if (process.argv[2] === 'child') { console.count('bar'); console.count('bar'); console.countReset('bar'); + console.time('\\winvalid_char'); console.time('foo'); setImmediate(() => { + console.timeEnd('\\winvalid_char'); console.timeLog('foo'); setImmediate(() => { console.timeEnd('foo'); diff --git a/test/pseudo-tty/console_colors.out b/test/pseudo-tty/console_colors.out index 006eb9edfe617d..80b147197431fa 100644 --- a/test/pseudo-tty/console_colors.out +++ b/test/pseudo-tty/console_colors.out @@ -12,6 +12,7 @@ foobar [90m at *[39m [90m at *[39m [90m at *[39m +[90m at *[39m Error: Should not ever get here. at Object. [90m(*node_modules*[4m*node_modules*[24m*bar.js:*:*[90m)[39m @@ -21,8 +22,8 @@ Error: Should not ever get here. [90m at *[39m [90m at *[39m [90m at *[39m - at Object. [90m(*console_colors.js:*:*[90m)[39m [90m at *[39m + at Object. [90m(*console_colors.js:*:*[90m)[39m [90m at *[39m Error diff --git a/test/pseudo-tty/test-fatal-error.out b/test/pseudo-tty/test-fatal-error.out index 3fe1eed39a021e..7040eb812ce6a8 100644 --- a/test/pseudo-tty/test-fatal-error.out +++ b/test/pseudo-tty/test-fatal-error.out @@ -8,6 +8,7 @@ TypeError: foobar [90m at *(node:internal*loader:*:*)[39m [90m at *(node:internal*loader:*:*)[39m [90m at *(node:internal*loader:*:*)[39m +[90m at *(node:internal*loader:*:*)[39m [90m at *[39m [90m at *[39m { bla: [33mtrue[39m diff --git a/test/pseudo-tty/test-trace-sigint.out b/test/pseudo-tty/test-trace-sigint.out index 956cbafccc2d19..ae6063b74242e4 100644 --- a/test/pseudo-tty/test-trace-sigint.out +++ b/test/pseudo-tty/test-trace-sigint.out @@ -7,3 +7,4 @@ KEYBOARD_INTERRUPT: Script execution was interrupted by `SIGINT` at * at * at * + at *