diff --git a/jest.config.js b/jest.config.js index 73b809a0b4b4..765ab5d146f2 100644 --- a/jest.config.js +++ b/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', ], }; diff --git a/lighthouse-logger/index.js b/lighthouse-logger/index.js index 041cf2a72e19..dd3639adf32c 100644 --- a/lighthouse-logger/index.js +++ b/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} 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,7 +54,7 @@ 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 { @@ -31,11 +62,12 @@ 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]); } } @@ -43,23 +75,36 @@ class Emitter extends EventEmitter { * 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} */ const loggersByTitle = {}; + const loggingBufferColumns = 25; + +/** @type {LogLevel} */ let level_; class Log { - static _logToStdErr(title, argsArray) { + /** + * @param {string} title + * @param {string|Error} message + * @param {Array} 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) { @@ -67,8 +112,10 @@ class Log { 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; } } @@ -76,7 +123,7 @@ class 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} 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>>}} 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} */ + 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} 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} 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} args + */ + static error(title, message, ...args) { + Log._logToStdErr(`${title}:error`, message, args); + } + + /** + * @param {string} title + * @param {string|Error} message + * @param {Array} 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; diff --git a/lighthouse-logger/package.json b/lighthouse-logger/package.json index 0f985fe4f961..1ef3b073f333 100644 --- a/lighthouse-logger/package.json +++ b/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", diff --git a/lighthouse-logger/test/index-test.js b/lighthouse-logger/test/index-test.js new file mode 100644 index 000000000000..3f2ea3196186 --- /dev/null +++ b/lighthouse-logger/test/index-test.js @@ -0,0 +1,125 @@ +/** + * @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'; + +/* eslint-env jest */ + +const assert = require('assert'); +const log = require('../index.js'); + +afterEach(log.takeTimeEntries); + +describe('Log.timeDecorate', function() { + it('records timings', () => { + const fn = () => {}; + const decoratedFn = log.timeDecorate(fn, { + msg: 'msg', + id: 'id', + }); + decoratedFn(); + assert.equal(log.getTimeEntries().length, 1); + assert.ok(log.getTimeEntries()[0].duration > 0); + }); + + it('retains return value', () => { + const fn = () => 'works'; + const decoratedFn = log.timeDecorate(fn, { + msg: 'msg', + id: 'id', + }); + assert.equal(decoratedFn(), 'works'); + }); + + it('retains async return value', async () => { + const fn = async () => 'works'; + const decoratedFn = log.timeDecorate(fn, { + msg: 'msg', + id: 'id', + }); + assert.equal(await decoratedFn(), 'works'); + }); + + it('retains parameters', () => { + const fn = (value1, value2) => value1 + value2; + const decoratedFn = log.timeDecorate(fn, { + msg: 'msg', + id: 'id', + }); + assert.equal(decoratedFn(1, 2), 3); + }); + + it('accepts function template for msg and id', () => { + // eslint-disable-next-line no-unused-vars + const fn = (value1, value2) => {}; + const decoratedFn = log.timeDecorate(fn, { + msg: (value1, value2) => `msg ${value1} ${value2}`, + id: (value1, value2) => `id:${value1}:${value2}`, + }); + decoratedFn('it', 'works'); + assert.equal(log.takeTimeEntries()[0].name, 'id:it:works'); + }); +}); + +describe('Log.timeDecorateClass', function() { + /* eslint-disable no-invalid-this */ + it('retains this binding', () => { + class Class { + constructor() { + this.value = 'works'; + } + + getValue() { + return this.value; + } + } + log.timeDecorateClass(Class.prototype, { + getValue: { + msg: 'msg', + id: 'id', + }, + }); + assert.equal((new Class).getValue(), 'works'); + }); + /* eslint-enable no-invalid-this */ + + it('kitchen sink', () => { + class Class { + static get staticWorks() { + return 'works'; + } + + static getStaticValue(value) { + return `${value} ${this.staticWorks}`; + } + + constructor() { + this.works = 'works'; + } + + getValue(value) { + return `${value} ${this.works}`; + } + } + + log.timeDecorateClass(Class, { + getStaticValue: { + msg: value => `msg ${value}`, + id: value => `id:${value}`, + }, + }); + assert.equal(Class.getStaticValue('it'), 'it works'); + assert.equal(log.takeTimeEntries()[0].name, 'id:it'); + + log.timeDecorateClass(Class.prototype, { + getValue: { + msg: value => `msg ${value}`, + id: value => `id:${value}`, + }, + }); + assert.equal((new Class).getValue('it'), 'it works'); + assert.equal(log.takeTimeEntries()[0].name, 'id:it'); + }); +}); diff --git a/lighthouse-logger/type-helpers.d.ts b/lighthouse-logger/type-helpers.d.ts new file mode 100644 index 000000000000..a4f515d0e4e8 --- /dev/null +++ b/lighthouse-logger/type-helpers.d.ts @@ -0,0 +1,7 @@ +/** + * @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. + */ + +export type IsFunction = T extends Function ? T : never; diff --git a/lighthouse-logger/yarn.lock b/lighthouse-logger/yarn.lock index 5cef70256d6c..190ea404ae4e 100644 --- a/lighthouse-logger/yarn.lock +++ b/lighthouse-logger/yarn.lock @@ -2,16 +2,24 @@ # yarn lockfile v1 +"@types/debug@^0.0.31": + version "0.0.31" + resolved "https://registry.yarnpkg.com/@types/debug/-/debug-0.0.31.tgz#bac8d8aab6a823e91deb7f79083b2a35fa638f33" + integrity sha512-LS1MCPaQKqspg7FvexuhmDbWUhE2yIJ+4AgVIyObfc06/UKZ8REgxGNjZc82wPLWmbeOm7S+gSsLgo75TanG4A== + debug@^2.6.8: version "2.6.8" resolved "https://registry.yarnpkg.com/debug/-/debug-2.6.8.tgz#e731531ca2ede27d188222427da17821d68ff4fc" + integrity sha1-5zFTHKLt4n0YgiJCfaF4IdaP9Pw= dependencies: ms "2.0.0" marky@^1.2.0: version "1.2.0" resolved "https://registry.yarnpkg.com/marky/-/marky-1.2.0.tgz#9617ed647bbbea8f45d19526da33dec70606df42" + integrity sha1-lhftZHu76o9F0ZUm2jPexwYG30I= ms@2.0.0: version "2.0.0" resolved "https://registry.yarnpkg.com/ms/-/ms-2.0.0.tgz#5608aeadfc00be6c2901df5f9861788de0d597c8" + integrity sha1-VgiurfwAvmwpAd9fmGF4jeDVl8g= diff --git a/package.json b/package.json index 5f33e4fd7cee..123877de1de8 100644 --- a/package.json +++ b/package.json @@ -31,9 +31,11 @@ "unit-core:ci": "jest --runInBand --coverage --ci \"lighthouse-core/\"", "unit-cli": "jest --runInBand \"lighthouse-cli/\"", "unit-cli:ci": "jest --runInBand --coverage --ci \"lighthouse-cli/\"", + "unit-logger": "jest --runInBand \"lighthouse-logger/\"", + "unit-logger:ci": "jest --runInBand --coverage --ci \"lighthouse-logger/\"", "unit-viewer": "mocha --reporter dot \"lighthouse-viewer/test/**/*-test.js\"", - "unit": "yarn unit-core && yarn unit-cli && yarn unit-viewer", - "unit:ci": "yarn unit-core:ci && yarn unit-cli:ci && yarn unit-viewer", + "unit": "yarn unit-core && yarn unit-cli && yarn unit-logger && yarn unit-viewer", + "unit:ci": "yarn unit-core:ci && yarn unit-cli:ci && yarn unit-logger:ci && yarn unit-viewer", "core-unit": "yarn unit-core", "cli-unit": "yarn unit-cli", "viewer-unit": "yarn unit-viewer", @@ -76,6 +78,7 @@ "@types/configstore": "^2.1.1", "@types/cpy": "^5.1.0", "@types/css-font-loading-module": "^0.0.2", + "@types/debug": "^0.0.31", "@types/esprima": "^4.0.2", "@types/gh-pages": "^2.0.0", "@types/google.analytics": "0.0.39", diff --git a/tsconfig.json b/tsconfig.json index 6d57b103eab5..9c829e2aa7bc 100644 --- a/tsconfig.json +++ b/tsconfig.json @@ -19,6 +19,7 @@ "include": [ "lighthouse-cli/**/*.js", "lighthouse-core/**/*.js", + "lighthouse-logger/**/*.js", "clients/**/*.js", "build/**/*.js", "./types/*.d.ts", @@ -26,6 +27,7 @@ "exclude": [ "lighthouse-cli/test/**/*.js", "lighthouse-core/test/**/*.js", + "lighthouse-logger/test/**/*.js", "clients/test/**/*.js", ] } diff --git a/types/marky/index.d.ts b/types/marky/index.d.ts new file mode 100644 index 000000000000..4f8dc7126f19 --- /dev/null +++ b/types/marky/index.d.ts @@ -0,0 +1,9 @@ +declare module 'marky' { + class Marky { + static mark(name: string): void; + static stop(name: string): void; + static getEntries(): PerformanceEntry[]; + static clear(): void; + } + export = Marky; +} diff --git a/yarn.lock b/yarn.lock index a412a74ff2c3..da06a805c099 100644 --- a/yarn.lock +++ b/yarn.lock @@ -143,6 +143,11 @@ resolved "https://registry.yarnpkg.com/@types/css-font-loading-module/-/css-font-loading-module-0.0.2.tgz#09f1f1772975777e37851b7b7a4389d97c210add" integrity sha512-zZTq/B1ZcJMepOfBIMEwOZ/g/jpSPUJoxP8zPtPizOKE/Q89SujK1BLYZBg+4LLW3IzJGOI67dbeePy8uPUs+g== +"@types/debug@^0.0.31": + version "0.0.31" + resolved "https://registry.yarnpkg.com/@types/debug/-/debug-0.0.31.tgz#bac8d8aab6a823e91deb7f79083b2a35fa638f33" + integrity sha512-LS1MCPaQKqspg7FvexuhmDbWUhE2yIJ+4AgVIyObfc06/UKZ8REgxGNjZc82wPLWmbeOm7S+gSsLgo75TanG4A== + "@types/esprima@^4.0.2": version "4.0.2" resolved "https://registry.yarnpkg.com/@types/esprima/-/esprima-4.0.2.tgz#0303602d0644086d4802635d7abc9ac0eec57207"