[engine] Support tracebacks in engine traces; only show them w/ flag (#…

…4549)

### Problem
Tracebacks from within rules don't show up in engine traces when --print-exception-stacktraces is enabled. #4446

### Solution
Capture tracebacks and carry them through the engine.

Also, only print traces when --print-exception-stacktraces is enabled.

### Result

Traces include the exception trace. Traces are only shown when --print-exception-stacktraces is enabled.

src/python/pants/bin/engine_initializer.py

@@ -85,15 +85,16 @@ def warm_product_graph(self, target_roots):
     if result.error:
       raise result.error
 
-  def create_build_graph(self, target_roots, build_root=None):
+  def create_build_graph(self, target_roots, build_root=None, include_trace_on_error=True):
     """Construct and return a `BuildGraph` given a set of input specs.
 
     :param TargetRoots target_roots: The targets root of the request.
     :param string build_root: The build root.
     :returns: A tuple of (BuildGraph, AddressMapper).
     """
     logger.debug('target_roots are: %r', target_roots)
-    graph = LegacyBuildGraph.create(self.scheduler, self.engine, self.symbol_table_cls)
+    graph = LegacyBuildGraph.create(self.scheduler, self.engine, self.symbol_table_cls,
+                                    include_trace_on_error=include_trace_on_error)
     logger.debug('build_graph is: %s', graph)
     with self.scheduler.locked():
       # Ensure the entire generator is unrolled.
@@ -117,7 +118,8 @@ def setup_legacy_graph(pants_ignore_patterns,
                          symbol_table_cls=None,
                          build_ignore_patterns=None,
                          exclude_target_regexps=None,
-                         subproject_roots=None):
+                         subproject_roots=None,
+                         include_trace_on_error=True):
     """Construct and return the components necessary for LegacyBuildGraph construction.
 
     :param list pants_ignore_patterns: A list of path ignore patterns for FileSystemProjectTree,
@@ -132,6 +134,7 @@ def setup_legacy_graph(pants_ignore_patterns,
     :param list exclude_target_regexps: A list of regular expressions for excluding targets.
     :param list subproject_roots: Paths that correspond with embedded build roots
                                   under the current build root.
+    :param bool include_trace_on_error: If True, when an error occurs, the error message will include the graph trace.
     :returns: A tuple of (scheduler, engine, symbol_table_cls, build_graph_cls).
     """
 
@@ -162,7 +165,7 @@ def setup_legacy_graph(pants_ignore_patterns,
 
     # TODO: Do not use the cache yet, as it incurs a high overhead.
     scheduler = LocalScheduler(workdir, dict(), tasks, project_tree, native)
-    engine = LocalSerialEngine(scheduler, use_cache=False)
+    engine = LocalSerialEngine(scheduler, use_cache=False, include_trace_on_error=include_trace_on_error)
     change_calculator = EngineChangeCalculator(scheduler, engine, symbol_table_cls, scm) if scm else None
 
     return LegacyGraphHelper(scheduler, engine, symbol_table_cls, change_calculator)

src/python/pants/bin/goal_runner.py

@@ -102,12 +102,15 @@ def _init_graph(self, use_engine, pants_ignore_patterns, build_ignore_patterns,
           native=native,
           build_ignore_patterns=build_ignore_patterns,
           exclude_target_regexps=exclude_target_regexps,
-          subproject_roots=subproject_build_roots)
+          subproject_roots=subproject_build_roots,
+          include_trace_on_error=self._options.for_global_scope().print_exception_stacktrace
+        )
 
       target_roots = TargetRoots.create(options=self._options,
                                         build_root=self._root_dir,
                                         change_calculator=graph_helper.change_calculator)
-      graph, address_mapper = graph_helper.create_build_graph(target_roots, self._root_dir)
+      graph, address_mapper = graph_helper.create_build_graph(target_roots, self._root_dir,
+                                                              include_trace_on_error=self._global_options.print_exception_stacktrace)
       return graph, address_mapper, target_roots.as_specs()
     else:
       spec_roots = TargetRoots.parse_specs(target_specs, self._root_dir)

src/python/pants/engine/engine.py

