UnauthorizedServiceException due to mismatched ACS Url

[Peter Barnes]

We recently had an issue with a service provider generating errors for an unauthorized service that we could not identify.

When performing SSO if there was no established session on cas the user could successfully authenticate and the SSO flow would successfully complete for the SP. However if there was already an established cas session i.e. the user already logging into a different SP, when attempting SSO for the initial SP it generates the unauthorized service error.

In both cases the flow is started using SP initiated using the exact same url.

There were no errors/warnings in the cas logs to give any indication as to what was at fault, it wasn't until we enabled debug logging that we found the following.

Resolved [org.apereo.cas.support.saml.SamlException: Assertion consumer service [https://xxxxxxxxxxx/saml2/auth/login] cannot be located in metadata [[https://xxxxxxxxx/employee/saml2/post]]] to ModelAndView [view="casServiceErrorView"; model={rootCauseException=org.apereo.cas.services.UnauthorizedServiceException: }]

Using this we identified that the consumer url in the saml request did not match the consumer url in the metadata and we were able to workaround the issue.

What we cannot identify is

1. Why is the behavior different based on existing/new session
2. Why is this not logged anywhere as an error? Using debug logging to find this is not practical

Cas Version: 6.3.5

Assumed location of original error: SamlIdpUtils#207

[Ray Bon]

Peter,

You can use samltracer to see the saml being sent. You can verify the ACS.

If the ACS in the request does not match the metadata, the unauthorized service error should always be thrown. 

It should be logged at warn, I would think.

Ray

On Fri, 2022-01-07 at 05:17 -0800, Peter Barnes wrote:

Notice: This message was sent from outside the University of Victoria email system. Please be cautious with links and sensitive information.

[Peter Barnes]

Ray,

Based on enabling debug logging i know that the urls did not match, the issue two fold

1) The error is suppressed and not logged anywhere (without debug logging)

2) The behavior is different based on the existence of a session

When we first identified this is was on a QA environment so it was not possible to attach a debugger to get the stack trace, however i have now done it locally. The following is the stacktrace when there is an existing idp session, when using the debugger to catch the exception and step forward there is no catch block that logs the message, so this is effectively swallowed.

Steps to reproduce

Case #1

1.  Configure Cas with Two saml Services
   
   1. Purposefully edit the SP metadata of the second service and change the consumer service url
2. login to SP 1 using sp initiated sso
3. Attempt to login to SP 2 using sp initiated SSO

Result

Unauthorized service exception is displayed but no error logged

Case #2

Note: Ensure that this is a clear setup, or that all test users are logged out from Cas before proceeding, this case requires there to be no existing sessions in cas.

1.  Configure Cas with Two saml Services
   
   1. Purposefully edit the SP metadata of the second service and change the consumer service url
2. Login to SP 2 using sp initiated SSO

Result

User is able to login to the SP despite the ACS url mismatch

invokeMethod:285, ReflectionUtils (org.springframework.util)

invoke:499, GenericScope$LockedScopedProxyFactoryBean (org.springframework.cloud.context.scope)

proceed:186, ReflectiveMethodInvocation (org.springframework.aop.framework)

invoke:212, JdkDynamicAopProxy (org.springframework.aop.framework)

build:-1, $Proxy287 (com.sun.proxy)

build:97, SamlProfileSamlAssertionBuilder (org.apereo.cas.support.saml.web.idp.profile.builders.assertion)

build:37, SamlProfileSamlAssertionBuilder (org.apereo.cas.support.saml.web.idp.profile.builders.assertion)

invoke:-1, GeneratedMethodAccessor303 (jdk.internal.reflect)

invoke:43, DelegatingMethodAccessorImpl (jdk.internal.reflect)

invoke:566, Method (java.lang.reflect)

invokeMethod:282, ReflectionUtils (org.springframework.util)

invoke:499, GenericScope$LockedScopedProxyFactoryBean (org.springframework.cloud.context.scope)

proceed:186, ReflectiveMethodInvocation (org.springframework.aop.framework)

invoke:212, JdkDynamicAopProxy (org.springframework.aop.framework)

build:-1, $Proxy287 (com.sun.proxy)

buildSamlAssertion:128, BaseSamlProfileSamlResponseBuilder (org.apereo.cas.support.saml.web.idp.profile.builders.response)

