authentication failure reasons in IdP logs

[David Bantz]

Thanks for your response Daniel.  I hope you will further indulge me,
because your suggestion seems to me at odds with some aspects
of what the logs appear to state. 

On Fri, 20 Jun 2014, at 11:06 , Daniel Fisher <dfisher at vt.edu> wrote:
> ...
> What you're seeing (I think) is the result of an invalid password. The
> first module correctly resolves the DN, but the bind fails. The second
> module cannot resolve the DN.

If the second (AD) module could not resolve the dn, where oh where does the dn in the logs come from:
Authentication failed for dn: CN=jlrosenthal,OU=userAccounts,dc=ua,dc=ad,dc=alaska,dc=edu
...invalid dn

Note that the dn CN=jlrosenthal,OU=userAccounts,dc=ua,dc=ad,dc=alaska,dc=edu 
is both CORRECT - independently verified to be a valid dn in AD, and
is NOTHING LIKE the dn's in LDAP, which are of the form UID=12WYNPGYZ01,dc=alaska,dc=edu


> So you should expect logs from both
> modules anytime a user gives the wrong password. A user whose login
> succeeds on the first module would only produce logs for that module.
> A user whose login succeeds on the second module would produce logs
> from both modules.

Yes of course; that's not at issue at all.  
My question - my attempt to understand what’s happening with a few users -
is what the error message “invalid dn” is reflecting; in particular what is it reflecting
that is DIFFERENT from both a failure to find a dn for the principal and from an
invalid password submitted by the user.  It seems your analysis is that 
“sometimes” an incorrect password is logged as “invalid credential” but sometimes
as “invalid dn” and that these different log messages reflect the same underlying
failure with no determinate cause of which message is output to the logs. 
That is conceivable, but introduces an unfortunate randomness to the behavior 
of the IdP!

In hopes of a more comfortable answer to those differences, here’s a slightly larger snippet from the same event(s), and contrasting output from other sequences.
In each instance I’m providing pertinent log messages for BOTH the first (LDAP) and second (AD) modules.  These include interactions for which there is:
1	No DN in LDAP		+	Failed bind to AD DN		= 	“invalid dn"
2	No DN in LDAP		+	No DN in AD				=	“invalid credential”
3	No DN in LDAP		+	Successful bind to AD DN	=	Successfully authenticated
4	Failed bind to LDAP DN	+	Successful bind to AD DN	=	Successfully authenticated
5	Failed bind to LDAP DN	+	Failed bind to AD DN		=	“Invalid Credentials”

1
13:33:41.982 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.provider.UsernamePasswordLoginServlet:153] - Attempting to authenticate user 31115951
13:33:42.036 - INFO [edu.vt.middleware.ldap.auth.SearchDnResolver:161] - Search for user: 31115951 failed using filter: (|(uid={0})(uasystemid={0})(bannerid={0}))
13:33:42.494 - INFO [edu.vt.middleware.ldap.jaas.JaasAuthenticator:180] - Authentication failed for dn: CN=jlrosenthal,OU=userAccounts,dc=ua,dc=ad,dc=alaska,dc=edu
13:33:42.497 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.provider.UsernamePasswordLoginServlet:176] - User authentication for 31115951 failed
javax.security.auth.login.LoginException: Cannot authenticate dn, invalid dn

If I understand your analysis, Daniel, the IdP 
	first failed to locate the principal in the LDAP, logged as failed search
	then tried AD, found the principal and retrieved the DN, in the log 
	then failed to bind to AD, (we’re now 0.5 seconds from the fail-over to AD - and that difference of 0.5 sec is very consistent as the time it takes AD to respond with success or failure)
	then logged the failed first search again, this time as an "invalid dn"

Really?  And why sometimes that odd sequence, when usually the logs report a more comprehensible (to me) sequences:

