[cas-user] Authentication Failure

[E.LT]

Hello everyone and thanks in advance for your time !

I'm having problems authenticating uportal to CAS.

Every first authentication is failing and i don't know why.

I'm having a Tomcat 500 error and when i try to retry the uportal URL it's ok. I really don't understand why it behaves like this. Only the first authentication fails. then you can chain disconnect / reconnect successfuly.

Here's the web error message :




exception

java.lang.RuntimeException: java.io.IOException: Server returned HTTP response
code: 500 for URL:
https://sso-cas.xxx.fr/cas/proxyValidate?pgtUrl=http%3A%2F%2Fent1.xxx.fr%2FCasProxyServlet&ticket=ST-350-NzDBiGHm4WIBGqq4nxUV-cas&service=http%3A%2F%2Fent1.xxx.fr%2FLogin

org.jasig.cas.client.util.CommonUtils.getResponseFromServer(CommonUtils.java:295)

org.jasig.cas.client.validation.AbstractCasProtocolUrlBasedTicketValidator.retrieveResponseFromServer(AbstractCasProtocolUrlBasedTicketValidator.java:33)

org.jasig.cas.client.validation.AbstractUrlBasedTicketValidator.validate(AbstractUrlBasedTicketValidator.java:178)

org.jasig.cas.client.validation.AbstractTicketValidationFilter.doFilter(AbstractTicketValidationFilter.java:132)
cause mère

java.io.IOException: Server returned HTTP response code: 500 for URL:
https://sso-cas.xxx.fr/cas/proxyValidate?pgtUrl=http%3A%2F%2Fent1.xxx.fr%2FCasProxyServlet&ticket=ST-350-NzDBiGHm4WIBGqq4nxUV-cas&service=http%3A%2F%2Fent1.xxx.fr%2FLogin

sun.net.www.protocol.http.HttpURLConnection.getInputStream(HttpURLConnection.java:1436)

com.sun.net.ssl.internal.www.protocol.https.HttpsURLConnectionOldImpl.getInputStream(HttpsURLConnectionOldImpl.java:204)

org.jasig.cas.client.util.CommonUtils.getResponseFromServer(CommonUtils.java:281)

org.jasig.cas.client.validation.AbstractCasProtocolUrlBasedTicketValidator.retrieveResponseFromServer(AbstractCasProtocolUrlBasedTicketValidator.java:33)

org.jasig.cas.client.validation.AbstractUrlBasedTicketValidator.validate(AbstractUrlBasedTicketValidator.java:178)

org.jasig.cas.client.validation.AbstractTicketValidationFilter.doFilter(AbstractTicketValidationFilter.java:132


I'm really lost ..

Thanks a lot (And sorry for the faults :()
--
You are currently subscribed to cas-...@lists.jasig.org as: jasig-cas-user...@googlegroups.com
To unsubscribe, change settings or access archives, see http://www.ja-sig.org/wiki/display/JSG/cas-user

[Andrew Petro]

Hi,

That's a weird behavior, that it fails initially and then works.  I don't have an explanation for that off hand.

Are there corresponding log entries from the CAS server wherein the server explains why it is responding with a 500 status code?

Otherwise:

1) Do you get the failure behavior when manually exercising the ticket validation?  As in, turn up ST timeouts, manually obtain an ST, manually validate it, in your browser.

2) Why /cas/proxyValidate ?  If the application validating the ST intends only to accept service tickets and not proxy tickets, it's preferable to use the /cas/serviceValidate endpoint so as to avoid accidentally accepting a proxy ticket.  Note that /cas/proxyValidate is necessary only to *validate* a proxy ticket, not just to obtain a PGT.

3) Try cranking up Java CAS client logging to TRACE to get more context.  Likewise, crank up logging on the CAS server.

Hope this helps,

Andrew

--
You are currently subscribed to cas-...@lists.jasig.org as: ape...@unicon.net

