Merge lp:~wallyworld/python-jujuclient/retry-on-upgrade into lp:python-jujuclient

[Ian Booth]

A small moment of time after a freshly bootstrapped Juju environment accepts connections, it may be in an upgrading state.

This branch changes the RPC calls so that if an "upgrade in progress" error is reported, then then RPC call is retried. The retries occur every 1 second, up to a minute.

This change allows the deployer to be more robust to Juju upgrades, since it will now not simply error out.

Fixes bug bug 146017

A small moment of time after a freshly bootstrapped Juju environment accepts connections, it may be in an upgrading state.

This branch changes the RPC calls so that if an "upgrade in progress" error is reported, then then RPC call is retried. The retries occur every 1 second, up to a minute.

This change allows the deployer to be more robust to Juju upgrades, since it will now not simply error out.

[lp:~wallyworld/python-jujuclient/retry-on-upgrade]

60. By Ian Booth on 2015-06-01

Fix test

[John A Meinel (jameinel)]

Overall I think LGTM. I do have a couple comments.

[John A Meinel (jameinel)]

review: Approve

[lp:~wallyworld/python-jujuclient/retry-on-upgrade]

61. By Ian Booth on 2015-06-01

Fix formatting

[Kapil Thangavelu (hazmat)]

i'd suggest UPPER CASING CONSTANTS, the block their being inserted into is full of instance variables where as these are not.

How long is the upgrade expected to last? On new systems 5-10s depending on machine, and extant envs o(n) size of env?

[Kapil Thangavelu (hazmat)]

lgtm

review: Approve

[Adam Collard (adam-collard)]

review: Needs Fixing

[lp:~wallyworld/python-jujuclient/retry-on-upgrade]

62. By Ian Booth on 2015-06-01

Remove stupid ++

63. By Ian Booth on 2015-06-01

Tweak while loop for rpc retries

[Adam Collard (adam-collard)]

I don't think the proposed change will fix the bug.

The error in the linked bug occurred when deployer tried to look at the status (called .get_stat()), which made a new watcher and (tried to) started it. That's when the error that Juju was upgrading occurred.

This branch would make that RPC call to start a new watcher get retried, whilst Juju is upgrading. However, once the upgrade is complete, IIUC one would need to re-authenticate to Juju (and probably renegotiate facade versioning - we've just got a new version of Juju!).

In other words, the retry is at the wrong level.

[Ian Booth (wallyworld)]

> I don't think the proposed change will fix the bug.
>
> The error in the linked bug occurred when deployer tried to look at the status
> (called .get_stat()), which made a new watcher and (tried to) started it.
> That's when the error that Juju was upgrading occurred.
>
> This branch would make that RPC call to start a new watcher get retried,
> whilst Juju is upgrading. However, once the upgrade is complete, IIUC one
> would need to re-authenticate to Juju (and probably renegotiate facade
> versioning - we've just got a new version of Juju!).
>
> In other words, the retry is at the wrong level.

There's appears to be a little misunderstanding of what this fix does. It does not handle the case where Juju disconnects clients when the agents reboot after an agent upgrade.

What the fix does is this. When the Juju agent starts up, the API is in a limited "upgrading" mode while Juju a) performs any version upgrade steps, and b) checks if any agent upgrades are required. Until both of these complete, any attempts to do much more than get status will result in an "upgrade in progress" error. There are no agent restarts during any of this. So the deployer will not become disconnected. But it will get confused in the short window where an "upgrade in progress" error is reported, so this MP teaches it how to deal with that. It simply retries until the full API becomes available, which is what happens 99.9999% of the time when no agent upgrades are necessary.

[Ian Booth (wallyworld)]

TL;DR; this MP fixes bug 1460171 not bug 1455260

[Ian Booth (wallyworld)]

> i'd suggest UPPER CASING CONSTANTS, the block their being inserted into is
> full of instance variables where as these are not.
>
> How long is the upgrade expected to last? On new systems 5-10s depending on
> machine, and extant envs o(n) size of env?

