Shibboleth IDP 3 as CAS Server and Saml11TicketValidator

Dimitris Maniadakis chaniadimitris at yahoo.gr
Wed Nov 8 04:59:46 EST 2017 

Hello,
we have enabled CAS protocol in our IdP Shibboleth 3.3.0 according to instructions in https://wiki.shibboleth.net/confluence/display/IDP30/CasProtocolConfiguration
We have tested successfully that it works with a phpCAS client (1.3.5).
So far, so good.

However, we now want to use a web application which relies on an old java CAS client and it cannot successfully work with our IdP.
Specifically, the client is cas-client-core-3.2.1.jar.

My main question is: Is there any known issue between that CAS client version and IdP Shibboleth 3.3.0 ?
I have seen similar problems in the list i.e. http://shibboleth.net/pipermail/users/2015-September/023913.html where Saml11TicketValidator was reported to cause problem.

I quote the idp-process.log part (having enabled DEBUG mode in most components). As you may see, the process stops just before validation step.

DEBUG [net.shibboleth.idp.cas.flow.impl.GrantServiceTicketAction:107] - Granting service ticket for http://XXXXXXXX/j_spring_cas_security_check
DEBUG [net.shibboleth.idp.cas.ticket.impl.AbstractTicketService:187] - Storing ST-1510128430419-MAxoD6L6nLi1LFofMbBfOgUvy in context https://www.apereo.org/cas/protocol/login
INFO [net.shibboleth.idp.cas.flow.impl.GrantServiceTicketAction:123] - Granted service ticket for http://XXXXXXXX/j_spring_cas_security_check
DEBUG [org.springframework.webflow.execution.ActionExecutor:53] - Finished executing net.shibboleth.idp.cas.flow.impl.GrantServiceTicketAction at 16e6784f; result = null
DEBUG [org.springframework.webflow.execution.AnnotatedAction:149] - Clearing action execution attributes map[[empty]]
DEBUG [org.springframework.webflow.execution.ActionExecutor:53] - Finished executing [EvaluateAction at 203395da expression = GrantServiceTicket, resultExpression = [null]]; result = null
DEBUG [org.springframework.webflow.engine.ActionState:120] - Action execution [1] returned a [null] event: proceeding to the next action in the list
DEBUG [org.springframework.webflow.execution.ActionExecutor:49] - Executing [EvaluateAction at 2b465abd expression = PublishProtocolResponse, resultExpression = [null]]
DEBUG [org.springframework.webflow.execution.AnnotatedAction:142] - Putting action execution attributes map[[empty]]
DEBUG [org.springframework.beans.factory.support.DefaultListableBeanFactory:251] - Returning cached instance of singleton bean 'PublishProtocolResponse'
DEBUG [org.springframework.webflow.execution.ActionExecutor:49] - Executing net.shibboleth.idp.cas.flow.impl.PublishProtocolMessageAction at 3435cf80
DEBUG [org.springframework.webflow.execution.ActionExecutor:53] - Finished executing net.shibboleth.idp.cas.flow.impl.PublishProtocolMessageAction at 3435cf80; result = null
DEBUG [org.springframework.webflow.execution.AnnotatedAction:149] - Clearing action execution attributes map[[empty]]
DEBUG [org.springframework.webflow.execution.ActionExecutor:53] - Finished executing [EvaluateAction at 2b465abd expression = PublishProtocolResponse, resultExpression = [null]]; result = null
DEBUG [org.springframework.webflow.engine.ActionState:120] - Action execution [2] returned a [null] event: proceeding to the next action in the list
DEBUG [org.springframework.webflow.execution.ActionExecutor:49] - Executing [EvaluateAction at 1801f457 expression = PopulateOutboundInterceptContext, resultExpression = [null]]
DEBUG [org.springframework.webflow.execution.AnnotatedAction:142] - Putting action execution attributes map[[empty]]
DEBUG [org.springframework.beans.factory.support.DefaultListableBeanFactory:448] - Creating instance of bean 'PopulateOutboundInterceptContext'
DEBUG [org.springframework.beans.factory.support.DefaultListableBeanFactory:448] - Creating instance of bean 'net.shibboleth.idp.profile.config.navigate.OutboundFlowsLookupFunction#69ca560a'
DEBUG [org.springframework.beans.factory.support.DefaultListableBeanFactory:1669] - No default init method named 'initialize' found on bean with name 'net.shibboleth.idp.profile.config.navigate.OutboundFlowsLookupFunction#69ca560a'
DEBUG [org.springframework.beans.factory.support.DefaultListableBeanFactory:484] - Finished creating instance of bean 'net.shibboleth.idp.profile.config.navigate.OutboundFlowsLookupFunction#69ca560a'
DEBUG [org.springframework.beans.factory.support.DefaultListableBeanFactory:251] - Returning cached instance of singleton bean 'shibboleth.AvailableInterceptFlows'
DEBUG [org.springframework.beans.factory.support.DefaultListableBeanFactory:1678] - Invoking init method  'initialize' on bean with name 'PopulateOutboundInterceptContext'
DEBUG [org.springframework.beans.factory.support.DefaultListableBeanFactory:484] - Finished creating instance of bean 'PopulateOutboundInterceptContext'
DEBUG [org.springframework.webflow.execution.ActionExecutor:49] - Executing net.shibboleth.idp.profile.interceptor.impl.PopulateProfileInterceptorContext at 649250a8
DEBUG [org.springframework.webflow.execution.ActionExecutor:53] - Finished executing net.shibboleth.idp.profile.interceptor.impl.PopulateProfileInterceptorContext at 649250a8; result = null
DEBUG [org.springframework.webflow.execution.AnnotatedAction:149] - Clearing action execution attributes map[[empty]]
DEBUG [org.springframework.webflow.execution.ActionExecutor:53] - Finished executing [EvaluateAction at 1801f457 expression = PopulateOutboundInterceptContext, resultExpression = [null]]; result = null
DEBUG [org.springframework.webflow.engine.ActionState:120] - Action execution [3] returned a [null] event: proceeding to the next action in the list
DEBUG [org.springframework.webflow.execution.ActionExecutor:49] - Executing [EvaluateAction at 71e78c30 expression = PopulateClientStorageSaveContext, resultExpression = [null]]
DEBUG [org.springframework.webflow.execution.AnnotatedAction:142] - Putting action execution attributes map[[empty]]
DEBUG [org.springframework.beans.factory.support.DefaultListableBeanFactory:448] - Creating instance of bean 'PopulateClientStorageSaveContext'
DEBUG [org.springframework.beans.factory.support.DefaultListableBeanFactory:251] - Returning cached instance of singleton bean 'shibboleth.ClientStorageServices'
DEBUG [org.springframework.beans.factory.support.DefaultListableBeanFactory:1678] - Invoking init method  'initialize' on bean with name 'PopulateClientStorageSaveContext'
DEBUG [org.springframework.beans.factory.support.DefaultListableBeanFactory:484] - Finished creating instance of bean 'PopulateClientStorageSaveContext'
DEBUG [org.springframework.webflow.execution.ActionExecutor:49] - Executing net.shibboleth.idp.profile.impl.WebFlowProfileActionAdaptor at 3789b352
DEBUG [org.springframework.webflow.execution.ActionExecutor:53] - Finished executing net.shibboleth.idp.profile.impl.WebFlowProfileActionAdaptor at 3789b352; result = NoSaveNeeded
DEBUG [org.springframework.webflow.execution.AnnotatedAction:149] - Clearing action execution attributes map[[empty]]
DEBUG [org.springframework.webflow.execution.ActionExecutor:53] - Finished executing [EvaluateAction at 71e78c30 expression = PopulateClientStorageSaveContext, resultExpression = [null]]; result = NoSaveNeeded
DEBUG [org.springframework.webflow.execution.ActionExecutor:49] - Executing [SetAction at 3a8d7881 name = flowScope.redirectUrl, value = flowScope.serviceTicketResponse.redirectUrl]
DEBUG [org.springframework.webflow.execution.AnnotatedAction:142] - Putting action execution attributes map[[empty]]
DEBUG [org.springframework.webflow.execution.AnnotatedAction:149] - Clearing action execution attributes map[[empty]]
DEBUG [org.springframework.webflow.execution.ActionExecutor:53] - Finished executing [SetAction at 3a8d7881 name = flowScope.redirectUrl, value = flowScope.serviceTicketResponse.redirectUrl]; result = success
DEBUG [org.springframework.webflow.engine.Transition:214] - Executing [Transition at 50d888d6 on = NoSaveNeeded, to = CheckOutboundInterceptContext]
DEBUG [org.springframework.webflow.engine.Transition:222] - Exiting state 'GrantServiceTicket'
DEBUG [org.springframework.webflow.engine.DecisionState:189] - Entering state 'CheckOutboundInterceptContext' of flow 'cas/login'
DEBUG [org.springframework.webflow.engine.Transition:214] - Executing [Transition at 216c5379 on = opensamlProfileRequestContext.getSubcontext(T(net.shibboleth.idp.profile.context.ProfileInterceptorContext)).getAvailableFlows().isEmpty(), to = ReturnToService]
DEBUG [org.springframework.webflow.engine.Transition:222] - Exiting state 'CheckOutboundInterceptContext'
DEBUG [org.springframework.webflow.engine.DecisionState:189] - Entering state 'ReturnToService' of flow 'cas/login'
DEBUG [org.springframework.webflow.engine.Transition:214] - Executing [Transition at 6839db2e on = *, to = RedirectToService]
DEBUG [org.springframework.webflow.engine.Transition:222] - Exiting state 'ReturnToService'
DEBUG [org.springframework.webflow.engine.EndState:189] - Entering state 'RedirectToService' of flow 'cas/login'
DEBUG [org.springframework.webflow.execution.ActionExecutor:49] - Executing [EvaluateAction at 2376871c expression = PopulateAuditContext, resultExpression = [null]]
DEBUG [org.springframework.webflow.execution.AnnotatedAction:142] - Putting action execution attributes map[[empty]]
DEBUG [org.springframework.beans.factory.support.DefaultListableBeanFactory:448] - Creating instance of bean 'PopulateAuditContext'
DEBUG [org.springframework.beans.factory.support.DefaultListableBeanFactory:251] - Returning cached instance of singleton bean 'shibboleth.AuditFormattingMap'
DEBUG [org.springframework.beans.factory.support.DefaultListableBeanFactory:251] - Returning cached instance of singleton bean 'shibboleth.DefaultCASLoginAuditExtractors'
DEBUG [org.springframework.beans.factory.support.DefaultListableBeanFactory:1678] - Invoking init method  'initialize' on bean with name 'PopulateAuditContext'
DEBUG [org.springframework.beans.factory.support.DefaultListableBeanFactory:484] - Finished creating instance of bean 'PopulateAuditContext'
DEBUG [org.springframework.webflow.execution.ActionExecutor:49] - Executing net.shibboleth.idp.profile.audit.impl.PopulateAuditContext at 74485f91
DEBUG [org.springframework.webflow.execution.ActionExecutor:53] - Finished executing net.shibboleth.idp.profile.audit.impl.PopulateAuditContext at 74485f91; result = null
DEBUG [org.springframework.webflow.execution.AnnotatedAction:149] - Clearing action execution attributes map[[empty]]
DEBUG [org.springframework.webflow.execution.ActionExecutor:53] - Finished executing [EvaluateAction at 2376871c expression = PopulateAuditContext, resultExpression = [null]]; result = null
DEBUG [org.springframework.webflow.execution.ActionExecutor:49] - Executing [EvaluateAction at 13d1b444 expression = WriteAuditLog, resultExpression = [null]]
DEBUG [org.springframework.webflow.execution.AnnotatedAction:142] - Putting action execution attributes map[[empty]]
DEBUG [org.springframework.beans.factory.support.DefaultListableBeanFactory:448] - Creating instance of bean 'WriteAuditLog'
DEBUG [org.springframework.beans.factory.support.DefaultListableBeanFactory:251] - Returning cached instance of singleton bean 'shibboleth.AuditFormattingMap'
DEBUG [org.springframework.beans.factory.support.DefaultListableBeanFactory:251] - Returning cached instance of singleton bean 'shibboleth.HttpServletRequest'
DEBUG [org.springframework.beans.factory.support.DefaultListableBeanFactory:1678] - Invoking init method  'initialize' on bean with name 'WriteAuditLog'
DEBUG [org.springframework.beans.factory.support.DefaultListableBeanFactory:484] - Finished creating instance of bean 'WriteAuditLog'
DEBUG [org.springframework.webflow.execution.ActionExecutor:49] - Executing net.shibboleth.idp.profile.audit.impl.WriteAuditLog at 2553d578
INFO [Shibboleth-Audit.SSO:241] - 20171108T080710Z|||http://XXXXXXXX/j_spring_cas_security_check|https://www.apereo.org/cas/protocol/login||||YYYYYYYY|||YYYYYYYY|ST-1510128430419-MAxoD6L6nLi1LFofMbBfOgUvy|
DEBUG [org.springframework.webflow.execution.ActionExecutor:53] - Finished executing net.shibboleth.idp.profile.audit.impl.WriteAuditLog at 2553d578; result = null
DEBUG [org.springframework.webflow.execution.AnnotatedAction:149] - Clearing action execution attributes map[[empty]]
DEBUG [org.springframework.webflow.execution.ActionExecutor:53] - Finished executing [EvaluateAction at 13d1b444 expression = WriteAuditLog, resultExpression = [null]]; result = null
DEBUG [org.springframework.webflow.execution.ActionExecutor:49] - Executing org.springframework.webflow.action.ViewFactoryActionAdapter at 77840d6e
DEBUG [org.springframework.webflow.execution.ActionExecutor:49] - Executing org.springframework.webflow.action.ExternalRedirectAction at 7037d10d
DEBUG [org.springframework.webflow.execution.ActionExecutor:53] - Finished executing org.springframework.webflow.action.ExternalRedirectAction at 7037d10d; result = success
DEBUG [org.springframework.webflow.execution.ActionExecutor:53] - Finished executing org.springframework.webflow.action.ViewFactoryActionAdapter at 77840d6e; result = success
DEBUG [org.springframework.webflow.engine.Transition:235] - Completed transition execution.  As a result, the flow execution has ended
DEBUG [org.springframework.webflow.engine.Transition:235] - Completed transition execution.  As a result, the flow execution has ended
DEBUG [org.springframework.webflow.engine.Transition:235] - Completed transition execution.  As a result, the flow execution has ended
DEBUG [org.springframework.webflow.engine.Transition:235] - Completed transition execution.  As a result, the flow execution has ended
DEBUG [org.springframework.webflow.engine.Transition:235] - Completed transition execution.  As a result, the flow execution has ended
DEBUG [org.springframework.webflow.engine.Transition:235] - Completed transition execution.  As a result, the flow execution has ended
DEBUG [org.springframework.webflow.engine.Transition:235] - Completed transition execution.  As a result, the flow execution has ended
DEBUG [org.springframework.webflow.engine.Transition:235] - Completed transition execution.  As a result, the flow execution has ended
DEBUG [org.springframework.webflow.engine.Transition:235] - Completed transition execution.  As a result, the flow execution has ended
DEBUG [org.springframework.webflow.engine.Transition:235] - Completed transition execution.  As a result, the flow execution has ended
DEBUG [org.springframework.webflow.engine.Transition:235] - Completed transition execution.  As a result, the flow execution has ended
DEBUG [org.springframework.webflow.engine.Transition:235] - Completed transition execution.  As a result, the flow execution has ended
DEBUG [org.springframework.webflow.engine.Transition:235] - Completed transition execution.  As a result, the flow execution has ended
DEBUG [org.springframework.webflow.engine.Transition:235] - Completed transition execution.  As a result, the flow execution has ended
DEBUG [org.springframework.webflow.engine.Transition:235] - Completed transition execution.  As a result, the flow execution has ended
DEBUG [org.springframework.webflow.engine.Transition:235] - Completed transition execution.  As a result, the flow execution has ended
DEBUG [org.springframework.webflow.engine.Transition:235] - Completed transition execution.  As a result, the flow execution has ended
DEBUG [org.springframework.webflow.engine.Transition:235] - Completed transition execution.  As a result, the flow execution has ended
DEBUG [org.springframework.webflow.engine.Transition:235] - Completed transition execution.  As a result, the flow execution has ended
DEBUG [org.springframework.webflow.engine.Transition:235] - Completed transition execution.  As a result, the flow execution has ended
DEBUG [org.springframework.webflow.execution.repository.impl.DefaultFlowExecutionRepository:131] - Removing flow execution '[Ended execution of 'cas/login']' from repository
DEBUG [org.springframework.webflow.conversation.impl.SessionBindingConversationManager:100] - Ending conversation 1
DEBUG [org.springframework.webflow.conversation.impl.SessionBindingConversationManager:107] - Unlocking conversation 1
DEBUG [org.springframework.webflow.mvc.servlet.FlowHandlerAdapter:495] - Sending external redirect to 'http://XXXXXXXX/j_spring_cas_security_check?ticket=ST-1510128430419-MAxoD6L6nLi1LFofMbBfOgUvy'
DEBUG [org.springframework.web.servlet.DispatcherServlet:1044] - Null ModelAndView returned to DispatcherServlet with name 'idp': assuming HandlerAdapter completed request handling
DEBUG [org.springframework.web.servlet.DispatcherServlet:1000] - Successfully completed request

