mask keystone token in debug output

replaying the keystone token in debug output is both completely
burdensome to read (given it's unbounded size), but it's also
potentially a security issue given that it could be used in replay
attacks.

Instead, filter the headers to sha1 sensitive things, with X-Auth-Token
being the only one listed so far. The sha1 will at least give us the
understanding of tokens being the same or different (and an administrator
could use that to figure out if they were valid later).

This also removes some extra '\n' that were being injected into the
debug logs, because they were not helping with readability.

Lastly, actually test logging. This introduces the first tests of the
logging path using the logging fixture. It's pretty basic, but does
verify that requests are logged at debug, that the SHA1 format works,
and that headers which are not listed get shown straight through.

DocImpact because this changes the curl dumped strings which people
may have been using. They can still do that as long as they generate
their own keystone token.

Change-Id: I1edb94785705c3b6a05f118b77d3aeb07461cd44

novaclient/client.py

@@ -20,6 +20,7 @@
 OpenStack Client interface. Handles the REST calls and responses.
 """
 
+import hashlib
 import logging
 import time
 
@@ -39,6 +40,8 @@ from novaclient.openstack.common import network_utils
 from novaclient import service_catalog
 from novaclient import utils
 
+SENSITIVE_HEADERS = ('X-Auth-Token')
+
 
 class _ClientConnectionPool(object):
 
@@ -160,6 +163,16 @@ class HTTPClient(object):
     def reset_timings(self):
         self.times = []
 
+    def safe_header(self, name, value):
+        if name in SENSITIVE_HEADERS:
+            # because in python3 byte string handling is ... ug
+            v = value.encode('utf-8')
+            h = hashlib.sha1(v)
+            d = h.hexdigest()
+            return name, "SHA1(%s)" % d
+        else:
+            return name, value
+
     def http_log_req(self, method, url, kwargs):
         if not self.http_log_debug:
             return
@@ -172,13 +185,16 @@ class HTTPClient(object):
         string_parts.append(" '%s'" % url)
         string_parts.append(' -X %s' % method)
 
-        for element in kwargs['headers']:
-            header = ' -H "%s: %s"' % (element, kwargs['headers'][element])
+        # because dict ordering changes from 2 to 3
+        keys = sorted(kwargs['headers'].keys())
+        for name in keys:
+            value = kwargs['headers'][name]
+            header = ' -H "%s: %s"' % self.safe_header(name, value)
             string_parts.append(header)
 
         if 'data' in kwargs:
             string_parts.append(" -d '%s'" % (kwargs['data']))
-        self._logger.debug("\nREQ: %s\n" % "".join(string_parts))
+        self._logger.debug("REQ: %s" % "".join(string_parts))
 
     def http_log_resp(self, resp):
         if not self.http_log_debug:

novaclient/tests/test_client.py

@@ -14,9 +14,12 @@
 #    under the License.
 
 
+import logging
 import mock
 import requests
 
+import fixtures
+
 import novaclient.client
 import novaclient.extension
 import novaclient.tests.fakes as fakes
@@ -320,3 +323,36 @@ class ClientTest(utils.TestCase):
         cs = novaclient.client.HTTPClient("user", None, "",
                                           connection_pool=True)
         self.assertEqual(cs._connection_pool, fake_pool)
+
+    def test_log_req(self):
+        self.logger = self.useFixture(
+            fixtures.FakeLogger(
+                format="%(message)s",
+                level=logging.DEBUG,
+                nuke_handlers=True
+            )
+        )
+        cs = novaclient.client.HTTPClient("user", None, "",
+                                          connection_pool=True)
+        cs.http_log_debug = True
+        cs.http_log_req('GET', '/foo', {'headers': {}})
+        cs.http_log_req('GET', '/foo', {'headers':
+                                        {'X-Auth-Token': 'totally_bogus'}
+                                    })
+        cs.http_log_req('GET', '/foo', {'headers':
+                                        {'X-Foo': 'bar',
+                                         'X-Auth-Token': 'totally_bogus'}
+                                    })
+
+        output = self.logger.output.split('\n')
+
+        self.assertIn("REQ: curl -i '/foo' -X GET", output)
+        self.assertIn(
+            "REQ: curl -i '/foo' -X GET -H "
+            '"X-Auth-Token: SHA1(b42162b6ffdbd7c3c37b7c95b7ba9f51dda0236d)"',
+            output)
+        self.assertIn(
+            "REQ: curl -i '/foo' -X GET -H "
+            '"X-Auth-Token: SHA1(b42162b6ffdbd7c3c37b7c95b7ba9f51dda0236d)"'
+            ' -H "X-Foo: bar"',
+            output)