Merge ~mpontillo/maas:surface-post-commissioning-errors--bug-1718517 into maas:master

[Mike Pontillo]

LP: #1718517 - Handle and properly surface post-processing errors during commissioning.

E2E tested throughout development - working well for me.

[Lee Trager (ltrager)]

LGTM thanks for fixing this!

review: Approve

diff --git a/src/metadataserver/api.py b/src/metadataserver/api.py
index af4f4af..18153ea 100644
--- a/src/metadataserver/api.py
+++ b/src/metadataserver/api.py
@@ -71,7 +71,10 @@ from maasserver.preseed import (
     get_preseed,
 )
 from maasserver.utils import find_rack_controller
-from maasserver.utils.orm import get_one
+from maasserver.utils.orm import (
+    get_one,
+    is_retryable_failure,
+)
 from metadataserver import logger
 from metadataserver.builtin_scripts.hooks import NODE_INFO_SCRIPTS
 from metadataserver.enum import (
@@ -94,9 +97,13 @@ from provisioningserver.events import (
     EVENT_DETAILS,
     EVENT_TYPES,
 )
+from provisioningserver.logger import LegacyLogger
 import yaml
 
 
+log = LegacyLogger()
+
+
 class UnknownMetadataVersion(MAASAPINotFound):
     """Not a known metadata version."""
 
@@ -364,6 +371,44 @@ class StatusHandler(MetadataViewHandler):
             'be used instead.')
 
 
+def try_or_log_event(
+        machine, signal_status, error_message, func, *args, **kwargs):
+    """
+    Attempts to run the specified function, related to the specified node and
+    signal status. Will log the specified error, and create a node event,
+    if the function fails.
+
+    If the function raises a retryable failure, will re-raise the exception so
+    that a retry can be attempted.
+
+    :param machine: The machine related to the attempted action. Will be used
+        in order to log an event, if the function raises an exception.
+    :param signal_status: The initial SIGNAL_STATUS, which will be returned
+        as-is if no exception occurs. If an exception occurs,
+        SIGNAL_STATUS.FAILED will be returned.
+    :param error_message: The error message for the log (and node event log) if
+        an exception occurs.
+    :param func: The function which will be attempted
+    :param args: Arguments to pass to the function to be attempted.
+    :param kwargs: Keyword arguments to pass to the function to be attempted.
+    :return:
+    """
+    try:
+        func(*args, **kwargs)
+    except BaseException as e:
+        if is_retryable_failure(e):
+            # Not the fault of the post-processing function, so
+            # re-raise so that the retry mechanism does its job.
+            raise
+        log.err(None, error_message)
+        Event.objects.create_node_event(
+            system_id=machine.system_id,
+            event_type=EVENT_TYPES.SCRIPT_RESULT_ERROR,
+            event_description=error_message)
+        signal_status = SIGNAL_STATUS.FAILED
+    return signal_status
+
+
 class VersionIndexHandler(MetadataViewHandler):
     """Listing for a given metadata version."""
     create = update = delete = None
@@ -488,10 +533,14 @@ class VersionIndexHandler(MetadataViewHandler):
             # Commissioning was successful, setup the default storage layout
             # and the initial networking configuration for the node.
             if status in (SIGNAL_STATUS.TESTING, SIGNAL_STATUS.OK):
-                # XXX 2016-05-10 ltrager, LP:1580405 - Exceptions raised
-                # here are not logged or shown to the user.
-                node.set_default_storage_layout()
-                node.set_initial_networking_configuration()
+                status = try_or_log_event(
+                    node, status,
+                    "Failed to set default storage layout.",
+                    node.set_default_storage_layout)
+                status = try_or_log_event(
+                    node, status,
+                    "Failed to set default networking configuration.",
+                    node.set_initial_networking_configuration)
 
             # XXX 2014-10-21 newell, bug=1382075
             # Auto detection for IPMI tries to save power parameters
@@ -516,11 +565,22 @@ class VersionIndexHandler(MetadataViewHandler):
             node.current_testing_script_set.regenerate()
 
         if target_status in [NODE_STATUS.READY, NODE_STATUS.TESTING]:
