Lighthouse: Heroku kills the lighthouse process

Created on 8 Dec 2020 · 8Comments · Source: GoogleChrome/lighthouse

Provide the steps to reproduce

Simple Setup, NodeJS puppeteer & lightroom
Audit https://amazon.com

What is the current behavior?

Lightroom exit after audit without returning report

8:57:44 PM web.1 |  Website URL:  https://amazon.com
8:57:45 PM web.1 |  Tue, 08 Dec 2020 19:57:45 GMT config:warn IFrameElements gatherer requested, however no audit requires it.
8:57:45 PM web.1 |  Tue, 08 Dec 2020 19:57:45 GMT config:warn InspectorIssues gatherer requested, however no audit requires it.
8:57:45 PM web.1 |  Tue, 08 Dec 2020 19:57:45 GMT status Connecting to browser
8:57:45 PM web.1 |  Tue, 08 Dec 2020 19:57:45 GMT status Resetting state with about:blank
8:57:46 PM web.1 |  Tue, 08 Dec 2020 19:57:46 GMT status Benchmarking machine
8:57:46 PM web.1 |  Tue, 08 Dec 2020 19:57:46 GMT status Initializing…
8:57:46 PM web.1 |  Tue, 08 Dec 2020 19:57:46 GMT status Running defaultPass pass CSSUsage, JsUsage, ViewportDimensions, RuntimeExceptions, ConsoleMessages, AnchorElements, ImageElements, LinkElements, MetaElements, ScriptElements, IFrameElements, MainDocumentContent, AppCacheManifest, Doctype, DOMStats, OptimizedImages, PasswordInputsWithPreventedPaste, ResponseCompression, TagsBlockingFirstPaint, FontSize, EmbeddedContent, RobotsTxt, TapTargets, Accessibility, TraceElements, InspectorIssues, SourceMaps
8:57:46 PM web.1 |  Tue, 08 Dec 2020 19:57:46 GMT status Resetting state with about:blank
8:57:46 PM web.1 |  Tue, 08 Dec 2020 19:57:46 GMT status Setting up network for the pass trace
8:57:46 PM web.1 |  Tue, 08 Dec 2020 19:57:46 GMT status Cleaning browser cache
8:57:46 PM web.1 |  Tue, 08 Dec 2020 19:57:46 GMT status Beginning devtoolsLog and trace
8:57:46 PM web.1 |  Tue, 08 Dec 2020 19:57:46 GMT status Loading page & waiting for onload
8:57:57 PM web.1 |  Tue, 08 Dec 2020 19:57:57 GMT status Gathering in-page: CSSUsage
8:57:57 PM web.1 |  Tue, 08 Dec 2020 19:57:57 GMT status Gathering in-page: JsUsage
8:57:57 PM web.1 |  Tue, 08 Dec 2020 19:57:57 GMT status Gathering in-page: ViewportDimensions
8:57:57 PM web.1 |  Tue, 08 Dec 2020 19:57:57 GMT status Gathering in-page: RuntimeExceptions
8:57:57 PM web.1 |  Tue, 08 Dec 2020 19:57:57 GMT status Gathering in-page: ConsoleMessages
8:57:57 PM web.1 |  Tue, 08 Dec 2020 19:57:57 GMT status Gathering in-page: AnchorElements
8:57:57 PM web.1 |  Tue, 08 Dec 2020 19:57:57 GMT status Gathering in-page: ImageElements
8:57:57 PM web.1 |  Tue, 08 Dec 2020 19:57:57 GMT status Gathering in-page: LinkElements
8:57:57 PM web.1 |  Tue, 08 Dec 2020 19:57:57 GMT status Gathering in-page: MetaElements
8:57:57 PM web.1 |  Tue, 08 Dec 2020 19:57:57 GMT status Gathering in-page: ScriptElements
8:57:57 PM web.1 |  Tue, 08 Dec 2020 19:57:57 GMT status Gathering in-page: IFrameElements
8:57:57 PM web.1 |  Tue, 08 Dec 2020 19:57:57 GMT status Gathering in-page: MainDocumentContent
8:57:57 PM web.1 |  Tue, 08 Dec 2020 19:57:57 GMT status Gathering in-page: AppCacheManifest
8:57:57 PM web.1 |  Tue, 08 Dec 2020 19:57:57 GMT status Gathering in-page: Doctype
8:57:57 PM web.1 |  Tue, 08 Dec 2020 19:57:57 GMT status Gathering in-page: DOMStats
8:57:57 PM web.1 |  Tue, 08 Dec 2020 19:57:57 GMT status Gathering in-page: OptimizedImages
8:57:57 PM web.1 |  Tue, 08 Dec 2020 19:57:57 GMT status Gathering in-page: PasswordInputsWithPreventedPaste
8:57:57 PM web.1 |  Tue, 08 Dec 2020 19:57:57 GMT status Gathering in-page: ResponseCompression
8:57:57 PM web.1 |  Tue, 08 Dec 2020 19:57:57 GMT status Gathering in-page: TagsBlockingFirstPaint
8:57:57 PM web.1 |  Tue, 08 Dec 2020 19:57:57 GMT status Gathering in-page: FontSize
8:57:57 PM web.1 |  Tue, 08 Dec 2020 19:57:57 GMT status Gathering in-page: EmbeddedContent
8:57:57 PM web.1 |  Tue, 08 Dec 2020 19:57:57 GMT status Gathering in-page: RobotsTxt
8:57:57 PM web.1 |  Tue, 08 Dec 2020 19:57:57 GMT status Gathering in-page: TapTargets
8:57:57 PM web.1 |  Tue, 08 Dec 2020 19:57:57 GMT status Gathering in-page: Accessibility
8:57:57 PM web.1 |  Tue, 08 Dec 2020 19:57:57 GMT status Gathering in-page: TraceElements
8:57:57 PM web.1 |  Tue, 08 Dec 2020 19:57:57 GMT status Gathering in-page: InspectorIssues
8:57:57 PM web.1 |  Tue, 08 Dec 2020 19:57:57 GMT status Gathering in-page: SourceMaps
8:57:57 PM web.1 |  Tue, 08 Dec 2020 19:57:57 GMT status Gathering trace
8:57:59 PM web.1 |  Tue, 08 Dec 2020 19:57:59 GMT status Gathering devtoolsLog & network records
8:57:59 PM web.1 |  Tue, 08 Dec 2020 19:57:59 GMT status Gathering: CSSUsage
8:57:59 PM web.1 |  Tue, 08 Dec 2020 19:57:59 GMT status Gathering: JsUsage
8:57:59 PM web.1 |  Tue, 08 Dec 2020 19:57:59 GMT status Gathering: ViewportDimensions
8:57:59 PM web.1 |  Tue, 08 Dec 2020 19:57:59 GMT status Gathering: RuntimeExceptions
8:57:59 PM web.1 |  Tue, 08 Dec 2020 19:57:59 GMT status Gathering: ConsoleMessages
8:57:59 PM web.1 |  Tue, 08 Dec 2020 19:57:59 GMT status Gathering: AnchorElements
8:57:59 PM web.1 |  Tue, 08 Dec 2020 19:57:59 GMT status Gathering: ImageElements
8:57:59 PM web.1 |  Tue, 08 Dec 2020 19:57:59 GMT status Gathering: LinkElements
8:58:00 PM web.1 |  Tue, 08 Dec 2020 19:58:00 GMT status Gathering: MetaElements
8:58:00 PM web.1 |  Tue, 08 Dec 2020 19:58:00 GMT status Gathering: ScriptElements
8:58:00 PM web.1 |  Tue, 08 Dec 2020 19:58:00 GMT status Gathering: IFrameElements
8:58:00 PM web.1 |  Tue, 08 Dec 2020 19:58:00 GMT status Gathering: MainDocumentContent
8:58:00 PM web.1 |  Tue, 08 Dec 2020 19:58:00 GMT status Gathering: AppCacheManifest
8:58:00 PM web.1 |  Tue, 08 Dec 2020 19:58:00 GMT status Gathering: Doctype
8:58:00 PM web.1 |  Tue, 08 Dec 2020 19:58:00 GMT status Gathering: DOMStats
8:58:00 PM web.1 |  Tue, 08 Dec 2020 19:58:00 GMT status Gathering: OptimizedImages
8:58:02 PM web.1 |  Tue, 08 Dec 2020 19:58:02 GMT status Gathering: PasswordInputsWithPreventedPaste
8:58:02 PM web.1 |  Tue, 08 Dec 2020 19:58:02 GMT status Gathering: ResponseCompression
8:58:02 PM web.1 |  Tue, 08 Dec 2020 19:58:02 GMT status Gathering: TagsBlockingFirstPaint
8:58:02 PM web.1 |  Tue, 08 Dec 2020 19:58:02 GMT status Gathering: FontSize
8:58:02 PM web.1 |  Tue, 08 Dec 2020 19:58:02 GMT status Gathering: EmbeddedContent
8:58:02 PM web.1 |  Tue, 08 Dec 2020 19:58:02 GMT status Gathering: RobotsTxt
8:58:02 PM web.1 |  Tue, 08 Dec 2020 19:58:02 GMT status Gathering: TapTargets
8:58:03 PM web.1 |  Tue, 08 Dec 2020 19:58:03 GMT status Gathering: Accessibility
8:58:04 PM web.1 |  Tue, 08 Dec 2020 19:58:04 GMT status Gathering: TraceElements
8:58:04 PM web.1 |  Tue, 08 Dec 2020 19:58:04 GMT status Gathering: InspectorIssues
8:58:04 PM web.1 |  Tue, 08 Dec 2020 19:58:04 GMT status Gathering: SourceMaps
8:58:04 PM web.1 |  Tue, 08 Dec 2020 19:58:04 GMT status Running offlinePass pass ServiceWorker, Offline, StartUrl
8:58:04 PM web.1 |  Tue, 08 Dec 2020 19:58:04 GMT status Resetting state with about:blank
8:58:04 PM web.1 |  Tue, 08 Dec 2020 19:58:04 GMT status Setting up network for the pass trace
8:58:04 PM web.1 |  Tue, 08 Dec 2020 19:58:04 GMT status Beginning devtoolsLog and trace
8:58:04 PM web.1 |  Tue, 08 Dec 2020 19:58:04 GMT status Loading page & waiting for onload
8:58:05 PM web.1 |  Tue, 08 Dec 2020 19:58:05 GMT status Gathering in-page: ServiceWorker
8:58:05 PM web.1 |  Tue, 08 Dec 2020 19:58:05 GMT status Gathering in-page: Offline
8:58:05 PM web.1 |  Tue, 08 Dec 2020 19:58:05 GMT status Gathering in-page: StartUrl
8:58:05 PM web.1 |  Tue, 08 Dec 2020 19:58:05 GMT status Gathering devtoolsLog & network records
8:58:05 PM web.1 |  Tue, 08 Dec 2020 19:58:05 GMT status Gathering: ServiceWorker
8:58:05 PM web.1 |  Tue, 08 Dec 2020 19:58:05 GMT status Gathering: Offline
8:58:05 PM web.1 |  Tue, 08 Dec 2020 19:58:05 GMT status Gathering: StartUrl
8:58:05 PM web.1 |  Tue, 08 Dec 2020 19:58:05 GMT status Running redirectPass pass HTTPRedirect, HTMLWithoutJavaScript
8:58:05 PM web.1 |  Tue, 08 Dec 2020 19:58:05 GMT status Resetting state with about:blank
[DONE] Killing all processes with signal  SIGINT
8:58:05 PM web.1 Exited Successfully

