common-workflow-language / common-workflow-language/cwltool

Evaluation expressions that timeout can raise JSONDecodeError

Open
#1,999 0 comments 0 reactions 0 assignees View on GitHub
Dominant language
Python
Stars
376
Forks
255
Avg merge
2d 7h
Merged PRs (30d)
12

Description

## Expected Behavior

When an evaluation expression exceeds the timeout, the resulting error should be clear that is the cause.

## Actual Behavior

At least some of the time, this situation raises a `JSONDecodeError` exception. If the user doesn't realize the timeout might be the issue, this can cause them to lose a lot of time trying to debug an issue in the expression itself where none exists.

This is sort of a sequel issue to #1680.

## Workflow Code

[eval-timeout.zip](https://github.com/common-workflow-language/cwltool/files/15297660/eval-timeout.zip)

## Full Traceback

This issue was noticed with a "real" expression that similarly built a large array of an array of files, and hit the default evaluation timeout. However, you can reproduce the issue using the attached minimal reproduction and a small evaluation timeout:

```
% venv/bin/cwltool --debug --eval-timeout=.1 wf.cwl array-in.yml
INFO venv/bin/cwltool 3.1.20240404144621
INFO Resolved 'wf.cwl' to 'file:///home/brett/Scratch/wf.cwl'
DEBUG [workflow ] initialized from file:///home/brett/Scratch/wf.cwl
INFO [workflow ] start
DEBUG [workflow ] inputs {}
INFO [workflow ] starting step build_array
DEBUG [step build_array] job input {}
DEBUG [step build_array] evaluated job input to {}
INFO [step build_array] start
Expecting value: line 1 column 1 (char 0)
script was:
01 "use strict";
02 var inputs = {};
03 var self = null;
04 var runtime = {
05 "cores": 1,
06 "ram": 256,
07 "tmpdirSize": 1024,
08 "outdirSize": 1024,
09 "tmpdir": null,
10 "outdir": null
11 };
12 (function(){
13 var result = [];
14 for (var i=0; i<100000; i++) {
15 var arr = [];
16 result.push(arr);
17 for (var j=0; j<100000; j++) {
18 var num = i * 100000 + j;
19 arr.push({
20 class: "File",
21 location: "file:///tmp/array.cwl/file" + num.toString() + ".fq",
22 format: "http://edamontology.org/format_1930"
23 });
24 }
25 }
26 return {"out_arr": result};
27 })()
stdout was: ''
stderr was: ''
Traceback (most recent call last):
File "/home/brett/Scratch/venv/lib/python3.12/site-packages/cwl_utils/sandboxjs.py", line 512, in eval
return cast(CWLOutputType, json.loads(stdout))
^^^^^^^^^^^^^^^^^^
File "/usr/local/lib/python3.12/json/__init__.py", line 346, in loads
return _default_decoder.decode(s)
^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/usr/local/lib/python3.12/json/decoder.py", line 337, in decode
obj, end = self.raw_decode(s, idx=_w(s, 0).end())
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/usr/local/lib/python3.12/json/decoder.py", line 355, in raw_decode
raise JSONDecodeError("Expecting value", s, err.value) from None
json.decoder.JSONDecodeError: Expecting value: line 1 column 1 (char 0)

The above exception was the direct cause of the following exception:

[Note: Everything from here on is basically propagation of the same root cause exception, but here it is for completeness:]

Traceback (most recent call last):
File "/home/brett/Scratch/venv/lib/python3.12/site-packages/cwl_utils/expression.py", line 315, in do_eval
return interpolate(
^^^^^^^^^^^^
File "/home/brett/Scratch/venv/lib/python3.12/site-packages/cwl_utils/expression.py", line 215, in interpolate
e = evaluator(
^^^^^^^^^^
File "/home/brett/Scratch/venv/lib/python3.12/site-packages/cwl_utils/expression.py", line 161, in evaluator
return cast(CWLOutputType, js_engine.eval(ex, jslib, **kwargs))
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/home/brett/Scratch/venv/lib/python3.12/site-packages/cwl_utils/sandboxjs.py", line 514, in eval
raise JavascriptException(
cwl_utils.errors.JavascriptException: Expecting value: line 1 column 1 (char 0)
script was:
01 "use strict";
02 var inputs = {};
03 var self = null;
04 var runtime = {
05 "cores": 1,
06 "ram": 256,
07 "tmpdirSize": 1024,
08 "outdirSize": 1024,
09 "tmpdir": null,
10 "outdir": null
11 };
12 (function(){
13 var result = [];
14 for (var i=0; i<100000; i++) {
15 var arr = [];
16 result.push(arr);
17 for (var j=0; j<100000; j++) {
18 var num = i * 100000 + j;
19 arr.push({
20 class: "File",
21 location: "file:///tmp/array.cwl/file" + num.toString() + ".fq",
22 format: "http://edamontology.org/format_1930"
23 });
24 }
25 }
26 return {"out_arr": result};
27 })()
stdout was: ''
stderr was: ''

ERROR Got workflow error
[error messages and tracebacks repeat from here]
```

## Your Environment
* cwltool version: 3.1.20240404144621

## Diagnosis

This occurs because of a few related issues in the way that the expression evaluation timeout is implemented:

* The evaluator stops reading expression output as soon as the timeout has been reached (i.e., the child process has been sent SIGKILL): https://github.com/common-workflow-language/cwl-utils/blob/0ad6983898f0d9001fe0f416f97c4d8b940e384a/cwl_utils/sandboxjs.py#L252
* Then it unconditionally removes the "process finished str" from the output. This is a bug because if the child process timed out, there's no reason to expect that string to be in the output, so this is just arbitrary truncation: https://github.com/common-workflow-language/cwl-utils/blob/0ad6983898f0d9001fe0f416f97c4d8b940e384a/cwl_utils/sandboxjs.py#L269-L270
* Then it polls the child process a couple times, and determines success based on this. If the child process has not actually received the SIGKILL and ended yet, it's possible `nodejs.poll()` will return `None`, causing the conditional to assume it succeeded: https://github.com/common-workflow-language/cwl-utils/blob/0ad6983898f0d9001fe0f416f97c4d8b940e384a/cwl_utils/sandboxjs.py#L272-L280

In general, there's a lot of code in `exec_js_process` that seems like it could be handled by the subprocess module directly, following the example code documented with [`Popen.communicate`](https://docs.python.org/3/library/subprocess.html#subprocess.Popen.communicate). A rough sketch would be something like:

```python
def exec_js_process(
self,
js_text: str,
timeout: float = default_timeout,
...,
) -> Tuple[int, str, str]:
...
with subprocess.Popen(
["nodejs", "--eval", js_text],
stdin=subprocess.DEVNULL,
stdout=subprocess.PIPE,
stderr=subprocess.PIPE,
text=True,
encoding='utf-8',
) as nodejs:
try:
stdoutdata, stderrdata = nodejs.communicate(timeout=timeout)
except subprocess.TimeoutExpired:
nodejs.kill()
stdoutdata, stderrdata = nodejs.communicate()
returncode = -1
else:
returncode = nodejs.returncode
return returncode, stdoutdata, stderrdata
```

This would still need code at the top to find the name of the Node command, handle other arguments, etc. But I think this could replace all the process and timeout management code that currently lives in the method, while addressing the bugs above.

Contributor guide

Open the contributing guide

Assessment

This issue has not been assessed yet.

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.