Error bubbling or better error documentation about q2-dada2 HOT 19 CLOSED

Sorry I haven't looked into this more, but is stderr exclusively used for errors in R and dada2? I know this isn't the case for fasttree or mafft, but we could probably just naively pass along stderr if it's clean enough. That alone could be a huge improvement.

from q2-dada2.

It appears that Rscript invocations (which is how the plugin is calling the dada2 code) output print and cat statements to stdout, and message, warning and stop messages to stderr.

The message output wouldn't be desired (that doesn't indicate the kind of problem usually associated with stderr) but capturing and reporting the warning and stop messages in stderr would make sense, as they correspond to the kind of messages generally expected in stderr from shell commands.

So, I think this is a good idea that is definitely worth trying. If there are too many messages, we also can modify the R code to suppress them to keep things cleaner.

from q2-dada2.

This may be a non-issue. It appears that stdout/stderr is being captured and displayed if there's an error raised in R. I chatted with @maxvonhippel and showed him the current behavior and it appears to be working as expected.

The confusion was related to the CLI capturing stdout/stderr and dumping it in a log file. For example, this is what users will see when a command fails within R:

$ qiime dada2 denoise-single --i-demultiplexed-seqs demux.qza --p-trim-left 0 --p-trunc-len 5000 --o-representative-sequences rep-seqs-dada2.qza --o-table table-dada2.qza --p-n-threads 0

Plugin error from dada2:

  Command '['run_dada_single.R', '/tmp/qiime2-archive-6jn0vrm3/b0aa4c34-
  2cfe-4d84-a04c-1185cf3d31dc/data', '/tmp/tmprc6rl9ev/output.tsv.biom',
  '/tmp/tmprc6rl9ev', '5000', '0', '2.0', '2', 'consensus', '1.0', '0',
  '1000000']' returned non-zero exit status 2

Debug info has been saved to /tmp/qiime2-q2cli-err-g3hwwrqf.log.

Here's what's in the debug log created by the CLI:

$ cat /tmp/qiime2-q2cli-err-g3hwwrqf.log
Running external command line application(s). This may print messages to stdout and/or stderr.
The command(s) being run are below. These commands cannot be manually re-run as they will depend on temporary files that no longer exist.

Command: run_dada_single.R /tmp/qiime2-archive-6jn0vrm3/b0aa4c34-2cfe-4d84-a04c-1185cf3d31dc/data /tmp/tmprc6rl9ev/output.tsv.biom /tmp/tmprc6rl9ev 5000 0 2.0 2 consensus 1.0 0 1000000

R version 3.3.1 (2016-06-21) 
Loading required package: Rcpp
Warning messages:
1: multiple methods tables found for ‘arbind’ 
2: multiple methods tables found for ‘acbind’ 
3: replacing previous import ‘IRanges::arbind’ by ‘SummarizedExperiment::arbind’ when loading ‘GenomicAlignments’ 
4: replacing previous import ‘IRanges::acbind’ by ‘SummarizedExperiment::acbind’ when loading ‘GenomicAlignments’ 
5: multiple methods tables found for ‘left’ 
6: multiple methods tables found for ‘right’ 
DADA2 R package version: 1.4.0 
1) Filtering The filter removed all reads: /tmp/tmprc6rl9ev/L2S204_1_L001_R1_001.fastq.gz not written.
xThe filter removed all reads: /tmp/tmprc6rl9ev/L5S155_2_L001_R1_001.fastq.gz not written.
x
Error: No reads passed the filter (was truncLen longer than the read length?)
Traceback (most recent call last):
  File "/home/jairideout/dev/qiime2/q2cli/q2cli/commands.py", line 222, in __call__
    results = action(**arguments)
  File "<decorator-gen-240>", line 2, in denoise_single
  File "/home/jairideout/dev/qiime2/qiime2/qiime2/sdk/action.py", line 200, in callable_wrapper
    output_types, provenance)
  File "/home/jairideout/dev/qiime2/qiime2/qiime2/sdk/action.py", line 297, in _callable_executor_
    output_views = callable(**view_args)
  File "/home/jairideout/dev/qiime2/q2-dada2/q2_dada2/_denoise.py", line 126, in denoise_single
    run_commands([cmd])
  File "/home/jairideout/dev/qiime2/q2-dada2/q2_dada2/_denoise.py", line 35, in run_commands
    subprocess.run(cmd, check=True)
  File "/home/jairideout/miniconda3/envs/qiime2/lib/python3.5/subprocess.py", line 398, in run
    output=stdout, stderr=stderr)
