{"id":801,"date":"2024-11-20T15:50:14","date_gmt":"2024-11-20T15:50:14","guid":{"rendered":"https:\/\/blog.67bricks.com\/?p=801"},"modified":"2024-11-21T10:17:23","modified_gmt":"2024-11-21T10:17:23","slug":"on-jspawnhelper-and-automatic-updates","status":"publish","type":"post","link":"https:\/\/blog.67bricks.com\/?p=801","title":{"rendered":"On jspawnhelper and automatic updates"},"content":{"rendered":"\n

I had just settled down to write some ScalaCheck tests when suddenly my peace and harmony was shattered by the news that the “download PDF” functionality on one of our sites had recently ceased functioning, and it would be quite nice if it could be restored to good working order. And so begins our tale.<\/p>\n\n\n\n\n\n\n\n

First step – can I reproduce it? Yes – if I visit the page in the supplied screenshot and attempt to download it as a PDF I get an error message “Failed to create a PDF for the document”<\/p>\n\n\n\n

Although some documents on the site have PDFs already available for download, there are some that don’t, and in those cases we invoke the application wkhtmltopdf<\/a> to create one.<\/p>\n\n\n\n

So I took a look at the site logs, and attempted to download a PDF:<\/p>\n\n\n\n

2024-11-19 13:05:26,089 INFO  controllers.DocumentController :: Displaying document 2018ewhc818fam_TNA in index card 2018000893 as a generated pdf\n2024-11-19 13:05:26,094 INFO  com.sixtysevenbricks.client.documents.DocumentService :: Allowing access to 2018ewhc818fam_TNA for reporter\/editor\/admin user REDACTED\n2024-11-19 13:05:26,094 DEBUG com.sixtysevenbricks.client.pdf.WkHtmlToPdfGenerator :: generateUrl(): http:\/\/127.0.0.1:9000\/document\/2018000893\/2018ewhc818fam_TNA\/html?name=REDACTED\n2024-11-19 13:05:26,096 WARN  controllers.DocumentController :: displayDocumentAsPdf(): Failed to create PDF for document '2018ewhc818fam_TNA'\njava.io.IOException: Cannot run program \"\/usr\/local\/bin\/wkhtmltopdf\": error=0, Failed to exec spawn helper: pid: 2403844, exit value: 1\n        at java.base\/java.lang.ProcessBuilder.start(ProcessBuilder.java:1143)\n        at java.base\/java.lang.ProcessBuilder.start(ProcessBuilder.java:1073)\n        at com.sixtysevenbricks.client.pdf.WkHtmlToPdfGenerator.$anonfun$generatePdf$1(WkHtmlToPdfGenerator.scala:26)<\/code><\/pre>\n\n\n\n
So there’s a problem running wkhtmltopdf<\/code>. Check it exists at the given path (it does) and can be run and produces output (it does). The interesting thing is “Failed to exec spawn helper”<\/p>\n\n\n\n
It’s going to be fiddly to debug this code in situ<\/em> but I have the cunning plan of writing the simplest possible Java program that will do what the actual application code is doing:<\/p>\n\n\n\n
public class RunProcess {\n  public static void main(String[] args) {\n    File pdfFile = new File(\"\/tmp\/daniel.pdf\");\n    File outputFile = new File(\"\/tmp\/daniel.txt\");\n    try {\n      Process process = new ProcessBuilder(\"\/usr\/local\/bin\/wkhtmltopdf\",\n        \"--print-media-type\",\n        \"--no-background\",\n        \"http:\/\/127.0.0.1:9000\/document\/2018000893\/2018ewhc818fam_TNA\/html?displayIndexCardOverlay=false&pdfGenerate=true&name=REDACTED\",\n        pdfFile.getAbsolutePath())\n        .redirectErrorStream(true)\n        .redirectOutput(ProcessBuilder.Redirect.appendTo(outputFile))\n        .start();\n      int result = process.waitFor();\n      System.out.println(\"Status \" + result);\n    } catch (InterruptedException ex) {\n      ex.printStackTrace();\n    } catch (IOException ex) {\n      ex.printStackTrace();\n    }\n  }\n}<\/code><\/pre>\n\n\n\n
Put this on the server as RunProcess.java<\/code>, compile and run and… it works. The PDF is generated as expected.<\/p>\n\n\n\n
So my next thought was to wonder whether I could get more information about what was going wrong. It turns out that the log messages from the site log weren’t the whole story; there were more tantalising bits to be found using journalctl -f<\/code> and repeating the “download PDF” test:<\/p>\n\n\n\n
Nov 19 13:05:26 [debug] - com.sixtysevenbricks.client.pdf.WkHtmlToPdfGenerator - generateUrl(): http:\/\/127.0.0.1:9000\/document\/2018000893\/2018ewhc818fam_TNA\/html?displayIndexCardOverlay=false&pdfGenerate=true\nNov 19 13:05:26 Incorrect number of arguments: 2\nNov 19 13:05:26 jspawnhelper version 17.0.13+11-Ubuntu-2ubuntu120.04\nNov 19 13:05:26 This command is not for general use and should only be run as the result of a call to\nNov 19 13:05:26 ProcessBuilder.start() or Runtime.exec() in a java application\nNov 19 13:05:26 [warn] - controllers.DocumentController - displayDocumentAsPdf(): Failed to create PDF for document '2018ewhc818fam_TNA'\nNov 19 13:05:26 java.io.IOException: Cannot run program \"\/usr\/local\/bin\/wkhtmltopdf\": error=0, Failed to exec spawn helper: pid: 2403844, exit value: 1\nNov 19 13:05:26         at java.base\/java.lang.ProcessBuilder.start(ProcessBuilder.java:1143)<\/code><\/pre>\n\n\n\n
I wonder what jspawnhelper<\/code> is? Turns out it is \/usr\/lib\/jvm\/java-17-openjdk-amd64\/lib\/jspawnhelper<\/code>. What happens if I run it?<\/p>\n\n\n\n
$ \/usr\/lib\/jvm\/java-17-openjdk-amd64\/lib\/jspawnhelper\nIncorrect number of arguments: 1\njspawnhelper version 17.0.13+11-Ubuntu-2ubuntu120.04\nThis command is not for general use and should only be run as the result of a call to\nProcessBuilder.start() or Runtime.exec() in a java application<\/code><\/pre>\n\n\n\n
If I run it, I get a similar “Incorrect number of arguments” message. So, naturally, the next question is “what do the arguments look like”?<\/p>\n\n\n\n
One quick Google<\/s> DuckDuckGo later, and I am aware of the strace<\/code> utility, and after a bit of faff, I discover that I can find what happens when my simple Java application tries to call this jspawnhelper<\/code> thing:<\/p>\n\n\n\n
$ strace -s 255 -f -etrace=execve -everbose=execve java RunProcess\nexecve(\"\/usr\/bin\/java\", [\"java\", \"RunProcess\"], 0x7ffe88a48a80 \/* 26 vars *\/) = 0\n...\n[pid 2418068] execve(\"\/usr\/lib\/jvm\/java-17-openjdk-amd64\/lib\/jspawnhelper\", [\"\/usr\/lib\/jvm\/java-17-openjdk-amd64\/lib\/jspawnhelper\", \"17.0.13+11-Ubuntu-2ubuntu120.04\", \"9:10:12\"], 0x7ffdd659f6d0 \/* 26 vars *\/) = 0\n[pid 2418068] execve(\"\/usr\/local\/bin\/wkhtmltopdf\", [\"\/usr\/local\/bin\/wkhtmltopdf\", \"--print-media-type\", \"--no-background\", \"http:\/\/127.0.0.1:9000\/document\/2018000893\/2018ewhc818fam_TNA\/html?displayIndexCardOverlay=false&pdfGenerate=true&name=REDACTES\", \"\/tmp\/daniel.pdf\"], 0x7ffd72d56088 \/* 26 vars *\/) = 0\n...<\/code><\/pre>\n\n\n\n
We see in the execve<\/code> call that there are 3 arguments; the zeroth (in UNIX tradition) is the name of the binary used to call it, the first looks like a Java version number, and I’m not sure what the second is. But it means I can experiment by calling it:<\/p>\n\n\n\n
$ \/usr\/lib\/jvm\/java-17-openjdk-amd64\/lib\/jspawnhelper first second\nIncorrect Java version: first\njspawnhelper version 17.0.13+11-Ubuntu-2ubuntu120.04\n<\/code><\/pre>\n\n\n\n
It seems that the first parameter is supposed to be the build version reported when running java<\/code> without parameters.<\/p>\n\n\n\n
$ \/usr\/lib\/jvm\/java-17-openjdk-amd64\/lib\/jspawnhelper 17.0.13+11-Ubuntu-2ubuntu120.04 second\nIncorrect FD array data: second\njspawnhelper version 17.0.13+11-Ubuntu-2ubuntu120.04<\/code><\/pre>\n\n\n\n
So the last parameter is presumably a set of file descriptors that tell this utility what it’s supposed to be doing. I’m not concerned about them, but let’s try to see what the failing application is doing. It turns out one can strace<\/code> a running process, so if I try sudo strace -s 255 -f -etrace=execve -everbose=execve -p 1593594<\/code> and download the PDF, I see:<\/p>\n\n\n\n
strace: Process 2414425 attached\n[pid 2414425] execve(\"\/usr\/lib\/jvm\/java-17-openjdk-amd64\/lib\/jspawnhelper\", [\"\/usr\/lib\/jvm\/java-17-openjdk-amd64\/lib\/jspawnhelper\", \"307:311:313\"], 0x7ffe34173620 \/* 17 vars *\/) = 0\n[pid 2414425] +++ exited with 1 +++\n<\/code><\/pre>\n\n\n\n
Only two arguments! What happened to the Java version?<\/p>\n\n\n\n
At this point, a sixth sense kicked in, and I thought about checking to see if there had been any shenanigans with updating the installed Java version. Another quick Bing<\/s> DuckDuckGo and I find that apt<\/code> stores history at \/var\/log\/apt\/history.log<\/code> so I take a look at that and see:<\/p>\n\n\n\n
Start-Date: 2024-11-13  06:08:43\nCommandline: \/usr\/bin\/unattended-upgrade\nUpgrade: openjdk-17-jre-headless:amd64 (17.0.12+7-1ubuntu2~20.04, 17.0.13+11-2ubuntu1~20.04), openjdk-17-jre:amd64 (17.0.12+7-1ubuntu2~20.04, 17.0.13+11-2ubuntu1~20.04)\nEnd-Date: 2024-11-13  06:08:51<\/code><\/pre>\n\n\n\n
Interesting; I presume this is an update from version 17.0.12+7...<\/code> to 17.0.3+11...<\/code> on 13th November. How long has the server been running?<\/p>\n\n\n\n
$ ps -ef | grep java\nubuntu   1593594       1  2 Nov12 ?        04:51:23 java -Duser.dir=REDACTED -XX:MaxRAMPercentage=65 -Dhttp.address=0.0.0.0 -Dhttp.port=9000 -Dplay.http.secret.key=REDACTED -Dconfig.file=REDACTED -cp REDACTED play.core.server.ProdServerStart<\/code><\/pre>\n\n\n\n
Since November 12th! So I’m guessing the java<\/code> binary has had its directory unceremoniously removed from under it, and my hypothesis is that one manifestation of this is that when it tries to get hold of the current version to pass to jspawnhelper<\/code> it is failing, but without raising an error (or, alternatively, maybe the .13<\/code> version added the requirement for the version to be passed as an argument). Either way, my hypothesis now is that killing the java<\/code> process will fix the issue; systemd<\/code> will note its demise and start a new one almost instantly, downtime will be unavoidable but minimal, and PDF downloads should start working again…<\/p>\n\n\n\n
…and they did. And we all lived happily ever after.<\/p>\n\n\n\n
I think the moral of this story is, as is so often the case, the solution really is to turn it off and on again.<\/p>\n","protected":false},"excerpt":{"rendered":"
I had just settled down to write some ScalaCheck tests when suddenly my peace and harmony was shattered by the news that the “download PDF” functionality on one of our sites had recently ceased functioning, and it would be quite nice if it could be restored to good working order. And so begins our tale.<\/p>\n","protected":false},"author":5,"featured_media":0,"comment_status":"closed","ping_status":"closed","sticky":false,"template":"","format":"standard","meta":{"footnotes":""},"categories":[19,22],"tags":[95,96,97],"class_list":["post-801","post","type-post","status-publish","format-standard","hentry","category-java","category-war-stories","tag-jspawnhelper","tag-strace","tag-wkhtmltopdf"],"_links":{"self":[{"href":"https:\/\/blog.67bricks.com\/index.php?rest_route=\/wp\/v2\/posts\/801","targetHints":{"allow":["GET"]}}],"collection":[{"href":"https:\/\/blog.67bricks.com\/index.php?rest_route=\/wp\/v2\/posts"}],"about":[{"href":"https:\/\/blog.67bricks.com\/index.php?rest_route=\/wp\/v2\/types\/post"}],"author":[{"embeddable":true,"href":"https:\/\/blog.67bricks.com\/index.php?rest_route=\/wp\/v2\/users\/5"}],"replies":[{"embeddable":true,"href":"https:\/\/blog.67bricks.com\/index.php?rest_route=%2Fwp%2Fv2%2Fcomments&post=801"}],"version-history":[{"count":9,"href":"https:\/\/blog.67bricks.com\/index.php?rest_route=\/wp\/v2\/posts\/801\/revisions"}],"predecessor-version":[{"id":821,"href":"https:\/\/blog.67bricks.com\/index.php?rest_route=\/wp\/v2\/posts\/801\/revisions\/821"}],"wp:attachment":[{"href":"https:\/\/blog.67bricks.com\/index.php?rest_route=%2Fwp%2Fv2%2Fmedia&parent=801"}],"wp:term":[{"taxonomy":"category","embeddable":true,"href":"https:\/\/blog.67bricks.com\/index.php?rest_route=%2Fwp%2Fv2%2Fcategories&post=801"},{"taxonomy":"post_tag","embeddable":true,"href":"https:\/\/blog.67bricks.com\/index.php?rest_route=%2Fwp%2Fv2%2Ftags&post=801"}],"curies":[{"name":"wp","href":"https:\/\/api.w.org\/{rel}","templated":true}]}}