Log request ids

We collect request ids from the cloud if they're there. Then, the
current approach is to attach them to the object - but they're ephemeral
and not actually a quality of the object - they're useful for debugging.
Instead of making an object property, log them. That way they can be
used where they're useful - ops logs for after the fact debugging.

The logger is named so that it can be explicitly controlled in a logging
config.

Change-Id: Ie5532cdc316cb00d5f15cae8b2a2f8674ae9da40

releasenotes/notes/log-request-ids-37507cb6eed9a7da.yaml

@@ -0,0 +1,5 @@
+---
+other:
+  - The contents of x-openstack-request-id are no longer
+    added to object returned. Instead, they are logged to
+    a logger named 'shade.request_ids'.

shade/meta.py

@@ -17,6 +17,7 @@ import munch
 import ipaddress
 import six
 
+from shade import _log
 from shade import exc
 
 
@@ -394,9 +395,23 @@ def get_hostvars_from_server(cloud, server, mounts=None):
     return server_vars
 
 
-def _add_request_id(obj, request_id):
+def _log_request_id(obj, request_id):
+    # Add it, if passed in, even though we're going to pop in a second,
+    # just to make the logic simpler
     if request_id is not None:
         obj['x_openstack_request_ids'] = [request_id]
+
+    request_id = None
+    request_ids = obj.pop('x_openstack_request_ids', None)
+    if request_ids:
+        request_id = request_ids[0]
+    if request_id:
+        log = _log.setup_logging('shade.request_ids')
+        # Log the request id and object id in a specific logger. This way
+        # someone can turn it on if they're interested in this kind of tracing.
+        log.debug("Retreived object {id}. Request ID {request_id}".format(
+            id=obj.get('id', obj.get('uuid')), request_id=request_id))
+
     return obj
 
 
@@ -417,7 +432,7 @@ def obj_to_dict(obj, request_id=None):
         return obj
     elif hasattr(obj, 'schema') and hasattr(obj, 'validate'):
         # It's a warlock
-        return _add_request_id(warlock_to_dict(obj), request_id)
+        return _log_request_id(warlock_to_dict(obj), request_id)
     elif isinstance(obj, dict):
         # The new request-id tracking spec:
         # https://specs.openstack.org/openstack/nova-specs/specs/juno/approved/log-request-id-mappings.html
@@ -440,7 +455,7 @@ def obj_to_dict(obj, request_id=None):
             continue
         if isinstance(value, NON_CALLABLES) and not key.startswith('_'):
             instance[key] = value
-    return _add_request_id(instance, request_id)
+    return _log_request_id(instance, request_id)
 
 
 def obj_list_to_dict(obj_list, request_id=None):

shade/tests/unit/test_caching.py

@@ -288,9 +288,7 @@ class TestMemoryCache(base.TestCase):
         mock_compute.get.return_value = mock_response
         self.assertEqual([], self.cloud.list_flavors())
 
-        fake_flavor = fakes.FakeFlavor(
-            '555', 'vanilla', 100, dict(
-                x_openstack_request_ids=['request-id']))
+        fake_flavor = fakes.FakeFlavor('555', 'vanilla', 100)
         fake_flavor_dict = _utils.normalize_flavors(
             [meta.obj_to_dict(fake_flavor)]
         )[0]