node/lib/internal/util/debuglog.js

'use strict';

const {
  MathFloor,
  Number,
  NumberPrototypeToFixed,
  ObjectDefineProperty,
  RegExp,
  RegExpPrototypeExec,
  SafeArrayIterator,
  SafeMap,
  StringPrototypePadStart,
  StringPrototypeSplit,
  StringPrototypeToLowerCase,
  StringPrototypeToUpperCase,
} = primordials;
const { inspect, format, formatWithOptions } = require('internal/util/inspect');
const {
  categoryEnabledChecker,
  trace,
  nodeTraceEventCategory,
  kAsyncBegin,
  kAsyncEnd,
  kTraceInstant,
} = require('internal/trace_events');

// `debugImpls` and `testEnabled` are deliberately not initialized so any call
// to `debuglog()` before `initializeDebugEnv()` is called will throw.
let debugImpls;
let testEnabled;


// `debugEnv` is initial value of process.env.NODE_DEBUG
function initializeDebugEnv(debugEnv) {
  debugImpls = { __proto__: null };
  if (debugEnv) {
    // This is run before any user code, it's OK not to use primordials.
    debugEnv = debugEnv.replace(/[|\\{}()[\]^$+?.]/g, '\\$&')
      .replaceAll('*', '.*')
      .replaceAll(',', '$|^');
    const debugEnvRegex = new RegExp(`^${debugEnv}$`, 'i');
    testEnabled = (str) => RegExpPrototypeExec(debugEnvRegex, str) !== null;
  } else {
    testEnabled = () => false;
  }
}

// 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 \'' + StringPrototypeToLowerCase(set) + '\' can expose sensitive ' +
      'data (such as passwords, tokens and authentication headers) ' +
      'in the resulting log.');
  }
}

const noop = () => {};

let utilColors;
function lazyUtilColors() {
  utilColors ??= require('internal/util/colors');
  return utilColors;
}

function debuglogImpl(enabled, set) {
  if (debugImpls[set] === undefined) {
    if (enabled) {
      const pid = process.pid;
      emitWarningIfNeeded(set);
      debugImpls[set] = function debug(...args) {
        const colors = lazyUtilColors().shouldColorize(process.stderr);
        const msg = formatWithOptions({ colors }, ...args);
        const coloredPID = inspect(pid, { colors });
        process.stderr.write(format('%s %s: %s\n', set, coloredPID, msg));
      };
    } else {
      debugImpls[set] = noop;
    }
  }
  return debugImpls[set];
}

// debuglogImpl depends on process.pid and process.env.NODE_DEBUG,
// so it needs to be called lazily in top scopes of internal modules
// that may be loaded before these run time states are allowed to
// be accessed.
function debuglog(set, cb) {
  function init() {
    set = StringPrototypeToUpperCase(set);
    enabled = testEnabled(set);
  }
  let debug = (...args) => {
    init();
    // Only invokes debuglogImpl() when the debug function is
    // called for the first time.
    debug = debuglogImpl(enabled, set);
    if (typeof cb === 'function') {
      ObjectDefineProperty(debug, 'enabled', {
        __proto__: null,
        get() {
          return enabled;
        },
        configurable: true,
        enumerable: true,
      });
      cb(debug);
    }
    switch (args.length) {
      case 1: return debug(args[0]);
      case 2: return debug(args[0], args[1]);
      default: return debug(...new SafeArrayIterator(args));
    }
  };
  let enabled;
  let test = () => {
    init();
    test = () => enabled;
    return enabled;
  };
  const logger = (...args) => {
    // Improve performance when debug is disabled, avoid calling `new SafeArrayIterator(args)`
    if (enabled === false) return;
    switch (args.length) {
      case 1: return debug(args[0]);
      case 2: return debug(args[0], args[1]);
      default: return debug(...new SafeArrayIterator(args));
    }
  };
  ObjectDefineProperty(logger, 'enabled', {
    __proto__: null,
    get() {
      return test();
    },
    configurable: true,
    enumerable: true,
  });
  return logger;
}