subprocess.CalledProcessError: Command '['run_dada_single.R', '/tmp/qiime2-archive-6jn0vrm3/b0aa4c34-2cfe-4d84-a04c-1185cf3d31dc/data', '/tmp/tmprc6rl9ev/output.tsv.biom', '/tmp/tmprc6rl9ev', '5000', '0', '2.0', '2', 'consensus', '1.0', '0', '1000000']' returned non-zero exit status 2

This same info is available when passing --verbose to the CLI command:

$ qiime dada2 denoise-single --i-demultiplexed-seqs demux.qza --p-trim-left 0 --p-trunc-len 5000 --o-representative-sequences rep-seqs-dada2.qza --o-table table-dada2.qza --p-n-threads 0 --verbose 
Running external command line application(s). This may print messages to stdout and/or stderr.
The command(s) being run are below. These commands cannot be manually re-run as they will depend on temporary files that no longer exist.

Command: run_dada_single.R /tmp/qiime2-archive-4l0ksjei/b0aa4c34-2cfe-4d84-a04c-1185cf3d31dc/data /tmp/tmpwe3m5tmm/output.tsv.biom /tmp/tmpwe3m5tmm 5000 0 2.0 2 consensus 1.0 0 1000000

R version 3.3.1 (2016-06-21) 
Loading required package: Rcpp
Warning messages:
1: multiple methods tables found for ‘arbind’ 
2: multiple methods tables found for ‘acbind’ 
3: replacing previous import ‘IRanges::arbind’ by ‘SummarizedExperiment::arbind’ when loading ‘GenomicAlignments’ 
4: replacing previous import ‘IRanges::acbind’ by ‘SummarizedExperiment::acbind’ when loading ‘GenomicAlignments’ 
5: multiple methods tables found for ‘left’ 
6: multiple methods tables found for ‘right’ 
DADA2 R package version: 1.4.0 
1) Filtering The filter removed all reads: /tmp/tmpwe3m5tmm/L2S204_1_L001_R1_001.fastq.gz not written.
xThe filter removed all reads: /tmp/tmpwe3m5tmm/L5S155_2_L001_R1_001.fastq.gz not written.
x
Error: No reads passed the filter (was truncLen longer than the read length?)
Traceback (most recent call last):
  File "/home/jairideout/dev/qiime2/q2cli/q2cli/commands.py", line 222, in __call__
    results = action(**arguments)
  File "<decorator-gen-240>", line 2, in denoise_single
  File "/home/jairideout/dev/qiime2/qiime2/qiime2/sdk/action.py", line 200, in callable_wrapper
    output_types, provenance)
  File "/home/jairideout/dev/qiime2/qiime2/qiime2/sdk/action.py", line 297, in _callable_executor_
    output_views = callable(**view_args)
  File "/home/jairideout/dev/qiime2/q2-dada2/q2_dada2/_denoise.py", line 126, in denoise_single
    run_commands([cmd])
  File "/home/jairideout/dev/qiime2/q2-dada2/q2_dada2/_denoise.py", line 35, in run_commands
    subprocess.run(cmd, check=True)
  File "/home/jairideout/miniconda3/envs/qiime2/lib/python3.5/subprocess.py", line 398, in run
    output=stdout, stderr=stderr)
