XenAPI: Add host information to glance download logs

This change adds a context field to the xenapi session
call_plugin_serialized_with_retry method to provide better
logging information.  This is then used by the glance image
downloading to provide the host IP we are contacting.  This
saves having to dig through other logs to get this information.

I added a mock unit test to test_glance to verify the download
retry mechanism works since this wasn't verified before.
It is the first mock test in test_glance.py

Change-Id: I4de2b9e61ce25fb8ab693eac2f67559d0eb01a77

3 files changed, 56 insertions, 5 deletions

diff --git a/nova/tests/virt/xenapi/image/test_glance.py b/nova/tests/virt/xenapi/image/test_glance.py
index c6f90322d1..51cf032983 100644
--- a/nova/tests/virt/xenapi/image/test_glance.py
+++ b/nova/tests/virt/xenapi/image/test_glance.py
@@ -13,10 +13,14 @@
 #    License for the specific language governing permissions and limitations
 #    under the License.
 
+import random
 import time
 
+import mock
+
 from nova import context
 from nova import exception
+from nova.openstack.common import log as logging
 from nova.tests.virt.xenapi import stubs
 from nova.virt.xenapi import driver as xenapi_conn
 from nova.virt.xenapi import fake
@@ -86,6 +90,48 @@ class TestGlanceStore(stubs.XenAPITestBaseNoDB):
 
         self.mox.VerifyAll()
 
+    @mock.patch.object(vm_utils, '_make_uuid_stack', return_value=['uuid1'])
+    @mock.patch.object(random, 'shuffle')
+    @mock.patch.object(time, 'sleep')
+    @mock.patch.object(logging.getLogger('nova.virt.xenapi.client.session'),
+                       'debug')
+    def test_download_image_retry(self, mock_log_debug,
+                                  mock_sleep, mock_shuffle,
+                                  mock_make_uuid_stack):
+        params = self._get_download_params()
+        self.flags(glance_num_retries=2)
+
+        params.pop("glance_port")
+        params.pop("glance_host")
+        calls = [mock.call('glance', 'download_vhd', glance_port=9292,
+                           glance_host='10.0.1.1', **params),
+                 mock.call('glance', 'download_vhd', glance_port=9293,
+                            glance_host='10.0.0.1', **params)]
+        log_calls = [mock.call(mock.ANY, {'callback_result': '10.0.1.1',
+                                          'attempts': 3, 'attempt': 1,
+                                          'fn': 'download_vhd',
+                                          'plugin': 'glance'}),
+                     mock.call(mock.ANY, {'callback_result': '10.0.0.1',
+                                          'attempts': 3, 'attempt': 2,
+                                          'fn': 'download_vhd',
+                                          'plugin': 'glance'})]
+
+        glance_api_servers = ['10.0.1.1:9292',
+                              'http://10.0.0.1:9293']
+        self.flags(glance_api_servers=glance_api_servers)
+
+        with (mock.patch.object(self.session, 'call_plugin_serialized')
+          ) as mock_call_plugin_serialized:
+            error_details = ["", "", "RetryableError", ""]
+            error = self.session.XenAPI.Failure(details=error_details)
+            mock_call_plugin_serialized.side_effect = [error, "success"]
+
+            vdis = self.store.download_image(
+                self.context, self.session, self.instance, 'fake_image_uuid')
+
+            mock_call_plugin_serialized.assert_has_calls(calls)
+            mock_log_debug.assert_has_calls(log_calls, any_order=True)
+
     def _get_upload_params(self, auto_disk_config=True,
                            expected_os_type='default'):
         params = self._get_params()
diff --git a/nova/virt/xenapi/client/session.py b/nova/virt/xenapi/client/session.py
index 23cb9887fc..e23948a7a7 100644
--- a/nova/virt/xenapi/client/session.py
+++ b/nova/virt/xenapi/client/session.py
@@ -210,17 +210,21 @@ class XenAPISession(object):
         attempts = num_retries + 1
         sleep_time = 0.5
         for attempt in xrange(1, attempts + 1):
-            LOG.info(_('%(plugin)s.%(fn)s attempt %(attempt)d/%(attempts)d'),
-                     {'plugin': plugin, 'fn': fn, 'attempt': attempt,
-                      'attempts': attempts})
             try:
                 if attempt > 1:
                     time.sleep(sleep_time)
                     sleep_time = min(2 * sleep_time, 15)
 
+                callback_result = None
                 if callback:
-                    callback(kwargs)
-
+                    callback_result = callback(kwargs)
+
+                msg = _('%(plugin)s.%(fn)s attempt %(attempt)d/%(attempts)d, '
+                        'callback_result: %(callback_result)s')
+                LOG.debug(msg,
+                          {'plugin': plugin, 'fn': fn, 'attempt': attempt,
+                           'attempts': attempts,
+                           'callback_result': callback_result})
                 return self.call_plugin_serialized(plugin, fn, *args, **kwargs)
             except self.XenAPI.Failure as exc:
                 if self._is_retryable_exception(exc):
diff --git a/nova/virt/xenapi/image/glance.py b/nova/virt/xenapi/image/glance.py
index ebfc14efb6..2315cb1233 100644
--- a/nova/virt/xenapi/image/glance.py
+++ b/nova/virt/xenapi/image/glance.py
@@ -33,6 +33,7 @@ class GlanceStore(object):
             kwargs['glance_host'] = g_host
             kwargs['glance_port'] = g_port
             kwargs['glance_use_ssl'] = g_use_ssl
+            return g_host
 
         return session.call_plugin_serialized_with_retry(
             'glance', fn, CONF.glance_num_retries, pick_glance, **params)