To unsubscribe, change settings or access archives, see http://www.ja-sig.org/wiki/display/JSG/cas-user

[E.LT]

Hello,

Thank you for your answer.

Unfortunatly, i don't know how to exactly make the changes you're asking.

I don't know why it asks for a PGT. When i'm having this error, i can find (i've put debug mode for logs) that i'm getting a Service Ticket

" Granted service ticket [ST-744-DA4yHAXUv6a2xxMJgpdOr9-cas] for service [http://ent2.xxx.fr/Login] for user [xxx]"

Yet, it still displays the HTTP 500 error.

On the catalina.out, i do have a trace :

"25 févr. 2013 16:09:55 org.apache.catalina.core.StandardWrapperValve invoke
GRAVE: "Servlet.service()" pour la servlet cas a généré une exception
java.lang.IllegalArgumentException: resourceOperatedUpon cannot be null
at com.github.inspektr.audit.AuditActionContext.assertNotNull(AuditActionContext.java:81)
at com.github.inspektr.audit.AuditActionContext.<init>(AuditActionContext.java:64)
at com.github.inspektr.audit.AuditTrailManagementAspect.executeAuditCode(AuditTrailManagementAspect.java:148)
at com.github.inspektr.audit.AuditTrailManagementAspect.handleAuditTrail(AuditTrailManagementAspect.java:139)
at sun.reflect.GeneratedMethodAccessor66.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:597)
at org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethodWithGivenArgs(AbstractAspectJAdvice.java:621)
at org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethod(AbstractAspectJAdvice.java:610)
at org.springframework.aop.aspectj.AspectJAroundAdvice.invoke(AspectJAroundAdvice.java:65)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:161)
at org.springframework.aop.aspectj.MethodInvocationProceedingJoinPoint.proceed(MethodInvocationProceedingJoinPoint.java:80)
at org.perf4j.aop.AbstractTimingAspect$1.proceed(AbstractTimingAspect.java:47)
at org.perf4j.aop.AgnosticTimingAspect.runProfiledMethod(AgnosticTimingAspect.java:44)
at org.perf4j.aop.AbstractTimingAspect.doPerfLogging(AbstractTimingAspect.java:45)
at sun.reflect.GeneratedMethodAccessor67.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:597)
at org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethodWithGivenArgs(AbstractAspectJAdvice.java:621)
at org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethod(AbstractAspectJAdvice.java:610)
at org.springframework.aop.aspectj.AspectJAroundAdvice.invoke(AspectJAroundAdvice.java:65)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:161)
at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:89)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:202)
at $Proxy44.delegateTicketGrantingTicket(Unknown Source)
at org.jasig.cas.web.ServiceValidateController.handleRequestInternal(ServiceValidateController.java:127)
at org.springframework.web.servlet.mvc.AbstractController.handleRequest(AbstractController.java:153)
at org.springframework.web.servlet.mvc.SimpleControllerHandlerAdapter.handle(SimpleControllerHandlerAdapter.java:48)
at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:790)
at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:719)
at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:644)
at org.springframework.web.servlet.FrameworkServlet.doGet(FrameworkServlet.java:549)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:617)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:717)
at org.jasig.cas.web.init.SafeDispatcherServlet.service_aroundBody2(SafeDispatcherServlet.java:115)
at org.jasig.cas.web.init.SafeDispatcherServlet.service_aroundBody3$advice(SafeDispatcherServlet.java:44)
at org.jasig.cas.web.init.SafeDispatcherServlet.service(SafeDispatcherServlet.java:1)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
at com.github.inspektr.common.web.ClientInfoThreadLocalFilter.doFilter(ClientInfoThreadLocalFilter.java:63)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
at org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:88)
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:76)
at org.springframework.web.filter.DelegatingFilterProxy.invokeDelegate(DelegatingFilterProxy.java:237)
at org.springframework.web.filter.DelegatingFilterProxy.doFilter(DelegatingFilterProxy.java:167)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:233)
at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:191)
at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:127)
at com.googlecode.psiprobe.Tomcat60AgentValve.invoke(Tomcat60AgentValve.java:30)
at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102)
at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109)
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:298)
at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:859)
at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:588)
at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:489)
at java.lang.Thread.run(Thread.java:662)
"


