Do not reveal auth token in swiftclient log messages by default

Currently the swiftclient logs sensitive info in headers when logging
HTTP requests. This patch hides sensitive info in headers such as
'X-Auth-Token' in a similar way to swift itself (we add a
'reveal_sensitive_prefix' configuration to the client).

With this patch, tokens are truncated by removing the specified number
of characters, after which '...' is appended to the logged token to
indicate that it has been redacted.

Co-Authored-By: Li Cheng <shcli@cn.ibm.com>
Co-Authored-By: Zack M. Davis <zdavis@swiftstack.com>
Change-Id: I43dd7254f7281d4db59b286aa2145643c64e1705
Closes-bug: #1516692

swiftclient/client.py

@@ -72,6 +72,64 @@ def prepare_unicode_headers(self, headers):
 logger = logging.getLogger("swiftclient")
 logger.addHandler(NullHandler())
 
+#: Default behaviour is to redact tokens, showing only the initial 16 chars.
+#: To disable, set the value of 'redact_sensitive_tokens' to False.
+#: When token redaction is enabled 'reveal_sensitive_prefix' configures the
+#: maximum length of any sensitive token data sent to the logs (if the token
+#: is less than 32 chars long then int(len(token)/2) chars will be logged,
+logger_settings = {
+    'redact_sensitive_tokens': True,
+    'reveal_sensitive_prefix': 16
+}
+#: A list of sensitive headers to redact in logs. Note that when extending this
+#: list, the header names must be added in all lower case.
+LOGGER_SENSITIVE_HEADERS = [
+    'x-auth-token', 'x-auth-key', 'x-service-token', 'x-storage-token',
+    'x-account-meta-temp-url-key', 'x-account-meta-temp-url-key-2',
+    'x-container-meta-temp-url-key', 'x-container-meta-temp-url-key-2',
+    'set-cookie'
+]
+
+
+def safe_value(name, value):
+    """
+    Only show up to logger_settings['reveal_sensitive_prefix'] characters
+    from a sensitive header.
+
+    :param name: Header name
+    :param value: Header value
+    :return: Safe (header, value) pair
+    """
+    if name.lower() in LOGGER_SENSITIVE_HEADERS:
+        prefix_length = logger_settings.get('reveal_sensitive_prefix', 16)
+        prefix_length = int(
+            min(prefix_length, (len(value) ** 2) / 32, len(value) / 2)
+        )
+        redacted_value = value[0:prefix_length]
+        return redacted_value + '...'
+    return value
+
+
+def scrub_headers(headers):
+    """
+    Redact header values that can contain sensitive information that
+    should not be logged.
+
+    :param headers: Either a dict or an iterable of two-element tuples
+    :return: Safe dictionary of headers with sensitive information removed
+    """
+    if isinstance(headers, dict):
+        headers = headers.items()
+    headers = [
+        (parse_header_string(key), parse_header_string(val))
+        for (key, val) in headers
+    ]
+    if not logger_settings.get('redact_sensitive_tokens', True):
+        return dict(headers)
+    if logger_settings.get('reveal_sensitive_prefix', 16) < 0:
+        logger_settings['reveal_sensitive_prefix'] = 16
+    return {key: safe_value(key, val) for (key, val) in headers}
+
 
 def http_log(args, kwargs, resp, body):
     if not logger.isEnabledFor(logging.INFO):
@@ -87,8 +145,9 @@ def http_log(args, kwargs, resp, body):
         else:
             string_parts.append(' %s' % element)
     if 'headers' in kwargs:
-        for element in kwargs['headers']:
-            header = ' -H "%s: %s"' % (element, kwargs['headers'][element])
+        headers = scrub_headers(kwargs['headers'])
+        for element in headers:
+            header = ' -H "%s: %s"' % (element, headers[element])
             string_parts.append(header)
 
     # log response as debug if good, or info if error
@@ -99,7 +158,7 @@ def http_log(args, kwargs, resp, body):
 
     log_method("REQ: %s", "".join(string_parts))
     log_method("RESP STATUS: %s %s", resp.status, resp.reason)
-    log_method("RESP HEADERS: %s", resp.getheaders())
+    log_method("RESP HEADERS: %s", scrub_headers(resp.getheaders()))
     if body:
         log_method("RESP BODY: %s", body)
 
@@ -386,11 +445,11 @@ def get_auth_1_0(url, user, key, snet, **kwargs):
     parsed, conn = http_connection(url, cacert=cacert, insecure=insecure,
                                    timeout=timeout)
     method = 'GET'
-    conn.request(method, parsed.path, '',
-                 {'X-Auth-User': user, 'X-Auth-Key': key})
+    headers = {'X-Auth-User': user, 'X-Auth-Key': key}
+    conn.request(method, parsed.path, '', headers)
     resp = conn.getresponse()
     body = resp.read()
-    http_log((url, method,), {}, resp, body)
+    http_log((url, method,), headers, resp, body)
     url = resp.getheader('x-storage-url')
 
     # There is a side-effect on current Rackspace 1.0 server where a

swiftclient/shell.py

@@ -33,6 +33,7 @@
 from swiftclient.multithreading import OutputManager
 from swiftclient.exceptions import ClientException
 from swiftclient import __version__ as client_version
