Issue with Ticket Registry Cleanup (MongoDB

Paul Chauvet

unread,

Nov 6, 2019, 1:18:12 PM11/6/19

to cas-...@apereo.org

Hi all,

There’s an error that is in our cas.log file very two minutes, regarding the DefaultTicketRegistryCleaner. The error is coming up on all three of our production CAS servers. I don’t know if it is causing issues or not – but when I look at the ticket registry (MongoDB) – I see tickets going back as far as October 9^th of this year. The error has been in our logs since October 9^th (same date on all three servers) – which was (I’m sure not coincidentally) when I upgraded our production CAS hosts from 5.2.9 to 5.3.12.1.

Our environment is:

OS: RHEL 7
Tomcat: 8.5.46
MongoDB (as Ticket Registry): 3.6.14

Does anyone have any idea what could be causing this (or what I need to do to resolve this)? Any assistance or guidance in this would be greatly appreciated.

The error is below:

2019-11-06 13:13:14,305 ERROR [org.apereo.cas.ticket.registry.DefaultTicketRegistryCleaner] - <null>

org.apereo.cas.ticket.InvalidTicketException: null

at org.apereo.cas.ticket.BaseTicketSerializers.deserializeTicket(BaseTicketSerializers.java:176) ~[cas-server-core-tickets-api-5.3.12.1.jar:5.3.12.1]

at org.apereo.cas.ticket.registry.MongoDbTicketRegistry.deserializeTicketFromMongoDocument(MongoDbTicketRegistry.java:289) ~[cas-server-support-mongo-ticket-registry-5.3.12.1.jar:5.3.12.1]

at org.apereo.cas.ticket.registry.MongoDbTicketRegistry.lambda$getTicketsStream$8(MongoDbTicketRegistry.java:238) ~[cas-server-support-mongo-ticket-registry-5.3.12.1.jar:5.3.12.1]

at java.util.stream.ReferencePipeline$3$1.accept(ReferencePipeline.java:193) ~[?:1.8.0_222]

at java.util.Iterator.forEachRemaining(Iterator.java:116) ~[?:1.8.0_222]

at java.util.Spliterators$IteratorSpliterator.forEachRemaining(Spliterators.java:1801) ~[?:1.8.0_222]

at java.util.stream.ReferencePipeline$Head.forEach(ReferencePipeline.java:647) ~[?:1.8.0_222]

at java.util.stream.ReferencePipeline$7$1.accept(ReferencePipeline.java:272) ~[?:1.8.0_222]

at java.util.stream.ReferencePipeline$3$1.accept(ReferencePipeline.java:193) ~[?:1.8.0_222]

at java.util.ArrayList$ArrayListSpliterator.forEachRemaining(ArrayList.java:1382) ~[?:1.8.0_222]

at java.util.stream.AbstractPipeline.copyInto(AbstractPipeline.java:482) ~[?:1.8.0_222]

at java.util.stream.AbstractPipeline.wrapAndCopyInto(AbstractPipeline.java:472) ~[?:1.8.0_222]

at java.util.stream.ReduceOps$ReduceOp.evaluateSequential(ReduceOps.java:708) ~[?:1.8.0_222]

at java.util.stream.AbstractPipeline.evaluate(AbstractPipeline.java:234) ~[?:1.8.0_222]

at java.util.stream.IntPipeline.reduce(IntPipeline.java:479) ~[?:1.8.0_222]

at java.util.stream.IntPipeline.sum(IntPipeline.java:437) ~[?:1.8.0_222]

at org.apereo.cas.ticket.registry.DefaultTicketRegistryCleaner.cleanInternal(DefaultTicketRegistryCleaner.java:66) ~[cas-server-core-tickets-api-5.3.12.1.jar:5.3.12.1]

at org.apereo.cas.ticket.registry.DefaultTicketRegistryCleaner.clean(DefaultTicketRegistryCleaner.java:47) ~[cas-server-core-tickets-api-5.3.12.1.jar:5.3.12.1]

at org.apereo.cas.ticket.registry.DefaultTicketRegistryCleaner$$FastClassBySpringCGLIB$$29f046b2.invoke(<generated>) ~[cas-server-core-tickets-api-5.3.12.1.jar:5.3.12.1]

at org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:204) ~[spring-core-4.3.25.RELEASE.jar:4.3.25.RELEASE]

at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.invokeJoinpoint(CglibAopProxy.java:736) ~[spring-aop-4.3.25.RELEASE.jar:4.3.25.RELEASE]

at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:157) ~[spring-aop-4.3.25.RELEASE.jar:4.3.25.RELEASE]

at org.springframework.transaction.interceptor.TransactionInterceptor$1.proceedWithInvocation(TransactionInterceptor.java:99) ~[spring-tx-4.3.25.RELEASE.jar:4.3.25.RELEASE]

