[mitreid-connect] Exception during cleanup

Tue Sep 1 11:16:16 EDT 2015

Hi Luiz,

Check out
https://github.com/mitreid-connect/OpenID-Connect-Java-Spring-Server/issues/862,
it seems to be exactly the problem you're having.

Regards,
Mark

On Tue, 1 Sep 2015 at 16:50 Luiz Omori <luiz.omori at duke.edu> wrote:

> 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>
> Date: Monday, August 31, 2015 at 4:50 PM
> To: "mitreid-connect at mit.edu" <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
> _______________________________________________
> mitreid-connect mailing list
> mitreid-connect at mit.edu
> http://mailman.mit.edu/mailman/listinfo/mitreid-connect
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://mailman.mit.edu/pipermail/mitreid-connect/attachments/20150901/5291f439/attachment.html