build:61, BaseSamlProfileSamlResponseBuilder (org.apereo.cas.support.saml.web.idp.profile.builders.response)

invoke:-1, BaseSamlProfileSamlResponseBuilder$$FastClassBySpringCGLIB$$f1322d9c (org.apereo.cas.support.saml.web.idp.profile.builders.response)

invoke:218, MethodProxy (org.springframework.cglib.proxy)

invokeJoinpoint:771, CglibAopProxy$CglibMethodInvocation (org.springframework.aop.framework)

proceed:163, ReflectiveMethodInvocation (org.springframework.aop.framework)

proceed:749, CglibAopProxy$CglibMethodInvocation (org.springframework.aop.framework)

proceed:88, MethodInvocationProceedingJoinPoint (org.springframework.aop.aspectj)

handleAuditTrail:135, AuditTrailManagementAspect (org.apereo.inspektr.audit)

invoke:-1, GeneratedMethodAccessor234 (jdk.internal.reflect)

invoke:43, DelegatingMethodAccessorImpl (jdk.internal.reflect)

invoke:566, Method (java.lang.reflect)

invokeAdviceMethodWithGivenArgs:644, AbstractAspectJAdvice (org.springframework.aop.aspectj)

invokeAdviceMethod:633, AbstractAspectJAdvice (org.springframework.aop.aspectj)

invoke:70, AspectJAroundAdvice (org.springframework.aop.aspectj)

proceed:175, ReflectiveMethodInvocation (org.springframework.aop.framework)

proceed:749, CglibAopProxy$CglibMethodInvocation (org.springframework.aop.framework)

invoke:95, ExposeInvocationInterceptor (org.springframework.aop.interceptor)

proceed:186, ReflectiveMethodInvocation (org.springframework.aop.framework)

proceed:749, CglibAopProxy$CglibMethodInvocation (org.springframework.aop.framework)

intercept:691, CglibAopProxy$DynamicAdvisedInterceptor (org.springframework.aop.framework)

build:-1, SamlProfileSaml2ResponseBuilder$$EnhancerBySpringCGLIB$$19327656 (org.apereo.cas.support.saml.web.idp.profile.builders.response)

invoke:-1, GeneratedMethodAccessor303 (jdk.internal.reflect)

invoke:43, DelegatingMethodAccessorImpl (jdk.internal.reflect)

invoke:566, Method (java.lang.reflect)

invokeMethod:282, ReflectionUtils (org.springframework.util)

invoke:499, GenericScope$LockedScopedProxyFactoryBean (org.springframework.cloud.context.scope)

proceed:186, ReflectiveMethodInvocation (org.springframework.aop.framework)

invoke:212, JdkDynamicAopProxy (org.springframework.aop.framework)

build:-1, $Proxy287 (com.sun.proxy)

buildSamlResponse:565, AbstractSamlIdPProfileHandlerController (org.apereo.cas.support.saml.web.idp.profile)

initiateAuthenticationRequest:463, AbstractSamlIdPProfileHandlerController (org.apereo.cas.support.saml.web.idp.profile)

handleSsoPostProfileRequest:88, SSOSamlIdPPostProfileHandlerController (org.apereo.cas.support.saml.web.idp.profile.sso)

handleSaml2ProfileSsoRedirectRequest:44, SSOSamlIdPPostProfileHandlerController (org.apereo.cas.support.saml.web.idp.profile.sso)

invoke0:-1, NativeMethodAccessorImpl (jdk.internal.reflect)

invoke:62, NativeMethodAccessorImpl (jdk.internal.reflect)

invoke:43, DelegatingMethodAccessorImpl (jdk.internal.reflect)

invoke:566, Method (java.lang.reflect)

invokeMethod:282, ReflectionUtils (org.springframework.util)

invoke:499, GenericScope$LockedScopedProxyFactoryBean (org.springframework.cloud.context.scope)

proceed:186, ReflectiveMethodInvocation (org.springframework.aop.framework)

proceed:749, CglibAopProxy$CglibMethodInvocation (org.springframework.aop.framework)

intercept:691, CglibAopProxy$DynamicAdvisedInterceptor (org.springframework.aop.framework)

handleSaml2ProfileSsoRedirectRequest:-1, SSOSamlIdPPostProfileHandlerController$$EnhancerBySpringCGLIB$$7fe7ef0 (org.apereo.cas.support.saml.web.idp.profile.sso)

