New navigation flow doesn't exit test with existing browser.

[pmeenan]

FAQ

• Yes, my issue is not about variability or throttling.
• Yes, my issue is not about a specific accessibility audit (file with axe-core instead).

URL

https://www.webpagetest.org/

What happened?

Running lighthouse@next integrated with WebPageTest cause the lighthouse run to timeout. Lighthouse completed but didn't exit the process after saving the JSON.

15:23:33.939 - lighthouse "https://www.webpagetest.org/" --channel wpt --enable-error-reporting --max-wait-for-load 80000 --port 9223 --output html --output json --output-path "/home/pmeenan/wptagent/work/ubuntu-192.168.10.50/230208_ZiEK_1.1.0/lighthouse.json" --throttling-method provided --verbose --save-assets --skip-audits screenshot-thumbnails,final-screenshot,full-page-screenshot --form-factor desktop --screenEmulation.disabled --chrome-flags="--user-agent='Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML like Gecko) Chrome/110.0.0.0 Safari/537.36 PTST/230208.231544'"
15:23:34.494 - Wed, 08 Feb 2023 23:23:34 GMT LH:status:verbose Initialize config
15:23:34.534 - Wed, 08 Feb 2023 23:23:34 GMT LH:status:verbose Resolve artifact definitions
15:23:34.603 - Wed, 08 Feb 2023 23:23:34 GMT LH:statusEnd:verbose Resolve artifact definitions
15:23:34.603 - Wed, 08 Feb 2023 23:23:34 GMT LH:status:verbose Resolve navigation definitions
15:23:34.604 - Wed, 08 Feb 2023 23:23:34 GMT LH:statusEnd:verbose Resolve navigation definitions
15:23:34.896 - Wed, 08 Feb 2023 23:23:34 GMT LH:statusEnd:verbose Initialize config
15:23:34.897 - Wed, 08 Feb 2023 23:23:34 GMT LH:status:verbose Gather phase
15:23:34.981 - Wed, 08 Feb 2023 23:23:34 GMT LH:status Connecting to browser
15:23:34.988 - Wed, 08 Feb 2023 23:23:34 GMT LH:target-manager:verbose target about:blank attached
...
15:24:07.327 - Wed, 08 Feb 2023 23:24:07 GMT LH:statusEnd:verbose Audit phase
15:24:07.377 - Wed, 08 Feb 2023 23:24:07 GMT LH:pwmetrics-events:verbose Sythesizing trace events for First Contentful Paint
15:24:07.378 - Wed, 08 Feb 2023 23:24:07 GMT LH:pwmetrics-events:verbose Sythesizing trace events for First Meaningful Paint
15:24:07.378 - Wed, 08 Feb 2023 23:24:07 GMT LH:pwmetrics-events:verbose Sythesizing trace events for Speed Index
15:24:07.378 - Wed, 08 Feb 2023 23:24:07 GMT LH:pwmetrics-events:verbose Sythesizing trace events for First Visual Change
15:24:07.378 - Wed, 08 Feb 2023 23:24:07 GMT LH:pwmetrics-events:verbose Sythesizing trace events for Visually Complete 100%
15:24:07.378 - Wed, 08 Feb 2023 23:24:07 GMT LH:pwmetrics-events:verbose Sythesizing trace events for Interactive
15:24:07.379 - Wed, 08 Feb 2023 23:24:07 GMT LH:pwmetrics-events:verbose Sythesizing trace events for End of Trace
15:24:07.379 - Wed, 08 Feb 2023 23:24:07 GMT LH:pwmetrics-events:verbose Sythesizing trace events for On Load
15:24:07.379 - Wed, 08 Feb 2023 23:24:07 GMT LH:pwmetrics-events:verbose Sythesizing trace events for DOM Content Loaded
15:24:07.387 - Wed, 08 Feb 2023 23:24:07 GMT LH:saveAssets devtools log saved to disk: /home/pmeenan/wptagent/work/ubuntu-192.168.10.50/230208_ZiEK_1.1.0/lighthouse-0.devtoolslog.json
15:24:07.525 - Wed, 08 Feb 2023 23:24:07 GMT LH:saveAssets trace file streamed to disk: /home/pmeenan/wptagent/work/ubuntu-192.168.10.50/230208_ZiEK_1.1.0/lighthouse-0.trace.json
15:24:07.528 - Wed, 08 Feb 2023 23:24:07 GMT LH:Printer html output written to /home/pmeenan/wptagent/work/ubuntu-192.168.10.50/230208_ZiEK_1.1.0/lighthouse.report.html
15:24:07.529 - Wed, 08 Feb 2023 23:24:07 GMT LH:CLI Protip: Run lighthouse with `--view` to immediately open the HTML report in your browser
15:24:07.531 - Wed, 08 Feb 2023 23:24:07 GMT LH:Printer json output written to /home/pmeenan/wptagent/work/ubuntu-192.168.10.50/230208_ZiEK_1.1.0/lighthouse.report.json
15:32:44.543 - Terminated
15:32:44.569 - Terminating all instances of node

