Unhandled exception calling finish_job

[cheeseindustries]

Greetings,

I am with the GenomeTrakr project at the FDA\CFSAN. We seem to be hitting a Galaxy bug that has caused an OOM condition on our production Galaxy instance for GalaxyTrakr which led to an outage. We are seeing the following errors in our job handler logs, it seems there is a bug in the finish_job method which is causing the job handlers to crash leading to Galaxy spawning a large number of uWSGI processes. This eventually lead to system processes on our host invoking OOM killer on uWSGI, which seems to have eventually caused our upstream web proxy to be unable to reach Galaxy. If there is any other relevant info or log data that you need I can provide it.

EDIT: Sorry forgot to include version. We are currently on 19.01

Thanks!

From job handler logs:

galaxy.jobs.runners ERROR 2019-05-15 21:44:20,442 [p:10617,w:0,m:1] [DRMAARunner.work_thread-3] (167903/5913) Job wrapper finish method failed
galaxy.jobs.runners ERROR 2019-05-15 21:44:21,143 [p:10617,w:0,m:1] [DRMAARunner.work_thread-3] (167903) Unhandled exception calling finish_job
galaxy.jobs.runners ERROR 2019-05-15 21:47:20,674 [p:10617,w:0,m:1] [DRMAARunner.work_thread-2] (167905/5915) Job wrapper finish method failed
galaxy.jobs.runners ERROR 2019-05-15 21:47:22,242 [p:10617,w:0,m:1] [DRMAARunner.work_thread-2] (167905) Unhandled exception calling finish_job
galaxy.jobs.runners ERROR 2019-05-15 21:55:09,751 [p:10617,w:0,m:1] [DRMAARunner.work_thread-3] (167907/5917) Job wrapper finish method failed
galaxy.jobs.runners ERROR 2019-05-15 21:56:00,636 [p:10617,w:0,m:1] [DRMAARunner.work_thread-3] (167907) Unhandled exception calling finish_job

Lots of these messages in /var/log/messages:

May 15 21:47:19 ip-X-X-X-X kernel: Out of memory: Kill process 10606 (uwsgi) score 14 or sacrifice child
May 15 21:47:19 ip-X-X-X-X kernel: Killed process 10606 (uwsgi) total-vm:1761168kB, anon-rss:464936kB, file-rss:0kB, shme
m-rss:124kB
May 15 21:47:19 ip-X-X-X-X kernel: sge_qmaster invoked oom-killer: gfp_mask=0x201da, order=0, oom_score_adj=0
May 15 21:47:19 ip-X-X-X-X kernel: sge_qmaster cpuset=/ mems_allowed=0
May 15 21:47:19 ip-X-X-X-X kernel: CPU: 4 PID: 13570 Comm: sge_qmaster Kdump: loaded Not tainted 3.10.0-957.10.1.el7.x86_
64 #1

[bernt-matthias]

If its reproducible I would suggest to insert some debugging code here:

galaxy/lib/galaxy/jobs/runners/__init__.py

Line 511 in f6011ba

log.exception("(%s/%s) Job wrapper finish method failed" % (job_id or '', external_job_id or ''))

or in one of the two places in this file

https://github.com/galaxyproject/galaxy/blob/f6011bab5b8adbabae4986a45849bb9158ffc8bb/lib/galaxy/jobs/runners/__init__.py

where Unhandled exception calling finish_job is printed. I guess best would be to print the Traceback to the log. Then it might be easier to find the reason.

[cheeseindustries]

@bernt-matthias Thanks! We actually resolved this issue ourselves. The problem was due to a bug in the lib/galaxy/objectstore/s3_multipart_upload.py module which was patched in the 19.05 branch. I just replaced that module on our instance with the one from 19.05 and all is well.

If anyone is curious, it seems that our issue stemmed from user jobs which generated large DAT files. When Galaxy would attempt to upload those files to S3, s3_multipart_upload.py would overflow Python's call stack causing the job handler to crash. Rinse and repeat a bunch of times, and the constant spawning of the job handlers caused the OOM condition we saw on our instance. Obviously this would only impact 19.01 users who are using Galaxy's AWS S3 integration.

Thanks again!