invoke0:-1, NativeMethodAccessorImpl (jdk.internal.reflect)

invoke:62, NativeMethodAccessorImpl (jdk.internal.reflect)

invoke:43, DelegatingMethodAccessorImpl (jdk.internal.reflect)

invoke:566, Method (java.lang.reflect)

doInvoke:190, InvocableHandlerMethod (org.springframework.web.method.support)

invokeForRequest:138, InvocableHandlerMethod (org.springframework.web.method.support)

invokeAndHandle:105, ServletInvocableHandlerMethod (org.springframework.web.servlet.mvc.method.annotation)

invokeHandlerMethod:878, RequestMappingHandlerAdapter (org.springframework.web.servlet.mvc.method.annotation)

handleInternal:792, RequestMappingHandlerAdapter (org.springframework.web.servlet.mvc.method.annotation)

handle:87, AbstractHandlerMethodAdapter (org.springframework.web.servlet.mvc.method)

doDispatch:1040, DispatcherServlet (org.springframework.web.servlet)

doService:943, DispatcherServlet (org.springframework.web.servlet)

processRequest:1006, FrameworkServlet (org.springframework.web.servlet)

doGet:898, FrameworkServlet (org.springframework.web.servlet)

service:655, HttpServlet (javax.servlet.http)

service:883, FrameworkServlet (org.springframework.web.servlet)

service:764, HttpServlet (javax.servlet.http)

internalDoFilter:227, ApplicationFilterChain (org.apache.catalina.core)

doFilter:162, ApplicationFilterChain (org.apache.catalina.core)

doFilter:80, PodForwarderFilter (zeyt.wfr.pod)

internalDoFilter:189, ApplicationFilterChain (org.apache.catalina.core)

doFilter:162, ApplicationFilterChain (org.apache.catalina.core)

doFilter:28, AuthenticationCredentialsThreadLocalBinderClearingFilter (org.apereo.cas.web.support)

internalDoFilter:189, ApplicationFilterChain (org.apache.catalina.core)

doFilter:162, ApplicationFilterChain (org.apache.catalina.core)

doFilter:401, RequestParameterPolicyEnforcementFilter (org.apereo.cas.web.support.filters)

internalDoFilter:189, ApplicationFilterChain (org.apache.catalina.core)

doFilter:162, ApplicationFilterChain (org.apache.catalina.core)

doFilter:200, ResponseHeadersEnforcementFilter (org.apereo.cas.web.support.filters)

internalDoFilter:189, ApplicationFilterChain (org.apache.catalina.core)

doFilter:162, ApplicationFilterChain (org.apache.catalina.core)

doFilter:64, AddResponseHeadersFilter (org.apereo.cas.web.support.filters)

internalDoFilter:189, ApplicationFilterChain (org.apache.catalina.core)

doFilter:162, ApplicationFilterChain (org.apache.catalina.core)

doFilterInternal:204, FilterChainProxy (org.springframework.security.web)

doFilter:183, FilterChainProxy (org.springframework.security.web)

invokeDelegate:358, DelegatingFilterProxy (org.springframework.web.filter)

doFilter:271, DelegatingFilterProxy (org.springframework.web.filter)

internalDoFilter:189, ApplicationFilterChain (org.apache.catalina.core)

doFilter:162, ApplicationFilterChain (org.apache.catalina.core)

doFilterInternal:100, RequestContextFilter (org.springframework.web.filter)

doFilter:119, OncePerRequestFilter (org.springframework.web.filter)

internalDoFilter:189, ApplicationFilterChain (org.apache.catalina.core)

doFilter:162, ApplicationFilterChain (org.apache.catalina.core)

doFilterInternal:93, FormContentFilter (org.springframework.web.filter)

doFilter:119, OncePerRequestFilter (org.springframework.web.filter)

internalDoFilter:189, ApplicationFilterChain (org.apache.catalina.core)

doFilter:162, ApplicationFilterChain (org.apache.catalina.core)

doFilterInternal:93, WebMvcMetricsFilter (org.springframework.boot.actuate.metrics.web.servlet)

doFilter:119, OncePerRequestFilter (org.springframework.web.filter)

internalDoFilter:189, ApplicationFilterChain (org.apache.catalina.core)

doFilter:162, ApplicationFilterChain (org.apache.catalina.core)

