[engine] Initial Trace implementation for rust engine (#4076)

Problem
----------
Re-implementing trace was deferred during the initial work on the Rust scheduler. See #4007.

Solution
----------
 This patch partially reintroduces it. The rust implementation will now produce traces that include the subjects and some of the information about failures. Some types of failures will not have good messages yet. This is because we haven't landed a patch to fix #4025. Also, the trace function will produce traces for each of the roots.

Result
-------

Example output:

    $ echo "WUT" >> BUILD.tools 
    $ ./pants --enable-v2-engine list //:
    Exception caught: (<class 'pants.build_graph.address_lookup_error.AddressLookupError'>)
      File "/.../pants/src/python/pants/bin/pants_exe.py", line 50, in <module>
        main()
      File "/.../pants/src/python/pants/bin/pants_exe.py", line 44, in main
        PantsRunner(exiter).run()
      File "/.../pants/src/python/pants/bin/pants_runner.py", line 57, in run
        options_bootstrapper=options_bootstrapper)
      File "/.../pants/src/python/pants/bin/pants_runner.py", line 46, in _run
        return LocalPantsRunner(exiter, args, env, options_bootstrapper=options_bootstrapper).run()
      File "/.../pants/src/python/pants/bin/local_pants_runner.py", line 37, in run
        self._run()
      File "/.../pants/src/python/pants/bin/local_pants_runner.py", line 77, in _run
        self._exiter).setup()
      File "/.../pants/src/python/pants/bin/goal_runner.py", line 184, in setup
        goals, context = self._setup_context()
      File "/.../pants/src/python/pants/bin/goal_runner.py", line 157, in _setup_context
        self._daemon_graph_helper
      File "/.../pants/src/python/pants/bin/goal_runner.py", line 101, in _init_graph
        graph, address_mapper = graph_helper.create_build_graph(target_roots, self._root_dir)
      File "/.../pants/src/python/pants/bin/engine_initializer.py", line 88, in create_build_graph
        for _ in graph.inject_specs_closure(target_roots.as_specs()):
      File "/.../pants/src/python/pants/engine/legacy/graph.py", line 205, in inject_specs_closure
        for address in self._inject(specs):
      File "/.../pants/src/python/pants/engine/legacy/graph.py", line 225, in _inject
        self._index(target_entries)
      File "/.../pants/src/python/pants/engine/legacy/graph.py", line 83, in _index
        'Build graph construction failed for {}:\n{}'.format(node, trace))

    Exception message: Build graph construction failed for (SiblingAddresses(directory=u''), Select(Collection.of(HydratedTarget))):
    Computing =Collection.of(HydratedTarget) for SiblingAddresses(directory=u'')
      Computing =Collection.of(HydratedTarget) for SiblingAddresses(directory=u'')
        Computing =HydratedTarget for SiblingAddresses(directory=u'')
          Computing =Collection.of(Address) for SiblingAddresses(directory=u'')
            Computing =Collection.of(Address) for SiblingAddresses(directory=u'')
              Computing =AddressFamily for SiblingAddresses(directory=u'')
                Computing =AddressFamily for Dir(path=u'')
                  Computing =AddressFamily for Dir(path=u'')
                    Throw("EntryId(17) failed!")

    Computing =Collection.of(Address) for SiblingAddresses(directory=u'')
      Computing =Collection.of(Address) for SiblingAddresses(directory=u'')
        Computing =AddressFamily for SiblingAddresses(directory=u'')
          Computing =AddressFamily for Dir(path=u'')
            Computing =AddressFamily for Dir(path=u'')
              Throw("EntryId(17) failed!")


Testing
--------

Local manual testing with ./pants list and a corrupted BUILD file. Running tests that had been skipped due to this feature being missing. CI away on #4076

src/python/pants/backend/python/tasks2/resolve_requirements.py

@@ -6,8 +6,8 @@
                         unicode_literals, with_statement)
 
 import os
-
 import shutil
+
 from pex.fetcher import Fetcher
 from pex.interpreter import PythonInterpreter
 from pex.pex import PEX
