ServiceTicket does not exist

classic Classic list List threaded Threaded
1 message Options
Reply | Threaded
Open this post in threaded view
|

ServiceTicket does not exist

lloowen
This post has NOT been accepted by the mailing list yet.
I'm setting up a Liferay Portal + CAS SSO solution. They are running on their own devices. The CAS SSO is plugged into LDAP and it uses a mysql database for managing the tickets.

The redirection from Liferay to the CAS server works. Users can log in and are redirected back to their Liferay portal page. As soon as a user clicks on any link or refreshes the page, the liferay portal page goes blank!

Now when I check the CAS logs as all this is going on, I see that ldap users are being authenticated and are granted tickets. The service ticket is granted and validation initially succeeds. Then when the users refresh the page or go to another page, I see that the service ticket validation fails, with an explanation such as:

<ServiceTicket [ST-1-a2QNJmGQY1zt6LEKIuYn-exAmpleSite.com] does not exist.>

I thought perhaps the service ticket validation expiry, which is defaulted to 10seconds was too short. So I prolonged it to two minutes. However I'm still seeing this type of error when users are logging in.

Is far as I can tell, both devices have their SSL certificates configured correctly and they can talk to each other. I'm not seeing any error messages in the logs to suggest otherwise.

Please check the logs below. You can clearly see the service ticket is created and validated successfully. Then it suddenly disappears!!


Really grateful for any help. I'm totally stuck with what to do....

Thanks in advance.






2015-04-27 10:28:06,525 INFO [org.jasig.cas.authentication.AuthenticationManagerImpl] - <Resolved principal Harold>
2015-04-27 10:28:06,525 INFO [org.jasig.cas.authentication.AuthenticationManagerImpl] - <org.jasig.cas.adaptors.ldap.BindLdapAuthenticationHandler@72078ac8 authenticated Harold with credential [username: Harold].>
2015-04-27 10:28:06,526 DEBUG [org.jasig.cas.authentication.AuthenticationManagerImpl] - <Attribute map for Harold: {}>
2015-04-27 10:28:06,532 INFO [com.github.inspektr.audit.support.Slf4jLoggingAuditTrailManager] - <Audit trail record BEGIN
=============================================================
WHO: [username: Harold]
WHAT: supplied credentials: [username: Harold]
ACTION: AUTHENTICATION_SUCCESS
APPLICATION: CAS
WHEN: Mon Apr 27 10:28:06 CEST 2015
CLIENT IP ADDRESS: 192.168.1.47
SERVER IP ADDRESS: 10.10.0.23
=============================================================

>
2015-04-27 10:28:06,534 DEBUG [org.jasig.cas.ticket.registry.DefaultTicketRegistry] - <Added ticket [TGT-1-zQLyVdvQR4nYD7vK2GmvRexjxYzXS97ZIUcjzcCDMdYDBh6Y6g-exAmpleSite.com] to registry.>
2015-04-27 10:28:06,534 INFO [com.github.inspektr.audit.support.Slf4jLoggingAuditTrailManager] - <Audit trail record BEGIN
=============================================================
WHO: [username: Harold]
WHAT: TGT-1-zQLyVdvQR4nYD7vK2GmvRexjxYzXS97ZIUcjzcCDMdYDBh6Y6g-exAmpleSite.com
ACTION: TICKET_GRANTING_TICKET_CREATED
APPLICATION: CAS
WHEN: Mon Apr 27 10:28:06 CEST 2015
CLIENT IP ADDRESS: 192.168.1.47
SERVER IP ADDRESS: 10.10.0.23
=============================================================

