Repository: GoogleChrome/lighthouse (js)

Issue:
Add timeout to all protocol commands
Some commands already do this (see `getRequestContent` and `_evaluateInContext` in the driver). We could benefit from implementing a timeout for all commands.

where: `sendCommand` in `lighthouse-core/gather/connections/connection.js`

Would prevent issues like #6287


Pull request:
core: add timeout to all protocol commands
Fixes #6296

Patch:
diff --git a/lighthouse-core/gather/driver.js b/lighthouse-core/gather/driver.js
index 34c886b91..699371bcf 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<LH.CrdpEvents>} CrdpEventEmitter
@@ -85,6 +87,12 @@ class Driver {
      * @private
      */
     this._lastSecurityState = null;
+
+    /**
+     * @type {number}
+     * @private
+     */
+    this._nextProtocolTimeout = DEFAULT_PROTOCOL_TIMEOUT;
   }
 
   static get traceCategories() {
@@ -240,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<LH.CrdpCommands[C]['returnType']>}
    */
   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';
@@ -255,8 +275,21 @@ class Driver {
         return Promise.resolve();
       }
     }
-
-    return this._connection.sendCommand(method, ...params);
+    return new Promise(async (resolve, reject) => {
+      const asyncTimeout = setTimeout((_ => {
+        const err = new LHError(LHError.errors.PROTOCOL_TIMEOUT);
+        err.message += ` Method: ${method}`;
+        reject(err);
+      }), timeout);
+      try {
+        const result = await this._connection.sendCommand(method, ...params);
+        clearTimeout(asyncTimeout);
+        resolve(result);
+      } catch (err) {
+        clearTimeout(asyncTimeout);
+        reject(err);
+      }
+    });
   }
 
   /**
@@ -306,61 +339,46 @@ 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);
-      });
-    });
+    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
+      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;
+    }
   }
 
   /**
@@ -863,24 +881,14 @@ class Driver {
    * @param {number} [timeout]
    * @return {Promise<string>}
    */
-  getRequestContent(requestId, timeout = 1000) {
+  async getRequestContent(requestId, timeout = 1000) {
     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 1s.
+    this.setNextProtocolTimeout(timeout);
+    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 ae1d8dbf3..2a09ba497 100644
--- a/lighthouse-core/lib/lh-error.js
+++ b/lighthouse-core/lib/lh-error.js
@@ -169,17 +169,20 @@ 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,
+    lhrRuntimeError: true,
+  },
+
+  // Hey! When adding a new error type, update lighthouse-result.proto too.
 };
 
 /** @type {Record<keyof typeof ERRORS, LighthouseErrorDefinition>} */
diff --git a/lighthouse-core/lib/strings.js b/lighthouse-core/lib/strings.js
index 0b5c81edc..377a4117e 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-logger/index.js b/lighthouse-logger/index.js
index 4c6304a59..041cf2a72 100644
--- a/lighthouse-logger/index.js
+++ b/lighthouse-logger/index.js
@@ -52,6 +52,7 @@ class Emitter extends EventEmitter {
 
 const loggersByTitle = {};
 const loggingBufferColumns = 25;
+let level_;
 
 class Log {
   static _logToStdErr(title, argsArray) {
@@ -74,7 +75,11 @@ class Log {
     return log;
   }
 
+  /**
+   * @param {string} level
+   */
   static setLevel(level) {
+    level_ = level;
     switch (level) {
       case 'silent':
         debug.enable('-*');
@@ -106,6 +111,13 @@ class Log {
     Log._logToStdErr(`${prefix}:${level || ''}`, [method, snippet]);
   }
 
+  /**
+   * @return {boolean}
+   */
+  static isVerbose() {
+    return level_ === 'verbose';
+  }
+
   static time({msg, id, args = []}, level = 'log') {
     marky.mark(id);
     Log[level]('status', msg, ...args);
@@ -219,10 +231,11 @@ class Log {
 }
 
 Log.events = new Emitter();
-Log.takeTimeEntries = _ => {
+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 cbe4a8275..0f985fe4f 100644
--- a/lighthouse-logger/package.json
+++ b/lighthouse-logger/package.json
@@ -1,6 +1,6 @@
 {
   "name": "lighthouse-logger",
-  "version": "1.1.0",
+  "version": "1.2.0",
   "license": "Apache-2.0",
   "dependencies": {
     "debug": "^2.6.8",
diff --git a/proto/lighthouse-result.proto b/proto/lighthouse-result.proto
index 58c595087..8c93bdc20 100644
--- a/proto/lighthouse-result.proto
+++ b/proto/lighthouse-result.proto
@@ -43,6 +43,10 @@ enum LighthouseError {
   PARSING_PROBLEM = 14;
   // The trace data failed to stream over the protocol.
   READ_FAILED = 15;
+  // Used when security error prevents page load.
+  INSECURE_DOCUMENT_REQUEST = 16;
+  // Used when protocol command times out.
+  PROTOCOL_TIMEOUT = 17;
 }
 
 // The overarching Lighthouse Response object (LHR)


Test patch:
diff --git a/lighthouse-core/test/gather/driver-test.js b/lighthouse-core/test/gather/driver-test.js
index dbbefe448..419ddd760 100644
--- a/lighthouse-core/test/gather/driver-test.js
+++ b/lighthouse-core/test/gather/driver-test.js
@@ -165,7 +165,7 @@ describe('Browser Driver', () => {
     return driverStub.getRequestContent('', MAX_WAIT_FOR_PROTOCOL).then(_ => {
       assert.ok(false, 'long-running getRequestContent supposed to reject');
     }, e => {
-      assert.equal(e.code, 'REQUEST_CONTENT_TIMEOUT');
+      assert.equal(e.code, 'PROTOCOL_TIMEOUT');
     });
   });