@@ -18,8 +18,8 @@
 
 from pants.backend.python.python_setup import PythonRepos, PythonSetup
 from pants.backend.python.targets.python_requirement_library import PythonRequirementLibrary
-from pants.base.fingerprint_strategy import DefaultFingerprintHashingMixin
-from pants.base.fingerprint_strategy import TaskIdentityFingerprintStrategy
+from pants.base.fingerprint_strategy import (DefaultFingerprintHashingMixin,
+                                             TaskIdentityFingerprintStrategy)
 from pants.invalidation.cache_manager import VersionedTargetSet
 from pants.task.task import Task
 

src/python/pants/engine/engine.py

@@ -111,7 +111,7 @@ def product_request(self, product, subjects):
     # 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 = self._scheduler.trace(throw_roots)
+      cumulative_trace = self._scheduler.trace()
       stringified_throw_roots = ', '.join(str(x) for x in throw_roots)
       raise ExecutionError('received unexpected Throw state(s) for root(s): {}\n{}'
                            .format(stringified_throw_roots, cumulative_trace))

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

@@ -78,7 +78,7 @@ def _index(self, roots):
     # Index the ProductGraph.
     for node, state in roots.items():
       if type(state) is Throw:
-        trace = 'TODO: restore trace!\n  {}'.format(state) #'\n'.join(self._graph.trace(node))
+        trace = '\n'.join(self._scheduler.trace())
         raise AddressLookupError(
             'Build graph construction failed for {}:\n{}'.format(node, trace))
       elif type(state) is not Return:

src/python/pants/engine/scheduler.py

@@ -26,6 +26,7 @@
                                            extern_id_to_str, extern_key_for, extern_project,
                                            extern_project_multi, extern_satisfied_by,
                                            extern_store_list, extern_val_to_str)
+from pants.util.contextutil import temporary_file_path
 from pants.util.objects import datatype
 
 
@@ -209,12 +210,14 @@ def _register_tasks(self, tasks):
             raise ValueError('Unrecognized Selector type: {}'.format(selector))
         self._native.lib.task_end(self._scheduler)
 