What is the expected behavior?

Lightroom return report after audit

Environment Information

Source Code: https://github.com/floriannagel/puppeteer-lightroom/blob/main/app.js
Affected Channels:
Lighthouse version: 6.5.0
Chrome version: puppeteer 5.5.0 > 81.88.58
Node.js version: v12.18.2
Operating System: macOS 11.0.1

needs-more-info needs-priority

Source

floriannagel

All 8 comments

Do you have a specific question, or previous debugging you can share?

Maybe this will help you https://github.com/GoogleChrome/lighthouse/blob/master/docs/puppeteer.md

connorjclark on 8 Dec 2020

👍1

Specific question is, why is lighthouse quitting before the report is returned?

Puppeteer setup itself is working with a simple page loading and title extracting.

Tried a different lighthouse version: 6.2.0.
Same behavior every run. No change.

floriannagel on 8 Dec 2020

@floriannagel those logs indicate that Lighthouse process is being killed with SIGINT signal in the middle of the run by PM. Is there anything you've already researched that indicates why the process manager would decide to kill its child processes?

patrickhulce on 8 Dec 2020

👍1

The last two lines comes from the heruko logger. In direct Call from the Terminal the execution stops at "Resetting...".

Question what can I do to investigate the problem?
The code is linked in the issue!

