Use exception chaining & str(exc) (#1136)

* Use exception chaining & str(exc)

Use exception chaining (via raise_from which is a stub on python2) so
that the entire traceback is captured by the exception.

Explicitly coerce exceptions to str() in error messages so we only get
the exception message and not the entire representation (stacktrace
etc).

This should mostly bring py2/py3 error logging behavior back into
sync.

* Add future to dependencies.

* Fix raise_from type annotation to NoReturn

* Bump schema salad dependency

Author: Peter Amstutz

cwltool/builder.py

@@ -18,6 +18,7 @@
 from schema_salad.sourceline import SourceLine
 from schema_salad.ref_resolver import uri_file_path
 from six import iteritems, string_types
+from future.utils import raise_from
 from typing import IO
 from typing_extensions import (TYPE_CHECKING,  # pylint: disable=unused-import
                                Text, Type)
@@ -348,9 +349,9 @@ def _capture_files(f):
                         check_format(datum, self.do_eval(schema["format"]),
                                      self.formatgraph)
                     except validate.ValidationException as ve:
-                        raise WorkflowException(
+                        raise_from(WorkflowException(
                             "Expected value of '%s' to have format %s but\n "
-                            " %s" % (schema["name"], schema["format"], ve))
+                            " %s" % (schema["name"], schema["format"], ve)), ve)
 
                 visit_class(datum.get("secondaryFiles", []), ("File", "Directory"), _capture_files)
 

cwltool/command_line_tool.py

@@ -24,6 +24,7 @@
 from schema_salad.ref_resolver import file_uri, uri_file_path
 from schema_salad.sourceline import SourceLine
 from six import string_types
+from future.utils import raise_from
 
 from six.moves import map, urllib
 from typing_extensions import (TYPE_CHECKING,  # pylint: disable=unused-import
@@ -108,7 +109,7 @@ def run(self,
                 self.output_callback(ev, "success")
             except Exception as err:
                 _logger.warning(u"Failed to evaluate expression:\n%s",
-                                err, exc_info=runtimeContext.debug)
+                                Text(err), exc_info=runtimeContext.debug)
                 self.output_callback({}, "permanentFail")
 
     def job(self,
@@ -649,9 +650,9 @@ def makeWorkflowException(msg):
                 adjustFileObjs(ret, builder.mutation_manager.set_generation)
             return ret if ret is not None else {}
         except validate.ValidationException as e:
-            raise WorkflowException(
+            raise_from(WorkflowException(
                 "Error validating output record. " + Text(e) + "\n in "
-                + json_dumps(ret, indent=4))
+                + json_dumps(ret, indent=4)), e)
         finally:
             if builder.mutation_manager and readers:
                 for r in readers.values():

cwltool/executors.py

@@ -11,6 +11,7 @@
 import psutil
 from six import string_types, with_metaclass
 from typing_extensions import Text  # pylint: disable=unused-import
+from future.utils import raise_from
 from schema_salad.validate import ValidationException
 
 from .builder import Builder  # pylint: disable=unused-import
@@ -189,7 +190,7 @@ def run_jobs(self,
             raise
         except Exception as err:
             logger.exception("Got workflow error")
-            raise WorkflowException(Text(err))
+            raise_from(WorkflowException(Text(err)), err)
 
 
 class MultithreadedJobExecutor(JobExecutor):

cwltool/expression.py

@@ -8,6 +8,7 @@
 
 import six
 from six import string_types, u
+from future.utils import raise_from
 from typing_extensions import Text  # pylint: disable=unused-import
 # move to a regular typing import when Python 3.3-3.6 is no longer supported
 
@@ -143,16 +144,16 @@ def next_seg(parsed_string, remaining_string, current_value):  # type: (Text, Te
             try:
                 key = int(next_segment_str[1:-1])
             except ValueError as v:
-                raise WorkflowException(u(str(v)))
+                raise_from(WorkflowException(u(str(v))), v)
             if not isinstance(current_value, MutableSequence):
                 raise WorkflowException("%s is a %s, cannot index on int '%s'" % (parsed_string, type(current_value).__name__, key))
             if key >= len(current_value):
                 raise WorkflowException("%s list index %i out of range" % (parsed_string, key))
 
         try:
             return next_seg(parsed_string + remaining_string, remaining_string[m.end(0):], current_value[key])
-        except KeyError:
-            raise WorkflowException("%s doesn't have property %s" % (parsed_string, key))
+        except KeyError as e:
+            raise_from(WorkflowException("%s doesn't have property %s" % (parsed_string, key)), e)
     else:
         return current_value
 
@@ -295,6 +296,6 @@ def do_eval(ex,                       # type: Union[Text, Dict]
                                strip_whitespace=strip_whitespace)
 
         except Exception as e:
-            raise WorkflowException("Expression evaluation error:\n%s" % e)
+            raise_from(WorkflowException("Expression evaluation error:\n%s" % Text(e)), e)
     else:
         return ex

cwltool/job.py

@@ -24,6 +24,7 @@
 from prov.model import PROV
 from schema_salad.sourceline import SourceLine
 from six import PY2, with_metaclass
+from future.utils import raise_from
 from typing_extensions import (TYPE_CHECKING,  # pylint: disable=unused-import
                                Text)
 
@@ -344,14 +345,14 @@ def _execute(self,
         except OSError as e:
             if e.errno == 2:
                 if runtime:
-                    _logger.error(u"'%s' not found: %s", runtime[0], e)
+                    _logger.error(u"'%s' not found: %s", runtime[0], Text(e))
                 else:
-                    _logger.error(u"'%s' not found: %s", self.command_line[0], e)
+                    _logger.error(u"'%s' not found: %s", self.command_line[0], Text(e))
             else:
                 _logger.exception(u"Exception while running job")
             processStatus = "permanentFail"
         except WorkflowException as err:
-            _logger.error(u"[job %s] Job error:\n%s", self.name, err)
+            _logger.error(u"[job %s] Job error:\n%s", self.name, Text(err))
             processStatus = "permanentFail"
         except Exception as e:
             _logger.exception(u"Exception while running job")
@@ -659,8 +660,8 @@ def run(self,
                 container = "Singularity" if runtimeContext.singularity else "Docker"
                 _logger.debug(u"%s error", container, exc_info=True)
                 if docker_is_req:
-                    raise UnsupportedRequirement(
-                        "%s is required to run this tool: %s" % (container, err))
+                    raise_from(UnsupportedRequirement(
+                        "%s is required to run this tool: %s" % (container, Text(err))), err)
                 else:
                     raise WorkflowException(
                         "{0} is not available for this tool, try "

cwltool/main.py

@@ -733,18 +733,18 @@ def my_represent_none(self, data):  # pylint: disable=unused-argument
                 return 0
 
         except (validate.ValidationException) as exc:
-            _logger.error(u"Tool definition failed validation:\n%s", exc,
+            _logger.error(u"Tool definition failed validation:\n%s", Text(exc),
                           exc_info=args.debug)
             return 1
         except (RuntimeError, WorkflowException) as exc:
-            _logger.error(u"Tool definition failed initialization:\n%s", exc,
+            _logger.error(u"Tool definition failed initialization:\n%s", Text(exc),
                           exc_info=args.debug)
             return 1
         except Exception as exc:
             _logger.error(
                 u"I'm sorry, I couldn't load this CWL file%s.\nThe error was: %s",
                 try_again_msg,
-                exc if not args.debug else "",
+                Text(exc) if not args.debug else "",
                 exc_info=args.debug)
             return 1
 
@@ -770,7 +770,7 @@ def my_represent_none(self, data):  # pylint: disable=unused-argument
                     try:
                         os.makedirs(os.path.dirname(getattr(runtimeContext, dirprefix)))
                     except Exception as e:
-                        _logger.error("Failed to create directory: %s", e)
+                        _logger.error("Failed to create directory: %s", Text(e))
                         return 1
 
         if args.cachedir:
@@ -852,12 +852,12 @@ def loc_to_path(obj):
             return 0
 
         except (validate.ValidationException) as exc:
-            _logger.error(u"Input object failed validation:\n%s", exc,
+            _logger.error(u"Input object failed validation:\n%s", Text(exc),
                           exc_info=args.debug)
             return 1
         except UnsupportedRequirement as exc:
             _logger.error(
-                u"Workflow or tool uses unsupported feature:\n%s", exc,
+                u"Workflow or tool uses unsupported feature:\n%s", Text(exc),
                 exc_info=args.debug)
             return 33
         except WorkflowException as exc:
@@ -867,7 +867,7 @@ def loc_to_path(obj):
             return 1
         except Exception as exc:  # pylint: disable=broad-except
             _logger.error(
-                u"Unhandled error%s:\n  %s", try_again_msg, exc, exc_info=args.debug)
+                u"Unhandled error%s:\n  %s", try_again_msg, Text(exc), exc_info=args.debug)
             return 1
 
     finally:

cwltool/process.py

@@ -24,6 +24,7 @@
 from ruamel.yaml.comments import CommentedMap, CommentedSeq
 from six import PY3, iteritems, itervalues, string_types, with_metaclass
 from six.moves import urllib
+from future.utils import raise_from
 from typing_extensions import (TYPE_CHECKING,  # pylint: disable=unused-import
                                Text)
 from schema_salad import schema, validate
@@ -556,7 +557,7 @@ def __init__(self,
                     _logger.error(
                         "Failed to read options file %s",
                         loadingContext.js_hint_options_file)
-                    raise err
+                    raise
             else:
                 validate_js_options = None
             if self.doc_schema is not None:
@@ -654,7 +655,7 @@ def inc(d):  # type: (List[int]) -> None
 """ % (filecount[0], k))))
 
         except (validate.ValidationException, WorkflowException) as err:
-            raise WorkflowException("Invalid job input record:\n" + Text(err))
+            raise_from(WorkflowException("Invalid job input record:\n" + Text(err)), err)
 
         files = []  # type: List[Dict[Text, Text]]
         bindings = CommentedSeq()

cwltool/sandboxjs.py

@@ -12,6 +12,7 @@
 from typing import Any, Dict, List, Tuple, Union
 
 import six
+from future.utils import raise_from
 from pkg_resources import resource_stream
 from typing_extensions import Text  # pylint: disable=unused-import
 # move to a regular typing import when Python 3.3-3.6 is no longer supported
@@ -374,6 +375,6 @@ def fn_linenum():  # type: () -> Text
     try:
         return json.loads(stdout)
     except ValueError as err:
-        raise JavascriptException(
+        raise_from(JavascriptException(
             u"{}\nscript was:\n{}\nstdout was: '{}'\nstderr was: '{}'\n".format(
-                err, fn_linenum(), stdout, stderr))
+                err, fn_linenum(), stdout, stderr)), err)

cwltool/workflow.py

@@ -17,6 +17,7 @@
 from schema_salad.sourceline import SourceLine
 from six import string_types, iteritems
 from six.moves import range
+from future.utils import raise_from
 from typing_extensions import Text  # pylint: disable=unused-import
 # move to a regular typing import when Python 3.3-3.6 is no longer supported
 
@@ -249,7 +250,7 @@ def do_output_callback(self, final_output_callback):
                 "outputSource", incomplete=True)
         except WorkflowException as err:
             _logger.error(
-                u"[%s] Cannot collect workflow output: %s", self.name, err)
+                u"[%s] Cannot collect workflow output: %s", self.name, Text(err))
             self.processStatus = "permanentFail"
         if self.prov_obj and self.parent_wf \
                 and self.prov_obj.workflow_run_uri != self.parent_wf.workflow_run_uri:
@@ -464,7 +465,7 @@ def job(self,
                         step.iterable = self.try_make_job(
                             step, output_callback, runtimeContext)
                     except WorkflowException as exc:
-                        _logger.error(u"[%s] Cannot make job: %s", step.name, exc)
+                        _logger.error(u"[%s] Cannot make job: %s", step.name, Text(exc))
                         _logger.debug("", exc_info=True)
                         self.processStatus = "permanentFail"
 
@@ -480,7 +481,7 @@ def job(self,
                             else:
                                 break
                     except WorkflowException as exc:
-                        _logger.error(u"[%s] Cannot make job: %s", step.name, exc)
+                        _logger.error(u"[%s] Cannot make job: %s", step.name, Text(exc))
                         _logger.debug("", exc_info=True)
                         self.processStatus = "permanentFail"
 
@@ -633,9 +634,9 @@ def __init__(self,
         except validate.ValidationException as vexc:
             if loadingContext.debug:
                 _logger.exception("Validation exception")
-            raise WorkflowException(
+            raise_from(WorkflowException(
                 u"Tool definition %s failed validation:\n%s" %
-                (toolpath_object["run"], validate.indent(str(vexc))))
+                (toolpath_object["run"], validate.indent(str(vexc)))), vexc)
 
         validation_errors = []
         self.tool = toolpath_object = copy.deepcopy(toolpath_object)
@@ -804,7 +805,7 @@ def job(self,
             raise
         except Exception as exc:
             _logger.exception("Unexpected exception")
-            raise WorkflowException(Text(exc))
+            raise_from(WorkflowException(Text(exc)), exc)
 
     def visit(self, op):
         self.embedded_tool.visit(op)
@@ -871,7 +872,7 @@ def parallel_steps(steps, rc, runtimeContext):
                 if made_progress:
                     break
             except WorkflowException as exc:
-                _logger.error(u"Cannot make scatter job: %s", exc)
+                _logger.error(u"Cannot make scatter job: %s", Text(exc))
                 _logger.debug("", exc_info=True)
                 rc.receive_scatter_output(index, {}, "permanentFail")
         if not made_progress and rc.completed < rc.total:

requirements.txt

@@ -2,7 +2,7 @@ requests>=2.4.3
 ruamel.yaml>=0.12.4,<=0.15.77
 rdflib>=4.2.2,<4.3
 shellescape>=3.4.1,<3.5
-schema-salad>=4.0,<5
+schema-salad>=4.4,<5
 typing>=3.5.3; python_version<"3.6"
 pathlib2==2.3.2; python_version<"3"
 prov==1.5.1
@@ -13,3 +13,4 @@ scandir
 subprocess32 >= 3.5.0; os.name=="posix" and python_version<"3.5"
 typing-extensions
 coloredlogs
+future