CAS Cluster, but, only validate ST and TGT if the call comes from the server issued it

[Yan Zhou]

Hello,

I have two CAS (CAS 4.1.9 overlay) servers running separately, they both point to the same 3rd server running memcached.  Is that shared ticket registry (i.e., the 3rd server is the ticket store, shared by the two CAS server)?

However, if the call to generate TGT or ST are made on server 1, then subsequent calls has to be from the same server for it to work. If the subsequent calls are from server 2, then I am getting "ticket not found", see below for error when /serverValidate is called on Server 2 but ST is issued by Server 1. 

Why is that the case, the 2nd server will look up in the same ticket registry (which is memcached on the 3rd server), as the 1st server would,  but why one fails but the other works?

I enabled debug logging on net.spy.memcached client, I cannot figure it out, I do not think that is a memcached client issue, though.  All I can see is "Failed fetching error" without any details, I do not know what it is "waiting for".

Can some render help?

Thx!

sever 2 (failed to validate tickets)

2016-08-08 21:12:13,825 DEBUG [net.spy.memcached.MemcachedConnection] - Handling IO for:  sun.nio.ch.SelectionKeyImpl@75e50bef (r=true, w=false, c=false, op={QA sa=qacas01.qa.medplus.com/172.18.38.111:11211, #Rops=1, #Wops=0, #iq=0, topRop=Cmd: 0 Opaque: 2 Key: ST-1-YL50uuFNN4MgQBTm1VHM-dcasde01.dev.medplus.com, topWop=null, toWrite=0, interested=1})

2016-08-08 21:12:13,825 DEBUG [net.spy.memcached.MemcachedConnection] - Read 599 bytes

2016-08-08 21:12:13,825 DEBUG [net.spy.memcached.protocol.binary.GetOperationImpl] - Reading 24 header bytes

2016-08-08 21:12:13,825 DEBUG [net.spy.memcached.protocol.binary.GetOperationImpl] - Reading 575 payload bytes

2016-08-08 21:12:13,826 DEBUG [net.spy.memcached.protocol.binary.GetOperationImpl] - Transitioned state from READING to COMPLETE

2016-08-08 21:12:13,826 DEBUG [net.spy.memcached.MemcachedConnection] - Completed read op: Cmd: 0 Opaque: 2 Key: ST-1-YL50uuFNN4MgQBTm1VHM-dcasde01.dev.medplus.com and giving the next 0 bytes

2016-08-08 21:12:13,826 DEBUG [net.spy.memcached.protocol.binary.BinaryMemcachedNodeImpl] - Setting interested opts to 0

2016-08-08 21:12:13,826 DEBUG [net.spy.memcached.MemcachedConnection] - Done dealing with queue.

2016-08-08 21:12:13,826 DEBUG [net.spy.memcached.MemcachedConnection] - Selecting with delay of 1000ms

2016-08-08 21:12:13,827 ERROR [org.jasig.cas.ticket.registry.MemCacheTicketRegistry] - Failed fetching [ST-1-YL50uuFNN4MgQBTm1VHM-dcasde01.dev.medplus.com, java.lang.RuntimeException: Exception waiting for value]

2016-08-08 21:12:13,835 INFO [org.jasig.inspektr.audit.support.Slf4jLoggingAuditTrailManager] - Audit trail record BEGIN

=============================================================

WHO: audit:unknown

WHAT: ST-1-YL50uuFNN4MgQBTm1VHM-dcasde01.dev.medplus.com

ACTION: SERVICE_TICKET_VALIDATE_FAILED

APPLICATION: CAS

WHEN: Mon Aug 08 21:12:13 UTC 2016

CLIENT IP ADDRESS: 172.18.100.19

SERVER IP ADDRESS: 172.18.38.131

=============================================================

2016-08-08 21:12:13,872 INFO [org.springframework.web.context.support.GenericWebApplicationContext] - Refreshing org.springframework.web.context.support.GenericWebApplicationContext@7336a963: startup date [Mon Aug 08 21:12:13 UTC 2016]; parent: WebApplicationContext for namespace 'cas-servlet'

server 1 (success)

2016-08-08 21:13:12,102 DEBUG [net.spy.memcached.MemcachedConnection] - Handling IO for:  sun.nio.ch.SelectionKeyImpl@53e35b7f (r=true, w=false, c=false, op={QA sa=qacas01.qa.medplus.com/172.18.38.111:11211, #Rops=1, #Wops=0, #iq=0, topRop=Cmd: 4 Opaque: 13 Key: ST-1-YL50uuFNN4MgQBTm1VHM-dcasde01.dev.medplus.com Cas: 0, topWop=null, toWrite=0, interested=1})

2016-08-08 21:13:12,102 DEBUG [net.spy.memcached.MemcachedConnection] - Read 24 bytes

2016-08-08 21:13:12,102 DEBUG [net.spy.memcached.protocol.binary.DeleteOperationImpl] - Reading 24 header bytes

2016-08-08 21:13:12,102 DEBUG [net.spy.memcached.protocol.binary.DeleteOperationImpl] - Reading 0 payload bytes

2016-08-08 21:13:12,102 DEBUG [net.spy.memcached.protocol.binary.DeleteOperationImpl] - Transitioned state from READING to COMPLETE

2016-08-08 21:13:12,103 DEBUG [net.spy.memcached.MemcachedConnection] - Completed read op: Cmd: 4 Opaque: 13 Key: ST-1-YL50uuFNN4MgQBTm1VHM-dcasde01.dev.medplus.com Cas: 0 and giving the next 0 bytes

2016-08-08 21:13:12,103 DEBUG [net.spy.memcached.protocol.binary.BinaryMemcachedNodeImpl] - Setting interested opts to 0

2016-08-08 21:13:12,103 DEBUG [net.spy.memcached.MemcachedConnection] - Done dealing with queue.

2016-08-08 21:13:12,103 DEBUG [net.spy.memcached.MemcachedConnection] - Selecting with delay of 1000ms

2016-08-08 21:13:12,104 INFO [org.jasig.inspektr.audit.support.Slf4jLoggingAuditTrailManager] - Audit trail record BEGIN

=============================================================

WHO: y

WHAT: ST-1-YL50uuFNN4MgQBTm1VHM-dcasde01.dev.medplus.com

ACTION: SERVICE_TICKET_VALIDATED

APPLICATION: CAS

WHEN: Mon Aug 08 21:13:12 UTC 2016

CLIENT IP ADDRESS: 172.18.100.19

SERVER IP ADDRESS: 172.18.38.130

=============================================================

2016-08-08 21:13:12,123 INFO [org.springframework.web.context.support.GenericWebApplicationContext] - Refreshing org.springframework.web.context.support.GenericWebApplicationContext@784524ca: startup date [Mon Aug 08 21:13:12 UTC 2016]; parent: WebApplicationContext for namespace 'cas-servlet'

2016-08-08 21:13:13,104 DEBUG [net.spy.memcached.MemcachedConnection] - Done dealing with queue.