subprocess.CalledProcessError: Command '['run_dada_single.R', '/tmp/qiime2-archive-4l0ksjei/b0aa4c34-2cfe-4d84-a04c-1185cf3d31dc/data', '/tmp/tmpwe3m5tmm/output.tsv.biom', '/tmp/tmpwe3m5tmm', '5000', '0', '2.0', '2', 'consensus', '1.0', '0', '1000000']' returned non-zero exit status 2

Plugin error from dada2:

  Command '['run_dada_single.R', '/tmp/qiime2-archive-4l0ksjei/b0aa4c34-
  2cfe-4d84-a04c-1185cf3d31dc/data', '/tmp/tmpwe3m5tmm/output.tsv.biom',
  '/tmp/tmpwe3m5tmm', '5000', '0', '2.0', '2', 'consensus', '1.0', '0',
  '1000000']' returned non-zero exit status 2

See above for debug info.

The error handling/display works the same way if an error is raised on the Python side:

$ qiime dada2 denoise-single --i-demultiplexed-seqs demux.qza --p-trim-left 0 --p-trunc-len -1 --o-representative-sequences rep-seqs-dada2.qza --o-table table-dada2.qza --p-n-threads 0

Plugin error from dada2:

  Argument to 'trunc_len' was -1, should be non-negative.

Debug info has been saved to /tmp/qiime2-q2cli-err-t7y794ah.log.

Contents of debug log file:

$ cat /tmp/qiime2-q2cli-err-t7y794ah.log
Traceback (most recent call last):
  File "/home/jairideout/dev/qiime2/q2cli/q2cli/commands.py", line 222, in __call__
    results = action(**arguments)
  File "<decorator-gen-240>", line 2, in denoise_single
  File "/home/jairideout/dev/qiime2/qiime2/qiime2/sdk/action.py", line 200, in callable_wrapper
    output_types, provenance)
  File "/home/jairideout/dev/qiime2/qiime2/qiime2/sdk/action.py", line 297, in _callable_executor_
    output_views = callable(**view_args)
  File "/home/jairideout/dev/qiime2/q2-dada2/q2_dada2/_denoise.py", line 114, in denoise_single
    _check_inputs(**locals())
  File "/home/jairideout/dev/qiime2/q2-dada2/q2_dada2/_denoise.py", line 81, in _check_inputs
    % (param, arg, explanation))
ValueError: Argument to 'trunc_len' was -1, should be non-negative.

When run with --verbose:

$ qiime dada2 denoise-single --i-demultiplexed-seqs demux.qza --p-trim-left 0 --p-trunc-len -1 --o-representative-sequences rep-seqs-dada2.qza --o-table table-dada2.qza --p-n-threads 0 --verbose
Traceback (most recent call last):
  File "/home/jairideout/dev/qiime2/q2cli/q2cli/commands.py", line 222, in __call__
    results = action(**arguments)
  File "<decorator-gen-240>", line 2, in denoise_single
  File "/home/jairideout/dev/qiime2/qiime2/qiime2/sdk/action.py", line 200, in callable_wrapper
    output_types, provenance)
  File "/home/jairideout/dev/qiime2/qiime2/qiime2/sdk/action.py", line 297, in _callable_executor_
    output_views = callable(**view_args)
  File "/home/jairideout/dev/qiime2/q2-dada2/q2_dada2/_denoise.py", line 114, in denoise_single
    _check_inputs(**locals())
  File "/home/jairideout/dev/qiime2/q2-dada2/q2_dada2/_denoise.py", line 81, in _check_inputs
    % (param, arg, explanation))
ValueError: Argument to 'trunc_len' was -1, should be non-negative.

Plugin error from dada2:

  Argument to 'trunc_len' was -1, should be non-negative.

See above for debug info.

It appears that error handling is consistent on both Python and R sides, and we're capturing stdout/stderr from R. Thus, I don't think there's much to change here, but perhaps we can tweak things to make it a little clearer to users. @maxvonhippel and I chatted about:

• Prepend some text to the non-zero exit status message users see when an error occurs in R:

