[mitreid-connect] Exception during cleanup

Tue Sep 1 11:53:39 EDT 2015

Justin, just to clarify, my local tests show that the JTI is NOT in the ID token and they ARE in the access tokens. See below decoded tokens that I just got (1.1.16):

2015/Sep/01 11:15:15
Access Token
{
  "aud": [
    "growth_chart"
  ],
  "iss": "http://localhost:8080/ldap-openid-connect-server/",
  "exp": 1441120575,
  "iat": 1441120515,
  "jti": "54384e60-1ef6-4612-9ebc-374023ee7687"
}
ID Token
{
  "iss": "http://localhost:8080/ldap-openid-connect-server/",
  "sub": "CATS_dashsrv",
  "aud": [
    "growth_chart"
  ],
  "exp": 1441120575,
  "iat": 1441120515,
  "kid": "rsa1"
}

Regards,
Luiz

From: Justin Richer <jricher at mit.edu<mailto:jricher at mit.edu>>
Date: Tuesday, September 1, 2015 at 11:34 AM
To: Luiz Omori <luiz.omori at dm.duke.edu<mailto:luiz.omori at dm.duke.edu>>
Cc: "mitreid-connect at mit.edu<mailto:mitreid-connect at mit.edu>" <mitreid-connect at mit.edu<mailto:mitreid-connect at mit.edu>>
Subject: Re: [mitreid-connect] Exception during cleanup

The tokens are supposed to be unique anyway, so that’s not good to see. But seeing the problem in this context, when it’s not the exact same request creating erroneous multiple tokens, has shed new light on things.

Adding a JTI will probably fix this. ID tokens already have them:

https://github.com/mitreid-connect/OpenID-Connect-Java-Spring-Server/blob/9ba1a78d09eec4fd6b142276118b39170c450cb4/openid-connect-server/src/main/java/org/mitre/openid/connect/token/ConnectTokenEnhancer.java#L101

And refresh tokens have them:

https://github.com/mitreid-connect/OpenID-Connect-Java-Spring-Server/blob/22c05ec51bce775e7f6c737089d85a4258be1f6f/openid-connect-server/src/main/java/org/mitre/oauth2/service/impl/DefaultOAuth2ProviderTokenService.java#L220

So I could have *sworn* that access tokens had them too! But looking at the generation function, they apparently don’t:

https://github.com/mitreid-connect/OpenID-Connect-Java-Spring-Server/blob/22c05ec51bce775e7f6c737089d85a4258be1f6f/openid-connect-server/src/main/java/org/mitre/oauth2/service/impl/DefaultOAuth2ProviderTokenService.java#L143

We’ll also need to check special tokens like registration tokens and UMA tokens that are made from their own services.

I think that’s a worthwhile addition and it’s one that’s easy to put in and it should be easy to test. It should probably also be backported to 1.1. I’ve added an issue for it here:

https://github.com/mitreid-connect/OpenID-Connect-Java-Spring-Server/issues/900

If someone would like to contribute SQL changes to add indices and constraints to the token tables where appropriate as well, please do! The database has not been really updated like that. As a rule we don’t update the database schema within a release cycle (so 1.0, 1.1, and 1.2 all have “stable” schemas), but we’ve made an exception in the past just for indexes and constraints exactly like this, since they can be easily added on top of production systems without affecting valid data if people desire.

Thanks everyone, this is starting to make a little bit more sense.
 — Justin

On Sep 1, 2015, at 10:50 AM, Luiz Omori <luiz.omori at duke.edu<mailto: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<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
_______________________________________________
mitreid-connect mailing list
mitreid-connect at mit.edu<mailto: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/be2176ef/attachment-0001.html