Merge lp:~rvb/maas/retry-power-changes into lp:~maas-committers/maas/trunk

[Raphaël Badin]

Add utility to retry powering up or down a node.

This is part of the robustness work.

In between retries, the code waits a little longer every time. This is to "avoid" a race condition where a node gets power-cycled and then is still in the process of being power-cycled when the power state check occurs. This is obviously a bit fragile but it's better than nothing.

I deliberately didn't use the retries() utility that we have because: a) I don't think the waiting time should be constant (to avoid the race condition I mentioned above) b) I didn't want to use a fixed timeout: some power templates take a long time executing and this shouldn't mean they can't be retried.

[Julian Edwards (julian-edwards)]

Good branch but a few things to fix:

1. Use the test matchers, Luke! (See inline)
2. You're not catching Failures from the deferToThread calls (yield turns errback into exceptions)
3. The tests aren't very Twisted-like in terms of using a Clock(), which means that you've not tested the pause durations anywhere. If you don't know how to use Clock() ping me on IRC and I'll show you.

review: Needs Fixing

[Raphaël Badin (rvb)]

Thanks for the review. First batch of changes published. I'm working on your suggestion to use Clock() now.

[Julian Edwards (julian-edwards)]

On Wednesday 23 Jul 2014 12:23:49 you wrote:
> Not dealing with errors was deliberate: I don't want the retry loop to catch
> failures at all. Failures should only happen when there is a problem
> executing the power template (syntax problem, missing argument, etc.) and I
> don't think we should catch any of those. If something inside
> perform_power_change() raises an exceptions, none of the twisted magic will
> swallow it right? It will simply be "raised" from 'yield deferToThread(…)
> correct?

I'm afraid I don't agree with this approach. :)

Yes, Twisted internally turns it into a Failure, and then yield will re-raise
the exception it contains.

We've had instances in the past where we've had support requests for "power
not working" which was caused by a dodgy template that someone had edited, and
they were not looking at the cluster log at all!

I really think that we should catch these and flag them up somewhere.

> That's not part of the interface (yet). I think the node event log will
> contain the explanation of why it failed but we can always refine this
> later based on actual user testing.

OK.

I'd like to see a failure_reason text on the node for this situation. The
user should be able to see this alongside the BROKEN status IMO.

> Fixed (I didn't realize we had so many matchers to deal with mocks). Here
> and elsewhere.

They're great, add more :)

[Raphaël Badin (rvb)]

On 07/23/2014 02:33 PM, Julian Edwards wrote:
> On Wednesday 23 Jul 2014 12:23:49 you wrote:
>> Not dealing with errors was deliberate: I don't want the retry loop to catch
>> failures at all. Failures should only happen when there is a problem
>> executing the power template (syntax problem, missing argument, etc.) and I
>> don't think we should catch any of those. If something inside
>> perform_power_change() raises an exceptions, none of the twisted magic will
>> swallow it right? It will simply be "raised" from 'yield deferToThread(…)
>> correct?
>
> I'm afraid I don't agree with this approach. :)
>
> Yes, Twisted internally turns it into a Failure, and then yield will re-raise
> the exception it contains.
>
> We've had instances in the past where we've had support requests for "power
> not working" which was caused by a dodgy template that someone had edited, and
> they were not looking at the cluster log at all!

Hum, I still think the stacktrace belongs to the log file… but one thing
is sure (and means that, like you said, we need to take care of this
case): we want the node marked as broken when the template execution
blows up.

