<html xmlns:v="urn:schemas-microsoft-com:vml" xmlns:o="urn:schemas-microsoft-com:office:office" xmlns:w="urn:schemas-microsoft-com:office:word" xmlns:m="http://schemas.microsoft.com/office/2004/12/omml" xmlns="http://www.w3.org/TR/REC-html40">
<head>
<meta http-equiv="Content-Type" content="text/html; charset=us-ascii">
<meta name="Generator" content="Microsoft Word 15 (filtered medium)">
<style><!--
/* Font Definitions */
@font-face
{font-family:"Cambria Math";
panose-1:2 4 5 3 5 4 6 3 2 4;}
@font-face
{font-family:Calibri;
panose-1:2 15 5 2 2 2 4 3 2 4;}
/* Style Definitions */
p.MsoNormal, li.MsoNormal, div.MsoNormal
{margin:0in;
margin-bottom:.0001pt;
font-size:11.0pt;
font-family:"Calibri",sans-serif;}
a:link, span.MsoHyperlink
{mso-style-priority:99;
color:#0563C1;
text-decoration:underline;}
a:visited, span.MsoHyperlinkFollowed
{mso-style-priority:99;
color:#954F72;
text-decoration:underline;}
span.EmailStyle17
{mso-style-type:personal-compose;
font-family:"Calibri",sans-serif;
color:windowtext;}
.MsoChpDefault
{mso-style-type:export-only;
font-family:"Calibri",sans-serif;}
@page WordSection1
{size:8.5in 11.0in;
margin:1.0in 1.0in 1.0in 1.0in;}
div.WordSection1
{page:WordSection1;}
--></style><!--[if gte mso 9]><xml>
<o:shapedefaults v:ext="edit" spidmax="1026" />
</xml><![endif]--><!--[if gte mso 9]><xml>
<o:shapelayout v:ext="edit">
<o:idmap v:ext="edit" data="1" />
</o:shapelayout></xml><![endif]-->
</head>
<body lang="EN-US" link="#0563C1" vlink="#954F72">
<div class="WordSection1">
<p class="MsoNormal">Apologies if the format of my question is wrong; this is my first time posting to this list.<o:p></o:p></p>
<p class="MsoNormal"><o:p> </o:p></p>
<p class="MsoNormal">I am in the process of updating the look of a customer’s IdP login page, and I am having trouble successfully connecting to the LDAP server defined in ldap.properties. I should point out that the
<i>currently in-use </i>login page is login.vm, and it works flawlessly. For reasons I won’t get into, we are moving from Velocity to JSP. However, even when using the stock login.jsp page provided by the Shibboleth IdP software, LDAP contact is not being made,
so it doesn’t look like the actual JSP code is the problem. Additionally, when doing a tcpdump searching for traffic to the LDAP server, there is absolutely no traffic when using login.jsp, and a ton of traffic when using login.vm. So I just need to figure
out where in the flow that difference is being caused from. I have included what I think are relevant log lines from idp-process.log, but I have shortened a lot of it. There was so much noise that I figured it would be better to send fewer logs initially and
let whoever responds ask for specific log sections rather than just dumping literally everything in here at once. The lines highlighted in yellow indicate where it seems to me that the flow path differs between the login.jsp and login.vm attempts.<o:p></o:p></p>
<p class="MsoNormal"><o:p> </o:p></p>
<p class="MsoNormal">Thanks to anyone who can provide assistance.<o:p></o:p></p>
<p class="MsoNormal"><o:p> </o:p></p>
<p class="MsoNormal">USING LOGIN.JSP<o:p></o:p></p>
<p class="MsoNormal">-----------------------<o:p></o:p></p>
<p class="MsoNormal">2018-04-13 15:06:11,480 - DEBUG [net.shibboleth.idp.saml.profile.impl.PopulateBindingAndEndpointContexts:375] - Profile Action PopulateBindingAndEndpointContexts: Attempting to resolve endpoint of type {urn:oasis:names:tc:SAML:2.0:metadata}AssertionConsumerService
for outbound message<o:p></o:p></p>
<p class="MsoNormal">2018-04-13 15:06:11,480 - TRACE [net.shibboleth.idp.saml.profile.impl.PopulateBindingAndEndpointContexts:390] - Profile Action PopulateBindingAndEndpointContexts: Candidate outbound bindings: [urn:oasis:names:tc:SAML:2.0:bindings:HTTP-POST,
urn:oasis:names:tc:SAML:2.0:bindings:HTTP-POST-SimpleSign, urn:oasis:names:tc:SAML:2.0:bindings:HTTP-Artifact]<o:p></o:p></p>
<p class="MsoNormal">2018-04-13 15:06:11,480 - DEBUG [net.shibboleth.idp.saml.profile.impl.PopulateBindingAndEndpointContexts:516] - Profile Action PopulateBindingAndEndpointContexts: Populating template endpoint for resolution from SAML AuthnRequest<o:p></o:p></p>
<p class="MsoNormal">2018-04-13 15:06:11,480 - DEBUG [net.shibboleth.idp.saml.profile.impl.PopulateBindingAndEndpointContexts:418] - Profile Action PopulateBindingAndEndpointContexts: Resolved endpoint at location
<a href="https://example.peer.com/saml/SSO">https://example.peer.com/saml/SSO</a> using binding urn:oasis:names:tc:SAML:2.0:bindings:HTTP-POST<o:p></o:p></p>
<p class="MsoNormal">2018-04-13 15:06:11,481 - DEBUG [net.shibboleth.idp.saml.saml2.profile.delegation.impl.PopulateDelegationContext:387] - No AttributeConsumingService was resolved, won't be able to determine delegation requested status via metadata<o:p></o:p></p>
<p class="MsoNormal">2018-04-13 15:06:11,481 - DEBUG [net.shibboleth.idp.saml.saml2.profile.delegation.impl.PopulateDelegationContext:520] - No AttributeConsumingService was available<o:p></o:p></p>
<p class="MsoNormal">2018-04-13 15:06:11,481 - DEBUG [net.shibboleth.idp.saml.saml2.profile.delegation.impl.PopulateDelegationContext:505] - Delegation request was not explicitly indicated, using default value: NOT_REQUESTED<o:p></o:p></p>
<p class="MsoNormal">2018-04-13 15:06:11,481 - DEBUG [net.shibboleth.idp.saml.saml2.profile.delegation.impl.PopulateDelegationContext:294] - Issuance of a delegated Assertion is not in effect, skipping further processing<o:p></o:p></p>
<p class="MsoNormal">2018-04-13 15:06:11,483 - DEBUG [net.shibboleth.idp.saml.saml2.profile.impl.PopulateEncryptionParameters:299] - Profile Action PopulateEncryptionParameters: No encryption requested, nothing to do<o:p></o:p></p>
<p class="MsoNormal">2018-04-13 15:06:11,486 - DEBUG [net.shibboleth.idp.saml.profile.impl.ExtractSubjectFromRequest:144] - Profile Action ExtractSubjectFromRequest: No Subject NameID/NameIdentifier in message needs inbound processing<o:p></o:p></p>
<p class="MsoNormal">2018-04-13 15:06:11,487 - DEBUG [net.shibboleth.idp.saml.profile.impl.InitializeAuthenticationContext:115] - Profile Action InitializeAuthenticationContext: Created authentication context: AuthenticationContext{initiationInstant=2018-04-13T15:06:11.487-05:00,
isPassive=false, forceAuthn=false, hintedName=null, potentialFlows=[], activeResults=[], attemptedFlow=null, signaledFlowId=null, authenticationStateMap={}, resultCacheable=true, initialAuthenticationResult=null, authenticationResult=null, completionInstant=1969-12-31T18:00:00.000-06:00}<o:p></o:p></p>
<p class="MsoNormal">2018-04-13 15:06:11,488 - DEBUG [net.shibboleth.idp.session.impl.PopulateSessionContext:133] - Profile Action PopulateSessionContext: No session found for client<o:p></o:p></p>
<p class="MsoNormal">2018-04-13 15:06:11,489 - DEBUG [net.shibboleth.idp.authn.impl.PopulateAuthenticationContext:200] - Profile Action PopulateAuthenticationContext: Installed 1 potential authentication flows into AuthenticationContext<o:p></o:p></p>
<p class="MsoNormal">2018-04-13 15:06:11,489 - DEBUG [net.shibboleth.idp.authn.impl.FilterFlowsByForcedAuthn:53] - Profile Action FilterFlowsByForcedAuthn: Request does not have forced authentication requirement, nothing to do<o:p></o:p></p>
<p class="MsoNormal">2018-04-13 15:06:11,489 - DEBUG [net.shibboleth.idp.authn.impl.FilterFlowsByNonBrowserSupport:53] - Profile Action FilterFlowsByNonBrowserSupport: Request does not have non-browser requirement, nothing to do<o:p></o:p></p>
<p class="MsoNormal">2018-04-13 15:06:11,490 - DEBUG [net.shibboleth.idp.authn.impl.SelectAuthenticationFlow:255] - Profile Action SelectAuthenticationFlow: No specific Principals requested<o:p></o:p></p>
<p class="MsoNormal">2018-04-13 15:06:11,491 - DEBUG [net.shibboleth.idp.authn.impl.SelectAuthenticationFlow:290] - Profile Action SelectAuthenticationFlow: No usable active results available, selecting an inactive flow<o:p></o:p></p>
<p class="MsoNormal">2018-04-13 15:06:11,491 - DEBUG [net.shibboleth.idp.authn.impl.SelectAuthenticationFlow:338] - Profile Action SelectAuthenticationFlow: Selecting inactive authentication flow authn/Password<o:p></o:p></p>
<p class="MsoNormal"><span style="background:yellow;mso-highlight:yellow">2018-04-13 15:06:11,492 - DEBUG [net.shibboleth.idp.authn.impl.ExtractUsernamePasswordFromBasicAuth:115] - Profile Action ExtractUsernamePasswordFromBasicAuth: No appropriate Authorization
header found</span><span style="color:red"><o:p></o:p></span></p>
<p class="MsoNormal">2018-04-13 15:06:11,498 - TRACE [net.shibboleth.idp.profile.support.ProfileRequestContextFlowExecutionListener:62] - Updating ProfileRequestContext in servlet request<o:p></o:p></p>
<p class="MsoNormal"><o:p> </o:p></p>
<p class="MsoNormal">[[it is between these two lines when I submitted a username and password, but nothing showed up in the logs about it except for the line below]]<o:p></o:p></p>
<p class="MsoNormal"><b><o:p> </o:p></b></p>
<p class="MsoNormal">2018-04-13 15:06:18,997 - TRACE [net.shibboleth.idp.profile.support.ProfileRequestContextFlowExecutionListener:62] - Updating ProfileRequestContext in servlet request<o:p></o:p></p>
<p class="MsoNormal"><o:p> </o:p></p>
<p class="MsoNormal">[[Logs for this attempt end here]]<o:p></o:p></p>
<p class="MsoNormal"><o:p> </o:p></p>
<p class="MsoNormal"><o:p> </o:p></p>
<p class="MsoNormal"><o:p> </o:p></p>
<p class="MsoNormal">USING LOGIN.VM<o:p></o:p></p>
<p class="MsoNormal">-----------------------<o:p></o:p></p>
<p class="MsoNormal">2018-04-13 15:09:48,735 - DEBUG [net.shibboleth.idp.saml.profile.impl.PopulateBindingAndEndpointContexts:375] - Profile Action PopulateBindingAndEndpointContexts: Attempting to resolve endpoint of type {urn:oasis:names:tc:SAML:2.0:metadata}AssertionConsumerService
for outbound message<o:p></o:p></p>
<p class="MsoNormal">2018-04-13 15:09:48,735 - TRACE [net.shibboleth.idp.saml.profile.impl.PopulateBindingAndEndpointContexts:390] - Profile Action PopulateBindingAndEndpointContexts: Candidate outbound bindings: [urn:oasis:names:tc:SAML:2.0:bindings:HTTP-POST,
urn:oasis:names:tc:SAML:2.0:bindings:HTTP-POST-SimpleSign, urn:oasis:names:tc:SAML:2.0:bindings:HTTP-Artifact]<o:p></o:p></p>
<p class="MsoNormal">2018-04-13 15:09:48,736 - DEBUG [net.shibboleth.idp.saml.profile.impl.PopulateBindingAndEndpointContexts:516] - Profile Action PopulateBindingAndEndpointContexts: Populating template endpoint for resolution from SAML AuthnRequest<o:p></o:p></p>
<p class="MsoNormal">2018-04-13 15:09:48,737 - DEBUG [net.shibboleth.idp.saml.profile.impl.PopulateBindingAndEndpointContexts:418] - Profile Action PopulateBindingAndEndpointContexts: Resolved endpoint at location
<a href="https://example.peer.com/saml/SSO">https://example.peer.com/saml/SSO</a> using binding urn:oasis:names:tc:SAML:2.0:bindings:HTTP-POST<o:p></o:p></p>
<p class="MsoNormal">2018-04-13 15:09:48,743 - DEBUG [net.shibboleth.idp.saml.saml2.profile.delegation.impl.PopulateDelegationContext:387] - No AttributeConsumingService was resolved, won't be able to determine delegation requested status via metadata<o:p></o:p></p>
<p class="MsoNormal">2018-04-13 15:09:48,743 - DEBUG [net.shibboleth.idp.saml.saml2.profile.delegation.impl.PopulateDelegationContext:520] - No AttributeConsumingService was available<o:p></o:p></p>
<p class="MsoNormal">2018-04-13 15:09:48,743 - DEBUG [net.shibboleth.idp.saml.saml2.profile.delegation.impl.PopulateDelegationContext:505] - Delegation request was not explicitly indicated, using default value: NOT_REQUESTED<o:p></o:p></p>
<p class="MsoNormal">2018-04-13 15:09:48,744 - DEBUG [net.shibboleth.idp.saml.saml2.profile.delegation.impl.PopulateDelegationContext:294] - Issuance of a delegated Assertion is not in effect, skipping further processing<o:p></o:p></p>
<p class="MsoNormal">2018-04-13 15:09:48,768 - DEBUG [net.shibboleth.idp.saml.saml2.profile.impl.PopulateEncryptionParameters:299] - Profile Action PopulateEncryptionParameters: No encryption requested, nothing to do<o:p></o:p></p>
<p class="MsoNormal">2018-04-13 15:09:48,796 - DEBUG [net.shibboleth.idp.saml.profile.impl.ExtractSubjectFromRequest:144] - Profile Action ExtractSubjectFromRequest: No Subject NameID/NameIdentifier in message needs inbound processing<o:p></o:p></p>
<p class="MsoNormal">2018-04-13 15:09:48,818 - INFO [org.springframework.beans.factory.xml.XmlBeanDefinitionReader:317] - Loading XML bean definitions from file [/opt/shibboleth-idp/system/flows/client-storage/client-storage-read-beans.xml]<o:p></o:p></p>
<p class="MsoNormal">2018-04-13 15:09:48,825 - INFO [org.springframework.web.context.support.GenericWebApplicationContext:581] - Refreshing Flow ApplicationContext [client-storage/read]: startup date [Fri Apr 13 15:09:48 CDT 2018]; parent: WebApplicationContext
for namespace 'idp-servlet'<o:p></o:p></p>
<p class="MsoNormal">2018-04-13 15:09:48,825 - INFO [org.springframework.beans.factory.support.DefaultListableBeanFactory:874] - Replacing scope 'request' from [org.springframework.web.context.request.RequestScope@68156a12] to [org.springframework.web.context.request.RequestScope@6165edac]<o:p></o:p></p>
<p class="MsoNormal">2018-04-13 15:09:48,858 - DEBUG [net.shibboleth.idp.saml.profile.impl.InitializeAuthenticationContext:115] - Profile Action InitializeAuthenticationContext: Created authentication context: AuthenticationContext{initiationInstant=2018-04-13T15:09:48.858-05:00,
isPassive=false, forceAuthn=false, hintedName=null, potentialFlows=[], activeResults=[], attemptedFlow=null, signaledFlowId=null, authenticationStateMap={}, resultCacheable=true, initialAuthenticationResult=null, authenticationResult=null, completionInstant=1969-12-31T18:00:00.000-06:00}<o:p></o:p></p>
<p class="MsoNormal">2018-04-13 15:09:48,873 - INFO [org.springframework.beans.factory.xml.XmlBeanDefinitionReader:317] - Loading XML bean definitions from file [/opt/shibboleth-idp/system/flows/authn/authn-beans.xml]<o:p></o:p></p>
<p class="MsoNormal">2018-04-13 15:09:48,882 - INFO [org.springframework.web.context.support.GenericWebApplicationContext:581] - Refreshing Flow ApplicationContext [authn-initial]: startup date [Fri Apr 13 15:09:48 CDT 2018]; parent: WebApplicationContext for
namespace 'idp-servlet'<o:p></o:p></p>
<p class="MsoNormal">2018-04-13 15:09:48,882 - INFO [org.springframework.beans.factory.support.DefaultListableBeanFactory:874] - Replacing scope 'request' from [org.springframework.web.context.request.RequestScope@1589b47] to [org.springframework.web.context.request.RequestScope@48814b37]<o:p></o:p></p>
<p class="MsoNormal">2018-04-13 15:09:48,978 - DEBUG [net.shibboleth.idp.session.impl.PopulateSessionContext:133] - Profile Action PopulateSessionContext: No session found for client<o:p></o:p></p>
<p class="MsoNormal">2018-04-13 15:09:48,991 - DEBUG [net.shibboleth.idp.authn.impl.PopulateAuthenticationContext:200] - Profile Action PopulateAuthenticationContext: Installed 1 potential authentication flows into AuthenticationContext<o:p></o:p></p>
<p class="MsoNormal">2018-04-13 15:09:48,996 - DEBUG [net.shibboleth.idp.authn.impl.FilterFlowsByForcedAuthn:53] - Profile Action FilterFlowsByForcedAuthn: Request does not have forced authentication requirement, nothing to do<o:p></o:p></p>
<p class="MsoNormal">2018-04-13 15:09:49,001 - DEBUG [net.shibboleth.idp.authn.impl.FilterFlowsByNonBrowserSupport:53] - Profile Action FilterFlowsByNonBrowserSupport: Request does not have non-browser requirement, nothing to do<o:p></o:p></p>
<p class="MsoNormal">2018-04-13 15:09:49,006 - DEBUG [net.shibboleth.idp.authn.impl.SelectAuthenticationFlow:255] - Profile Action SelectAuthenticationFlow: No specific Principals requested<o:p></o:p></p>
<p class="MsoNormal">2018-04-13 15:09:49,007 - DEBUG [net.shibboleth.idp.authn.impl.SelectAuthenticationFlow:290] - Profile Action SelectAuthenticationFlow: No usable active results available, selecting an inactive flow<o:p></o:p></p>
<p class="MsoNormal">2018-04-13 15:09:49,007 - DEBUG [net.shibboleth.idp.authn.impl.SelectAuthenticationFlow:338] - Profile Action SelectAuthenticationFlow: Selecting inactive authentication flow authn/Password<o:p></o:p></p>
<p class="MsoNormal">2018-04-13 15:09:49,019 - INFO [org.springframework.beans.factory.xml.XmlBeanDefinitionReader:317] - Loading XML bean definitions from file [/opt/shibboleth-idp/system/flows/authn/password-authn-beans.xml]<o:p></o:p></p>
<p class="MsoNormal">2018-04-13 15:09:49,027 - INFO [org.springframework.beans.factory.xml.XmlBeanDefinitionReader:317] - Loading XML bean definitions from file [/opt/shibboleth-idp/system/flows/authn/../../../conf/authn/password-authn-config.xml]<o:p></o:p></p>
<p class="MsoNormal">2018-04-13 15:09:49,036 - INFO [org.springframework.beans.factory.xml.XmlBeanDefinitionReader:317] - Loading XML bean definitions from file [/opt/shibboleth-idp/conf/authn/ldap-authn-config.xml]<o:p></o:p></p>
<p class="MsoNormal">2018-04-13 15:09:49,041 - INFO [org.springframework.web.context.support.GenericWebApplicationContext:581] - Refreshing Flow ApplicationContext [authn/Password]: startup date [Fri Apr 13 15:09:49 CDT 2018]; parent: WebApplicationContext
for namespace 'idp-servlet'<o:p></o:p></p>
<p class="MsoNormal">2018-04-13 15:09:49,042 - INFO [org.springframework.beans.factory.support.DefaultListableBeanFactory:874] - Replacing scope 'request' from [org.springframework.web.context.request.RequestScope@737828aa] to [org.springframework.web.context.request.RequestScope@21a6360d]<o:p></o:p></p>
<p class="MsoNormal"><span style="background:yellow;mso-highlight:yellow">2018-04-13 15:09:49,216 - DEBUG [net.shibboleth.idp.authn.impl.ExtractUsernamePasswordFromBasicAuth:115] - Profile Action ExtractUsernamePasswordFromBasicAuth: No appropriate Authorization
header found</span><o:p></o:p></p>
<p class="MsoNormal">2018-04-13 15:09:49,235 - TRACE [net.shibboleth.idp.profile.support.ProfileRequestContextFlowExecutionListener:62] - Updating ProfileRequestContext in servlet request<o:p></o:p></p>
<p class="MsoNormal">2018-04-13 15:10:00,686 - TRACE [net.shibboleth.idp.profile.support.ProfileRequestContextFlowExecutionListener:62] - Updating ProfileRequestContext in servlet request<o:p></o:p></p>
<p class="MsoNormal">2018-04-13 15:10:00,698 - DEBUG [net.shibboleth.idp.authn.AbstractExtractionAction:137] - Profile Action ExtractUsernamePasswordFromFormRequest: Trimming whitespace of input string 'sso_test'<o:p></o:p></p>
<p class="MsoNormal"><o:p> </o:p></p>
<p class="MsoNormal">[[The login.jsp page doesn’t even get to the AbstractExtractionAction profile action, as it does here.]]<o:p></o:p></p>
<p class="MsoNormal"><o:p> </o:p></p>
<p class="MsoNormal">[[A lot of LDAP and other related noise was here, but I have removed it for brevity.]]<o:p></o:p></p>
<p class="MsoNormal"><o:p> </o:p></p>
<p class="MsoNormal">2018-04-13 15:10:02,957 - DEBUG [net.shibboleth.idp.profile.impl.RecordResponseComplete:89] - Profile Action RecordResponseComplete: Record response complete<o:p></o:p></p>
<p class="MsoNormal"><o:p> </o:p></p>
<p class="MsoNormal">[[Success!]]<o:p></o:p></p>
<p class="MsoNormal"><o:p> </o:p></p>
</div>
</body>
</html>