I really don't get it... I'm panicking, 400 users are calling saying there is an error. And i can't just simply tell them to try again.

1) I don't know how to do that ... I found some examples in JASIG cas wiki saying to test with "Foo" app. But i get the "you're not authorized to use this application on CAS"

2) I don't know why, or where this is configured. This Uportal + Cas have been working for 2 years.

3)crank ?


Thank you again for your time.

[Andrew Petro]

Hi,

Oh dear.  These things do tend to happily work well for months and months until they don't.

Ok.  The Granted bit is a good sign.  However, that happens when the end user interacts with /cas/login .  The failure you're seeing happens when your application interacts with /cas/proxyValidate to validate a ticket.  There should be corresponding audit log entries for the ticket validation attempt.

Except there won't be, given that stack trace you've posted.  It looks like the audit trail system itself is failing, for lack of a "resourceOperatedOn" to log.

What version of Inspektr are you using?  For that matter, what version of CAS are you using?  You can determine the versions of both of these by looking at the .jar files in /WEB-INF/lib -- say, cas-server-core for the CAS version and something inspektr for the Inspektr version.

This issue sounds familiar to me.  I think something like this came up before and led to better diagnostics in the latest Inspektr release. 

https://github.com/dima767/inspektr/issues/13

https://github.com/dima767/inspektr/commit/a7c9187fc59db572478929508e0f90bb2ec12da6

If you're on a back version, you might try bumping up to the 1.0.7 version and see if it helps or at least you get better errors in the log.

http://mvnrepository.com/artifact/com.github.inspektr/inspektr

Kind regards,

Andrew

--
You are currently subscribed to cas-...@lists.jasig.org as: ape...@unicon.net

To unsubscribe, change settings or access archives, see http://www.ja-sig.org/wiki/display/JSG/cas-user

[Marvin Addison]

> I really don't get it... I'm panicking, 400 users are calling saying there is an error. And i can't just simply tell them to try again.

Triage the problem by disabling Inspektr auditing. Simply remove
auditTrailContext.xml from your config and restart. See
https://wiki.jasig.org/display/CASUM/Auditing+and+Statistics+Via+Inspektr
for background.

Review the resources Andrew mentioned then you can troubleshoot in a
test environment. The root cause is some AuditResourceResolver or
AuditPrincipalResolver is returning null.

M

[Andrew Petro]

Incidentally and more strategically for Inspektr, it might be worth revisiting the assertions to make unexpected inputs to the audit trail logging not induce failure in the functionality being logged.

Captured thought to issue #16 in the Inspektr project.

https://github.com/dima767/inspektr/issues/16

[E.LT]

Hello,

I just removed the file you asked and i got different results. Here's the web http 500 error :

"exception

javax.servlet.ServletException: org.jasig.cas.client.validation.TicketValidationException:
the ticket 'ST-14-o6h5Xx1BDhb1CPUQsT7Y-cas' is unknown

org.jasig.cas.client.validation.AbstractTicketValidationFilter.doFilter(AbstractTicketValidationFilter.java:155)


cause mère

org.jasig.cas.client.validation.TicketValidationException:
the ticket 'ST-14-o6h5Xx1BDhb1CPUQsT7Y-cas' is unknown

org.jasig.cas.client.validation.Cas20ServiceTicketValidator.parseResponseFromServer(Cas20ServiceTicketValidator.java:73)
org.jasig.cas.client.validation.AbstractUrlBasedTicketValidator.validate(AbstractUrlBasedTicketValidator.java:188)
org.jasig.cas.client.validation.AbstractTicketValidationFilter.doFilter(AbstractTicketValidationFilter.java:132)

"



And in the cas.log :