Replaced peppeteer with chrome-launcher. Same

Even in a simple node container the problem is still there.

Misconfiguration? Do I oversee something?

I googled and searched in the issues for relevant information!

floriannagel on 8 Dec 2020

Running that script from node in a regular non-heroku docker container works just fine. I'm guessing heroku doesn't like something about Chrome+lighthouse? We can't really provide support for their environmental quirks though :/

I'd recommend turning on verbose logging, and trying to piece together smaller puppeteer debug sessions incrementally, or reaching out to heroku support for more information or logs on why it would kill the process. If you figure it out, commenting back here with the resolution might help future askers :)

patrickhulce on 8 Dec 2020

👀1

Sorry for the confusion! It's NOT a heroku problem 😅
It was just for demonstration. I try it from a vanilla node environment and no success.
In the verbose log there is no error whatsoever!
Tried an empty node:12 docker container with the same result (local run).

So the question is, how can I detect errors in the lighthouse run? The chrome/puppeteer run is working fine 😩

The execution stops after audit! If run it without lighthouse it's running through and gives the 202 response. With lighthouse it stops with no information about why...

floriannagel on 8 Dec 2020

Ah I see what you're saying now.

Appears to be bug in the version of Chromium bundled with puppeteer. Officially Lighthouse only supports Chrome stable, which runs that script just fine in docker.

