JAAS module debugging

Mauro Minella Mauro.Minella at microsoft.com
Sun Oct 7 06:53:43 EDT 2012 

Hello,
I can't get authenticated via JAAS when it's used for ECP authentication. In fact, when Outlook (active client) tries to connect, the password is asked over and over.

Here is my module:
******************
ShibUserPassAuth {
   edu.vt.middleware.ldap.jaas.LdapLoginModule required
      host="localhost"
      port="389"
      base="CN=Users,DC=shibdomain,DC=local"
      serviceCredential="MYPASSWORD"
      serviceUser="adreader at shibdomain.local"
      subtreeSearch = "true"
      userField="sAMAccountName";
}
******************

Nothing is traced in catalina.log, but this is what I get in idp-process.log. I frankly cannot identify an error message (I even get "Authentication succeeded"), however the authentication fails, can you help me debugging the following to identify what's wrong?
******************
12:38:24.017 - TRACE [edu.vt.middleware.ldap.jaas.LdapLoginModule:144] - Begin initialize
12:38:24.017 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:180] - useFirstPass = false
12:38:24.017 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:181] - tryFirstPass = false
12:38:24.017 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:182] - storePass = false
12:38:24.017 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:183] - clearPass = false
12:38:24.017 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:184] - setLdapPrincipal = true
12:38:24.017 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:185] - setLdapDnPrincipal = false
12:38:24.017 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:186] - setLdapCredential = true
12:38:24.017 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:187] - defaultRole = []
12:38:24.017 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:188] - principalGroupName = null
12:38:24.017 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:189] - roleGroupName = null
12:38:24.017 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:77] - userRoleAttribute = []
12:38:24.048 - TRACE [edu.vt.middleware.ldap.auth.AuthenticatorConfig:1385] - setting searchScope: ONELEVEL
12:38:24.048 - TRACE [edu.vt.middleware.ldap.auth.AuthenticatorConfig:427] - setting subtreeSearch: true
12:38:24.048 - TRACE [edu.vt.middleware.ldap.auth.AuthenticatorConfig:1385] - setting searchScope: SUBTREE
12:38:24.048 - TRACE [edu.vt.middleware.ldap.auth.AuthenticatorConfig:1309] - setting bindCredential: <suppressed>
12:38:24.048 - TRACE [edu.vt.middleware.ldap.auth.AuthenticatorConfig:1168] - setting ldapUrl: ldap://localhost:389
12:38:24.048 - TRACE [edu.vt.middleware.ldap.auth.AuthenticatorConfig:274] - setting userField: [sAMAccountName]
12:38:24.048 - TRACE [edu.vt.middleware.ldap.auth.AuthenticatorConfig:1276] - setting bindDn: adreader at shibdomain.local
12:38:24.048 - TRACE [edu.vt.middleware.ldap.auth.AuthenticatorConfig:1370] - setting baseDn: CN=Users,DC=shibdomain,DC=local
12:38:24.048 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:83] - Created authenticator: edu.vt.middleware.ldap.auth.AuthenticatorConfig at 2377718::env={java.naming.provider.url=ldap://localhost:389, java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory}
12:38:24.048 - TRACE [edu.vt.middleware.ldap.jaas.LdapLoginModule:412] - Begin getCredentials
12:38:24.048 - TRACE [edu.vt.middleware.ldap.jaas.LdapLoginModule:413] -   useFistPass = false
12:38:24.048 - TRACE [edu.vt.middleware.ldap.jaas.LdapLoginModule:414] -   tryFistPass = false
12:38:24.048 - TRACE [edu.vt.middleware.ldap.jaas.LdapLoginModule:415] -   useCallback = false
12:38:24.048 - TRACE [edu.vt.middleware.ldap.jaas.LdapLoginModule:416] -   callbackhandler class = javax.security.auth.login.LoginContext$SecureCallbackHandler
12:38:24.048 - TRACE [edu.vt.middleware.ldap.jaas.LdapLoginModule:419] -   name callback class = javax.security.auth.callback.NameCallback
12:38:24.048 - TRACE [edu.vt.middleware.ldap.jaas.LdapLoginModule:421] -   password callback class = javax.security.auth.callback.PasswordCallback
12:38:24.048 - DEBUG [edu.vt.middleware.ldap.auth.SearchDnResolver:108] - Looking up DN using userField
12:38:24.048 - DEBUG [edu.vt.middleware.ldap.auth.SearchDnResolver:193] - Search with the following parameters:
12:38:24.048 - DEBUG [edu.vt.middleware.ldap.auth.SearchDnResolver:194] -   dn = CN=Users,DC=shibdomain,DC=local
12:38:24.048 - DEBUG [edu.vt.middleware.ldap.auth.SearchDnResolver:195] -   filter = (sAMAccountName={0})
12:38:24.048 - DEBUG [edu.vt.middleware.ldap.auth.SearchDnResolver:196] -   filterArgs = [aldo.minella]
12:38:24.048 - DEBUG [edu.vt.middleware.ldap.auth.SearchDnResolver:197] -   searchControls = javax.naming.directory.SearchControls at 18bd39a
12:38:24.048 - DEBUG [edu.vt.middleware.ldap.auth.SearchDnResolver:198] -   handler = [edu.vt.middleware.ldap.handler.FqdnSearchResultHandler at f139cb]
12:38:24.048 - TRACE [edu.vt.middleware.ldap.auth.SearchDnResolver:200] -   config = {java.naming.provider.url=ldap://localhost:389, java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory}
12:38:24.048 - TRACE [edu.vt.middleware.ldap.handler.DefaultConnectionHandler:93] - setting connectionStrategy: DEFAULT
12:38:24.048 - TRACE [edu.vt.middleware.ldap.handler.DefaultConnectionHandler:110] - setting connectionRetryExceptions: [class javax.naming.NamingException]
12:38:24.048 - TRACE [edu.vt.middleware.ldap.handler.DefaultConnectionHandler:152] - {0} Attempting connection to ldap://localhost:389 for strategy DEFAULT
12:38:24.048 - DEBUG [edu.vt.middleware.ldap.handler.DefaultConnectionHandler:74] - Bind with the following parameters:
12:38:24.048 - DEBUG [edu.vt.middleware.ldap.handler.DefaultConnectionHandler:75] -   authtype = simple
12:38:24.048 - DEBUG [edu.vt.middleware.ldap.handler.DefaultConnectionHandler:76] -   dn = adreader at shibdomain.local
12:38:24.048 - DEBUG [edu.vt.middleware.ldap.handler.DefaultConnectionHandler:83] -   credential = <suppressed>
12:38:24.048 - TRACE [edu.vt.middleware.ldap.handler.DefaultConnectionHandler:87] -   env = {java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory, java.naming.provider.url=ldap://localhost:389}
12:38:24.080 - TRACE [edu.vt.middleware.ldap.handler.FqdnSearchResultHandler:69] - processing relative dn: CN=Aldo Minella
12:38:24.080 - TRACE [edu.vt.middleware.ldap.handler.FqdnSearchResultHandler:95] - processed dn: CN=Aldo Minella,CN=Users,DC=shibdomain,DC=local
12:38:24.080 - TRACE [edu.vt.middleware.ldap.handler.DefaultConnectionHandler:93] - setting connectionStrategy: DEFAULT
12:38:24.080 - TRACE [edu.vt.middleware.ldap.handler.DefaultConnectionHandler:110] - setting connectionRetryExceptions: [class javax.naming.NamingException]
12:38:24.080 - TRACE [edu.vt.middleware.ldap.handler.DefaultConnectionHandler:152] - {1} Attempting connection to ldap://localhost:389 for strategy DEFAULT
12:38:24.080 - DEBUG [edu.vt.middleware.ldap.handler.DefaultConnectionHandler:74] - Bind with the following parameters:
12:38:24.080 - DEBUG [edu.vt.middleware.ldap.handler.DefaultConnectionHandler:75] -   authtype = simple
12:38:24.080 - DEBUG [edu.vt.middleware.ldap.handler.DefaultConnectionHandler:76] -   dn = CN=Aldo Minella,CN=Users,DC=shibdomain,DC=local
12:38:24.080 - DEBUG [edu.vt.middleware.ldap.handler.DefaultConnectionHandler:83] -   credential = <suppressed>
12:38:24.080 - TRACE [edu.vt.middleware.ldap.handler.DefaultConnectionHandler:87] -   env = {java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory, java.naming.provider.url=ldap://localhost:389}
12:38:24.080 - INFO [edu.vt.middleware.ldap.jaas.JaasAuthenticator:176] - Authentication succeeded for dn: CN=Aldo Minella,CN=Users,DC=shibdomain,DC=local
12:38:24.095 - DEBUG [edu.vt.middleware.ldap.auth.SearchDnResolver:108] - Looking up DN using userField
12:38:24.095 - DEBUG [edu.vt.middleware.ldap.auth.SearchDnResolver:193] - Search with the following parameters:
12:38:24.095 - DEBUG [edu.vt.middleware.ldap.auth.SearchDnResolver:194] -   dn = CN=Users,DC=shibdomain,DC=local
12:38:24.095 - DEBUG [edu.vt.middleware.ldap.auth.SearchDnResolver:195] -   filter = (sAMAccountName={0})
12:38:24.095 - DEBUG [edu.vt.middleware.ldap.auth.SearchDnResolver:196] -   filterArgs = [aldo.minella]
12:38:24.095 - DEBUG [edu.vt.middleware.ldap.auth.SearchDnResolver:197] -   searchControls = javax.naming.directory.SearchControls at 6aad80
12:38:24.095 - DEBUG [edu.vt.middleware.ldap.auth.SearchDnResolver:198] -   handler = [edu.vt.middleware.ldap.handler.FqdnSearchResultHandler at f139cb]
12:38:24.095 - TRACE [edu.vt.middleware.ldap.auth.SearchDnResolver:200] -   config = {java.naming.provider.url=ldap://localhost:389, java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory}
12:38:24.095 - TRACE [edu.vt.middleware.ldap.handler.FqdnSearchResultHandler:69] - processing relative dn: CN=Aldo Minella
12:38:24.095 - TRACE [edu.vt.middleware.ldap.handler.FqdnSearchResultHandler:95] - processed dn: CN=Aldo Minella,CN=Users,DC=shibdomain,DC=local
12:38:24.095 - TRACE [edu.vt.middleware.ldap.jaas.LdapLoginModule:208] - Begin commit
12:38:24.095 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:223] - Committed the following principals: [aldo.minella[]]
12:38:24.095 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:229] - Committed the following roles: []
******************

Thanks

Mauro
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://shibboleth.net/pipermail/users/attachments/20121007/950fca76/attachment-0001.html

More information about the users mailing list