<html><head><meta http-equiv="Content-Type" content="text/html charset=windows-1252"></head><body style="word-wrap: break-word; -webkit-nbsp-mode: space; -webkit-line-break: after-white-space;">Thanks for your response Daniel. I hope you will further indulge me,<div>because your suggestion seems to me at odds with some aspects</div><div>of what the logs appear to state. <br><div><div><br></div><div><div>On Fri, 20 Jun 2014, at 11:06 , Daniel Fisher <<a href="mailto:dfisher@vt.edu">dfisher@vt.edu</a>> wrote:</div><blockquote type="cite"><font color="#000000">...</font><br>What you're seeing (I think) is the result of an invalid password. The<br>first module correctly resolves the DN, but the bind fails. The second<br>module cannot resolve the DN. </blockquote><div><br></div><div>If the second (AD) module could not resolve the dn, where oh where does the dn in the logs come from:</div><div><span style="font-family: Monaco; font-size: 10px; background-color: rgb(255, 250, 194);">Authentication failed for dn: CN=</span><span style="font-family: Monaco; font-size: 10px; background-color: rgb(230, 230, 0);">jlrosenthal</span><span style="font-family: Monaco; font-size: 10px; background-color: rgb(255, 250, 194);">,OU=userAccounts,dc=ua,dc=ad,dc=alaska,dc=edu</span></div>...<span style="font-family: Monaco; font-size: 10px; background-color: rgb(255, 250, 194);">invalid dn</span></div><div><span style="font-family: Monaco; font-size: 10px; background-color: rgb(255, 250, 194);"><br></span></div><div><span style="font-family: Monaco; font-size: 10px; background-color: rgb(255, 250, 194);">Note that the dn </span><span style="font-family: Monaco; font-size: 10px; background-color: rgb(255, 250, 194);">CN=</span><span style="font-family: Monaco; font-size: 10px; background-color: rgb(230, 230, 0);">jlrosenthal</span><span style="font-family: Monaco; font-size: 10px; background-color: rgb(255, 250, 194);">,OU=userAccounts,dc=ua,dc=ad,dc=alaska,dc=edu </span></div><div><span style="background-color: rgb(255, 250, 194);"><font face="Monaco" size="1">is both CORRECT - independently verified to be a valid dn in AD, and</font></span></div><div><span style="font-family: Monaco; font-size: 10px; background-color: rgb(255, 250, 194);">is NOTHING LIKE the dn's in LDAP, which are of the form UID=12WYNPGYZ01,dc=alaska,dc=edu</span></div><div><span style="font-family: Monaco; font-size: 10px; background-color: rgb(255, 250, 194);"><br></span></div><div><br></div><div><blockquote type="cite">So you should expect logs from both<br>modules anytime a user gives the wrong password. A user whose login<br>succeeds on the first module would only produce logs for that module.<br>A user whose login succeeds on the second module would produce logs<br>from both modules.<br></blockquote><div><br></div>Yes of course; that's not at issue at all. </div><div>My question - my attempt to understand what’s happening with a few users -</div><div>is what the error message “invalid dn” is reflecting; in particular what is it reflecting</div><div>that is DIFFERENT from both a failure to find a dn for the principal and from an</div><div>invalid password submitted by the user. It seems your analysis is that </div><div>“sometimes” an incorrect password is logged as “invalid credential” but sometimes</div><div>as “invalid dn” and that these different log messages reflect the same underlying</div><div>failure with no determinate cause of which message is output to the logs. </div><div>That is conceivable, but introduces an unfortunate randomness to the behavior </div><div>of the IdP!</div><div><br></div><div>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.</div><div>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:</div><div>1<span class="Apple-tab-span" style="white-space:pre"> </span>No DN in LDAP<span class="Apple-tab-span" style="white-space:pre"> </span><span class="Apple-tab-span" style="white-space:pre"> </span>+<span class="Apple-tab-span" style="white-space:pre"> </span>Failed bind to AD DN<span class="Apple-tab-span" style="white-space:pre"> </span>= <span class="Apple-tab-span" style="white-space:pre"> </span>“invalid dn"</div><div>2<span class="Apple-tab-span" style="white-space:pre"> </span>No DN in LDAP<span class="Apple-tab-span" style="white-space:pre"> </span><span class="Apple-tab-span" style="white-space:pre"> </span>+<span class="Apple-tab-span" style="white-space:pre"> </span>No DN in AD<span class="Apple-tab-span" style="white-space:pre"> </span>=<span class="Apple-tab-span" style="white-space:pre"> </span>“invalid credential”</div><div>3<span class="Apple-tab-span" style="white-space:pre"> </span>No DN in LDAP<span class="Apple-tab-span" style="white-space:pre"> </span>+<span class="Apple-tab-span" style="white-space:pre"> </span>Successful bind to AD DN<span class="Apple-tab-span" style="white-space:pre"> </span>=<span class="Apple-tab-span" style="white-space:pre"> </span>Successfully authenticated</div><div>4<span class="Apple-tab-span" style="white-space: pre;"> </span>Failed bind to LDAP DN<span class="Apple-tab-span" style="white-space: pre;"> </span>+<span class="Apple-tab-span" style="white-space: pre;"> </span>Successful bind to AD DN<span class="Apple-tab-span" style="white-space: pre;"> </span>=<span class="Apple-tab-span" style="white-space: pre;"> </span>Successfully authenticated</div><div>5<span class="Apple-tab-span" style="white-space:pre"> </span>Failed bind to LDAP DN<span class="Apple-tab-span" style="white-space:pre"> </span>+<span class="Apple-tab-span" style="white-space:pre"> </span>Failed bind to AD DN<span class="Apple-tab-span" style="white-space:pre"> </span>=<span class="Apple-tab-span" style="white-space:pre"> </span>“Invalid Credentials”</div><div><br></div><div><div>1</div><div><div style="margin: 0px; font-size: 10px; font-family: Monaco; background-color: rgb(255, 250, 194);">13:33:41.982 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.provider.UsernamePasswordLoginServlet:153] - Attempting to authenticate user 31115951</div><div style="margin: 0px; font-size: 10px; font-family: Monaco; background-color: rgb(255, 250, 194);">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}))</div><div style="margin: 0px; font-size: 10px; font-family: Monaco; background-color: rgb(255, 250, 194);">13:33:42.494 - INFO [edu.vt.middleware.ldap.jaas.JaasAuthenticator:180] - Authentication failed for dn: CN=<span style="background-color: rgb(230, 230, 0);">jlrosenthal</span>,OU=userAccounts,dc=ua,dc=ad,dc=alaska,dc=edu</div><div style="margin: 0px; font-size: 10px; font-family: Monaco; background-color: rgb(255, 250, 194);">13:33:42.497 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.provider.UsernamePasswordLoginServlet:176] - User authentication for 31115951 failed</div><div style="margin: 0px; font-size: 10px; font-family: Monaco; background-color: rgb(255, 250, 194);">javax.security.auth.login.LoginException: Cannot authenticate dn, invalid dn</div><div><br></div><div>If I understand your analysis, Daniel, the IdP </div><div><span class="Apple-tab-span" style="white-space: pre;"> </span>first failed to locate the principal in the LDAP, logged as failed search</div><div><span class="Apple-tab-span" style="white-space: pre;"> </span>then tried AD, found the principal and retrieved the DN, in the log </div><div><span class="Apple-tab-span" style="white-space: pre;"> </span>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)</div><div><span class="Apple-tab-span" style="white-space: pre;"> </span>then logged the failed first search again, this time as an "invalid dn"</div><div><br></div><div>Really? And why sometimes that odd sequence, when usually the logs report a more comprehensible (to me) sequences:</div><div><br></div><div><div>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:</div><div><div style="margin: 0px; font-size: 11px; font-family: Monaco; background-color: rgb(255, 250, 194);">01:22:32.849 - INFO [edu.vt.middleware.ldap.auth.SearchDnResolver:161] - Search for user: <a href="http://otmail.com">otmail.com</a> <span style="background-color: rgb(230, 230, 0);">failed using filter</span>: (|(uid={0})(uasystemid={0})(bannerid={0}))</div><div style="margin: 0px; font-size: 11px; font-family: Monaco; background-color: rgb(255, 250, 194);">01:22:33.082 - INFO [edu.vt.middleware.ldap.auth.SearchDnResolver:161] - Search for user: <a href="http://otmail.com">otmail.com</a> <span style="background-color: rgb(230, 230, 0);">failed using filter</span>: (|(sAMAccountName={0})(uaIdentifier={0}))</div><div style="margin: 0px; font-size: 11px; font-family: Monaco; background-color: rgb(255, 250, 194);">01:22:33.085 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.provider.UsernamePasswordLoginServlet:176] - User authentication for <a href="http://otmail.com">otmail.com</a> failed</div><div style="margin: 0px; font-size: 11px; font-family: Monaco; background-color: rgb(255, 250, 194);">javax.security.auth.login.LoginException: Cannot authenticate dn, invalid credential</div></div><div>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</div></div><div><br></div><div>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”:</div><div><div style="margin: 0px; font-size: 11px; font-family: Monaco; background-color: rgb(255, 250, 194);">14:30:50.636 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.provider.UsernamePasswordLoginServlet:153] - Attempting to authenticate user slwagner2</div><div style="margin: 0px; font-size: 11px; font-family: Monaco; background-color: rgb(255, 250, 194);">14:30:50.691 - INFO [edu.vt.middleware.ldap.auth.<span style="background-color: rgb(230, 230, 0);">Search</span>DnResolver:161] - <span style="background-color: rgb(230, 230, 0);">Search</span> for user: slwagner2 failed using filter: (|(uid={0})(uasystemid={0})(bannerid={0}))</div><div style="margin: 0px; font-size: 11px; font-family: Monaco; background-color: rgb(255, 250, 194);">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</div><div style="margin: 0px; font-size: 11px; font-family: Monaco; background-color: rgb(255, 250, 194);">14:30:51.132 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.provider.UsernamePasswordLoginServlet:161] - Successfully authenticated user slwagner2</div></div><div>there is no subsequent log entry similar to the “invalid dn” message seen when AD fails to authenticate.</div><div><br></div><div>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:</div><div><div style="margin: 0px; font-size: 11px; font-family: Monaco; background-color: rgb(255, 250, 194);">11:34:50.142 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.provider.UsernamePasswordLoginServlet:153] - Attempting to authenticate user rgmiller</div><div style="margin: 0px; font-size: 11px; font-family: Monaco; background-color: rgb(255, 250, 194);">11:34:50.261 - INFO [edu.vt.middleware.ldap.jaas.JaasAuthenticator:180] - <span style="background-color: rgb(230, 230, 0);">Authentication failed</span> for dn: uid=NND37KHI01,ou=people,dc=alaska,dc=edu</div><div style="margin: 0px; font-size: 11px; font-family: Monaco; background-color: rgb(255, 250, 194);">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</div></div><div>there is no subsequent log entry similar to the “invalid dn” or invalid credential message seen when AD fails to authenticate; </div><div style="font-size: 11px;"><br></div><div style="font-size: 11px;">5 Both LDAP and AD resolve DNs; but bind fails in both:</div><div style="font-size: 11px;"><div style="margin: 0px; font-size: 10px; font-family: Monaco; background-color: rgb(255, 250, 194);">09:49:45.916 - INFO [edu.vt.middleware.ldap.jaas.JaasAuthenticator:180] - Authentication failed for dn: uid=MV96J91201,ou=people,dc=alaska,dc=edu</div><div style="margin: 0px; font-size: 10px; font-family: Monaco; background-color: rgb(255, 250, 194);">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</div><div style="margin: 0px; font-size: 10px; font-family: Monaco; background-color: rgb(255, 250, 194);">09:49:46.380 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.provider.UsernamePasswordLoginServlet:176] - User authentication for djohnston2 failed</div><div style="margin: 0px; font-size: 10px; font-family: Monaco; background-color: rgb(255, 250, 194);">javax.security.auth.login.LoginException: [LDAP: error code <span style="background-color: #e6e600">49 - I</span>nvalid Credentials]</div></div><div><br></div><div><br></div><div>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. </div><div><br></div><div>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? </div></div></div><div><br><blockquote type="cite"><br>--Daniel Fisher<br></blockquote></div><br></div></div></body></html>