lib: explicitly initialize debuglog during bootstrap

This patch splits the implementation of util.debuglog into a separate file and explicitly initialize it during pre-execution since the initialization depends on environment variables. Also delays the call to `debuglog` in modules that are loaded during bootstrap to make sure we only access the environment variable during pre-execution.
nodejs · joyeecheung · Mar 6, 2019 · Mar 6, 2019 · Mar 6, 2019 · Mar 6, 2019
commit 83f1c582fcf3c043e0cffd4f043aa960daf130d5
diff --git a/lib/_stream_readable.js b/lib/_stream_readable.js
@@ -27,8 +27,15 @@ Readable.ReadableState = ReadableState;
 const EE = require('events');
 const Stream = require('stream');
 const { Buffer } = require('buffer');
-const util = require('util');
-const debug = util.debuglog('stream');
+
+let debuglog;
+function debug(...args) {
+  if (!debuglog) {
+    debuglog = require('internal/util/debuglog').debuglog('stream');
+  }
+  debuglog(...args);
+}
+
 const BufferList = require('internal/streams/buffer_list');
 const destroyImpl = require('internal/streams/destroy');
 const { getHighWaterMark } = require('internal/streams/state');

diff --git a/lib/internal/bootstrap/pre_execution.js b/lib/internal/bootstrap/pre_execution.js
@@ -8,6 +8,8 @@ let traceEventsAsyncHook;
 function prepareMainThreadExecution() {
   setupTraceCategoryState();
 
+  setupDebugEnv();
+
   // Only main thread receives signals.
   setupSignalHandlers();
 
@@ -52,6 +54,10 @@ function initializeReport() {
   });
 }
 