$ docker run -it --entrypoint /bin/bash patrickhulce/lhci-client
$ wget https://raw.githubusercontent.com/floriannagel/puppeteer-lightroom/main/app.js
$ sed -i "s/.launch({/.launch({executablePath:'\/opt\/google\/chrome\/google-chrome',/" app.js
$ npm install lighthouse puppeteer
$ node app.js

[1208/222413.896327:ERROR:bad_message.cc(26)] Terminating renderer for bad IPC message, reason 205
[1208/222413.896380:FATAL:render_process_host_impl.cc(2900)] Check failed: false.
#0 0x55cc95f07b39 base::debug::CollectStackTrace()
#1 0x55cc95e7a4c3 base::debug::StackTrace::StackTrace()
#2 0x55cc95e8ac80 logging::LogMessage::~LogMessage()
#3 0x55cc95e8b84e logging::LogMessage::~LogMessage()
#4 0x55cc9474db47 content::RenderProcessHostImpl::ShutdownForBadMessage()
#5 0x55cc9472699e content::RenderFrameHostImpl::ValidateDidCommitParams()
#6 0x55cc94711c2e content::RenderFrameHostImpl::DidCommitNavigationInternal()
#7 0x55cc94711742 content::RenderFrameHostImpl::DidCommitNavigation()
#8 0x55cc947124c4 content::RenderFrameHostImpl::DidCommitPerNavigationMojoInterfaceNavigation()
#9 0x55cc94730922 base::internal::Invoker<>::RunOnce()
#10 0x55cc93f089d4 content::mojom::NavigationClient_CommitNavigation_ForwardToCallback::Accept()
#11 0x55cc965f34f1 mojo::InterfaceEndpointClient::HandleValidatedMessage()
#12 0x55cc96cb34f5 IPC::(anonymous namespace)::ChannelAssociatedGroupController::AcceptOnProxyThread()
#13 0x55cc96cb0df7 base::internal::Invoker<>::RunOnce()
#14 0x55cc95eca156 base::TaskAnnotator::RunTask()
#15 0x55cc95edb015 base::sequence_manager::internal::ThreadControllerWithMessagePumpImpl::DoWorkImpl()
#16 0x55cc95edad18 base::sequence_manager::internal::ThreadControllerWithMessagePumpImpl::DoWork()
#17 0x55cc95e91117 base::(anonymous namespace)::WorkSourceDispatch()
#18 0x7fe07fd15f2e g_main_context_dispatch
#19 0x7fe07fd161c8 (/usr/lib/x86_64-linux-gnu/libglib-2.0.so.0.5800.3+0x4e1c7)
#20 0x7fe07fd1625c g_main_context_iteration
#21 0x55cc95e90ee2 base::MessagePumpGlib::Run()
#22 0x55cc95edb7bd base::sequence_manager::internal::ThreadControllerWithMessagePumpImpl::Run()
#23 0x55cc95eb1fde base::RunLoop::Run()
#24 0x55cc9440135a content::BrowserMainLoop::RunMainMessageLoopParts()
#25 0x55cc944031e2 content::BrowserMainRunnerImpl::Run()
#26 0x55cc9af45651 headless::HeadlessContentMainDelegate::RunProcess()
#27 0x55cc95e254d7 content::ContentMainRunnerImpl::RunServiceManager()
#28 0x55cc95e2510e content::ContentMainRunnerImpl::Run()
#29 0x55cc95e22574 content::RunContentProcess()
#30 0x55cc95e22f5c content::ContentMain()
#31 0x55cc95e743d2 headless::(anonymous namespace)::RunContentMain()
#32 0x55cc95e740bc headless::HeadlessShellMain()
#33 0x55cc93475a03 ChromeMain
#34 0x7fe07dfa209b __libc_start_main
#35 0x55cc9347582a _start
Task trace:
#0 0x55cc96cb07dd IPC::(anonymous namespace)::ChannelAssociatedGroupController::Accept()
#1 0x55cc966094ef mojo::SimpleWatcher::Context::Notify()
#2 0x55cc96cb0b53 IPC::(anonymous namespace)::ChannelAssociatedGroupController::SendMessage()
#3 0x55cc96cb07dd IPC::(anonymous namespace)::ChannelAssociatedGroupController::Accept()
#4 0x55cc966094ef mojo::SimpleWatcher::Context::Notify()
Task trace buffer limit hit, update PendingTask::kTaskBacktraceLength to increase.