And stops at this point.

Log file from the client includes:
[ajp-nio-8009-exec-1] DEBUG o.j.c.c.s.SingleSignOutHandler - Recording session for token ST-1510128430419-MAxoD6L6nLi1LFofMbBfOgUvy
[ajp-nio-8009-exec-1] DEBUG o.j.c.c.s.HashMapBackedSessionMappingStorage - Attempting to remove Session=[9CD45B6E9E0DFFF81FFEED78D363ED21]
[ajp-nio-8009-exec-1] DEBUG o.j.c.c.s.HashMapBackedSessionMappingStorage - No mapping for session found.  Ignoring.
[ajp-nio-8009-exec-1] DEBUG o.j.c.c.v.Saml11TicketValidator - Placing URL parameters in map.
[ajp-nio-8009-exec-1] DEBUG o.j.c.c.v.Saml11TicketValidator - Calling template URL attribute map.
[ajp-nio-8009-exec-1] DEBUG o.j.c.c.v.Saml11TicketValidator - Loading custom parameters from configuration.
[ajp-nio-8009-exec-1] DEBUG o.j.c.c.v.Saml11TicketValidator - Constructing validation url: https://ZZZZZZZZZ/samlValidate?TARGET=http%3A%2F%2FXXXXXXXX%2Fj_spring_cas_security_check
[ajp-nio-8009-exec-1] DEBUG o.j.c.c.v.Saml11TicketValidator - Retrieving response from server.