I finally terminated the node process after waiting for ~8 minutes and the results were fine.

Running the same test with --legacy-navigation completed the test successfully.

15:34:29.521 - lighthouse "https://www.webpagetest.org/" --channel wpt --enable-error-reporting --legacy-navigation --max-wait-for-load 80000 --port 9223 --output html --output json --output-path "/home/pmeenan/wptagent/work/ubuntu-192.168.10.50/230208_Zi27_2.1.0/lighthouse.json" --throttling-method provided --verbose --save-assets --skip-audits screenshot-thumbnails,final-screenshot,full-page-screenshot --form-factor desktop --screenEmulation.disabled --chrome-flags="--user-agent='Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML like Gecko) Chrome/110.0.0.0 Safari/537.36 PTST/230208.231544'"
15:34:30.126 - Wed, 08 Feb 2023 23:34:30 GMT LH:CLI:warn Legacy navigation CLI is deprecated
15:34:30.127 - Wed, 08 Feb 2023 23:34:30 GMT LH:status:verbose Create config
15:34:30.171 - Wed, 08 Feb 2023 23:34:30 GMT LH:status:verbose Requiring gatherers
15:34:30.228 - Wed, 08 Feb 2023 23:34:30 GMT LH:statusEnd:verbose Requiring gatherers
15:34:30.229 - Wed, 08 Feb 2023 23:34:30 GMT LH:status:verbose Requiring audits
15:34:30.522 - Wed, 08 Feb 2023 23:34:30 GMT LH:statusEnd:verbose Requiring audits
15:34:30.522 - Wed, 08 Feb 2023 23:34:30 GMT LH:config:warn unrecognized audit in 'skipAudits': full-page-screenshot
15:34:30.536 - Wed, 08 Feb 2023 23:34:30 GMT LH:statusEnd:verbose Create config
...
15:35:03.897 - Wed, 08 Feb 2023 23:35:03 GMT LH:statusEnd:verbose Audit phase
15:35:03.930 - Wed, 08 Feb 2023 23:35:03 GMT LH:pwmetrics-events:verbose Sythesizing trace events for First Contentful Paint
15:35:03.931 - Wed, 08 Feb 2023 23:35:03 GMT LH:pwmetrics-events:verbose Sythesizing trace events for First Meaningful Paint
15:35:03.931 - Wed, 08 Feb 2023 23:35:03 GMT LH:pwmetrics-events:verbose Sythesizing trace events for Speed Index
15:35:03.931 - Wed, 08 Feb 2023 23:35:03 GMT LH:pwmetrics-events:verbose Sythesizing trace events for First Visual Change
15:35:03.932 - Wed, 08 Feb 2023 23:35:03 GMT LH:pwmetrics-events:verbose Sythesizing trace events for Visually Complete 100%
15:35:03.932 - Wed, 08 Feb 2023 23:35:03 GMT LH:pwmetrics-events:verbose Sythesizing trace events for Interactive
15:35:03.933 - Wed, 08 Feb 2023 23:35:03 GMT LH:pwmetrics-events:verbose Sythesizing trace events for End of Trace
15:35:03.933 - Wed, 08 Feb 2023 23:35:03 GMT LH:pwmetrics-events:verbose Sythesizing trace events for On Load
15:35:03.934 - Wed, 08 Feb 2023 23:35:03 GMT LH:pwmetrics-events:verbose Sythesizing trace events for DOM Content Loaded
15:35:03.936 - Wed, 08 Feb 2023 23:35:03 GMT LH:saveAssets devtools log saved to disk: /home/pmeenan/wptagent/work/ubuntu-192.168.10.50/230208_Zi27_2.1.0/lighthouse-0.devtoolslog.json
15:35:04.004 - Wed, 08 Feb 2023 23:35:04 GMT LH:saveAssets trace file streamed to disk: /home/pmeenan/wptagent/work/ubuntu-192.168.10.50/230208_Zi27_2.1.0/lighthouse-0.trace.json
15:35:04.008 - Wed, 08 Feb 2023 23:35:04 GMT LH:Printer html output written to /home/pmeenan/wptagent/work/ubuntu-192.168.10.50/230208_Zi27_2.1.0/lighthouse.report.html
15:35:04.009 - Wed, 08 Feb 2023 23:35:04 GMT LH:CLI Protip: Run lighthouse with `--view` to immediately open the HTML report in your browser
15:35:04.012 - Wed, 08 Feb 2023 23:35:04 GMT LH:Printer json output written to /home/pmeenan/wptagent/work/ubuntu-192.168.10.50/230208_Zi27_2.1.0/lighthouse.report.json
15:35:04.039 - Terminating all instances of node

