The display assertion vaguely points towards xpra or Xorg. Smells like a race condition on service restart, possibly with the old Xorg or xpra still hanging around. The line "Mar 08 00:30:32 scb1003 pdfrender[26738]: Xpra: Fatal IO error 2 (No such file or directory) on X server :711." could be related.

I would also expect this to go away on restart. I think the logs already give us all the information we can get out of this instance, and restarting it is fine.

We'll need to reproduce this in order to fix it.

This is (unfortunately) a common scenario on service start-up. The current work-around is stopping the service, wait a bit and start it (just restarting it also works sometimes, but it's not as reliable).

As an immediate work-around, maybe we could add a delay in the restart process? One way to do this might be to add a sleep in https://www.freedesktop.org/software/systemd/man/systemd.service.html#ExecStopPost=.

Change 341833 had a related patch set uploaded (by GWicke):
[operations/puppet] Delay service shut-down to work around xpra race

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

The same thing has just happened when I've tried to update the service to a newer version (see T160764). Will put the patch for puppet SWAT and attempt to deploy after it's merged.

Change 341833 merged by Filippo Giunchedi:
[operations/puppet@production] PDFRender: Delay service shut-down to work around xpra race

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

Although the patch was merged, the situation didn't change - the exact same log is produced on server restart. This blocks deployment of the new version T160764 because, although for the old version the error was there, it didn't prevent the service from starting up. The new version just hangs after the AssertionError and doesn't accept connections. In beta cluster though this doesn't happen.

The problem (pdfrender hanging at startup) just showed up again on scb1002, and it seems there is no way to get around that race condition at the moment (no amount of waiting is ok).

For the moment, I couldn't find anything justifying what's happening besides a race condition at startup time, so that the pdf service tries to access xpra before it's ready.

I would suggest we run xpra as a separate service that pdfrender depends upon in systemd, and use some systemd primitive to ensure the latter starts only when the former is ready.

For now I'll ack the alarm in icinga and wait for someone of you to be online to further debug the issue toghether.

Happened again today afaics on scb100[12], resolved restarting pdfrender on both.

Restarted pdfrender on scb1004, scb200[2,4] today, xpra race condition traces in /srv/log/pdfrender

Mentioned in SAL (#wikimedia-operations) [2017-06-15T22:02:40Z] <volans> restarted pdfrender on scb1001 T159922

Mentioned in SAL (#wikimedia-operations) [2017-06-17T16:51:00Z] <volans> restarted pdfrender on scb200[2,4] T159922

There is an ETA for a permanent fix? It seems to me that we've already delayed this too much given the frequency at which it's happening lately.

In T159922#3357374, @Volans wrote:

There is an ETA for a permanent fix? It seems to me that we've already delayed this too much given the frequency at which it's happening lately.

There is currently a debate as to whether Electron will be kept at all in T166188: Architecture of new rendering backend for Extension:Collection. I would suggest to see what the final outcome of that will be before investing efforts into finding the correct fix for Electron.

Change 359967 had a related patch set uploaded (by GWicke; owner: GWicke):
[operations/puppet@production] Restart pdfrender service once per day

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

Marko's new version of the patch actually checks whether the service is responsive, and only restarts it when necessary. This should eliminate for manual restarts, and should buy us enough time until the longer term browser-based renderer is determined in T166188.

I am also wondering if there were any hangs during normal operation (not after a manual restart) before the Electron upgrade on April 11th, or if this is a regression.

@GWicke, @mobrovac - currently all of the options we are seriously looking at include electron. We are leaning towards T168871#3449625 and would be ready to commit unless there's significant objections from your team or ops. Do we know what portion of renders this bug is affecting? Currently, electron is used as the default renderer on all projects.

@ovasileva, thanks for the update. Anything that uses a generic browser based print process is good news to me. Electron is just one of several possible wrappers around Chrome, and we can replace it with other options like the newer native Chrome print mode without any changes in behavior or output.

The Electron issues are relatively rare, but when they happen, they hang one instance until it is restarted. This is something we need to address in the longer term, once a decision between generic browser-based rendering (ex: Electron) vs. specialized tools like wkhtml2pdf has been made on your end.

@GWicke - about 90% sure that we'll go with electron. If there's no significant objections to the proposal in T168871, we will probably be committing to that approach by the end of this week.

Change 359967 merged by Giuseppe Lavagetto:
[operations/puppet@production] PDF Render: Check hourly if the service is running via cron

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

on scb1002

Current Status:	  CRITICAL  
 (for 0d 5h 51m 50s)
Status Information:	connect to address 10.64.16.21 and port 5252: Connection refused
HTTP CRITICAL - Unable to open TCP socket

https://icinga.wikimedia.org/cgi-bin/icinga/extinfo.cgi?type=2&host=scb1002&service=pdfrender

duration: 0d 5h 52m 52s

Mentioned in SAL (#wikimedia-operations) [2017-07-28T02:26:56Z] <mutante> scb1002 - systemctl restart pdfrender - was "connect to address 10.64.16.21 and port 5252: Connection refused" in Icinga since a couple hours (T159922) - recovered

19:27 < icinga-wm> RECOVERY - pdfrender on scb1002 is OK: HTTP OK: HTTP/1.1 200 OK - 275 bytes in 0.002 second response time

Mentioned in SAL (#wikimedia-operations) [2017-07-31T17:12:05Z] <herron> scb1001 restarted pdfrender service - T159922

Mentioned in SAL (#wikimedia-operations) [2017-07-31T20:48:59Z] <mutante> restarting pdfrender service on sc1001 after icinga alert (T159922)

^ that was scb1002 - not sc1001 - typo

This happened today at around 6:58 on scb1001, due to oomkiller killing one of electron's children

Aug  2 06:57:58 scb1001 kernel: [3687844.422723] Memory cgroup out of memory: Kill process 13114 (electron) score 922 or sacrifice child
Aug  2 06:57:58 scb1001 kernel: [3687844.433046] Killed process 13116 (electron) total-vm:322044kB, anon-rss:928kB, file-rss:25052kB, shmem-rss:0kB

Then xpra shuts down and everything gets restarted by systemd

Aug  2 06:58:07 scb1001 pdfrender[13039]: xpra at :918 has exited.
Aug  2 06:58:08 scb1001 pdfrender[13039]: Xpra server pid 13040, xpra client pid 13073, jail 13074
Aug  2 06:58:09 scb1001 pdfrender[13039]: (EE) Server terminated successfully (0). Closing log file.
Aug  2 06:58:21 scb1001 systemd[1]: pdfrender.service holdoff time over, scheduling restart.
Aug  2 06:58:21 scb1001 systemd[1]: Stopping "pdfrender service"...
Aug  2 06:58:21 scb1001 systemd[1]: Starting "pdfrender service"...
Aug  2 06:58:21 scb1001 systemd[1]: Started "pdfrender service".

I noticed in case of a restart not working pdfrender isn't even emitting Renderer listening on http://0.0.0.0:5252 in the logs which matches what we're seeing (not listening on socket).

Looking at the code it seems either electron hasn't finished booting and/or windowpool never finishes?

// Electron finished booting
electronApp.once('ready', () => {
  electronApp.ready = true;
  app.pool = new WindowPool();
  const listener = app.listen(PORT, HOSTNAME, () => printBootMessage(listener));
});

In either case there should be some failsafe to at least retry whatever electron or windowpool were trying to do

Mentioned in SAL (#wikimedia-operations) [2017-08-07T12:39:29Z] <_joe_> restarting pdfrender on scb1001, T159922

I just reported the issue on the other ticket, interested on a fix, of course, but unsubscribing to try to keep my inbox under 100 phab daily emails :-) Readd me if you need help.

Mentioned in SAL (#wikimedia-operations) [2017-08-13T19:01:50Z] <godog> bounce pdfrender on scb1001 and scb1003 - T159922

This just happened again, any thoughts on what I wrote in T159922#3492238 ? Namely that xpra might not be necessarily the root cause

Mentioned in SAL (#wikimedia-operations) [2017-08-15T13:21:51Z] <moritzm> bounced pdfrender on scb1001 (T159922)

Mentioned in SAL (#wikimedia-operations) [2017-08-15T15:21:30Z] <mobrovac> restarting pdfrender on scb1001, added some debug messages to help us diagnose T159922

In T159922#3522796, @fgiunchedi wrote:

This just happened again, any thoughts on what I wrote in T159922#3492238 ? Namely that xpra might not be necessarily the root cause

I added some debugging messages to the service on scb1001, and, in fact, the initialisation process never finishes:

[INIT] Electron App back-end ready, creating the windows ...
[WindowPool] Created window with id = 1, n = 7
[WindowPool] Created window with id = 2, n = 6
[WindowPool] Created window with id = 3, n = 5
[WindowPool] Created window with id = 4, n = 4
[WindowPool] Created window with id = 5, n = 3

It hangs after a certain amount of windows have been created. For reference, when the service starts up normally, these log entries are produced:

[INIT] Electron App back-end ready, creating the windows ...
[WindowPool] Created window with id = 1, n = 7
[WindowPool] Created window with id = 2, n = 6
[WindowPool] Created window with id = 3, n = 5
[WindowPool] Created window with id = 4, n = 4
[WindowPool] Created window with id = 5, n = 3
[WindowPool] Created window with id = 6, n = 2
[WindowPool] Created window with id = 7, n = 1
[WindowPool] Created window with id = 8, n = 0
[INIT] Window creating completed
Renderer listening on http://0.0.0.0:5252
Usage: GET http://0.0.0.0:5252/[pdf|png|jpeg]?accessKey=[token]&url=http%3A%2F%2Fgoogle.com

I don't have an answer as to why the window-creation process hangs at the moment.

Mentioned in SAL (#wikimedia-operations) [2017-08-16T08:10:24Z] <moritzm> bounced pdfrender on scb1004 (T159922)

I tried setting a time-out during the initialisation process that would kill the process if ti doesn't complete in a reasonable amount of time (and hence allow SystemD to restart it), but unfortunately it seems that Electron's window-creation process blocks entirely the libuv loop, so it is never executed.

I did notice, however, that even when that happens in most of the cases at least 4 windows get created, so a temporary work-around might be to lower the concurrency to 4. That should be enough to serve the current rate of requests (~2reqs/sec).

Change 372156 had a related patch set uploaded (by Mobrovac; owner: Mobrovac):
[operations/puppet@production] PDF Render: Lower the concurrency to 4

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

Change 372156 merged by Alexandros Kosiaris:
[operations/puppet@production] PDF Render: Lower the concurrency to 4

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

At least one instance on scb100* broke again about 20 hours ago:

I just restarted the instances on scb1001-1004, which resolved the alert.

Assuming this was an instance with the reduced concurrency applied, it seems that this change did not help much either.

In T159922#3532373, @GWicke wrote:

Assuming this was an instance with the reduced concurrency applied, it seems that this change did not help much either.

The concurrency change was meant only to help for the restart process itself, not the service process running, but hanging issue (which is a different beast). If you managed to restart them in one go, then it's actually working :)

Mentioned in SAL (#wikimedia-operations) [2017-08-24T21:59:54Z] <gwicke> restarted pdfrender service instances in eqiad / T159922

Mentioned in SAL (#wikimedia-operations) [2017-08-28T18:48:52Z] <gwicke> restarted pdfrender instances in eqiad (T159922)

This task was about pdfrender failing to start, and that problem has been "hotfixed".

It has nothing to do with the service hanging and us having no functional monitoring (because we have no swagger spec for this, for instnance).

I'd resolve this ticket at this point. @mobrovac what do you think?

I personally am not sure whether the startup issues are caused by the same underlying issue as the hangs, or not. I would imagine that an electron worker process restarting could run into similar hangs as on service startup.

In any case, the hangs are an important problem right now, requiring frequent manual intervention. If we decide to close this task, lets make sure we have another task to keep tracking the hangs.

FWIW I support closing this and moving the other parts into their own tasks. This task is already long enough and treats at least 3 different things (pdfrending hanging problem + pdfrender start up problem + discussions pertaining to a new service. i.e. T166188) so it's becoming a little bit confusing. Let's rename this one to reflect we 've treated the pdf start up problem (which is pretty much 80% of the task) and move the other parts into their own tasks.