Add debug logs for when provider inventory changes

Because of the ProviderTree caching involved in both
the ResourceTracker and SchedulerReportClient, it can
be hard to know if inventory changes are being correctly
reported to the placement service as expected, especially
with things like configurable allocation ratios. This
adds debug logs to the SchedulerReportClient and
ProviderTree to determine if inventory has changed and
when it's flushed back to placement.

Change-Id: Ia6ab3ab4dea08b479bb6b794f408fd2e6f678c50
Related-Bug: #1789654

nova/compute/provider_tree.py

@@ -168,8 +168,12 @@ def update_inventory(self, inventory, generation):
         """
         self._update_generation(generation, 'update_inventory')
         if self.has_inventory_changed(inventory):
+            LOG.debug('Updating inventory in ProviderTree for provider %s '
+                      'with inventory: %s', self.uuid, inventory)
             self.inventory = copy.deepcopy(inventory)
             return True
+        LOG.debug('Inventory has not changed in ProviderTree for provider: %s',
+                  self.uuid)
         return False
 
     def have_traits_changed(self, new):

nova/scheduler/client/report.py

@@ -756,6 +756,9 @@ def _refresh_and_get_inventory(self, context, rp_uuid):
         if curr is None:
             return None
 
+        LOG.debug('Updating ProviderTree inventory for provider %s from '
+                  '_refresh_and_get_inventory using data: %s', rp_uuid,
+                  curr['inventories'])
         self._provider_tree.update_inventory(
             rp_uuid, curr['inventories'],
             generation=curr['resource_provider_generation'])
@@ -863,12 +866,15 @@ def _update_inventory_attempt(self, context, rp_uuid, inv_data):
         # update_resource_stats() is called? :(
         curr = self._refresh_and_get_inventory(context, rp_uuid)
         if curr is None:
+            LOG.debug('No inventory for provider: %s', rp_uuid, inv_data)
             return False
 
         cur_gen = curr['resource_provider_generation']
 
         # Check to see if we need to update placement's view
         if not self._provider_tree.has_inventory_changed(rp_uuid, inv_data):
+            LOG.debug('Inventory has not changed for provider %s based '
+                      'on inventory data: %s', rp_uuid, inv_data)
             return True
 
         payload = {
@@ -961,11 +967,11 @@ def _update_inventory_attempt(self, context, rp_uuid, inv_data):
         # Update our view of the generation for next time
         updated_inventories_result = result.json()
         new_gen = updated_inventories_result['resource_provider_generation']
-
+        LOG.debug('Updating ProviderTree inventory for provider %s with '
+                  'generation %s from _update_inventory_attempt with data: '
+                  '%s', rp_uuid, new_gen, inv_data)
         self._provider_tree.update_inventory(rp_uuid, inv_data,
                                              generation=new_gen)
-        LOG.debug('Updated inventory for %s at generation %i',
-                  rp_uuid, new_gen)
         return True
 
     @safe_connect
@@ -1110,6 +1116,8 @@ def do_put(url, payload):
 
         # If not different from what we've got, short out
         if not self._provider_tree.has_inventory_changed(rp_uuid, inv_data):
+            LOG.debug('Inventory has not changed for provider %s based '
+                      'on inventory data: %s', rp_uuid, inv_data)
             return
 
         # Ensure non-standard resource classes exist, creating them if needed.
@@ -1125,6 +1133,9 @@ def do_put(url, payload):
         resp = do_put(url, payload)
 
         if resp.status_code == 200:
+            LOG.debug('Updated inventory for provider %s with generation %s '
+                      'in Placement from _set_inventory_for_provider using '
+                      'data: %s', rp_uuid, generation, inv_data)
             json = resp.json()
             self._provider_tree.update_inventory(
                 rp_uuid, json['inventories'],