>> Fixed (I didn't realize we had so many matchers to deal with mocks). Here
>> and elsewhere.
>
> They're great, add more :)

The errors I'm getting aren't so great sometimes:
[...]
      raise mismatch_error
MismatchError: !=:
reference = [call(context-key-22VPn2=u'context-val-JmgwGQ',
power_change=u'on')]
actual = [call(context-key-22VPn2=u'context-val-JmgwGQ',
power_change=u'on')]
: after <function get_mock_calls> on <Mock name='mock().execute'
id='140547462746960'>: calls do not match

[Julian Edwards (julian-edwards)]

On Wednesday 23 Jul 2014 12:48:24 you wrote:
> Hum, I still think the stacktrace belongs to the log file… but one thing
> is sure (and means that, like you said, we need to take care of this
> case): we want the node marked as broken when the template execution
> blows up.

There's no point putting a stack trace in the log for template errors. Other
errors, yes.

[Julian Edwards (julian-edwards)]

Getting there! Couple of comments inline

[Raphaël Badin (rvb)]

Thanks for the review!

[Julian Edwards (julian-edwards)]

 review: approve

On Thursday 24 Jul 2014 10:36:00 you wrote:
> Turns out simply using 'yield power.change_power_state(…, clock=clock)'
> (instead of calling clock.callLater) is enough to remove the
> clock.advance(0.1). I /think/ this is due to the fact that all the waiting
> done inside power.change_power_state is using the clock that you pass to
> the method so the initial yield ensures the first run is done (and thus the
> first check succeeds) and after that, you can control the waiting by using
> clock.advance.

\o/

Awesome.

review: Approve

[Gavin Panella (allenap)]

A couple of things I noticed that means this branch needs fixing. Also, perform_power_change('query') is a weird concoction; it's not a change.

[Gavin Panella (allenap)]

review: Needs Fixing

[Julian Edwards (julian-edwards)]

On Sunday 27 Jul 2014 11:47:18 you wrote:
> Same here, mark_node_broken() does not exist.
>
> I think this highlights a shortcoming with using Mock: it lets you do
> anything. A couple of things come to mind that might help here:
>
> 1. Don't mock the whole client object, just mock __call__.
> 2. Use mock.create_autospec() to create mocks that only all things that the
> underlying implementation does (so you can mock the whole client).

*cough* end-to-end fixture *cough*

[Gavin Panella (allenap)]

> *cough* end-to-end fixture *cough*

This would means configuring Django and creating databases in the pserv tests. The pserv tests are currently fast and quick to iterate on, and they won't be if we do that.

We actually need to test against the RPC schemas. That's why I've been doing my utmost to keep them tightly defined. The call_responder helper function does that back-and-forth through the schemas. Where we need to stub out actual RPC calls we ought to use call_responder to keep us honest.

[Julian Edwards (julian-edwards)]

On Sunday 27 Jul 2014 13:49:06 Gavin Panella wrote:
> > *cough* end-to-end fixture *cough*
>
> This would means configuring Django and creating databases in the pserv
> tests. The pserv tests are currently fast and quick to iterate on, and they
> won't be if we do that.
>
> We actually need to test against the RPC schemas. That's why I've been doing
> my utmost to keep them tightly defined. The call_responder helper function
> does that back-and-forth through the schemas. Where we need to stub out
> actual RPC calls we ought to use call_responder to keep us honest.

I didn't mean that we don't need a real Django running; a mock one will do.
But we need something that responds like a real call to avoid the mistake that
rvb made.

[Gavin Panella (allenap)]

> I didn't mean that we don't need a real Django running; a mock one
> will do.  But we need something that responds like a real call to
> avoid the mistake that rvb made.

Ah, okeydoke, then I agree. I think we can dynamically create an amp.AMP
subclass with stub responders that correspond to a subset of amp.Command
calls.

Maybe something like:

    def make_stub_amp_thing(*commands):
        responders = {
            "responder_for_%s" % command.name:
                command.responder(Mock())
            for command in commands
        }
        return type("DynamicAMP", amp.AMP, responders)

    amp = make_stub_amp_thing(MakeMeASandwich)
    amp.responder_for_MakeMeASandwich.return_value = "Use sudo"

    call_responder(amp(), MakeMeASandwich, {
        "fillings": ["ketchup", "crisps", "scratchings"],
    })

The `Client` returned from ClusterService.getClient() needs to be
patched to use call_responder in this way. Or, as ClusterRPCFixture
does, the connections that the client uses need to be patched.

[Julian Edwards (julian-edwards)]

Right, my end aim is to be able to do client(GetBootSources) in the real code
and have that talk to a mock backend with canned responses, maybe even hook it
into a function in the tests that does that responding.

Perhaps we can talk more about it at the sprint this week!

[Raphaël Badin (rvb)]

> The client has no method mark_node_broken(). This needs to be client(MarkNodeBroken, system_id=system_id).
>

Damn. Using Mock is indeed a bit nasty indeed, and I wasn't really
about this… but I thought you had the end-to-end fixture in progress so
my intention to switch to that once it was done. Let's work on the
fixture this week.

=== modified file 'src/provisioningserver/rpc/clusterservice.py'
--- src/provisioningserver/rpc/clusterservice.py	2014-07-22 14:38:34 +0000
+++ src/provisioningserver/rpc/clusterservice.py	2014-07-24 10:46:38 +0000
@@ -32,7 +32,6 @@
     ArchitectureRegistry,
     PowerTypeRegistry,
     )
