Don't log sensitive auth data

Add the ability to turn off logging from the session object and then
handle logging of auth requests within their own sections.  This is a
very simplistic ability to completely disable logging.  Logging more
filtered debugging can be added later.

This new ability is utilized in this patch to prevent logging of
requests that include passwords.  This covers authenticate, password
change, and user update requests that include passwords.

SecurityImpact
Change-Id: I3dabb94ab047e86b8730e73416c1a1c333688489
Closes-Bug: #1004114
Closes-Bug: #1327019

keystoneclient/auth/identity/v2.py

@@ -11,6 +11,7 @@
 # under the License.
 
 import abc
+import logging
 
 from oslo.config import cfg
 import six
@@ -20,6 +21,8 @@ from keystoneclient.auth.identity import base
 from keystoneclient import exceptions
 from keystoneclient import utils
 
+_logger = logging.getLogger(__name__)
+
 
 @six.add_metaclass(abc.ABCMeta)
 class Auth(base.BaseIdentityPlugin):
@@ -66,8 +69,9 @@ class Auth(base.BaseIdentityPlugin):
         if self.trust_id:
             params['auth']['trust_id'] = self.trust_id
 
+        _logger.debug('Making authentication request to %s', url)
         resp = session.post(url, json=params, headers=headers,
-                            authenticated=False)
+                            authenticated=False, log=False)
 
         try:
             resp_data = resp.json()['access']

keystoneclient/auth/identity/v3.py

@@ -105,8 +105,9 @@ class Auth(base.BaseIdentityPlugin):
         elif self.trust_id:
             body['auth']['scope'] = {'OS-TRUST:trust': {'id': self.trust_id}}
 
+        _logger.debug('Making authentication request to %s', self.token_url)
         resp = session.post(self.token_url, json=body, headers=headers,
-                            authenticated=False)
+                            authenticated=False, log=False)
 
         try:
             resp_data = resp.json()['token']

keystoneclient/base.py

@@ -46,6 +46,11 @@ def getid(obj):
         return obj
 
 
+def filter_none(**kwargs):
+    """Remove any entries from a dictionary where the value is None."""
+    return dict((k, v) for k, v in six.iteritems(kwargs) if v is not None)
+
+
 def filter_kwargs(f):
     @functools.wraps(f)
     def func(*args, **kwargs):

keystoneclient/contrib/auth/v3/saml2.py

@@ -246,7 +246,7 @@ class Saml2UnscopedToken(v3.AuthConstructor):
             headers={'Content-type': 'text/xml'},
             data=etree.tostring(idp_saml2_authn_request),
             requests_auth=(self.username, self.password),
-            authenticated=False)
+            authenticated=False, log=False)
 
         try:
             self.saml2_idp_authn_response = etree.XML(idp_response.content)

keystoneclient/session.py

@@ -130,11 +130,69 @@ class Session(object):
         if user_agent is not None:
             self.user_agent = user_agent
 
