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-core/lib/log.js

@@ -0,0 +1,9 @@
+/**
+ * @license Copyright 2018 Google Inc. All Rights Reserved.
+ * Licensed under the Apache License, Version 2.0 (the "License"); you may not use this file except in compliance with the License. You may obtain a copy of the License at http://www.apache.org/licenses/LICENSE-2.0
+ * Unless required by applicable law or agreed to in writing, software distributed under the License is distributed on an "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. See the License for the specific language governing permissions and limitations under the License.
+ */
+'use strict';
+
+/** @type {typeof import('../../lighthouse-logger')} */
+module.exports = require('lighthouse-logger');

lighthouse-logger/index.js

@@ -1,17 +1,59 @@
 /**
- * @license Copyright 2016 Google Inc. All Rights Reserved.
+ * @license Copyright 2018 Google Inc. All Rights Reserved.
  * Licensed under the Apache License, Version 2.0 (the "License"); you may not use this file except in compliance with the License. You may obtain a copy of the License at http://www.apache.org/licenses/LICENSE-2.0
  * Unless required by applicable law or agreed to in writing, software distributed under the License is distributed on an "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. See the License for the specific language governing permissions and limitations under the License.
  */
 'use strict';
 
 const debug = require('debug');
+// @ts-ignore
 const marky = require('marky');
-
 const EventEmitter = require('events').EventEmitter;
+
+/**
+ * @template {Function} F
+ * @typedef {import('./type-helpers').ArgumentTypes<F>} ArgumentTypes
+ */
+
+/**
+ * @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 {LogLevel & keyof typeof Log} LogAction
+ */
+
+/**
+ * @typedef {{
+ *   msg:string,
+ *   id: string,
+ *   args?: any[],
+ * }} Status
+ */
+
+/**
+ * @typedef {[any, ...any[]]} ArrayAtLeastOne
+ */
+
 const isWindows = process.platform === 'win32';
 
 // process.browser is set when browserify'd via the `process` npm module
+// @ts-ignore
 const isBrowser = process.browser;
 
 const colors = {
@@ -24,6 +66,7 @@ const colors = {
 };
 
 // whitelist non-red/yellow colors for debug()
+// @ts-ignore
 debug.colors = [colors.cyan, colors.green, colors.blue, colors.magenta];
 
 class Emitter extends EventEmitter {
@@ -50,33 +93,46 @@ class Emitter extends EventEmitter {
   }
 }
 
+/** @type {{[k: string] : debug.IDebugger}} */
 const loggersByTitle = {};
+
 const loggingBufferColumns = 25;
+
+/** @type {LogLevel} */
 let level_;
 
 class Log {
+  /**
+   * @param {string} title
+   * @param {ArrayAtLeastOne} argsArray
+   */
   static _logToStdErr(title, argsArray) {
     const log = Log.loggerfn(title);
     log(...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,10 +155,10 @@ 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
@@ -118,33 +174,164 @@ class Log {
     return level_ === 'verbose';
   }
 
+  /**
+   * @param {Status} param0
+   * @param {LogAction} level
+   */
   static time({msg, id, args = []}, level = 'log') {
     marky.mark(id);
     Log[level]('status', msg, ...args);
   }
 
+  /**
+   * @param {Status} param0
+   * @param {LogAction} level
+   */
   static timeEnd({msg, id, args = []}, level = 'verbose') {
     Log[level]('statusEnd', msg, ...args);
     marky.stop(id);
   }
 
+  /* eslint-disable no-invalid-this */
+  /**
+   * Decorates a function, calling time/timeEnd before/after calling the original function.
+   * @template T, R
+   * @template {*[]} Args
+   * @param {(this: T, ...args: Args) => R} originalFn
+   * @param {TimeDecorateOpts<T, Args>} opts
+   * @return {(this: T, ...args: Args) => R}
+   */
+  static timeDecorate(originalFn, opts) {
+    /**
+     * @type {(this: *, ...args: *[]) => string}
+     */
+    const computeMsg = (_this, args) => {
+      let msg = '';
+      if (typeof opts.msg === 'string') {
+        msg = opts.msg;
+      } else if (typeof opts.msg === 'function') {
+        // TODO turn on --strictBindCallApply when tsc is upgraded to 3.2
+        msg = opts.msg.apply(_this, args);
+      }
+      if (!msg) {
+        throw new Error('expected msg');
+      }
+      return msg;
+    };
+
+    /**
+     * @type {(this: *, ...args: *[]) => string}
+     */
+    const computeId = (_this, args) => {
+      let id = '';
+      if (typeof opts.id === 'string') {
+        id = opts.id;
+      } else if (typeof opts.id === 'function') {
+        // TODO turn on --strictBindCallApply when tsc is upgraded to 3.2
+        id = opts.id.apply(this, args);
+      } else {
+        id = `lh:${originalFn.name}`;
+      }
+      if (!id) {
+        throw new Error('expected id');
+      }
+      return id;
+    };
+
+    /**
+     * @type {(this: T, ...args: Args) => R}
+     */
+    const fn = function timeDecoratedFn(...args) {
+      const timeStartLogLevel = opts.timeStartLogLevel || 'log';
+      const timeEndLogLevel = opts.timeEndLogLevel || 'verbose';
+
+      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);
+        err.stack = err.stack.replace(/.* at timeDecoratedFn .*\n/g, '');
+        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);
+          err.stack = err.stack.replace(/.* at timeDecoratedFn .*\n/, '');
+          throw err;
+        });
+      } else {
+        Log.timeEnd(status, timeEndLogLevel);
+        return result;
+      }
+    };
+    return fn;
+  }
+  /* eslint-enable no-invalid-this */
+
+  /**
+   * 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, ArgumentTypes<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);
+    }
+  }
+
+  /**
+   * @param {string} title
+   * @param {ArrayAtLeastOne} args
+   */
   static log(title, ...args) {
     Log.events.issueStatus(title, args);
-    return Log._logToStdErr(title, args);
+    Log._logToStdErr(title, args);
   }
 
+  /**
+   * @param {string} title
+   * @param {ArrayAtLeastOne} args
+   */
   static warn(title, ...args) {
     Log.events.issueWarning(title, args);
-    return Log._logToStdErr(`${title}:warn`, args);
+    Log._logToStdErr(`${title}:warn`, args);
   }
 
+  /**
+   * @param {string} title
+   * @param {ArrayAtLeastOne} args
+   */
   static error(title, ...args) {
-    return Log._logToStdErr(`${title}:error`, args);
+    Log._logToStdErr(`${title}:error`, args);
   }
 
+  /**
+   * @param {string} title
+   * @param {ArrayAtLeastOne} args
+   */
   static verbose(title, ...args) {
     Log.events.issueStatus(title, args);
-    return Log._logToStdErr(`${title}:verbose`, args);
+    Log._logToStdErr(`${title}:verbose`, args);
   }
 
   /**
@@ -228,14 +415,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",