Merge lp:~vila/uci-engine/1302474-nova-transient-failures into lp:uci-engine

[Vincent Ladeuil]

Handle nova transient failures by re-trying failed requests *once*.

This handles nova transient failures by re-trying a failed request *once*.

See https://app.asana.com/0/8499154990155/15202707172731 Handle permanent nova failures for the planned long term solution.

Re-trying once should be enough to guard against most of the issues I've encountered during HP cloud hiccups and should significantly improve the test runner reliability.

Backstory at https://app.asana.com/0/8312550429058/15041456645310 Handle transient nova failures.

More details below.

I've tried a simpler approach with nova.http.adapters['https://'].max_retries = 1 but, apart from peeking far too deep under the covers of the nova client implementation, it didn't provide a way to control which exceptions we wanted to catch nor when nor a way to log them.

This proposal address that by wrapping all the used nova requests into a dedicated nova client (and goes into the right direction for the long term solution).

I also found out that the nova <manager>.find() pattern issues more requests than necessary.

Since I was working on making the requests more reliable, having less of them was a no brainer.

Finally, I've added the MISSINGTESTs and removed a good chunk of FIXMEs (the
remaining ones are unrelated to nova).

[PS Jenkins bot (ps-jenkins)]

FAILED: Continuous integration, rev:745
http://s-jenkins.ubuntu-ci:8080/job/uci-engine-ci/1245/
Executed test runs:

Click here to trigger a rebuild:
http://s-jenkins.ubuntu-ci:8080/job/uci-engine-ci/1245/rebuild

review: Needs Fixing (continuous-integration)

[lp:~vila/uci-engine/1302474-nova-transient-failures]

746. By Vincent Ladeuil on 2014-08-06

Fix pep8 issue.

[PS Jenkins bot (ps-jenkins)]

PASSED: Continuous integration, rev:746
http://s-jenkins.ubuntu-ci:8080/job/uci-engine-ci/1246/
Executed test runs:

Click here to trigger a rebuild:
http://s-jenkins.ubuntu-ci:8080/job/uci-engine-ci/1246/rebuild

review: Approve (continuous-integration)

[Evan (ev)]

This looks good. Top approving as well, since Vincent is on holiday.

review: Approve

=== modified file 'ci-utils/ci_utils/testing/features.py'
--- ci-utils/ci_utils/testing/features.py	2014-07-30 16:24:48 +0000
+++ ci-utils/ci_utils/testing/features.py	2014-08-06 13:17:27 +0000
@@ -67,6 +67,8 @@
         if client is None:
             return False
         try:
+            # can transiently fail with requests.exceptions.ConnectionError
+            # (converted from MaxRetryError).
             client.authenticate()
         except nova_exceptions.ClientException:
             return False
@@ -84,6 +86,9 @@
         except KeyError:
             # If we miss some env vars, we can't get a client
             return None
+        except nova_exceptions.Unauthorized:
+            # If the credentials are wrong, we can't get a client
+            return None
 
 
 # The single instance shared by all tests

=== modified file 'test_runner/tstrun/testbed.py'
--- test_runner/tstrun/testbed.py	2014-07-31 08:46:00 +0000
+++ test_runner/tstrun/testbed.py	2014-08-06 13:17:27 +0000
@@ -17,19 +17,20 @@
 
 import logging
 import os
-import requests
 import subprocess
 import time
 
+import requests
 
-from novaclient import exceptions
-from novaclient.v1_1 import client
+from novaclient import (
+    client,
+    exceptions,
+)
 from uciconfig import options
 from ucivms import (
     config,
     vms,
 )
-
 from ci_utils import unit_config
 
 