at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:283) ~[spring-tx-4.3.25.RELEASE.jar:4.3.25.RELEASE]

at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:96) ~[spring-tx-4.3.25.RELEASE.jar:4.3.25.RELEASE]

at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179) ~[spring-aop-4.3.25.RELEASE.jar:4.3.25.RELEASE]

at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:671) ~[spring-aop-4.3.25.RELEASE.jar:4.3.25.RELEASE]

at org.apereo.cas.ticket.registry.DefaultTicketRegistryCleaner$$EnhancerBySpringCGLIB$$105be668.clean(<generated>) ~[cas-server-core-tickets-api-5.3.12.1.jar:5.3.12.1]

at org.apereo.cas.config.CasCoreTicketsSchedulingConfiguration$TicketRegistryCleanerScheduler.run(CasCoreTicketsSchedulingConfiguration.java:89) ~[cas-server-core-tickets-5.3.12.1.jar:5.3.12.1]

at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:1.8.0_222]

at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:1.8.0_222]

at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:1.8.0_222]

at java.lang.reflect.Method.invoke(Method.java:498) ~[?:1.8.0_222]

at org.springframework.scheduling.support.ScheduledMethodRunnable.run(ScheduledMethodRunnable.java:65) ~[spring-context-4.3.25.RELEASE.jar:4.3.25.RELEASE]

at org.springframework.scheduling.support.DelegatingErrorHandlingRunnable.run(DelegatingErrorHandlingRunnable.java:54) ~[spring-context-4.3.25.RELEASE.jar:4.3.25.RELEASE]

at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) ~[?:1.8.0_222]

at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308) ~[?:1.8.0_222]

at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180) ~[?:1.8.0_222]

at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294) ~[?:1.8.0_222]

at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) ~[?:1.8.0_222]

at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) ~[?:1.8.0_222]

at java.lang.Thread.run(Thread.java:748) [?:1.8.0_222]

Paul Chauvet, CISSP

Information Security Officer

State University of New York at New Paltz

845-257-3828

chau...@newpaltz.edu

emlogo

Andy Ng

unread,

Nov 7, 2019, 3:22:00 AM11/7/19

to CAS Community

Hi Paul,

I have done some investigation on your case, and:

I can reproduce your error case using my testing docker with CAS 5.3.x and MongoDB 4 ticket registry, after a single login, I can see the error same as yours occurs.

Below are my error log as well:

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

2019-11-07 08:00:58,144 INFO [org.apereo.cas.services.AbstractServicesManager] - <Loaded [1] service(s) from [JsonServiceRegistry].>

