From fafc3150d797c0aa22a1bb6bfe2df46210093f8c Mon Sep 17 00:00:00 2001 From: Connor Clark Date: Fri, 19 Oct 2018 14:29:58 -0700 Subject: [PATCH 1/4] core: add timeout to all protocol commands (#6296) --- lighthouse-core/gather/driver.js | 145 ++++++++++----------- lighthouse-core/lib/lh-error.js | 14 +- lighthouse-core/lib/strings.js | 1 + lighthouse-core/test/gather/driver-test.js | 6 +- proto/lighthouse-result.proto | 4 + 5 files changed, 89 insertions(+), 81 deletions(-) diff --git a/lighthouse-core/gather/driver.js b/lighthouse-core/gather/driver.js index 34c886b9134e..39fdc86dcae4 100644 --- a/lighthouse-core/gather/driver.js +++ b/lighthouse-core/gather/driver.js @@ -29,6 +29,8 @@ const DEFAULT_PAUSE_AFTER_LOAD = 0; const DEFAULT_NETWORK_QUIET_THRESHOLD = 5000; // Controls how long to wait between longtasks before determining the CPU is idle, off by default const DEFAULT_CPU_QUIET_THRESHOLD = 0; +// Controls how long to wait for a response after sending a DevTools protocol command. +const DEFAULT_PROTOCOL_TIMEOUT = 5000; /** * @typedef {LH.Protocol.StrictEventEmitter} CrdpEventEmitter @@ -85,6 +87,12 @@ class Driver { * @private */ this._lastSecurityState = null; + + /** + * @type {number} + * @private + */ + this._protocolTimeout = DEFAULT_PROTOCOL_TIMEOUT; } static get traceCategories() { @@ -142,6 +150,13 @@ class Driver { return this.evaluateAsync(`(${pageFunctions.ultradumbBenchmarkString})()`); } + /** + * @param {number} timeout + */ + setProtocolTimeout(timeout) { + this._protocolTimeout = timeout; + } + /** * @return {Promise} */ @@ -255,8 +270,20 @@ class Driver { return Promise.resolve(); } } - - return this._connection.sendCommand(method, ...params); + return new Promise((resolve, reject) => { + const asyncTimeout = setTimeout((_ => { + const err = new LHError(LHError.errors.PROTOCOL_TIMEOUT); + err.message += ` Method: ${method}`; + reject(err); + }), this._protocolTimeout); + this._connection.sendCommand(method, ...params).then(result => { + clearTimeout(asyncTimeout); + resolve(result); + }).catch(err => { + clearTimeout(asyncTimeout); + reject(err); + }); + }); } /** @@ -306,61 +333,45 @@ class Driver { * @param {number|undefined} contextId * @return {Promise<*>} */ - _evaluateInContext(expression, contextId) { - return new Promise((resolve, reject) => { - // If this gets to 60s and it hasn't been resolved, reject the Promise. - const asyncTimeout = setTimeout( - (_ => reject(new Error('The asynchronous expression exceeded the allotted time of 60s'))), - 60000 - ); - - const evaluationParams = { - // We need to explicitly wrap the raw expression for several purposes: - // 1. Ensure that the expression will be a native Promise and not a polyfill/non-Promise. - // 2. Ensure that errors in the expression are captured by the Promise. - // 3. Ensure that errors captured in the Promise are converted into plain-old JS Objects - // so that they can be serialized properly b/c JSON.stringify(new Error('foo')) === '{}' - expression: `(function wrapInNativePromise() { - const __nativePromise = window.__nativePromise || Promise; - const URL = window.__nativeURL || window.URL; - return new __nativePromise(function (resolve) { - return __nativePromise.resolve() - .then(_ => ${expression}) - .catch(${pageFunctions.wrapRuntimeEvalErrorInBrowserString}) - .then(resolve); - }); - }())`, - includeCommandLineAPI: true, - awaitPromise: true, - returnByValue: true, - contextId, - }; - - this.sendCommand('Runtime.evaluate', evaluationParams).then(response => { - clearTimeout(asyncTimeout); - - if (response.exceptionDetails) { - // An error occurred before we could even create a Promise, should be *very* rare - return reject(new Error(`Evaluation exception: ${response.exceptionDetails.text}`)); - } - - // Protocol should always return a 'result' object, but it is sometimes undefined. See #6026. - if (response.result === undefined) { - return reject(new Error('Runtime.evaluate response did not contain a "result" object')); - } - - const value = response.result.value; + async _evaluateInContext(expression, contextId) { + const evaluationParams = { + // We need to explicitly wrap the raw expression for several purposes: + // 1. Ensure that the expression will be a native Promise and not a polyfill/non-Promise. + // 2. Ensure that errors in the expression are captured by the Promise. + // 3. Ensure that errors captured in the Promise are converted into plain-old JS Objects + // so that they can be serialized properly b/c JSON.stringify(new Error('foo')) === '{}' + expression: `(function wrapInNativePromise() { + const __nativePromise = window.__nativePromise || Promise; + const URL = window.__nativeURL || window.URL; + return new __nativePromise(function (resolve) { + return __nativePromise.resolve() + .then(_ => ${expression}) + .catch(${pageFunctions.wrapRuntimeEvalErrorInBrowserString}) + .then(resolve); + }); + }())`, + includeCommandLineAPI: true, + awaitPromise: true, + returnByValue: true, + contextId, + }; - if (value && value.__failedInBrowser) { - return reject(Object.assign(new Error(), value)); - } else { - resolve(value); - } - }).catch(err => { - clearTimeout(asyncTimeout); - reject(err); - }); - }); + const response = await this.sendCommand('Runtime.evaluate', evaluationParams); + if (response.exceptionDetails) { + // An error occurred before we could even create a Promise, should be *very* rare + return Promise.reject(new Error(`Evaluation exception: ${response.exceptionDetails.text}`)); + } + // Protocol should always return a 'result' object, but it is sometimes undefined. See #6026. + if (response.result === undefined) { + return Promise.reject( + new Error('Runtime.evaluate response did not contain a "result" object')); + } + const value = response.result.value; + if (value && value.__failedInBrowser) { + return Promise.reject(Object.assign(new Error(), value)); + } else { + return value; + } } /** @@ -860,27 +871,15 @@ class Driver { * Return the body of the response with the given ID. Rejects if getting the * body times out. * @param {string} requestId - * @param {number} [timeout] * @return {Promise} */ - getRequestContent(requestId, timeout = 1000) { + async getRequestContent(requestId) { requestId = NetworkRequest.getRequestIdForBackend(requestId); - return new Promise((resolve, reject) => { - // If this takes more than 1s, reject the Promise. - // Why? Encoding issues can lead to hanging getResponseBody calls: https://github.com/GoogleChrome/lighthouse/pull/4718 - const err = new LHError(LHError.errors.REQUEST_CONTENT_TIMEOUT); - const asyncTimeout = setTimeout((_ => reject(err)), timeout); - - this.sendCommand('Network.getResponseBody', {requestId}).then(result => { - clearTimeout(asyncTimeout); - // Ignoring result.base64Encoded, which indicates if body is already encoded - resolve(result.body); - }).catch(e => { - clearTimeout(asyncTimeout); - reject(e); - }); - }); + // Encoding issues may lead to hanging getResponseBody calls: https://github.com/GoogleChrome/lighthouse/pull/4718 + // driver.sendCommand will handle timeout after 5s. + const result = await this.sendCommand('Network.getResponseBody', {requestId}); + return result.body; } async listenForSecurityStateChanges() { diff --git a/lighthouse-core/lib/lh-error.js b/lighthouse-core/lib/lh-error.js index ae1d8dbf3646..dbaf2f426676 100644 --- a/lighthouse-core/lib/lh-error.js +++ b/lighthouse-core/lib/lh-error.js @@ -169,17 +169,19 @@ const ERRORS = { lhrRuntimeError: true, }, - // Protocol timeout failures - REQUEST_CONTENT_TIMEOUT: { - code: 'REQUEST_CONTENT_TIMEOUT', - message: strings.requestContentTimeout, - }, - // URL parsing failures INVALID_URL: { code: 'INVALID_URL', message: strings.urlInvalid, }, + + // Protocol timeout failures + PROTOCOL_TIMEOUT: { + code: 'PROTOCOL_TIMEOUT', + message: strings.protocolTimeout, + }, + + // Hey! When adding a new error type, update lighthouse-result.proto too. }; /** @type {Record} */ diff --git a/lighthouse-core/lib/strings.js b/lighthouse-core/lib/strings.js index 0b5c81edc013..377a4117e7e9 100644 --- a/lighthouse-core/lib/strings.js +++ b/lighthouse-core/lib/strings.js @@ -15,4 +15,5 @@ module.exports = { internalChromeError: `An internal Chrome error occurred. Please restart Chrome and try re-running Lighthouse.`, requestContentTimeout: 'Fetching resource content has exceeded the allotted time', urlInvalid: `The URL you have provided appears to be invalid.`, + protocolTimeout: `Waiting for DevTools protocol response has exceeded the allotted time.`, }; diff --git a/lighthouse-core/test/gather/driver-test.js b/lighthouse-core/test/gather/driver-test.js index dbbefe448e9d..aaa48af46148 100644 --- a/lighthouse-core/test/gather/driver-test.js +++ b/lighthouse-core/test/gather/driver-test.js @@ -110,6 +110,8 @@ connection.sendCommand = function(command, params) { } }; +driverStub.setProtocolTimeout(MAX_WAIT_FOR_PROTOCOL); + /* eslint-env jest */ describe('Browser Driver', () => { @@ -162,10 +164,10 @@ describe('Browser Driver', () => { }); it('throws if getRequestContent takes too long', () => { - return driverStub.getRequestContent('', MAX_WAIT_FOR_PROTOCOL).then(_ => { + return driverStub.getRequestContent('').then(_ => { assert.ok(false, 'long-running getRequestContent supposed to reject'); }, e => { - assert.equal(e.code, 'REQUEST_CONTENT_TIMEOUT'); + assert.equal(e.code, 'PROTOCOL_TIMEOUT'); }); }); diff --git a/proto/lighthouse-result.proto b/proto/lighthouse-result.proto index 7e8ba733246a..8ee8725f51ef 100644 --- a/proto/lighthouse-result.proto +++ b/proto/lighthouse-result.proto @@ -42,6 +42,10 @@ enum LighthouseError { PARSING_PROBLEM = 15; // The trace data failed to stream over the protocol. READ_FAILED = 16; + // Used when security error prevents page load. + INSECURE_DOCUMENT_REQUEST = 17; + // Used when security error prevents page load. + PROTOCOL_TIMEOUT = 18; } // The overarching Lighthouse Response object (LHR) From 0e70d6f26e6fe854a9387860bfc3a3cef268fb3b Mon Sep 17 00:00:00 2001 From: Connor Clark Date: Fri, 19 Oct 2018 17:09:05 -0700 Subject: [PATCH 2/4] setNextProtocolTimeout, lhRuntimeError --- lighthouse-core/gather/driver.js | 39 +++++++++++++--------- lighthouse-core/lib/lh-error.js | 1 + lighthouse-core/test/gather/driver-test.js | 4 +-- 3 files changed, 26 insertions(+), 18 deletions(-) diff --git a/lighthouse-core/gather/driver.js b/lighthouse-core/gather/driver.js index 39fdc86dcae4..7b1240f54977 100644 --- a/lighthouse-core/gather/driver.js +++ b/lighthouse-core/gather/driver.js @@ -92,7 +92,7 @@ class Driver { * @type {number} * @private */ - this._protocolTimeout = DEFAULT_PROTOCOL_TIMEOUT; + this._nextProtocolTimeout = DEFAULT_PROTOCOL_TIMEOUT; } static get traceCategories() { @@ -150,13 +150,6 @@ class Driver { return this.evaluateAsync(`(${pageFunctions.ultradumbBenchmarkString})()`); } - /** - * @param {number} timeout - */ - setProtocolTimeout(timeout) { - this._protocolTimeout = timeout; - } - /** * @return {Promise} */ @@ -255,14 +248,26 @@ class Driver { } } + /** + * NOTE: This can eventually be replaced when TypeScript + * resolves https://github.com/Microsoft/TypeScript/issues/5453. + * @param {number} timeout + */ + setNextProtocolTimeout(timeout) { + this._nextProtocolTimeout = timeout; + } + /** * Call protocol methods. + * To configure the timeout for the next call, use 'setNextProtocolTimeout'. * @template {keyof LH.CrdpCommands} C * @param {C} method - * @param {LH.CrdpCommands[C]['paramsType']} params, + * @param {LH.CrdpCommands[C]['paramsType']} params * @return {Promise} */ sendCommand(method, ...params) { + const timeout = this._nextProtocolTimeout; + this._nextProtocolTimeout = DEFAULT_PROTOCOL_TIMEOUT; const domainCommand = /^(\w+)\.(enable|disable)$/.exec(method); if (domainCommand) { const enable = domainCommand[2] === 'enable'; @@ -270,19 +275,20 @@ class Driver { return Promise.resolve(); } } - return new Promise((resolve, reject) => { + return new Promise(async (resolve, reject) => { const asyncTimeout = setTimeout((_ => { const err = new LHError(LHError.errors.PROTOCOL_TIMEOUT); err.message += ` Method: ${method}`; reject(err); - }), this._protocolTimeout); - this._connection.sendCommand(method, ...params).then(result => { + }), timeout); + try { + const result = await this._connection.sendCommand(method, ...params); clearTimeout(asyncTimeout); resolve(result); - }).catch(err => { + } catch (err) { clearTimeout(asyncTimeout); reject(err); - }); + } }); } @@ -356,6 +362,7 @@ class Driver { contextId, }; + this.setNextProtocolTimeout(60000); const response = await this.sendCommand('Runtime.evaluate', evaluationParams); if (response.exceptionDetails) { // An error occurred before we could even create a Promise, should be *very* rare @@ -871,13 +878,15 @@ class Driver { * Return the body of the response with the given ID. Rejects if getting the * body times out. * @param {string} requestId + * @param {number} timeout * @return {Promise} */ - async getRequestContent(requestId) { + async getRequestContent(requestId, timeout = 5000) { requestId = NetworkRequest.getRequestIdForBackend(requestId); // Encoding issues may lead to hanging getResponseBody calls: https://github.com/GoogleChrome/lighthouse/pull/4718 // driver.sendCommand will handle timeout after 5s. + this.setNextProtocolTimeout(timeout); const result = await this.sendCommand('Network.getResponseBody', {requestId}); return result.body; } diff --git a/lighthouse-core/lib/lh-error.js b/lighthouse-core/lib/lh-error.js index dbaf2f426676..2a09ba497de3 100644 --- a/lighthouse-core/lib/lh-error.js +++ b/lighthouse-core/lib/lh-error.js @@ -179,6 +179,7 @@ const ERRORS = { PROTOCOL_TIMEOUT: { code: 'PROTOCOL_TIMEOUT', message: strings.protocolTimeout, + lhrRuntimeError: true, }, // Hey! When adding a new error type, update lighthouse-result.proto too. diff --git a/lighthouse-core/test/gather/driver-test.js b/lighthouse-core/test/gather/driver-test.js index aaa48af46148..419ddd76005f 100644 --- a/lighthouse-core/test/gather/driver-test.js +++ b/lighthouse-core/test/gather/driver-test.js @@ -110,8 +110,6 @@ connection.sendCommand = function(command, params) { } }; -driverStub.setProtocolTimeout(MAX_WAIT_FOR_PROTOCOL); - /* eslint-env jest */ describe('Browser Driver', () => { @@ -164,7 +162,7 @@ describe('Browser Driver', () => { }); it('throws if getRequestContent takes too long', () => { - return driverStub.getRequestContent('').then(_ => { + return driverStub.getRequestContent('', MAX_WAIT_FOR_PROTOCOL).then(_ => { assert.ok(false, 'long-running getRequestContent supposed to reject'); }, e => { assert.equal(e.code, 'PROTOCOL_TIMEOUT'); From 368f7223c786353e5c6e15a5f8222b5331b81e3d Mon Sep 17 00:00:00 2001 From: Connor Clark Date: Fri, 19 Oct 2018 17:10:40 -0700 Subject: [PATCH 3/4] getRequestContent 1s --- lighthouse-core/gather/driver.js | 4 ++-- proto/lighthouse-result.proto | 2 +- 2 files changed, 3 insertions(+), 3 deletions(-) diff --git a/lighthouse-core/gather/driver.js b/lighthouse-core/gather/driver.js index 7b1240f54977..228188010f49 100644 --- a/lighthouse-core/gather/driver.js +++ b/lighthouse-core/gather/driver.js @@ -881,11 +881,11 @@ class Driver { * @param {number} timeout * @return {Promise} */ - async getRequestContent(requestId, timeout = 5000) { + async getRequestContent(requestId, timeout = 1000) { requestId = NetworkRequest.getRequestIdForBackend(requestId); // Encoding issues may lead to hanging getResponseBody calls: https://github.com/GoogleChrome/lighthouse/pull/4718 - // driver.sendCommand will handle timeout after 5s. + // driver.sendCommand will handle timeout after 1s. this.setNextProtocolTimeout(timeout); const result = await this.sendCommand('Network.getResponseBody', {requestId}); return result.body; diff --git a/proto/lighthouse-result.proto b/proto/lighthouse-result.proto index 8ee8725f51ef..6cf6cebea7a1 100644 --- a/proto/lighthouse-result.proto +++ b/proto/lighthouse-result.proto @@ -44,7 +44,7 @@ enum LighthouseError { READ_FAILED = 16; // Used when security error prevents page load. INSECURE_DOCUMENT_REQUEST = 17; - // Used when security error prevents page load. + // Used when protocol command times out. PROTOCOL_TIMEOUT = 18; } From 3e9c5389dde431065cf9825fac7f30996c94171c Mon Sep 17 00:00:00 2001 From: Connor Clark Date: Wed, 24 Oct 2018 11:40:29 -0700 Subject: [PATCH 4/4] mark timeout param as optional --- lighthouse-core/gather/driver.js | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/lighthouse-core/gather/driver.js b/lighthouse-core/gather/driver.js index 228188010f49..699371bcf178 100644 --- a/lighthouse-core/gather/driver.js +++ b/lighthouse-core/gather/driver.js @@ -878,7 +878,7 @@ class Driver { * Return the body of the response with the given ID. Rejects if getting the * body times out. * @param {string} requestId - * @param {number} timeout + * @param {number} [timeout] * @return {Promise} */ async getRequestContent(requestId, timeout = 1000) {