-  def trace(self, roots):
-    """Yields a stringified 'stacktrace' starting from the given failed root.
-
-    :param iterable roots: An iterable of the root nodes to begin the trace from.
-    """
-    return "TODO: Restore trace (see: #4007)."
+  def trace(self):
+    """Yields a stringified 'stacktrace' starting from the scheduler's roots."""
+    with self._product_graph_lock:
+      with temporary_file_path() as path:
+        self._native.lib.graph_trace(self._scheduler, bytes(path))
+        with open(path) as fd:
+          for line in fd.readlines():
+            yield line.rstrip()
 
   def visualize_graph_to_file(self, filename):
     """Visualize a graph walk by writing graphviz `dot` output to a file.

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

@@ -134,6 +134,8 @@
     uint64_t graph_len(RawScheduler*);
     uint64_t graph_invalidate(RawScheduler*, Key*, uint64_t);
     void graph_visualize(RawScheduler*, char*);
+    void graph_trace(RawScheduler*, char*);
+
 
     void execution_reset(RawScheduler*);
     void execution_add_root_select(RawScheduler*, Key, TypeConstraint);
@@ -414,4 +416,4 @@ def new_handle(self, obj):
     return _FFI.new_handle(obj)
 
   def buffer(self, cdata):
-    return _FFI.buffer(cdata)
+    return _FFI.buffer(cdata)

src/python/pants/engine/subsystem/native_engine_version

@@ -1 +1 @@
-da39a3ee5e6b4b0d3255bfef95601890afd80709
+538c578313e7557de31b62f90f193d5430334de7

src/rust/engine/src/graph.rs

@@ -1,6 +1,7 @@
 
 use std::collections::{HashMap, HashSet, VecDeque};
 use std::fs::File;
+use std::fs::OpenOptions;
 use std::io::{BufWriter, Write};
 use std::io;
 use std::path::Path;
@@ -248,7 +249,7 @@ impl Graph {
    * Begins a topological Walk from the given roots.
    */
   fn walk<P>(&self, roots: VecDeque<EntryId>, predicate: P, dependents: bool) -> Walk<P>
-      where P: Fn(&Entry)->bool {
+    where P: Fn(&Entry)->bool {
     Walk {
       graph: self,
       dependents: dependents,
@@ -258,6 +259,22 @@ impl Graph {
     }
   }
 
+/**
+ *  Begins a topological walk from the given roots. Provides both the current entry as well as the
+ *  depth from the root.
+ */
+  fn leveled_walk<P>(&self, roots: VecDeque<EntryId>, predicate: P, dependents: bool) -> LeveledWalk<P>
+    where P: Fn(&Entry, Level) -> bool {
+    let rrr = roots.iter().map(|&r| (r, 0)).collect::<VecDeque<_>>();
+    LeveledWalk {
+      graph: self,
+      dependents: dependents,
+      deque: rrr,
+      walked: HashSet::default(),
+      predicate: predicate,
+    }
+  }
+
   /**
    * Finds all Nodes with the given subjects, and invalidates their transitive dependents.
    */
@@ -381,6 +398,72 @@ impl Graph {
     try!(f.write_all(b"}\n"));
     Ok(())
   }
+
+  pub fn trace(&self, root: &Node, path: &Path, externs: &Externs) -> io::Result<()> {
+    let file = try!(OpenOptions::new().append(true).open(path));
+    let mut f = BufWriter::new(file);
+
+    let is_bottom = |entry: &Entry| -> bool {
+      let match_result = match entry.state {
+        None => false,
+        Some(Complete::Throw(_)) => false,
+        Some(Complete::Noop(_, _)) => true,
+        Some(Complete::Return(_)) => true
+      };
+      match_result
+    };
+
+    let is_one_level_above_bottom = |c: &Entry| -> bool {
+      for d in &c.dependencies {
+        if !is_bottom(self.entry_for_id(*d)) {
+          return false;
+        }
+      }
+      true
+    };
+
+    let _indent = |level: u32| -> String {
+      let mut indent = String::new();
+      for _ in 0..level {
+        indent.push_str("  ");
+      }
+      indent
+    };
+
+    let _format = |entry: &Entry, level: u32| -> String {
+      let indent = _indent(level);
+      let output = format!("{}Computing {} for {}",
+                           indent,
+                           externs.id_to_str(entry.node.product().0),
+                           externs.id_to_str(entry.node.subject().id()));
+      if is_one_level_above_bottom(entry) {
+        let state_str = match entry.state {
+          Some(Complete::Return(ref x)) => format!("Return({})", externs.val_to_str(x)),
+          Some(Complete::Throw(ref x)) => format!("Throw({:?})", x),
+          Some(Complete::Noop(ref x, ref opt_node)) => format!("Noop({:?}, {:?})", x, opt_node),
+          None => String::new(),
+        };
+        format!("{}\n{}  {}", output, indent, state_str)
+      } else {
+        output
+      }
+    };
+
+    let root_entries = vec![root].iter().filter_map(|n| self.entry(n)).map(|e| e.id()).collect();
+    for t in self.leveled_walk(root_entries, |e,_| !is_bottom(e), false) {
+      let (entry, level) = t;
+      try!(write!(&mut f, "{}\n", _format(entry, level)));
+
+      for dep_entry in &entry.cyclic_dependencies {
+        let indent= _indent(level);
+        try!(write!(&mut f, "{}cycle for {:?}\n", indent, dep_entry));
+      }
+
+    }
+
+    try!(f.write_all(b"\n"));
+    Ok(())
+  }
 }
 
 /**
@@ -422,3 +505,48 @@ impl<'a, P: Fn(&Entry)->bool> Iterator for Walk<'a, P> {
     None
   }
 }
+
+type Level = u32;
+/**
+ * Represents the state of a particular topological walk through a Graph. Implements Iterator and
+ * has the same lifetime as the Graph itself.
+ */
+struct LeveledWalk<'a, P: Fn(&Entry, Level)->bool> {
+  graph: &'a Graph,
+  dependents: bool,
+  deque: VecDeque<(EntryId, Level)>,
+  walked: HashSet<EntryId, FNV>,
+  predicate: P,
+}
+
+impl<'a, P: Fn(&Entry, Level)->bool> Iterator for LeveledWalk<'a, P> {
+  type Item = (&'a Entry, Level);
+
+  fn next(&mut self) -> Option<(&'a Entry, Level)> {
+    while let Some((id, level)) = self.deque.pop_front() {
+      if self.walked.contains(&id) {
+        continue;
+      }
+      self.walked.insert(id);
+
+      let entry = self.graph.entry_for_id(id);
+      if !(self.predicate)(entry, level) {
+        continue;
+      }
+
+      // Entry matches.
+      if self.dependents {
+        for d in &entry.dependents {
+          self.deque.push_back((*d, level+1));
+        }
+      } else {
+        for d in &entry.dependencies {
+          self.deque.push_back((*d, level+1));
+        }
+      }
+      return Some((entry, level));
+    }
+
+    None
+  }
+}

src/rust/engine/src/lib.rs

@@ -454,6 +454,18 @@ pub extern fn graph_visualize(scheduler_ptr: *mut RawScheduler, path_ptr: *const
   })
 }
 
+#[no_mangle]
+pub extern fn graph_trace(scheduler_ptr: *mut RawScheduler, path_ptr: *const libc::c_char) {
+  let path_str = unsafe { CStr::from_ptr(path_ptr).to_string_lossy().into_owned() };
+  let path = Path::new(path_str.as_str());
+  with_scheduler(scheduler_ptr, |raw| {
+     raw.scheduler.trace(path).unwrap_or_else(|e| {
+       println!("Failed to write trace to {}: {:?}", path.display(), e);
+     });
+  });
+}
+
+
 #[no_mangle]
 pub extern fn nodes_destroy(raw_nodes_ptr: *mut RawNodes) {
   // convert the raw pointer back to a Box (without `forget`ing it) in order to cause it

src/rust/engine/src/scheduler.rs

@@ -45,6 +45,16 @@ impl Scheduler {
     self.graph.visualize(&self.roots, path, &self.tasks.externs)
   }
 
+  pub fn trace(&self, path: &Path) -> io::Result<()> {
+    for root in &self.roots {
+      let result = self.graph.trace(&root, path, &self.tasks.externs);
+      if result.is_err() {
+        return result;
+      }
+    }
+    Ok(())
+  }
+
   pub fn reset(&mut self) {
     self.roots.clear();
     self.candidates.clear();

tests/python/pants_test/backend/python/tasks2/test_resolve_requirements.py

@@ -13,8 +13,7 @@
 
 from pants.backend.python.interpreter_cache import PythonInterpreterCache
 from pants.backend.python.python_requirement import PythonRequirement
-from pants.backend.python.python_setup import PythonRepos
-from pants.backend.python.python_setup import PythonSetup
+from pants.backend.python.python_setup import PythonRepos, PythonSetup
 from pants.backend.python.targets.python_requirement_library import PythonRequirementLibrary
 from pants.backend.python.tasks2.resolve_requirements import ResolveRequirements
 from pants.base.build_environment import get_buildroot

tests/python/pants_test/engine/legacy/test_build_ignore_integration.py

@@ -7,7 +7,6 @@
 
 import os
 import tempfile
-import unittest
 
 from pants_test.pants_run_integration_test import PantsRunIntegrationTest, ensure_engine
 
@@ -62,7 +61,6 @@ def output_to_list(output_filename):
     self.assertNotIn('testprojects/src/java/org/pantsbuild/testproject/phrases:there-was-a-duck',
                      results)
 
-  @unittest.skip('Skipped to expedite landing the native engine: #4007.')
   @ensure_engine
   def test_build_ignore_dependency(self):
     run_result = self.run_pants(['-q',

tests/python/pants_test/engine/legacy/test_filemap_integration.py

@@ -53,7 +53,7 @@ def test_python_sources(self):
     # up in filemap, because it is synthetic. see https://github.com/pantsbuild/pants/issues/3563
     #self.assertIn('testprojects/src/python/sources/sources.txt', run.stdout_data)
 
-  @unittest.skip('Skipped to expedite landing the native engine: #4007.')
+  @unittest.skip('Skipped to expedite landing the native engine: #4007, #4025.')
   def test_exclude_invalid_string(self):
     build_path = os.path.join(self.PATH_PREFIX, 'BUILD.invalid')
     build_content = '''python_library(name='exclude_strings_disallowed',

tests/python/pants_test/engine/test_build_files.py

@@ -196,13 +196,12 @@ def do_test_trace_message(self, scheduler, parsed_address, expected_string=None)
     # Confirm that the root failed, and that a cycle occurred deeper in the graph.
     root, state = self._populate(scheduler, parsed_address)
     self.assertEqual(type(state), Throw)
-    trace_message = scheduler.trace([root])
+    trace_message = '\n'.join(scheduler.trace())
 
     self.assert_throws_are_leaves(trace_message, Throw.__name__)
     if expected_string:
       self.assertIn(expected_string, trace_message)
 
-  @unittest.skip('Skipped to expedite landing #3821; see: #4007.')
   def do_test_cycle(self, address_str):
     scheduler = self.create_json()
     parsed_address = Address.parse(address_str)
@@ -214,8 +213,8 @@ def indent_of(s):
 
     def assert_equal_or_more_indentation(more_indented_line, less_indented_line):
       self.assertTrue(indent_of(more_indented_line) >= indent_of(less_indented_line),
-                      '\n"{}"\nshould have more equal or more indentation than\n"{}"'.format(more_indented_line,
-                                                                                             less_indented_line))
+                      '\n"{}"\nshould have more equal or more indentation than\n"{}"\n{}'.format(more_indented_line,
+                                                                                             less_indented_line, error_msg))
 
     lines = error_msg.splitlines()
     line_indices_of_throws = [i for i, v in enumerate(lines) if throw_name in v]
@@ -237,27 +236,34 @@ def test_cycle_direct(self):
   def test_cycle_indirect(self):
     self.do_test_cycle('graph_test:indirect_cycle')
 
-  @unittest.skip('Skipped to expedite landing #3821; see: #4007.')
+  @unittest.skip('Skipped to expedite landing #3821; see: #4007, #4025.')
   def test_type_mismatch_error(self):
     scheduler = self.create_json()
     mismatch = Address.parse('graph_test:type_mismatch')
-    self.assertEquals(type(self.resolve_failure(scheduler, mismatch)), ResolvedTypeMismatchError)
+    self.assert_resolve_failure_type(ResolvedTypeMismatchError, mismatch, scheduler)
     self.do_test_trace_message(scheduler, mismatch)
 
-  @unittest.skip('Skipped to expedite landing #3821; see: #4007.')
+  @unittest.skip('Skipped to expedite landing #3821; see: #4007, #4025.')
   def test_not_found_but_family_exists(self):
     scheduler = self.create_json()
     dne = Address.parse('graph_test:this_addressable_does_not_exist')
-    self.assertEquals(type(self.resolve_failure(scheduler, dne)), ResolveError)
+    self.assert_resolve_failure_type(ResolveError, dne, scheduler)
     self.do_test_trace_message(scheduler, dne)
 
-  @unittest.skip('Skipped to expedite landing #3821; see: #4007.')
+  @unittest.skip('Skipped to expedite landing #3821; see: #4007, #4025.')
   def test_not_found_and_family_does_not_exist(self):
     scheduler = self.create_json()
     dne = Address.parse('this/dir/does/not/exist')
-    self.assertEquals(type(self.resolve_failure(scheduler, dne)), ResolveError)
+    self.assert_resolve_failure_type(ResolveError, dne, scheduler)
     self.do_test_trace_message(scheduler, dne)
 
+  def assert_resolve_failure_type(self, expected_type, mismatch, scheduler):
+
+    failure = self.resolve_failure(scheduler, mismatch)
+    self.assertEquals(type(failure),
+                      expected_type,
+                      'type was not {}. Instead was {}, {!r}'.format(expected_type.__name__, type(failure).__name__, failure))
+
 
 class LazyResolvingGraphTest(GraphTestBase):
   def do_test_codegen_simple(self, scheduler):