Best way to optimize using Grover (just discovered 750 chrome processes opened)

[altjx]

Hi there,

I am having a similar issue to https://github.com/Studiosity/grover/issues/60, but my scenario is just slightly different. I am using Sidekiq (plus Ruby on Rails) to generate a PDF document within a docker container. I am using Sidekiq worker to basically process HTML content (which sometimes have up to two charts).

Here's how I'm using them:

    grover_options = {
      format: "Letter",
      full_page: true,
      prefer_css_page_size: false,
      emulate_media: "screen",
      cache: false,
      timeout: 0, # Timeout in ms. A value of `0` means 'no timeout'
      launch_args: ["--font-render-hinting=medium", "--no-sandbox"],
      margin: { top: 75, right: 30, bottom: 44, left: 30 },
      print_background: true,
      scale: 0.75,
      display_header_footer: true,
      header_template: header_template,
      footer_template: footer_template,
    }

    final_pdf = CombinePDF.new
    final_pdf << CombinePDF.parse(Grover.new(cover_html, grover_options.merge(margin: { top: 0, right: 0, bottom: 0, left: 0 })).to_pdf)
    final_pdf << CombinePDF.parse(Grover.new(body_html, grover_options).to_pdf)

I realized that, lately, the Sidekiq worker has been failing with these types of errors:

2021-01-22T03:29:04.135Z pid=31936 tid=gmywnrgm0 WARN: Grover::Error: Failed to instantiate worker process:

2021-01-22T03:29:04.136Z pid=31936 tid=gmywnrgm0 WARN: /usr/local/bundle/gems/grover-0.14.1/lib/grover/processor.rb:42:in `ensure_packages_are_initiated'
/usr/local/bundle/gems/grover-0.14.1/lib/grover/processor.rb:19:in `convert'
/usr/local/bundle/gems/grover-0.14.1/lib/grover.rb:50:in `to_pdf'
/myapp/app/workers/report_generator_worker.rb:219:in `get_report_contents'
/myapp/app/workers/report_generator_worker.rb:68:in `perform'
/usr/local/bundle/gems/sidekiq-6.1.2/lib/sidekiq/processor.rb:196:in `execute_job'
/usr/local/bundle/gems/sidekiq-6.1.2/lib/sidekiq/processor.rb:164:in `block (2 levels) in process'
/usr/local/bundle/gems/sidekiq-6.1.2/lib/sidekiq/middleware/chain.rb:133:in `invoke'
/usr/local/bundle/gems/sidekiq-6.1.2/lib/sidekiq/processor.rb:163:in `block in process'
/usr/local/bundle/gems/sidekiq-6.1.2/lib/sidekiq/processor.rb:136:in `block (6 levels) in dispatch'
/usr/local/bundle/gems/sidekiq-6.1.2/lib/sidekiq/job_retry.rb:111:in `local'
/usr/local/bundle/gems/sidekiq-6.1.2/lib/sidekiq/processor.rb:135:in `block (5 levels) in dispatch'
/usr/local/bundle/gems/sidekiq-6.1.2/lib/sidekiq/rails.rb:14:in `block in call'
/usr/local/bundle/gems/activesupport-5.2.4/lib/active_support/execution_wrapper.rb:87:in `wrap'
/usr/local/bundle/gems/activesupport-5.2.4/lib/active_support/reloader.rb:73:in `block in wrap'
/usr/local/bundle/gems/activesupport-5.2.4/lib/active_support/execution_wrapper.rb:87:in `wrap'
/usr/local/bundle/gems/activesupport-5.2.4/lib/active_support/reloader.rb:72:in `wrap'
/usr/local/bundle/gems/sidekiq-6.1.2/lib/sidekiq/rails.rb:13:in `call'
/usr/local/bundle/gems/sidekiq-6.1.2/lib/sidekiq/processor.rb:131:in `block (4 levels) in dispatch'
/usr/local/bundle/gems/sidekiq-6.1.2/lib/sidekiq/processor.rb:257:in `stats'
/usr/local/bundle/gems/sidekiq-6.1.2/lib/sidekiq/processor.rb:126:in `block (3 levels) in dispatch'
/usr/local/bundle/gems/sidekiq-6.1.2/lib/sidekiq/job_logger.rb:13:in `call'
/usr/local/bundle/gems/sidekiq-6.1.2/lib/sidekiq/processor.rb:125:in `block (2 levels) in dispatch'
/usr/local/bundle/gems/sidekiq-6.1.2/lib/sidekiq/job_retry.rb:78:in `global'
/usr/local/bundle/gems/sidekiq-6.1.2/lib/sidekiq/processor.rb:124:in `block in dispatch'
/usr/local/bundle/gems/sidekiq-6.1.2/lib/sidekiq/logger.rb:10:in `with'
/usr/local/bundle/gems/sidekiq-6.1.2/lib/sidekiq/job_logger.rb:33:in `prepare'
/usr/local/bundle/gems/sidekiq-6.1.2/lib/sidekiq/processor.rb:123:in `dispatch'
/usr/local/bundle/gems/sidekiq-6.1.2/lib/sidekiq/processor.rb:162:in `process'
/usr/local/bundle/gems/sidekiq-6.1.2/lib/sidekiq/processor.rb:78:in `process_one'
/usr/local/bundle/gems/sidekiq-6.1.2/lib/sidekiq/processor.rb:68:in `run'
/usr/local/bundle/gems/sidekiq-6.1.2/lib/sidekiq/util.rb:15:in `watchdog'
/usr/local/bundle/gems/sidekiq-6.1.2/lib/sidekiq/util.rb:24:in `block in safe_thread'
Killed

The above output is the most common. The one below is one I've just started seeing:

2021-01-22T03:28:49.846Z pid=31936 tid=gmywnu0js WARN: Grover::Error: Worker process failed:
(node:592) UnhandledPromiseRejectionWarning: Error: Page crashed!
    at Page._onTargetCrashed (/myapp/node_modules/puppeteer/lib/Page.js:209:28)
    at CDPSession.<anonymous> (/myapp/node_modules/puppeteer/lib/Page.js:129:57)
    at CDPSession.emit (events.js:314:20)
    at CDPSession._onMessage (/myapp/node_modules/puppeteer/lib/Connection.js:166:18)
    at Connection._onMessage (/myapp/node_modules/puppeteer/lib/Connection.js:83:25)
    at WebSocket.<anonymous> (/myapp/node_modules/puppeteer/lib/WebSocketTransport.js:25:32)
    at WebSocket.onMessage (/myapp/node_modules/ws/lib/event-target.js:132:16)
    at WebSocket.emit (events.js:314:20)
    at Receiver.receiverOnMessage (/myapp/node_modules/ws/lib/websocket.js:825:20)
    at Receiver.emit (events.js:314:20)
(node:592) UnhandledPromiseRejectionWarning: Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). To terminate the node process on unhandled promise rejection, use the CLI flag `--unhandled-rejections=strict` (see https://nodejs.org/
api/cli.html#cli_unhandled_rejections_mode). (rejection id: 1)
(node:592) [DEP0018] DeprecationWarning: Unhandled promise rejections are deprecated. In the future, promise rejections that are not handled will terminate the Node.js process with a non-zero exit code.

2021-01-22T03:28:49.848Z pid=31936 tid=gmywnu0js WARN: /usr/local/bundle/gems/grover-0.14.1/lib/grover/processor.rb:96:in `rescue in call_js_method'
/usr/local/bundle/gems/grover-0.14.1/lib/grover/processor.rb:79:in `call_js_method'
/usr/local/bundle/gems/grover-0.14.1/lib/grover/processor.rb:20:in `convert'
/usr/local/bundle/gems/grover-0.14.1/lib/grover.rb:50:in `to_pdf'
/myapp/app/workers/report_generator_worker.rb:220:in `get_report_contents'
/myapp/app/workers/report_generator_worker.rb:68:in `perform'
/usr/local/bundle/gems/sidekiq-6.1.2/lib/sidekiq/processor.rb:196:in `execute_job'
/usr/local/bundle/gems/sidekiq-6.1.2/lib/sidekiq/processor.rb:164:in `block (2 levels) in process'
/usr/local/bundle/gems/sidekiq-6.1.2/lib/sidekiq/middleware/chain.rb:133:in `invoke'
/usr/local/bundle/gems/sidekiq-6.1.2/lib/sidekiq/processor.rb:163:in `block in process'
/usr/local/bundle/gems/sidekiq-6.1.2/lib/sidekiq/processor.rb:136:in `block (6 levels) in dispatch'
/usr/local/bundle/gems/sidekiq-6.1.2/lib/sidekiq/job_retry.rb:111:in `local'
/usr/local/bundle/gems/sidekiq-6.1.2/lib/sidekiq/processor.rb:135:in `block (5 levels) in dispatch'
/usr/local/bundle/gems/sidekiq-6.1.2/lib/sidekiq/rails.rb:14:in `block in call'
/usr/local/bundle/gems/activesupport-5.2.4/lib/active_support/execution_wrapper.rb:87:in `wrap'
/usr/local/bundle/gems/activesupport-5.2.4/lib/active_support/reloader.rb:73:in `block in wrap'
/usr/local/bundle/gems/activesupport-5.2.4/lib/active_support/execution_wrapper.rb:87:in `wrap'
/usr/local/bundle/gems/activesupport-5.2.4/lib/active_support/reloader.rb:72:in `wrap'
/usr/local/bundle/gems/sidekiq-6.1.2/lib/sidekiq/rails.rb:13:in `call'
/usr/local/bundle/gems/sidekiq-6.1.2/lib/sidekiq/processor.rb:131:in `block (4 levels) in dispatch'
/usr/local/bundle/gems/sidekiq-6.1.2/lib/sidekiq/processor.rb:257:in `stats'                                                                                                                                                                                                                                                                                       [97/1794]
/usr/local/bundle/gems/sidekiq-6.1.2/lib/sidekiq/processor.rb:126:in `block (3 levels) in dispatch'
/usr/local/bundle/gems/sidekiq-6.1.2/lib/sidekiq/job_logger.rb:13:in `call'
/usr/local/bundle/gems/sidekiq-6.1.2/lib/sidekiq/processor.rb:125:in `block (2 levels) in dispatch'
/usr/local/bundle/gems/sidekiq-6.1.2/lib/sidekiq/job_retry.rb:78:in `global'
/usr/local/bundle/gems/sidekiq-6.1.2/lib/sidekiq/processor.rb:124:in `block in dispatch'
/usr/local/bundle/gems/sidekiq-6.1.2/lib/sidekiq/logger.rb:10:in `with'
/usr/local/bundle/gems/sidekiq-6.1.2/lib/sidekiq/job_logger.rb:33:in `prepare'
/usr/local/bundle/gems/sidekiq-6.1.2/lib/sidekiq/processor.rb:123:in `dispatch'
/usr/local/bundle/gems/sidekiq-6.1.2/lib/sidekiq/processor.rb:162:in `process'
/usr/local/bundle/gems/sidekiq-6.1.2/lib/sidekiq/processor.rb:78:in `process_one'
/usr/local/bundle/gems/sidekiq-6.1.2/lib/sidekiq/processor.rb:68:in `run'
/usr/local/bundle/gems/sidekiq-6.1.2/lib/sidekiq/util.rb:15:in `watchdog'
/usr/local/bundle/gems/sidekiq-6.1.2/lib/sidekiq/util.rb:24:in `block in safe_thread'

I haven't seen the error above before except for today. I did some investigating and, from what I can see, each time I run something as simple as:

Grover.new("<body>html</body>", {launch_args: ["--font-render-hinting=medium", "--no-sandbox"]}).to_pdf

This spawns 5 processes that contains "chrome" in it and they don't seem to ever close.

root@61195ba0f622:/myapp# pgrep -f chrome | wc -l
750
root@61195ba0f622:/myapp# pgrep -f chrome | wc -l
755

I wonder if this is my problem? If so, is there a best practice that I should be implementing to ensure that the chrome process closes once it's finished? As you can see from the above example, it's just loading a very basic HTML with small data, but yet the 5 chrome processes stay opened.

It gets to the point to where I can't even kill the chrome process with kill -9 [pid]:

root     32724  0.0  0.0      0     0 ?        Z    03:06   0:00 [chrome] <defunct>
root     32735  0.3  0.0      0     0 ?        Z    03:06   0:09 [chrome] <defunct>
root@61195ba0f622:/myapp# kill -9 32735
root@61195ba0f622:/myapp# ps aux | grep -i 32735
root      1966  0.0  0.0   4836   892 pts/3    S+   03:49   0:00 grep -i 32735
root     32735  0.3  0.0      0     0 ?        Z    03:06   0:09 [chrome] <defunct>

[abrom]

Not sure what you've got going on there. You're using Chrome rather than Chromium? It's possible there is some sort of memory leaking happening; either something in what you're converting or something in the version of Chrome you're using?

Our servers get rolled a number of times per week, but they process decent numbers of PDFs don't have any signs of memory or process bloat.

> `pgrep -if chrom`
 => "" 
> Grover.new('hey').to_pdf; nil
 => nil 
> `pgrep -if chrom`
 => "" 

More than likely this isn't something I can help with. Grover really is just a thin wrapper around Puppeteer (using NodeJS), which of course is what makes the calls out to Chromium/Chrome/Firefox. I would suggest starting by looking at what versions of each of these tools you're using. If you're all up to date, then suggest taking this issue upstream.

[altjx]

Gotcha. Thanks @abrom. I think it's actually using Chromium from what I can see. I found this in htop:

When running the same command from the CLI, I can see it's running Chromium 83.0.4103.0:

root@13cc063857fe:/myapp# /myapp/node_modules/puppeteer/.local-chromium/linux-756035/chrome-linux/chrome --version
Chromium 83.0.4103.0

Think it's most likely related to Chromium in this case? I'm not too knowledgeable with node modules but it looks like it's just loading whichever chromium version is included in the puppeteer module? Not quite sure if that's an accurate statement or not.

EDIT

Tried updating Chromium and ended up with version 90.0.4396.0 and the issue is still happening even after using executable_path to use a different version of Chromium. Will continue to investigate but good to know it's most likely unrelated to the Grover gem.

[altjx]

@abrom are your servers using Grover in a docker container? Wondering if this may be the common denominator. I've confirmed in 3 docker containers that the issue happens and on 2 non-docker instances that it doesn't happen.

[abrom]

Hi @altjx, no we don't use docker for the instances generating PDFs. Sounds like that might be the smoking gun.

This might help?? https://github.com/puppeteer/puppeteer/blob/main/docs/troubleshooting.md#running-puppeteer-in-docker

This seems like a possible culprit:

# If running Docker >= 1.13.0 use docker run's --init arg to reap zombie processes, otherwise
# uncomment the following lines to have `dumb-init` as PID 1

They also suggest to include the SYS_ADMIN capability to the container. Seems rather extreme, but there might be something to it. And they're also installing chrome stable, although by default their container config doesn't actually use it?!

Seems likely it's one (or many) of the above..

[altjx]

Gotcha. Thanks so much for that tip. First time running into this so this is extremely helpful for me!

[robyurkowski]

@altjx Apologies for being off-topic, but any chance you could share how you got Puppeteer to pick up your stylesheets while containerized? I've got Grover emitting correctly prefixed URLs but am having no luck getting my styles to appear in rendered PDFs. Debugging's a bit trickier when you have to be headless, too.

Edit: Ooh, never mind. Pro-tip to anyone else doing this: if you're running from a rake task or something similar using docker-compose run rather than docker-compose exec, try out exec and see if it works.

[altjx]

Haha no problem! Glad you got it figured it out. Feel free to PM me if you run into any other situations. We're relying on this gem pretty heavily so it's pretty critical for me.

[jandresrodriguez]

@altjx @abrom you guys were able to solve this issue ? It's happening to me now

[abrom]

@jandresrodriguez I provided a possible list of reasons and possible solutions above. I don't use Grover with Docker in our production environment so I have not seen this issue myself.

[jandresrodriguez]

Adding init to the docker-compose worked for me! 🎉

[abrom]

I'm going to close this as there hasn't been any movement here for a while. I will suggest that the browser_ws_endpoint option might be of use in this case though. It allows Grover to connect to a remote Chromium instance, but also doesn't close the browser, only the page, which might provide a performance bump