The Terminating all instances of node log message is from WebPageTest as part of the cleanup after running lighthouse to make sure there are no stray node processes.

What did you expect?

I expected the lighthouse process to exit when the test completed.

What have you tried?

Using --legacy-navigation works correctly so the issue appears to be specific to the new navigation flow.

How were you running Lighthouse?

CLI

Lighthouse Version

9.5.0-dev.20230207

Chrome Version

110 (current stable)

Node Version

16.19.0

OS

Ubuntu 18.04

Relevant log output

No response

[connorjclark]

Thanks!

Confirmed the same, hangs on json output written.

Note: can use node core/scripts/manual-chrome-launcher.js (or npx chrome-debug if lighthouse is install globally) to quickly get a debug Chrome / port.

[connorjclark]

So with just setting --port, Lighthouse is going to launch the browser for you using that port. Sounds like you need to also set --hostname (setting to anything other than localhost will skip our own launching). Maybe that just got lost in translation in making the bug report?

But this is unrelated, there is a real problem here. @adamraine believes Puppeteer is not being shut down correctly on our end.

[pmeenan]

@connorjclark Guess it just happens to use the chrome instance I already launched since I already started it on the port that I pass in. If I past --hostname=127.0.0.1 will that work to prevent the attempted launching?

Does Lighthouse log the chrome command-line when it launches it or is one of my other params causing it to not try launching a new instance? I don't see anything about launching chrome in the log.