@@ -54,7 +54,7 @@ def failure(cls, error):
       """
       return cls(error=error, root_products=None)
 
-  def __init__(self, scheduler, storage=None, cache=None, use_cache=True):
+  def __init__(self, scheduler, storage=None, cache=None, use_cache=True, include_trace_on_error=True):
     """
     :param scheduler: The local scheduler for creating execution graphs.
     :type scheduler: :class:`pants.engine.scheduler.LocalScheduler`
@@ -66,7 +66,10 @@ def __init__(self, scheduler, storage=None, cache=None, use_cache=True):
     :param use_cache: True to enable usage of the cache. The cache incurs a large amount of
       overhead for small tasks, and needs TODO: further improvement.
     :type use_cache: bool
+    :param include_trace_on_error: Include the trace through the graph upon encountering errors.
+    :type include_trace_on_error: bool
     """
+    self._include_trace_on_error = include_trace_on_error
     self._scheduler = scheduler
     self._storage = storage or Storage.create()
     self._cache = cache or Cache.create(storage)
@@ -98,7 +101,7 @@ def product_request(self, product, subjects):
     result = self.execute(request)
     if result.error:
       raise result.error
-    result_items = self._scheduler.root_entries(request).items()
+    result_items = result.root_products.items()
 
     # State validation.
     unknown_state_types = tuple(
@@ -109,10 +112,18 @@ def product_request(self, product, subjects):
 
     # Throw handling.
     # TODO: See https://github.com/pantsbuild/pants/issues/3912
-    throw_roots = tuple(root for root, state in result_items if type(state) is Throw)
-    if throw_roots:
-      cumulative_trace = '\n'.join(self._scheduler.trace())
-      raise ExecutionError('Received unexpected Throw state(s):\n{}'.format(cumulative_trace))
+    throw_root_states = tuple(state for root, state in result_items if type(state) is Throw)
+    if throw_root_states:
+      if self._include_trace_on_error:
+        cumulative_trace = '\n'.join(self._scheduler.trace())
+        raise ExecutionError('Received unexpected Throw state(s):\n{}'.format(cumulative_trace))
+
+      if len(throw_root_states) == 1:
+        raise throw_root_states[0].exc
+      else:
+        raise ExecutionError('Multiple exceptions encountered:\n  {}'
+                             .format('\n  '.join('{}: {}'.format(type(t.exc).__name__, str(t.exc))
+                                                 for t in throw_root_states)))
 
     # Return handling.
     returns = tuple(state.value for _, state in result_items if type(state) is Return)

src/python/pants/engine/legacy/graph.py

@@ -49,18 +49,19 @@ class InvalidCommandLineSpecError(AddressLookupError):
     """Raised when command line spec is not a valid directory"""
 
   @classmethod
-  def create(cls, scheduler, engine, symbol_table_cls):
+  def create(cls, scheduler, engine, symbol_table_cls, include_trace_on_error=True):
     """Construct a graph given a Scheduler, Engine, and a SymbolTable class."""
-    return cls(scheduler, engine, cls._get_target_types(symbol_table_cls))
+    return cls(scheduler, engine, cls._get_target_types(symbol_table_cls), include_trace_on_error=include_trace_on_error)
 
-  def __init__(self, scheduler, engine, target_types):
+  def __init__(self, scheduler, engine, target_types, include_trace_on_error=True):
     """Construct a graph given a Scheduler, Engine, and a SymbolTable class.
 
     :param scheduler: A Scheduler that is configured to be able to resolve HydratedTargets.
     :param engine: An Engine subclass to execute calls to `inject`.
     :param symbol_table_cls: A SymbolTable class used to instantiate Target objects. Must match
       the symbol table installed in the scheduler (TODO: see comment in `_instantiate_target`).
     """
+    self._include_trace_on_error = include_trace_on_error
     self._scheduler = scheduler
     self._engine = engine
     self._target_types = target_types
@@ -257,9 +258,17 @@ def _assert_type_is_return(self, node, state):
     if isinstance(state.exc, ResolveError):
       raise AddressLookupError(str(state.exc))
     else:
-      trace = '\n'.join(self._scheduler.trace())
-      raise AddressLookupError(
-        'Build graph construction failed for {}:\n{}'.format(node, trace))
+      if self._include_trace_on_error:
+        trace = '\n'.join(self._scheduler.trace())
+        raise AddressLookupError(
+          'Build graph construction failed for {}:\n{}'.format(node, trace))
+      else:
+        raise AddressLookupError(
+          'Build graph construction failed for {}: {} {}'
+            .format(node,
+                    type(state.exc).__name__,
+                    str(state.exc))
+        )
 
   def _assert_correct_value_type(self, state, expected_type):
     # TODO This is a pretty general assertion, and it should live closer to where the result is generated.

src/python/pants/engine/subsystem/native.py

@@ -11,6 +11,7 @@
 import sys
 import sysconfig
 import threading
+import traceback
 
 import cffi
 import pkg_resources
@@ -83,6 +84,7 @@
 typedef struct {
   Value  value;
   _Bool  is_throw;
+  Buffer traceback;
 } RunnableComplete;
 
 typedef void ExternContext;
@@ -407,11 +409,13 @@ def extern_invoke_runnable(context_handle, func, args_ptr, args_len, cacheable):
     try:
       val = runnable(*args)
       is_throw = False
+      traceback_str = ''
     except Exception as e:
       val = e
       is_throw = True
+      traceback_str = traceback.format_exc()
 
-    return RunnableComplete(c.to_value(val), is_throw)
+    return RunnableComplete(c.to_value(val), is_throw, c.utf8_buf(traceback_str))
 
 
 class Value(datatype('Value', ['handle'])):
@@ -434,7 +438,7 @@ class TypeId(datatype('TypeId', ['id_'])):
   """Corresponds to the native object of the same name."""
 
 
-class RunnableComplete(datatype('RunnableComplete', ['value', 'is_throw'])):
+class RunnableComplete(datatype('RunnableComplete', ['value', 'is_throw', 'traceback'])):
   """Corresponds to the native object of the same name."""
 
 

src/python/pants/engine/subsystem/native_engine_version

@@ -1 +1 @@
-1713915b4db92ef6fb255e16fab40c0a82af79df
+860eaab129ac88e1cbe6bd411ee02297fc691f46

src/rust/engine/src/core.rs

@@ -157,7 +157,7 @@ impl fmt::Debug for Value {
 #[derive(Debug, Clone)]
 pub enum Failure {
   Noop(Noop),
-  Throw(Value),
+  Throw(Value, String),
 }
 
 // NB: enum members are listed in ascending priority order based on how likely they are

src/rust/engine/src/externs.rs

@@ -158,7 +158,10 @@ pub fn invoke_runnable(func: &Value, args: &[Value], cacheable: bool) -> Result<
       )
     });
   if result.is_throw {
-    Err(Failure::Throw(result.value))
+    let traceback = result.traceback.to_string().unwrap_or_else(|e| {
+                      format!("<failed to decode unicode for {:?}: {}>", result.traceback, e)
+                    });
+    Err(Failure::Throw(result.value, traceback))
   } else {
     Ok(result.value)
   }
@@ -323,6 +326,7 @@ pub enum LogLevel {
 pub struct RunnableComplete {
   value: Value,
   is_throw: bool,
+  traceback: Buffer
 }
 
 // Points to an array containing a series of values allocated by Python.
@@ -369,6 +373,7 @@ pub type ProjectMultiExtern =
   extern "C" fn(*const ExternContext, *const Value, field_name_ptr: *const u8, field_name_len: u64) -> ValueBuffer;
 
 #[repr(C)]
+#[derive(Debug)]
 pub struct Buffer {
   bytes_ptr: *mut u8,
   bytes_len: u64,

src/rust/engine/src/graph.rs

@@ -141,7 +141,7 @@ impl Entry {
     let state =
       match self.peek::<N>() {
         Some(Ok(ref nr)) => format!("{:?}", nr),
-        Some(Err(Failure::Throw(ref v))) => externs::val_to_str(v),
+        Some(Err(Failure::Throw(ref v, _))) => externs::val_to_str(v),
         Some(Err(ref x)) => format!("{:?}", x),
         None => "<None>".to_string(),
       };
@@ -322,7 +322,7 @@ impl InnerGraph {
       |entry: &Entry| {
         match entry.peek::<NodeKey>() {
           None | Some(Err(Failure::Noop(_))) => "white".to_string(),
-          Some(Err(Failure::Throw(_))) => "4".to_string(),
+          Some(Err(Failure::Throw(..))) => "4".to_string(),
           Some(Ok(_)) => {
             let viz_colors_len = viz_colors.len();
             viz_colors.entry(entry.node.content().product_str()).or_insert_with(|| {
@@ -374,7 +374,7 @@ impl InnerGraph {
     let is_bottom = |eid: EntryId| -> bool {
       match self.entry_for_id(eid).peek::<NodeKey>() {
         None | Some(Err(Failure::Noop(..))) => true,
-        Some(Err(Failure::Throw(_))) => false,
+        Some(Err(Failure::Throw(..))) => false,
         Some(Ok(_)) => true,
       }
     };
@@ -399,7 +399,14 @@ impl InnerGraph {
         let state_str = match entry.peek::<NodeKey>() {
           None => "<None>".to_string(),
           Some(Ok(ref x)) => format!("{:?}", x),
-          Some(Err(Failure::Throw(ref x))) => format!("Throw({})", externs::val_to_str(x)),
+          Some(Err(Failure::Throw(ref x, ref traceback))) => format!(
+            "Throw({})\n{}",
+            externs::val_to_str(x),
+            traceback.split("\n")
+                     .map(|l| format!("{}    {}", indent, l))
+                     .collect::<Vec<_>>()
+                     .join("\n")
+          ),
           Some(Err(Failure::Noop(ref x))) => format!("Noop({:?})", x),
         };
         format!("{}\n{}  {}", output, indent, state_str)

src/rust/engine/src/lib.rs

@@ -92,8 +92,8 @@ impl RawNode {
           (RawStateTag::Empty as u8, externs::create_exception("No value")),
         Some(Ok(v)) =>
           (RawStateTag::Return as u8, v),
-        Some(Err(Failure::Throw(msg))) =>
-          (RawStateTag::Throw as u8, msg),
+        Some(Err(Failure::Throw(exc, _))) =>
+          (RawStateTag::Throw as u8, exc),
         Some(Err(Failure::Noop(noop))) =>
           (RawStateTag::Noop as u8, externs::create_exception(&format!("{:?}", noop))),
       };

src/rust/engine/src/nodes.rs

@@ -39,7 +39,7 @@ fn err<O: Send + 'static>(failure: Failure) -> NodeFuture<O> {
 }
 
 fn throw(msg: &str) -> Failure {
-  Failure::Throw(externs::create_exception(msg))
+  Failure::Throw(externs::create_exception(msg), format!("Traceback (no traceback):\n  <pants native internals>\nException: {}", msg).to_string())
 }
 
 ///
@@ -89,7 +89,7 @@ impl VFS<Failure> for Context {
   }
 
   fn mk_error(msg: &str) -> Failure {
-    Failure::Throw(externs::create_exception(msg))
+    Failure::Throw(externs::create_exception(msg), "<pants native internals>".to_string())
   }
 }
 
@@ -235,7 +235,7 @@ impl Select {
               }
               continue
             },
-            f @ Failure::Throw(_) =>
+            f @ Failure::Throw(..) =>
               return Err(f),
           }
         },

tests/python/pants_test/engine/test_build_files.py

@@ -222,10 +222,8 @@ def assert_equal_or_more_indentation(more_indented_line, less_indented_line):
       # Make sure lines with Throw have more or equal indentation than its neighbors.
       current_line = lines[idx]
       line_above = lines[max(0, idx - 1)]
-      line_below = lines[min(len(lines) - 1, idx + 1)]
 
       assert_equal_or_more_indentation(current_line, line_above)
-      assert_equal_or_more_indentation(current_line, line_below)
 
   def test_cycle_self(self):
     self.do_test_cycle('graph_test:self_cycle')