+function setupDebugEnv() {
+  require('internal/util/debuglog').initializeDebugEnv(process.env.NODE_DEBUG);
+}
+
 function setupSignalHandlers() {
   const {
     createSignalHandlers
@@ -231,6 +237,7 @@ function loadPreloadModules() {
 }
 
 module.exports = {
+  setupDebugEnv,
   prepareMainThreadExecution,
   initializeDeprecations,
   initializeESMLoader,

diff --git a/lib/internal/main/worker_thread.js b/lib/internal/main/worker_thread.js
@@ -4,6 +4,7 @@
 // message port.
 
 const {
+  setupDebugEnv,
   initializeDeprecations,
   initializeESMLoader,
   initializeFrozenIntrinsics,
@@ -37,6 +38,9 @@ const {
 } = require('internal/process/execution');
 
 const publicWorker = require('worker_threads');
+
+setupDebugEnv();
+
 const debug = require('util').debuglog('worker');
 
 debug(`[${threadId}] is setting up worker child environment`);

diff --git a/lib/internal/modules/cjs/loader.js b/lib/internal/modules/cjs/loader.js
@@ -174,7 +174,13 @@ Object.defineProperty(Module, 'wrapper', {
   }
 });
 
-const debug = util.debuglog('module');
+let debuglog;
+function debug(...args) {
+  if (!debuglog) {
+    debuglog = require('internal/util/debuglog').debuglog('module');
+  }
+  debuglog(...args);
+}
 
 Module._debug = util.deprecate(debug, 'Module._debug is deprecated.',
                                'DEP0077');

diff --git a/lib/internal/util/debuglog.js b/lib/internal/util/debuglog.js
@@ -0,0 +1,54 @@
+'use strict';
+
+const { format } = require('internal/util/inspect');
+
+// `debugs` is deliberately initialized to undefined so any call to
+// debuglog() before initializeDebugEnv() is called will throw.
+let debugs;
+
+let debugEnvRegex = /^$/;
+
+// `debugEnv` is initial value of process.env.NODE_DEBUG
+function initializeDebugEnv(debugEnv) {
+  debugs = {};
+  if (debugEnv) {
+    debugEnv = debugEnv.replace(/[|\\{}()[\]^$+?.]/g, '\\$&')
+      .replace(/\*/g, '.*')
+      .replace(/,/g, '$|^')
+      .toUpperCase();
+    debugEnvRegex = new RegExp(`^${debugEnv}$`, 'i');
+  }
+}
+
+// Emits warning when user sets
+// NODE_DEBUG=http or NODE_DEBUG=http2.
+function emitWarningIfNeeded(set) {
+  if ('HTTP' === set || 'HTTP2' === set) {
+    process.emitWarning('Setting the NODE_DEBUG environment variable ' +
+      'to \'' + set.toLowerCase() + '\' can expose sensitive ' +
+      'data (such as passwords, tokens and authentication headers) ' +
+      'in the resulting log.');
+  }
+}
+
+function debuglog(set) {
+  set = set.toUpperCase();
+  if (!debugs[set]) {
+    if (debugEnvRegex.test(set)) {
+      const pid = process.pid;
+      emitWarningIfNeeded(set);
+      debugs[set] = function debug(...args) {
+        const msg = format(...args);
+        console.error('%s %d: %s', set, pid, msg);
+      };
+    } else {
+      debugs[set] = function debug() {};
+    }
+  }
+  return debugs[set];
+}
+
+module.exports = {
+  debuglog,
+  initializeDebugEnv
+};
diff --git a/lib/internal/worker.js b/lib/internal/worker.js
@@ -3,7 +3,7 @@
 const EventEmitter = require('events');
 const assert = require('internal/assert');
 const path = require('path');
-const util = require('util');
+
 const {
   ERR_WORKER_PATH,
   ERR_WORKER_UNSERIALIZABLE_ERROR,
@@ -45,7 +45,13 @@ const kOnCouldNotSerializeErr = Symbol('kOnCouldNotSerializeErr');
 const kOnErrorMessage = Symbol('kOnErrorMessage');
 const kParentSideStdio = Symbol('kParentSideStdio');
 
-const debug = util.debuglog('worker');
+let debuglog;
+function debug(...args) {
+  if (!debuglog) {
+    debuglog = require('internal/util/debuglog').debuglog('worker');
+  }
+  debuglog(...args);
+}
 
 class Worker extends EventEmitter {
   constructor(filename, options = {}) {

diff --git a/lib/internal/worker/io.js b/lib/internal/worker/io.js
@@ -15,7 +15,14 @@ const { threadId } = internalBinding('worker');
 const { Readable, Writable } = require('stream');
 const EventEmitter = require('events');
 const util = require('util');
-const debug = util.debuglog('worker');
+
+let debuglog;
+function debug(...args) {
+  if (!debuglog) {
+    debuglog = require('internal/util/debuglog').debuglog('worker');
+  }
+  debuglog(...args);
+}
 
 const kIncrementsPortRef = Symbol('kIncrementsPortRef');
 const kName = Symbol('kName');

diff --git a/lib/timers.js b/lib/timers.js
@@ -42,7 +42,15 @@ const {
 const internalUtil = require('internal/util');
 const util = require('util');
 const { ERR_INVALID_CALLBACK } = require('internal/errors').codes;
-const debug = util.debuglog('timer');
+
+let debuglog;
+function debug(...args) {
+  if (!debuglog) {
+    debuglog = require('internal/util/debuglog').debuglog('timer');
+  }
+  debuglog(...args);
+}
+
 const {
   destroyHooksExist,
   // The needed emit*() functions.

diff --git a/lib/util.js b/lib/util.js
@@ -27,6 +27,7 @@ const {
   formatWithOptions,
   inspect
 } = require('internal/util/inspect');
+const { debuglog } = require('internal/util/debuglog');
 const {
   ERR_FALSY_VALUE_REJECTION,
   ERR_INVALID_ARG_TYPE,
@@ -52,45 +53,6 @@ const objectToString = uncurryThis(Object.prototype.toString);
 
 let internalDeepEqual;
 
-const debugs = {};
-let debugEnvRegex = /^$/;
-if (process.env.NODE_DEBUG) {
-  let debugEnv = process.env.NODE_DEBUG;
-  debugEnv = debugEnv.replace(/[|\\{}()[\]^$+?.]/g, '\\$&')
-      .replace(/\*/g, '.*')
-      .replace(/,/g, '$|^')
-      .toUpperCase();
-  debugEnvRegex = new RegExp(`^${debugEnv}$`, 'i');
-}
-
-// Emits warning when user sets
-// NODE_DEBUG=http or NODE_DEBUG=http2.
-function emitWarningIfNeeded(set) {
-  if ('HTTP' === set || 'HTTP2' === set) {
-    process.emitWarning('Setting the NODE_DEBUG environment variable ' +
-      'to \'' + set.toLowerCase() + '\' can expose sensitive ' +
-      'data (such as passwords, tokens and authentication headers) ' +
-      'in the resulting log.');
-  }
-}
-
-function debuglog(set) {
-  set = set.toUpperCase();
-  if (!debugs[set]) {
-    if (debugEnvRegex.test(set)) {
-      const pid = process.pid;
-      emitWarningIfNeeded(set);
-      debugs[set] = function debug() {
-        const msg = exports.format.apply(exports, arguments);
-        console.error('%s %d: %s', set, pid, msg);
-      };
-    } else {
-      debugs[set] = function debug() {};
-    }
-  }
-  return debugs[set];
-}
-
 function isBoolean(arg) {
   return typeof arg === 'boolean';
 }

diff --git a/node.gyp b/node.gyp
@@ -185,6 +185,7 @@
       'lib/internal/url.js',
       'lib/internal/util.js',
       'lib/internal/util/comparisons.js',
+      'lib/internal/util/debuglog.js',
       'lib/internal/util/inspect.js',
       'lib/internal/util/inspector.js',
       'lib/internal/util/types.js',