Fix WeighedHost logging regression

Change I8666e0af3f057314f6b06939a108411b8a88d64b in Pike
refactored some code in the FilterScheduler which accidentally
changed how the list of weighed hosts are logged, which caused
the wrapped HostState objects to be logged rather than the
WeighedHost objects, which contain the actual "weight" attribute
which is useful for debugging weigher configuration and
scheduling decisions.

This fixes the regression by logging the weighed hosts before
stripping off the WeighedHost wrapper and adds a simple wrinkle
to an existing test to assert we are logging the correct object.

Change-Id: I528794b4b6f0007efc1238ad28dc402456664f86
Closes-Bug: #1816360

nova/scheduler/filter_scheduler.py

@@ -457,11 +457,12 @@ class FilterScheduler(driver.Scheduler):
                           if w.weight == weighed_hosts[0].weight]
             random.shuffle(best_hosts)
             weighed_hosts = best_hosts + weighed_hosts[len(best_hosts):]
+        # Log the weighed hosts before stripping off the wrapper class so that
+        # the weight value gets logged.
+        LOG.debug("Weighed %(hosts)s", {'hosts': weighed_hosts})
         # Strip off the WeighedHost wrapper class...
         weighed_hosts = [h.obj for h in weighed_hosts]
 
-        LOG.debug("Weighed %(hosts)s", {'hosts': weighed_hosts})
-
         # We randomize the first element in the returned list to alleviate
         # congestion where the same host is consistently selected among
         # numerous potential hosts for similar request specs.

nova/tests/unit/scheduler/test_filter_scheduler.py

@@ -592,10 +592,11 @@ class FilterSchedulerTestCase(test_scheduler.SchedulerTestCase):
         self.assertEqual(0, len(spec_obj.obj_what_changed()),
                          spec_obj.obj_what_changed())
 
+    @mock.patch('nova.scheduler.filter_scheduler.LOG.debug')
     @mock.patch('random.choice', side_effect=lambda x: x[1])
     @mock.patch('nova.scheduler.host_manager.HostManager.get_weighed_hosts')
     @mock.patch('nova.scheduler.host_manager.HostManager.get_filtered_hosts')
-    def test_get_sorted_hosts(self, mock_filt, mock_weighed, mock_rand):
+    def test_get_sorted_hosts(self, mock_filt, mock_weighed, mock_rand, debug):
         """Tests the call that returns a sorted list of hosts by calling the
         host manager's filtering and weighing routines
         """
@@ -610,8 +611,18 @@ class FilterSchedulerTestCase(test_scheduler.SchedulerTestCase):
             weights.WeighedHost(hs1, 1.0), weights.WeighedHost(hs2, 1.0),
         ]
 
+        # Make sure that when logging the weighed hosts we are logging them
+        # with the WeighedHost wrapper class rather than the HostState objects.
+        def fake_debug(message, *args, **kwargs):
+            if message.startswith('Weighed'):
+                self.assertEqual(1, len(args))
+                for weighed_host in args[0]['hosts']:
+                    self.assertIsInstance(weighed_host, weights.WeighedHost)
+        debug.side_effect = fake_debug
+
         results = self.driver._get_sorted_hosts(mock.sentinel.spec,
             all_host_states, mock.sentinel.index)
+        debug.assert_called()
 
         mock_filt.assert_called_once_with(all_host_states, mock.sentinel.spec,
             mock.sentinel.index)