Log all document data following any layering action failure

This is to log out all document data following any layering action
failure. This consists of two stages:

1) Scrubbing all primitives contained in the data sections of both
   the child and parent being layered together.
2) Logging scrubbed-out data sections for both documents, in addition
   to their names, schemas, and the layering action itself.

This will hopefully provide DEs with enough information about why
a layering action may have failed to apply while at the same time
preventing any secret data from being logged out.

Change-Id: I3fedd259bba7b930c7969e9c30d1fffef5bf77bd

deckhand/common/utils.py

@@ -19,6 +19,7 @@ import string
 
 import jsonpath_ng
 from oslo_log import log as logging
+from oslo_utils import excutils
 import six
 
 from deckhand import errors
@@ -175,9 +176,10 @@ def jsonpath_replace(data, value, jsonpath, pattern=None):
                 try:
                     new_value = re.sub(pattern, str(value), to_replace)
                 except TypeError as e:
-                    LOG.error('Failed to substitute the value %s into %s '
+                    with excutils.save_and_reraise_exception():
-                              'using pattern %s. Details: %s', str(value),
+                        LOG.error('Failed to substitute the value %s into %s '
-                              to_replace, pattern, six.text_type(e))
+                                  'using pattern %s. Details: %s', str(value),
+                                  to_replace, pattern, six.text_type(e))
             return p.update(data, new_value)
 
     result = _do_replace()
@@ -188,10 +190,9 @@ def jsonpath_replace(data, value, jsonpath, pattern=None):
     # and then figure out what re.match(data[jsonpath], pattern) is (in
     # pseudocode). But raise an exception in case the path isn't present in the
     # data and a pattern has been provided since it is impossible to do the
-    # look up.
+    # look-up.
     if pattern:
-        raise errors.MissingDocumentPattern(
+        raise errors.MissingDocumentPattern(path=jsonpath, pattern=pattern)
-            data=data, path=jsonpath, pattern=pattern)
 
     # However, Deckhand should be smart enough to create the nested keys in the
     # data if they don't exist and a pattern isn't required.

deckhand/engine/layering.py

@@ -20,6 +20,7 @@ from networkx.algorithms.cycles import find_cycle
 from networkx.algorithms.dag import topological_sort
 from oslo_log import log as logging
 from oslo_log import versionutils
+from oslo_utils import excutils
 
 from deckhand.common import document as document_wrapper
 from deckhand.common import utils
@@ -445,6 +446,29 @@ class DocumentLayering(object):
         del self._documents_by_layer
         del self._documents_by_labels
 
+    def _log_data_for_layering_failure(self, child, parent, action):
+        child_data = copy.deepcopy(child.data)
+        parent_data = copy.deepcopy(parent.data)
+
+        engine_utils.deep_scrub(child_data, None)
+        engine_utils.deep_scrub(parent_data, None)
+
+        LOG.debug('An exception occurred while attempting to layer child '
+                  'document [%s] %s with parent document [%s] %s using '
+                  'layering action: %s.\nScrubbed child document data: %s.\n'
+                  'Scrubbed parent document data: %s.', child.schema,
+                  child.name, parent.schema, parent.name, action, child_data,
+                  parent_data)
+
+    def _log_data_for_substitution_failure(self, document):
+        document_data = copy.deepcopy(document.data)
+        engine_utils.deep_scrub(document_data, None)
+
+        LOG.debug('An exception occurred while attempting to add substitutions'
+                  ' %s into document [%s] %s\nScrubbed document data: %s.',
+                  document.substitutions, document.schema, document.name,
+                  document_data)
+
     def _apply_action(self, action, child_data, overall_data):
         """Apply actions to each layer that is rendered.
 
@@ -565,10 +589,18 @@ class DocumentLayering(object):
                         # Apply each action to the current document.
                         for action in doc.actions:
                             LOG.debug('Applying action %s to document with '
-                                      'schema=%s, name=%s, layer=%s.', action,
+                                      'schema=%s, layer=%s, name=%s.', action,
                                       *doc.meta)
-                            rendered_data = self._apply_action(
+                            try:
-                                action, doc, rendered_data)
+                                rendered_data = self._apply_action(
+                                    action, doc, rendered_data)
+                            except Exception:
+                                with excutils.save_and_reraise_exception():
+                                    try:
+                                        self._log_data_for_layering_failure(
+                                            doc, parent, action)
+                                    except Exception:  # nosec
+                                        pass
                         if not doc.is_abstract:
                             doc.data = rendered_data.data
                         self.secrets_substitution.update_substitution_sources(
@@ -584,8 +616,15 @@ class DocumentLayering(object):
             # Perform substitutions on abstract data for child documents that
             # inherit from it, but only update the document's data if concrete.
             if doc.substitutions:
-                substituted_data = list(
+                try:
-                    self.secrets_substitution.substitute_all(doc))
+                    substituted_data = list(
+                        self.secrets_substitution.substitute_all(doc))
+                except Exception:
+                    with excutils.save_and_reraise_exception():
+                        try:
+                            self._log_data_for_substitution_failure(doc)
+                        except Exception:  # nosec
+                            pass
                 if substituted_data:
                     rendered_data = substituted_data[0]
                     # Update the actual document data if concrete.

deckhand/engine/utils.py

@@ -69,3 +69,28 @@ def deep_delete(target, value, parent):
             if found:
                 return True
     return False
+
+
+def deep_scrub(value, parent):
+    """Scrubs all primitives in document data recursively. Useful for scrubbing
+    any and all secret data that may have been substituted into the document
+    data section before logging it out safely following an error.
+    """
+    primitive = (int, float, complex, str, bytes, bool)
+
+    def is_primitive(value):
+        return isinstance(value, primitive)
+
+    if is_primitive(value):
+        if isinstance(parent, list):
+            parent[parent.index(value)] = 'Scrubbed'
+        elif isinstance(parent, dict):
+            for k, v in parent.items():
+                if v == value:
+                    parent[k] = 'Scrubbed'
+    elif isinstance(value, list):
+        for v in value:
+            deep_scrub(v, value)
+    elif isinstance(value, dict):
+        for v in value.values():
+            deep_scrub(v, value)

deckhand/errors.py

@@ -255,9 +255,15 @@ class MissingDocumentPattern(DeckhandException):
     """'Pattern' is not None and data[jsonpath] doesn't exist.
 
     **Troubleshoot:**
