Hi,
A few times a day we see ticket not recognized errors that occur when the
client app attempts to validate the same ticket twice within a couple seconds.
Looking at the client app's access log, it appears that the user is caught in
some sort of redirect loop. This only happens sometimes. There are many users
using the system without a problem.
Does anyone know why a redirect loop like this might occur and how to prevent
it? If the client app page being requested redirects to another page within the
client app after authentication, could that cause problems with CAS?
We are using CAS 3.4.12 and phpCAS 1.3.2.
Any suggestions are much appreciated. Thank you!
-Tim
App access log:
{USER IP} - - [15/Aug/2013:10:52:08 -0400] "GET {APP URL}/ HTTP/1.1" 302 456
{USER IP} - - [15/Aug/2013:10:52:09 -0400] "GET {APP
URL}/?ticket=ST-235369-GE3X9xCZHE3LHBmvKQgq-cas HTTP/1.1" 302 -
{USER IP} - - [15/Aug/2013:10:52:09 -0400] "GET {APP URL}/ HTTP/1.1" 302 456
{USER IP} - - [15/Aug/2013:10:52:09 -0400] "GET {APP
URL}/?ticket=ST-235370-G0eeLBRkdAPoT5KmI4cW-cas HTTP/1.1" 302 -
{USER IP} - - [15/Aug/2013:10:52:09 -0400] "GET {APP URL}/ HTTP/1.1" 302 456
{USER IP} - - [15/Aug/2013:10:52:09 -0400] "GET {APP
URL}/?ticket=ST-235371-9jyVbi09QSiyE2SmGHkg-cas HTTP/1.1" 302 -
{USER IP} - - [15/Aug/2013:10:52:09 -0400] "GET {APP URL}/ HTTP/1.1" 302 456
{USER IP} - - [15/Aug/2013:10:52:09 -0400] "GET {APP
URL}/?ticket=ST-235372-HItmyzuCbp9iGiBx0sbV-cas HTTP/1.1" 302 -
{USER IP} - - [15/Aug/2013:10:52:10 -0400] "GET {APP URL}/ HTTP/1.1" 302 456
{USER IP} - - [15/Aug/2013:10:52:10 -0400] "GET {APP
URL}/?ticket=ST-235373-y0Ke4xagnJfL7TKCUz0c-cas HTTP/1.1" 302 -
{USER IP} - - [15/Aug/2013:10:52:10 -0400] "GET {APP URL}/ HTTP/1.1" 302 456
{USER IP} - - [15/Aug/2013:10:52:10 -0400] "GET {APP
URL}/?ticket=ST-235374-5PVKGtck9jcsyBjeQ5bc-cas HTTP/1.1" 302 -
{USER IP} - - [15/Aug/2013:10:52:11 -0400] "GET {APP URL}/ HTTP/1.1" 302 456
{USER IP} - - [15/Aug/2013:10:52:11 -0400] "GET {APP URL}/ HTTP/1.1" 302 456
{USER IP} - - [15/Aug/2013:10:52:11 -0400] "GET {APP
URL}/?ticket=ST-235376-uPlgJebsxOdLbndrgtVX-cas HTTP/1.1" 302 -
{USER IP} - - [15/Aug/2013:10:52:11 -0400] "GET {APP URL}/ HTTP/1.1" 302 456
{USER IP} - - [15/Aug/2013:10:52:11 -0400] "GET {APP
URL}/?ticket=ST-235377-autVDfodHGx3BIKAh75t-cas HTTP/1.1" 302 -
{USER IP} - - [15/Aug/2013:10:52:11 -0400] "GET {APP URL}/ HTTP/1.1" 302 456
{USER IP} - - [15/Aug/2013:10:52:11 -0400] "GET {APP
URL}/?ticket=ST-235379-c3RdGQXO9Eqx3QylRfu3-cas HTTP/1.1" 302 -
{USER IP} - - [15/Aug/2013:10:52:12 -0400] "GET {APP URL}/ HTTP/1.1" 302 456
{USER IP} - - [15/Aug/2013:10:52:12 -0400] "GET {APP
URL}/?ticket=ST-235380-xj4b2qYW7Da1MlgFdYUv-cas HTTP/1.1" 302 -
{USER IP} - - [15/Aug/2013:10:52:12 -0400] "GET {APP URL}/ HTTP/1.1" 302 456
{USER IP} - - [15/Aug/2013:10:52:12 -0400] "GET {APP
URL}/?ticket=ST-235381-BxTltz3eEGNPmYAUoBJz-cas HTTP/1.1" 302 -
{USER IP} - - [15/Aug/2013:10:52:12 -0400] "GET {APP URL}/ HTTP/1.1" 302 456
{USER IP} - - [15/Aug/2013:10:52:13 -0400] "GET {APP
URL}/?ticket=ST-235382-2dfrUqWPmGj21JUQrHnE-cas HTTP/1.1" 302 -
{USER IP} - - [15/Aug/2013:10:52:13 -0400] "GET {APP URL}/ HTTP/1.1" 302 456
{USER IP} - - [15/Aug/2013:10:52:14 -0400] "GET {APP
URL}/?ticket=ST-235383-6vjRbi5FIfXQfxH3hS6A-cas HTTP/1.1" 302 -
{USER IP} - - [15/Aug/2013:10:52:16 -0400] "GET {APP
URL}/?ticket=ST-235383-6vjRbi5FIfXQfxH3hS6A-cas HTTP/1.1" 200 1088
--> Error
{USER IP} - - [15/Aug/2013:10:52:24 -0400] "GET {APP URL}/ HTTP/1.1" 302 456
{USER IP} - - [15/Aug/2013:10:52:25 -0400] "GET {APP
URL}/?ticket=ST-235385-6A9qqwzSUdK4s1MUEHdc-cas HTTP/1.1" 302 -
{USER IP} - - [15/Aug/2013:10:52:25 -0400] "GET {APP URL}/ HTTP/1.1" 302 456
{USER IP} - - [15/Aug/2013:10:52:26 -0400] "GET {APP
URL}/?ticket=ST-235386-Xjtp2DyDIsfxkYEekcmO-cas HTTP/1.1" 302 -
{USER IP} - - [15/Aug/2013:10:52:26 -0400] "GET {APP URL}/ HTTP/1.1" 302 456
{USER IP} - - [15/Aug/2013:10:52:28 -0400] "GET {APP
URL}/?ticket=ST-235388-zXyhO5eP9LPM6aCqQgiX-cas HTTP/1.1" 302 -
{USER IP} - - [15/Aug/2013:10:52:28 -0400] "GET {APP URL}/ HTTP/1.1" 302 456
{USER IP} - - [15/Aug/2013:10:52:29 -0400] "GET {APP
URL}/?ticket=ST-235389-5LfgACcVia6sG4y5z7wf-cas HTTP/1.1" 302 -
{USER IP} - - [15/Aug/2013:10:52:29 -0400] "GET {APP URL}/ HTTP/1.1" 302 456
{USER IP} - - [15/Aug/2013:10:52:29 -0400] "GET {APP
URL}/?ticket=ST-235390-FXyvKjj0ByuLLqlptg6N-cas HTTP/1.1" 302 -
{USER IP} - - [15/Aug/2013:10:52:30 -0400] "GET {APP URL}/ HTTP/1.1" 302 456
{USER IP} - - [15/Aug/2013:10:52:30 -0400] "GET {APP
URL}/?ticket=ST-235391-HKk1jFRzAzbGsNAcbgyI-cas HTTP/1.1" 302 -
{USER IP} - - [15/Aug/2013:10:52:30 -0400] "GET {APP URL}/ HTTP/1.1" 302 456
{USER IP} - - [15/Aug/2013:10:52:30 -0400] "GET {APP
URL}/?ticket=ST-235392-r2Ok4gvYBXyRcQ2UnKl4-cas HTTP/1.1" 302 -
{USER IP} - - [15/Aug/2013:10:53:07 -0400] "GET {APP URL}/ HTTP/1.1" 302 456
{USER IP} - - [15/Aug/2013:10:53:07 -0400] "GET {APP
URL}/?ticket=ST-235400-ycfdNWuBNeVtWGm2BlmH-cas HTTP/1.1" 302 -
{USER IP} - - [15/Aug/2013:10:53:07 -0400] "GET {APP URL}/ HTTP/1.1" 302 -
{USER IP} - - [15/Aug/2013:10:53:07 -0400] "GET {APP URL}/{APP FILE NAME}?{APP
QUERY STRING} HTTP/1.1" 200 2044
Application code:
if ( ! isset($_SESSION['user']))
{
include_once({CAS PATH}/CAS-1.3.2/CAS.php');
phpCAS::setDebug({LOG PATH});
phpCAS::client(CAS_VERSION_2_0, {CAS URL}, 443, 'cas');
// phpCAS::setNoCasServerValidation();
phpCAS::setCasServerCACert({CERT PATH});
phpCAS::handleLogoutRequests(true);
phpCAS::forceAuthentication();
$_SESSION['user'] = phpCAS::getUser();
}
phpCAS log:
EE53 .START phpCAS-1.3.2 ****************** [CAS.php:450]
EE53 .=> phpCAS::client('2.0', '{CAS URL}', 443, 'cas') [User.php:71]
EE53 .| => CAS_Client::__construct('2.0', false, '{CAS URL}', 443, 'cas',
true) [CAS.php:347]
EE53 .| | Ticket 'ST-235383-6vjRbi5FIfXQfxH3hS6A-cas' found
[Client.php:870]
EE53 .| <= ''
EE53 .<= ''
EE53 .=> phpCAS::setCasServerCACert('{CERT PATH}') [User.php:75]
EE53 .<= ''
EE53 .=> CAS_Client::handleLogoutRequests(true, false) [CAS.php:1299]
EE53 .| Not a logout request [Client.php:1469]
EE53 .<= ''
EE53 .=> phpCAS::forceAuthentication() [User.php:79]
EE53 .| => CAS_Client::forceAuthentication() [CAS.php:1101]
EE53 .| | => CAS_Client::isAuthenticated() [Client.php:1083]
EE53 .| | | => CAS_Client::_wasPreviouslyAuthenticated()
[Client.php:1189]
EE53 .| | | | no user found [Client.php:1375]
EE53 .| | | <= false
EE53 .| | | CAS 2.0 ticket `ST-235383-6vjRbi5FIfXQfxH3hS6A-cas' is
present [Client.php:1223]
EE53 .| | | => CAS_Client::validateCAS20('', NULL, NULL)
[Client.php:1224]
EE53 .| | | | [Client.php:2747]
EE53 .| | | | => CAS_Client::getServerServiceValidateURL()
[Client.php:2753]
EE53 .| | | | | => CAS_Client::getURL() [Client.php:417]
EE53 .| | | | | | Final URI: {APP URL} [Client.php:3071]
EE53 .| | | | | <= '{APP URL}'
EE53 .| | | | <= 'https://{CAS
URL}/cas/serviceValidate?service={APP URL}'
EE53 .| | | | => CAS_Client::_readURL('https://{CAS
URL}/cas/serviceValidate?service={APP
URL}&ticket=ST-235383-6vjRbi5FIfXQfxH3hS6A-cas', NULL, NULL, NULL)
[Client.php:2762]
EE53 .| | | | | => CAS_Request_CurlRequest::sendRequest()
[AbstractRequest.php:220]
EE53 .| | | | | | CURL: Set CURLOPT_CAINFO {CERT PATH}
[CurlRequest.php:127]
EE53 .| | | | | | Response Body:
EE53 .| | | | | | <cas:serviceResponse
xmlns:cas='http://www.yale.edu/tp/cas'>
EE53 .| | | | | | <cas:authenticationSuccess>
EE53 .| | | | | |
<cas:user>{USERNAME}</cas:user>
EE53 .| | | | | |
EE53 .| | | | | |
EE53 .| | | | | | </cas:authenticationSuccess>
EE53 .| | | | | | </cas:serviceResponse>
EE53 .| | | | | | [CurlRequest.php:82]
EE53 .| | | | | <= true
EE53 .| | | | <= true
EE53 .| | | | => CAS_Client::_readExtraAttributesCas20(DOMNodeList)
[Client.php:2813]
EE53 .| | | | | Testing for rubycas style attributes
[Client.php:2923]
EE53 .| | | | <= ''
EE53 .| | | | Storing Proxy List [Client.php:2822]
EE53 .| | | | =>
CAS_ProxyChain_AllowedList::isProxyListAllowed(array ()) [Client.php:2825]
EE53 .| | | | | No proxies were found in the response
[AllowedList.php:81]
EE53 .| | | | <= true
EE53 .| | | | =>
CAS_Client::_renameSession('ST-235383-6vjRbi5FIfXQfxH3hS6A-cas')
[Client.php:2856]
EE53 .| | | | | Session ID: ST-235383-6vjRbi5FIfXQfxH3hS6A-cas
[Client.php:3180]
EE53 .| | | | | Restoring old session vars [Client.php:3183]
EE53 .| | | | <= ''
EE53 .| | | <= true
EE53 .| | | CAS 2.0 ticket `ST-235383-6vjRbi5FIfXQfxH3hS6A-cas' was
validated [Client.php:1225]
EE53 .| | | => CAS_Client::getURL() [Client.php:1279]
EE53 .| | | <= '{APP URL}'
EE53 .| | | Prepare redirect to : {APP URL} [Client.php:1279]
EE53 .| | | => CAS_Client::getURL() [Client.php:1280]
EE53 .| | | <= '{APP URL}'
EE53 .| | | exit()
EE53 .| | | -
EE53 .| | -
EE53 .| -
4C07 .START phpCAS-1.3.2 ****************** [CAS.php:450]
4C07 .=> phpCAS::client('2.0', '{CAS URL}', 443, 'cas') [User.php:71]
4C07 .| => CAS_Client::__construct('2.0', false, '{CAS URL}', 443, 'cas',
true) [CAS.php:347]
4C07 .| | Ticket 'ST-235383-6vjRbi5FIfXQfxH3hS6A-cas' found
[Client.php:870]
4C07 .| <= ''
4C07 .<= ''
4C07 .=> phpCAS::setCasServerCACert('{CERT PATH}') [User.php:75]
4C07 .<= ''
4C07 .=> CAS_Client::handleLogoutRequests(true, false) [CAS.php:1299]
4C07 .| Not a logout request [Client.php:1469]
4C07 .<= ''
4C07 .=> phpCAS::forceAuthentication() [User.php:79]
4C07 .| => CAS_Client::forceAuthentication() [CAS.php:1101]
4C07 .| | => CAS_Client::isAuthenticated() [Client.php:1083]
4C07 .| | | => CAS_Client::_wasPreviouslyAuthenticated()
[Client.php:1189]
4C07 .| | | | no user found [Client.php:1375]
4C07 .| | | <= false
4C07 .| | | CAS 2.0 ticket `ST-235383-6vjRbi5FIfXQfxH3hS6A-cas' is
present [Client.php:1223]
4C07 .| | | => CAS_Client::validateCAS20('', NULL, NULL)
[Client.php:1224]
4C07 .| | | | [Client.php:2747]
4C07 .| | | | => CAS_Client::getServerServiceValidateURL()
[Client.php:2753]
4C07 .| | | | | => CAS_Client::getURL() [Client.php:417]
4C07 .| | | | | | Final URI: {APP URL} [Client.php:3071]
4C07 .| | | | | <= '{APP URL}'
4C07 .| | | | <= 'https://{CAS
URL}/cas/serviceValidate?service={APP URL}'
4C07 .| | | | => CAS_Client::_readURL('https://{CAS
URL}/cas/serviceValidate?service={APP
URL}&ticket=ST-235383-6vjRbi5FIfXQfxH3hS6A-cas', NULL, NULL, NULL)
[Client.php:2762]
4C07 .| | | | | => CAS_Request_CurlRequest::sendRequest()
[AbstractRequest.php:220]
4C07 .| | | | | | CURL: Set CURLOPT_CAINFO {CERT PATH}
[CurlRequest.php:127]
4C07 .| | | | | | Response Body:
4C07 .| | | | | | <cas:serviceResponse
xmlns:cas='http://www.yale.edu/tp/cas'>
4C07 .| | | | | | <cas:authenticationFailure
code='INVALID_TICKET'>
4C07 .| | | | | | ticket
'ST-235383-6vjRbi5FIfXQfxH3hS6A-cas' not recognized
4C07 .| | | | | | </cas:authenticationFailure>
4C07 .| | | | | | </cas:serviceResponse>
4C07 .| | | | | | [CurlRequest.php:82]
4C07 .| | | | | <= true
4C07 .| | | | <= true
4C07 .| | | | =>
CAS_AuthenticationException::__construct(CAS_Client, 'Ticket not validated',
'https://{CAS URL}/cas/serviceValidate?service={APP
URL}&ticket=ST-235383-6vjRbi5FIfXQfxH3hS6A-cas', false, false,
'<cas:serviceResponse xmlns:cas=\'http://www.yale.edu/tp/cas\'>
<cas:authenticationFailure code=\'INVALID_TICKET\'> ticket
'ST-235383-6vjRbi5FIfXQfxH3hS6A-cas' not recognized
</cas:authenticationFailure></cas:serviceResponse>', 'INVALID_TICKET', 'ticket
\'ST-235383-6vjRbi5FIfXQfxH3hS6A-cas\' not recognized') [Client.php:2845]
4C07 .| | | | | => CAS_Client::getURL()
[AuthenticationException.php:76]
4C07 .| | | | | <= '{APP URL}'
4C07 .| | | | | CAS URL: https://{CAS
URL}/cas/serviceValidate?service={APP
URL}&ticket=ST-235383-6vjRbi5FIfXQfxH3hS6A-cas [AuthenticationException.php:79]
4C07 .| | | | | Authentication failure: Ticket not validated
[AuthenticationException.php:80]
4C07 .| | | | | Reason: [INVALID_TICKET] CAS error: ticket
'ST-235383-6vjRbi5FIfXQfxH3hS6A-cas' not recognized
[AuthenticationException.php:95]
4C07 .| | | | | CAS response: <cas:serviceResponse
xmlns:cas='http://www.yale.edu/tp/cas'>
4C07 .| | | | | <cas:authenticationFailure
code='INVALID_TICKET'>
4C07 .| | | | | ticket
'ST-235383-6vjRbi5FIfXQfxH3hS6A-cas' not recognized
4C07 .| | | | | </cas:authenticationFailure>
4C07 .| | | | | </cas:serviceResponse>
[AuthenticationException.php:100]
4C07 .| | | | | exit()
4C07 .| | | | | -
4C07 .| | | | -
4C07 .| | | -
4C07 .| | -
4C07 .| -
CAS log:
2013-08-15 10:52:13,933 DEBUG
[org.jasig.cas.ticket.registry.DefaultTicketRegistry] - Added ticket
[ST-235383-6vjRbi5FIfXQfxH3hS6A-cas] to registry.
2013-08-15 10:52:13,934 INFO [org.jasig.cas.CentralAuthenticationServiceImpl] -
Granted service ticket [ST-235383-6vjRbi5FIfXQfxH3hS6A-cas] for service [{APP
URL}] for user [{USERNAME}]
2013-08-15 10:52:13,934 DEBUG
[org.jasig.cas.ticket.registry.DefaultTicketRegistry] - Attempting to retrieve
ticket [TGT-87485-OfECdkBsig7opkDf166VK1GQTn2cU9fUipEniheqKu1BeofArR-cas]
2013-08-15 10:52:13,934 DEBUG
[org.jasig.cas.ticket.registry.DefaultTicketRegistry] - Ticket
[TGT-87485-OfECdkBsig7opkDf166VK1GQTn2cU9fUipEniheqKu1BeofArR-cas] found in
registry.
2013-08-15 10:52:13,934 INFO
[com.github.inspektr.audit.support.Slf4jLoggingAuditTrailManager] - Audit trail
record BEGIN
=============================================================
WHO: {USERNAME}
WHAT: ST-235383-6vjRbi5FIfXQfxH3hS6A-cas for {APP URL}
ACTION: SERVICE_TICKET_CREATED
APPLICATION: CAS
WHEN: Thu Aug 15 10:52:13 EDT 2013
CLIENT IP ADDRESS: {USER IP}
SERVER IP ADDRESS: {CAS IP}
=============================================================
2013-08-15 10:52:14,283 DEBUG [org.jasig.cas.web.support.CasArgumentExtractor]
- Extractor generated service for: {APP URL}
2013-08-15 10:52:14,283 DEBUG
[org.jasig.cas.ticket.registry.DefaultTicketRegistry] - Attempting to retrieve
ticket [ST-235383-6vjRbi5FIfXQfxH3hS6A-cas]
2013-08-15 10:52:14,283 DEBUG
[org.jasig.cas.ticket.registry.DefaultTicketRegistry] - Ticket
[ST-235383-6vjRbi5FIfXQfxH3hS6A-cas] found in registry.
2013-08-15 10:52:14,283 DEBUG
[org.jasig.cas.ticket.registry.DefaultTicketRegistry] - Removing ticket
[ST-235383-6vjRbi5FIfXQfxH3hS6A-cas] from registry
2013-08-15 10:52:14,283 DEBUG
[org.jasig.cas.ticket.registry.DefaultTicketRegistry] - Attempting to retrieve
ticket [ST-235383-6vjRbi5FIfXQfxH3hS6A-cas]
2013-08-15 10:52:14,283 INFO
[com.github.inspektr.audit.support.Slf4jLoggingAuditTrailManager] - Audit trail
record BEGIN
=============================================================
WHO: audit:unknown
WHAT: ST-235383-6vjRbi5FIfXQfxH3hS6A-cas
ACTION: SERVICE_TICKET_VALIDATED
APPLICATION: CAS
WHEN: Thu Aug 15 10:52:14 EDT 2013
CLIENT IP ADDRESS: {APP IP}
SERVER IP ADDRESS: {CAS IP}
=============================================================
2013-08-15 10:52:14,284 DEBUG [org.jasig.cas.web.ServiceValidateController] -
Successfully validated service ticket: ST-235383-6vjRbi5FIfXQfxH3hS6A-cas
...
2013-08-15 10:52:16,702 DEBUG [org.jasig.cas.web.support.CasArgumentExtractor]
- Extractor generated service for: {APP URL}
2013-08-15 10:52:16,702 DEBUG
[org.jasig.cas.ticket.registry.DefaultTicketRegistry] - Attempting to retrieve
ticket [ST-235383-6vjRbi5FIfXQfxH3hS6A-cas]
2013-08-15 10:52:16,702 INFO [org.jasig.cas.CentralAuthenticationServiceImpl] -
ServiceTicket [ST-235383-6vjRbi5FIfXQfxH3hS6A-cas] does not exist.
2013-08-15 10:52:16,702 DEBUG
[org.jasig.cas.ticket.registry.DefaultTicketRegistry] - Attempting to retrieve
ticket [ST-235383-6vjRbi5FIfXQfxH3hS6A-cas]
2013-08-15 10:52:16,702 INFO
[com.github.inspektr.audit.support.Slf4jLoggingAuditTrailManager] - Audit trail
record BEGIN
=============================================================
WHO: audit:unknown
WHAT: ST-235383-6vjRbi5FIfXQfxH3hS6A-cas
ACTION: SERVICE_TICKET_VALIDATE_FAILED
APPLICATION: CAS
WHEN: Thu Aug 15 10:52:16 EDT 2013
CLIENT IP ADDRESS: {APP IP}
SERVER IP ADDRESS: {CAS IP}
=============================================================
--
You are currently subscribed to [email protected] as:
[email protected]
To unsubscribe, change settings or access archives, see
http://www.ja-sig.org/wiki/display/JSG/cas-user
