misc(logger): 1.3.0, package types, timeDecorate, add tests

jest.config.js

@@ -11,6 +11,7 @@ module.exports = {
   collectCoverageFrom: [
     '**/lighthouse-core/**/*.js',
     '**/lighthouse-cli/**/*.js',
+    '**/lighthouse-logger/**/*.js',
     '!**/test/',
     '!**/scripts/',
   ],
@@ -19,5 +20,6 @@ module.exports = {
   testMatch: [
     '**/lighthouse-core/**/*-test.js',
     '**/lighthouse-cli/**/*-test.js',
+    '**/lighthouse-logger/**/*-test.js',
   ],
 };

lighthouse-logger/index.js

@@ -7,11 +7,42 @@
 
 const debug = require('debug');
 const marky = require('marky');
-
 const EventEmitter = require('events').EventEmitter;
+
+/**
+ * @template T
+ * @typedef {import('./type-helpers').IsFunction<T>} IsFunction
+ */
+
+/**
+ * @template Class
+ * @template {*[]} Args
+ * @typedef {{
+ *  msg: string | ((this: Class, ...args: Args) => string),
+ *  id?: string | ((this: Class, ...args: Args) => string),
+ *  timeStartLogLevel?: LogAction,
+ *  timeEndLogLevel?: LogAction,
+ * }} TimeDecorateOpts
+ */
+
+/**
+ * @typedef {'verbose'|'error'|'silent'|'log'|'info'|'warn'} LogLevel
+ */
+/**
+ * @typedef {'verbose'|'error'|'log'|'warn'} LogAction
+ */
+
+/**
+ * @typedef {{
+ *   msg: string,
+ *   id: string,
+ *   args?: any[],
+ * }} Status
+ */
+
 const isWindows = process.platform === 'win32';
 
-// process.browser is set when browserify'd via the `process` npm module
+// @ts-ignore - process.browser is set when browserify'd via the `process` npm module
 const isBrowser = process.browser;
 
 const colors = {
@@ -23,60 +54,76 @@ const colors = {
   magenta: isBrowser ? 'palevioletred' : 5,
 };
 
-// whitelist non-red/yellow colors for debug()
+// @ts-ignore - whitelist non-red/yellow colors for debug(). not public
 debug.colors = [colors.cyan, colors.green, colors.blue, colors.magenta];
 
 class Emitter extends EventEmitter {
   /**
    * Fires off all status updates. Listen with
    * `require('lib/log').events.addListener('status', callback)`
    * @param {string} title
+   * @param {string|Error} message
    * @param {!Array<*>} argsArray
    */
-  issueStatus(title, argsArray) {
+  issueStatus(title, message, argsArray) {
     if (title === 'status' || title === 'statusEnd') {
-      this.emit(title, [title, ...argsArray]);
+      this.emit(title, [title, message, ...argsArray]);
     }
   }
 
   /**
    * Fires off all warnings. Listen with
    * `require('lib/log').events.addListener('warning', callback)`
    * @param {string} title
+   * @param {string|Error} message
    * @param {!Array<*>} argsArray
    */
-  issueWarning(title, argsArray) {
-    this.emit('warning', [title, ...argsArray]);
+  issueWarning(title, message, argsArray) {
+    this.emit('warning', [title, message, ...argsArray]);
   }
 }
 
+/** @type {Record<string, debug.IDebugger>} */
 const loggersByTitle = {};
+
 const loggingBufferColumns = 25;
+
+/** @type {LogLevel} */
 let level_;
 
 class Log {
-  static _logToStdErr(title, argsArray) {
+  /**
+   * @param {string} title
+   * @param {string|Error} message
+   * @param {Array<any>} argsArray
+   */
+  static _logToStdErr(title, message, argsArray) {
     const log = Log.loggerfn(title);
-    log(...argsArray);
+    log(message, ...argsArray);
   }
 
+  /**
+   * @param {string} title
+   */
   static loggerfn(title) {
     let log = loggersByTitle[title];
     if (!log) {
       log = debug(title);
       loggersByTitle[title] = log;
       // errors with red, warnings with yellow.
       if (title.endsWith('error')) {
+        // @ts-ignore
         log.color = colors.red;
       } else if (title.endsWith('warn')) {
+        // @ts-ignore
         log.color = colors.yellow;
       }
     }
     return log;
   }
 
   /**
-   * @param {string} level
+   * @param {LogLevel} level
    */
   static setLevel(level) {
     level_ = level;
@@ -99,16 +146,16 @@ class Log {
    * A simple formatting utility for event logging.
    * @param {string} prefix
    * @param {!Object} data A JSON-serializable object of event data to log.
-   * @param {string=} level Optional logging level. Defaults to 'log'.
+   * @param {LogLevel=} level Optional logging level. Defaults to 'log'.
    */
   static formatProtocol(prefix, data, level) {
-    const columns = (!process || process.browser) ? Infinity : process.stdout.columns;
+    const columns = isBrowser ? Infinity : (process.stdout.columns || Infinity);
     const method = data.method || '?????';
     const maxLength = columns - method.length - prefix.length - loggingBufferColumns;
     // IO.read blacklisted here to avoid logging megabytes of trace data
     const snippet = (data.params && method !== 'IO.read') ?
       JSON.stringify(data.params).substr(0, maxLength) : '';
-    Log._logToStdErr(`${prefix}:${level || ''}`, [method, snippet]);
+    Log._logToStdErr(`${prefix}:${level || ''}`, method, [snippet]);
   }
 
   /**
@@ -118,33 +165,148 @@ class Log {
     return level_ === 'verbose';
   }
 
-  static time({msg, id, args = []}, level = 'log') {
+  /**
+   * @param {Status} status
+   * @param {LogAction} level
+   */
+  static time({msg, id, args}, level = 'log') {
     marky.mark(id);
-    Log[level]('status', msg, ...args);
+    Log[level]('status', msg, ...(args || []));
   }
 
-  static timeEnd({msg, id, args = []}, level = 'verbose') {
-    Log[level]('statusEnd', msg, ...args);
+  /**
+   * @param {Status} status
+   * @param {LogAction} level
+   */
+  static timeEnd({msg, id, args}, level = 'verbose') {
+    Log[level]('statusEnd', msg, ...(args || []));
     marky.stop(id);
   }
 
-  static log(title, ...args) {
-    Log.events.issueStatus(title, args);
-    return Log._logToStdErr(title, args);
+  /* eslint-disable no-invalid-this */
+  /**
+   * Decorates a function, calling time/timeEnd before/after calling the original function.
+   * @template {*} R
+   * @template {*[]} Args
+   * @param {(...args: Args) => R} originalFn
+   * @param {TimeDecorateOpts<any, Args>} opts
+   * @return {(...args: Args) => R}
+   */
+  static timeDecorate(originalFn, opts) {
+    /**
+     * @type {(_this: *, args: Args) => string}
+     */
+    const computeMsg = (_this, args) => {
+      if (typeof opts.msg === 'string') return opts.msg;
+      if (typeof opts.msg === 'function') return opts.msg.apply(_this, args);
+      throw new Error('expected msg');
+    };
+
+    /**
+     * @type {(_this: *, args: Args) => string}
+     */
+    const computeId = (_this, args) => {
+      if (typeof opts.id === 'string') return opts.id;
+      if (typeof opts.id === 'function') return opts.id.apply(_this, args);
+      return `lh:${originalFn.name}`;
+    };
+
+    const timeStartLogLevel = opts.timeStartLogLevel || 'log';
+    const timeEndLogLevel = opts.timeEndLogLevel || 'verbose';
+
+    /**
+     * @type {(this: *, ...args: Args) => R}
+    */
+    const fn = function timeDecoratedFn(...args) {
+      const status = {msg: computeMsg(this, args), id: computeId(this, args)};
+      Log.time(status, timeStartLogLevel);
+
+      let result;
+      try {
+        result = originalFn.apply(this, args);
+      } catch (err) {
+        Log.timeEnd(status, timeEndLogLevel);
+        throw err;
+      }
+
+      if (result && typeof result.then === 'function') {
+        return result.then((/** @type {any} */ value) => {
+          Log.timeEnd(status, timeEndLogLevel);
+          return value;
+        }).catch((/** @type {any} */ err) => {
+          Log.timeEnd(status, timeEndLogLevel);
+          throw err;
+        });
+      } else {
+        Log.timeEnd(status, timeEndLogLevel);
+        return result;
+      }
+    };
+    return fn;
   }
+  /* eslint-enable no-invalid-this */
 
-  static warn(title, ...args) {
-    Log.events.issueWarning(title, args);
-    return Log._logToStdErr(`${title}:warn`, args);
+  /**
+   * Decorates (like timeDecorate) specified methods of a class.
+   * If decorating instance methods, use the class's prototype.
+   * If decorating static methods, use the class directly.
+   * @template {Object|Function} Class
+   * @template {keyof Class} Prop
+   * @param {Class} klass
+   * @param {{[key in Prop]: TimeDecorateOpts<Class, Parameters<IsFunction<Class[key]>>>}} methods
+   */
+  static timeDecorateClass(klass, methods) {
+    for (const [method, opts] of Object.entries(methods)) {
+      if (!opts.id) {
+        const className = (typeof klass === 'function' ? klass : klass.constructor).name;
+        opts.id = `lh:${className}:${method}`;
+      }
+      /** @type {IsFunction<Class[typeof method]>} */
+      const original = klass[method];
+      if (!original) {
+        throw new Error(`Cannot decorate non-existent method ${method}`);
+      }
+      klass[method] = Log.timeDecorate(original, opts);
+    }
   }
 
-  static error(title, ...args) {
-    return Log._logToStdErr(`${title}:error`, args);
+  /**
+   * @param {string} title
+   * @param {string|Error} message
+   * @param {Array<any>} args
+   */
+  static log(title, message, ...args) {
+    Log.events.issueStatus(title, message, args);
+    Log._logToStdErr(title, message, args);
   }
 
-  static verbose(title, ...args) {
-    Log.events.issueStatus(title, args);
-    return Log._logToStdErr(`${title}:verbose`, args);
+  /**
+   * @param {string} title
+   * @param {string|Error} message
+   * @param {Array<any>} args
+   */
+  static warn(title, message, ...args) {
+    Log.events.issueWarning(title, message, args);
+    Log._logToStdErr(`${title}:warn`, message, args);
+  }
+
+  /**
+   * @param {string} title
+   * @param {string|Error} message
+   * @param {Array<any>} args
+   */
+  static error(title, message, ...args) {
+    Log._logToStdErr(`${title}:error`, message, args);
+  }
+
+  /**
+   * @param {string} title
+   * @param {string|Error} message
+   * @param {Array<any>} args
+   */
+  static verbose(title, message, ...args) {
+    Log.events.issueStatus(title, message, args);
+    Log._logToStdErr(`${title}:verbose`, message, args);
   }
 
   /**
@@ -228,14 +390,24 @@ class Log {
   static get doubleLightHorizontal() {
     return '──';
   }
+
+  /**
+   * @return {PerformanceEntry[]}
+   */
+  static takeTimeEntries() {
+    const entries = marky.getEntries();
+    marky.clear();
+    return entries;
+  }
+
+  /**
+   * @return {PerformanceEntry[]}
+   */
+  static getTimeEntries() {
+    return marky.getEntries();
+  }
 }
 
 Log.events = new Emitter();
-Log.takeTimeEntries = () => {
-  const entries = marky.getEntries();
-  marky.clear();
-  return entries;
-};
-Log.getTimeEntries = () => marky.getEntries();
 
 module.exports = Log;

lighthouse-logger/package.json

@@ -1,6 +1,6 @@
 {
   "name": "lighthouse-logger",
-  "version": "1.2.0",
+  "version": "1.3.0",
   "license": "Apache-2.0",
   "dependencies": {
     "debug": "^2.6.8",