+    @utils.positional()
+    def _http_log_request(self, url, method=None, data=None,
+                          json=None, headers=None):
+        if not _logger.isEnabledFor(logging.DEBUG):
+            # NOTE(morganfainberg): This whole debug section is expensive,
+            # there is no need to do the work if we're not going to emit a
+            # debug log.
+            return
+
+        string_parts = ['REQ: curl -i']
+
+        # NOTE(jamielennox): None means let requests do its default validation
+        # so we need to actually check that this is False.
+        if self.verify is False:
+            string_parts.append('--insecure')
+
+        if method:
+            string_parts.extend(['-X', method])
+
+        string_parts.append(url)
+
+        if headers:
+            for header in six.iteritems(headers):
+                string_parts.append('-H "%s: %s"' % header)
+        if json:
+            data = jsonutils.dumps(json)
+        if data:
+            string_parts.append("-d '%s'" % data)
+
+        _logger.debug(' '.join(string_parts))
+
+    @utils.positional()
+    def _http_log_response(self, response=None, json=None,
+                           status_code=None, headers=None, text=None):
+        if not _logger.isEnabledFor(logging.DEBUG):
+            return
+
+        if response:
+            if not status_code:
+                status_code = response.status_code
+            if not headers:
+                headers = response.headers
+            if not text:
+                text = response.text
+        if json:
+            text = jsonutils.dumps(json)
+
+        string_parts = ['RESP:']
+
+        if status_code:
+            string_parts.append('[%s]' % status_code)
+        if headers:
+            string_parts.append('%s' % headers)
+        if text:
+            string_parts.append('\nRESP BODY: %s\n' % text)
+
+        _logger.debug(' '.join(string_parts))
+
     @utils.positional(enforcement=utils.positional.WARN)
     def request(self, url, method, json=None, original_ip=None,
                 user_agent=None, redirect=None, authenticated=None,
                 endpoint_filter=None, auth=None, requests_auth=None,
-                raise_exc=True, allow_reauth=True, **kwargs):
+                raise_exc=True, allow_reauth=True, log=True, **kwargs):
         """Send an HTTP request with the specified characteristics.
 
         Wrapper around `requests.Session.request` to handle tasks such as
@@ -183,6 +241,8 @@ class Session(object):
         :param bool allow_reauth: Allow fetching a new token and retrying the
                                   request on receiving a 401 Unauthorized
                                   response. (optional, default True)
+        :param bool log: If True then log the request and response data to the
+                         debug log. (optional, default True)
         :param kwargs: any other parameter that can be passed to
                        requests.Session.request (such as `headers`). Except:
                        'data' will be overwritten by the data in 'json' param.
@@ -250,28 +310,10 @@ class Session(object):
         if requests_auth:
             kwargs['auth'] = requests_auth
 
-        string_parts = ['curl -i']
+        if log:
-
+            self._http_log_request(url, method=method,
-        # NOTE(jamielennox): None means let requests do its default validation
+                                   data=kwargs.get('data'),
-        # so we need to actually check that this is False.
+                                   headers=headers)
-        if self.verify is False:
-            string_parts.append('--insecure')
-
-        if method:
-            string_parts.extend(['-X', method])
-
-        string_parts.append(url)
-
-        if headers:
-            for header in six.iteritems(headers):
-                string_parts.append('-H "%s: %s"' % header)
-
-        try:
-            string_parts.append("-d '%s'" % kwargs['data'])
-        except KeyError:
-            pass
-
-        _logger.debug('REQ: %s', ' '.join(string_parts))
 
         # Force disable requests redirect handling. We will manage this below.
         kwargs['allow_redirects'] = False
@@ -279,7 +321,7 @@ class Session(object):
         if redirect is None:
             redirect = self.redirect
 
-        resp = self._send_request(url, method, redirect, **kwargs)
+        resp = self._send_request(url, method, redirect, log, **kwargs)
 
         # handle getting a 401 Unauthorized response by invalidating the plugin
         # and then retrying the request. This is only tried once.
@@ -288,7 +330,8 @@ class Session(object):
                 token = self.get_token(auth)
                 if token:
                     headers['X-Auth-Token'] = token
-                    resp = self._send_request(url, method, redirect, **kwargs)
+                    resp = self._send_request(url, method, redirect, log,
+                                              **kwargs)
 
         if raise_exc and resp.status_code >= 400:
             _logger.debug('Request returned failure status: %s',
@@ -297,7 +340,7 @@ class Session(object):
 
         return resp
 
-    def _send_request(self, url, method, redirect, **kwargs):
+    def _send_request(self, url, method, redirect, log, **kwargs):
         # NOTE(jamielennox): We handle redirection manually because the
         # requests lib follows some browser patterns where it will redirect
         # POSTs as GETs for certain statuses which is not want we want for an
@@ -315,8 +358,8 @@ class Session(object):
             msg = 'Unable to establish connection to %s' % url
             raise exceptions.ConnectionRefused(msg)
 
-        _logger.debug('RESP: [%s] %s\nRESP BODY: %s\n',
+        if log:
-                      resp.status_code, resp.headers, resp.text)
+            self._http_log_response(response=resp)
 
         if resp.status_code in self.REDIRECT_STATUSES:
             # be careful here in python True == 1 and False == 0
@@ -335,7 +378,7 @@ class Session(object):
                 _logger.warn("Failed to redirect request to %s as new "
                              "location was not provided.", resp.url)
             else:
-                new_resp = self._send_request(location, method, redirect,
+                new_resp = self._send_request(location, method, redirect, log,
                                               **kwargs)
 
                 if not isinstance(new_resp.history, list):

keystoneclient/tests/auth/test_identity_v2.py

@@ -11,6 +11,7 @@
 # under the License.
 
 import copy
+import uuid
 
 import httpretty
 from six.moves import urllib
@@ -255,3 +256,14 @@ class V2IdentityPlugin(utils.TestCase):
         self.assertEqual('token1', s.get_token())
         a.invalidate()
         self.assertEqual('token2', s.get_token())
+
+    @httpretty.activate
+    def test_doesnt_log_password(self):
+        self.stub_auth(json=self.TEST_RESPONSE_DICT)
+        password = uuid.uuid4().hex
+
+        a = v2.Password(self.TEST_URL, username=self.TEST_USER,
+                        password=password)
+        s = session.Session(auth=a)
+        self.assertEqual(self.TEST_TOKEN, s.get_token())
+        self.assertNotIn(password, self.logger.output)

keystoneclient/tests/auth/test_identity_v3.py

@@ -11,6 +11,7 @@
 # under the License.
 
 import copy
+import uuid
 
 import httpretty
 from six.moves import urllib
@@ -408,3 +409,15 @@ class V3IdentityPlugin(utils.TestCase):
         self.assertEqual('token1', s.get_token())
         a.invalidate()
         self.assertEqual('token2', s.get_token())
+
+    @httpretty.activate
+    def test_doesnt_log_password(self):
+        self.stub_auth(json=self.TEST_RESPONSE_DICT)
+
+        password = uuid.uuid4().hex
+        a = v3.Password(self.TEST_URL, username=self.TEST_USER,
+                        password=password)
+        s = session.Session(a)
+        self.assertEqual(self.TEST_TOKEN, s.get_token())
+
+        self.assertNotIn(password, self.logger.output)

keystoneclient/tests/v2_0/test_users.py

@@ -47,10 +47,11 @@ class UserTests(utils.TestCase):
     def test_create(self):
         tenant_id = uuid.uuid4().hex
         user_id = uuid.uuid4().hex
+        password = uuid.uuid4().hex
         req_body = {
             "user": {
                 "name": "gabriel",
-                "password": "test",
+                "password": password,
                 "tenantId": tenant_id,
                 "email": "test@example.com",
                 "enabled": True,
@@ -63,7 +64,7 @@ class UserTests(utils.TestCase):
                 "enabled": True,
                 "tenantId": tenant_id,
                 "id": user_id,
-                "password": "test",
+                "password": password,
                 "email": "test@example.com",
             }
         }
@@ -80,6 +81,7 @@ class UserTests(utils.TestCase):
         self.assertEqual(user.name, "gabriel")
         self.assertEqual(user.email, "test@example.com")
         self.assertRequestBodyIs(json=req_body)
+        self.assertNotIn(password, self.logger.output)
 
     @httpretty.activate
     def test_create_user_without_email(self):
@@ -210,10 +212,11 @@ class UserTests(utils.TestCase):
                 "name": "gabriel",
             }
         }
+        password = uuid.uuid4().hex
         req_2 = {
             "user": {
                 "id": self.DEMO_USER_ID,
-                "password": "swordfish",
+                "password": password,
             }
         }
         tenant_id = uuid.uuid4().hex
@@ -245,18 +248,22 @@ class UserTests(utils.TestCase):
                                  name='gabriel',
                                  email='gabriel@example.com')
         self.assertRequestBodyIs(json=req_1)
-        self.client.users.update_password(self.DEMO_USER_ID, 'swordfish')
+        self.client.users.update_password(self.DEMO_USER_ID, password)
         self.assertRequestBodyIs(json=req_2)
         self.client.users.update_tenant(self.DEMO_USER_ID, tenant_id)
         self.assertRequestBodyIs(json=req_3)
         self.client.users.update_enabled(self.DEMO_USER_ID, False)
         self.assertRequestBodyIs(json=req_4)
+        self.assertNotIn(password, self.logger.output)
 
     @httpretty.activate
     def test_update_own_password(self):
+        old_password = uuid.uuid4().hex
+        new_password = uuid.uuid4().hex
         req_body = {
             'user': {
-                'password': 'ABCD', 'original_password': 'DCBA'
+                'password': new_password,
+                'original_password': old_password
             }
         }
         resp_body = {
@@ -267,8 +274,10 @@ class UserTests(utils.TestCase):
                       json=resp_body)
 
         self.client.user_id = user_id
-        self.client.users.update_own_password('DCBA', 'ABCD')
+        self.client.users.update_own_password(old_password, new_password)
         self.assertRequestBodyIs(json=req_body)
+        self.assertNotIn(old_password, self.logger.output)
+        self.assertNotIn(new_password, self.logger.output)
 
     @httpretty.activate
     def test_user_role_listing(self):

keystoneclient/tests/v3/test_users.py

@@ -96,6 +96,25 @@ class UserTests(utils.TestCase, utils.CrudTests):
                           user=ref['id'],
                           group=None)
 
+    @httpretty.activate
+    def test_create_doesnt_log_password(self):
+        password = uuid.uuid4().hex
+        ref = self.new_ref()
+
+        self.stub_entity(httpretty.POST, [self.collection_key],
+                         status=201, entity=ref)
+
+        req_ref = ref.copy()
+        req_ref.pop('id')
+        param_ref = req_ref.copy()
+
+        param_ref['password'] = password
+        params = utils.parameterize(param_ref)
+
+        self.manager.create(**params)
+
+        self.assertNotIn(password, self.logger.output)
+
     @httpretty.activate
     def test_create_with_project(self):
         # Can create a user with the deprecated project option rather than
@@ -148,6 +167,26 @@ class UserTests(utils.TestCase, utils.CrudTests):
                 'Expected different %s' % attr)
         self.assertEntityRequestBodyIs(req_ref)
 
+    @httpretty.activate
+    def test_update_doesnt_log_password(self):
+        password = uuid.uuid4().hex
+        ref = self.new_ref()
+
+        req_ref = ref.copy()
+        req_ref.pop('id')
+        param_ref = req_ref.copy()
+
+        self.stub_entity(httpretty.PATCH,
+                         [self.collection_key, ref['id']],
+                         status=200, entity=ref)
+
+        param_ref['password'] = password
+        params = utils.parameterize(param_ref)
+
+        self.manager.update(ref['id'], **params)
+
+        self.assertNotIn(password, self.logger.output)
+
     @httpretty.activate
     def test_update_with_project(self):
         # Can update a user with the deprecated project option rather than
@@ -217,6 +256,8 @@ class UserTests(utils.TestCase, utils.CrudTests):
         self.assertEqual('/v3/users/test/password',
                          httpretty.last_request().path)
         self.assertRequestBodyIs(json=exp_req_body)
+        self.assertNotIn(old_password, self.logger.output)
+        self.assertNotIn(new_password, self.logger.output)
 
     def test_update_password_with_bad_inputs(self):
         old_password = uuid.uuid4().hex

keystoneclient/v2_0/tokens.py

@@ -53,7 +53,7 @@ class TokenManager(base.Manager):
             reset = 1
             self.api.management_url = self.api.auth_url
         token_ref = self._create('/tokens', params, "access",
-                                 return_raw=return_raw)
+                                 return_raw=return_raw, log=False)
         if reset:
             self.api.management_url = None
         return token_ref

keystoneclient/v2_0/users.py

@@ -68,7 +68,7 @@ class UserManager(base.ManagerWithFind):
                            "password": password}}
 
         return self._update("/users/%s/OS-KSADM/password" % base.getid(user),
-                            params, "user")
+                            params, "user", log=False)
 
     def update_own_password(self, origpasswd, passwd):
         """Update password."""
@@ -78,7 +78,8 @@ class UserManager(base.ManagerWithFind):
         return self._update("/OS-KSCRUD/users/%s" % self.api.user_id, params,
                             response_key="access",
                             method="PATCH",
-                            management=False)
+                            management=False,
+                            log=False)
 
     def update_tenant(self, user, tenant):
         """Update default tenant."""
@@ -98,7 +99,7 @@ class UserManager(base.ManagerWithFind):
                            "tenantId": tenant_id,
                            "email": email,
                            "enabled": enabled}}
-        return self._create('/users', params, "user")
+        return self._create('/users', params, "user", log=not bool(password))
 
     def delete(self, user):
         """Delete a user."""

keystoneclient/v3/users.py

@@ -61,8 +61,7 @@ class UserManager(base.CrudManager):
             LOG.warning("The project argument is deprecated, "
                         "use default_project instead.")
         default_project_id = base.getid(default_project) or base.getid(project)
-        return super(UserManager, self).create(
+        user_data = base.filter_none(name=name,
-            name=name,
                                      domain_id=base.getid(domain),
                                      default_project_id=default_project_id,
                                      password=password,
@@ -71,6 +70,9 @@ class UserManager(base.CrudManager):
                                      enabled=enabled,
                                      **kwargs)
 
+        return self._create('/users', {'user': user_data}, 'user',
+                            log=not bool(password))
+
     @utils.positional(enforcement=utils.positional.WARN)
     def list(self, project=None, domain=None, group=None, default_project=None,
              **kwargs):
@@ -125,9 +127,7 @@ class UserManager(base.CrudManager):
             LOG.warning("The project argument is deprecated, "
                         "use default_project instead.")
         default_project_id = base.getid(default_project) or base.getid(project)
-        return super(UserManager, self).update(
+        user_data = base.filter_none(name=name,
-            user_id=base.getid(user),
-            name=name,
                                      domain_id=base.getid(domain),
                                      default_project_id=default_project_id,
                                      password=password,
@@ -136,6 +136,12 @@ class UserManager(base.CrudManager):
                                      enabled=enabled,
                                      **kwargs)
 
+        return self._update('/users/%s' % base.getid(user),
+                            {'user': user_data},
+                            'user',
+                            method='PATCH',
+                            log=False)
+
     def update_password(self, old_password, new_password):
         """Update the password for the user the token belongs to."""
         if not (old_password and new_password):
@@ -151,7 +157,8 @@ class UserManager(base.CrudManager):
 
         base_url = '/users/%s/password' % self.api.user_id
 
-        return self._update(base_url, params, method='POST', management=False)
+        return self._update(base_url, params, method='POST', management=False,
+                            log=False)
 
     def add_to_group(self, user, group):
         self._require_user_and_group(user, group)