← Back to team overview

yahoo-eng-team team mailing list archive

  1. yahoo-eng-team team
  2. Mailing list archive
  3. Message #19762

[Bug 1364521] [NEW] LDAP integration with Active Directory backend can throw: UnicodeDecodeError

  Thread Previous • Date Previous • • Thread Next 
Public bug reported:

Basic AD integration with Keystone using the LDAP backend.

Started getting the following trace:

2014-09-02 07:48:56.473 21448 DEBUG keystone.common.ldap.core [-] LDAP bind: dn=CN=role-admin,OU=openstack,OU=Groups,DC=LAB,DC=RMSONECLOUD,DC=NET simple_bind_s /usr/lib/python2.6/site-packages/keystone/common/ldap/core.py:780
2014-09-02 07:48:56.481 21448 DEBUG keystone.common.ldap.core [-] LDAP search: dn=OU=openstack,OU=Groups,DC=LAB,DC=RMSONECLOUD,DC=NET, scope=2, query=(&(CN=role-admin)(objectclass=organizationalPerson)), attrs=None search_s /usr/lib/python2.6/site-packages/keystone/common/ldap/core.py:816
2014-09-02 07:48:56.491 21448 DEBUG keystone.common.ldap.core [-] LDAP unbind unbind_s /usr/lib/python2.6/site-packages/keystone/common/ldap/core.py:786
2014-09-02 07:48:56.492 21448 DEBUG keystone.notifications [-] CADF Event: {'typeURI': 'http://schemas.dmtf.org/cloud/audit/1.0/event', 'initiator': {'typeURI': 'service/security/account/user', 'host': {'agent': 'python-keystoneclient', 'address': '10.76.32.80'}, 'id': 'openstack:83237b62-6c82-4dd1-a53d-6521462d329b', 'name': u'role-admin'}, 'target': {'typeURI': 'service/security/account/user', 'id': 'openstack:9eea98fe-b557-455a-a9a4-3174e06ce698'}, 'observer': {'typeURI': 'service/security', 'id': 'openstack:3cbf8b13-a535-4e24-8c98-bf9abcb4ced4'}, 'eventType': 'activity', 'eventTime': '2014-09-02T11:48:56.491795+0000', 'action': 'authenticate', 'outcome': 'failure', 'id': 'openstack:39adb273-edec-4efe-9825-80fb30b1a94f'} _send_audit_notification /usr/lib/python2.6/site-packages/keystone/notifications.py:289
2014-09-02 07:48:56.493 21448 ERROR keystone.common.wsgi [-] 'utf8' codec can't decode byte 0xfe in position 14: invalid start byte
2014-09-02 07:48:56.493 21448 TRACE keystone.common.wsgi Traceback (most recent call last):
2014-09-02 07:48:56.493 21448 TRACE keystone.common.wsgi   File "/usr/lib/python2.6/site-packages/keystone/common/wsgi.py", line 212, in __call__
2014-09-02 07:48:56.493 21448 TRACE keystone.common.wsgi     result = method(context, **params)
2014-09-02 07:48:56.493 21448 TRACE keystone.common.wsgi   File "/usr/lib/python2.6/site-packages/keystone/token/controllers.py", line 98, in authenticate
2014-09-02 07:48:56.493 21448 TRACE keystone.common.wsgi     context, auth)
2014-09-02 07:48:56.493 21448 TRACE keystone.common.wsgi   File "/usr/lib/python2.6/site-packages/keystone/token/controllers.py", line 276, in _authenticate_local
2014-09-02 07:48:56.493 21448 TRACE keystone.common.wsgi     password=password)
2014-09-02 07:48:56.493 21448 TRACE keystone.common.wsgi   File "/usr/lib/python2.6/site-packages/keystone/notifications.py", line 253, in wrapper
2014-09-02 07:48:56.493 21448 TRACE keystone.common.wsgi     result = f(wrapped_self, context, user_id, *args, **kwargs)
2014-09-02 07:48:56.493 21448 TRACE keystone.common.wsgi   File "/usr/lib/python2.6/site-packages/keystone/identity/core.py", line 189, in wrapper
2014-09-02 07:48:56.493 21448 TRACE keystone.common.wsgi     return f(self, *args, **kwargs)
2014-09-02 07:48:56.493 21448 TRACE keystone.common.wsgi   File "/usr/lib/python2.6/site-packages/keystone/identity/core.py", line 281, in authenticate
2014-09-02 07:48:56.493 21448 TRACE keystone.common.wsgi     ref = driver.authenticate(user_id, password)
2014-09-02 07:48:56.493 21448 TRACE keystone.common.wsgi   File "/usr/lib/python2.6/site-packages/keystone/identity/backends/ldap.py", line 63, in authenticate
2014-09-02 07:48:56.493 21448 TRACE keystone.common.wsgi     conn = self.user.get_connection(self.user._id_to_dn(user_id),
2014-09-02 07:48:56.493 21448 TRACE keystone.common.wsgi   File "/usr/lib/python2.6/site-packages/keystone/common/ldap/core.py", line 472, in _id_to_dn
2014-09-02 07:48:56.493 21448 TRACE keystone.common.wsgi     'objclass': self.object_class})
2014-09-02 07:48:56.493 21448 TRACE keystone.common.wsgi   File "/usr/lib/python2.6/site-packages/keystone/common/ldap/core.py", line 829, in search_s
2014-09-02 07:48:56.493 21448 TRACE keystone.common.wsgi     py_result = convert_ldap_result(ldap_result)
2014-09-02 07:48:56.493 21448 TRACE keystone.common.wsgi   File "/usr/lib/python2.6/site-packages/keystone/common/ldap/core.py", line 150, in convert_ldap_result
2014-09-02 07:48:56.493 21448 TRACE keystone.common.wsgi     for kind, values in six.iteritems(attrs))))
2014-09-02 07:48:56.493 21448 TRACE keystone.common.wsgi   File "/usr/lib/python2.6/site-packages/keystone/common/ldap/core.py", line 150, in <genexpr>
2014-09-02 07:48:56.493 21448 TRACE keystone.common.wsgi     for kind, values in six.iteritems(attrs))))
2014-09-02 07:48:56.493 21448 TRACE keystone.common.wsgi   File "/usr/lib/python2.6/site-packages/keystone/common/ldap/core.py", line 119, in ldap2py
2014-09-02 07:48:56.493 21448 TRACE keystone.common.wsgi     return utf8_decode(val)
2014-09-02 07:48:56.493 21448 TRACE keystone.common.wsgi   File "/usr/lib/python2.6/site-packages/keystone/common/ldap/core.py", line 80, in utf8_decode
2014-09-02 07:48:56.493 21448 TRACE keystone.common.wsgi     return _utf8_decoder(value)[0]
2014-09-02 07:48:56.493 21448 TRACE keystone.common.wsgi   File "/usr/lib64/python2.6/encodings/utf_8.py", line 16, in decode
2014-09-02 07:48:56.493 21448 TRACE keystone.common.wsgi     return codecs.utf_8_decode(input, errors, True)
2014-09-02 07:48:56.493 21448 TRACE keystone.common.wsgi UnicodeDecodeError: 'utf8' codec can't decode byte 0xfe in position 14: invalid start byte