2 A failure to find the principal in LDAP and a subsequent failure to find one in AD produces the expected two search fail and “invalid credential” errors:
01:22:32.849 - INFO [edu.vt.middleware.ldap.auth.SearchDnResolver:161] - Search for user: otmail.com failed using filter: (|(uid={0})(uasystemid={0})(bannerid={0}))
01:22:33.082 - INFO [edu.vt.middleware.ldap.auth.SearchDnResolver:161] - Search for user: otmail.com failed using filter: (|(sAMAccountName={0})(uaIdentifier={0}))
01:22:33.085 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.provider.UsernamePasswordLoginServlet:176] - User authentication for otmail.com failed
javax.security.auth.login.LoginException: Cannot authenticate dn, invalid credential
note “invalid credential” rather than invalid dn despite the same LDAP failure; suggests the invalid dn was result of different AD fail mode rather than same LDAP fail as case 1

3 A failure to find the principal in LDAP, but then finding a dn and binding to AD produces only the failed search entry in the logs, not the “invalid dn”:
14:30:50.636 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.provider.UsernamePasswordLoginServlet:153] - Attempting to authenticate user slwagner2
14:30:50.691 - INFO [edu.vt.middleware.ldap.auth.SearchDnResolver:161] - Search for user: slwagner2 failed using filter: (|(uid={0})(uasystemid={0})(bannerid={0}))
14:30:51.129 - INFO [edu.vt.middleware.ldap.jaas.JaasAuthenticator:176] - Authentication succeeded for dn: CN=slwagner2,OU=userAccounts,dc=ua,dc=ad,dc=alaska,dc=edu
14:30:51.132 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.provider.UsernamePasswordLoginServlet:161] - Successfully authenticated user slwagner2
there is no subsequent log entry similar to the “invalid dn” message seen when AD fails to authenticate.

4 Success in searching for principal in LDAP - note the radically different DN in LDAP - but a bad password; in combination with valid password in AD:
11:34:50.142 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.provider.UsernamePasswordLoginServlet:153] - Attempting to authenticate user rgmiller
11:34:50.261 - INFO [edu.vt.middleware.ldap.jaas.JaasAuthenticator:180] - Authentication failed for dn: uid=NND37KHI01,ou=people,dc=alaska,dc=edu
11:34:50.709 - INFO [edu.vt.middleware.ldap.jaas.JaasAuthenticator:176] - Authentication succeeded for dn: CN=rgmiller,OU=userAccounts,dc=ua,dc=ad,dc=alaska,dc=edu
there is no subsequent log entry similar to the “invalid dn” or invalid credential message seen when AD fails to authenticate; 

5 Both LDAP and AD resolve DNs; but bind fails in both:
09:49:45.916 - INFO [edu.vt.middleware.ldap.jaas.JaasAuthenticator:180] - Authentication failed for dn: uid=MV96J91201,ou=people,dc=alaska,dc=edu
09:49:46.378 - INFO [edu.vt.middleware.ldap.jaas.JaasAuthenticator:180] - Authentication failed for dn: CN=djohnston2,OU=userAccounts,dc=ua,dc=ad,dc=alaska,dc=edu
09:49:46.380 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.provider.UsernamePasswordLoginServlet:176] - User authentication for djohnston2 failed
javax.security.auth.login.LoginException: [LDAP: error code 49 - Invalid Credentials]


Mill’s methods entail the “invalid dn” log message is triggered by the AD failure to authenticate rather than the failure to find the user in LDAP (because that log message appears only when AD fails to authenticate the principal regardless of whether the principal was found in LDAP and it is always within a few milliseconds of the AD failure, while typically several hundred milliseconds after the failed LDAP search).  If the “invalid dn” log message were produced by the failure to find a dn in LDAP, it should be present in the 2nd and 3rd examples - but it is not.  

It is I suppose possible that the failure or success authenticating the principal to AD retroactively alters the logging of the prior failure to find the principal in LDAP.  Possible, but likely? 

> 
> --Daniel Fisher

-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://shibboleth.net/pipermail/users/attachments/20140620/691a3cb8/attachment-0001.html 
-------------- next part --------------
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 163 bytes
Desc: Message signed with OpenPGP using GPGMail
Url : http://shibboleth.net/pipermail/users/attachments/20140620/691a3cb8/attachment-0001.bin