-            # Recalculate tags when commissioning ends.
-            populate_tags_for_single_node(Tag.objects.all(), node)
-        elif (target_status == NODE_STATUS.FAILED_COMMISSIONING and
+            # Commissioning has ended. Check if any scripts failed during
+            # post-processing; if so, the commissioning counts as a failure.
+            qs = node.current_commissioning_script_set.scriptresult_set.filter(
+                status=SCRIPT_STATUS.FAILED)
+            if qs.count() > 0:
+                target_status = NODE_STATUS.FAILED_COMMISSIONING
+            else:
+                # Recalculate tags when commissioning ends.
+                try_or_log_event(
+                    node, status, "Failed to update tags.",
+                    populate_tags_for_single_node,
+                    Tag.objects.all(), node)
+
+        if (target_status == NODE_STATUS.FAILED_COMMISSIONING and
                 node.current_testing_script_set is not None):
-            # If commissioning failed testing doesn't run, mark any pending
+            # If commissioning failed, testing doesn't run; mark any pending
             # scripts as aborted.
             qs = node.current_testing_script_set.scriptresult_set.filter(
                 status=SCRIPT_STATUS.PENDING)
diff --git a/src/metadataserver/models/scriptresult.py b/src/metadataserver/models/scriptresult.py
index 9b9195e..7620ddd 100644
--- a/src/metadataserver/models/scriptresult.py
+++ b/src/metadataserver/models/scriptresult.py
@@ -255,10 +255,17 @@ class ScriptResult(CleanSave, TimestampedModel):
         if (self.script_set.result_type == RESULT_TYPE.COMMISSIONING and
                 self.name in NODE_INFO_SCRIPTS):
             post_process_hook = NODE_INFO_SCRIPTS[self.name]['hook']
-            post_process_hook(
+            err = (
+                "%s(%s): commissioning script '%s' failed during "
+                "post-processing." % (
+                    self.script_set.node.fqdn,
+                    self.script_set.node.system_id, self.name))
+            # Circular imports.
+            from metadataserver.api import try_or_log_event
+            try_or_log_event(
+                self.script_set.node, None, err, post_process_hook,
                 node=self.script_set.node, output=self.stdout,
                 exit_status=self.exit_status)
-
         self.save()
 
     @property
diff --git a/src/metadataserver/models/tests/test_scriptresult.py b/src/metadataserver/models/tests/test_scriptresult.py
index baa628f..ed8f41e 100644
--- a/src/metadataserver/models/tests/test_scriptresult.py
+++ b/src/metadataserver/models/tests/test_scriptresult.py
@@ -19,7 +19,10 @@ from maasserver.models import (
 from maasserver.testing.factory import factory
 from maasserver.testing.testcase import MAASServerTestCase
 from maasserver.utils.orm import reload_object
-from maastesting.matchers import MockCalledOnceWith
+from maastesting.matchers import (
+    DocTestMatches,
+    MockCalledOnceWith,
+)
 from metadataserver.enum import (
     RESULT_TYPE,
     SCRIPT_STATUS,
@@ -336,6 +339,27 @@ class TestScriptResult(MAASServerTestCase):
             MockCalledOnceWith(
                 node=script_set.node, output=b'', exit_status=exit_status))
 
+    def test_store_result_logs_event_upon_hook_failure(self):
+        script_set = factory.make_ScriptSet(
+            result_type=RESULT_TYPE.COMMISSIONING)
+        script_result = factory.make_ScriptResult(
+            script_set=script_set, status=SCRIPT_STATUS.RUNNING)
+        exit_status = random.randint(0, 255)
+
+        def _raise():
+            raise Exception()
+
+        scriptresult_module.NODE_INFO_SCRIPTS[script_result.name] = {
+            'hook': _raise,
+        }
+        self.addCleanup(
+            scriptresult_module.NODE_INFO_SCRIPTS.pop, script_result.name)
+        script_result.store_result(exit_status)
+        expected_event = Event.objects.last()
+        self.assertThat(
+            expected_event.description,
+            DocTestMatches("...failed during post-processing."))
+
     def test_save_stores_start_time(self):
         script_result = factory.make_ScriptResult(status=SCRIPT_STATUS.PENDING)
         script_result.status = SCRIPT_STATUS.RUNNING
diff --git a/src/metadataserver/tests/test_api.py b/src/metadataserver/tests/test_api.py
index 4bb1a83..bc6c8c7 100644
--- a/src/metadataserver/tests/test_api.py
+++ b/src/metadataserver/tests/test_api.py
@@ -64,6 +64,7 @@ from maasserver.testing.testcase import (
 from maasserver.testing.testclient import MAASSensibleOAuthClient
 from maasserver.utils.orm import reload_object
 from maastesting.matchers import (
+    DocTestMatches,
     MockCalledOnceWith,
     MockNotCalled,
 )
@@ -990,6 +991,23 @@ class TestInstallingAPI(MAASServerTestCase):
         self.assertEqual(NODE_STATUS.DEPLOYING, reload_object(node).status)
         self.assertThat(populate_tags_for_single_node, MockNotCalled())
 
+    def test_tag_population_failure_logs_event(self):
+        populate_tags_for_single_node = self.patch(
+            api, "populate_tags_for_single_node")
+        populate_tags_for_single_node.side_effect = Exception
+        node = factory.make_Node(
+            interface=True, status=NODE_STATUS.COMMISSIONING,
+            with_empty_script_sets=True)
+        client = make_node_client(node=node)
+        response = call_signal(client, status=SIGNAL_STATUS.OK)
+        self.assertEqual(http.client.OK, response.status_code)
+        self.assertEqual(
+            NODE_STATUS.READY, reload_object(node).status)
+        expected_event = Event.objects.last()
+        self.assertThat(
+            expected_event.description,
+            DocTestMatches("Failed to update tags."))
+
     def test_signaling_installation_success_is_idempotent(self):
         node = factory.make_Node(
             status=NODE_STATUS.DEPLOYING, with_empty_script_sets=True)
@@ -1914,6 +1932,47 @@ class TestCommissioningAPI(MAASServerTestCase):
             Node.set_default_storage_layout,
             MockCalledOnceWith(node))
 
+    def test_signal_fails_commissioning_and_logs_event_if_storage_config_fails(
+            self):
+        mock = self.patch_autospec(Node, "set_default_storage_layout")
+        mock.side_effect = Exception
+        node = factory.make_Node(
+            status=NODE_STATUS.COMMISSIONING, with_empty_script_sets=True)
+        client = make_node_client(node)
+        response = call_signal(
+            client, status=SIGNAL_STATUS.OK, script_result=0)
+        self.assertEqual(http.client.OK, response.status_code)
+        self.assertEqual(
+            NODE_STATUS.FAILED_COMMISSIONING, reload_object(node).status)
+        self.assertThat(
+            Node.set_default_storage_layout,
+            MockCalledOnceWith(node))
+        expected_event = Event.objects.last()
+        self.assertThat(
+            expected_event.description,
+            DocTestMatches("Failed to set default storage layout."))
+
+    def test_signal_fails_commissioning_and_logs_event_if_network_config_fails(
+            self):
+        mock = self.patch_autospec(
+            Node, "set_initial_networking_configuration")
+        mock.side_effect = Exception
+        node = factory.make_Node(
+            status=NODE_STATUS.COMMISSIONING, with_empty_script_sets=True)
+        client = make_node_client(node)
+        response = call_signal(
+            client, status=SIGNAL_STATUS.OK, script_result=0)
+        self.assertEqual(http.client.OK, response.status_code)
+        self.assertEqual(
+            NODE_STATUS.FAILED_COMMISSIONING, reload_object(node).status)
+        self.assertThat(
+            Node.set_initial_networking_configuration,
+            MockCalledOnceWith(node))
+        expected_event = Event.objects.last()
+        self.assertThat(
+            expected_event.description,
+            DocTestMatches("Failed to set default networking configuration."))
+
     def test_signal_sets_default_storage_layout_if_TESTING(self):
         self.patch_autospec(Node, "set_default_storage_layout")
         node = factory.make_Node(