I put in some debug statements into keystone.common.ldap.core to print out the attributes as they parse:

2014-09-02 12:36:51.013 29855 DEBUG keystone.common.ldap.core [-] in convert_ldap_result convert_ldap_result /usr/lib/python2.6/site-packages/keystone/common/ldap/core.py:144
2014-09-02 12:36:51.013 29855 DEBUG keystone.common.ldap.core [-] converting OU=admin,OU=project,OU=openstack,DC=LAB,DC=RMSONECLOUD,DC=NET convert_ldap_result /usr/lib/python2.6/site-packages/keystone/common/ldap/core.py:154
2014-09-02 12:36:51.013 29855 DEBUG keystone.common.ldap.core [-] working with:OU=admin,OU=project,OU=openstack,DC=LAB,DC=RMSONECLOUD,DC=NET ldap2py /usr/lib/python2.6/site-packages/keystone/common/ldap/core.py:111
2014-09-02 12:36:51.014 29855 DEBUG keystone.common.ldap.core [-] working with:20140829191850.0Z ldap2py /usr/lib/python2.6/site-packages/keystone/common/ldap/core.py:111
2014-09-02 12:36:51.014 29855 DEBUG keystone.common.ldap.core [-] working with:20140829191850.0Z ldap2py /usr/lib/python2.6/site-packages/keystone/common/ldap/core.py:111
2014-09-02 12:36:51.014 29855 DEBUG keystone.common.ldap.core [-] working with:16010101000000.0Z ldap2py /usr/lib/python2.6/site-packages/keystone/common/ldap/core.py:111
2014-09-02 12:36:51.014 29855 DEBUG keystone.common.ldap.core [-] working with:admin ldap2py /usr/lib/python2.6/site-packages/keystone/common/ldap/core.py:111
2014-09-02 12:36:51.014 29855 DEBUG keystone.common.ldap.core [-] working with:CN=Organizational-Unit,CN=Schema,CN=Configuration,DC=RMSONECLOUD,DC=NET ldap2py /usr/lib/python2.6/site-packages/keystone/common/ldap/core.py:111
2014-09-02 12:36:51.015 29855 DEBUG keystone.common.ldap.core [-] working with:top ldap2py /usr/lib/python2.6/site-packages/keystone/common/ldap/core.py:111
2014-09-02 12:36:51.015 29855 DEBUG keystone.common.ldap.core [-] working with:organizationalUnit ldap2py /usr/lib/python2.6/site-packages/keystone/common/ldap/core.py:111
2014-09-02 12:36:51.015 29855 DEBUG keystone.common.ldap.core [-] working with:?"?gZK??[J???? ldap2py /usr/lib/python2.6/site-packages/keystone/common/ldap/core.py:111
2014-09-02 12:36:51.015 29855 DEBUG keystone.common.ldap.core [-] working with:20140829192641.0Z ldap2py /usr/lib/python2.6/site-packages/keystone/common/ldap/core.py:111
2014-09-02 12:36:51.015 29855 DEBUG keystone.common.ldap.core [-] working with:20140829191850.0Z ldap2py /usr/lib/python2.6/site-packages/keystone/common/ldap/core.py:111
2014-09-02 12:36:51.016 29855 DEBUG keystone.common.ldap.core [-] working with:9885816 ldap2py /usr/lib/python2.6/site-packages/keystone/common/ldap/core.py:111
2014-09-02 12:36:51.016 29855 DEBUG keystone.common.ldap.core [-] working with:TRUE ldap2py /usr/lib/python2.6/site-packages/keystone/common/ldap/core.py:111
2014-09-02 12:36:51.016 29855 DEBUG keystone.common.ldap.core [-] working with:9886144 ldap2py /usr/lib/python2.6/site-packages/keystone/common/ldap/core.py:111
2014-09-02 12:36:51.016 29855 DEBUG keystone.common.ldap.core [-] working with:admin ldap2py /usr/lib/python2.6/site-packages/keystone/common/ldap/core.py:111
2014-09-02 12:36:51.016 29855 DEBUG keystone.common.ldap.core [-] working with:4 ldap2py /usr/lib/python2.6/site-packages/keystone/common/ldap/core.py:111
2014-09-02 12:36:51.017 29855 DEBUG keystone.common.ldap.core [-] finished converting convert_ldap_result /usr/lib/python2.6/site-packages/keystone/common/ldap/core.py:158
2014-09-02 12:36:51.017 29855 DEBUG keystone.common.ldap.core [-] LDAP unbind unbind_s /usr/lib/python2.6/site-packages/keystone/common/ldap/core.py:796