2019-11-07 08:01:08,187 ERROR [org.apereo.cas.util.serialization.AbstractJacksonBackedStringSerializer] - <Cannot read/parse [{"@class":"org.ape

reo.cas.ticket.TicketGrantingTicketImpl","@id":1,"id":"TGT-1-********************************Cull52Dyeq5...] to deserialize into type [interface

org.apereo.cas.ticket.TicketGrantingTicket]. This may be caused in the absence of a configuration/support module that knows how to interpret th

e fragment, specially if the fragment describes a CAS registered service definition. Internal parsing error is [Could not resolve type id 'org.a

pereo.cas.authentication.metadata.BasicCredentialMetaData' as a subtype of [simple type, class org.apereo.cas.authentication.CredentialMetaData]

: no such class found

at [Source: (String)"{"@class":"org.apereo.cas.ticket.TicketGrantingTicketImpl","@id":1,"id":"TGT-1-********************************Cull52Dyeq5

...Q7aMAvNyX4yrvvx0AI-7k-cas","authentication":{"@class":"org.apereo.cas.authentication.DefaultAuthentication","authenticationDate":1573113040.4

1772,"principal":{"@class":"org.apereo.cas.authentication.principal.SimplePrincipal","id":"casuser","attributes":{"@class":"java.util.TreeMap","

attributeRetriveFrom":["java.util.ArrayList",["json"]],"coolSystemYouGotThere":["java.util"[truncated 2347 chars]; line: 1, column: 575] (throug

h reference chain: org.apereo.cas.ticket.TicketGrantingTicketImpl["authentication"]->org.apereo.cas.authentication.DefaultAuthentication["creden

tials"]->java.util.ArrayList[0])]>

2019-11-07 08:01:08,193 ERROR [org.apereo.cas.ticket.registry.DefaultTicketRegistryCleaner] - <null>

org.apereo.cas.ticket.InvalidTicketException: null

at org.apereo.cas.ticket.BaseTicketSerializers.deserializeTicket(BaseTicketSerializers.java:208) ~[cas-server-core-tickets-api-5.3.12.1.jar!/:5.3.12.1]

at org.apereo.cas.ticket.BaseTicketSerializers.deserializeTicket(BaseTicketSerializers.java:185) ~[cas-server-core-tickets-api-5.3.12.1.jar!/:5.3.12.1]

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

As for fixing it, seems too complicated for me so I am probably not going to devote time into fixing it... See if other want to help investigate more.

Some alternative suggestions from me, which may or may not help you:

- During my simulation, I also tried using CAS 6.1.1 and MongoDB 4 ticket registry, and from my testing it works fine, no null pointer exception.

- If you can affort the upgrade, then this might be one path the choose.

- In my own production environment, I am using Hazelcast ticket registry and CAS 5.3, and didn't encounter any related error,

- so I guess the null pointer bug is MongoDB related, probably something bug related to phrasing of the JSON.

See if other can help more...

- Andy

Paul Chauvet

unread,

Nov 7, 2019, 7:09:18 PM11/7/19

to CAS Community

Hi Andy,

Apologies for the belated reply here. I really appreciate your time and effort looking into this!

I'm looking into options (downgrading to 5.2.9, upgrading to 5.3.14) for a fix. Next week is our advance registration - one of the busiest periods - so I'd prefer to avoid major changes.

Moving to 6.x is a path to consider if 5.3.14 doesn't work, as well as switching the ticket registry to Hazelcast as you suggest. I won't get a chance to do this (especially a 6.x upgrade) until I have more time available after classes are done for the semester.

As a shorter-term fix - I've gone into the MongoDB (primary instance in the replica set) and deleted any tickets that were set to expire in the past:

db.ticketGrantingTicketsCollection.deleteMany({expireAt: { $regex: /^2019-11-0[1-6]/ } } )

db.ticketGrantingTicketsCollection.deleteMany({expireAt: { $regex: /^2019-10-0[/ } } )

Tomorrow I'll write a script to clean old tickets on a daily basis until I can get a more permanent solution.

If the upgrade to 5.3.14 fixes the problem - I'll report back to the list in case anyone else experiences the same issue.

Paul Chauvet, CISSP

Information Security Officer

State University of New York at New Paltz

845-257-3828

chau...@newpaltz.edu

From: cas-...@apereo.org <cas-...@apereo.org> on behalf of Andy Ng <lon...@gmail.com>
Sent: Thursday, November 7, 2019 3:21 AM
To: CAS Community <cas-...@apereo.org>
Subject: [cas-user] Re: Issue with Ticket Registry Cleanup (MongoDB - CAS 5.3.12.1

CAUTION: Message from a non-New Paltz email server. Treat message, links, and attachments with extra caution.

Hi Paul,

I have done some investigation on your case, and:

I can reproduce your error case using my testing docker with CAS 5.3.x and MongoDB 4 ticket registry, after a single login, I can see the error same as yours occurs.

Below are my error log as well:

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

2019-11-07 08:00:58,144 INFO [org.apereo.cas.services.AbstractServicesManager] - <Loaded [1] service(s) from [JsonServiceRegistry].>

2019-11-07 08:01:08,187 ERROR [org.apereo.cas.util.serialization.AbstractJacksonBackedStringSerializer] - <Cannot read/parse [{"@class":"org.apereo.cas.ticket.TicketGrantingTicketImpl","@id":1,"id":"TGT-1-********************************Cull52Dyeq5...] to deserialize into type [interface org.apereo.cas.ticket.TicketGrantingTicket]. This may be caused in the absence of a configuration/support module that knows how to interpret the fragment, specially if the fragment describes a CAS registered service definition. Internal parsing error is [Could not resolve type id 'org.apereo.cas.authentication.metadata.BasicCredentialMetaData' as a subtype of [simple type, class org.apereo.cas.authentication.CredentialMetaData]

: no such class found at [Source: (String)"{"@class":"org.apereo.cas.ticket.TicketGrantingTicketImpl","@id":1,"id":"TGT-1-********************************Cull52Dyeq5Q7aMAvNyX4yrvvx0AI-7k-cas","authentication":{"@class":"org.apereo.cas.authentication.DefaultAuthentication","authenticationDate":1573113040.4

1772,"principal":{"@class":"org.apereo.cas.authentication.principal.SimplePrincipal","id":"casuser","attributes":{"@class":"java.util.TreeMap","attributeRetriveFrom":["java.util.ArrayList",["json"]],"coolSystemYouGotThere":["java.util"[truncated 2347 chars]; line: 1, column: 575] (through reference chain: org.apereo.cas.ticket.TicketGrantingTicketImpl["authentication"]->org.apereo.cas.authentication.DefaultAuthentication["credentials"]->java.util.ArrayList[0])]>