[Using Sakai] CAS related sakai problem
Andrew Petro
apetro at unicon.net
Thu Mar 29 05:39:17 PDT 2012
Hi Anders,
> Here is the cas.out log:
>
> 2012-03-23 10:54:24,499 WARN [org.jasig.cas.util.HttpClient] - Error Sending message to url endpoint [https://studentportalen.his.se/uPortal/Login]. Error is [Server redirected too many times (20)]
>
> (this "server redirected to many times" log occur every day at all times)
This looks like the CAS single sign-*out* callback feature, whereby CAS can call back to applications the user logged in to to advice them that the user has since explicitly logged out, or even that the single sign-on session ended without the user particularly trying to log out.
I bet your routing handles requests to that https://studentportalen.his.se/uPortal/Login URL differently when they are originated directly from the CAS server (as is the case in single logout callbacks) versus when they are originated from end user web browsers.
https://wiki.jasig.org/display/CASUM/Single+Sign+Out
More generally, is your CAS server configured to do single sign-out callbacks, and if so, is your Sakai prepared to accept those callbacks and handle them appropriately?
(In general my position is that appropriately handling single sign *out* callbacks is infeasible and the best course of action is to disable this feature in the CAS server so as to not have the opportunity to handle these callbacks inappropriately.)
I doubt single sign-out callbacks are the whole problem here, but they may be contributing to the noise.
Andrew
On Mar 29, 2012, at 6:08 AM, Anders Nordkvist wrote:
> Hi,
>
> The problem is ocurring quite often. It seems to help to restart our CAS-servers then the logs in Sakai are not showing anymore and everything seems normal for a while. This is the catalina.out logs from CAS1 with the same ticket as from the other logs:
>
>
> 2012-03-23 10:53:32,090 INFO [org.jasig.cas.CentralAuthenticationServiceImpl] - <Granted service ticket [ST-408-N0ZlV2izrLYiEZ4qficK-cas] for service [http://scio.his.se/sakai-login-tool/container] for user [***]>
> WHAT: ST-408-N0ZlV2izrLYiEZ4qficK-cas for http://scio.his.se/sakai-login-tool/container
>
>
>
> Here is the cas.out log:
>
> 2012-03-23 10:51:06,786 WARN [org.jasig.cas.util.HttpClient] - Error Sending message to url endpoint [https://studentportalen.his.se/uPortal/Login]. Error is [Server redirected too many times (20)]
> 2012-03-23 10:53:58,651 WARN [org.jasig.cas.util.HttpClient] - Error Sending message to url endpoint [https://studentportalen.his.se/uPortal/Login]. Error is [Server redirected too many times (20)]
> 2012-03-23 10:54:24,499 WARN [org.jasig.cas.util.HttpClient] - Error Sending message to url endpoint [https://studentportalen.his.se/uPortal/Login]. Error is [Server redirected too many times (20)]
>
> (this "server redirected to many times" log occur every day at all times)
>
>
>
> This is the cas.log from the other cas- server (CAS2). I couldn't find the ticket from 23/3 so I have taken one from today instead (we had the same issue today so the Sakai logs are like below). I have masked some things out:
>
>
> 2012-03-29 10:54:09,944 INFO [org.jasig.cas.CentralAuthenticationServiceImpl] - ServiceTicket [ST-24382-cQw9f70fOCYblCYVf0nt-cas] has expired.
> 2012-03-29 10:54:09,945 INFO [com.github.inspektr.audit.support.Slf4jLoggingAuditTrailManager] - Audit trail record BEGIN
> =============================================================
> WHO: audit:unknown
> WHAT: ST-24382-cQw9f70fOCYblCYVf0nt-cas
> ACTION: SERVICE_TICKET_VALIDATE_FAILED
> APPLICATION: CAS
> WHEN: Thu Mar 29 10:54:09 CEST 2012
> CLIENT IP ADDRESS: 193.10.***.*** (out netscaler server)
> SERVER IP ADDRESS: 193.10.***.*** (our cas2 server)
>
>
> Steve, if you mean the database in the back it's a mysql database (not clustered). The database is virtual and stores both CAS and Sakai. we have had some performance issues with it lately which ended in bosting it up with two CPU's (4 CPU's now).
>
>
> Regards
> Anders Nordkvist
> System administrator
> University Of Skövde
> Sweden
>
>
>
> -----Original Message-----
> From: sakai-user-bounces at collab.sakaiproject.org [mailto:sakai-user-bounces at collab.sakaiproject.org] On Behalf Of Andrew Petro
> Sent: den 25 mars 2012 15:08
> To: Sakai User
> Subject: Re: [Using Sakai] CAS related sakai problem
>
> Anders,
>
> While you might get better logging with the latest Jasig Java CAS Client, there's no problem with the legacy Yale Java CAS Client such that it would be unsuccessful in validating a service ticket.
>
> I agree the SSL issue should be addressed. CAS service tickets should be presented to Sakai over https:// rather than http:// to prevent man-in-the-middle attacks involving those service tickets being intercepted and illicitly used by adversaries to log in to Sakai as the end user.
>
> What I think you're saying is that every month or so, a service ticket fails to validate. Ok. But service tickets failing to validate aren't in themselves a particularly surprising -- service tickets are short-lived one-time-use tokens. They can be invalid because they've expired, i.e., crazy long delays between issue and validation stemming from network or browser slowness. They can be invalid because they've already been validated once, i.e., user stepped back through browser history or reloaded with the ticket on the URL. Having that sort of thing happen every month or so could be within normal parameters.
>
> Or it could be a real problem. Steve's question is interesting, and latency in ticket replication such that the other CAS server node is not yet aware of a service ticket being validated could certainly cause this issue.
>
> I wonder what your CAS server logs have to say about this? In particular, if you're running a recent enough version of CAS and are using the Inspektr-implemented audit logging feature, that could provide a relatively clean history of what happened with what tickets when, and could let you know (through some interpretation of the logs) if the specific service ticket id that's failing to validate is failing because of expiration, because of having already been validated, or because the CAS server node asked isn't aware of it at all.
>
> Kind regards,
>
> Andrew
>
>
>
>
> On Mar 24, 2012, at 4:56 AM, Steve Swinsburg wrote:
>
>> First thing would be to use the Jasig cas client rather than the Yale one.
>>
>> The ssl issue Sam noted also should be addressed.
>>
>> Also, what's the ticket registry storage on the CAS server? We used to use a jpa database backend which was clustered but not replicating fast enough so it was causing this exact issue.
>>
>> Cheers
>> Steve
>>
>>
>> Sent from my iPhone
>>
>> On 24/03/2012, at 1:49, Sam Ottenhoff <ottenhoff at longsight.com> wrote:
>>
>>> It seems like your Sakai is running on HTTPS: https://scio.his.se/portal
>>>
>>> But your service parameter to CAS is saying that you are running on plain HTTP: service=http%3A%2F%2Fscio.his.se%2Fsakai-login-tool%2Fcontainer
>>>
>>> --Sam
>>>
>>> On Fri, Mar 23, 2012 at 10:38 AM, Anders Nordkvist <anders.nordqvist at his.se> wrote:
>>> Hi,
>>>
>>>
>>>
>>> We have sakai version 2.7.X and use CAS version 3.4.6 for authentication. We have two Sakai nodes and two CAS nodes in a load balanced environment. We use a mysql database server. Today we had a rather strange problem. A problem that's returning with say a month interval. The problem is that Sakai users get this error log when logging in to our CAS authentication server:tus500 -
>>>
>>> type Exception report
>>>
>>> message
>>>
>>> description The server encountered an internal error () that prevented it from fulfilling this request.
>>>
>>> exception
>>>
>>> javax.servlet.ServletException: Unable to validate ProxyTicketValidator [[edu.yale.its.tp.cas.client.ProxyTicketValidator proxyList=[null] [edu.yale.its.tp.cas.client.ServiceTicketValidator casValidateUrl=[https://hscas.his.se/cas/serviceValidate] ticket=[ST-408-N0ZlV2izrLYiEZ4qficK-cas] service=[http%3A%2F%2Fscio.his.se%2Fsakai-login-tool%2Fcontainer] errorCode=[INVALID_TICKET] errorMessage=[ticket 'ST-408-N0ZlV2izrLYiEZ4qficK-cas' not recognized] renew=false entireResponse=[<cas:serviceResponse xmlns:cas='http://www.yale.edu/tp/cas'>
>>>
>>> <cas:authenticationFailure code='INVALID_TICKET'>
>>>
>>> ticket 'ST-408-N0ZlV2izrLYiEZ4qficK-cas' not recognized
>>>
>>> </cas:authenticationFailure>
>>>
>>> </cas:serviceResponse>
>>>
>>> ]]]]
>>>
>>> edu.yale.its.tp.cas.client.filter.CASFilter.doFilter(CASFilter.java:381)
>>>
>>> org.sakaiproject.util.RequestFilter.doFilter(RequestFilter.java:658)
>>>
>>> root cause
>>>
>>> edu.yale.its.tp.cas.client.CASAuthenticationException: Unable to validate ProxyTicketValidator [[edu.yale.its.tp.cas.client.ProxyTicketValidator proxyList=[null] [edu.yale.its.tp.cas.client.ServiceTicketValidator casValidateUrl=[https://hscas.his.se/cas/serviceValidate] ticket=[ST-408-N0ZlV2izrLYiEZ4qficK-cas] service=[http%3A%2F%2Fscio.his.se%2Fsakai-login-tool%2Fcontainer] errorCode=[INVALID_TICKET] errorMessage=[ticket 'ST-408-N0ZlV2izrLYiEZ4qficK-cas' not recognized] renew=false entireResponse=[<cas:serviceResponse xmlns:cas='http://www.yale.edu/tp/cas'>
>>>
>>> <cas:authenticationFailure code='INVALID_TICKET'>
>>>
>>> ticket 'ST-408-N0ZlV2izrLYiEZ4qficK-cas' not recognized
>>>
>>> </cas:authenticationFailure>
>>>
>>> </cas:serviceResponse>
>>>
>>> ]]]]
>>>
>>> edu.yale.its.tp.cas.client.CASReceipt.getReceipt(CASReceipt.java:62)
>>>
>>> edu.yale.its.tp.cas.client.filter.CASFilter.getAuthenticatedUser(CASFilter.java:455)
>>>
>>> edu.yale.its.tp.cas.client.filter.CASFilter.doFilter(CASFilter.java:378)
>>>
>>> org.sakaiproject.util.RequestFilter.doFilter(RequestFilter.java:658)
>>>
>>> note The full stack trace of the root cause is available in the Apache Tomcat/5.5.31 logs.
>>>
>>>
>>>
>>> This is the log from one of our Sakai nodes:
>>>
>>>
>>>
>>> 2012-03-23 10:53:49,883 ERROR http-8080-Processor6 edu.yale.its.tp.cas.client.CASReceipt - validation of [[edu.yale.its.tp.cas.client.ProxyTicketValidator proxyList=[null] [edu.yale.its.tp.cas.client.ServiceTicketValidator casValidateUrl=[https://hscas.his.se/cas/serviceValidate] ticket=[ST-408-N0ZlV2izrLYiEZ4qficK-cas] service=[http%3A%2F%2Fscio.his.se%2Fsakai-login-tool%2Fcontainer] errorCode=[INVALID_TICKET] errorMessage=[ticket 'ST-408-N0ZlV2izrLYiEZ4qficK-cas' not recognized] renew=false entireResponse=[<cas:serviceResponse xmlns:cas='http://www.yale.edu/tp/cas'>
>>>
>>> <cas:authenticationFailure code='INVALID_TICKET'>
>>>
>>> ticket 'ST-408-N0ZlV2izrLYiEZ4qficK-cas' not recognized
>>>
>>> </cas:authenticationFailure>
>>>
>>> </cas:serviceResponse>
>>>
>>> ]]]] was not successful.
>>>
>>> 2012-03-23 10:53:49,883 ERROR http-8080-Processor6 edu.yale.its.tp.cas.client.filter.CASFilter - edu.yale.its.tp.cas.client.CASAuthenticationException: Unable to validate ProxyTicketValidator [[edu.yale.its.tp.cas.client.ProxyTicketValidator proxyList=[null] [edu.yale.its.tp.cas.client.ServiceTicketValidator casValidateUrl=[https://hscas.his.se/cas/serviceValidate] ticket=[ST-408-N0ZlV2izrLYiEZ4qficK-cas] service=[http%3A%2F%2Fscio.his.se%2Fsakai-login-tool%2Fcontainer] errorCode=[INVALID_TICKET] errorMessage=[ticket 'ST-408-N0ZlV2izrLYiEZ4qficK-cas' not recognized] renew=false entireResponse=[<cas:serviceResponse xmlns:cas='http://www.yale.edu/tp/cas'>
>>>
>>> <cas:authenticationFailure code='INVALID_TICKET'>
>>>
>>> ticket 'ST-408-N0ZlV2izrLYiEZ4qficK-cas' not recognized
>>>
>>> </cas:authenticationFailure>
>>>
>>> </cas:serviceResponse>
>>>
>>> ]]]]
>>>
>>> 2012-03-23 10:53:49,884 WARN http-8080-Processor6 org.sakaiproject.util.RequestFilter - Unable to validate ProxyTicketValidator [[edu.yale.its.tp.cas.client.ProxyTicketValidator proxyList=[null] [edu.yale.its.tp.cas.client.ServiceTicketValidator casValidateUrl=[https://hscas.his.se/cas/serviceValidate] ticket=[ST-408-N0ZlV2izrLYiEZ4qficK-cas] service=[http%3A%2F%2Fscio.his.se%2Fsakai-login-tool%2Fcontainer] errorCode=[INVALID_TICKET] errorMessage=[ticket 'ST-408-N0ZlV2izrLYiEZ4qficK-cas' not recognized] renew=false entireResponse=[<cas:serviceResponse xmlns:cas='http://www.yale.edu/tp/cas'>
>>>
>>> <cas:authenticationFailure code='INVALID_TICKET'>
>>>
>>> ticket 'ST-408-N0ZlV2izrLYiEZ4qficK-cas' not recognized
>>>
>>> </cas:authenticationFailure>
>>>
>>> </cas:serviceResponse>
>>>
>>> ]]]]
>>>
>>> javax.servlet.ServletException: Unable to validate ProxyTicketValidator [[edu.yale.its.tp.cas.client.ProxyTicketValidator proxyList=[null] [edu.yale.its.tp.cas.client.ServiceTicketValidator casValidateUrl=[https://hscas.his.se/cas/serviceValidate] ticket=[ST-408-N0ZlV2izrLYiEZ4qficK-cas] service=[http%3A%2F%2Fscio.his.se%2Fsakai-login-tool%2Fcontainer] errorCode=[INVALID_TICKET] errorMessage=[ticket 'ST-408-N0ZlV2izrLYiEZ4qficK-cas' not recognized] renew=false entireResponse=[<cas:serviceResponse xmlns:cas='http://www.yale.edu/tp/cas'>
>>>
>>> <cas:authenticationFailure code='INVALID_TICKET'>
>>>
>>> ticket 'ST-408-N0ZlV2izrLYiEZ4qficK-cas' not recognized
>>>
>>> </cas:authenticationFailure>
>>>
>>> </cas:serviceResponse>
>>>
>>> ]]]]
>>>
>>> at edu.yale.its.tp.cas.client.filter.CASFilter.doFilter(CASFilter.java:381)
>>>
>>> at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:215)
>>>
>>> at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:188)
>>>
>>> at org.sakaiproject.util.RequestFilter.doFilter(RequestFilter.java:658)
>>>
>>> at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:215)
>>>
>>> at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:188)
>>>
>>> at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:213)
>>>
>>> at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:172)
>>>
>>> at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:127)
>>>
>>> at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:117)
>>>
>>> at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:108)
>>>
>>> at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:174)
>>>
>>> at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:879)
>>>
>>> at org.apache.coyote.http11.Http11BaseProtocol$Http11ConnectionHandler.processConnection(Http11BaseProtocol.java:665)
>>>
>>> at org.apache.tomcat.util.net.PoolTcpEndpoint.processSocket(PoolTcpEndpoint.java:528)
>>>
>>> at org.apache.tomcat.util.net.LeaderFollowerWorkerThread.runIt(LeaderFollowerWorkerThread.java:81)
>>>
>>> at org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:689)
>>>
>>> at java.lang.Thread.run(Thread.java:662)
>>>
>>> 2012-03-23 10:53:49,884 ERROR http-8080-Processor6 org.apache.catalina.core.ContainerBase.[Catalina].[sakai1.hs.local].[/sakai-login-tool].[sakai.login.container] - Servlet.service() for servlet sakai.login.container threw exception
>>>
>>> edu.yale.its.tp.cas.client.CASAuthenticationException: Unable to validate ProxyTicketValidator [[edu.yale.its.tp.cas.client.ProxyTicketValidator proxyList=[null] [edu.yale.its.tp.cas.client.ServiceTicketValidator casValidateUrl=[https://hscas.his.se/cas/serviceValidate] ticket=[ST-408-N0ZlV2izrLYiEZ4qficK-cas] service=[http%3A%2F%2Fscio.his.se%2Fsakai-login-tool%2Fcontainer] errorCode=[INVALID_TICKET] errorMessage=[ticket 'ST-408-N0ZlV2izrLYiEZ4qficK-cas' not recognized] renew=false entireResponse=[<cas:serviceResponse xmlns:cas='http://www.yale.edu/tp/cas'>
>>>
>>> <cas:authenticationFailure code='INVALID_TICKET'>
>>>
>>> ticket 'ST-408-N0ZlV2izrLYiEZ4qficK-cas' not recognized
>>>
>>> </cas:authenticationFailure>
>>>
>>> </cas:serviceResponse>
>>>
>>>
>>>
>>> Does anyone have an idea of what the problem might be here?
>>>
>>> Your welcome to request more logs if you need them!
>>>
>>>
>>>
>>>
>>>
>>> Regards
>>>
>>> Anders Nordkvist
>>>
>>> System administrator
>>>
>>> University Of Skövde
>>>
>>> Sweden
>>>
>>>
>>>
>>>
>>>
>>>
>>> _______________________________________________
>>> sakai-user mailing list
>>> sakai-user at collab.sakaiproject.org
>>> http://collab.sakaiproject.org/mailman/listinfo/sakai-user
>>>
>>> TO UNSUBSCRIBE: send email to sakai-user-unsubscribe at collab.sakaiproject.org with a subject of "unsubscribe"
>>>
>>> _______________________________________________
>>> sakai-user mailing list
>>> sakai-user at collab.sakaiproject.org
>>> http://collab.sakaiproject.org/mailman/listinfo/sakai-user
>>>
>>> TO UNSUBSCRIBE: send email to sakai-user-unsubscribe at collab.sakaiproject.org with a subject of "unsubscribe"
>> _______________________________________________
>> sakai-user mailing list
>> sakai-user at collab.sakaiproject.org
>> http://collab.sakaiproject.org/mailman/listinfo/sakai-user
>>
>> TO UNSUBSCRIBE: send email to sakai-user-unsubscribe at collab.sakaiproject.org with a subject of "unsubscribe"
>
> _______________________________________________
> sakai-user mailing list
> sakai-user at collab.sakaiproject.org
> http://collab.sakaiproject.org/mailman/listinfo/sakai-user
>
> TO UNSUBSCRIBE: send email to sakai-user-unsubscribe at collab.sakaiproject.org with a subject of "unsubscribe"
More information about the sakai-user
mailing list