+from swiftclient.client import logger_settings as client_logger_settings
 from swiftclient.service import SwiftService, SwiftError, \
     SwiftUploadObject, get_conn
 from swiftclient.command_helpers import print_account_stats, \
@@ -1107,6 +1108,7 @@ def parse_args(parser, args, enforce_requires=True):
         if options.debug:
             logging.basicConfig(level=logging.DEBUG)
             logging.getLogger('iso8601').setLevel(logging.WARNING)
+            client_logger_settings['redact_sensitive_tokens'] = False
         elif options.info:
             logging.basicConfig(level=logging.INFO)
 

tests/unit/test_swiftclient.py

@@ -987,7 +987,7 @@ def test_unicode_ok(self):
                 mock_file)
         text = u'\u5929\u7a7a\u4e2d\u7684\u4e4c\u4e91'
         headers = {'X-Header1': text,
-                   'X-2': 1, 'X-3': {'a': 'b'}, 'a-b': '.x:yz mn:fg:lp'}
+                   'X-2': '1', 'X-3': "{'a': 'b'}", 'a-b': '.x:yz mn:fg:lp'}
 
         resp = MockHttpResponse()
         conn[1].getresponse = resp.fake_response
@@ -1221,7 +1221,7 @@ def test_unicode_ok(self):
         text = u'\u5929\u7a7a\u4e2d\u7684\u4e4c\u4e91'
         headers = {'X-Header1': text,
                    b'X-Header2': 'value',
-                   'X-2': '1', 'X-3': {'a': 'b'}, 'a-b': '.x:yz mn:kl:qr',
+                   'X-2': '1', 'X-3': "{'a': 'b'}", 'a-b': '.x:yz mn:kl:qr',
                    'X-Object-Meta-Header-not-encoded': text,
                    b'X-Object-Meta-Header-encoded': 'value'}
 
@@ -2188,6 +2188,78 @@ def test_get_error(self):
                               'http://www.test.com', 'asdf', 'asdf', 'asdf')
         self.assertEqual(e.http_status, 404)
 
+    def test_redact_token(self):
+        with mock.patch('swiftclient.client.logger.debug') as mock_log:
+            token_value = 'tkee96b40a8ca44fc5ad72ec5a7c90d9b'
+            unicode_token_value = (u'\u5929\u7a7a\u4e2d\u7684\u4e4c\u4e91'
+                                   u'\u5929\u7a7a\u4e2d\u7684\u4e4c\u4e91'
+                                   u'\u5929\u7a7a\u4e2d\u7684\u4e4c')
+            set_cookie_value = 'X-Auth-Token=%s' % token_value
+            c.http_log(
+                ['GET'],
+                {'headers': {
+                    'X-Auth-Token': token_value,
+                    'X-Storage-Token': unicode_token_value
+                }},
+                MockHttpResponse(
+                    status=200,
+                    headers={
+                        'X-Auth-Token': token_value,
+                        'X-Storage-Token': unicode_token_value,
+                        'Etag': b'mock_etag',
+                        'Set-Cookie': set_cookie_value
+                    }
+                ),
+                ''
+            )
+            out = []
+            for _, args, kwargs in mock_log.mock_calls:
+                for arg in args:
+                    out.append(u'%s' % arg)
+            output = u''.join(out)
+            self.assertIn('X-Auth-Token', output)
+            self.assertIn(token_value[:16] + '...', output)
+            self.assertIn('X-Storage-Token', output)
+            self.assertIn(unicode_token_value[:8] + '...', output)
+            self.assertIn('Set-Cookie', output)
+            self.assertIn(set_cookie_value[:16] + '...', output)
+            self.assertNotIn(token_value, output)
+            self.assertNotIn(unicode_token_value, output)
+            self.assertNotIn(set_cookie_value, output)
+
+    def test_show_token(self):
+        with mock.patch('swiftclient.client.logger.debug') as mock_log:
+            token_value = 'tkee96b40a8ca44fc5ad72ec5a7c90d9b'
+            unicode_token_value = (u'\u5929\u7a7a\u4e2d\u7684\u4e4c\u4e91'
+                                   u'\u5929\u7a7a\u4e2d\u7684\u4e4c\u4e91'
+                                   u'\u5929\u7a7a\u4e2d\u7684\u4e4c')
+            c.logger_settings['redact_sensitive_tokens'] = False
+            c.http_log(
+                ['GET'],
+                {'headers': {
+                    'X-Auth-Token': token_value,
+                    'X-Storage-Token': unicode_token_value
+                }},
+                MockHttpResponse(
+                    status=200,
+                    headers=[
+                        ('X-Auth-Token', token_value),
+                        ('X-Storage-Token', unicode_token_value),
+                        ('Etag', b'mock_etag')
+                    ]
+                ),
+                ''
+            )
+            out = []
+            for _, args, kwargs in mock_log.mock_calls:
+                for arg in args:
+                    out.append(u'%s' % arg)
+            output = u''.join(out)
+            self.assertIn('X-Auth-Token', output)
+            self.assertIn(token_value, output)
+            self.assertIn('X-Storage-Token', output)
+            self.assertIn(unicode_token_value, output)
+
 
 class TestCloseConnection(MockHttpTest):