I didn't treat those values as constants, just member variables with defaults. I left it open for them to be changed by set_reconnect_params() if required later.

I have no exact figures on how long upgrade steps (not agent upgrades) will take to run. Typically seconds from what has been observed so far. So 1 minute seems like more than enough. Note this is upgrade steps which run once on the state server, not agent upgrades which requires each agent to restart.

=== modified file 'jujuclient.py'
--- jujuclient.py	2015-05-19 01:17:21 +0000
+++ jujuclient.py	2015-06-01 14:14:11 +0000
@@ -263,11 +263,13 @@
 
 
 class RPC(object):
-
+    _upgrade_retry_delay_secs = 1
+    _upgrade_retry_count = 60
     _auth = False
     _request_id = 0
     _debug = False
     _reconnect_params = None
+
     conn = None
 
     def _rpc(self, op):
@@ -277,6 +279,29 @@
             op['Params'] = {}
         op['RequestId'] = self._request_id
         self._request_id += 1
+        result = self._rpc_retry_if_upgrading(op)
+        if 'Error' in result:
+            # The backend disconnects us on err, bug: http://pad.lv/1160971
+            self.conn.connected = False
+            raise EnvError(result)
+        return result['Response']
+
+    def _rpc_retry_if_upgrading(self, op):
+        """If Juju is upgrading when the specified rpc call is made,
+        retry the call."""
+        retry_count = 0
+        result = {'Response': ''}
+        while retry_count <= self._upgrade_retry_count:
+            result = self._send_request(op)
+            if 'Error' in result and 'upgrade in progress' in result['Error']:
+                log.info("Juju upgrade in progress...")
+                retry_count += 1
+                time.sleep(self._upgrade_retry_delay_secs)
+                continue
+            break
+        return result
+
+    def _send_request(self, op):
         if self._debug:
             log.debug("rpc request:\n%s" % (json.dumps(op, indent=2)))
         self.conn.send(json.dumps(op))
@@ -284,12 +309,7 @@
         result = json.loads(raw)
         if self._debug:
             log.debug("rpc response:\n%s" % (json.dumps(result, indent=2)))
-
-        if 'Error' in result:
-            # The backend disconnects us on err, bug: http://pad.lv/1160971
-            self.conn.connected = False
-            raise EnvError(result)
-        return result['Response']
+        return result
 
     def login(self, password, user="user-admin"):
         """Login gets shared to watchers for reconnect."""

=== modified file 'test_jujuclient.py'
--- test_jujuclient.py	2015-05-18 23:26:08 +0000
+++ test_jujuclient.py	2015-06-01 14:14:11 +0000
@@ -10,7 +10,7 @@
 import yaml
 
 from jujuclient import (
-    Environment, Connector,
+    Environment, EnvError, Connector, RPC,
     # Watch wrappers
     WaitForNoMachines,
     # Facades
@@ -34,6 +34,25 @@
     WaitForNoMachines(watch).run()
 
 
+class ClientRPCTest(unittest.TestCase):
+
+    @mock.patch('jujuclient.RPC._send_request')
+    @mock.patch('jujuclient.RPC._upgrade_retry_delay_secs', 0.001)
+    def test_retry_on_upgrade_error(self, send_request):
+        send_request.return_value = {"Error": "upgrade in progress"}
+        rpc_client = RPC()
+        rpc_client.conn = mock.Mock()
+        self.assertRaises(EnvError, rpc_client.login, "password")
+        self.assertEquals(send_request.call_count, 61)
+
+    @mock.patch('jujuclient.RPC._send_request')
+    def test_no_retry_required(self, send_request):
+        send_request.return_value = {"Error": "some other error"}
+        rpc_client = RPC()
+        rpc_client.conn = mock.Mock()
+        self.assertRaises(EnvError, rpc_client.login, "password")
+        self.assertEquals(send_request.call_count, 1)
+
 class ClientConnectorTest(unittest.TestCase):
 
     @mock.patch('jujuclient.websocket')