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
=============================================================
--
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 [email protected].
To post to this group, send email to [email protected].
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.
