[mitreid-connect] Exception during cleanup

[Luiz Omori]

OK, I managed to reproduce the problem: it’s related to duplicated ID tokens being created when multiple similar requests are received within the same second.  In our case we use the Resource Owner flow for some legacy web services calls and that exacerbates the problem. At some point the code does a select on the access_token table using the token_value column and checks for number of rows returned, enforcing 1.

This token appears 38 times in the access_token table when we ran a stress test that makes 50 parallel Resource Owner requests (test environment):

eyJraWQiOiJyc2ExIiwiYWxnIjoiUlMyNTYifQ.eyJpc3MiOiJodHRwOlwvXC9sb2NhbGhvc3Q6ODA4MFwvbGRhcC1vcGVuaWQtY29ubmVjdC1zZXJ2ZXJcLyIsInN1YiI6IkNBVFNfZGFzaHNydiIsImF1ZCI6WyJncm93dGhfY2hhcnQiXSwiZXhwIjoxNDQxMTE0NTMzLCJpYXQiOjE0NDExMTQ0NzMsImtpZCI6InJzYTEifQ.NVSFBd9onhEUgMDC46KAJx5M_CaBy-INuy0MqodLqOCO7YQ5N9ZARG9BKemjv8G0Aj8aIYOa-CJeUYycv6Uk1qqVTcXX9jgpX7-f9xK4T4MxcOhhTwRqkvT8l7yWL5uAm1uG7lcKKHw6h2RGed4x9zej1Zb0PFiHTZHkPRl6OWwJvmaZySd0CZM3VVVtW4HIB45vNURE--ee5zkH1ezoJOfR0JlFFEaQfcTnW-PGBcNri6huk1fosUwLxoZE8-YGjwWVzKyy_1qmZBhS9Yg1ch6uXuxaXjG96_ITZQVoIyFwWyMi3rXOiwdgAzN_7aZOt8HSxNm7OUqFxZEr6JChbw

The concern is the growth of that table and since at least in MySQL version the token_value is not indexed (we could fix it locally) potential slow down over time.

Is there any workaround that we could use on our production system? Unfortunately, as opposed to my local system, our production environment is using HSSQLDB which most likely will prevent us from running delete SQL commands while the system is running.

Maybe we can add JTI to the ID tokens to make them unique?

Regards,
Luiz

From: Luiz Omori <luiz.omori at dm.duke.edu<mailto:luiz.omori at dm.duke.edu>>
Date: Monday, August 31, 2015 at 4:50 PM
To: "mitreid-connect at mit.edu<mailto:mitreid-connect at mit.edu>" <mitreid-connect at mit.edu<mailto:mitreid-connect at mit.edu>>
Subject: Exception during cleanup

Hi,

We have a system in production that is logging some exceptions. This is happening in DefaultOAuth2ProviderTokenService.clearExpiredTokens. I’ve been trying to track that down but so far no luck reproducing it on my development environment.  Has anybody seem this? Is it benign or something we should be concerned about?

@Override
public void clearExpiredTokens() {
logger.info("Cleaning out all expired tokens");

Collection<OAuth2AccessTokenEntity> accessTokens = getExpiredAccessTokens();
logger.info("Found " + accessTokens.size() + " expired access tokens");
for (OAuth2AccessTokenEntity oAuth2AccessTokenEntity : accessTokens) {
try {
revokeAccessToken(oAuth2AccessTokenEntity);
} catch (IllegalArgumentException e) {
//An ID token is deleted with its corresponding access token, but then the ID token is on the list of expired tokens as well and there is
//nothing in place to distinguish it from any other.
//An attempt to delete an already deleted token returns an error, stopping the cleanup dead. We need it to keep going.
}
}
…

2015Aug27 16:38:49,564: ERROR: org.springframework.scheduling.support.TaskUtils$LoggingErrorHandler - Unexpected error occurred in scheduled task.
java.lang.IllegalStateException: Expected single result, got 2
        at org.mitre.util.jpa.JpaUtil.getSingleResult(JpaUtil.java:36)
        at org.mitre.oauth2.repository.impl.JpaOAuth2TokenRepository.getAccessTokenByValue(JpaOAuth2TokenRepository.java:62)
        at org.mitre.oauth2.repository.impl.JpaOAuth2TokenRepository.removeAccessToken(JpaOAuth2TokenRepository.java:79)
        at org.mitre.oauth2.repository.impl.JpaOAuth2TokenRepository$$FastClassBySpringCGLIB$$145026dd.invoke(<generated>)
        at org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:204)
        at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.invokeJoinpoint(CglibAopProxy.java:700)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:150)
        at org.springframework.transaction.interceptor.TransactionInterceptor$1.proceedWithInvocation(TransactionInterceptor.java:96)
        at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:260)
        at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:94)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
        at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:633)
        at org.mitre.oauth2.repository.impl.JpaOAuth2TokenRepository$$EnhancerBySpringCGLIB$$e7092f0b.removeAccessToken(<generated>)
        at org.mitre.oauth2.service.impl.DefaultOAuth2ProviderTokenService.revokeAccessToken(DefaultOAuth2ProviderTokenService.java:380)
        at org.mitre.oauth2.service.impl.DefaultOAuth2ProviderTokenService.clearExpiredTokens(DefaultOAuth2ProviderTokenService.java:411)
        at sun.reflect.GeneratedMethodAccessor210.invoke(Unknown Source)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)
        at java.lang.reflect.Method.invoke(Unknown Source)
        at org.springframework.scheduling.support.ScheduledMethodRunnable.run(ScheduledMethodRunnable.java:64)
        at org.springframework.scheduling.support.DelegatingErrorHandlingRunnable.run(DelegatingErrorHandlingRunnable.java:53)
        at java.util.concurrent.Executors$RunnableAdapter.call(Unknown Source)
        at java.util.concurrent.FutureTask.runAndReset(Unknown Source)
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(Unknown Source)
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(Unknown Source)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
        at java.lang.Thread.run(Unknown Source)

Regards,
Luiz
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://mailman.mit.edu/pipermail/mitreid-connect/attachments/20150901/ba078554/attachment-0001.html