-from provisioningserver.power.poweraction import PowerAction
 from provisioningserver.rpc import (
     cluster,
     common,
@@ -45,6 +44,7 @@
     get_preseed_data,
     validate_license_key,
     )
+from provisioningserver.rpc.power import change_power_state
 from twisted.application.internet import (
     StreamServerEndpointService,
     TimerService,
@@ -150,15 +150,15 @@
     @cluster.PowerOn.responder
     def power_on(self, system_id, power_type, context):
         """Turn a node on."""
-        action = PowerAction(power_type)
-        action.execute(power_change='on', **context)
+        change_power_state(
+            system_id, power_type, power_change='on', context=context)
         return {}
 
     @cluster.PowerOff.responder
     def power_off(self, system_id, power_type, context):
         """Turn a node off."""
-        action = PowerAction(power_type)
-        action.execute(power_change='off', **context)
+        change_power_state(
+            system_id, power_type, power_change='off', context=context)
         return {}
 
     @amp.StartTLS.responder
 
=== added file 'src/provisioningserver/rpc/power.py'
--- src/provisioningserver/rpc/power.py	1970-01-01 00:00:00 +0000
+++ src/provisioningserver/rpc/power.py	2014-07-24 10:46:38 +0000
@@ -0,0 +1,83 @@
+# Copyright 2014 Canonical Ltd.  This software is licensed under the
+# GNU Affero General Public License version 3 (see the file LICENSE).
+
+"""RPC helpers relating to power control."""
+
+from __future__ import (
+    absolute_import,
+    print_function,
+    unicode_literals,
+    )
+
+str = None
+
+__metaclass__ = type
+__all__ = [
+    "change_power_state",
+]
+
+
+from provisioningserver.power.poweraction import PowerAction
+from provisioningserver.rpc import getRegionClient
+from provisioningserver.utils import pause
+from twisted.internet import reactor
+from twisted.internet.defer import inlineCallbacks
+from twisted.internet.threads import deferToThread
+
+# List of power_types that support querying the power state.
+# change_power_state() will only retry changing the power
+# state for these power types.
+# This is meant to be temporary until all the power types support
+# querying the power state of a node.
+QUERY_POWER_TYPES = ['amt', 'ipmi']
+
+
+def perform_power_change(system_id, power_type, power_change, context):
+    """Issue the given `power_change` command.
+
+    If any exception is raised during the execution of the command, mark
+    the node as broken and re-raise the exception.
+    """
+    action = PowerAction(power_type)
+    try:
+        return action.execute(power_change=power_change, **context)
+    except Exception:
+        client = getRegionClient()
+        client.mark_node_broken(system_id)
+        raise
+
+
+@inlineCallbacks
+def change_power_state(system_id, power_type, power_change, context,
+                       clock=reactor):
+    """Change the power state of a node.
+
+    Monitor the result of the power change action by querying the
+    power state of the node and mark the node as failed if it doesn't
+    work.
+    """
+    assert power_change in ('on', 'off'), (
+        "Unknown power change: %s" % power_change)
+
+    # Use increasing waiting times to work around race conditions that could
+    # arise when power-cycling the node.
+    for waiting_time in (3, 5, 10):
+        # Perform power change.
+        yield deferToThread(
+            perform_power_change, system_id, power_type, power_change,
+            context)
+        # If the power_type doesn't support querying the power state:
+        # exit now.
+        if power_type not in QUERY_POWER_TYPES:
+            return
+        # Wait to let the node some time to change its power state.
+        yield pause(waiting_time, clock)
+        # Check current power state.
+        new_power_state = yield deferToThread(
+            perform_power_change, system_id, power_type, 'query', context)
+        if new_power_state == power_change:
+            return
+
+    # Failure: the power state of the node hasn't changed: mark it as broken.
+    client = getRegionClient()
+    client.mark_node_broken(system_id)
 
=== modified file 'src/provisioningserver/rpc/tests/test_clusterservice.py'
--- src/provisioningserver/rpc/tests/test_clusterservice.py	2014-07-22 14:38:34 +0000
+++ src/provisioningserver/rpc/tests/test_clusterservice.py	2014-07-24 10:46:38 +0000
@@ -857,8 +857,8 @@
         responder = protocol.locateResponder(self.command.commandName)
         self.assertIsNot(responder, None)
 
-    def test_executes_a_power_action(self):
-        PowerAction = self.patch(clusterservice, "PowerAction")
+    def test_executes_change_power_state(self):
+        change_power_state = self.patch(clusterservice, "change_power_state")
 
         system_id = factory.make_name("system_id")
         power_type = factory.make_name("power_type")
@@ -873,17 +873,16 @@
         })
 
         def check(response):