The 'working with:' lines are the values that it's trying to convert.  you can see the one mid way through with the  strange question marks and other chars.  Not sure WHY this is getting returned as a network capture shows clean, ledgible attribute values, however, it IS getting returned and I think we should trap this sort of thing in ldap2py.

** Affects: keystone
     Importance: Undecided
         Status: New

** Description changed:

  Basic AD integration with Keystone using the LDAP backend.
  
  Started getting the following trace:
- <code>
+ 
  2014-09-02 07:48:56.473 21448 DEBUG keystone.common.ldap.core [-] LDAP bind: dn=CN=role-admin,OU=openstack,OU=Groups,DC=LAB,DC=RMSONECLOUD,DC=NET simple_bind_s /usr/lib/python2.6/site-packages/keystone/common/ldap/core.py:780
  2014-09-02 07:48:56.481 21448 DEBUG keystone.common.ldap.core [-] LDAP search: dn=OU=openstack,OU=Groups,DC=LAB,DC=RMSONECLOUD,DC=NET, scope=2, query=(&(CN=role-admin)(objectclass=organizationalPerson)), attrs=None search_s /usr/lib/python2.6/site-packages/keystone/common/ldap/core.py:816
  2014-09-02 07:48:56.491 21448 DEBUG keystone.common.ldap.core [-] LDAP unbind unbind_s /usr/lib/python2.6/site-packages/keystone/common/ldap/core.py:786
  2014-09-02 07:48:56.492 21448 DEBUG keystone.notifications [-] CADF Event: {'typeURI': 'http://schemas.dmtf.org/cloud/audit/1.0/event', 'initiator': {'typeURI': 'service/security/account/user', 'host': {'agent': 'python-keystoneclient', 'address': '10.76.32.80'}, 'id': 'openstack:83237b62-6c82-4dd1-a53d-6521462d329b', 'name': u'role-admin'}, 'target': {'typeURI': 'service/security/account/user', 'id': 'openstack:9eea98fe-b557-455a-a9a4-3174e06ce698'}, 'observer': {'typeURI': 'service/security', 'id': 'openstack:3cbf8b13-a535-4e24-8c98-bf9abcb4ced4'}, 'eventType': 'activity', 'eventTime': '2014-09-02T11:48:56.491795+0000', 'action': 'authenticate', 'outcome': 'failure', 'id': 'openstack:39adb273-edec-4efe-9825-80fb30b1a94f'} _send_audit_notification /usr/lib/python2.6/site-packages/keystone/notifications.py:289
  2014-09-02 07:48:56.493 21448 ERROR keystone.common.wsgi [-] 'utf8' codec can't decode byte 0xfe in position 14: invalid start byte
  2014-09-02 07:48:56.493 21448 TRACE keystone.common.wsgi Traceback (most recent call last):
  2014-09-02 07:48:56.493 21448 TRACE keystone.common.wsgi   File "/usr/lib/python2.6/site-packages/keystone/common/wsgi.py", line 212, in __call__
  2014-09-02 07:48:56.493 21448 TRACE keystone.common.wsgi     result = method(context, **params)
  2014-09-02 07:48:56.493 21448 TRACE keystone.common.wsgi   File "/usr/lib/python2.6/site-packages/keystone/token/controllers.py", line 98, in authenticate
  2014-09-02 07:48:56.493 21448 TRACE keystone.common.wsgi     context, auth)
  2014-09-02 07:48:56.493 21448 TRACE keystone.common.wsgi   File "/usr/lib/python2.6/site-packages/keystone/token/controllers.py", line 276, in _authenticate_local
  2014-09-02 07:48:56.493 21448 TRACE keystone.common.wsgi     password=password)
  2014-09-02 07:48:56.493 21448 TRACE keystone.common.wsgi   File "/usr/lib/python2.6/site-packages/keystone/notifications.py", line 253, in wrapper
  2014-09-02 07:48:56.493 21448 TRACE keystone.common.wsgi     result = f(wrapped_self, context, user_id, *args, **kwargs)
  2014-09-02 07:48:56.493 21448 TRACE keystone.common.wsgi   File "/usr/lib/python2.6/site-packages/keystone/identity/core.py", line 189, in wrapper
  2014-09-02 07:48:56.493 21448 TRACE keystone.common.wsgi     return f(self, *args, **kwargs)
  2014-09-02 07:48:56.493 21448 TRACE keystone.common.wsgi   File "/usr/lib/python2.6/site-packages/keystone/identity/core.py", line 281, in authenticate
  2014-09-02 07:48:56.493 21448 TRACE keystone.common.wsgi     ref = driver.authenticate(user_id, password)
  2014-09-02 07:48:56.493 21448 TRACE keystone.common.wsgi   File "/usr/lib/python2.6/site-packages/keystone/identity/backends/ldap.py", line 63, in authenticate
  2014-09-02 07:48:56.493 21448 TRACE keystone.common.wsgi     conn = self.user.get_connection(self.user._id_to_dn(user_id),
  2014-09-02 07:48:56.493 21448 TRACE keystone.common.wsgi   File "/usr/lib/python2.6/site-packages/keystone/common/ldap/core.py", line 472, in _id_to_dn
  2014-09-02 07:48:56.493 21448 TRACE keystone.common.wsgi     'objclass': self.object_class})
  2014-09-02 07:48:56.493 21448 TRACE keystone.common.wsgi   File "/usr/lib/python2.6/site-packages/keystone/common/ldap/core.py", line 829, in search_s
  2014-09-02 07:48:56.493 21448 TRACE keystone.common.wsgi     py_result = convert_ldap_result(ldap_result)
  2014-09-02 07:48:56.493 21448 TRACE keystone.common.wsgi   File "/usr/lib/python2.6/site-packages/keystone/common/ldap/core.py", line 150, in convert_ldap_result
  2014-09-02 07:48:56.493 21448 TRACE keystone.common.wsgi     for kind, values in six.iteritems(attrs))))
  2014-09-02 07:48:56.493 21448 TRACE keystone.common.wsgi   File "/usr/lib/python2.6/site-packages/keystone/common/ldap/core.py", line 150, in <genexpr>
  2014-09-02 07:48:56.493 21448 TRACE keystone.common.wsgi     for kind, values in six.iteritems(attrs))))
  2014-09-02 07:48:56.493 21448 TRACE keystone.common.wsgi   File "/usr/lib/python2.6/site-packages/keystone/common/ldap/core.py", line 119, in ldap2py
  2014-09-02 07:48:56.493 21448 TRACE keystone.common.wsgi     return utf8_decode(val)
  2014-09-02 07:48:56.493 21448 TRACE keystone.common.wsgi   File "/usr/lib/python2.6/site-packages/keystone/common/ldap/core.py", line 80, in utf8_decode
  2014-09-02 07:48:56.493 21448 TRACE keystone.common.wsgi     return _utf8_decoder(value)[0]
  2014-09-02 07:48:56.493 21448 TRACE keystone.common.wsgi   File "/usr/lib64/python2.6/encodings/utf_8.py", line 16, in decode
  2014-09-02 07:48:56.493 21448 TRACE keystone.common.wsgi     return codecs.utf_8_decode(input, errors, True)
  2014-09-02 07:48:56.493 21448 TRACE keystone.common.wsgi UnicodeDecodeError: 'utf8' codec can't decode byte 0xfe in position 14: invalid start byte