>
2015-04-27 10:28:06,535 DEBUG [org.springframework.orm.jpa.JpaTransactionManager] - <Initiating transaction commit>
2015-04-27 10:28:06,535 DEBUG [org.springframework.orm.jpa.JpaTransactionManager] - <Committing JPA transaction on EntityManager [org.hibernate.ejb.EntityManagerImpl@452f7cdd]>
2015-04-27 10:28:06,537 DEBUG [org.springframework.orm.jpa.JpaTransactionManager] - <Closing JPA EntityManager [org.hibernate.ejb.EntityManagerImpl@452f7cdd] after transaction>
2015-04-27 10:28:06,537 DEBUG [org.springframework.orm.jpa.EntityManagerFactoryUtils] - <Closing JPA EntityManager>
2015-04-27 10:28:06,537 DEBUG [org.jasig.cas.web.support.CookieRetrievingCookieGenerator] - <Removed cookie with name [CASPRIVACY]>
2015-04-27 10:28:06,538 DEBUG [org.springframework.webflow.execution.AnnotatedAction] - <Clearing action execution attributes map[[empty]]>
2015-04-27 10:28:06,538 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Finished executing [EvaluateAction@1aba6c98 expression = authenticationViaFormAction.submit(flowRequestContext, flowScope.credentials, messageContext), resultExpression = [null]]; result = success>
2015-04-27 10:28:06,538 DEBUG [org.springframework.webflow.engine.Transition] - <Executing [Transition@251f3afe on = success, to = sendTicketGrantingTicket]>
2015-04-27 10:28:06,538 DEBUG [org.springframework.webflow.engine.Transition] - <Exiting state 'realSubmit'>
2015-04-27 10:28:06,538 DEBUG [org.springframework.webflow.engine.ActionState] - <Entering state 'sendTicketGrantingTicket' of flow 'login'>
2015-04-27 10:28:06,539 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Executing [EvaluateAction@255a0cbc expression = sendTicketGrantingTicketAction, resultExpression = [null]]>
2015-04-27 10:28:06,539 DEBUG [org.springframework.webflow.execution.AnnotatedAction] - <Putting action execution attributes map[[empty]]>
2015-04-27 10:28:06,539 DEBUG [org.springframework.beans.factory.support.DefaultListableBeanFactory] - <Returning cached instance of singleton bean 'sendTicketGrantingTicketAction'>
2015-04-27 10:28:06,539 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Executing org.jasig.cas.web.flow.SendTicketGrantingTicketAction@3afa1dcc>
2015-04-27 10:28:06,540 DEBUG [org.jasig.cas.web.support.CookieRetrievingCookieGenerator] - <Added cookie with name [CASTGC] and value [TGT-1-zQLyVdvQR4nYD7vK2GmvRexjxYzXS97ZIUcjzcCDMdYDBh6Y6g-exAmpleSite.com]>
2015-04-27 10:28:06,540 DEBUG [org.springframework.beans.factory.support.DefaultListableBeanFactory] - <Returning cached instance of singleton bean 'transactionManager'>
2015-04-27 10:28:06,540 DEBUG [org.springframework.orm.jpa.JpaTransactionManager] - <Creating new transaction with name [org.jasig.cas.CentralAuthenticationServiceImpl.destroyTicketGrantingTicket]: PROPAGATION_REQUIRED,ISOLATION_DEFAULT; ''>
2015-04-27 10:28:06,541 DEBUG [org.springframework.orm.jpa.JpaTransactionManager] - <Opened new EntityManager [org.hibernate.ejb.EntityManagerImpl@7aba5a53] for JPA transaction>
2015-04-27 10:28:06,541 DEBUG [org.springframework.orm.jpa.JpaTransactionManager] - <Exposing JPA transaction as JDBC transaction [org.springframework.orm.jpa.vendor.HibernateJpaDialect$HibernateConnectionHandle@60803e17]>
2015-04-27 10:28:06,542 DEBUG [org.jasig.cas.CentralAuthenticationServiceImpl] - <Removing ticket [TGT-1-YwyE7uZ9wngisMfEykCvx6DVY0riqZbE96UnZdV3b1l1TwritG-exAmpleSite.com] from registry.>
2015-04-27 10:28:06,542 DEBUG [org.jasig.cas.ticket.registry.DefaultTicketRegistry] - <Attempting to retrieve ticket [TGT-1-YwyE7uZ9wngisMfEykCvx6DVY0riqZbE96UnZdV3b1l1TwritG-exAmpleSite.com]>
2015-04-27 10:28:06,542 DEBUG [org.jasig.cas.ticket.registry.DefaultTicketRegistry] - <Attempting to retrieve ticket [TGT-1-YwyE7uZ9wngisMfEykCvx6DVY0riqZbE96UnZdV3b1l1TwritG-exAmpleSite.com]>
2015-04-27 10:28:06,543 INFO [com.github.inspektr.audit.support.Slf4jLoggingAuditTrailManager] - <Audit trail record BEGIN
=============================================================
WHO: audit:unknown
WHAT: TGT-1-YwyE7uZ9wngisMfEykCvx6DVY0riqZbE96UnZdV3b1l1TwritG-exAmpleSite.com
ACTION: TICKET_GRANTING_TICKET_DESTROYED
APPLICATION: CAS
WHEN: Mon Apr 27 10:28:06 CEST 2015
CLIENT IP ADDRESS: 192.168.1.47
SERVER IP ADDRESS: 10.10.0.23
=============================================================