-            self.assertThat(PowerAction, MockCalledOnceWith(power_type))
             self.assertThat(
-                PowerAction.return_value.execute,
+                change_power_state,
                 MockCalledOnceWith(
-                    power_change=self.expected_power_change,
-                    **context))
+                    system_id, power_type,
+                    power_change=self.expected_power_change, context=context))
         return d.addCallback(check)
 
     def test_power_on_can_propagate_UnknownPowerType(self):
-        PowerAction = self.patch(clusterservice, "PowerAction")
-        PowerAction.side_effect = UnknownPowerType
+        self.patch(clusterservice, "change_power_state").side_effect = (
+            UnknownPowerType)
 
         d = call_responder(Cluster(), self.command, {
             "system_id": "id", "power_type": "type", "context": {},
@@ -897,8 +896,8 @@
         return d.addErrback(check)
 
     def test_power_on_can_propagate_NotImplementedError(self):
-        PowerAction = self.patch(clusterservice, "PowerAction")
-        PowerAction.side_effect = NotImplementedError
+        self.patch(clusterservice, "change_power_state").side_effect = (
+            NotImplementedError)
 
         d = call_responder(Cluster(), self.command, {
             "system_id": "id", "power_type": "type", "context": {},
@@ -912,8 +911,8 @@
         return d.addErrback(check)
 
     def test_power_on_can_propagate_PowerActionFail(self):
-        PowerAction = self.patch(clusterservice, "PowerAction")
-        PowerAction.return_value.execute.side_effect = PowerActionFail
+        self.patch(clusterservice, "change_power_state").side_effect = (
+            PowerActionFail)
 
         d = call_responder(Cluster(), self.command, {
             "system_id": "id", "power_type": "type", "context": {},
 
=== added file 'src/provisioningserver/rpc/tests/test_power.py'
--- src/provisioningserver/rpc/tests/test_power.py	1970-01-01 00:00:00 +0000
+++ src/provisioningserver/rpc/tests/test_power.py	2014-07-24 10:46:38 +0000
@@ -0,0 +1,232 @@
+# Copyright 2014 Canonical Ltd.  This software is licensed under the
+# GNU Affero General Public License version 3 (see the file LICENSE).
+
+"""Tests for :py:module:`~provisioningserver.rpc.power`."""
+
+from __future__ import (
+    absolute_import,
+    print_function,
+    unicode_literals,
+    )
+
+str = None
+
+__metaclass__ = type
+__all__ = []
+
+
+import random
+
+from maastesting.factory import factory
+from maastesting.matchers import (
+    MockCalledOnceWith,
+    MockCallsMatch,
+    MockNotCalled,
+    )
+from maastesting.testcase import MAASTestCase
+from mock import (
+    call,
+    Mock,
+    )
+from provisioningserver.rpc import power
+from testtools.deferredruntest import (
+    assert_fails_with,
+    AsynchronousDeferredRunTest,
+    )
+from twisted.internet.defer import (
+    inlineCallbacks,
+    maybeDeferred,
+    )
+from twisted.internet.task import Clock
+
+
+class TestPowerHelpers(MAASTestCase):
+
+    run_tests_with = AsynchronousDeferredRunTest.make_factory(timeout=5)
+
+    def patch_power_action(self, return_value=None, side_effect=None):
+        """Patch the PowerAction object.
+
+        Patch the PowerAction object so that PowerAction().execute
+        is replaced by a Mock object created using the given `return_value`
+        and `side_effect`.
+
+        This can be used to simulate various successes or failures patterns
+        while manipulating the power state of a node.
+
+        Returns a tuple of mock objects: power.PowerAction and
+        power.PowerAction().execute.
+        """
+        power_action_obj = Mock()
+        power_action_obj_execute = Mock(
+            return_value=return_value, side_effect=side_effect)
+        power_action_obj.execute = power_action_obj_execute
+        power_action = self.patch(power, 'PowerAction')
+        power_action.return_value = power_action_obj
+        return power_action, power_action_obj_execute
+
+    @inlineCallbacks
+    def test_change_power_state_changes_power_state(self):
+        system_id = factory.make_name('system_id')
+        power_type = random.choice(power.QUERY_POWER_TYPES)
+        power_change = random.choice(['on', 'off'])
+        context = {
+            factory.make_name('context-key'): factory.make_name('context-val')
+        }
+        self.patch(power, 'pause')
+        client = Mock()
+        self.patch(power, 'getRegionClient').return_value = client
+        # Patch the power action utility so that it says the node is
+        # in the required power state.
+        power_action, execute = self.patch_power_action(
+            return_value=power_change)
+
+        yield power.change_power_state(
+            system_id, power_type, power_change, context)
+        self.assertThat(
+            execute,
+            MockCallsMatch(
+                # One call to change the power state.
+                call(power_change=power_change, **context),
+                # One call to query the power state.
+                call(power_change='query', **context),
+            ),
+        )
+        # The node hasn't been marked broken.
+        self.assertThat(client.mark_node_broken, MockNotCalled())
+
+    @inlineCallbacks
+    def test_change_power_state_doesnt_retry_for_certain_power_types(self):
+        system_id = factory.make_name('system_id')
+        # Use a power type that is not among power.QUERY_POWER_TYPES.
+        power_type = factory.make_name('power_type')
+        power_change = random.choice(['on', 'off'])
+        context = {
+            factory.make_name('context-key'): factory.make_name('context-val')
+        }
+        self.patch(power, 'pause')
+        client = Mock()
+        self.patch(power, 'getRegionClient').return_value = client
+        power_action, execute = self.patch_power_action(
+            return_value=random.choice(['on', 'off']))
+
+        yield power.change_power_state(
+            system_id, power_type, power_change, context)
+        self.assertThat(
+            execute,
+            MockCallsMatch(
+                # Only one call to change the power state.
+                call(power_change=power_change, **context),
+            ),
+        )
+        # The node hasn't been marked broken.
+        self.assertThat(client.mark_node_broken, MockNotCalled())
+
+    @inlineCallbacks
+    def test_change_power_state_retries_if_power_state_doesnt_change(self):
+        system_id = factory.make_name('system_id')
+        power_type = random.choice(power.QUERY_POWER_TYPES)
+        power_change = 'on'
+        context = {
+            factory.make_name('context-key'): factory.make_name('context-val')
+        }
+        self.patch(power, 'pause')
+        client = Mock()
+        self.patch(power, 'getRegionClient').return_value = client
+        # Simulate a failure to power up the node, then a success.
+        power_action, execute = self.patch_power_action(
+            side_effect=[None, 'off', None, 'on'])
+
+        yield power.change_power_state(
+            system_id, power_type, power_change, context)
+        self.assertThat(
+            execute,
+            MockCallsMatch(
+                call(power_change=power_change, **context),
+                call(power_change='query', **context),
+                call(power_change=power_change, **context),
+                call(power_change='query', **context),
+            )
+        )
+        # The node hasn't been marked broken.
+        self.assertThat(client.mark_node_broken, MockNotCalled())
+
+    @inlineCallbacks
+    def test_change_power_state_marks_the_node_broken_if_failure(self):
+        system_id = factory.make_name('system_id')
+        power_type = random.choice(power.QUERY_POWER_TYPES)
+        power_change = 'on'
+        context = {
+            factory.make_name('context-key'): factory.make_name('context-val')
+        }
+        self.patch(power, 'pause')
+        client = Mock()
+        self.patch(power, 'getRegionClient').return_value = client
+        # Simulate a persistent failure.
+        power_action, execute = self.patch_power_action(return_value='off')
+
+        yield power.change_power_state(
+            system_id, power_type, power_change, context)
+
+        # The node has been marked broken.
+        self.assertThat(
+            client.mark_node_broken, MockCalledOnceWith(system_id))
+
+    def test_change_power_state_marks_the_node_broken_if_exception(self):
+        system_id = factory.make_name('system_id')
+        power_type = random.choice(power.QUERY_POWER_TYPES)
+        power_change = 'on'
+        context = {
+            factory.make_name('context-key'): factory.make_name('context-val')
+        }
+        self.patch(power, 'pause')
+        client = Mock()
+        self.patch(power, 'getRegionClient').return_value = client
+        # Simulate an exception.
+        power_action, execute = self.patch_power_action(side_effect=Exception)
+
+        d = power.change_power_state(
+            system_id, power_type, power_change, context)
+        assert_fails_with(d, Exception)
+        return d.addErrback(
+            lambda failure: self.assertThat(
+                client.mark_node_broken, MockCalledOnceWith(system_id)))
+
+    def test_change_power_state_pauses_in_between_retries(self):
+        system_id = factory.make_name('system_id')
+        power_type = random.choice(power.QUERY_POWER_TYPES)
+        power_change = 'on'
+        context = {
+            factory.make_name('context-key'): factory.make_name('context-val')
+        }
+        client = Mock()
+        self.patch(power, 'getRegionClient').return_value = client
+        # Simulate two failures to power up the node, then a success.
+        power_action, execute = self.patch_power_action(
+            side_effect=[None, 'off', None, 'off', None, 'on'])
+        self.patch(power, "deferToThread", maybeDeferred)
+        clock = Clock()
+
+        calls_and_pause = [
+            ([
+                call(power_change=power_change, **context),
+            ], 3),
+            ([
+                call(power_change='query', **context),
+                call(power_change=power_change, **context),
+            ], 5),
+            ([
+                call(power_change='query', **context),
+                call(power_change=power_change, **context),
+            ], 10),
+            ([
+                call(power_change='query', **context),
+            ], 0),
+        ]
+        calls = []
+        yield power.change_power_state(
+            system_id, power_type, power_change, context, clock=clock)
+        for newcalls, waiting_time in calls_and_pause:
+            calls.extend(newcalls)
+            self.assertThat(execute, MockCallsMatch(*calls))
+            clock.advance(waiting_time)