+
+    * Check that the destination document's data section contains the
+      pattern specified under `substitutions.dest.pattern` in its data
+      section at `substitutions.dest.path`.
     """
-    msg_fmt = ("Missing document pattern %(pattern)s in %(data)s at path "
+    msg_fmt = ("The destination document's `data` section is missing the "
-               "%(path)s.")
+               "pattern %(pattern)s specified under "
+               "`substitutions.dest.pattern` at path %(jsonpath)s, specified "
+               "under `substitutions.dest.path`.")
     code = 400
 
 

deckhand/tests/unit/engine/test_document_layering_and_substitution_negative.py

@@ -12,6 +12,8 @@
 # See the License for the specific language governing permissions and
 # limitations under the License.
 
+import mock
+
 from deckhand.engine import layering
 from deckhand import errors
 from deckhand import factories
@@ -113,10 +115,12 @@ class TestDocumentLayeringWithSubstitutionNegative(
         self.assertRaises(
             errors.SubstitutionDependencyCycle, self._test_layering, documents)
 
-    def test_layering_with_missing_substitution_source_raises_exc(self):
+    @mock.patch.object(layering, 'LOG', autospec=True)
+    def test_layering_with_missing_substitution_source_raises_exc(
+            self, mock_log):
         """Validate that a missing substitution source document fails."""
         mapping = {
-            "_SITE_SUBSTITUTIONS_1_": [{
+            "_GLOBAL_SUBSTITUTIONS_1_": [{
                 "dest": {
                     "path": ".c"
                 },
@@ -125,10 +129,26 @@ class TestDocumentLayeringWithSubstitutionNegative(
                     "name": "nowhere-to-be-found",
                     "path": "."
                 }
-            }]
+            }],
+            "_GLOBAL_DATA_1_": {
+                "data": {
+                    "a": {"b": [1, 2, 3]}, "c": "d"
+                }
+            }
         }
-        doc_factory = factories.DocumentFactory(2, [1, 1])
+        doc_factory = factories.DocumentFactory(1, [1])
-        documents = doc_factory.gen_test(mapping, site_abstract=False)
+        documents = doc_factory.gen_test(mapping, global_abstract=False)
+
+        scrubbed_data = {
+            'a': {'b': ['Scrubbed', 'Scrubbed', 'Scrubbed']}, 'c': 'Scrubbed'}
 
         self.assertRaises(
             errors.SubstitutionSourceNotFound, self._test_layering, documents)
+
+        # Verifies that document data is recursively scrubbed prior to logging
+        # it.
+        mock_log.debug.assert_called_with(
+            'An exception occurred while attempting to add substitutions %s '
+            'into document [%s] %s\nScrubbed document data: %s.',
+            documents[1]['metadata']['substitutions'], documents[1]['schema'],
+            documents[1]['metadata']['name'], scrubbed_data)

deckhand/tests/unit/engine/test_document_layering_negative.py

@@ -39,20 +39,31 @@ class TestDocumentLayeringNegative(
         self.assertRaises(errors.MissingDocumentKey, self._test_layering,
                           documents)
 
-    def test_layering_method_delete_key_not_in_child(self):
+    @mock.patch.object(layering, 'LOG', autospec=True)
+    def test_layering_method_delete_key_not_in_child(self, mock_log):
         # The key will not be in the site after the global data is copied into
         # the site data implicitly.
+        action = {'method': 'delete', 'path': '.b'}
         mapping = {
             "_GLOBAL_DATA_1_": {"data": {"a": {"x": 1, "y": 2}, "c": 9}},
             "_SITE_DATA_1_": {"data": {"a": {"x": 7, "z": 3}, "b": 4}},
-            "_SITE_ACTIONS_1_": {
+            "_SITE_ACTIONS_1_": {"actions": [action]}
-                "actions": [{"method": "delete", "path": ".b"}]}
         }
         doc_factory = factories.DocumentFactory(2, [1, 1])
         documents = doc_factory.gen_test(mapping, site_abstract=False)
 
         self.assertRaises(errors.MissingDocumentKey, self._test_layering,
                           documents)
+        # Verifies that document data is recursively scrubbed prior to logging
+        # it.
+        mock_log.debug.assert_called_with(
+            'An exception occurred while attempting to layer child document '
+            '[%s] %s with parent document [%s] %s using layering action: %s.\n'
+            'Scrubbed child document data: %s.\nScrubbed parent document data:'
+            ' %s.', documents[2]['schema'], documents[2]['metadata']['name'],
+            documents[1]['schema'], documents[1]['metadata']['name'],
+            action, {'b': 'Scrubbed', 'a': {'z': 'Scrubbed', 'x': 'Scrubbed'}},
+            {'c': 'Scrubbed', 'a': {'x': 'Scrubbed', 'y': 'Scrubbed'}})
 
     def test_layering_method_replace_key_not_in_child(self):
         mapping = {