[Using Sakai] CAS related sakai problem
Steve Swinsburg
steve.swinsburg at gmail.com
Thu Mar 29 03:49:56 PDT 2012
Hi Anders,
The service ticket has been granted for scio.his.se (Sakai) but the error message is coming from studentportalen.his.se (uPortal). Are you sure those are the logs for this particular issue?
cheers,
Steve
On 29/03/2012, at 9:08 PM, 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