Problem with web page authentication flow

Mon Apr 16 10:43:24 EDT 2018

Apologies if the format of my question is wrong; this is my first time posting to this list.

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 currently in-use 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.

Thanks to anyone who can provide assistance.

USING LOGIN.JSP
-----------------------
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
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]
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
2018-04-13 15:06:11,480 - DEBUG [net.shibboleth.idp.saml.profile.impl.PopulateBindingAndEndpointContexts:418] - Profile Action PopulateBindingAndEndpointContexts: Resolved endpoint at location https://example.peer.com/saml/SSO using binding urn:oasis:names:tc:SAML:2.0:bindings:HTTP-POST
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
2018-04-13 15:06:11,481 - DEBUG [net.shibboleth.idp.saml.saml2.profile.delegation.impl.PopulateDelegationContext:520] - No AttributeConsumingService was available
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
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
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
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
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}
2018-04-13 15:06:11,488 - DEBUG [net.shibboleth.idp.session.impl.PopulateSessionContext:133] - Profile Action PopulateSessionContext: No session found for client
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
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
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
2018-04-13 15:06:11,490 - DEBUG [net.shibboleth.idp.authn.impl.SelectAuthenticationFlow:255] - Profile Action SelectAuthenticationFlow: No specific Principals requested
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
2018-04-13 15:06:11,491 - DEBUG [net.shibboleth.idp.authn.impl.SelectAuthenticationFlow:338] - Profile Action SelectAuthenticationFlow: Selecting inactive authentication flow authn/Password
2018-04-13 15:06:11,492 - DEBUG [net.shibboleth.idp.authn.impl.ExtractUsernamePasswordFromBasicAuth:115] - Profile Action ExtractUsernamePasswordFromBasicAuth: No appropriate Authorization header found
2018-04-13 15:06:11,498 - TRACE [net.shibboleth.idp.profile.support.ProfileRequestContextFlowExecutionListener:62] - Updating ProfileRequestContext in servlet request

[[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]]

2018-04-13 15:06:18,997 - TRACE [net.shibboleth.idp.profile.support.ProfileRequestContextFlowExecutionListener:62] - Updating ProfileRequestContext in servlet request

[[Logs for this attempt end here]]

USING LOGIN.VM
-----------------------
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
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]
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
2018-04-13 15:09:48,737 - DEBUG [net.shibboleth.idp.saml.profile.impl.PopulateBindingAndEndpointContexts:418] - Profile Action PopulateBindingAndEndpointContexts: Resolved endpoint at location https://example.peer.com/saml/SSO using binding urn:oasis:names:tc:SAML:2.0:bindings:HTTP-POST
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
2018-04-13 15:09:48,743 - DEBUG [net.shibboleth.idp.saml.saml2.profile.delegation.impl.PopulateDelegationContext:520] - No AttributeConsumingService was available
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
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
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
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
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]
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'
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 at 68156a12] to [org.springframework.web.context.request.RequestScope at 6165edac]
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}
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]
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'
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 at 1589b47] to [org.springframework.web.context.request.RequestScope at 48814b37]
2018-04-13 15:09:48,978 - DEBUG [net.shibboleth.idp.session.impl.PopulateSessionContext:133] - Profile Action PopulateSessionContext: No session found for client
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
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
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
2018-04-13 15:09:49,006 - DEBUG [net.shibboleth.idp.authn.impl.SelectAuthenticationFlow:255] - Profile Action SelectAuthenticationFlow: No specific Principals requested
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
2018-04-13 15:09:49,007 - DEBUG [net.shibboleth.idp.authn.impl.SelectAuthenticationFlow:338] - Profile Action SelectAuthenticationFlow: Selecting inactive authentication flow authn/Password
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]
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]
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]
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'
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 at 737828aa] to [org.springframework.web.context.request.RequestScope at 21a6360d]
2018-04-13 15:09:49,216 - DEBUG [net.shibboleth.idp.authn.impl.ExtractUsernamePasswordFromBasicAuth:115] - Profile Action ExtractUsernamePasswordFromBasicAuth: No appropriate Authorization header found
2018-04-13 15:09:49,235 - TRACE [net.shibboleth.idp.profile.support.ProfileRequestContextFlowExecutionListener:62] - Updating ProfileRequestContext in servlet request
2018-04-13 15:10:00,686 - TRACE [net.shibboleth.idp.profile.support.ProfileRequestContextFlowExecutionListener:62] - Updating ProfileRequestContext in servlet request
2018-04-13 15:10:00,698 - DEBUG [net.shibboleth.idp.authn.AbstractExtractionAction:137] - Profile Action ExtractUsernamePasswordFromFormRequest: Trimming whitespace of input string 'sso_test'

[[The login.jsp page doesn't even get to the AbstractExtractionAction profile action, as it does here.]]

[[A lot of LDAP and other related noise was here, but I have removed it for brevity.]]

2018-04-13 15:10:02,957 - DEBUG [net.shibboleth.idp.profile.impl.RecordResponseComplete:89] - Profile Action RecordResponseComplete: Record response complete

[[Success!]]

-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://shibboleth.net/pipermail/users/attachments/20180416/22469215/attachment.html>