>
2015-04-27 10:28:06,544 DEBUG [org.springframework.orm.jpa.JpaTransactionManager] - <Initiating transaction commit>
2015-04-27 10:28:06,544 DEBUG [org.springframework.orm.jpa.JpaTransactionManager] - <Committing JPA transaction on EntityManager [org.hibernate.ejb.EntityManagerImpl@7aba5a53]>
2015-04-27 10:28:06,544 DEBUG [org.springframework.orm.jpa.JpaTransactionManager] - <Closing JPA EntityManager [org.hibernate.ejb.EntityManagerImpl@7aba5a53] after transaction>
2015-04-27 10:28:06,545 DEBUG [org.springframework.orm.jpa.EntityManagerFactoryUtils] - <Closing JPA EntityManager>
2015-04-27 10:28:06,545 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Finished executing org.jasig.cas.web.flow.SendTicketGrantingTicketAction@3afa1dcc; result = success>
2015-04-27 10:28:06,545 DEBUG [org.springframework.webflow.execution.AnnotatedAction] - <Clearing action execution attributes map[[empty]]>
2015-04-27 10:28:06,545 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Finished executing [EvaluateAction@255a0cbc expression = sendTicketGrantingTicketAction, resultExpression = [null]]; result = success>
2015-04-27 10:28:06,545 DEBUG [org.springframework.webflow.engine.Transition] - <Executing [Transition@36c8980 on = *, to = serviceCheck]>
2015-04-27 10:28:06,545 DEBUG [org.springframework.webflow.engine.Transition] - <Exiting state 'sendTicketGrantingTicket'>
2015-04-27 10:28:06,546 DEBUG [org.springframework.webflow.engine.DecisionState] - <Entering state 'serviceCheck' of flow 'login'>
2015-04-27 10:28:06,546 DEBUG [org.springframework.webflow.engine.Transition] - <Executing [Transition@4ab73441 on = flowScope.service != null, to = generateServiceTicket]>
2015-04-27 10:28:06,546 DEBUG [org.springframework.webflow.engine.Transition] - <Exiting state 'serviceCheck'>
2015-04-27 10:28:06,546 DEBUG [org.springframework.webflow.engine.ActionState] - <Entering state 'generateServiceTicket' of flow 'login'>
2015-04-27 10:28:06,547 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Executing [EvaluateAction@38b1cb70 expression = generateServiceTicketAction, resultExpression = [null]]>
2015-04-27 10:28:06,547 DEBUG [org.springframework.webflow.execution.AnnotatedAction] - <Putting action execution attributes map[[empty]]>
2015-04-27 10:28:06,547 DEBUG [org.springframework.beans.factory.support.DefaultListableBeanFactory] - <Returning cached instance of singleton bean 'generateServiceTicketAction'>
2015-04-27 10:28:06,547 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Executing org.jasig.cas.web.flow.GenerateServiceTicketAction@20a34324>
2015-04-27 10:28:06,547 DEBUG [org.springframework.beans.factory.support.DefaultListableBeanFactory] - <Returning cached instance of singleton bean 'transactionManager'>
2015-04-27 10:28:06,547 DEBUG [org.springframework.orm.jpa.JpaTransactionManager] - <Creating new transaction with name [org.jasig.cas.CentralAuthenticationServiceImpl.grantServiceTicket]: PROPAGATION_REQUIRED,ISOLATION_DEFAULT; ''>
2015-04-27 10:28:06,548 DEBUG [org.springframework.orm.jpa.JpaTransactionManager] - <Opened new EntityManager [org.hibernate.ejb.EntityManagerImpl@41c7bdb9] for JPA transaction>
2015-04-27 10:28:06,549 DEBUG [org.springframework.orm.jpa.JpaTransactionManager] - <Exposing JPA transaction as JDBC transaction [org.springframework.orm.jpa.vendor.HibernateJpaDialect$HibernateConnectionHandle@2078de6c]>
2015-04-27 10:28:06,549 DEBUG [org.jasig.cas.ticket.registry.DefaultTicketRegistry] - <Attempting to retrieve ticket [TGT-1-zQLyVdvQR4nYD7vK2GmvRexjxYzXS97ZIUcjzcCDMdYDBh6Y6g-exAmpleSite.com]>
2015-04-27 10:28:06,549 DEBUG [org.jasig.cas.ticket.registry.DefaultTicketRegistry] - <Ticket [TGT-1-zQLyVdvQR4nYD7vK2GmvRexjxYzXS97ZIUcjzcCDMdYDBh6Y6g-exAmpleSite.com] found in registry.>
2015-04-27 10:28:06,551 DEBUG [org.jasig.cas.ticket.registry.DefaultTicketRegistry] - <Added ticket [ST-1-a2QNJmGQY1zt6LEKIuYn-exAmpleSite.com] to registry.>
2015-04-27 10:28:06,552 INFO [org.jasig.cas.CentralAuthenticationServiceImpl] - <Granted service ticket [ST-1-a2QNJmGQY1zt6LEKIuYn-exAmpleSite.com] for service [https://serv1.exAmpleSite.com:8443/c/portal/login?p_l_id=11407] for user [Harold]>
2015-04-27 10:28:06,552 DEBUG [org.jasig.cas.ticket.registry.DefaultTicketRegistry] - <Attempting to retrieve ticket [TGT-1-zQLyVdvQR4nYD7vK2GmvRexjxYzXS97ZIUcjzcCDMdYDBh6Y6g-exAmpleSite.com]>
2015-04-27 10:28:06,553 DEBUG [org.jasig.cas.ticket.registry.DefaultTicketRegistry] - <Ticket [TGT-1-zQLyVdvQR4nYD7vK2GmvRexjxYzXS97ZIUcjzcCDMdYDBh6Y6g-exAmpleSite.com] found in registry.>
2015-04-27 10:28:06,553 INFO [com.github.inspektr.audit.support.Slf4jLoggingAuditTrailManager] - <Audit trail record BEGIN
=============================================================
WHO: Harold
WHAT: ST-1-a2QNJmGQY1zt6LEKIuYn-exAmpleSite.com for https://serv1.exAmpleSite.com:8443/c/portal/login?p_l_id=11407
ACTION: SERVICE_TICKET_CREATED
APPLICATION: CAS
WHEN: Mon Apr 27 10:28:06 CEST 2015
CLIENT IP ADDRESS: 192.168.1.47
SERVER IP ADDRESS: 10.10.0.23
=============================================================

>
2015-04-27 10:28:06,554 DEBUG [org.springframework.orm.jpa.JpaTransactionManager] - <Initiating transaction commit>
2015-04-27 10:28:06,554 DEBUG [org.springframework.orm.jpa.JpaTransactionManager] - <Committing JPA transaction on EntityManager [org.hibernate.ejb.EntityManagerImpl@41c7bdb9]>
2015-04-27 10:28:06,555 DEBUG [org.springframework.orm.jpa.JpaTransactionManager] - <Closing JPA EntityManager [org.hibernate.ejb.EntityManagerImpl@41c7bdb9] after transaction>
2015-04-27 10:28:06,555 DEBUG [org.springframework.orm.jpa.EntityManagerFactoryUtils] - <Closing JPA EntityManager>
2015-04-27 10:28:06,555 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Finished executing org.jasig.cas.web.flow.GenerateServiceTicketAction@20a34324; result = success>
2015-04-27 10:28:06,556 DEBUG [org.springframework.webflow.execution.AnnotatedAction] - <Clearing action execution attributes map[[empty]]>
2015-04-27 10:28:06,556 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Finished executing [EvaluateAction@38b1cb70 expression = generateServiceTicketAction, resultExpression = [null]]; result = success>
2015-04-27 10:28:06,556 DEBUG [org.springframework.webflow.engine.Transition] - <Executing [Transition@5f52951b on = success, to = warn]>
2015-04-27 10:28:06,556 DEBUG [org.springframework.webflow.engine.Transition] - <Exiting state 'generateServiceTicket'>
2015-04-27 10:28:06,556 DEBUG [org.springframework.webflow.engine.DecisionState] - <Entering state 'warn' of flow 'login'>
2015-04-27 10:28:06,557 DEBUG [org.springframework.webflow.engine.Transition] - <Executing [Transition@26bb5081 on = *, to = redirect]>
2015-04-27 10:28:06,557 DEBUG [org.springframework.webflow.engine.Transition] - <Exiting state 'warn'>
2015-04-27 10:28:06,557 DEBUG [org.springframework.webflow.engine.ActionState] - <Entering state 'redirect' of flow 'login'>
2015-04-27 10:28:06,558 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Executing [EvaluateAction@53a25904 expression = flowScope.service.getResponse(requestScope.serviceTicketId), resultExpression = requestScope.response]>
2015-04-27 10:28:06,558 DEBUG [org.springframework.webflow.execution.AnnotatedAction] - <Putting action execution attributes map[[empty]]>
2015-04-27 10:28:06,566 DEBUG [org.springframework.webflow.execution.AnnotatedAction] - <Clearing action execution attributes map[[empty]]>
2015-04-27 10:28:06,566 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Finished executing [EvaluateAction@53a25904 expression = flowScope.service.getResponse(requestScope.serviceTicketId), resultExpression = requestScope.response]; result = success>
2015-04-27 10:28:06,567 DEBUG [org.springframework.webflow.engine.Transition] - <Executing [Transition@52fea682 on = *, to = postRedirectDecision]>
2015-04-27 10:28:06,567 DEBUG [org.springframework.webflow.engine.Transition] - <Exiting state 'redirect'>
2015-04-27 10:28:06,567 DEBUG [org.springframework.webflow.engine.DecisionState] - <Entering state 'postRedirectDecision' of flow 'login'>
2015-04-27 10:28:06,573 DEBUG [org.springframework.webflow.engine.Transition] - <Executing [Transition@619030c1 on = *, to = redirectView]>
2015-04-27 10:28:06,573 DEBUG [org.springframework.webflow.engine.Transition] - <Exiting state 'postRedirectDecision'>
2015-04-27 10:28:06,574 DEBUG [org.springframework.webflow.engine.EndState] - <Entering state 'redirectView' of flow 'login'>
2015-04-27 10:28:06,574 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Executing org.springframework.webflow.action.ViewFactoryActionAdapter@417100f1>
2015-04-27 10:28:06,575 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Executing org.springframework.webflow.action.ExternalRedirectAction@580d34f6>
2015-04-27 10:28:06,576 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Finished executing org.springframework.webflow.action.ExternalRedirectAction@580d34f6; result = success>
2015-04-27 10:28:06,576 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Finished executing org.springframework.webflow.action.ViewFactoryActionAdapter@417100f1; result = success>
2015-04-27 10:28:06,576 DEBUG [org.springframework.webflow.engine.Transition] - <Completed transition execution.  As a result, the flow execution has ended>
2015-04-27 10:28:06,577 DEBUG [org.springframework.webflow.engine.Transition] - <Completed transition execution.  As a result, the flow execution has ended>
2015-04-27 10:28:06,577 DEBUG [org.springframework.webflow.engine.Transition] - <Completed transition execution.  As a result, the flow execution has ended>
2015-04-27 10:28:06,577 DEBUG [org.springframework.webflow.engine.Transition] - <Completed transition execution.  As a result, the flow execution has ended>
2015-04-27 10:28:06,577 DEBUG [org.springframework.webflow.engine.Transition] - <Completed transition execution.  As a result, the flow execution has ended>
2015-04-27 10:28:06,577 DEBUG [org.springframework.webflow.engine.Transition] - <Completed transition execution.  As a result, the flow execution has ended>
2015-04-27 10:28:06,577 DEBUG [org.springframework.webflow.engine.Transition] - <Completed transition execution.  As a result, the flow execution has ended>
2015-04-27 10:28:06,577 DEBUG [org.springframework.webflow.engine.Transition] - <Completed transition execution.  As a result, the flow execution has ended>
2015-04-27 10:28:06,578 DEBUG [org.springframework.webflow.execution.repository.impl.DefaultFlowExecutionRepository] - <Removing flow execution '[Ended execution of 'login']' from repository>
2015-04-27 10:28:06,578 DEBUG [org.springframework.webflow.conversation.impl.SessionBindingConversationManager] - <Ending conversation 1>
2015-04-27 10:28:06,578 DEBUG [org.springframework.webflow.conversation.impl.SessionBindingConversationManager] - <Unlocking conversation 1>
2015-04-27 10:28:06,578 DEBUG [org.springframework.webflow.mvc.servlet.FlowHandlerAdapter] - <Sending external redirect to 'https://serv1.exAmpleSite.com:8443/c/portal/login?p_l_id=11407&ticket=ST-1-a2QNJmGQY1zt6LEKIuYn-exAmpleSite.com'>
2015-04-27 10:28:06,579 DEBUG [org.springframework.web.servlet.DispatcherServlet] - <Null ModelAndView returned to DispatcherServlet with name 'cas': assuming HandlerAdapter completed request handling>
2015-04-27 10:28:06,579 DEBUG [org.springframework.web.servlet.DispatcherServlet] - <Successfully completed request>
2015-04-27 10:28:09,934 DEBUG [org.springframework.web.servlet.DispatcherServlet] - <DispatcherServlet with name 'cas' processing GET request for [/cas/proxyValidate]>
2015-04-27 10:28:09,935 DEBUG [org.springframework.webflow.mvc.servlet.FlowHandlerMapping] - <No flow mapping found for request with URI '/cas/proxyValidate'>
2015-04-27 10:28:09,935 DEBUG [org.springframework.web.servlet.handler.SimpleUrlHandlerMapping] - <Mapping [/proxyValidate] to HandlerExecutionChain with handler [org.jasig.cas.web.ServiceValidateController@118510b7] and 1 interceptor>
2015-04-27 10:28:09,935 DEBUG [org.springframework.web.servlet.DispatcherServlet] - <Last-Modified value for [/cas/proxyValidate] is: -1>
2015-04-27 10:28:09,936 DEBUG [org.jasig.cas.web.support.CasArgumentExtractor] - <Extractor generated service for: https://serv1.exAmpleSite.com:8443/c/portal/login?p_l_id=11407>
2015-04-27 10:28:09,937 DEBUG [org.springframework.transaction.annotation.AnnotationTransactionAttributeSource] - <Adding transactional method 'validateServiceTicket' with attribute: PROPAGATION_REQUIRED,ISOLATION_DEFAULT; ''>
2015-04-27 10:28:09,939 DEBUG [org.springframework.beans.factory.support.DefaultListableBeanFactory] - <Returning cached instance of singleton bean 'transactionManager'>
2015-04-27 10:28:09,939 DEBUG [org.springframework.orm.jpa.JpaTransactionManager] - <Creating new transaction with name [org.jasig.cas.CentralAuthenticationServiceImpl.validateServiceTicket]: PROPAGATION_REQUIRED,ISOLATION_DEFAULT; ''>
2015-04-27 10:28:09,939 DEBUG [org.springframework.orm.jpa.JpaTransactionManager] - <Opened new EntityManager [org.hibernate.ejb.EntityManagerImpl@56fbf123] for JPA transaction>
2015-04-27 10:28:09,940 DEBUG [org.springframework.orm.jpa.JpaTransactionManager] - <Exposing JPA transaction as JDBC transaction [org.springframework.orm.jpa.vendor.HibernateJpaDialect$HibernateConnectionHandle@36945d72]>
2015-04-27 10:28:09,942 DEBUG [org.jasig.cas.ticket.registry.DefaultTicketRegistry] - <Attempting to retrieve ticket [ST-1-a2QNJmGQY1zt6LEKIuYn-exAmpleSite.com]>
2015-04-27 10:28:09,942 DEBUG [org.jasig.cas.ticket.registry.DefaultTicketRegistry] - <Ticket [ST-1-a2QNJmGQY1zt6LEKIuYn-exAmpleSite.com] found in registry.>
2015-04-27 10:28:09,942 DEBUG [org.jasig.cas.CentralAuthenticationServiceImpl] - <Principal id to return for service [null] is [Harold]. The default principal id is [Harold].>
2015-04-27 10:28:09,945 DEBUG [org.jasig.cas.ticket.registry.DefaultTicketRegistry] - <Removing ticket [ST-1-a2QNJmGQY1zt6LEKIuYn-exAmpleSite.com] from registry>
2015-04-27 10:28:09,946 DEBUG [org.jasig.cas.ticket.registry.DefaultTicketRegistry] - <Attempting to retrieve ticket [ST-1-a2QNJmGQY1zt6LEKIuYn-exAmpleSite.com]>
2015-04-27 10:28:09,946 INFO [com.github.inspektr.audit.support.Slf4jLoggingAuditTrailManager] - <Audit trail record BEGIN
=============================================================
WHO: audit:unknown
WHAT: ST-1-a2QNJmGQY1zt6LEKIuYn-exAmpleSite.com
ACTION: SERVICE_TICKET_VALIDATED
APPLICATION: CAS
WHEN: Mon Apr 27 10:28:09 CEST 2015
CLIENT IP ADDRESS: 192.168.1.47
SERVER IP ADDRESS: 10.10.0.23
=============================================================

>
2015-04-27 10:28:09,947 DEBUG [org.springframework.orm.jpa.JpaTransactionManager] - <Initiating transaction commit>
2015-04-27 10:28:09,947 DEBUG [org.springframework.orm.jpa.JpaTransactionManager] - <Committing JPA transaction on EntityManager [org.hibernate.ejb.EntityManagerImpl@56fbf123]>
2015-04-27 10:28:09,948 DEBUG [org.springframework.orm.jpa.JpaTransactionManager] - <Closing JPA EntityManager [org.hibernate.ejb.EntityManagerImpl@56fbf123] after transaction>
2015-04-27 10:28:09,948 DEBUG [org.springframework.orm.jpa.EntityManagerFactoryUtils] - <Closing JPA EntityManager>
2015-04-27 10:28:09,955 DEBUG [org.springframework.validation.DataBinder] - <DataBinder requires binding of required fields [renew]>
2015-04-27 10:28:09,970 DEBUG [org.jasig.cas.web.ServiceValidateController] - <Successfully validated service ticket: ST-1-a2QNJmGQY1zt6LEKIuYn-exAmpleSite.com>
2015-04-27 10:28:09,971 DEBUG [org.springframework.beans.factory.support.DefaultListableBeanFactory] - <Returning cached instance of singleton bean 'casServiceSuccessView'>
2015-04-27 10:28:09,971 DEBUG [org.springframework.web.servlet.DispatcherServlet] - <Rendering view [org.springframework.web.servlet.view.JstlView: name 'casServiceSuccessView'; URL [/WEB-INF/view/jsp/protocol/2.0/casServiceValidationSuccess.jsp]] in DispatcherServlet with name 'cas'>
2015-04-27 10:28:09,971 DEBUG [org.springframework.web.servlet.view.JstlView] - <Added model object 'assertion' of type [org.jasig.cas.validation.ImmutableAssertionImpl] to request in view with name 'casServiceSuccessView'>
2015-04-27 10:28:09,971 DEBUG [org.springframework.web.servlet.view.JstlView] - <Forwarding to resource [/WEB-INF/view/jsp/protocol/2.0/casServiceValidationSuccess.jsp] in InternalResourceView 'casServiceSuccessView'>
2015-04-27 10:28:09,999 DEBUG [org.springframework.web.servlet.DispatcherServlet] - <Successfully completed request>
2015-04-27 10:28:15,152 INFO [org.jasig.cas.services.DefaultServicesManagerImpl] - <Reloading registered services.>
2015-04-27 10:28:15,493 DEBUG [org.springframework.orm.jpa.JpaTemplate] - <Creating new EntityManager for JpaTemplate execution>
Hibernate: select abstractre0_.id as id0_, abstractre0_.allowedToProxy as allowedT3_0_, abstractre0_.anonymousAccess as anonymou4_0_, abstractre0_.description as descript5_0_, abstractre0_.enabled as enabled0_, abstractre0_.evaluation_order as evaluation7_0_, abstractre0_.ignoreAttributes as ignoreAt8_0_, abstractre0_.name as name0_, abstractre0_.serviceId as serviceId0_, abstractre0_.ssoEnabled as ssoEnabled0_, abstractre0_.theme as theme0_, abstractre0_.username_attr as username13_0_, abstractre0_.expression_type as expression1_0_ from RegisteredServiceImpl abstractre0_
2015-04-27 10:28:15,497 DEBUG [org.springframework.orm.jpa.JpaTemplate] - <Closing new EntityManager after JPA template execution>
2015-04-27 10:28:15,497 DEBUG [org.springframework.orm.jpa.EntityManagerFactoryUtils] - <Closing JPA EntityManager>
2015-04-27 10:28:15,498 INFO [org.jasig.cas.services.DefaultServicesManagerImpl] - <Loaded 0 services.>
2015-04-27 10:28:23,140 DEBUG [org.springframework.web.servlet.DispatcherServlet] - <DispatcherServlet with name 'cas' processing GET request for [/cas/proxyValidate]>
2015-04-27 10:28:23,141 DEBUG [org.springframework.webflow.mvc.servlet.FlowHandlerMapping] - <No flow mapping found for request with URI '/cas/proxyValidate'>
2015-04-27 10:28:23,141 DEBUG [org.springframework.web.servlet.handler.SimpleUrlHandlerMapping] - <Mapping [/proxyValidate] to HandlerExecutionChain with handler [org.jasig.cas.web.ServiceValidateController@118510b7] and 1 interceptor>
2015-04-27 10:28:23,141 DEBUG [org.springframework.web.servlet.DispatcherServlet] - <Last-Modified value for [/cas/proxyValidate] is: -1>
2015-04-27 10:28:23,142 DEBUG [org.jasig.cas.web.support.CasArgumentExtractor] - <Extractor generated service for: https://serv1.exAmpleSite.com:8443/c/portal/login?p_l_id=11407>
2015-04-27 10:28:23,142 DEBUG [org.springframework.beans.factory.support.DefaultListableBeanFactory] - <Returning cached instance of singleton bean 'transactionManager'>
2015-04-27 10:28:23,143 DEBUG [org.springframework.orm.jpa.JpaTransactionManager] - <Creating new transaction with name [org.jasig.cas.CentralAuthenticationServiceImpl.validateServiceTicket]: PROPAGATION_REQUIRED,ISOLATION_DEFAULT; ''>
2015-04-27 10:28:23,143 DEBUG [org.springframework.orm.jpa.JpaTransactionManager] - <Opened new EntityManager [org.hibernate.ejb.EntityManagerImpl@1ee26e61] for JPA transaction>
2015-04-27 10:28:23,144 DEBUG [org.springframework.orm.jpa.JpaTransactionManager] - <Exposing JPA transaction as JDBC transaction [org.springframework.orm.jpa.vendor.HibernateJpaDialect$HibernateConnectionHandle@23bcb21e]>
2015-04-27 10:28:23,145 DEBUG [org.jasig.cas.ticket.registry.DefaultTicketRegistry] - <Attempting to retrieve ticket [ST-1-a2QNJmGQY1zt6LEKIuYn-exAmpleSite.com]>
2015-04-27 10:28:23,145 INFO [org.jasig.cas.CentralAuthenticationServiceImpl] - <ServiceTicket [ST-1-a2QNJmGQY1zt6LEKIuYn-exAmpleSite.com] does not exist.>
2015-04-27 10:28:23,146 DEBUG [org.jasig.cas.ticket.registry.DefaultTicketRegistry] - <Attempting to retrieve ticket [ST-1-a2QNJmGQY1zt6LEKIuYn-exAmpleSite.com]>
2015-04-27 10:28:23,147 INFO [com.github.inspektr.audit.support.Slf4jLoggingAuditTrailManager] - <Audit trail record BEGIN
=============================================================
WHO: audit:unknown
WHAT: ST-1-a2QNJmGQY1zt6LEKIuYn-exAmpleSite.com
ACTION: SERVICE_TICKET_VALIDATE_FAILED
APPLICATION: CAS
WHEN: Mon Apr 27 10:28:23 CEST 2015
CLIENT IP ADDRESS: 192.168.1.47
SERVER IP ADDRESS: 10.10.0.23
=============================================================

>
2015-04-27 10:28:23,148 DEBUG [org.springframework.orm.jpa.JpaTransactionManager] - <Initiating transaction commit>
2015-04-27 10:28:23,148 DEBUG [org.springframework.orm.jpa.JpaTransactionManager] - <Committing JPA transaction on EntityManager [org.hibernate.ejb.EntityManagerImpl@1ee26e61]>
2015-04-27 10:28:23,149 DEBUG [org.springframework.orm.jpa.JpaTransactionManager] - <Closing JPA EntityManager [org.hibernate.ejb.EntityManagerImpl@1ee26e61] after transaction>
2015-04-27 10:28:23,149 DEBUG [org.springframework.orm.jpa.EntityManagerFactoryUtils] - <Closing JPA EntityManager>
2015-04-27 10:28:23,150 DEBUG [org.springframework.beans.factory.support.DefaultListableBeanFactory] - <Returning cached instance of singleton bean 'casServiceFailureView'>
2015-04-27 10:28:23,150 DEBUG [org.springframework.web.servlet.DispatcherServlet] - <Rendering view [org.springframework.web.servlet.view.JstlView: name 'casServiceFailureView'; URL [/WEB-INF/view/jsp/protocol/2.0/casServiceValidationFailure.jsp]] in DispatcherServlet with name 'cas'>
2015-04-27 10:28:23,150 DEBUG [org.springframework.web.servlet.view.JstlView] - <Added model object 'description' of type [java.lang.String] to request in view with name 'casServiceFailureView'>
2015-04-27 10:28:23,150 DEBUG [org.springframework.web.servlet.view.JstlView] - <Added model object 'code' of type [java.lang.String] to request in view with name 'casServiceFailureView'>
2015-04-27 10:28:23,151 DEBUG [org.springframework.web.servlet.view.JstlView] - <Forwarding to resource [/WEB-INF/view/jsp/protocol/2.0/casServiceValidationFailure.jsp] in InternalResourceView 'casServiceFailureView'>
2015-04-27 10:28:23,157 DEBUG [org.springframework.web.servlet.DispatcherServlet] - <Successfully completed request>