15:34:29.521 - lighthouse "https://www.webpagetest.org/" --channel wpt --enable-error-reporting --legacy-navigation --max-wait-for-load 80000 --port 9223 --output html --output json --output-path "/home/pmeenan/wptagent/work/ubuntu-192.168.10.50/230208_Zi27_2.1.0/lighthouse.json" --throttling-method provided --verbose --save-assets --skip-audits screenshot-thumbnails,final-screenshot,full-page-screenshot --form-factor desktop --screenEmulation.disabled --chrome-flags="--user-agent='Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML like Gecko) Chrome/110.0.0.0 Safari/537.36 PTST/230208.231544'"
15:34:30.126 - Wed, 08 Feb 2023 23:34:30 GMT LH:CLI:warn Legacy navigation CLI is deprecated
15:34:30.127 - Wed, 08 Feb 2023 23:34:30 GMT LH:status:verbose Create config
15:34:30.171 - Wed, 08 Feb 2023 23:34:30 GMT LH:status:verbose Requiring gatherers
15:34:30.228 - Wed, 08 Feb 2023 23:34:30 GMT LH:statusEnd:verbose Requiring gatherers
15:34:30.229 - Wed, 08 Feb 2023 23:34:30 GMT LH:status:verbose Requiring audits
15:34:30.522 - Wed, 08 Feb 2023 23:34:30 GMT LH:statusEnd:verbose Requiring audits
15:34:30.522 - Wed, 08 Feb 2023 23:34:30 GMT LH:config:warn unrecognized audit in 'skipAudits': full-page-screenshot
15:34:30.536 - Wed, 08 Feb 2023 23:34:30 GMT LH:statusEnd:verbose Create config
15:34:30.537 - Wed, 08 Feb 2023 23:34:30 GMT LH:status:verbose Gather phase
15:34:30.537 - Wed, 08 Feb 2023 23:34:30 GMT LH:listen for event =>:verbose Page.frameNavigated
15:34:30.538 - Wed, 08 Feb 2023 23:34:30 GMT LH:listen for event =>:verbose Runtime.executionContextDestroyed
15:34:30.538 - Wed, 08 Feb 2023 23:34:30 GMT LH:listen for event =>:verbose Target.attachedToTarget
15:34:30.538 - Wed, 08 Feb 2023 23:34:30 GMT LH:listen for event =>:verbose Page.frameNavigated
15:34:30.538 - Wed, 08 Feb 2023 23:34:30 GMT LH:status Connecting to browser
15:34:30.556 - Wed, 08 Feb 2023 23:34:30 GMT LH:statusEnd:verbose Connecting to browser
15:34:30.557 - Wed, 08 Feb 2023 23:34:30 GMT LH:status Resetting state with about:blank
15:34:30.557 - Wed, 08 Feb 2023 23:34:30 GMT LH:status Navigating to about:blank
15:34:30.558 - Wed, 08 Feb 2023 23:34:30 GMT LH:listen for event =>:verbose Page.frameNavigated
15:34:30.568 - Wed, 08 Feb 2023 23:34:30 GMT LH:Driver:verbose Page.enable
...

You can see the full raw log here (starts around 1/3 the way down - the first part is running the test for WebPageTest's logic.

[connorjclark]

Both 127.0.0.1 and localhost, and anything ending with .localhost will cause Lighthouse to not try to launch Chrome.

Guess it just happens to use the chrome instance I already launched since I already started it on the port that I pass in.

That seems to be what happens, I'd have guessed that a --port would just get ignored for an already launcher browser instance, but guess not.

Does Lighthouse log the chrome command-line when it launches it or is one of my other params causing it to not try launching a new instance? I don't see anything about launching chrome in the log.

Nope, because in this case it is falling into this early return:

https://github.com/GoogleChrome/chrome-launcher/blob/f64a7d891a98b411ae64f4f5a882c4d3e46221ef/src/chrome-launcher.ts#L254

We should add a log statement there saying we are re-using an existing connection, not launching a new browser.

[pmeenan]

Nope, because in this case it is falling into this early return:

https://github.com/GoogleChrome/chrome-launcher/blob/f64a7d891a98b411ae64f4f5a882c4d3e46221ef/src/chrome-launcher.ts#L254

I added --hostname 127.0.0.1 just to be safe but since I make sure the debugging port is available before starting lighthouse it sounds like it's already ok and doesn't actually launch another Chrome instance. Thanks for the pointer to where the launch code is.

[brendankenny]

@pmeenan unrelated to this issue, but you'll want --disable-full-page-screenshot as well. --skip-audits full-page-screenshot isn't going to do anything anymore (it's no longer an audit)