"2013-02-25 17:01:07,861 INFO [org.jasig.cas.CentralAuthenticationServiceImpl] - Granted service ticket [ST-14-o6h5Xx1BDhb1CPUQsT7Y-cas] for service [http://ent2.xxxx.fr/Login] for user [xxxxx]
2013-02-25 17:01:07,974 INFO [org.jasig.cas.authentication.AuthenticationManagerImpl] - AuthenticationHandler: org.jasig.cas.adaptors.ldap.BindLdapAuthenticationHandler failed to authenticate the user which provided the following credentials: [username: id3367]
2013-02-25 17:01:17,883 INFO [org.jasig.cas.authentication.AuthenticationManagerImpl] - AuthenticationHandler: org.jasig.cas.authentication.handler.support.HttpBasedServiceCredentialsAuthenticationHandler successfully authenticated the user which provided the following credentials: [callbackUrl: http://ent2.xxx.fr/CasProxyServlet]
2013-02-25 17:01:17,884 ERROR [org.jasig.cas.web.ServiceValidateController] - TicketException generating ticket for: [callbackUrl: http://ent2.xxx.fr/CasProxyServlet]
org.jasig.cas.ticket.InvalidTicketException
at org.jasig.cas.CentralAuthenticationServiceImpl.delegateTicketGrantingTicket_aroundBody6(CentralAuthenticationServiceImpl.java:278)
at org.jasig.cas.CentralAuthenticationServiceImpl.delegateTicketGrantingTicket_aroundBody7$advice(CentralAuthenticationServiceImpl.java:44)
at org.jasig.cas.CentralAuthenticationServiceImpl.delegateTicketGrantingTicket(CentralAuthenticationServiceImpl.java:1)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)

at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:597)

at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:309)
at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:183)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:150)

at org.springframework.aop.aspectj.MethodInvocationProceedingJoinPoint.proceed(MethodInvocationProceedingJoinPoint.java:80)
at org.perf4j.aop.AbstractTimingAspect$1.proceed(AbstractTimingAspect.java:47)
at org.perf4j.aop.AgnosticTimingAspect.runProfiledMethod(AgnosticTimingAspect.java:44)
at org.perf4j.aop.AbstractTimingAspect.doPerfLogging(AbstractTimingAspect.java:45)

at sun.reflect.GeneratedMethodAccessor56.invoke(Unknown Source)

at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:597)
at org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethodWithGivenArgs(AbstractAspectJAdvice.java:621)
at org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethod(AbstractAspectJAdvice.java:610)
at org.springframework.aop.aspectj.AspectJAroundAdvice.invoke(AspectJAroundAdvice.java:65)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:161)
at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:89)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:202)

at $Proxy40.delegateTicketGrantingTicket(Unknown Source)

2013-02-25 17:01:17,888 INFO [org.jasig.cas.CentralAuthenticationServiceImpl] - ServiceTicket [ST-14-o6h5Xx1BDhb1CPUQsT7Y-cas] has expired.
"

It's weird, in the previous message i'm being asked for a PGT. And here it seems that it creates the ST bug 10 seconds after it has expired.

Best regards

E.

[Andrew Petro]

E.,

Your portal is asking that CAS call it back with a PGT, yes, but otherwise the PGT shouldn't be relevant.  If the CAS server proxy callback fails, then CAS will issue the ST anyway and omit the PGTIOU from the ST validation response.  Maybe the PGT callback is inserting enough delay to run afoul of that 10 second timeout.

Incidentally, your portal's login URL and proxy callback URL aren't using https.  The former is poor practice, and the latter just shouldn't work.

But anyway, as a next thing to try: how about nudging up the service ticket timeout to 30 seconds rather than 10 seconds and see if anything changes?

Andrew

--
You are currently subscribed to cas-...@lists.jasig.org as: ape...@unicon.net

To unsubscribe, change settings or access archives, see http://www.ja-sig.org/wiki/display/JSG/cas-user