memcached registry, failed fetching error

[Yan Zhou]

Hi there,

We have two CAS server behind F5 load balancer, each runs memcached. 

cas.properties on both server reads:  memcached.servers=dcasde01.dev.medplus.com:11211, dcasde02.dev.medplus.com:11211

the problem I run into intermittently, is that server 1 issues a service ticket and /serviceValidate is called immediately on server 2, but server 2 cannot find the service ticket. 

I turned on debug mode on net.spy.memcached client, still cannot figure out what was wrong.

Thanks,

Yan

dcasde01 (server 1) node:  it generates ST, write and read complete

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

2016-08-02 19:18:19,261 DEBUG [net.spy.memcached.MemcachedConnection] - Added Cmd: 2 Opaque: 17 Key: ST-2-IuotzVXFdjPUucLs2ZVm-dcasde01.dev.medplus.com Cas: 0 Exp: 10 Flags: 0 Data Length: 777 to {QA sa=dcasde01.dev.medplus.com/172.18.38.130:11211, #Rops=0, #Wops=0, #iq=1, topRop=null, topWop=null, toWrite=0, interested=0}

2016-08-02 19:18:19,263 DEBUG [net.spy.memcached.MemcachedConnection] - Handling IO for:  sun.nio.ch.SelectionKeyImpl@6418da19 (r=false, w=true, c=false, op={QA sa=dcasde01.dev.medplus.com/172.18.38.130:11211, #Rops=0, #Wops=1, #iq=0, topRop=null, topWop=Cmd: 2 Opaque: 17 Key: ST-2-IuotzVXFdjPUucLs2ZVm-dcasde01.dev.medplus.com Cas: 0 Exp: 10 Flags: 0 Data Length: 777, toWrite=0, interested=4})

2016-08-02 19:18:19,263 DEBUG [net.spy.memcached.protocol.binary.StoreOperationImpl] - Transitioned state from WRITE_QUEUED to WRITING

2016-08-02 19:18:19,264 DEBUG [net.spy.memcached.protocol.binary.BinaryMemcachedNodeImpl] - After copying stuff from Cmd: 2 Opaque: 17 Key: ST-2-IuotzVXFdjPUucLs2ZVm-dcasde01.dev.medplus.com Cas: 0 Exp: 10 Flags: 0 Data Length: 777: java.nio.DirectByteBuffer[pos=859 lim=16384 cap=16384]

2016-08-02 19:18:19,264 DEBUG [net.spy.memcached.protocol.binary.StoreOperationImpl] - Transitioned state from WRITING to READING

2016-08-02 19:18:19,264 DEBUG [net.spy.memcached.protocol.binary.BinaryMemcachedNodeImpl] - Finished writing Cmd: 2 Opaque: 17 Key: ST-2-IuotzVXFdjPUucLs2ZVm-dcasde01.dev.medplus.com Cas: 0 Exp: 10 Flags: 0 Data Length: 777

2016-08-02 19:18:19,265 DEBUG [net.spy.memcached.MemcachedConnection] - Handling IO for:  sun.nio.ch.SelectionKeyImpl@6418da19 (r=true, w=false, c=false, op={QA sa=dcasde01.dev.medplus.com/172.18.38.130:11211, #Rops=1, #Wops=0, #iq=0, topRop=Cmd: 2 Opaque: 17 Key: ST-2-IuotzVXFdjPUucLs2ZVm-dcasde01.dev.medplus.com Cas: 0 Exp: 10 Flags: 0 Data Length: 777, topWop=null, toWrite=0, interested=1})

2016-08-02 19:18:19,266 DEBUG [net.spy.memcached.MemcachedConnection] - Completed read op: Cmd: 2 Opaque: 17 Key: ST-2-IuotzVXFdjPUucLs2ZVm-dcasde01.dev.medplus.com Cas: 0 Exp: 10 Flags: 0 Data Length: 777 and giving the next 0 bytes

2016-08-02 19:18:19,267 DEBUG [net.spy.memcached.MemcachedConnection] - Selecting with delay of 1000ms

2016-08-02 19:18:19,267 INFO [org.jasig.cas.CentralAuthenticationServiceImpl] - Granted ticket [ST-2-IuotzVXFdjPUucLs2ZVm-dcasde01.dev.medplus.com] for service [https://intcas.dev.medplus.com/cas-services/login/cas] for user [castempadmin]

2016-08-02 19:18:19,267 DEBUG [net.spy.memcached.MemcachedConnection] - Added Cmd: 0 Opaque: 18 Key: TGT-TGT-**********************************************DfT6jtz6yn-dcasde01.dev.medplus.com to {QA sa=dcasde02.dev.medplus.com/172.18.38.131:11211, #Rops=0, #Wops=0, #iq=1, topRop=null, topWop=null, toWrite=0, interested=0}

2016-08-02 19:18:19,294 INFO [org.jasig.inspektr.audit.support.Slf4jLoggingAuditTrailManager] - Audit trail record BEGIN

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

WHO: castempadmin

WHAT: ST-2-IuotzVXFdjPUucLs2ZVm-dcasde01.dev.medplus.com for https://intcas.dev.medplus.com/cas-services/login/cas

ACTION: SERVICE_TICKET_CREATED

APPLICATION: CAS

WHEN: Tue Aug 02 19:18:19 UTC 2016

CLIENT IP ADDRESS: 172.18.100.57

SERVER IP ADDRESS: 172.18.38.130

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

dcasde02 (server 2)  node access logs, /serviceValidate is called immediately afterwards

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

172.18.38.131 - - [02/Aug/2016:19:18:20 +0000] "GET /cas/p3/serviceValidate?ticket=ST-2-IuotzVXFdjPUucLs2ZVm-dcasde01.dev.medplus.com&service=https%3A%2F%2Fintcas.dev.medplus.com%2Fcas-services%2Flogin%2Fcas HTTP/1.1" 200 271 "-" "Java/1.7.0_75"

172.18.100.57 - - [02/Aug/2016:19:18:21 +0000] "GET /cas-services/login/cas?ticket=ST-2-IuotzVXFdjPUucLs2ZVm-dcasde01.dev.medplus.com HTTP/1.1" 302 - "-" "Mozilla/5.0 (Windows NT 6.1; WOW64; rv:47.0) Gecko/20100101 Firefox/47.0"

dcasde02 (server 2)  node, it failed fetching and again writes to memcached running on the other server

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

2016-08-02 19:18:19,597 DEBUG [net.spy.memcached.MemcachedConnection] - Added Cmd: 0 Opaque: 1 Key: ST-2-IuotzVXFdjPUucLs2ZVm-dcasde01.dev.medplus.com to {QA sa=dcasde01.dev.medplus.com/172.18.38.130:11211, #Rops=0, #Wops=0, #iq=1, topRop=null, topWop=null, toWrite=0, interested=0}

2016-08-02 19:18:19,599 DEBUG [net.spy.memcached.MemcachedConnection] - Handling IO for:  sun.nio.ch.SelectionKeyImpl@774ead62 (r=false, w=true, c=false, op={QA sa=dcasde01.dev.medplus.com/172.18.38.130:11211, #Rops=0, #Wops=1, #iq=0, topRop=null, topWop=Cmd: 0 Opaque: 1 Key: ST-2-IuotzVXFdjPUucLs2ZVm-dcasde01.dev.medplus.com, toWrite=0, interested=4})

2016-08-02 19:18:19,604 DEBUG [net.spy.memcached.protocol.binary.BinaryMemcachedNodeImpl] - After copying stuff from Cmd: 0 Opaque: 1 Key: ST-2-IuotzVXFdjPUucLs2ZVm-dcasde01.dev.medplus.com: java.nio.DirectByteBuffer[pos=74 lim=16384 cap=16384]

2016-08-02 19:18:19,604 DEBUG [net.spy.memcached.protocol.binary.BinaryMemcachedNodeImpl] - Finished writing Cmd: 0 Opaque: 1 Key: ST-2-IuotzVXFdjPUucLs2ZVm-dcasde01.dev.medplus.com

2016-08-02 19:18:19,606 DEBUG [net.spy.memcached.MemcachedConnection] - Handling IO for:  sun.nio.ch.SelectionKeyImpl@774ead62 (r=true, w=false, c=false, op={QA sa=dcasde01.dev.medplus.com/172.18.38.130:11211, #Rops=1, #Wops=0, #iq=0, topRop=Cmd: 0 Opaque: 1 Key: ST-2-IuotzVXFdjPUucLs2ZVm-dcasde01.dev.medplus.com, topWop=null, toWrite=0, interested=1})

2016-08-02 19:18:19,609 DEBUG [net.spy.memcached.MemcachedConnection] - Completed read op: Cmd: 0 Opaque: 1 Key: ST-2-IuotzVXFdjPUucLs2ZVm-dcasde01.dev.medplus.com and giving the next 0 bytes

2016-08-02 19:18:19,618 ERROR [org.jasig.cas.ticket.registry.MemCacheTicketRegistry] - Failed fetching [ST-2-IuotzVXFdjPUucLs2ZVm-dcasde01.dev.medplus.com, java.lang.RuntimeException: Exception waiting for value]

2016-08-02 19:18:19,618 INFO [org.jasig.cas.CentralAuthenticationServiceImpl] - Service ticket [ST-2-IuotzVXFdjPUucLs2ZVm-dcasde01.dev.medplus.com] does not exist.

2016-08-02 19:18:19,621 DEBUG [net.spy.memcached.MemcachedConnection] - Added Cmd: 0 Opaque: 2 Key: ST-2-IuotzVXFdjPUucLs2ZVm-dcasde01.dev.medplus.com to {QA sa=dcasde01.dev.medplus.com/172.18.38.130:11211, #Rops=0, #Wops=0, #iq=1, topRop=null, topWop=null, toWrite=0, interested=0}

2016-08-02 19:18:19,622 DEBUG [net.spy.memcached.MemcachedConnection] - Handling IO for:  sun.nio.ch.SelectionKeyImpl@774ead62 (r=false, w=true, c=false, op={QA sa=dcasde01.dev.medplus.com/172.18.38.130:11211, #Rops=0, #Wops=1, #iq=0, topRop=null, topWop=Cmd: 0 Opaque: 2 Key: ST-2-IuotzVXFdjPUucLs2ZVm-dcasde01.dev.medplus.com, toWrite=0, interested=4})

2016-08-02 19:18:19,623 DEBUG [net.spy.memcached.protocol.binary.BinaryMemcachedNodeImpl] - After copying stuff from Cmd: 0 Opaque: 2 Key: ST-2-IuotzVXFdjPUucLs2ZVm-dcasde01.dev.medplus.com: java.nio.DirectByteBuffer[pos=74 lim=16384 cap=16384]

                                                                                                                    

2016-08-02 19:18:19,623 DEBUG [net.spy.memcached.protocol.binary.BinaryMemcachedNodeImpl] - Finished writing Cmd: 0 Opaque: 2 Key: ST-2-IuotzVXFdjPUucLs2ZVm-dcasde01.dev.medplus.com

2016-08-02 19:18:19,624 DEBUG [net.spy.memcached.MemcachedConnection] - Handling IO for:  sun.nio.ch.SelectionKeyImpl@774ead62 (r=true, w=false, c=false, op={QA sa=dcasde01.dev.medplus.com/172.18.38.130:11211, #Rops=1, #Wops=0, #iq=0, topRop=Cmd: 0 Opaque: 2 Key: ST-2-IuotzVXFdjPUucLs2ZVm-dcasde01.dev.medplus.com, topWop=null, toWrite=0, interested=1})

2016-08-02 19:18:19,625 DEBUG [net.spy.memcached.MemcachedConnection] - Completed read op: Cmd: 0 Opaque: 2 Key: ST-2-IuotzVXFdjPUucLs2ZVm-dcasde01.dev.medplus.com and giving the next 0 bytes

2016-08-02 19:18:19,627 ERROR [org.jasig.cas.ticket.registry.MemCacheTicketRegistry] - Failed fetching [ST-2-IuotzVXFdjPUucLs2ZVm-dcasde01.dev.medplus.com, java.lang.RuntimeException: Exception waiting for value]

2016-08-02 19:18:19,635 INFO [org.jasig.inspektr.audit.support.Slf4jLoggingAuditTrailManager] - Audit trail record BEGIN

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

WHO: audit:unknown

WHAT: ST-2-IuotzVXFdjPUucLs2ZVm-dcasde01.dev.medplus.com

ACTION: SERVICE_TICKET_VALIDATE_FAILED

APPLICATION: CAS

WHEN: Tue Aug 02 19:18:19 UTC 2016

CLIENT IP ADDRESS: 172.18.38.131

SERVER IP ADDRESS: 172.18.38.131

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

[Niva Agmon]

We’re having the same issue here. Does anyone have CAS working behind the F5 or is it just broken?

 

Thanks,

Niva

--
You received this message because you are subscribed to the Google Groups "CAS Community" group.
To unsubscribe from this group and stop receiving emails from it, send an email to cas-user+u...@apereo.org.
To post to this group, send email to cas-...@apereo.org.
Visit this group at https://groups.google.com/a/apereo.org/group/cas-user/.
To view this discussion on the web visit https://groups.google.com/a/apereo.org/d/msgid/cas-user/da054b55-0ac1-4c81-9889-b304b2d45747%40apereo.org.
For more options, visit https://groups.google.com/a/apereo.org/d/optout.