Per https://phabricator.wikimedia.org/T181623#3854794 and lack of activity moving to backlog.

Upstream described the rubric they use to prioritise bugs and clarified that they consider it low priority: https://github.com/GoogleChrome/puppeteer/issues/1505#issuecomment-393470731

If this continues to be an issue, then we could either work around it on our side by either:

• Flagging the job as cancelled and drop any signals from Puppeteer; or
• Fixing the upstream bug ourselves; or
• …

There should be progress on this before we enter the full production stage, since keeping Chromium instances working while Proton thinks the resources are free can quickly lead to resource starvation scenarios on our scale.

@mobrovac We submitted an Issue in Puppeteer library: https://github.com/GoogleChrome/puppeteer/issues/1505 but they said it's a low-priority for them. We can try to fix the puppeteer lib by ourselves but I'm not sure if chromium itself allows stopping the PDF rendering. The second approach (the cruel one) would be just to kill the given chromium instance, but I'm not sure if this approach has no side effects.

We will log the amount of aborted request (we have different stats for the state when the request still waits in the queue and when it already started to render). If the number of aborted requests (which are currently in render state) is higher than X % (we have to find X, for now, let's say 10%), then we have to fix that issue.

In T181623#4476072, @pmiazga wrote:

@mobrovac We submitted an Issue in Puppeteer library: https://github.com/GoogleChrome/puppeteer/issues/1505 but they said it's a low-priority for them. We can try to fix the puppeteer lib by ourselves but I'm not sure if chromium itself allows stopping the PDF rendering. The second approach (the cruel one) would be just to kill the given chromium instance, but I'm not sure if this approach has no side effects.

Right, but it's not a low priority for us, so we need to do something about it. IMHO trying to first fix it in Puppeteer and submitting a PR upstream is the way forward here, especially because upsteam hasn't rejected the bug, which means they'd gladly accept fixes for it ;)

We will log the amount of aborted request (we have different stats for the state when the request still waits in the queue and when it already started to render). If the number of aborted requests (which are currently in render state) is higher than X % (we have to find X, for now, let's say 10%), then we have to fix that issue.

I don't think that's acceptable. At our scale, resource starvation is not to be considered an edge case, especially for heavy workloads such as PDF generation. We have already had cases of services starving resources, which always come unexpectedly and take a lot of time and effort to deal with in real time (the last occurrence was T199813 which managed to starve memory on nodes with a simple and lightweight get msg - send msg workflow). Therefore, since here we are aware of the problem, we absolutely have to deal with it before starting to send live traffic to Proton.

@mobrovac as a easy/hacky fix for now, we can use Browser.process() (kudos to @phuedx for finding that) to get the Chromium child process and kill it.

Change 451793 had a related patch set uploaded (by Pmiazga; owner: Pmiazga):
[mediawiki/services/chromium-render@master] To prevent resource starvation, try to kill chromium after 3s

https://gerrit.wikimedia.org/r/451793

Change 451817 had a related patch set uploaded (by Pmiazga; owner: Pmiazga):
[mediawiki/services/chromium-render@master] Handle the stopping chromium rendering correclty

https://gerrit.wikimedia.org/r/451817

Regarding T181623#4495059, can anyone in Readers Web review @pmiazga's changes? I'll also ask during today's standup ritual.

Notes from yesterday's standup ritual:

• All Readers Web engineers are capable of reviewing @pmiazga's changes.
• Reviewing the changes would require a non-trivial context switch.
• T177765: Security review of mediawiki-services-chromium-render is expected to take two weeks.
  • @charlotteportero confirmed this via email yesterday evening (BST)
• @mobrovac and @Pchelolo have reviewed @pmiazga's recent changes relatively quickly.
• My gut feeling is that reviewing this is a priority but we (Readers Web) can lean on Services to provide support while @pmiazga is on vacation.

@mobrovac/@Pchelolo: Could you review rMSCR3e074fd4abf8: Handle the stopping chromium rendering correctly and rMSCR130e32ee19dd: To prevent resource starvation, try to kill chromium after 3s at your earliest convenience?

Change 451793 merged by Mobrovac:
[mediawiki/services/chromium-render@master] To prevent resource starvation, try to kill chromium after 3s

https://gerrit.wikimedia.org/r/451793

blocked, we're waiting for @mobrovac to come back from vacation.,

Change 451817 merged by jenkins-bot:
[mediawiki/services/chromium-render@master] Handle the stopping chromium rendering correctly

https://gerrit.wikimedia.org/r/451817

@pmiazga: Could you provide instructions on how to test this?

Mentioned in SAL (#wikimedia-operations) [2018-09-12T06:56:54Z] <mobrovac@deploy1001> Started deploy [proton/deploy@ecb9a0e]: Update to Puppeteer v1.7.0 and fix browser connection abort handling - T181623

Mentioned in SAL (#wikimedia-operations) [2018-09-12T06:57:52Z] <mobrovac@deploy1001> Finished deploy [proton/deploy@ecb9a0e]: Update to Puppeteer v1.7.0 and fix browser connection abort handling - T181623 (duration: 00m 58s)

Looks like this task requires a technical QA - @Jdlrobson, @Niedzielski @Jdrewniak @nray - can one of you pick it up?

I've tested this on my local with Siege, and it appears to kill the chromium instances correctly, and the queue management seems to be working well.

I ran the following tests:

• I ran tests with a large queue (100 items) and intermittently canceled each request, the render tasks were aborted correctly
• Did the same and canceled all the requests at once, again no remaining chromium processes were visible
• I ran Siege for about an hour, and intermittently killed some chromium workers, the workers were restarted by the renderer correctly followed by the 'Queue health check'
• the rendering was aborted correctly when it took too long (renderTime=90000)
• unplugging and replugging my network connection, and killing some chromium processes intermittently

Out of all this I only ever saw 1 exception, when I manually killed the main chromium instance

[2018-09-17T11:48:55.573Z] FATAL: proton/6798 on jdrewniakwmf2204.local: Callback was already called. (err.levelPath=fatal/service-runner/unhandled)
    Error: Callback was already called.
        at /Users/jdrewniak/Gerrit/mediawiki/services/chromium-render/node_modules/async/internal/onlyOnce.js:9:32
        at timedRender (/Users/jdrewniak/Gerrit/mediawiki/services/chromium-render/lib/queue.js:206:17)
        at Timeout.timeoutCallback [as _onTimeout] (/Users/jdrewniak/Gerrit/mediawiki/services/chromium-render/node_modules/async/timeout.js:74:13)
        at ontimeout (timers.js:466:11)
        at tryOnTimeout (timers.js:304:5)
        at Timer.listOnTimeout (timers.js:267:5)
[2018-09-17T11:48:55.688Z] ERROR: proton/6796 on jdrewniakwmf2204.local: worker died, restarting (message="worker died, restarting", worker_pid=6798, exit_code=1, levelPath=error/service-runner/master)
[2018-09-17T11:48:56.522Z]  INFO: proton/6975 on jdrewniakwmf2204.local: Queue health check. (queueSize=0, runningTasksCount=0, levelPath=info/queue)
[2018-09-17T11:48:56.541Z]  INFO: proton/6975 on jdrewniakwmf2204.local: Worker 6975 listening on 0.0.0.0:3030 (levelPath=info)

Presumably that's because I forcefully killed the chromium process, and the onlyOnce method was doing it's job in preventing the callback from being called multiple times. Afterwards, the chromium worker restarted successfully.

In T181623#4588504, @Jdrewniak wrote:

[...]
Presumably that's because I forcefully killed the chromium process, and the onlyOnce method was doing it's job in preventing the callback from being called multiple times. Afterwards, the chromium worker restarted successfully.

Trying to kill Chromium manually was a good test! While we will not be killing them manually, the kernel might decide to kill the process due to resourcing problems. As provided in the log entry, when that happens, the proton worker servicing the request dies as well, which means that the client receives no response. It would be good to add some code that checks for the existence of the browser process before issuing the kill() call.

@mobrovac that's a good point. I was going to add the check anyway because that error kills the worker which IMHO is pretty bad. The chromium-render process shouldn't die, all errors have to be handled properly. Also, if that error (callback called twice) is triggered during tests -> that's more than sure it will happen on production. I'll analyze the flow and I'll try to prevent similar cases.

I'm thinking loud here: -> There is only one case when we jump out of puppeteer scope, in renderer.closeBrowser()) we ask the browser to close and then we listen to the native ChildProcess exit event - if it didn't happen we kill the browser.
The scenario @Jdrewniak talks about - happens only when something other than our code (something other than puppetter&chromium-render) tries to manage the chromium process. If we start listening to exit event all the time (not only when we ask the browser to close), we could log&prevent such situations in a nice manner.

Sth like (pseudocode):

[...]
let isRenderInProgress = false;
[...]
 articleToPdf(url, headers, puppeteerOptions, pdfOptions) {
    isRenderInProgress = true;
    [...]
    puppeteer.then((response) => {
        isRenderInProgress = false;
        [...]
        resolve(response.pdf);
   }
 }

childProcess.on('exit', function() {
  if (isRenderInProgress) {
    // something bad happened, log and gracefully exit the queue
  }
});

I'll work on a patch to prevent situations @Jdrewniak mentioned, as the error is triggered by our "render timeout" logic. We need to clearTimeout when we return from timedRender call, this is clearly a bug.
I'm just wondering/thinking loud, how often something like that (something else kills our precious chromium instances) can happen on production, Is it important to log/do some special handling in such cases? /cc @mobrovac @phuedx

Change 462579 had a related patch set uploaded (by Pmiazga; owner: Pmiazga):
[mediawiki/services/chromium-render@master] Html2pdf route should return promise

https://gerrit.wikimedia.org/r/462579

Change 462579 merged by jenkins-bot:
[mediawiki/services/chromium-render@master] Html2pdf route should return promise

https://gerrit.wikimedia.org/r/462579

I've run the pdf-renderer again, overflown it with lots of request, left it on for an hour, intermittently killed the main chromium processes, killed the child processes, disconnected and reconnected the network, and I'm unable to reproduce my previous bug. Good job!