diff --git a/clients/devtools-entry.js b/clients/devtools-entry.js index cd542f7b3fce..d6180d4a5129 100644 --- a/clients/devtools-entry.js +++ b/clients/devtools-entry.js @@ -7,7 +7,7 @@ const lighthouse = require('../lighthouse-core/index.js'); const RawProtocol = require('../lighthouse-core/gather/connections/raw.js'); -const log = require('lighthouse-logger'); +const log = require('../lighthouse-core/lib/log'); /** @typedef {import('../lighthouse-core/gather/connections/connection.js')} Connection */ diff --git a/clients/extension/scripts/extension-entry.js b/clients/extension/scripts/extension-entry.js index 4b92017d1012..5f884e9ebd8b 100644 --- a/clients/extension/scripts/extension-entry.js +++ b/clients/extension/scripts/extension-entry.js @@ -11,7 +11,7 @@ const defaultConfig = require('../../../lighthouse-core/config/default-config.js const i18n = require('../../../lighthouse-core/lib/i18n/i18n.js'); const ExtensionProtocol = require('../../../lighthouse-core/gather/connections/extension'); -const log = require('lighthouse-logger'); +const log = require('../../../lighthouse-core/lib/log'); /** @typedef {import('../../../lighthouse-core/gather/connections/connection.js')} Connection */ 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-cli/bin.js b/lighthouse-cli/bin.js index 40ff47b308a0..b2f21dfea64a 100644 --- a/lighthouse-cli/bin.js +++ b/lighthouse-cli/bin.js @@ -27,7 +27,7 @@ const getFlags = require('./cli-flags.js').getFlags; const runLighthouse = require('./run').runLighthouse; const generateConfig = require('../lighthouse-core/index.js').generateConfig; -const log = require('lighthouse-logger'); +const log = require('../lighthouse-core/lib/log'); const pkg = require('../package.json'); const Sentry = require('../lighthouse-core/lib/sentry'); diff --git a/lighthouse-cli/printer.js b/lighthouse-cli/printer.js index e41e30324bfe..f53fc424d66f 100644 --- a/lighthouse-cli/printer.js +++ b/lighthouse-cli/printer.js @@ -6,7 +6,7 @@ 'use strict'; const fs = require('fs'); -const log = require('lighthouse-logger'); +const log = require('../lighthouse-core/lib/log'); /** * An enumeration of acceptable output modes: diff --git a/lighthouse-cli/run.js b/lighthouse-cli/run.js index a602edc7b4f3..0727bd0bff59 100644 --- a/lighthouse-cli/run.js +++ b/lighthouse-cli/run.js @@ -14,7 +14,7 @@ const ChromeLauncher = require('chrome-launcher'); const yargsParser = require('yargs-parser'); const lighthouse = require('../lighthouse-core'); -const log = require('lighthouse-logger'); +const log = require('../lighthouse-core/lib/log'); const getFilenamePrefix = require('../lighthouse-core/lib/file-namer').getFilenamePrefix; const assetSaver = require('../lighthouse-core/lib/asset-saver'); diff --git a/lighthouse-cli/sentry-prompt.js b/lighthouse-cli/sentry-prompt.js index 405377e1da99..722ff3dbf8d5 100644 --- a/lighthouse-cli/sentry-prompt.js +++ b/lighthouse-cli/sentry-prompt.js @@ -8,7 +8,7 @@ const Configstore = require('configstore'); const inquirer = require('inquirer'); -const log = require('lighthouse-logger'); +const log = require('../lighthouse-core/lib/log'); const MAXIMUM_WAIT_TIME = 20 * 1000; diff --git a/lighthouse-cli/test/smokehouse/run-smoke.js b/lighthouse-cli/test/smokehouse/run-smoke.js index 12f2cb86d7cf..6ab7e9cf2a5c 100644 --- a/lighthouse-cli/test/smokehouse/run-smoke.js +++ b/lighthouse-cli/test/smokehouse/run-smoke.js @@ -10,7 +10,7 @@ const {promisify} = require('util'); const execAsync = promisify(require('child_process').exec); const {server, serverForOffline} = require('../fixtures/static-server'); -const log = require('lighthouse-logger'); +const log = require('../lib/log'); const purpleify = str => `${log.purple}${str}${log.reset}`; const smokehouseDir = 'lighthouse-cli/test/smokehouse/'; diff --git a/lighthouse-cli/test/smokehouse/smokehouse.js b/lighthouse-cli/test/smokehouse/smokehouse.js index c3bf337e9535..e9e0707eaf72 100755 --- a/lighthouse-cli/test/smokehouse/smokehouse.js +++ b/lighthouse-cli/test/smokehouse/smokehouse.js @@ -12,7 +12,7 @@ const fs = require('fs'); const path = require('path'); const spawnSync = require('child_process').spawnSync; const yargs = require('yargs'); -const log = require('lighthouse-logger'); +const log = require('../lib/log'); const PROTOCOL_TIMEOUT_EXIT_CODE = 67; const PAGE_HUNG_EXIT_CODE = 68; diff --git a/lighthouse-core/computed/trace-of-tab.js b/lighthouse-core/computed/trace-of-tab.js index 284c6d9e6055..f2066e1c822e 100644 --- a/lighthouse-core/computed/trace-of-tab.js +++ b/lighthouse-core/computed/trace-of-tab.js @@ -17,7 +17,7 @@ */ const makeComputedArtifact = require('./computed-artifact.js'); -const log = require('lighthouse-logger'); +const log = require('../lib/log.js'); const TracingProcessor = require('../lib/traces/tracing-processor.js'); const LHError = require('../lib/lh-error.js'); const Sentry = require('../lib/sentry.js'); diff --git a/lighthouse-core/config/config.js b/lighthouse-core/config/config.js index b7e4b4a41d8c..485dfc714c60 100644 --- a/lighthouse-core/config/config.js +++ b/lighthouse-core/config/config.js @@ -12,7 +12,7 @@ const constants = require('./constants.js'); const i18n = require('./../lib/i18n/i18n.js'); const isDeepEqual = require('lodash.isequal'); -const log = require('lighthouse-logger'); +const log = require('../lib/log'); const path = require('path'); const Audit = require('../audits/audit.js'); const Runner = require('../runner.js'); @@ -756,8 +756,6 @@ class Config { * @return {Config['audits']} */ static requireAudits(audits, configPath) { - const status = {msg: 'Requiring audits', id: 'lh:config:requireAudits'}; - log.time(status, 'verbose'); const expandedAudits = Config.expandAuditShorthand(audits); if (!expandedAudits) { return null; @@ -789,7 +787,6 @@ class Config { const mergedAuditDefns = mergeOptionsOfItems(auditDefns); mergedAuditDefns.forEach(audit => assertValidAudit(audit.implementation, audit.path)); - log.timeEnd(status); return mergedAuditDefns; } @@ -831,8 +828,6 @@ class Config { if (!passes) { return null; } - const status = {msg: 'Requiring gatherers', id: 'lh:config:requireGatherers'}; - log.time(status, 'verbose'); const coreList = Runner.getGathererList(); const fullPasses = passes.map(pass => { @@ -866,9 +861,19 @@ class Config { return Object.assign(pass, {gatherers: mergedDefns}); }); - log.timeEnd(status); return fullPasses; } } +log.timeDecorateClass(Config, { + requireAudits: { + msg: 'Requiring audits', + id: 'lh:config:requireAudits', + }, + requireGatherers: { + msg: 'Requiring gatherers', + id: 'lh:config:requireGatherers', + }, +}); + module.exports = Config; diff --git a/lighthouse-core/gather/computed/computed-artifact.js b/lighthouse-core/gather/computed/computed-artifact.js new file mode 100644 index 000000000000..03696d6ca73c --- /dev/null +++ b/lighthouse-core/gather/computed/computed-artifact.js @@ -0,0 +1,95 @@ +/** + * @license Copyright 2016 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 ArbitraryEqualityMap = require('../../lib/arbitrary-equality-map'); +const log = require('../../lib/log'); + +class ComputedArtifact { + /** + * @param {*} allComputedArtifacts + */ + constructor(allComputedArtifacts) { + const cache = new ArbitraryEqualityMap(); + cache.setEqualityFn(ArbitraryEqualityMap.deepEquals); + + /** @type {Map, Promise>>} */ + // @ts-ignore cache is close enough to a Map for our purposes (but e.g. no [Symbol.toStringTag]) + this._cache = cache; + + /** @type {*} */ + this._allComputedArtifacts = allComputedArtifacts; + } + + /** + * @return {string} + */ + get name() { + throw new Error('name getter not implemented for computed artifact ' + this.constructor.name); + } + + /* eslint-disable no-unused-vars */ + + /** + * Override with more specific `artifact` and return type to implement a + * computed artifact. + * @param {*} artifact Input to computation. + * @param {*} allComputedArtifacts Access to all computed artifacts. + * @return {Promise<*>} + * @throws {Error} + */ + async compute_(artifact, allComputedArtifacts) { + throw new Error('compute_() not implemented for computed artifact ' + this.name); + } + + /* eslint-enable no-unused-vars */ + + /** + * Request a computed artifact, caching the result on the input artifact. + * Types of `requiredArtifacts` and the return value are derived from the + * `compute_` method on classes derived from ComputedArtifact. + * @param {FirstParamType} requiredArtifacts + * @return {Promise>} + */ + async request(requiredArtifacts) { + const computed = this._cache.get(requiredArtifacts); + if (computed) { + return computed; + } + + // Need to cast since `this.compute_(...)` returns the concrete return type + // of the base class's compute_, not the called derived class's. + const artifactPromise = /** @type {ReturnType} */ ( + this.makeRequest(requiredArtifacts)); + this._cache.set(requiredArtifacts, artifactPromise); + return artifactPromise; + } + + /** + * Request a computed artifact, caching the result on the input artifact. + * Types of `requiredArtifacts` and the return value are derived from the + * `compute_` method on classes derived from ComputedArtifact. + * @param {FirstParamType} requiredArtifacts + * @return {Promise>} + */ + makeRequest(requiredArtifacts) { + return this.compute_(requiredArtifacts, this._allComputedArtifacts); + } +} + +log.timeDecorateClass(ComputedArtifact.prototype, { + makeRequest: { + msg: function() { + return `Computing artifact: ${this.name}`; + }, + id: function() { + return `lh:computed:${this.name}`; + }, + timeStartLogLevel: 'verbose', + }, +}); + +module.exports = ComputedArtifact; diff --git a/lighthouse-core/gather/connections/connection.js b/lighthouse-core/gather/connections/connection.js index df2040077520..8e936c1bb274 100644 --- a/lighthouse-core/gather/connections/connection.js +++ b/lighthouse-core/gather/connections/connection.js @@ -6,7 +6,7 @@ 'use strict'; const EventEmitter = require('events').EventEmitter; -const log = require('lighthouse-logger'); +const log = require('../../lib/log'); const LHError = require('../../lib/lh-error'); // TODO(bckenny): CommandCallback properties should be tied by command type after diff --git a/lighthouse-core/gather/connections/cri.js b/lighthouse-core/gather/connections/cri.js index f0b2713d1e36..ca2e66521430 100644 --- a/lighthouse-core/gather/connections/cri.js +++ b/lighthouse-core/gather/connections/cri.js @@ -8,7 +8,7 @@ const Connection = require('./connection.js'); const WebSocket = require('ws'); const http = require('http'); -const log = require('lighthouse-logger'); +const log = require('../../lib/log'); const DEFAULT_HOSTNAME = 'localhost'; const CONNECT_TIMEOUT = 10000; diff --git a/lighthouse-core/gather/connections/extension.js b/lighthouse-core/gather/connections/extension.js index 0c1a20a57f13..6dcdfb511759 100644 --- a/lighthouse-core/gather/connections/extension.js +++ b/lighthouse-core/gather/connections/extension.js @@ -8,7 +8,7 @@ 'use strict'; const Connection = require('./connection.js'); -const log = require('lighthouse-logger'); +const log = require('../../lib/log'); /* globals chrome */ diff --git a/lighthouse-core/gather/driver.js b/lighthouse-core/gather/driver.js index c49e512218f3..3e4d56b6fe66 100644 --- a/lighthouse-core/gather/driver.js +++ b/lighthouse-core/gather/driver.js @@ -13,8 +13,7 @@ const NetworkRequest = require('../lib/network-request'); const EventEmitter = require('events').EventEmitter; const URL = require('../lib/url-shim'); const constants = require('../config/constants'); - -const log = require('lighthouse-logger'); +const log = require('../lib/log'); const DevtoolsLog = require('./devtools-log'); const pageFunctions = require('../lib/page-functions.js'); @@ -136,13 +135,10 @@ class Driver { * @return {Promise} */ async getBrowserVersion() { - const status = {msg: 'Getting browser version', id: 'lh:gather:getVersion'}; - log.time(status, 'verbose'); const version = await this.sendCommand('Browser.getVersion'); const match = version.product.match(/\/(\d+)/); // eg 'Chrome/71.0.3577.0' const milestone = match ? parseInt(match[1]) : 0; - log.timeEnd(status); - return Object.assign(version, {milestone}); + return {...version, milestone}; } /** @@ -150,21 +146,14 @@ class Driver { * @return {Promise} */ async getBenchmarkIndex() { - const status = {msg: 'Benchmarking machine', id: 'lh:gather:getBenchmarkIndex'}; - log.time(status); - const indexVal = await this.evaluateAsync(`(${pageFunctions.ultradumbBenchmarkString})()`); - log.timeEnd(status); - return indexVal; + return this.evaluateAsync(`(${pageFunctions.ultradumbBenchmarkString})()`); } /** * @return {Promise} */ async connect() { - const status = {msg: 'Connecting to browser', id: 'lh:init:connect'}; - log.time(status); - await this._connection.connect(); - log.timeEnd(status); + return this._connection.connect(); } /** @@ -1318,4 +1307,19 @@ class Driver { } } +log.timeDecorateClass(Driver.prototype, { + getBenchmarkIndex: { + msg: 'Benchmarking machine', + id: 'lh:gather:getBenchmarkIndex', + }, + getBrowserVersion: { + msg: 'Getting browser version', + id: 'lh:gather:getVersion', + }, + connect: { + msg: 'Connecting to browser', + id: 'lh:init:connect', + }, +}); + module.exports = Driver; diff --git a/lighthouse-core/gather/gather-runner.js b/lighthouse-core/gather/gather-runner.js index 50726d04313d..76024b13335a 100644 --- a/lighthouse-core/gather/gather-runner.js +++ b/lighthouse-core/gather/gather-runner.js @@ -5,7 +5,7 @@ */ 'use strict'; -const log = require('lighthouse-logger'); +const log = require('../lib/log'); const LHError = require('../lib/lh-error'); const URL = require('../lib/url-shim'); const NetworkRecorder = require('../lib/network-recorder.js'); @@ -71,10 +71,7 @@ class GatherRunner { * @return {Promise} */ static async loadBlank(driver, url = constants.defaultPassConfig.blankPage) { - const status = {msg: 'Resetting state with about:blank', id: 'lh:gather:loadBlank'}; - log.time(status); await driver.gotoURL(url, {waitForNavigated: true}); - log.timeEnd(status); } /** @@ -100,8 +97,6 @@ class GatherRunner { * @return {Promise} */ static async setupDriver(driver, options) { - const status = {msg: 'Initializing…', id: 'lh:gather:setupDriver'}; - log.time(status); const resetStorage = !options.settings.disableStorageReset; await driver.assertNoSameOriginServiceWorkerClients(options.requestedUrl); await driver.beginEmulation(options.settings); @@ -111,7 +106,6 @@ class GatherRunner { await driver.dismissJavaScriptDialogs(); await driver.listenForSecurityStateChanges(); if (resetStorage) await driver.clearDataForOrigin(options.requestedUrl); - log.timeEnd(status); } /** @@ -119,9 +113,6 @@ class GatherRunner { * @return {Promise} */ static async disposeDriver(driver) { - const status = {msg: 'Disconnecting from browser...', id: 'lh:gather:disconnect'}; - - log.time(status); try { await driver.disconnect(); } catch (err) { @@ -131,7 +122,6 @@ class GatherRunner { log.error('GatherRunner disconnect', err.message); } } - log.timeEnd(status); } /** @@ -197,8 +187,6 @@ class GatherRunner { * @return {Promise} */ static async beforePass(passContext, gathererResults) { - const bpStatus = {msg: `Running beforePass methods`, id: `lh:gather:beforePass`}; - log.time(bpStatus, 'verbose'); const blockedUrls = (passContext.passConfig.blockedUrlPatterns || []) .concat(passContext.settings.blockedUrlPatterns || []); @@ -222,7 +210,6 @@ class GatherRunner { await artifactPromise.catch(() => {}); log.timeEnd(status); } - log.timeEnd(bpStatus); } /** @@ -505,4 +492,24 @@ class GatherRunner { } } +log.timeDecorateClass(GatherRunner, { + loadBlank: { + msg: 'Resetting state with about:blank', + id: 'lh:gather:loadBlank', + }, + setupDriver: { + msg: 'Initializing…', + id: 'lh:gather:setupDriver', + }, + disposeDriver: { + msg: 'Disconnecting from browser...', + id: 'lh:gather:disconnect', + }, + beforePass: { + msg: 'Running beforePass methods', + id: 'lh:gather:beforePass', + timeStartLogLevel: 'verbose', + }, +}); + module.exports = GatherRunner; diff --git a/lighthouse-core/index.js b/lighthouse-core/index.js index 09bca84b0187..053c4c74cfbf 100644 --- a/lighthouse-core/index.js +++ b/lighthouse-core/index.js @@ -6,7 +6,7 @@ 'use strict'; const Runner = require('./runner'); -const log = require('lighthouse-logger'); +const log = require('./lib/log'); const ChromeProtocol = require('./gather/connections/cri.js'); const Config = require('./config/config'); diff --git a/lighthouse-core/lib/asset-saver.js b/lighthouse-core/lib/asset-saver.js index 2faa29b37c21..7e06ca2e59a6 100644 --- a/lighthouse-core/lib/asset-saver.js +++ b/lighthouse-core/lib/asset-saver.js @@ -7,7 +7,7 @@ const fs = require('fs'); const path = require('path'); -const log = require('lighthouse-logger'); +const log = require('../lib/log'); const stream = require('stream'); const Simulator = require('./dependency-graph/simulator/simulator'); const lanternTraceSaver = require('./lantern-trace-saver'); @@ -79,8 +79,6 @@ async function loadArtifacts(basePath) { * @return {Promise} */ async function saveArtifacts(artifacts, basePath) { - const status = {msg: 'Saving artifacts', id: 'lh:assetSaver:saveArtifacts'}; - log.time(status); mkdirp.sync(basePath); rimraf.sync(`${basePath}/*${traceSuffix}`); rimraf.sync(`${basePath}/${artifactsFilename}`); @@ -102,7 +100,6 @@ async function saveArtifacts(artifacts, basePath) { const restArtifactsString = JSON.stringify(restArtifacts, null, 2); fs.writeFileSync(`${basePath}/${artifactsFilename}`, restArtifactsString, 'utf8'); log.log('Artifacts saved to disk in folder:', basePath); - log.timeEnd(status); } /** @@ -273,7 +270,10 @@ async function logAssets(artifacts, audits) { } module.exports = { - saveArtifacts, + saveArtifacts: log.timeDecorate(saveArtifacts, { + msg: 'Saving artifacts', + id: 'lh:assetSaver:saveArtifacts', + }), loadArtifacts, saveAssets, prepareAssets, diff --git a/lighthouse-core/lib/console-quieter.js b/lighthouse-core/lib/console-quieter.js index a3de9ed19d97..caaf092fe54f 100644 --- a/lighthouse-core/lib/console-quieter.js +++ b/lighthouse-core/lib/console-quieter.js @@ -7,9 +7,9 @@ /* eslint-disable no-console */ -const log = require('lighthouse-logger'); +const log = require('../lib/log'); -/** @type {Array<{type: 'log'|'warn'|'error', args: any[], prefix: string}>} */ +/** @type {Array<{type: 'log'|'warn'|'error', args: [any, ...any[]], prefix: string}>} */ let _logs = []; class ConsoleQuieter { @@ -17,15 +17,15 @@ class ConsoleQuieter { static mute(opts) { _logs = _logs || []; - /** @param {any[]} args */ + /** @param {[any, ...any[]]} args */ console.log = function(...args) { _logs.push({type: 'log', args, prefix: opts.prefix}); }; - /** @param {any[]} args */ + /** @param {[any, ...any[]]} args */ console.warn = function(...args) { _logs.push({type: 'warn', args, prefix: opts.prefix}); }; - /** @param {any[]} args */ + /** @param {[any, ...any[]]} args */ console.error = function(...args) { _logs.push({type: 'error', args, prefix: opts.prefix}); }; diff --git a/lighthouse-core/lib/i18n/i18n.js b/lighthouse-core/lib/i18n/i18n.js index 89c198a38ab5..80269fd33ec4 100644 --- a/lighthouse-core/lib/i18n/i18n.js +++ b/lighthouse-core/lib/i18n/i18n.js @@ -7,7 +7,7 @@ const path = require('path'); const isDeepEqual = require('lodash.isequal'); -const log = require('lighthouse-logger'); +const log = require('../log'); const MessageFormat = require('intl-messageformat').default; const MessageParser = require('intl-messageformat-parser'); const lookupClosestLocale = require('lookup-closest-locale'); diff --git a/lighthouse-core/lib/log.js b/lighthouse-core/lib/log.js new file mode 100644 index 000000000000..cbdd63976484 --- /dev/null +++ b/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'); diff --git a/lighthouse-core/lib/network-recorder.js b/lighthouse-core/lib/network-recorder.js index 4de1df7ffe4e..b494dbd35a7d 100644 --- a/lighthouse-core/lib/network-recorder.js +++ b/lighthouse-core/lib/network-recorder.js @@ -7,7 +7,7 @@ const NetworkRequest = require('./network-request'); const EventEmitter = require('events').EventEmitter; -const log = require('lighthouse-logger'); +const log = require('../lib/log'); const IGNORED_NETWORK_SCHEMES = ['data', 'ws']; diff --git a/lighthouse-core/lib/sentry.js b/lighthouse-core/lib/sentry.js index 9f49aae51e4f..daf731855d91 100644 --- a/lighthouse-core/lib/sentry.js +++ b/lighthouse-core/lib/sentry.js @@ -5,7 +5,7 @@ */ 'use strict'; -const log = require('lighthouse-logger'); +const log = require('../lib/log'); /** @typedef {import('raven').CaptureOptions} CaptureOptions */ /** @typedef {import('raven').ConstructorOptions} ConstructorOptions */ diff --git a/lighthouse-core/lib/traces/pwmetrics-events.js b/lighthouse-core/lib/traces/pwmetrics-events.js index 3fc0aa9facf7..6708a045830d 100644 --- a/lighthouse-core/lib/traces/pwmetrics-events.js +++ b/lighthouse-core/lib/traces/pwmetrics-events.js @@ -6,7 +6,7 @@ // @ts-nocheck 'use strict'; -const log = require('lighthouse-logger'); +const log = require('../log'); // TODO: rework this file to not need this function // see https://github.com/GoogleChrome/lighthouse/pull/5101/files#r186168840 diff --git a/lighthouse-core/runner.js b/lighthouse-core/runner.js index 83d84b8fb732..8bfbd3bf3c5c 100644 --- a/lighthouse-core/runner.js +++ b/lighthouse-core/runner.js @@ -10,7 +10,7 @@ const Driver = require('./gather/driver.js'); const GatherRunner = require('./gather/gather-runner'); const ReportScoring = require('./scoring'); const Audit = require('./audits/audit'); -const log = require('lighthouse-logger'); +const log = require('./lib/log'); const i18n = require('./lib/i18n/i18n.js'); const assetSaver = require('./lib/asset-saver'); const fs = require('fs'); @@ -213,9 +213,6 @@ class Runner { * @return {Promise>} */ static async _runAudits(settings, audits, artifacts, runWarnings) { - const status = {msg: 'Analyzing and running audits...', id: 'lh:runner:auditing'}; - log.time(status); - if (artifacts.settings) { const overrides = { locale: undefined, @@ -246,7 +243,6 @@ class Runner { auditResults.push(auditResult); } - log.timeEnd(status); return auditResults; } @@ -261,12 +257,6 @@ class Runner { */ static async _runAudit(auditDefn, artifacts, sharedAuditContext) { const audit = auditDefn.implementation; - const status = { - msg: `Evaluating: ${i18n.getFormatted(audit.meta.title, 'en-US')}`, - id: `lh:audit:${audit.meta.id}`, - }; - log.time(status); - let auditResult; try { // Return an early error if an artifact required for the audit is missing or an error. @@ -326,7 +316,6 @@ class Runner { auditResult = Audit.generateErrorAuditResult(audit, errorMessage); } - log.timeEnd(status); return auditResult; } @@ -462,4 +451,16 @@ class Runner { } } +log.timeDecorateClass(Runner, { + _runAudit: { + msg: auditDefn => + `Evaluating: ${i18n.getFormatted(auditDefn.implementation.meta.title, 'en-US')}`, + id: auditDefn => `lh:audit:${auditDefn.implementation.meta.id}`, + }, + _runAudits: { + msg: 'Analyzing and running audits...', + id: 'lh:runner:auditing', + }, +}); + module.exports = Runner; diff --git a/lighthouse-core/test/config/config-test.js b/lighthouse-core/test/config/config-test.js index 48c08cd1eb32..34d4e1cbb8b0 100644 --- a/lighthouse-core/test/config/config-test.js +++ b/lighthouse-core/test/config/config-test.js @@ -9,7 +9,7 @@ const Config = require('../../config/config'); const assert = require('assert'); const path = require('path'); const defaultConfig = require('../../config/default-config.js'); -const log = require('lighthouse-logger'); +const log = require('../../lib/log'); const Gatherer = require('../../gather/gatherers/gatherer'); const Audit = require('../../audits/audit'); const i18n = require('../../lib/i18n/i18n.js'); diff --git a/lighthouse-logger/helpers.d.ts b/lighthouse-logger/helpers.d.ts new file mode 100644 index 000000000000..1460876f1baa --- /dev/null +++ b/lighthouse-logger/helpers.d.ts @@ -0,0 +1,8 @@ +/** + * @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 ArgumentTypes = F extends (...args: infer A) => any ? A : never; +export type IsFunction = T extends Function ? T : never; diff --git a/lighthouse-logger/index.js b/lighthouse-logger/index.js index 041cf2a72e19..4eb7bda5be99 100644 --- a/lighthouse-logger/index.js +++ b/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('./helpers').ArgumentTypes} ArgumentTypes + */ + +/** + * @template T + * @typedef {import('./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 {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,16 +93,27 @@ 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) { @@ -67,8 +121,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 +132,7 @@ class 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} 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>>}} 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); + } + } + + /** + * @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; diff --git a/lighthouse-logger/package.json b/lighthouse-logger/package.json index 0f985fe4f961..7e40bab1a9e5 100644 --- a/lighthouse-logger/package.json +++ b/lighthouse-logger/package.json @@ -5,5 +5,8 @@ "dependencies": { "debug": "^2.6.8", "marky": "^1.2.0" + }, + "devDependencies": { + "@types/debug": "^0.0.31" } } diff --git a/lighthouse-logger/test/index-test.js b/lighthouse-logger/test/index-test.js new file mode 100644 index 000000000000..a035b084f24a --- /dev/null +++ b/lighthouse-logger/test/index-test.js @@ -0,0 +1,152 @@ +/** + * @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 */ +/* eslint-disable no-invalid-this */ + +const assert = require('assert'); +const log = require('..'); + +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('retains this binding', () => { + const object = new function() { + this.value = 'works'; + this.getValue = () => { + return this.value; + }; + }; + const fn = object.getValue; + const decoratedFn = log.timeDecorate(fn, { + msg: 'msg', + id: 'id', + }); + assert.equal(decoratedFn(), 'works'); + }); + + 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'); + }); + + it('scrubs decorator from trace', () => { + const fn = () => { + throw new Error('test error'); + }; + const decoratedFn = log.timeDecorate(fn, { + msg: 'test', + }); + let sawError = false; + try { + decoratedFn(); + } catch (err) { + assert.ok(!err.stack.includes('timeDecoratedFn')); + sawError = true; + } + assert.ok(sawError); + }); + + it('scrubs decorator from trace, async', async () => { + const fn = async () => { + throw new Error('test error'); + }; + const decoratedFn = log.timeDecorate(fn, { + msg: 'test', + }); + let sawError = false; + await decoratedFn().catch(err => { + assert.ok(!err.stack.includes('timeDecoratedFn')); + sawError = true; + }); + assert.ok(sawError); + }); +}); + +describe('Log.timeDecorateClass', function() { + 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/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 3450f925e17e..a74746bb25ad 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", 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/lighthouse-logger/index.d.ts b/types/lighthouse-logger/index.d.ts deleted file mode 100644 index f3f290a6c215..000000000000 --- a/types/lighthouse-logger/index.d.ts +++ /dev/null @@ -1,26 +0,0 @@ -/** - * @license Copyright 2017 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. - */ - -declare module 'lighthouse-logger' { - interface Status { - msg: string; - id: string; - args?: any[]; - } - export function setLevel(level: string): void; - export function formatProtocol(prefix: string, data: Object, level?: string): void; - export function log(title: string, ...args: any[]): void; - export function warn(title: string, ...args: any[]): void; - export function error(title: string, ...args: any[]): void; - export function verbose(title: string, ...args: any[]): void; - export function time(status: Status, level?: string): void; - export function timeEnd(status: Status, level?: string): void; - export function reset(): string; - /** Retrieves and clears all stored time entries */ - export function takeTimeEntries(): PerformanceEntry[]; - export function getTimeEntries(): PerformanceEntry[]; - export var events: import('events').EventEmitter; -}