doFilter:99, ThreadContextMDCServletFilter (org.apereo.cas.logging.web)

internalDoFilter:189, ApplicationFilterChain (org.apache.catalina.core)

doFilter:162, ApplicationFilterChain (org.apache.catalina.core)

doFilter:66, ClientInfoThreadLocalFilter (org.apereo.inspektr.common.web)

internalDoFilter:189, ApplicationFilterChain (org.apache.catalina.core)

doFilter:162, ApplicationFilterChain (org.apache.catalina.core)

doFilterInternal:201, CharacterEncodingFilter (org.springframework.web.filter)

doFilter:119, OncePerRequestFilter (org.springframework.web.filter)

internalDoFilter:189, ApplicationFilterChain (org.apache.catalina.core)

doFilter:162, ApplicationFilterChain (org.apache.catalina.core)

invoke:197, StandardWrapperValve (org.apache.catalina.core)

invoke:97, StandardContextValve (org.apache.catalina.core)

invoke:540, AuthenticatorBase (org.apache.catalina.authenticator)

invoke:135, StandardHostValve (org.apache.catalina.core)

invoke:92, ErrorReportValve (org.apache.catalina.valves)

invoke:78, StandardEngineValve (org.apache.catalina.core)

invoke:687, AbstractAccessLogValve (org.apache.catalina.valves)

invoke:769, RemoteIpValve (org.apache.catalina.valves)

service:357, CoyoteAdapter (org.apache.catalina.connector)

service:382, Http11Processor (org.apache.coyote.http11)

process:65, AbstractProcessorLight (org.apache.coyote)

process:895, AbstractProtocol$ConnectionHandler (org.apache.coyote)

doRun:1722, NioEndpoint$SocketProcessor (org.apache.tomcat.util.net)

run:49, SocketProcessorBase (org.apache.tomcat.util.net)

runWorker:1191, ThreadPoolExecutor (org.apache.tomcat.util.threads)

run:659, ThreadPoolExecutor$Worker (org.apache.tomcat.util.threads)

run:61, TaskThread$WrappingRunnable (org.apache.tomcat.util.threads)

run:829, Thread (java.lang)

[Peter Barnes]

Copy paste erro, missed the top of the previously posted stacktrace

determineEndpointForRequest:203, SamlIdPUtils (org.apereo.cas.support.saml) determineEndpointForRequest:144, SamlIdPUtils (org.apereo.cas.support.saml) buildSubject:79, SamlProfileSamlSubjectBuilder (org.apereo.cas.support.saml.web.idp.profile.builders.subject) build:64, SamlProfileSamlSubjectBuilder (org.apereo.cas.support.saml.web.idp.profile.builders.subject) build:35, SamlProfileSamlSubjectBuilder (org.apereo.cas.support.saml.web.idp.profile.builders.subject) invoke:-1, GeneratedMethodAccessor303 (jdk.internal.reflect) invoke:43, DelegatingMethodAccessorImpl (jdk.internal.reflect) invoke:566, Method (java.lang.reflect) invokeMethod:282, ReflectionUtils (org.springframework.util) invoke:499, GenericScope$LockedScopedProxyFactoryBean (org.springframework.cloud.context.scope) proceed:186, ReflectiveMethodInvocation (org.springframework.aop.framework) invoke:212, JdkDynamicAopProxy (org.springframework.aop.framework) build:-1, $Proxy287 (com.sun.proxy) build:97, SamlProfileSamlAssertionBuilder (org.apereo.cas.support.saml.web.idp.profile.builders.assertion) build:37, SamlProfileSamlAssertionBuilder (org.apereo.cas.support.saml.web.idp.profile.builders.assertion) invoke:-1, GeneratedMethodAccessor303 (jdk.internal.reflect) invoke:43, DelegatingMethodAccessorImpl (jdk.internal.reflect) invoke:566, Method (java.lang.reflect)

......

On Friday, January 7, 2022 at 6:09:16 PM UTC+1 Ray Bon wrote:

[Peter Barnes]

We identified why the behavior is different for new vs existing sessions. There was a bug fixed in 6.3.7

correct filtering of authn extension attributes to · apereo/cas@c8811dd · GitHub

This just leaves the issue of the error being suppressed and not logged without enabling debug. Is there an official way of creating issue reports within the project?