core(driver): handle promise rejections from sendCommand #6739

exterkamp · 2018-12-06T19:59:04Z

Summary
As of #6347 driver's sendCommand can reject its Promise if the underlying protocol command times out. This new rejection path isn't handled in some invocations of sendCommand leading to unhandled promise rejections. This would present as us "missing" a PROTOCOL_TIMEOUT in LR, leading to the graceful resolve fix push; however, upon investigation, the cause of missing those timeouts was the timeouts causing an unhandled promise rejection which freaks out LR!
This should catch all unhandled promise rejections as of right now. I did a lot of testing to try to track down unhandled promise rejection, but I might have missed some, so if you find any lmk.

Related Issues/PRs

makes core(gather-runner): gracefully recover from fatal errors #6671 irrelevant
runTimeError exists when there are NO_ERRORs #6336 doesn't fix this, but it does help LR's story and removes the need for more error handling, because the errors are handled now!

exterkamp · 2018-12-06T20:00:21Z

lighthouse-core/gather/driver.js

@@ -893,8 +894,8 @@ class Driver {
    // These can 'race' and that's OK.
    // We don't want to wait for Page.navigate's resolution, as it can now
    // happen _after_ onload: https://crbug.com/768961
-    this.sendCommand('Page.enable');
-    this.sendCommand('Emulation.setScriptExecutionDisabled', {value: disableJS});
+    await this.sendCommand('Page.enable');


Is it okay to await these? The comments above them talk about racing like this might be purposefully not-awaited.

Bug is marked as fixed now. If it truly is, can you also remove the comments?

the big bug was definitely about not awaiting Page.navigate, but why are we needing to await these? is it just about unhandled rejections?

could still timeout on any protocol command. what happens in the underlying connection dies? we should avoid any possible unhandled rejection.

But await each command isn't the only way to avoid unhandled rejections here. wdyt of just tacking a catch on Page.enable, or combining the two commands like this:

await Promise.all([ this.sendCommand('Page.enable'), this.sendCommand('Emulation.setScriptExecutionDisabled', {value: disableJS}), ])

so that it's one less event loop iteration ?

right I'm onboard with that, but I'm asking because there are then other things we might try instead of serialling awaiting like this._sendAndSilentlyIgnoreErrors or something :)

It looks like we used to be just fine waiting on these in sequence though, and the Page.navigate change just moved all of 'em to be together, so we don't need to go crazy avoiding the await #3413

I'm a tad spooked by this given that it was a real nasty bug to hunt down, but I think this makes sense if the bug really is fixed. +1 to removing the comments if we're making this change

_innerSendCommand is specifically for when you don't want to timeout.

I'm not sure if _innerSendCommand can ever reject. You could try setting a breakpoint just before, then kill Chrome, then hit play, and see what happens ... But if I read the code correctly for how the connection works, it won't ever result in a rejected promise - just a stalled one.

~~Or I guess sendCommand is never the real problem it's always the PROTOCOL_TIMEOUT that's the real problem?~~

You guys beat me to the punch you're already on it 👍 😄

maybe I'm not following the conversation correctly here, but _innerSendCommand can reject via connection:

lighthouse/lighthouse-core/gather/connections/connection.js

Lines 120 to 124 in 9ebf069