Received signal 6
#0 0x55cc95f07b39 base::debug::CollectStackTrace()
#1 0x55cc95e7a4c3 base::debug::StackTrace::StackTrace()
#2 0x55cc95f076db base::debug::(anonymous namespace)::StackDumpSignalHandler()
#3 0x7fe07fe58730 (/lib/x86_64-linux-gnu/libpthread-2.28.so+0x1272f)
#4 0x7fe07dfb57bb gsignal
#5 0x7fe07dfa0535 abort
#6 0x55cc95f06665 base::debug::BreakDebugger()
#7 0x55cc95e8b0f2 logging::LogMessage::~LogMessage()
#8 0x55cc95e8b84e logging::LogMessage::~LogMessage()
#9 0x55cc9474db47 content::RenderProcessHostImpl::ShutdownForBadMessage()
#10 0x55cc9472699e content::RenderFrameHostImpl::ValidateDidCommitParams()
#11 0x55cc94711c2e content::RenderFrameHostImpl::DidCommitNavigationInternal()
#12 0x55cc94711742 content::RenderFrameHostImpl::DidCommitNavigation()
#13 0x55cc947124c4 content::RenderFrameHostImpl::DidCommitPerNavigationMojoInterfaceNavigation()
#14 0x55cc94730922 base::internal::Invoker<>::RunOnce()
#15 0x55cc93f089d4 content::mojom::NavigationClient_CommitNavigation_ForwardToCallback::Accept()
#16 0x55cc965f34f1 mojo::InterfaceEndpointClient::HandleValidatedMessage()
#17 0x55cc96cb34f5 IPC::(anonymous namespace)::ChannelAssociatedGroupController::AcceptOnProxyThread()
#18 0x55cc96cb0df7 base::internal::Invoker<>::RunOnce()
#19 0x55cc95eca156 base::TaskAnnotator::RunTask()
#20 0x55cc95edb015 base::sequence_manager::internal::ThreadControllerWithMessagePumpImpl::DoWorkImpl()
#21 0x55cc95edad18 base::sequence_manager::internal::ThreadControllerWithMessagePumpImpl::DoWork()
#22 0x55cc95e91117 base::(anonymous namespace)::WorkSourceDispatch()
#23 0x7fe07fd15f2e g_main_context_dispatch
#24 0x7fe07fd161c8 (/usr/lib/x86_64-linux-gnu/libglib-2.0.so.0.5800.3+0x4e1c7)
#25 0x7fe07fd1625c g_main_context_iteration
#26 0x55cc95e90ee2 base::MessagePumpGlib::Run()
#27 0x55cc95edb7bd base::sequence_manager::internal::ThreadControllerWithMessagePumpImpl::Run()
#28 0x55cc95eb1fde base::RunLoop::Run()
#29 0x55cc9440135a content::BrowserMainLoop::RunMainMessageLoopParts()
#30 0x55cc944031e2 content::BrowserMainRunnerImpl::Run()
#31 0x55cc9af45651 headless::HeadlessContentMainDelegate::RunProcess()
#32 0x55cc95e254d7 content::ContentMainRunnerImpl::RunServiceManager()
#33 0x55cc95e2510e content::ContentMainRunnerImpl::Run()
#34 0x55cc95e22574 content::RunContentProcess()
#35 0x55cc95e22f5c content::ContentMain()
#36 0x55cc95e743d2 headless::(anonymous namespace)::RunContentMain()
#37 0x55cc95e740bc headless::HeadlessShellMain()
#38 0x55cc93475a03 ChromeMain
#39 0x7fe07dfa209b __libc_start_main
#40 0x55cc9347582a _start
  r8: 0000000000000000  r9: 00007ffc7f5f2720 r10: 0000000000000008 r11: 0000000000000246
 r12: 00003b32bed7dc80 r13: aaaaaaaaaaaaaaaa r14: 00003b32bed7dc90 r15: 00007ffc7f5f31c0
  di: 0000000000000002  si: 00007ffc7f5f2720  bp: 00007ffc7f5f2970  bx: 0000000000000006
  dx: 0000000000000000  ax: 0000000000000000  cx: 00007fe07dfb57bb  sp: 00007ffc7f5f2720
  ip: 00007fe07dfb57bb efl: 0000000000000246 cgf: 002b000000000033 erf: 0000000000000000
 trp: 0000000000000000 msk: 0000000000000000 cr2: 0000000000000000
[end of stack trace]

I can't repro locally with Chrome stable or Canary, so I'm guessing it's been fixed already and future puppeteer versions might work as expected. crbug.com would be the place to go for Chrome crashes though :)

patrickhulce on 8 Dec 2020

👍1

So the Chrome Version I was mentioned above? Thanks I will check that!! Helping me a lot!

floriannagel on 8 Dec 2020

👍1

Was this page helpful?

0 / 5 - 0 ratings