- </code>
  
- I put in some debug statements into keystone.common.ldap.core to print
- out the attributes as they parse:
  
- <code>
+ I put in some debug statements into keystone.common.ldap.core to print out the attributes as they parse:
+ 
  2014-09-02 12:36:51.013 29855 DEBUG keystone.common.ldap.core [-] in convert_ldap_result convert_ldap_result /usr/lib/python2.6/site-packages/keystone/common/ldap/core.py:144
  2014-09-02 12:36:51.013 29855 DEBUG keystone.common.ldap.core [-] converting OU=admin,OU=project,OU=openstack,DC=LAB,DC=RMSONECLOUD,DC=NET convert_ldap_result /usr/lib/python2.6/site-packages/keystone/common/ldap/core.py:154
  2014-09-02 12:36:51.013 29855 DEBUG keystone.common.ldap.core [-] working with:OU=admin,OU=project,OU=openstack,DC=LAB,DC=RMSONECLOUD,DC=NET ldap2py /usr/lib/python2.6/site-packages/keystone/common/ldap/core.py:111
  2014-09-02 12:36:51.014 29855 DEBUG keystone.common.ldap.core [-] working with:20140829191850.0Z ldap2py /usr/lib/python2.6/site-packages/keystone/common/ldap/core.py:111
  2014-09-02 12:36:51.014 29855 DEBUG keystone.common.ldap.core [-] working with:20140829191850.0Z ldap2py /usr/lib/python2.6/site-packages/keystone/common/ldap/core.py:111
  2014-09-02 12:36:51.014 29855 DEBUG keystone.common.ldap.core [-] working with:16010101000000.0Z ldap2py /usr/lib/python2.6/site-packages/keystone/common/ldap/core.py:111
  2014-09-02 12:36:51.014 29855 DEBUG keystone.common.ldap.core [-] working with:admin ldap2py /usr/lib/python2.6/site-packages/keystone/common/ldap/core.py:111
  2014-09-02 12:36:51.014 29855 DEBUG keystone.common.ldap.core [-] working with:CN=Organizational-Unit,CN=Schema,CN=Configuration,DC=RMSONECLOUD,DC=NET ldap2py /usr/lib/python2.6/site-packages/keystone/common/ldap/core.py:111
  2014-09-02 12:36:51.015 29855 DEBUG keystone.common.ldap.core [-] working with:top ldap2py /usr/lib/python2.6/site-packages/keystone/common/ldap/core.py:111
  2014-09-02 12:36:51.015 29855 DEBUG keystone.common.ldap.core [-] working with:organizationalUnit ldap2py /usr/lib/python2.6/site-packages/keystone/common/ldap/core.py:111
  2014-09-02 12:36:51.015 29855 DEBUG keystone.common.ldap.core [-] working with:?"?gZK??[J???? ldap2py /usr/lib/python2.6/site-packages/keystone/common/ldap/core.py:111
  2014-09-02 12:36:51.015 29855 DEBUG keystone.common.ldap.core [-] working with:20140829192641.0Z ldap2py /usr/lib/python2.6/site-packages/keystone/common/ldap/core.py:111
  2014-09-02 12:36:51.015 29855 DEBUG keystone.common.ldap.core [-] working with:20140829191850.0Z ldap2py /usr/lib/python2.6/site-packages/keystone/common/ldap/core.py:111
  2014-09-02 12:36:51.016 29855 DEBUG keystone.common.ldap.core [-] working with:9885816 ldap2py /usr/lib/python2.6/site-packages/keystone/common/ldap/core.py:111
  2014-09-02 12:36:51.016 29855 DEBUG keystone.common.ldap.core [-] working with:TRUE ldap2py /usr/lib/python2.6/site-packages/keystone/common/ldap/core.py:111
  2014-09-02 12:36:51.016 29855 DEBUG keystone.common.ldap.core [-] working with:9886144 ldap2py /usr/lib/python2.6/site-packages/keystone/common/ldap/core.py:111
  2014-09-02 12:36:51.016 29855 DEBUG keystone.common.ldap.core [-] working with:admin ldap2py /usr/lib/python2.6/site-packages/keystone/common/ldap/core.py:111
  2014-09-02 12:36:51.016 29855 DEBUG keystone.common.ldap.core [-] working with:4 ldap2py /usr/lib/python2.6/site-packages/keystone/common/ldap/core.py:111
  2014-09-02 12:36:51.017 29855 DEBUG keystone.common.ldap.core [-] finished converting convert_ldap_result /usr/lib/python2.6/site-packages/keystone/common/ldap/core.py:158
  2014-09-02 12:36:51.017 29855 DEBUG keystone.common.ldap.core [-] LDAP unbind unbind_s /usr/lib/python2.6/site-packages/keystone/common/ldap/core.py:796