function pad(value) {
  return StringPrototypePadStart(`${value}`, 2, '0');
}

const kNone = 1 << 0;
const kSkipLog = 1 << 1;
const kSkipTrace = 1 << 2;
const kShouldSkipAll = kSkipLog | kSkipTrace;

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),
      '.',
      2,
    ));
    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.replaceAll('\\', '\\\\').replaceAll('"', '\\"');
}

/**
 * @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(kAsyncBegin, 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(kAsyncEnd, 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<string, SafeMap>}
 */
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 traceCategory = nodeTraceEventCategory(`node.${StringPrototypeToLowerCase(set)}`);
  let traceCategoryEnabled;
  let debugLogCategoryEnabled = false;
  let timerFlags = kNone;

  function ensureTimerFlagsAreUpdated() {
    timerFlags &= ~kSkipTrace;

    if (!traceCategoryEnabled()) {
      timerFlags |= kSkipTrace;
    }
  }

  /**
   * @type {TimerStart}
   */
  function internalStartTimer(logLabel, traceLabel) {
    ensureTimerFlagsAreUpdated();

    if ((timerFlags & kShouldSkipAll) === kShouldSkipAll) {
      return;
    }

    time(
      tracesStores[set],
      traceCategory,
      'debuglog.time',
      timerFlags,
      logLabel,
      traceLabel,
    );
  }

  /**
   * @type {TimerEnd}
   */
  function internalEndTimer(logLabel, traceLabel) {
    ensureTimerFlagsAreUpdated();

    if ((timerFlags & kShouldSkipAll) === kShouldSkipAll) {
      return;
    }

    timeEnd(
      tracesStores[set],
      traceCategory,
      'debuglog.timeEnd',
      timerFlags,
      logImpl,
      logLabel,
      traceLabel,
    );
  }

  /**
   * @type {TimerLog}
   */
  function internalLogTimer(logLabel, traceLabel, args) {
    ensureTimerFlagsAreUpdated();

    if ((timerFlags & kShouldSkipAll) === kShouldSkipAll) {
      return;
    }

    timeLog(
      tracesStores[set],
      traceCategory,
      'debuglog.timeLog',
      timerFlags,
      logImpl,
      logLabel,
      traceLabel,
      args,
    );
  }

  function init() {
    if (tracesStores[set] === undefined) {
      tracesStores[set] = new SafeMap();
    }
    emitWarningIfNeeded(set);
    debugLogCategoryEnabled = testEnabled(set);
    traceCategoryEnabled = categoryEnabledChecker(traceCategory);

    timerFlags = kNone;

    if (!debugLogCategoryEnabled) {
      timerFlags |= kSkipLog;
    }

    if (!traceCategoryEnabled()) {
      timerFlags |= kSkipTrace;
    }

    cb(internalStartTimer, internalEndTimer, internalLogTimer);
  }

  /**
   * @type {TimerStart}
   */
  const startTimer = (logLabel, traceLabel) => {
    init();

    if ((timerFlags & kShouldSkipAll) !== kShouldSkipAll)
      internalStartTimer(logLabel, traceLabel);
  };

  /**
   * @type {TimerEnd}
   */
  const endTimer = (logLabel, traceLabel) => {
    init();

    if ((timerFlags & kShouldSkipAll) !== kShouldSkipAll)
      internalEndTimer(logLabel, traceLabel);
  };

  /**
   * @type {TimerLog}
   */
  const logTimer = (logLabel, traceLabel, args) => {
    init();

    if ((timerFlags & kShouldSkipAll) !== kShouldSkipAll)
      internalLogTimer(logLabel, traceLabel, args);
  };

  return {
    startTimer,
    endTimer,
    logTimer,
  };
}

module.exports = {
  kNone,
  kSkipLog,
  kSkipTrace,
  formatTime,
  time,
  timeEnd,
  timeLog,
  debuglog,
  debugWithTimer,
  initializeDebugEnv,
};