There was an error when running DADA2 in R:

Command '['run_dada_single.R', '/tmp/qiime2-archive-4l0ksjei/b0aa4c34-
  2cfe-4d84-a04c-1185cf3d31dc/data', '/tmp/tmpwe3m5tmm/output.tsv.biom',
  '/tmp/tmpwe3m5tmm', '5000', '0', '2.0', '2', 'consensus', '1.0', '0',
  '1000000']' returned non-zero exit status 2

• Add a section to the q2cli tutorial describing --verbose and the debug log.

• Add a blank line to the CLI's log file text to highlight the debug log

$ qiime dada2 denoise-single ...

Plugin error from dada2:

  <error message>

See above for debug info.

$

@benjjneb @ebolyen @maxvonhippel does this all make sense, or am I missing something here? Any other suggestions/tweaks that can be made to make things clearer?

Having an explicit mapping of DADA2 error codes to user-friendly messages would be great, but we'd need to have a stable exit code "API" across DADA2 versions to pull it off. @benjjneb are the DADA2 exit codes generally stable across package versions?

from q2-dada2.

The initial point of this conversation was that stderr is already reasonably short, and if it isn't it could be made shorter by slightly augmenting the R scripts. --verbose collates both stdout and stderr so it really isn't the same thing here.

Basically instead of passing check to the subprocess call, we would check the exit code ourselves and construct something like:

process = subprocess.run(...)
if process.exit_code:
    raise RException(process.exit_code, process.stderr)

The only thing that might need to change would be to stop emitting messages to stderr like @benjjneb noted.

This is going to take some coordination on both the R and Python side, but it's easier than an exit-code map (which is also a fine idea).

from q2-dada2.

@jairideout

There are some commands in R eg. suppressWarnings that can be used to simply not write out warnings, and will easily suppress those unimportant "multiple methods" warnings. I will start by cleaning some of that up, with the goal of getting to a point where the stderr is clean enough to be reported by the plugin when it exits with an error.

from q2-dada2.

Agree this would be useful. Right now the only communication from R to python is happening via the exit code, and its only being used for one specific type of error (no reads passed filter).

I'll note that the R code is printing to stdout useful progress and error information. That's suppressed by the plugin though (unless verbose mode is turned on).

from q2-dada2.

@jairideout my understanding was the goal was simply to elevate R's stderr into here:

$ qiime dada2 denoise-single ...

Plugin error from dada2:

  <Whatever R produced on stderr here>

Debug info has been saved to /tmp/qiime2-q2cli-err-g3hwwrqf.log.

We're not arguing that what it is doing is wrong, it's just that the following exception:

Command '['run_dada_single.R', '/tmp/qiime2-archive-4l0ksjei/b0aa4c34-
  2cfe-4d84-a04c-1185cf3d31dc/data', '/tmp/tmpwe3m5tmm/output.tsv.biom',
  '/tmp/tmpwe3m5tmm', '5000', '0', '2.0', '2', 'consensus', '1.0', '0',
  '1000000']' returned non-zero exit status 2

is essentially useless to the end use (maybe the exit code is worthwhile, but beyond that...)

from q2-dada2.

I am good with that plan. It does look like duplicating stderr so that the last line can even be read is not easy at all. It would required a re-implementation of tee with all kinds of fun os.fork and os.dup2 calls. This assumes we want stdout and stderr to be written and echo'ed in real-time (which I think is pretty important so that you can follow the entire process of what happened and when/where the failure occurred).

from q2-dada2.

@jairideout this all makes sense. I think my impression of inconsistent error handling was primarily because this:

Command '['run_dada_single.R', '/tmp/qiime2-archive-4l0ksjei/b0aa4c34-
  2cfe-4d84-a04c-1185cf3d31dc/data', '/tmp/tmpwe3m5tmm/output.tsv.biom',
  '/tmp/tmpwe3m5tmm', '5000', '0', '2.0', '2', 'consensus', '1.0', '0',
  '1000000']' returned non-zero exit status 2