- </code?
  
- The 'working with:' lines are the values that it's trying to convert.
- you can see the one mid way through with the  strange question marks and
- other chars.  Not sure WHY this is getting returned as a network capture
- shows clean, ledgible attribute values, however, it IS getting returned
- and I think we should trap this sort of thing in ldap2py.
+ 
+ The 'working with:' lines are the values that it's trying to convert.  you can see the one mid way through with the  strange question marks and other chars.  Not sure WHY this is getting returned as a network capture shows clean, ledgible attribute values, however, it IS getting returned and I think we should trap this sort of thing in ldap2py.

-- 
You received this bug notification because you are a member of Yahoo!
Engineering Team, which is subscribed to Keystone.
https://bugs.launchpad.net/bugs/1364521

Title:
  LDAP integration with Active Directory backend can throw:
  UnicodeDecodeError

Status in OpenStack Identity (Keystone):
  New

Bug description:
  Basic AD integration with Keystone using the LDAP backend.

  Started getting the following trace:

  2014-09-02 07:48:56.473 21448 DEBUG keystone.common.ldap.core [-] LDAP bind: dn=CN=role-admin,OU=openstack,OU=Groups,DC=LAB,DC=RMSONECLOUD,DC=NET simple_bind_s /usr/lib/python2.6/site-packages/keystone/common/ldap/core.py:780
  2014-09-02 07:48:56.481 21448 DEBUG keystone.common.ldap.core [-] LDAP search: dn=OU=openstack,OU=Groups,DC=LAB,DC=RMSONECLOUD,DC=NET, scope=2, query=(&(CN=role-admin)(objectclass=organizationalPerson)), attrs=None search_s /usr/lib/python2.6/site-packages/keystone/common/ldap/core.py:816
  2014-09-02 07:48:56.491 21448 DEBUG keystone.common.ldap.core [-] LDAP unbind unbind_s /usr/lib/python2.6/site-packages/keystone/common/ldap/core.py:786
  2014-09-02 07:48:56.492 21448 DEBUG keystone.notifications [-] CADF Event: {'typeURI': 'http://schemas.dmtf.org/cloud/audit/1.0/event', 'initiator': {'typeURI': 'service/security/account/user', 'host': {'agent': 'python-keystoneclient', 'address': '10.76.32.80'}, 'id': 'openstack:83237b62-6c82-4dd1-a53d-6521462d329b', 'name': u'role-admin'}, 'target': {'typeURI': 'service/security/account/user', 'id': 'openstack:9eea98fe-b557-455a-a9a4-3174e06ce698'}, 'observer': {'typeURI': 'service/security', 'id': 'openstack:3cbf8b13-a535-4e24-8c98-bf9abcb4ced4'}, 'eventType': 'activity', 'eventTime': '2014-09-02T11:48:56.491795+0000', 'action': 'authenticate', 'outcome': 'failure', 'id': 'openstack:39adb273-edec-4efe-9825-80fb30b1a94f'} _send_audit_notification /usr/lib/python2.6/site-packages/keystone/notifications.py:289
  2014-09-02 07:48:56.493 21448 ERROR keystone.common.wsgi [-] 'utf8' codec can't decode byte 0xfe in position 14: invalid start byte
  2014-09-02 07:48:56.493 21448 TRACE keystone.common.wsgi Traceback (most recent call last):
  2014-09-02 07:48:56.493 21448 TRACE keystone.common.wsgi   File "/usr/lib/python2.6/site-packages/keystone/common/wsgi.py", line 212, in __call__
  2014-09-02 07:48:56.493 21448 TRACE keystone.common.wsgi     result = method(context, **params)
  2014-09-02 07:48:56.493 21448 TRACE keystone.common.wsgi   File "/usr/lib/python2.6/site-packages/keystone/token/controllers.py", line 98, in authenticate
  2014-09-02 07:48:56.493 21448 TRACE keystone.common.wsgi     context, auth)
  2014-09-02 07:48:56.493 21448 TRACE keystone.common.wsgi   File "/usr/lib/python2.6/site-packages/keystone/token/controllers.py", line 276, in _authenticate_local
  2014-09-02 07:48:56.493 21448 TRACE keystone.common.wsgi     password=password)
  2014-09-02 07:48:56.493 21448 TRACE keystone.common.wsgi   File "/usr/lib/python2.6/site-packages/keystone/notifications.py", line 253, in wrapper
  2014-09-02 07:48:56.493 21448 TRACE keystone.common.wsgi     result = f(wrapped_self, context, user_id, *args, **kwargs)
  2014-09-02 07:48:56.493 21448 TRACE keystone.common.wsgi   File "/usr/lib/python2.6/site-packages/keystone/identity/core.py", line 189, in wrapper
  2014-09-02 07:48:56.493 21448 TRACE keystone.common.wsgi     return f(self, *args, **kwargs)
  2014-09-02 07:48:56.493 21448 TRACE keystone.common.wsgi   File "/usr/lib/python2.6/site-packages/keystone/identity/core.py", line 281, in authenticate
  2014-09-02 07:48:56.493 21448 TRACE keystone.common.wsgi     ref = driver.authenticate(user_id, password)
  2014-09-02 07:48:56.493 21448 TRACE keystone.common.wsgi   File "/usr/lib/python2.6/site-packages/keystone/identity/backends/ldap.py", line 63, in authenticate
  2014-09-02 07:48:56.493 21448 TRACE keystone.common.wsgi     conn = self.user.get_connection(self.user._id_to_dn(user_id),
  2014-09-02 07:48:56.493 21448 TRACE keystone.common.wsgi   File "/usr/lib/python2.6/site-packages/keystone/common/ldap/core.py", line 472, in _id_to_dn
  2014-09-02 07:48:56.493 21448 TRACE keystone.common.wsgi     'objclass': self.object_class})
  2014-09-02 07:48:56.493 21448 TRACE keystone.common.wsgi   File "/usr/lib/python2.6/site-packages/keystone/common/ldap/core.py", line 829, in search_s
  2014-09-02 07:48:56.493 21448 TRACE keystone.common.wsgi     py_result = convert_ldap_result(ldap_result)
  2014-09-02 07:48:56.493 21448 TRACE keystone.common.wsgi   File "/usr/lib/python2.6/site-packages/keystone/common/ldap/core.py", line 150, in convert_ldap_result
  2014-09-02 07:48:56.493 21448 TRACE keystone.common.wsgi     for kind, values in six.iteritems(attrs))))
  2014-09-02 07:48:56.493 21448 TRACE keystone.common.wsgi   File "/usr/lib/python2.6/site-packages/keystone/common/ldap/core.py", line 150, in <genexpr>
  2014-09-02 07:48:56.493 21448 TRACE keystone.common.wsgi     for kind, values in six.iteritems(attrs))))
  2014-09-02 07:48:56.493 21448 TRACE keystone.common.wsgi   File "/usr/lib/python2.6/site-packages/keystone/common/ldap/core.py", line 119, in ldap2py
  2014-09-02 07:48:56.493 21448 TRACE keystone.common.wsgi     return utf8_decode(val)
  2014-09-02 07:48:56.493 21448 TRACE keystone.common.wsgi   File "/usr/lib/python2.6/site-packages/keystone/common/ldap/core.py", line 80, in utf8_decode
  2014-09-02 07:48:56.493 21448 TRACE keystone.common.wsgi     return _utf8_decoder(value)[0]
  2014-09-02 07:48:56.493 21448 TRACE keystone.common.wsgi   File "/usr/lib64/python2.6/encodings/utf_8.py", line 16, in decode
  2014-09-02 07:48:56.493 21448 TRACE keystone.common.wsgi     return codecs.utf_8_decode(input, errors, True)
  2014-09-02 07:48:56.493 21448 TRACE keystone.common.wsgi UnicodeDecodeError: 'utf8' codec can't decode byte 0xfe in position 14: invalid start byte

  
  I put in some debug statements into keystone.common.ldap.core to print out the attributes as they parse:

  2014-09-02 12:36:51.013 29855 DEBUG keystone.common.ldap.core [-] in convert_ldap_result convert_ldap_result /usr/lib/python2.6/site-packages/keystone/common/ldap/core.py:144
  2014-09-02 12:36:51.013 29855 DEBUG keystone.common.ldap.core [-] converting OU=admin,OU=project,OU=openstack,DC=LAB,DC=RMSONECLOUD,DC=NET convert_ldap_result /usr/lib/python2.6/site-packages/keystone/common/ldap/core.py:154
  2014-09-02 12:36:51.013 29855 DEBUG keystone.common.ldap.core [-] working with:OU=admin,OU=project,OU=openstack,DC=LAB,DC=RMSONECLOUD,DC=NET ldap2py /usr/lib/python2.6/site-packages/keystone/common/ldap/core.py:111
  2014-09-02 12:36:51.014 29855 DEBUG keystone.common.ldap.core [-] working with:20140829191850.0Z ldap2py /usr/lib/python2.6/site-packages/keystone/common/ldap/core.py:111
  2014-09-02 12:36:51.014 29855 DEBUG keystone.common.ldap.core [-] working with:20140829191850.0Z ldap2py /usr/lib/python2.6/site-packages/keystone/common/ldap/core.py:111
  2014-09-02 12:36:51.014 29855 DEBUG keystone.common.ldap.core [-] working with:16010101000000.0Z ldap2py /usr/lib/python2.6/site-packages/keystone/common/ldap/core.py:111
  2014-09-02 12:36:51.014 29855 DEBUG keystone.common.ldap.core [-] working with:admin ldap2py /usr/lib/python2.6/site-packages/keystone/common/ldap/core.py:111
  2014-09-02 12:36:51.014 29855 DEBUG keystone.common.ldap.core [-] working with:CN=Organizational-Unit,CN=Schema,CN=Configuration,DC=RMSONECLOUD,DC=NET ldap2py /usr/lib/python2.6/site-packages/keystone/common/ldap/core.py:111
  2014-09-02 12:36:51.015 29855 DEBUG keystone.common.ldap.core [-] working with:top ldap2py /usr/lib/python2.6/site-packages/keystone/common/ldap/core.py:111
  2014-09-02 12:36:51.015 29855 DEBUG keystone.common.ldap.core [-] working with:organizationalUnit ldap2py /usr/lib/python2.6/site-packages/keystone/common/ldap/core.py:111
  2014-09-02 12:36:51.015 29855 DEBUG keystone.common.ldap.core [-] working with:?"?gZK??[J???? ldap2py /usr/lib/python2.6/site-packages/keystone/common/ldap/core.py:111
  2014-09-02 12:36:51.015 29855 DEBUG keystone.common.ldap.core [-] working with:20140829192641.0Z ldap2py /usr/lib/python2.6/site-packages/keystone/common/ldap/core.py:111
  2014-09-02 12:36:51.015 29855 DEBUG keystone.common.ldap.core [-] working with:20140829191850.0Z ldap2py /usr/lib/python2.6/site-packages/keystone/common/ldap/core.py:111
  2014-09-02 12:36:51.016 29855 DEBUG keystone.common.ldap.core [-] working with:9885816 ldap2py /usr/lib/python2.6/site-packages/keystone/common/ldap/core.py:111
  2014-09-02 12:36:51.016 29855 DEBUG keystone.common.ldap.core [-] working with:TRUE ldap2py /usr/lib/python2.6/site-packages/keystone/common/ldap/core.py:111
  2014-09-02 12:36:51.016 29855 DEBUG keystone.common.ldap.core [-] working with:9886144 ldap2py /usr/lib/python2.6/site-packages/keystone/common/ldap/core.py:111
  2014-09-02 12:36:51.016 29855 DEBUG keystone.common.ldap.core [-] working with:admin ldap2py /usr/lib/python2.6/site-packages/keystone/common/ldap/core.py:111
  2014-09-02 12:36:51.016 29855 DEBUG keystone.common.ldap.core [-] working with:4 ldap2py /usr/lib/python2.6/site-packages/keystone/common/ldap/core.py:111
  2014-09-02 12:36:51.017 29855 DEBUG keystone.common.ldap.core [-] finished converting convert_ldap_result /usr/lib/python2.6/site-packages/keystone/common/ldap/core.py:158
  2014-09-02 12:36:51.017 29855 DEBUG keystone.common.ldap.core [-] LDAP unbind unbind_s /usr/lib/python2.6/site-packages/keystone/common/ldap/core.py:796

  
  The 'working with:' lines are the values that it's trying to convert.  you can see the one mid way through with the  strange question marks and other chars.  Not sure WHY this is getting returned as a network capture shows clean, ledgible attribute values, however, it IS getting returned and I think we should trap this sort of thing in ldap2py.

To manage notifications about this bug go to:
https://bugs.launchpad.net/keystone/+bug/1364521/+subscriptions

Follow ups

References

  Thread Previous • Date Previous • • Thread Next