@@ -99,6 +100,18 @@
 a way to do so. This is intended to be fixed in uci-vms so vm.apt_sources can
 be used again.
 '''))
+register(options.Option('vm.nova.boot_timeout', default='300',
+                        from_unicode=options.float_from_store,
+                        help_string='''\
+Max time to boot a nova instance (in seconds).'''))
+register(options.Option('vm.nova.set_ip_timeout', default='300',
+                        from_unicode=options.float_from_store,
+                        help_string='''\
+Max time for a nova instance to get an IP (in seconds).'''))
+register(options.Option('vm.nova.cloud_init_timeout', default='1200',
+                        from_unicode=options.float_from_store,
+                        help_string='''\
+Max time for cloud-init to fisnish (in seconds).'''))
 
 
 logging.basicConfig(level=logging.INFO)
@@ -134,8 +147,69 @@
     return conf
 
 
+class NovaClient(object):
+    """A nova client re-trying requests on known transient failures."""
+
+    def __init__(self, *args, **kwargs):
+        debug = kwargs.pop('debug', False)
+        # Activating debug will output the http requests issued by nova and the
+        # corresponding responses.
+        if debug:
+            logging.root.setLevel(logging.DEBUG)
+        self.nova = client.Client('1.1', *args, http_log_debug=debug,
+                                  **kwargs)
+
+    def retry(self, func, *args, **kwargs):
+        try:
+            return func(*args, **kwargs)
+        except requests.ConnectionError:
+            # Most common transient failure: the API server is unreachable
+            nap_time = 1
+            log.warn('Received connection error for {},'
+                     ' retrying)'.format(func.__name__))
+        except exceptions.OverLimit:
+                # This happens rarely but breaks badly if not caught. elmo
+                # recommended a 30 seconds nap in that case.
+                nap_time = 30
+                msg = ('Rate limit reached for {},'
+                       ' will sleep for {} seconds')
+                log.exception(msg.format(func.__name__, nap_time))
+        time.sleep(nap_time)
+        return func(*args, **kwargs)  # Retry once
+
+    def flavors_list(self):
+        return self.retry(self.nova.flavors.list)
+
+    def images_list(self):
+        return self.retry(self.nova.images.list)
+
+    def create_server(self, name, flavor, image, user_data):
+        return self.retry(self.nova.servers.create, name=name,
+                          flavor=flavor, image=image, userdata=user_data)
+
+    def delete_server(self, server_id):
+        return self.retry(self.nova.servers.delete, server_id)
+
+    def create_floating_ip(self):
+        return self.retry(self.nova.floating_ips.create)
+
+    def delete_floating_ip(self, floating_ip):
+        return self.retry(self.nova.floating_ips.delete, floating_ip)
+
+    def add_floating_ip(self, instance, floating_ip):
+        return self.retry(instance.add_floating_ip, floating_ip)
+
+    def get_server_details(self, server_id):
+        return self.retry(self.nova.servers.get, server_id)
+
+    def get_server_console(self, server, length=None):
+        return self.retry(server.get_console_output, length)
+
+
 class TestBed(vms.VM):
 
+    nova_client_class = NovaClient
+
     def __init__(self, conf):
         super(TestBed, self).__init__(conf)
         self.instance = None
@@ -155,7 +229,8 @@
                 self.conf.get('os.auth_url')]
         kwargs = {'region_name': self.conf.get('os.region_name'),
                   'service_type': 'compute'}
-        return client.Client(*args, **kwargs)
+        nova_client = self.nova_client_class(*args, **kwargs)
+        return nova_client
 
     def ensure_ssh_key_is_available(self):
         self.test_bed_key_path = self.conf.get('vm.ssh_key_path')
@@ -173,23 +248,22 @@
                  '-f', self.test_bed_key_path, '-N', ''])
 
     def find_flavor(self):
-        for flavor in self.conf.get('vm.flavors'):
-            try:
-                return self.nova.flavors.find(name=flavor)
-            except exceptions.NotFound:
-                pass
-        # MISSINGTEST: some cloud doesn't provide one of our expected flavors
-        # -- vila 2014-01-06
+        flavors = self.conf.get('vm.flavors')
+        existing_flavors = self.nova.flavors_list()
+        for flavor in flavors:
+            for existing in existing_flavors:
+                if flavor == existing.name:
+                    return existing
         raise TestBedException(
-            'None of {} can be found'.format(self.flavors))
+            'None of [{}] can be found'.format(','.join(flavors)))
 
     def find_nova_image(self):
         image_name = self.conf.get('vm.image')
-        try:
-            return self.nova.images.find(name=image_name)
-        except exceptions.NotFound:
-            raise TestBedException(
-                'Image "{}" cannot be found'.format(image_name))
+        existing_images = self.nova.images_list()
+        for existing in existing_images:
+            if image_name == existing.name:
+                return existing
+        raise TestBedException('Image "{}" cannot be found'.format(image_name))
 
     def setup(self):
         flavor = self.find_flavor()
@@ -198,13 +272,13 @@
         self.create_user_data()
         with open(self._user_data_path) as f:
             user_data = f.read()
-        self.instance = self.nova.servers.create(
+        self.instance = self.nova.create_server(
             name=self.conf.get('vm.name'), flavor=flavor, image=image,
-            userdata=user_data)
+            user_data=user_data)
         self.wait_for_active_instance()
         if unit_config.is_hpcloud(self.conf.get('os.auth_url')):
-            self.floating_ip = self.nova.floating_ips.create()
-            self.instance.add_floating_ip(self.floating_ip)
+            self.floating_ip = self.nova.create_floating_ip()
+            self.nova.add_floating_ip(self.instance, self.floating_ip)
         self.wait_for_ip()
         self.wait_for_cloud_init()
         ppas = self.conf.get('vm.ppas')
@@ -236,38 +310,29 @@
         raise TestBedException('apt-get update never succeeded')
 
     def update_instance(self):
-        # MISSINGTEST: What if the instance disappear ? (could be approximated
-        # by deleting the nova instance) -- vila 2014-06-05
         try:
             # Always query nova to get updated data about the instance
-            self.instance = self.nova.servers.get(self.instance.id)
+            self.instance = self.nova.get_server_details(self.instance.id)
             return True
-        except requests.ConnectionError:
-            # The reported status is the one known before the last attempt.
-            log.warn('Received connection error for {},'
-                     ' retrying (status was: {})'.format(
-                         self.instance.id, self.instance.status))
-        return False
+        except:
+            # But catch exceptions if something goes wrong. Higher levels will
+            # deal with the instance not replying.
+            return False
 
     def wait_for_active_instance(self):
-        # FIXME: get_active_instance should be a config option
-        # -- vila 2014-05-13
-        get_active_instance = 300  # in seconds so 5 minutes
-        timeout_limit = time.time() + get_active_instance
-        while time.time() < timeout_limit and self.instance.status != 'ACTIVE':
-            time.sleep(5)
+        timeout_limit = time.time() + self.conf.get('vm.nova.boot_timeout')
+        while (time.time() <= timeout_limit
+               and self.instance.status != 'ACTIVE'):
             self.update_instance()
+            time.sleep(5)
         if self.instance.status != 'ACTIVE':
-            # MISSINGTEST: What if the instance doesn't come up ?
             msg = 'Instance never came up (last status: {})'.format(
                 self.instance.status)
             raise TestBedException(msg)
 
     def wait_for_ip(self):
-        # FIXME: get_ip_timeout should be a config option -- vila 2014-01-30
-        get_ip_timeout = 300  # in seconds so 5 minutes
-        timeout_limit = time.time() + get_ip_timeout
-        while time.time() < timeout_limit:
+        timeout_limit = time.time() + self.conf.get('vm.nova.set_ip_timeout')
+        while time.time() <= timeout_limit:
             if not self.update_instance():
                 time.sleep(5)
                 continue
@@ -280,46 +345,25 @@
                 # the floating one. In both cases that gives us a reachable IP.
                 self.ip = networks[0][-1]
                 log.info('Got IP {} for {}'.format(self.ip, self.instance.id))
-                # FIXME: Right place to report how long it took to spin up the
-                # instance as far as nova is concerned. -- vila 2014-01-30
                 return
             else:
                 log.info(
                     'IP not yet available for {}'.format(self.instance.id))
             time.sleep(5)
-        # MISSINGTEST: What if the instance still doesn't have an ip ?
         msg = 'Instance {} never provided an IP'.format(self.instance.id)
         raise TestBedException(msg)
 
     def get_cloud_init_console(self, length=None):
-        return self.instance.get_console_output(length)
+        return self.nova.get_server_console(self.instance, length)
 
     def wait_for_cloud_init(self):
-        # FIXME: cloud_init_timeout should be a config option (related to
-        # get_ip_timeout and probably the two can be merged) -- vila 2014-01-30
-        cloud_init_timeout = 1200  # in seconds so 20 minutes
-        timeout_limit = time.time() + cloud_init_timeout
+        timeout_limit = (time.time()
+                         + self.conf.get('vm.nova.cloud_init_timeout'))
         final_message = self.conf.get('vm.final_message')
         while time.time() < timeout_limit:
             # A relatively cheap way to catch cloud-init completion is to watch
             # the console for the specific message we specified in user-data).
-            try:
-                console = self.get_cloud_init_console(10)
-            except exceptions.OverLimit:
-                # This happens rarely but breaks badly if not caught. elmo
-                # recommended a 30 seconds nap in that case.
-                nap_time = 30
-                msg = ('Rate limit while acquiring nova console for {},'
-                       ' will sleep for {} seconds')
-                log.exception(msg.format(self.instance.id, nap_time))
-                time.sleep(nap_time)
-                continue
-            except requests.ConnectionError:
-                # The reported status is the one known before the last attempt.
-                log.warn('Received connection error for {},'
-                         ' retrying)'.format(self.instance.id))
-                time.sleep(5)
-                continue
+            console = self.get_cloud_init_console(10)
             if final_message in console:
                 # We're good to go
                 log.info(
@@ -330,10 +374,10 @@
 
     def teardown(self):
         if self.instance is not None:
-            self.nova.servers.delete(self.instance.id)
+            self.nova.delete_server(self.instance.id)
             self.instance = None
         if self.floating_ip is not None:
-            self.nova.floating_ips.delete(self.floating_ip)
+            self.nova.delete_floating_ip(self.floating_ip)
             self.floating_ip = None
         # FIXME: Now we can remove the testbed key from known_hosts (see
         # ssh()). -- vila 2014-01-30

=== modified file 'test_runner/tstrun/tests/test_testbed.py'
--- test_runner/tstrun/tests/test_testbed.py	2014-07-30 15:41:08 +0000
+++ test_runner/tstrun/tests/test_testbed.py	2014-08-06 13:17:27 +0000
@@ -19,11 +19,14 @@
 import subprocess
 import unittest
 
-
+import requests
 from uciconfig import options
+from ucitests import (
+    assertions,
+    fixtures,
+)
 from ucivms.tests import fixtures as vms_fixtures
 
-
 from ci_utils import unit_config
 from ci_utils.testing import (
     features,
@@ -36,6 +39,97 @@
 
 @features.requires(tests.nova_creds)
 @features.requires(features.nova_compute)
+class TestNovaClient(unittest.TestCase):
+    """Check the nova client behavior when it encounters exceptions.
+
+    This is achieved by overriding specific methods from NovaClient and
+    exercising it through the TestBed methods.
+    """
+
+    def setUp(self):
+        super(TestNovaClient, self).setUp()
+        vms_fixtures.isolate_from_disk(self)
+        self.tb_name = 'testing-nova-client'
+        # Prepare a suitable config, importing the nova credentials
+        conf = testbed.vms_config_from_auth_config(
+            self.tb_name, unit_config.get_auth_config())
+        # Default to precise
+        conf.set('vm.release', 'precise')
+        # Avoid triggering the 'atexit' hook as the config files are long gone
+        # at that point.
+        self.addCleanup(conf.store.save_changes)
+        self.conf = conf
+        os.makedirs(self.conf.get('vm.vms_dir'))
+
+    def get_image_id(self, series='precise'):
+        if unit_config.is_hpcloud(self.conf.get('os.auth_url')):
+            test_images = features.hpcloud_test_images
+        else:
+            test_images = features.canonistack_test_images
+        return test_images[series]
+
+    def test_retry_is_called(self):
+        self.retry_calls = []
+
+        class RetryingNovaClient(testbed.NovaClient):
+
+            def retry(inner, func, *args, **kwargs):
+                self.retry_calls.append((func, args, kwargs))
+                return super(RetryingNovaClient, inner).retry(
+                    func, *args, **kwargs)
+
+        image_id = self.get_image_id()
+        self.conf.set('vm.image', image_id)
+        fixtures.patch(self, testbed.TestBed,
+                       'nova_client_class', RetryingNovaClient)
+        tb = testbed.TestBed(self.conf)
+        self.assertEqual(image_id, tb.find_nova_image().name)
+        assertions.assertLength(self, 1, self.retry_calls)
+
+    def test_known_failure_is_retried(self):
+        self.nb_calls = 0
+
+        class FailingOnceNovaClient(testbed.NovaClient):
+
+            def fail_once(inner):
+                self.nb_calls += 1
+                if self.nb_calls == 1:
+                    raise requests.ConnectionError()
+                else:
+                    return inner.nova.flavors.list()
+
+            def flavors_list(inner):
+                return inner.retry(inner.fail_once)
+
+        fixtures.patch(self, testbed.TestBed,
+                       'nova_client_class', FailingOnceNovaClient)
+        tb = testbed.TestBed(self.conf)
+        tb.find_flavor()
+        self.assertEqual(2, self.nb_calls)
+
+    def test_unknown_failure_is_raised(self):
+
+        class FailingNovaClient(testbed.NovaClient):
+
+            def fail(inner):
+                raise AssertionError('Boom!')
+
+            def flavors_list(inner):
+                return inner.retry(inner.fail)
+
+        fixtures.patch(self, testbed.TestBed,
+                       'nova_client_class', FailingNovaClient)
+        tb = testbed.TestBed(self.conf)
+        # This mimics what will happen when we encounter unknown transient
+        # failures we want to catch: an exception will bubble up and we'll have
+        # to add it to NovaClient.retry().
+        with self.assertRaises(AssertionError) as cm:
+            tb.find_flavor()
+        self.assertEqual('Boom!', unicode(cm.exception))
+
+
[e-mail](tests.nova_creds)
[e-mail](features.nova_compute)
 class TestTestbed(unittest.TestCase):
 
     def setUp(self):
@@ -66,42 +160,51 @@
             tb.setup()
         self.assertEqual('vm.image must be set.', unicode(cm.exception))
 
-    def test_create_unknown(self):
-        tb = testbed.TestBed(self.conf)
+    def test_create_unknown_image(self):
         image_name = "I don't exist and eat kittens"
         self.conf.set('vm.image', image_name)
+        tb = testbed.TestBed(self.conf)
         with self.assertRaises(testbed.TestBedException) as cm:
             tb.setup()
         self.assertEqual('Image "{}" cannot be found'.format(image_name),
                          unicode(cm.exception))
 
+    def test_create_unknown_flavor(self):
+        flavors = "I don't exist and eat kittens"
+        self.conf.set('vm.flavors', flavors)
+        tb = testbed.TestBed(self.conf)
+        with self.assertRaises(testbed.TestBedException) as cm:
+            tb.setup()
+        self.assertEqual('None of [{}] can be found'.format(flavors),
+                         unicode(cm.exception))
+
     def test_existing_home_ssh(self):
         # The first request for the worker requires creating ~/.ssh if it
         # doesn't exist, but it may happen that this directory already exists
         # (see http://pad.lv/1334146).
-        tb = testbed.TestBed(self.conf)
         ssh_home = os.path.expanduser('~/sshkeys')
         os.mkdir(ssh_home)
         self.conf.set('vm.ssh_key_path', os.path.join(ssh_home, 'id_rsa'))
+        tb = testbed.TestBed(self.conf)
         tb.ensure_ssh_key_is_available()
         self.assertTrue(os.path.exists(ssh_home))
         self.assertTrue(os.path.exists(os.path.join(ssh_home, 'id_rsa')))
         self.assertTrue(os.path.exists(os.path.join(ssh_home, 'id_rsa.pub')))
 
     def test_create_new_ssh_key(self):
-        tb = testbed.TestBed(self.conf)
         self.conf.set('vm.image', self.get_image_id())
         # We use a '~' path to cover proper uci-vms user expansion
         self.conf.set('vm.ssh_key_path', '~/sshkeys/id_rsa')
+        tb = testbed.TestBed(self.conf)
         tb.ensure_ssh_key_is_available()
         self.assertTrue(os.path.exists(os.path.expanduser('~/sshkeys/id_rsa')))
         self.assertTrue(
             os.path.exists(os.path.expanduser('~/sshkeys/id_rsa.pub')))
 
     def test_create_usable_testbed(self):
-        tb = testbed.TestBed(self.conf)
         self.conf.set('vm.release', 'saucy')
         self.conf.set('vm.image', self.get_image_id('saucy'))
+        tb = testbed.TestBed(self.conf)
         self.addCleanup(tb.teardown)
         tb.setup()
         # We should be able to ssh with the right user
@@ -111,9 +214,9 @@
         self.assertEqual('ubuntu\n', out)
 
     def test_apt_get_update_retries(self):
-        tb = testbed.TestBed(self.conf)
         self.conf.set('vm.image', self.get_image_id())
         self.conf.set('vm.apt_get.update.timeouts', '0.1, 0.1')
+        tb = testbed.TestBed(self.conf)
         self.nb_calls = 0
 
         class Proc(object):
@@ -134,9 +237,9 @@
         self.assertEqual(2, self.nb_calls)
 
     def test_apt_get_update_fails(self):
-        tb = testbed.TestBed(self.conf)
         self.conf.set('vm.image', self.get_image_id())
         self.conf.set('vm.apt_get.update.timeouts', '0.1, 0.1, 0.1')
+        tb = testbed.TestBed(self.conf)
 
         def failing_update():
             class Proc(object):
@@ -151,3 +254,25 @@
             tb.safe_apt_get_update()
         self.assertEqual('apt-get update never succeeded',
                          unicode(cm.exception))
+
+    def test_wait_for_instance_fails(self):
+        self.conf.set('vm.image', self.get_image_id())
+        # Force a 0 timeout so the instance can't finish booting
+        self.conf.set('vm.nova.boot_timeout', '0')
+        tb = testbed.TestBed(self.conf)
+        self.addCleanup(tb.teardown)
+        with self.assertRaises(testbed.TestBedException) as cm:
+            tb.setup()
+        self.assertEqual('Instance never came up (last status: BUILD)',
+                         unicode(cm.exception))
+
+    def test_wait_for_ip_fails(self):
+        self.conf.set('vm.image', self.get_image_id())
+        # Force a 0 timeout so the instance never get an IP
+        self.conf.set('vm.nova.set_ip_timeout', '0')
+        tb = testbed.TestBed(self.conf)
+        self.addCleanup(tb.teardown)
+        with self.assertRaises(testbed.TestBedException) as cm:
+            tb.setup()
+        msg = 'Instance {} never provided an IP'.format(tb.instance.id)
+        self.assertEqual(msg, unicode(cm.exception))

=== modified file 'test_runner/tstrun/tests/test_worker.py'
--- test_runner/tstrun/tests/test_worker.py	2014-07-31 18:29:40 +0000
+++ test_runner/tstrun/tests/test_worker.py	2014-08-06 13:17:27 +0000
@@ -147,9 +147,9 @@
         worker = run_worker.TestRunnerWorker(self.ds_factory)
 
         def broken_teardown(test_bed):
-            self.addCleanup(test_bed.nova.servers.delete, test_bed.instance.id)
+            self.addCleanup(test_bed.nova.delete_server, test_bed.instance.id)
             if test_bed.floating_ip is not None:
-                self.addCleanup(test_bed.nova.floating_ips.delete,
+                self.addCleanup(test_bed.nova.delete_floating_ip,
                                 test_bed.floating_ip)
             raise AssertionError('Boom !')