... is not an informative, immediately helpful message to the average, non-technical user in the way that this is:

Argument to 'trunc_len' was -1, should be non-negative.

That said, as we discussed, for now, mapping exit codes to nice summary messages for dada2 is probably not worthwhile. I do think however that adding There was an error when running DADA2 in R:, as you mention in your first bullet point, would really help. This would give non-technical users a piece of information they can immediately understand, without needing the intuition of:

Ok, this array of commands is what was given to os in python and then executed in a shell I didn't see, and this is the exit code from that process I didn't see in my shell visibly in front of me, and I need to look at the R configuration to debug this rather than look at Qiime2

.

from q2-dada2.

@ebolyen I agree, but the concern is that the error that would be elevated seems to be pretty likely to be very long (looking at the debug log files produced at least). Which would kind of seem to undermine the whole point of the verbose flag, if the output was naively almost as verbose as when the user specifies verbose be True. Therefore it seems like we would need to map exit codes to shorter summary messages, as we do here, which could be a lot of work and also could be onerous if/when dada2 updates its exit codes etc.

from q2-dada2.

Chiming in a bit late, the current behavior @jairideout described does seem reasonable, but I also agree that having a more informative output immediately to the user (not just the log file) upon failures would be helpful.

There seem to be two options: emit the output of stderr from the R script upon a failure, or map errors to exit codes that then trigger useful text on the python side.

I think that the stderr output is the better way to go, especially as I suspect that messages can be redirected from stderr to stdout on the R side, leaving just the warnings and errors as desired.

Rscript calls do not to my knowledge naturally provide useful exit codes, so capturing the error and assigning an exit code would all have to be done by hand, which I think will be quite a bit harder to do in a way that covers all possible errors.

So if I fix the message issue, is it fairly easy on the python side to emit the stderr from the Rscript call upon a failure?

from q2-dada2.

Thanks for the discussion, @maxvonhippel @ebolyen @benjjneb!

@ebolyen @benjjneb, what you are describing makes sense (i.e. capturing and displaying stderr in the Python exception message). I understand that the R error message will usually be short, and thus appropriate for inclusion in the Python exception message. However, warnings are also printed to stderr, which are potentially of use to the user but are too long to include in a Python exception. For example, here's what the R stdout and stderr look like:

stdout:

Running external command line application(s). This may print messages to stdout and/or stderr.
The command(s) being run are below. These commands cannot be manually re-run as they will depend on temporary files that no longer exist.

Command: run_dada_single.R /tmp/qiime2-archive-5gyimnjn/b0aa4c34-2cfe-4d84-a04c-1185cf3d31dc/data /tmp/tmpi11vx2_t/output.tsv.biom /tmp/tmpi11vx2_t 5000 0 2.0 2 consensus 1.0 0 1000000

R version 3.3.1 (2016-06-21) 
DADA2 R package version: 1.4.0 
1) Filtering xx

stderr:

Loading required package: Rcpp
Warning messages:
1: multiple methods tables found for ‘arbind’ 
2: multiple methods tables found for ‘acbind’ 
3: replacing previous import ‘IRanges::arbind’ by ‘SummarizedExperiment::arbind’ when loading ‘GenomicAlignments’ 
4: replacing previous import ‘IRanges::acbind’ by ‘SummarizedExperiment::acbind’ when loading ‘GenomicAlignments’ 
5: multiple methods tables found for ‘left’ 
6: multiple methods tables found for ‘right’ 
The filter removed all reads: /tmp/tmpi11vx2_t/L2S204_1_L001_R1_001.fastq.gz not written.
The filter removed all reads: /tmp/tmpi11vx2_t/L5S155_2_L001_R1_001.fastq.gz not written.
Error: No reads passed the filter (was truncLen longer than the read length?)

