Merge lp:~allenap/maas/power-change-merge-and-log into lp:~maas-committers/maas/trunk

[Gavin Panella]

Improve logging for power changes in the cluster, and allow non-conflicting power changes.

[Raphaël Badin (rvb)]

Looks good… will this improve the situation for one of the bugs I filed yesterday about the mysterious unhandled twisted errors? (1436885 & co)

review: Approve

[Gavin Panella (allenap)]

> Looks good… will this improve the situation for one of the bugs I
> filed yesterday about the mysterious unhandled twisted errors?
> (1436885 & co)

I hope so. I wasn't sure so I haven't linked them to the bug/bugs, but I
think I will, but not assign the bug to myself unless they do end up
fixed.

=== modified file 'src/provisioningserver/rpc/power.py'
--- src/provisioningserver/rpc/power.py	2015-03-25 15:33:23 +0000
+++ src/provisioningserver/rpc/power.py	2015-03-27 00:50:35 +0000
@@ -40,6 +40,7 @@
 )
 from provisioningserver.utils.twisted import (
     asynchronous,
+    callOut,
     deferred,
     deferWithTimeout,
     pause,
@@ -47,6 +48,7 @@
 )
 from twisted.internet import reactor
 from twisted.internet.defer import (
+    CancelledError,
     DeferredList,
     DeferredSemaphore,
     inlineCallbacks,
@@ -183,33 +185,55 @@
     """
     assert power_change in ('on', 'off'), (
         "Unknown power change: %s" % power_change)
+
     # There should be one and only one power change for each system ID.
-    # If there's one already, raise an error.
-    registered_power_action = power_action_registry.get(system_id, None)
-    if registered_power_action is not None:
+    if system_id in power_action_registry:
+        current_power_change, d = power_action_registry[system_id]
+    else:
+        current_power_change, d = None, None
+
+    if current_power_change is None:
+        # Arrange for the power change to happen later; do not make the caller
+        # wait, because it might take a long time. We set a timeout of two
+        # minutes so that if the power action doesn't return in a timely
+        # fashion (or fails silently or some such) it doesn't block other
+        # actions on the node.
+        d = deferLater(
+            clock, 0, deferWithTimeout, CHANGE_POWER_STATE_TIMEOUT,
+            change_power_state, system_id, hostname, power_type, power_change,
+            context, clock)
+
+        power_action_registry[system_id] = power_change, d
+
+        # Whether we succeed or fail, we need to remove the action from the
+        # registry of actions, otherwise subsequent actions will fail.
+        d.addBoth(callOut, power_action_registry.pop, system_id, None)
+
+        # Log cancellations distinctly from other errors.
+        def eb_cancelled(failure):
+            failure.trap(CancelledError)
+            log.msg(
+                "%s: Power could not be turned %s; timed out."
+                % (hostname, power_change))
+        d.addErrback(eb_cancelled)
+
+        # Catch-all log.
+        d.addErrback(
+            log.err, "%s: Power could not be turned %s." % (
+                hostname, power_change))
+
+    elif current_power_change == power_change:
+        # What we want is already happening; let it continue.
+        pass
+
+    else:
+        # Right now we reject conflicting power changes. However, we have the
+        # Deferred (in `d`) along which the current power change is occurring,
+        # so the option to cancel is available if we want it.
         raise PowerActionAlreadyInProgress(
             "Unable to change power state to '%s' for node %s: another "
             "action is already in progress for that node." %
             (power_change, hostname))
-    power_action_registry[system_id] = power_change
-
-    def clean_up(*args, **kwargs):
-        power_action_registry.pop(system_id, None)
-
-    # Arrange for the power change to happen later; do not make the caller
-    # wait, because it might take a long time.
-    # We set a timeout of two minutes so that if the power action
-    # doesn't return in a timely fashion (or fails silently or
-    # some such) it doesn't block other actions on the node.
-    d = deferLater(
-        clock, 0, deferWithTimeout, CHANGE_POWER_STATE_TIMEOUT,
-        change_power_state, system_id, hostname, power_type,
-        power_change, context, clock)
-    d.addErrback(log.err)
-    # Whether we succeeded or failed, we need to remove the action
-    # from the registry of actions, otherwise every subsequent
-    # action will fail.
-    d.addBoth(clean_up)
 
 
 @asynchronous

=== modified file 'src/provisioningserver/rpc/tests/test_power.py'
--- src/provisioningserver/rpc/tests/test_power.py	2015-03-25 15:33:23 +0000
+++ src/provisioningserver/rpc/tests/test_power.py	2015-03-27 00:50:35 +0000
@@ -243,7 +243,7 @@
             factory.make_name('context-key'): factory.make_name('context-val')
         }
         self.patch(power, 'pause')
-        power.power_action_registry[system_id] = power_change
+        power.power_action_registry[system_id] = power_change, sentinel.d
         # Patch the power action utility so that it says the node is
         # in the required power state.
         power_action, execute = patch_power_action(
@@ -274,7 +274,7 @@
         context = {
             factory.make_name('context-key'): factory.make_name('context-val')
         }
-        power.power_action_registry[system_id] = power_change
+        power.power_action_registry[system_id] = power_change, sentinel.d
         self.patch(power, 'pause')
         power_action, execute = patch_power_action(
             self, return_value=random.choice(['on', 'off']))
@@ -302,7 +302,7 @@
             factory.make_name('context-key'): factory.make_name('context-val')
         }
         self.patch(power, 'pause')
-        power.power_action_registry[system_id] = power_change
+        power.power_action_registry[system_id] = power_change, sentinel.d
         # Simulate a failure to power up the node, then a success.
         power_action, execute = patch_power_action(
             self, side_effect=[None, 'off', None, 'on'])
@@ -332,7 +332,7 @@
             factory.make_name('context-key'): factory.make_name('context-val')
         }
         self.patch(power, 'pause')
-        power.power_action_registry[system_id] = power_change
+        power.power_action_registry[system_id] = power_change, sentinel.d
         # Patch the power action utility so that it says the node is
         # in the required power state.
         power_action, execute = patch_power_action(
@@ -363,7 +363,7 @@
             factory.make_name('context-key'): factory.make_name('context-val')
         }
         self.patch(power, 'pause')
-        power.power_action_registry[system_id] = power_change
+        power.power_action_registry[system_id] = power_change, sentinel.d
         # Simulate a persistent failure.
         power_action, execute = patch_power_action(
             self, return_value='off')
@@ -393,7 +393,7 @@
             factory.make_name('context-key'): factory.make_name('context-val')
         }
         self.patch(power, 'pause')
-        power.power_action_registry[system_id] = power_change
+        power.power_action_registry[system_id] = power_change, sentinel.d
         # Simulate an exception.
         exception_message = factory.make_name('exception')
         power_action, execute = patch_power_action(
@@ -418,7 +418,7 @@
         context = {
             factory.make_name('context-key'): factory.make_name('context-val')
         }
-        power.power_action_registry[system_id] = power_change
+        power.power_action_registry[system_id] = power_change, sentinel.d
         # Simulate two failures to power up the node, then a success.
         power_action, execute = patch_power_action(
             self, side_effect=[None, 'off', None, 'off', None, 'on'])
@@ -789,7 +789,8 @@
 
     run_tests_with = MAASTwistedRunTest.make_factory(timeout=5)
 
-    def patch_power_action_registry(self):
+    def setUp(self):
+        super(TestMaybeChangePowerState, self).setUp()
         self.patch(power, 'power_action_registry', {})
 
     def patch_methods_using_rpc(self):
@@ -809,7 +810,6 @@
     @inlineCallbacks
     def test_adds_action_to_registry(self):
         self.patch_methods_using_rpc()
-        self.patch_power_action_registry()
 
         system_id = factory.make_name('system_id')
         hostname = factory.make_name('hostname')
@@ -822,27 +822,45 @@
         yield power.maybe_change_power_state(
             system_id, hostname, power_type, power_change, context)
         self.assertEqual(
-            {system_id: power_change},
+            {system_id: (power_change, ANY)},
             power.power_action_registry)
         reactor.runUntilCurrent()  # Run all delayed calls.
         self.assertEqual({}, power.power_action_registry)
 
     @inlineCallbacks
-    def test_errors_when_change_already_registered(self):
+    def test_errors_when_change_conflicts_with_in_progress_change(self):
         system_id = factory.make_name('system_id')
         hostname = factory.make_name('hostname')
         power_type = random.choice(power.QUERY_POWER_TYPES)
-        power_change = random.choice(['on', 'off'])
+        power_changes = ['on', 'off']
+        random.shuffle(power_changes)
+        current_power_change, power_change = power_changes
         context = {
             factory.make_name('context-key'): factory.make_name('context-val')
         }
-
-        power.power_action_registry[system_id] = power_change
+        power.power_action_registry[system_id] = (
+            current_power_change, sentinel.d)
         with ExpectedException(exceptions.PowerActionAlreadyInProgress):
             yield power.maybe_change_power_state(
                 system_id, hostname, power_type, power_change, context)
 
     @inlineCallbacks
+    def test_does_nothing_when_change_matches_in_progress_change(self):
+        system_id = factory.make_name('system_id')
+        hostname = factory.make_name('hostname')
+        power_type = random.choice(power.QUERY_POWER_TYPES)
+        current_power_change = power_change = random.choice(['on', 'off'])
+        context = {
+            factory.make_name('context-key'): factory.make_name('context-val')
+        }
+        power.power_action_registry[system_id] = (
+            current_power_change, sentinel.d)
+        yield power.maybe_change_power_state(
+            system_id, hostname, power_type, power_change, context)
+        self.assertThat(power.power_action_registry, Equals(
+            {system_id: (power_change, sentinel.d)}))
+
+    @inlineCallbacks
     def test_calls_change_power_state_later(self):
         self.patch_methods_using_rpc()
 
@@ -865,7 +883,6 @@
 
     @inlineCallbacks
     def test_clears_lock_if_change_power_state_success(self):
-        self.patch_power_action_registry()
         self.patch_methods_using_rpc()
 
         system_id = factory.make_name('system_id')
@@ -883,7 +900,6 @@
 
     @inlineCallbacks
     def test_clears_lock_if_change_power_state_fails(self):
-        self.patch_power_action_registry()
 
         class TestException(Exception):
             pass
@@ -892,7 +908,7 @@
         power.power_change_starting.side_effect = TestException('boom')
 
         system_id = factory.make_name('system_id')
-        hostname = sentinel.hostname
+        hostname = factory.make_hostname()
         power_type = sentinel.power_type
         power_change = random.choice(['on', 'off'])
         context = sentinel.context
@@ -904,12 +920,46 @@
         reactor.runUntilCurrent()  # Run all delayed calls.
         self.assertNotIn(system_id, power.power_action_registry)
         self.assertDocTestMatches(
-            "Unhandled Error...TestException: boom",
+            """\
+            %s: Power could not be turned %s.
+            Traceback (most recent call last):
+            ...
+            %s.TestException: boom
+            """ % (hostname, power_change, __name__),
+            logger.dump())
+
+    @inlineCallbacks
+    def test_clears_lock_if_change_power_state_is_cancelled(self):
+        # Patch in an unfired Deferred here. This will pause the call so that
+        # we can grab the delayed call from the registry in time to cancel it.
+        self.patch_autospec(power, 'change_power_state')
+        power.change_power_state.return_value = Deferred()
+
+        system_id = factory.make_name('system_id')
+        hostname = factory.make_hostname()
+        power_type = sentinel.power_type
+        power_change = random.choice(['on', 'off'])
+        context = sentinel.context
+
+        logger = self.useFixture(TwistedLoggerFixture())
+
+        yield power.maybe_change_power_state(
+            system_id, hostname, power_type, power_change, context)
+
+        # Get the Deferred from the registry and cancel it.
+        _, d = power.power_action_registry[system_id]
+        d.cancel()
+        yield d
+
+        self.assertNotIn(system_id, power.power_action_registry)
+        self.assertDocTestMatches(
+            """\
+            %s: Power could not be turned %s; timed out.
+            """ % (hostname, power_change),
             logger.dump())
 
     @inlineCallbacks
     def test__calls_change_power_state_with_timeout(self):
-        self.patch_power_action_registry()
         self.patch_methods_using_rpc()
         defer_with_timeout = self.patch(power, 'deferWithTimeout')