return callback.resolve(Promise.resolve().then(_ => {

if (object.error) {

log.formatProtocol('method <= browser ERR', {method: callback.method}, 'error');

throw LHError.fromProtocolMessage(callback.method, object.error);

}

(throwing inside Promise.resolve().then(_ => {/* throw */}) rejects it, then callback.resolve() with a rejected promise rejects as well. We could probably make that a lot more understandable with an explicit callback.resolve or callback.reject, as well as using an async function for the inner part)

so do we want to add an empty catch to the this._innerSendCommand('Page.navigate', {url}); line? Or are we assuming it's so rare that it's ok that a unhandledRejection listener can catch it?

Since it seems like this never happens, should we just let sleeping dragons lie?

connorjclark · 2018-12-06T20:02:15Z

lighthouse-core/gather/driver.js

@@ -893,8 +894,8 @@ class Driver {
    // These can 'race' and that's OK.
    // We don't want to wait for Page.navigate's resolution, as it can now
    // happen _after_ onload: https://crbug.com/768961
-    this.sendCommand('Page.enable');
-    this.sendCommand('Emulation.setScriptExecutionDisabled', {value: disableJS});
+    await this.sendCommand('Page.enable');


Bug is marked as fixed now. If it truly is, can you also remove the comments?

connorjclark · 2018-12-06T20:06:04Z

lighthouse-core/gather/driver.js

    }

    /** @type {(() => void)} */
    let cancel = () => {
      throw new Error('_waitForCPUIdle.cancel() called before it was defined');
    };
    const promise = new Promise((resolve, reject) => {
-      checkForQuiet(this, resolve);
+      checkForQuiet(this, resolve, reject);


what happens if reject is called twice? is that possible here?

IIRC, once a promise has been resolved/rejected all further calls will be noops

lighthouse-core/gather/driver.js

patrickhulce · 2018-12-06T20:22:11Z

lighthouse-core/gather/driver.js

@@ -893,8 +894,8 @@ class Driver {
    // These can 'race' and that's OK.
    // We don't want to wait for Page.navigate's resolution, as it can now
    // happen _after_ onload: https://crbug.com/768961
-    this.sendCommand('Page.enable');
-    this.sendCommand('Emulation.setScriptExecutionDisabled', {value: disableJS});
+    await this.sendCommand('Page.enable');


the big bug was definitely about not awaiting Page.navigate, but why are we needing to await these? is it just about unhandled rejections?

lighthouse-core/gather/driver.js

patrickhulce · 2018-12-06T22:49:50Z

lighthouse-core/gather/driver.js

@@ -893,8 +894,8 @@ class Driver {
    // These can 'race' and that's OK.
    // We don't want to wait for Page.navigate's resolution, as it can now
    // happen _after_ onload: https://crbug.com/768961
-    this.sendCommand('Page.enable');
-    this.sendCommand('Emulation.setScriptExecutionDisabled', {value: disableJS});
+    await this.sendCommand('Page.enable');


~~Or I guess sendCommand is never the real problem it's always the PROTOCOL_TIMEOUT that's the real problem?~~

You guys beat me to the punch you're already on it 👍 😄

brendankenny

#3413 also provides a repro step. Updated for the current cli flags, that would be yarn start ----emulated-form-factor=none --throttling-method=provided http://example.com --verbose, run against this PR and not seeing a long timeout pause.

However the main solution from #3413 seems to just be not waiting on Page.navigate. This still doesn't do that, so that shouldn't be a problem even if the underlying crbug isn't actually fixed.

lighthouse-core/gather/driver.js

brendankenny · 2018-12-10T22:16:53Z

lighthouse-core/gather/driver.js

@@ -893,8 +894,8 @@ class Driver {
    // These can 'race' and that's OK.
    // We don't want to wait for Page.navigate's resolution, as it can now
    // happen _after_ onload: https://crbug.com/768961
-    this.sendCommand('Page.enable');
-    this.sendCommand('Emulation.setScriptExecutionDisabled', {value: disableJS});
+    await this.sendCommand('Page.enable');


so do we want to add an empty catch to the this._innerSendCommand('Page.navigate', {url}); line? Or are we assuming it's so rare that it's ok that a unhandledRejection listener can catch it?

lighthouse-core/gather/driver.js

brendankenny · 2018-12-11T02:02:11Z

lighthouse-core/gather/driver.js

-    this.sendCommand('Page.enable');
-    this.sendCommand('Emulation.setScriptExecutionDisabled', {value: disableJS});
+    await this.sendCommand('Page.enable');
+    await this.sendCommand('Emulation.setScriptExecutionDisabled', {value: disableJS});
    // No timeout needed for Page.navigate. See #6413.
    this._innerSendCommand('Page.navigate', {url});


ok, after talking this through for a little while, we think we do want to incorporate the Page.navigate errors into the promise chain. It's a little ugly, so if anyone has any other structure ideas, please chime in :)

Basically it would be something like

const waitforPageNavigateCmd = this._innerSendCommand('Page.navigate', {url}); // ... let pageWaiter = Promise.resolve(); if (waitForNavigated) { pageWaiter = this._waitForFrameNavigated(); } else if (waitForLoad) { // ... pageWaiter = this._waitForFullyLoaded(/* ... */); } await Promise.all([ waitforPageNavigateCmd, pageWaiter, ]);

If Page.navigate has no problem, as before it doesn't block or interfere with observing the page load

If Page.navigate throws, it wins the Promise.all with a rejection, which leads to lighthouse exit.

The main issue I see (besides reduced readability) is that we don't clean up the _waitForFullyLoaded machinery. This is a fatal error so it doesn't matter in most clients, but are we going to have to actually clean up to support when LH is run as a module?

also during error testing we discovered that _waitForFrameNavigated should probably also have a timeout instead of blindly waiting on the Page.frameNavigated event.

we discovered that _waitForFrameNavigated should probably also have a timeout

WDYT about having an option to this.once that does the timeout bit?

is that we don't clean up the _waitForFullyLoaded machinery

why don't we just await waitForPageNavigateCmd as the ultimate very last thing? the only thing we want to happen is get the errors into the chain, right? if we do it as the very last thing, then it can't prevent other cleanup

WDYT about having an option to this.once that does the timeout bit?

yeah, good idea. We have at least one or two places we will happily wait forever on an event.

though the service worker one I'm thinking of only waits forever on about:blank, which adding an _waitForFrameNavigated timeout will fix :)

why don't we just await waitForPageNavigateCmd as the ultimate very last thing? the only thing we want to happen is get the errors into the chain, right? if we do it as the very last thing, then it can't prevent other cleanup

This would definitely be easier to follow.

The ordering will be a little wonky (I'd imagine a Page.navigate failure would end up usually failing on another command within _waitForFullyLoaded or by hitting the 45 second timeout), but ordering is already an issue with Promise.all() (and without cancelling _waitForFullyLoaded), and we've already all agreed that Page.navigate rarely if ever fails :)

brendankenny

just the nit, but otherwise LGTM!

lighthouse-core/gather/driver.js

brendankenny · 2018-12-12T19:44:33Z

lighthouse-core/gather/driver.js

-    }
-
-    if (waitForLoad) {
+    } else if (waitForLoad) {


patrickhulce · 2018-12-12T19:59:47Z

lighthouse-core/gather/driver.js

@@ -918,6 +911,9 @@ class Driver {
          maxWaitMs);
    }

+    // Awaiting so that errors can be properly processed.


nit: while this comment makes total sense in the context of this PR, I can definitely see myself coming back in a year and being like "what?" maybe a link to this PR or a tad more explanation?

good call. Maybe even just something like // Bring any 'Page.navigate' errors back into the promise chain. and a link back here.

The comment above the Page.navigate command isn't terribly helpful either, but I don't have a great suggestion :)

patrickhulce

LGTM % nit!

patrickhulce · 2018-12-12T20:00:51Z

lighthouse-core/gather/driver.js

@@ -918,6 +911,9 @@ class Driver {
          maxWaitMs);
    }

+    // Awaiting so that errors can be properly processed.
+    await waitforPageNavigateCmd;


there's nothing in _endNetworkStatusMonitoring we need, right?

there's nothing in _endNetworkStatusMonitoring we need, right?

it returns the finalUrl after redirects, which is used for updating passContext (and eventually the artifact).

A little too convoluted but somewhat difficult to fix since networkRecords don't entirely exist by that point.

Handle promise rejections from SendCommand.

55165e8

exterkamp requested review from paulirish, brendankenny, patrickhulce and connorjclark December 6, 2018 19:59

exterkamp commented Dec 6, 2018

View reviewed changes

exterkamp changed the title ~~core(driver): Handle promise rejections from sendCommand~~ core(driver): handle promise rejections from sendCommand Dec 6, 2018

exterkamp mentioned this pull request Dec 6, 2018

core(gather-runner): gracefully recover from fatal errors #6671

Closed

connorjclark reviewed Dec 6, 2018

View reviewed changes

patrickhulce reviewed Dec 6, 2018

View reviewed changes

Moved checkForQuiet catch to outside function. Thx Patrick!

c5ae03e

exterkamp mentioned this pull request Dec 6, 2018

runTimeError exists when there are NO_ERRORs #6336

Closed

patrickhulce suggested changes Dec 6, 2018

View reviewed changes

Use Promise.resolve() instead of resolve().

3d64d5d

brendankenny reviewed Dec 10, 2018

View reviewed changes

exterkamp added 3 commits December 10, 2018 16:17

Brendan's async refactor suggestion!

773e4f7

Removed old comments.

ab932b4

I got overzealous in my changes.

85bda02

brendankenny reviewed Dec 11, 2018

View reviewed changes

Awaited Page.navigate and cleaned up if-else.

76a4046

brendankenny approved these changes Dec 12, 2018

View reviewed changes

patrickhulce reviewed Dec 12, 2018

View reviewed changes

patrickhulce approved these changes Dec 12, 2018

View reviewed changes

Comment nits.

b1fd5b6

brendankenny merged commit acd6c93 into master Dec 13, 2018

brendankenny deleted the handle-protocol-rejections branch December 13, 2018 02:02

connorjclark mentioned this pull request Dec 18, 2018

INSECURE error not working as expected #6595

Closed

This was referenced Dec 19, 2018

core: produce LHR when error is thrown during gather-runner #6330

Closed

Extension Error: INSECURE_DOCUMENT_REQUEST #6809

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

core(driver): handle promise rejections from sendCommand #6739

core(driver): handle promise rejections from sendCommand #6739

exterkamp commented Dec 6, 2018

exterkamp Dec 6, 2018

connorjclark Dec 6, 2018

patrickhulce Dec 6, 2018

connorjclark Dec 6, 2018

patrickhulce Dec 6, 2018

connorjclark Dec 6, 2018 •

edited

Loading

patrickhulce Dec 6, 2018 •

edited

Loading

brendankenny Dec 10, 2018

brendankenny Dec 10, 2018

exterkamp Dec 11, 2018

connorjclark Dec 6, 2018

connorjclark Dec 6, 2018

patrickhulce Dec 6, 2018

patrickhulce Dec 6, 2018

patrickhulce Dec 6, 2018 •

edited

Loading

brendankenny left a comment

brendankenny Dec 10, 2018

brendankenny Dec 11, 2018

brendankenny Dec 11, 2018 •

edited

Loading

patrickhulce Dec 11, 2018

patrickhulce Dec 11, 2018

brendankenny Dec 11, 2018

brendankenny Dec 11, 2018

brendankenny Dec 11, 2018

brendankenny left a comment

brendankenny Dec 12, 2018

patrickhulce Dec 12, 2018

brendankenny Dec 12, 2018

patrickhulce left a comment

patrickhulce Dec 12, 2018

brendankenny Dec 12, 2018

	return callback.resolve(Promise.resolve().then(_ => {
	if (object.error) {
	log.formatProtocol('method <= browser ERR', {method: callback.method}, 'error');
	throw LHError.fromProtocolMessage(callback.method, object.error);
	}

core(driver): handle promise rejections from sendCommand #6739

core(driver): handle promise rejections from sendCommand #6739

Conversation

exterkamp commented Dec 6, 2018

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

connorjclark Dec 6, 2018 • edited Loading

Choose a reason for hiding this comment

patrickhulce Dec 6, 2018 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

patrickhulce Dec 6, 2018 • edited Loading

Choose a reason for hiding this comment

brendankenny left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

brendankenny Dec 11, 2018 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

brendankenny left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

patrickhulce left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

connorjclark Dec 6, 2018 •

edited

Loading

patrickhulce Dec 6, 2018 •

edited

Loading

patrickhulce Dec 6, 2018 •

edited

Loading

brendankenny Dec 11, 2018 •

edited

Loading