Running with @benjjneb's idea, we could modify the R scripts to send message and warning to stdout, so that only the R error message is included in stderr. However, from searching around it doesn't appear possible to redirect all message, warning, stop, and quit calls to stdout (e.g. see this post and this post). We can update the R scripts in this repo to use cat (stdout) instead of message, warning, etc. but AFAIK we aren't able to control how other R libraries/scripts behave in this respect (i.e. those invoked by the dada2 R scripts).

@benjjneb do you have any ideas for how to accomplish what I'm describing above? My apologies if I'm missing something obvious here (I'm fairly clueless when it comes to R).

from q2-dada2.

Another option might be to just echo the last line of stderr.

from q2-dada2.

I will start by cleaning some of that up, with the goal of getting to a point where the stderr is clean enough to be reported by the plugin when it exits with an error.

@benjjneb thanks, that'll be really helpful!

Another option might be to just echo the last line of stderr.

That's a good idea! It should work with the current error messages produced by the R scripts.

Another idea is to use some sort of identifier/tag in the error message(s) we want displayed in the Python exception. Then on the Python side, stderr can be easily parsed and the relevant part of the error message displayed. For example, the R scripts could emit error messages starting with "R DADA2 Error: ..." or something like that.

With either of these solutions, the existing stdout/stderr behavior in the R scripts could remain as-is and we wouldn't have to suppress certain warnings/messages/etc. @ebolyen's solution sounds simpler and may be enough for our purposes here. If we want to get fancier than that, explicit exit codes is probably the better way to go in the long run. What do you guys think?

from q2-dada2.

Another idea is to use some sort of identifier/tag in the error message(s) we want displayed in the Python exception. Then on the Python side, stderr can be easily parsed and the relevant part of the error message displayed. For example, the R scripts could emit error messages starting with "R DADA2 Error: ..." or something like that.

I think one of the more compelling reasons for this change is to handle situations where R itself crashes (often because it is out of memory). What kind of error you get when that happens is pretty hard to predict. For the most part there really isn't any good reason for the R script to fail (other than the one exit code we are catching) as we validate everything in Python, so this would ideally target situations where we don't really have that level of control.

from q2-dada2.

I'm not sure I understand your followup @ebolyen -- are you proposing we go with your solution (parsing the final line), the solution I proposed, or something different?

from q2-dada2.

I think stderr capture of some kind is probably necessary to handle the unexpected errors from the language/lower level libraries. But I don't expect parsing out a substring or exit codes to really work in that situation, as we don't have much control over what happens when things catastrophically fail.

This is mostly what we noticed in the LV workshop, the errors were never really something the dada2 code was producing, it usually came from elsewhere. So it seems like either making stderr shorter, or only grabbing the last line which we assume to relate to whatever fatal error the script encountered would be the most robust way of handling this.

from q2-dada2.

Thanks for clarifying! It sounds like error parsing (using tags or the final line) nor exit code mappings aren't going to work great in all situations. Handling stdout/stderr from external applications will get tackled in qiime2/qiime2#224 when we have explicit support for plugins with external commands -- it's probably better to come up with a consistent strategy then and update existing plugins to conform to it.

For now, how about leaving the behavior as-is, since it's consistent with how other plugins work and the current behavior isn't lossy (i.e. the user has access to all stdout/stderr produced by the command)? Having @benjjneb clean up the stdout/stderr would be useful, and those improvements could be made at any time.

If we decide to leave the behavior as-is, I'd be happy to make those other updates @maxvonhippel proposed (listed in my comment) to help users find the error log produced by q2cli.

from q2-dada2.

Note: @ebolyen's merged PR implements @maxvonhippel's first suggestion from a previous comment:

Prepend some text to the non-zero exit status message users see when an error occurs in R:

I created an issue on the docs repo to track @maxvonhippel's second suggestion:

Add a section to the q2cli tutorial describing --verbose and the debug log.

I created another issue to discuss ways of making q2cli's debug output easier to notice:

Add a blank line to the CLI's log file text to highlight the debug log

Thanks everyone for the discussion!

from q2-dada2.