On 12/08/11 16:12, Brian Burch wrote:
I will try to do the test again tomorrow with debugging turned on unless
you see something useful above.
Well, I am baffled. The debug log is quite big but doesn't tell me
anything we didn't know already. I don't want to fill up the mail
archive, so here is a summary:
The SASL dialog progresses normally until the client response to the
server challenge arrives, and is decoded without error.
[10:24:08] DEBUG
[org.apache.directory.shared.ldap.codec.TwixTransformer] - Transforming
LdapMessage <2, BIND_REQUEST> from Twix to Snickers.
[10:24:08] DEBUG [org.apache.directory.server.ldap.handlers.BindHandler]
- Received: BindRequest
Version : '3'
Name : ''
Sasl credentials
Mechanism :'DIGEST-MD5'
Credentials :
'charset=utf-8,username="uid=testDigest,ou=people,o=pingtoo.com",realm="pingtoo.com",nonce="G33N7OiolRjzUUPZ0rt9Xd+yekVkscWuLSGaTbpV",nc=00000001,cnonce="NLeTmnE3GMTyaUC7fm0PvSu6rLzCgdr5aNIZvGrj",digest-uri="ldap/ldap.pingtoo.com",maxbuf=65536,response=01f3099702d77231b7e00b0ce97ed1fd,qop=auth
(hex snipped out)'
Then only this is logged:
[10:24:08] DEBUG
[org.apache.directory.server.ldap.handlers.bind.AbstractSaslCallbackHandler]
- Processing callback 1 of 3: {}class javax.security.sasl.RealmCallback
[10:24:08] DEBUG
[org.apache.directory.server.ldap.handlers.bind.AbstractSaslCallbackHandler]
- RealmCallback default text: pingtoo.com
[10:24:08] DEBUG
[org.apache.directory.server.ldap.handlers.bind.AbstractSaslCallbackHandler]
- Processing callback 2 of 3: {}class
javax.security.auth.callback.NameCallback
[10:24:08] DEBUG
[org.apache.directory.server.ldap.handlers.bind.AbstractSaslCallbackHandler]
- NameCallback default name: uid=testDigest,ou=people,o=pingtoo.com
[10:24:08] DEBUG
[org.apache.directory.server.ldap.handlers.bind.AbstractSaslCallbackHandler]
- Processing callback 3 of 3: {}class
javax.security.auth.callback.PasswordCallback
[10:24:08] DEBUG
[org.apache.directory.server.schema.registries.DefaultOidRegistry] -
looked up OID '2.5.4.35' with id 'userPassword'
[10:24:08] DEBUG
[org.apache.directory.server.schema.registries.DefaultAttributeTypeRegistry]
- lookup with id2.5.4.35' of attributeType: <2.5.4.35, userPassword>
[10:24:08] DEBUG
[org.apache.directory.server.core.authn.AuthenticationInterceptor] -
Operation Context: LookupContext for DN 'ou=people,ou=pingtoo.com',
attributes : <>
[10:24:08] DEBUG
[org.apache.directory.server.core.partition.DefaultPartitionNexus] -
Check if DN '2.5.4.11=people,2.5.4.11=pingtoo.com' exists.
[10:24:08] DEBUG
[org.apache.directory.server.schema.registries.DefaultOidRegistry] -
looked up OID '0.9.2342.19200300.100.1.1' with id 'uid'
[10:24:08] DEBUG
[org.apache.directory.server.schema.registries.DefaultOidRegistry] -
looked up OID '0.9.2342.19200300.100.1.1' with id 'uid'
[10:24:08] DEBUG
[org.apache.directory.server.schema.registries.DefaultAttributeTypeRegistry]
- lookup with id0.9.2342.19200300.100.1.1' of attributeType:
<0.9.2342.19200300.100.1.1, uid>
[10:24:08] DEBUG
[org.apache.directory.server.schema.registries.DefaultOidRegistry] -
looked up OID '0.9.2342.19200300.100.1.1' with id 'uid'
[10:24:08] DEBUG
[org.apache.directory.server.schema.registries.DefaultAttributeTypeRegistry]
- lookup with id0.9.2342.19200300.100.1.1' of attributeType:
<0.9.2342.19200300.100.1.1, uid>
[10:24:08] DEBUG
[org.apache.directory.server.schema.registries.DefaultOidRegistry] -
looked up OID '0.9.2342.19200300.100.1.1' with id 'uid'
[10:24:08] DEBUG
[org.apache.directory.server.schema.registries.DefaultAttributeTypeRegistry]
- lookup with id0.9.2342.19200300.100.1.1' of attributeType:
<0.9.2342.19200300.100.1.1, uid>
[10:24:08] DEBUG
[org.apache.directory.server.schema.registries.DefaultNormalizerRegistry] -
registered normalizer with oid: 2.5.13.2
[10:24:08] DEBUG
[org.apache.directory.server.schema.registries.DefaultOidRegistry] -
looked up OID '0.9.2342.19200300.100.1.1' with id 'uid'
[10:24:08] DEBUG
[org.apache.directory.server.core.authn.AuthenticationInterceptor] -
Operation Context: SearchContext for DN 'ou=people,ou=pingtoo.com',
filter :'(0.9.2342.19200300.100.1.1=uid=testdigest,ou=people,o=pingtoo.com)'
[10:24:08] DEBUG
[org.apache.directory.server.schema.registries.DefaultAttributeTypeRegistry]
- lookup with id0.9.2342.19200300.100.1.1' of attributeType:
<0.9.2342.19200300.100.1.1, uid>
[10:24:08] DEBUG
[org.apache.directory.server.core.partition.DefaultPartitionNexus] -
Check if DN '2.5.4.11=people,2.5.4.11=pingtoo.com' exists.
[10:24:08] ERROR [org.apache.directory.server.ldap.handlers.BindHandler]
- INVALID_CREDENTIALS: DIGEST-MD5: cannot acquire password for
uid=testDigest,ou=people,o=pingtoo.com in realm : pingtoo.com
[10:24:08] DEBUG
[org.apache.directory.shared.ldap.codec.TwixTransformer] - Transforming
message type BIND_RESPONSE
[10:24:08] DEBUG
[org.apache.directory.shared.ldap.codec.TwixTransformer] - Transformed
message : LdapMessage
message Id : 2
BindResponse
Ldap Result
Result code : (INVALID_CREDENTIALS) invalidCredentials
Matched DN : ''
Error message : 'INVALID_CREDENTIALS: DIGEST-MD5: cannot
acquire password for uid=testDigest,ou=people,o=pingtoo.com in realm :
pingtoo.com'
I've looked carefully for some trivial typo, but I can't find any. The
user entry exists and holds a cleartext userpassword. The SASL
authentication thread logged earlier that it was running as
dn[n]: 0.9.2342.19200300.100.1.1=admin,2.5.4.11=system
... who definitely is able to read the user's password via studio or
ldapsearch. Why can't it read the userpassword within the SASL
authentication dialogue?
I don't have a debugger environment set up, so it will take me quite a
while before I'm able to step through the source at the time of the error.