After some seconds of waiting, the browser shows an error:

HTTP Status 500 - java.net.ConnectException: Connection timed out (Connection timed out)
type Exception report
message java.net.ConnectException: Connection timed out (Connection timed out)
description The server encountered an internal error that prevented it from fulfilling this request.
exception
java.lang.RuntimeException: java.net.ConnectException: Connection timed out (Connection timed out)
    org.jasig.cas.client.validation.Saml11TicketValidator.retrieveResponseFromServer(Saml11TicketValidator.java:231)
    org.jasig.cas.client.validation.AbstractUrlBasedTicketValidator.validate(AbstractUrlBasedTicketValidator.java:207)
    org.springframework.security.cas.authentication.CasAuthenticationProvider.authenticateNow(CasAuthenticationProvider.java:140)
    org.springframework.security.cas.authentication.CasAuthenticationProvider.authenticate(CasAuthenticationProvider.java:126)
    org.springframework.security.authentication.ProviderManager.authenticate(ProviderManager.java:156)
    org.springframework.security.cas.web.CasAuthenticationFilter.attemptAuthentication(CasAuthenticationFilter.java:242)
    org.springframework.security.web.authentication.AbstractAuthenticationProcessingFilter.doFilter(AbstractAuthenticationProcessingFilter.java:211)
    org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:342)
    org.jasig.cas.client.session.SingleSignOutFilter.doFilter(SingleSignOutFilter.java:76)
    org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:342)
    org.springframework.security.web.authentication.logout.LogoutFilter.doFilter(LogoutFilter.java:110)
    org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:342)
    org.springframework.security.web.authentication.logout.LogoutFilter.doFilter(LogoutFilter.java:110)
    org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:342)
    org.springframework.security.web.context.request.async.WebAsyncManagerIntegrationFilter.doFilterInternal(WebAsyncManagerIntegrationFilter.java:50)
    org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
    org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:342)
    org.springframework.security.web.context.SecurityContextPersistenceFilter.doFilter(SecurityContextPersistenceFilter.java:87)
    org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:342)
    org.springframework.security.web.authentication.AbstractAuthenticationProcessingFilter.doFilter(AbstractAuthenticationProcessingFilter.java:199)
    org.gunet.dilosdlm.security.tokenauth.CustomTokenAuthenticationFilter.doFilter(CustomTokenAuthenticationFilter.java:85)
    org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:342)
    org.springframework.security.web.FilterChainProxy.doFilterInternal(FilterChainProxy.java:192)
    org.springframework.security.web.FilterChainProxy.doFilter(FilterChainProxy.java:160)
    org.springframework.web.filter.DelegatingFilterProxy.invokeDelegate(DelegatingFilterProxy.java:343)
    org.springframework.web.filter.DelegatingFilterProxy.doFilter(DelegatingFilterProxy.java:260)
    org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:88)
    org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
    com.thetransactioncompany.cors.CORSFilter.doFilter(CORSFilter.java:168)
    com.thetransactioncompany.cors.CORSFilter.doFilter(CORSFilter.java:233)
    
P.S. Unfortunately I cannot update the java CAS client to a newer version because the web application is based on that particular version.
    
Thank you,
Dimitris
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://shibboleth.net/pipermail/users/attachments/20171108/2a1e11a8/attachment-0001.html>

More information about the users mailing list