spring-security-oauth2 requesting asynchronously does "duplicate key value violates unique constraint" error

Created on 4 Dec 2017  路  25Comments  路  Source: spring-projects/spring-security-oauth

Context

I am using spring-security-oauth2 2.2.1
and spring-boot 1.5.8

I have a Nodejs http client driver and I am using it to query the backend asynchronously.

Configuration

AuthorizationServerConfig:

@Configuration
@EnableAuthorizationServer
public class AuthorizationServerConfig extends AuthorizationServerConfigurerAdapter {

    private static final Logger log = LoggerFactory.getLogger(AuthorizationServerConfig.class);
    @Autowired
    @Qualifier(DATA_SOURCE)
    private DataSource dataSource;

    @Autowired
    @Qualifier(AUTHENTICATION_MANAGER)
    private AuthenticationManager authenticationManager;

    @Autowired
    private LocalOrgLdapUserDetailsManager userDetailsService;

    @Autowired
    private ClientService clientService;

    @Autowired
    private AuthenticationEntryPoint authenticationEntryPoint;

    @Autowired
    private AccessDeniedHandler accessDeniedHandler;

    @Autowired
    private OAuth2Properties oAuth2Properties;

    private TokenEnhancer tokenEnhancer;


    @Autowired
    private Environment env;

    @Autowired
    public void setTokenEnhancer(TokenEnhancer tokenEnhancer) {
        this.tokenEnhancer = tokenEnhancer;
    }

    @Bean
    public ClientDetailsService clientDetailsService() {
        return new ClientDetailsService(clientService);
    }

    @Override
    public void configure(final AuthorizationServerSecurityConfigurer oauthServer) throws Exception {
        oauthServer
                .passwordEncoder(passwordEncoder())
                .tokenKeyAccess("permitAll()")
                .checkTokenAccess("isAuthenticated()")
                .authenticationEntryPoint(authenticationEntryPoint)
                .accessDeniedHandler(accessDeniedHandler);
    }

    @Override
    public void configure(ClientDetailsServiceConfigurer clients) throws Exception {
        clients.withClientDetails(clientDetailsService());
    }

    @Override
    public void configure(AuthorizationServerEndpointsConfigurer endpoints) throws Exception {
        final TokenEnhancerChain tokenEnhancerChain = new TokenEnhancerChain();
        tokenEnhancerChain.setTokenEnhancers(Arrays.asList(tokenEnhancer, accessTokenConverter()));
        endpoints
                .tokenStore(tokenStore())
                .approvalStoreDisabled()
                .authorizationCodeServices(authorizationCodeServices())
                .tokenEnhancer(tokenEnhancerChain)
                .reuseRefreshTokens(false)
                .authenticationManager(authenticationManager)
                .userDetailsService(userDetailsService);
    }

    @Bean(name = "clientPasswordEncoder")
    public PasswordEncoder passwordEncoder() {
        return new BCryptPasswordEncoder();
    }

    @Bean
    public JwtAccessTokenConverter accessTokenConverter() {
        final JwtAccessTokenConverter converter = new JwtAccessTokenConverter();
            if (null != oAuth2Properties.getAuthorization().getJks()) {
            try {
                ClassPathResource jks = new ClassPathResource(oAuth2Properties.getAuthorization().getJks());
                final KeyStoreKeyFactory keyStoreKeyFactory = new KeyStoreKeyFactory(jks, oAuth2Properties.getAuthorization().getJkspass().toCharArray());
                converter.setKeyPair(keyStoreKeyFactory.getKeyPair(oAuth2Properties.getAuthorization().getAlias()));
            } catch (Exception e) {
                log.warn("Authorization server does not have certificate ! The jks file " + oAuth2Properties.getAuthorization().getJks() + " does not exist in your classpath.");
            }
        }
        return converter;
    }

    @Bean
    public TokenEnhancer tokenEnhancer() {
        return this.tokenEnhancer;
    }

    @Bean
    public TokenStore tokenStore() throws SQLException {
        return new JdbcTokenStore(dataSource);
    }

    @Bean
    protected AuthorizationCodeServices authorizationCodeServices() throws SQLException {
        return new JdbcAuthorizationCodeServices(dataSource);
    }

}

ResourceServerConfig

@Configuration
@EnableResourceServer
public class ResourceServerConfig extends ResourceServerConfigurerAdapter {

    @Autowired
    private AuthenticationManager authenticationManager;

    @Autowired
    private AuthenticationEntryPoint authenticationEntryPoint;

    @Autowired
    private AccessDeniedHandler accessDeniedHandler;

    @Autowired
    private OAuth2Properties OAuth2Properties;

    @Autowired
    private TokenStore tokenStore;

    @Override
    public void configure(HttpSecurity http) throws Exception {
        http
                .authorizeRequests()
                .anyRequest()
                .permitAll()
            .and()
                .exceptionHandling()
                .authenticationEntryPoint(authenticationEntryPoint)
                .accessDeniedHandler(accessDeniedHandler);
    }

    @Override
    public void configure(ResourceServerSecurityConfigurer resources) throws Exception {
        resources
                .tokenServices(tokenServices())
                .resourceId(OAuth2Properties.getResource().getName());
    }

    @Bean
    @Primary
    public ResourceServerTokenServices tokenServices() throws SQLException {
        final DefaultTokenServices defaultTokenServices = new DefaultTokenServices();
        defaultTokenServices.setTokenStore(tokenStore);
        defaultTokenServices.setSupportRefreshToken(true);
        defaultTokenServices.setAuthenticationManager(authenticationManager);
        return defaultTokenServices;
    }

}

Expected

To have a 200 success

Result

I have a 500 error

{
  "error" : "server_error",
  "error_description" : "PreparedStatementCallback; SQL [insert into oauth_access_token (token_id, token, authentication_id, user_name, client_id, authentication, refresh_token) values (?, ?, ?, ?, ?, ?, ?)]; ERROR: duplicate key value violates unique constraint "oauth_access_token_pkey"\n  Detail: Key (authentication_id)=(7c7cecc72affde558d7f364f17a1771c) already exists.; nested exception is org.postgresql.util.PSQLException: ERROR: duplicate key value violates unique constraint "oauth_access_token_pkey"\n  Detail: Key (authentication_id)=(7c7cecc72affde558d7f364f17a1771c) already exists."
}

This happen only when using asynchronous script, which is something we want to support by default.

How can I fix it ?

picture kopax
👍1

Most helpful comment

@kopax I was able to reproduce the issue based on your sample and I know what the issue is.

To recap, the root issue you are facing is a unique key constraint violation which logs this exception:

org.h2.jdbc.JdbcSQLException: Unique index or primary key violation: "PRIMARY_KEY_D ON PUBLIC.OAUTH_ACCESS_TOKEN(AUTHENTICATION_ID) VALUES ('b762270ce877e5b49c8f9305e3eb0ab1', 1)"

In your migration script V0_0_6__CreateTablesOAuth2.sql, the following table is created:

create table oauth_access_token (
  token_id VARCHAR(256),
  token BYTEA,
  authentication_id VARCHAR(256) PRIMARY KEY,
  user_name VARCHAR(256),
  client_id VARCHAR(256),
  authentication BYTEA,
  refresh_token VARCHAR(256)
);

The primary key is authentication_id.

DefaultAuthenticationKeyGenerator.extractKey() is the value generator for the authentication_id column.

Given your client test case, you are using the following user and client for all requests:

User: admin
Client: myfirstapp
Scopes: read trust write

Given these request parameters to the Token Endpoint, the value generated by DefaultAuthenticationKeyGenerator.extractKey() will always be the same for the authentication_id column.

This alone invalidates the test because you are simulating only one user instead of different users. For example, the same user/client combination calling the token endpoint is not a real world test and cannot really happen unless 2 user's log in with the same credentials and go through the exact same flow at the same time.

Either way, I want to explain why this error ocurrs in the async case.

Let's imagine the following scenario in this step sequence:

  1. Request 1 (Thread 1) - admin/myfirstapp requests an access token calling the Token endpoint. All is good and auth server issues a new access token. At this point we have a record in oauth_access_token with the authentication_id keyed using -> admin/myfirstapp/read trust write
    NOTE: Let's assume the expiration of the access token is 1 min from issue.

  2. Request 2 (Thread 2) - admin/myfirstapp requests an access token calling the Token endpoint. Given that an access token was created in Step 1 for the same user/client (admin/myfirstapp), then the existing access token is returned.

2 mins has passed now since the issuance of the access token...

  1. Request 3 (Thread 1) - admin/myfirstapp requests an access token calling the Token endpoint. There is an existing access token associated to admin/myfirstapp but it's expired. At this point a DELETE oauth_access_token is recorded followed by an INSERT oauth_access_token. Given that DefaultTokenServices.createAccessToken() has @Transactional it is check-pointed within a transaction. BUT before this method returns, which will commit the 2 transactions, Step 4 happens...

  2. Request 4 (Thread 2) - admin/myfirstapp requests an access token calling the Token endpoint. There is an existing access token associated to admin/myfirstapp but it's expired. At this point a DELETE oauth_access_token is recorded followed by an INSERT oauth_access_token. Given that DefaultTokenServices.createAccessToken() has @Transactional it is check-pointed within a transaction. BUT before this method returns, which will commit the 2 transactions, Step 5 happens...

  3. The 2 threads in Step 3 and 4 are executing at the same time using the same user/client and have similar transactions that are about to be committed. The only difference in the transactions is the value of the access token. But the authentication_id is the same, this is where the issue happens. Now let's say from Step 3. Request 3 (Thread 1), the call stack returns from DefaultTokenServices.createAccessToken() and therefore the 2 transactions are committed. Now we have a new record in oauth_access_token with a new access token but same authentication_id. All is good at this point. Now the next thing that happens is from Step 4. Request 4 (Thread 2), the call stack returns from DefaultTokenServices.createAccessToken() and therefore the 2 transactions are going to be committed but don't because the unique constraint happens. The insert statement for the oauth_access_token has the same authentication_id and therefore fails.

I hope this explains why the error is happening? It's pretty difficult to troubleshoot these kinds of errors and explain it in writing as well...race conditions are inherently difficult.

In a nutshell, using the same user principal to call the token endpoint on multiple async requests is not really a real world use case. It should be different user principals per request.

I'm going to leave this open for now until you go over my analysis and provide me your feedback on your understanding.

picture jgrandja on 13 Dec 2017
👍8 ❤4 🎉3

All 25 comments

I have create unique index in db,and I plan to use distribute redis-lock in AuthorizationServerTokenServices

xugc picture xugc on 5 Dec 2017
👍1

@xugc, sorry but that didn't really helped me.

I've created a reproduction, I hope someone will have a look, this error is present since forever:

You will find the reproduction here:

Issue #1242 #1202

I want to request resource data asynchronously.

These are my endpoints :

An __anonymous user__ should be able to access only these endpoints

An __authenticated user__ with ROLE_USER should be able to access only these endpoints

An __authenticated user using a jwt__ can access these endpoints

I am executing a list of request to a OAuth secured endpoint in two modes:

  • synchronously
  • asynchronously

Reproduction

You will need two project, the spring backend and a nodejs rest client:

Requirement:

  • Java JDK 8
  • Node 4 or later
  • Npm 4 or later

  1. Clone the project

    mkdir -p ~/tmp && cd ~/tmp && git clone https://github.com/kopax/spring-security-oauth-issues-1202 && cd spring-security-oauth-issues-1202

  2. start the server

    ./gradlew build --info && java -jar $(find build/libs -name "*.jar" -type f | xargs ls -tr | tail -1) --spring.profiles.active=default

  3. Open a new terminal and clone the client test project

    mkdir -p ~/tmp && cd ~/tmp && git clone [email protected]:kopax/spring-security-oauth-issues-1202-client.git && cd spring-security-oauth-issues-1202-client && npm install

  4. Run the client test synchronously (always succeed)

    npm run roles
# this will prompt for credential which are already set for you, just press enter till the end

  5. Run the client test asynchronously (mostly will fail)

    npm run roles
# this will prompt for credential which are already set for you
# press enter till the question "ASYNC MODE" where you MUST choose "YES"

  6. Clean the reproduction

    rm -rf ~/tmp

Expected

http status code 200

Result

Handling error: DuplicateKeyException, PreparedStatementCallback; SQL [insert into oauth_access_token (token_id, token, authentication_id, user_name, client_id, authentication, refresh_token) values (?, ?, ?, ?, ?, ?, ?)]; Unique index or primary key violation: "PRIMARY_KEY_D ON PUBLIC.OAUTH_ACCESS_TOKEN(AUTHENTICATION_ID) VALUES ('b762270ce877e5b49c8f9305e3eb0ab1', 14)"; SQL statement:
insert into oauth_access_token (token_id, token, authentication_id, user_name, client_id, authentication, refresh_token) values (?, ?, ?, ?, ?, ?, ?) [23505-194]; nested exception is org.h2.jdbc.JdbcSQLException: Unique index or primary key violation: "PRIMARY_KEY_D ON PUBLIC.OAUTH_ACCESS_TOKEN(AUTHENTICATION_ID) VALUES ('b762270ce877e5b49c8f9305e3eb0ab1', 14)"; SQL statement:
insert into oauth_access_token (token_id, token, authentication_id, user_name, client_id, authentication, refresh_token) values (?, ?, ?, ?, ?, ?, ?) [23505-194]
org.springframework.dao.DuplicateKeyException: PreparedStatementCallback; SQL [insert into oauth_access_token (token_id, token, authentication_id, user_name, client_id, authentication, refresh_token) values (?, ?, ?, ?, ?, ?, ?)]; Unique index or primary key violation: "PRIMARY_KEY_D ON PUBLIC.OAUTH_ACCESS_TOKEN(AUTHENTICATION_ID) VALUES ('b762270ce877e5b49c8f9305e3eb0ab1', 14)"; SQL statement:
insert into oauth_access_token (token_id, token, authentication_id, user_name, client_id, authentication, refresh_token) values (?, ?, ?, ?, ?, ?, ?) [23505-194]; nested exception is org.h2.jdbc.JdbcSQLException: Unique index or primary key violation: "PRIMARY_KEY_D ON PUBLIC.OAUTH_ACCESS_TOKEN(AUTHENTICATION_ID) VALUES ('b762270ce877e5b49c8f9305e3eb0ab1', 14)"; SQL statement:
insert into oauth_access_token (token_id, token, authentication_id, user_name, client_id, authentication, refresh_token) values (?, ?, ?, ?, ?, ?, ?) [23505-194]
    at org.springframework.jdbc.support.SQLErrorCodeSQLExceptionTranslator.doTranslate(SQLErrorCodeSQLExceptionTranslator.java:239)
    at org.springframework.jdbc.support.AbstractFallbackSQLExceptionTranslator.translate(AbstractFallbackSQLExceptionTranslator.java:73)
    at org.springframework.jdbc.core.JdbcTemplate.execute(JdbcTemplate.java:655)
    at org.springframework.jdbc.core.JdbcTemplate.update(JdbcTemplate.java:876)
    at org.springframework.jdbc.core.JdbcTemplate.update(JdbcTemplate.java:937)
    at org.springframework.jdbc.core.JdbcTemplate.update(JdbcTemplate.java:942)
    at org.springframework.security.oauth2.provider.token.store.JdbcTokenStore.storeAccessToken(JdbcTokenStore.java:148)
    at org.springframework.security.oauth2.provider.token.DefaultTokenServices.createAccessToken(DefaultTokenServices.java:122)
    at org.springframework.security.oauth2.provider.token.AbstractTokenGranter.getAccessToken(AbstractTokenGranter.java:70)
    at org.springframework.security.oauth2.provider.token.AbstractTokenGranter.grant(AbstractTokenGranter.java:65)
    at org.springframework.security.oauth2.provider.CompositeTokenGranter.grant(CompositeTokenGranter.java:38)
    at org.springframework.security.oauth2.config.annotation.web.configurers.AuthorizationServerEndpointsConfigurer$4.grant(AuthorizationServerEndpointsConfigurer.java:561)
    at org.springframework.security.oauth2.provider.endpoint.TokenEndpoint.postAccessToken(TokenEndpoint.java:132)
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:498)
    at org.springframework.web.method.support.InvocableHandlerMethod.doInvoke(InvocableHandlerMethod.java:205)
    at org.springframework.web.method.support.InvocableHandlerMethod.invokeForRequest(InvocableHandlerMethod.java:133)
    at org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod.invokeAndHandle(ServletInvocableHandlerMethod.java:97)
    at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.invokeHandlerMethod(RequestMappingHandlerAdapter.java:827)
    at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.handleInternal(RequestMappingHandlerAdapter.java:738)
    at org.springframework.web.servlet.mvc.method.AbstractHandlerMethodAdapter.handle(AbstractHandlerMethodAdapter.java:85)
    at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:967)
    at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:901)
    at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:970)
    at org.springframework.web.servlet.FrameworkServlet.doPost(FrameworkServlet.java:872)
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:661)
    at org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:846)
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:742)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:231)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
    at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
    at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:317)
    at org.springframework.security.web.access.intercept.FilterSecurityInterceptor.invoke(FilterSecurityInterceptor.java:127)
    at org.springframework.security.web.access.intercept.FilterSecurityInterceptor.doFilter(FilterSecurityInterceptor.java:91)
    at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331)
    at org.springframework.security.web.access.ExceptionTranslationFilter.doFilter(ExceptionTranslationFilter.java:114)
    at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331)
    at org.springframework.security.web.session.SessionManagementFilter.doFilter(SessionManagementFilter.java:137)
    at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331)
    at org.springframework.security.web.authentication.AnonymousAuthenticationFilter.doFilter(AnonymousAuthenticationFilter.java:111)
    at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331)
    at org.springframework.security.web.servletapi.SecurityContextHolderAwareRequestFilter.doFilter(SecurityContextHolderAwareRequestFilter.java:170)
    at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331)
    at org.springframework.security.web.savedrequest.RequestCacheAwareFilter.doFilter(RequestCacheAwareFilter.java:63)
    at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331)
    at org.springframework.security.web.authentication.www.BasicAuthenticationFilter.doFilterInternal(BasicAuthenticationFilter.java:215)
    at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
    at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331)
    at org.springframework.security.web.authentication.logout.LogoutFilter.doFilter(LogoutFilter.java:116)
    at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331)
    at org.springframework.security.web.header.HeaderWriterFilter.doFilterInternal(HeaderWriterFilter.java:64)
    at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
    at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331)
    at org.springframework.security.web.context.SecurityContextPersistenceFilter.doFilter(SecurityContextPersistenceFilter.java:105)
    at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331)
    at org.springframework.security.web.context.request.async.WebAsyncManagerIntegrationFilter.doFilterInternal(WebAsyncManagerIntegrationFilter.java:56)
    at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
    at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331)
    at org.springframework.security.web.FilterChainProxy.doFilterInternal(FilterChainProxy.java:214)
    at org.springframework.security.web.FilterChainProxy.doFilter(FilterChainProxy.java:177)
    at org.springframework.web.filter.DelegatingFilterProxy.invokeDelegate(DelegatingFilterProxy.java:347)
    at org.springframework.web.filter.DelegatingFilterProxy.doFilter(DelegatingFilterProxy.java:263)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
    at org.springframework.web.filter.RequestContextFilter.doFilterInternal(RequestContextFilter.java:99)
    at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
    at org.springframework.web.filter.HttpPutFormContentFilter.doFilterInternal(HttpPutFormContentFilter.java:108)
    at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
    at org.springframework.web.filter.HiddenHttpMethodFilter.doFilterInternal(HiddenHttpMethodFilter.java:81)
    at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
    at org.springframework.session.web.http.SessionRepositoryFilter.doFilterInternal(SessionRepositoryFilter.java:167)
    at org.springframework.session.web.http.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:80)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
    at org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:197)
    at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
    at com.common.servlet.filter.CORSFilter.doFilter(CORSFilter.java:40)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
    at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:199)
    at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:96)
    at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:478)
    at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:140)
    at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:81)
    at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:87)
    at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:342)
    at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:803)
    at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:66)
    at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:868)
    at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1459)
    at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
    at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
    at java.lang.Thread.run(Thread.java:748)
Caused by: org.h2.jdbc.JdbcSQLException: Unique index or primary key violation: "PRIMARY_KEY_D ON PUBLIC.OAUTH_ACCESS_TOKEN(AUTHENTICATION_ID) VALUES ('b762270ce877e5b49c8f9305e3eb0ab1', 14)"; SQL statement:
insert into oauth_access_token (token_id, token, authentication_id, user_name, client_id, authentication, refresh_token) values (?, ?, ?, ?, ?, ?, ?) [23505-194]
    at org.h2.message.DbException.getJdbcSQLException(DbException.java:345)
    at org.h2.message.DbException.get(DbException.java:179)
    at org.h2.message.DbException.get(DbException.java:155)
    at org.h2.index.BaseIndex.getDuplicateKeyException(BaseIndex.java:103)
    at org.h2.mvstore.db.MVSecondaryIndex.checkUnique(MVSecondaryIndex.java:231)
    at org.h2.mvstore.db.MVSecondaryIndex.add(MVSecondaryIndex.java:190)
    at org.h2.mvstore.db.MVTable.addRow(MVTable.java:707)
    at org.h2.command.dml.Insert.insertRows(Insert.java:156)
    at org.h2.command.dml.Insert.update(Insert.java:114)
    at org.h2.command.CommandContainer.update(CommandContainer.java:101)
    at org.h2.command.Command.executeUpdate(Command.java:258)
    at org.h2.jdbc.JdbcPreparedStatement.executeUpdateInternal(JdbcPreparedStatement.java:160)
    at org.h2.jdbc.JdbcPreparedStatement.executeUpdate(JdbcPreparedStatement.java:146)
    at org.springframework.jdbc.core.JdbcTemplate$2.doInPreparedStatement(JdbcTemplate.java:883)
    at org.springframework.jdbc.core.JdbcTemplate$2.doInPreparedStatement(JdbcTemplate.java:876)
    at org.springframework.jdbc.core.JdbcTemplate.execute(JdbcTemplate.java:639)
    ... 104 common frames omitted
Socket: [org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper@4f2cecca:org.apache.tomcat.util.net.NioChannel@486d5308:java.nio.channels.SocketChannel[connected local=/127.0.0.1:8080 remote=/127.0.0.1:39524]], Read from buffer: [0]
Received [GET /roles?organization=kopax&siteServiceIds=6000 HTTP/1.1
accept: application/json
authorization: Bearer eyJhbGciOiJIUzI1NiIsInR5cCI6IkpXVCJ9.eyJhdWQiOlsibXlhcHAvYXBpIl0sInVzZXJfbmFtZSI6ImFkbWluIiwic2NvcGUiOlsidHJ1c3QiLCJyZWFkIiwid3JpdGUiXSwiZXhwIjoxNTEzMDQ0MDA1LCJhdXRob3JpdGllcyI6WyJST0xFX01BTkFHRVIiLCJST0xFX0FETUlOIiwiUk9MRV9VU0VSIl0sImp0aSI6IjE3YjgxNWNhLTc5NmMtNGI4Ni05YjZjLWY3YzgzMjA0NzczOSIsImNsaWVudF9pZCI6Im15Zmlyc3RhcHAiLCJ1c2VybmFtZSI6ImFkbWluIn0.NQx11bSgHKv3dHYaLydyo7kwqsiydSLTZPvRaSXsXl4
content-type: application/json
cookie: XSRF-TOKEN=d1111657-c1b2-471a-99aa-a338c23dd8b5; JSESSIONID=983615fd-d156-4072-ac18-efd365345036
accept-encoding: gzip,deflate
user-agent: node-fetch/1.0 (+https://github.com/bitinn/node-fetch)
connection: close
Host: localhost:8080

Useful information:

Spring server:

Security account (cookie):

  • username: admin
  • password: verysecret

OAuth account (jwt):

  • client_id: myfirstapp
  • client_secret: test
  • redirect_uri: http://localhost:8080/
  • access_token_uri: http://localhost:8080/oauth/token
  • authorization_uri: http://localhost:8080/oauth/authorize
  • authorization_grant: code
  • redirect_uri: http://localhost:8080

Can you please keep us updated ?

kopax picture kopax on 12 Dec 2017
👍1

@kopax I was able to reproduce the issue based on your sample and I know what the issue is.

To recap, the root issue you are facing is a unique key constraint violation which logs this exception:

org.h2.jdbc.JdbcSQLException: Unique index or primary key violation: "PRIMARY_KEY_D ON PUBLIC.OAUTH_ACCESS_TOKEN(AUTHENTICATION_ID) VALUES ('b762270ce877e5b49c8f9305e3eb0ab1', 1)"

In your migration script V0_0_6__CreateTablesOAuth2.sql, the following table is created:

create table oauth_access_token (
  token_id VARCHAR(256),
  token BYTEA,
  authentication_id VARCHAR(256) PRIMARY KEY,
  user_name VARCHAR(256),
  client_id VARCHAR(256),
  authentication BYTEA,
  refresh_token VARCHAR(256)
);

The primary key is authentication_id.

DefaultAuthenticationKeyGenerator.extractKey() is the value generator for the authentication_id column.

Given your client test case, you are using the following user and client for all requests:

User: admin
Client: myfirstapp
Scopes: read trust write

Given these request parameters to the Token Endpoint, the value generated by DefaultAuthenticationKeyGenerator.extractKey() will always be the same for the authentication_id column.

This alone invalidates the test because you are simulating only one user instead of different users. For example, the same user/client combination calling the token endpoint is not a real world test and cannot really happen unless 2 user's log in with the same credentials and go through the exact same flow at the same time.

Either way, I want to explain why this error ocurrs in the async case.

Let's imagine the following scenario in this step sequence:

  1. Request 1 (Thread 1) - admin/myfirstapp requests an access token calling the Token endpoint. All is good and auth server issues a new access token. At this point we have a record in oauth_access_token with the authentication_id keyed using -> admin/myfirstapp/read trust write
    NOTE: Let's assume the expiration of the access token is 1 min from issue.

  2. Request 2 (Thread 2) - admin/myfirstapp requests an access token calling the Token endpoint. Given that an access token was created in Step 1 for the same user/client (admin/myfirstapp), then the existing access token is returned.

2 mins has passed now since the issuance of the access token...

  1. Request 3 (Thread 1) - admin/myfirstapp requests an access token calling the Token endpoint. There is an existing access token associated to admin/myfirstapp but it's expired. At this point a DELETE oauth_access_token is recorded followed by an INSERT oauth_access_token. Given that DefaultTokenServices.createAccessToken() has @Transactional it is check-pointed within a transaction. BUT before this method returns, which will commit the 2 transactions, Step 4 happens...

  2. Request 4 (Thread 2) - admin/myfirstapp requests an access token calling the Token endpoint. There is an existing access token associated to admin/myfirstapp but it's expired. At this point a DELETE oauth_access_token is recorded followed by an INSERT oauth_access_token. Given that DefaultTokenServices.createAccessToken() has @Transactional it is check-pointed within a transaction. BUT before this method returns, which will commit the 2 transactions, Step 5 happens...

  3. The 2 threads in Step 3 and 4 are executing at the same time using the same user/client and have similar transactions that are about to be committed. The only difference in the transactions is the value of the access token. But the authentication_id is the same, this is where the issue happens. Now let's say from Step 3. Request 3 (Thread 1), the call stack returns from DefaultTokenServices.createAccessToken() and therefore the 2 transactions are committed. Now we have a new record in oauth_access_token with a new access token but same authentication_id. All is good at this point. Now the next thing that happens is from Step 4. Request 4 (Thread 2), the call stack returns from DefaultTokenServices.createAccessToken() and therefore the 2 transactions are going to be committed but don't because the unique constraint happens. The insert statement for the oauth_access_token has the same authentication_id and therefore fails.

I hope this explains why the error is happening? It's pretty difficult to troubleshoot these kinds of errors and explain it in writing as well...race conditions are inherently difficult.

In a nutshell, using the same user principal to call the token endpoint on multiple async requests is not really a real world use case. It should be different user principals per request.

I'm going to leave this open for now until you go over my analysis and provide me your feedback on your understanding.

jgrandja picture jgrandja on 13 Dec 2017
👍8 ❤4 🎉3

so long as it doesn't display this sql in the http response 

Handling error: DuplicateKeyException, PreparedStatementCallback; SQL [insert into oauth_access_token (token_id, token, authentication_id, user_name, client_id, authentication, refresh_token) values (?, ?, ?, ?, ?, ?, ?)]; Unique index or primary key violation: "PRIMARY_KEY_D ON PUBLIC.OAUTH_ACCESS_TOKEN(AUTHENTICATION_ID) VALUES ('b762270ce877e5b49c8f9305e3eb0ab1', 14)"; SQL statement:

per #1200

xenoterracide picture xenoterracide on 13 Dec 2017

@xenoterracide Have you not tested it yet on your end? Or are you saying that it is displaying?

jgrandja picture jgrandja on 13 Dec 2017

@jgrandja thanks for providing detailled analysis. I understand that the race condition is producing this error.

The error is caused because of my script, which is doing an authentication for the same user asynchronously.

This can be easely corrected by updating my script to perform only one authentication and add the handling of renewing the token for long processing script.

But you also say this is not supposed to happen in real world, assuming a same account would never login multiple time at the same moment. This is by assuming a user have to be human. I assume it could be an automate.

To me, an automate user is a user used by script. It should be able to authenticate asynchronously.

For my automate users, I see a limitation. Either if possible we use a different automate user for each process or we handle the authentication using a service in charge of serving the jwt to scripts.

Could automate user be a feature of spring security or is it antipattern?

kopax picture kopax on 14 Dec 2017

@kopax I see your point and agree that a system-level user may be used in automated scripts that may perform load on the system and require authentication, as is the case for your test client.

However, the current implementation of DefaultTokenServices.createAccessToken() is correct and does not have any limitations. This is really an architecture problem and how your services/components and back-end data stores communicate with each other in a distributed/scalable environment.

To recap, the current implementation of DefaultTokenServices.createAccessToken() will remove an expired access token using a DELETE and add a new access token with an INSERT all in one transaction, given the fact the method is annotated with @Transactional. This logic/flow makes sense and is implemented as expected. There isn't a limitation here.

From a system architecture standpoint, there is a lot to consider when you have multiple requests hitting the same service and back-end store at the same time. I would recommend looking at database isolation levels (e.g. Serializable level) and ensure you have the proper setting for your data-store. You want to ensure that the transaction for DELETE expired token and INSERT new access token is committed before a READ access token (from another thread) happens for the same authentication_id or else you will get _dirty-reads_ which causes this issue. Keep in mind that certain isolation levels do affect performance.

There are other ways to solve these kinds of issues but that is another topic on the architecture side of things that is not related to this current implementation.

I'm going to close this issue as the current implementation works as designed and this really is a system level architecture problem that needs to be looked at.

jgrandja picture jgrandja on 14 Dec 2017
👎3 👍2

Thank you for your time, it did help.

kopax picture kopax on 14 Dec 2017

No worries and I'm glad it helped.

jgrandja picture jgrandja on 14 Dec 2017

@jgrandja , sorry to comment on the closed issue, but does this explanation applies to the client_credentials grant too? I see that discussion here is for the authorization_grant: code. I would see the same problems when using client_credentials which in fact only has 1 app as a user that, if scaled, should ask auth in parallel.

bcavlin picture bcavlin on 2 Apr 2018
👍2

Pardon me @jgrandja, did you point out actually that just because it's unusual to have multiple token requests from same user and client, you are not going to process them correctly (i.e. by rewriting existing token) AND not going to reflect any specific limitations in the manual? I suppose it's OK to refuse spending efforts on handling this specific case but if I decided so I would feel obliged to document that "please don't make concurrent token requests for same login and client combination"... But even so, how would my client instances (JS running on user's computer) ensure following that requirement? They don't know what other instances do. If some user decides to log in simultaneously from two instances, and the only description of the error is some DuplicateKeyException, do I just decide that any DuplicateKeyException means that the user tries simultaneous log-in? :) And tell the user "no simultaneous login attempt are allowed, please repeat your attempt now" :)

mgumerov picture mgumerov on 4 May 2018
👍5 ❤1

Also, I think I can propose yet another scenario for this problem: 1) two transactions check if there is a token in DB, both see there is none, but no key-range locks are applied because repeatable-reads do not forbid phantoms, and people rarely use isolation levels higher than repeatable_read. 2) both transactions create refresh token and then access token (don't yet store them). 3) both transactions attempt to store access token and refresh token, one succeeds another fails.

mgumerov picture mgumerov on 4 May 2018

@mgumerov ,i think so.but I use distribute-lock to solve it temporarily

xugc picture xugc on 8 May 2018

@mgumerov have you other suggestion?

xugc picture xugc on 8 May 2018

Sure. I'm gonna suffer.
To be serious, I'll settle with reporting unknown authentication error to the user in case this error happens. That's bad, but given how improbable it is to have one user logging in multiple times concurrently (if we are not speaking of tests, etc.), I am not expecting actual complaints about that.

mgumerov picture mgumerov on 9 May 2018

I confirm this is not uncommon at all when using client credentials from a busy application with multiple instances.
Had to fallback to this kind of hack : https://stackoverflow.com/questions/40981084/spring-oauth2-duplicatekeyexception-when-using-jdbctokenstore-and-defaulttokens

michaeltecourt picture michaeltecourt on 12 Oct 2018
👍6

Most of all it's disturbing and awkward to have to use hacks in a library which is supposed to be commercially ready, especially when a library is related to security - as everyone probably knows it's dangerous to invent something homebrewn in this area unless one is a seasoned professional in it. But here we are, having to rely on something proposed by some random guy on stackoverflow, however clever he might or might not be.

mgumerov picture mgumerov on 13 Oct 2018
👍2

Hello @jgrandja
I know this is an Old issue but it's still causing pain.

Here is what I've observed using the password flow:

A user logs in at oauth/token and gets an access-token. If the access-token is not used in any request before calling the oauth/token again there'll be an internal server error.

{
    "error": "server_error",
    "error_description": "Internal Server Error"
}

This is going to happen if the issued access-token has expired or not.

The internal server error is due to a duplicate primary key exception which is because the user's old access token still exists in the oauth_access_token table and from your explanation above, the same set of credentials will always generate the same authentication_id which is the primary key.

I enabled DEBUG logging level and found these lines:

...
2019-04-04 16:37:28.511 DEBUG 53859 --- [nio-8081-exec-6] o.s.jdbc.core.JdbcTemplate               : Executing prepared SQL statement [select token_id, token from oauth_access_token where authentication_id = ?]
2019-04-04 16:37:28.511 DEBUG 53859 --- [nio-8081-exec-6] o.s.jdbc.datasource.DataSourceUtils      : Fetching JDBC Connection from DataSource
2019-04-04 16:37:28.513 DEBUG 53859 --- [nio-8081-exec-6] o.a.c.loader.WebappClassLoaderBase       :     findClass(sun.reflect.GeneratedMethodAccessor60)
2019-04-04 16:37:28.514 DEBUG 53859 --- [nio-8081-exec-6] o.a.c.loader.WebappClassLoaderBase       :     --> Returning ClassNotFoundException
2019-04-04 16:37:28.515 ERROR 53859 --- [nio-8081-exec-6] o.s.s.o.p.token.store.JdbcTokenStore     : Could not extract access token for authentication org.springframework.security.oauth2.provider.OAuth2Authentication@83443d86: Principal: org.springframework.security.core.userdetails.User@586034f: Username: admin; Password: [PROTECTED]; Enabled: true; AccountNonExpired: true; credentialsNonExpired: true; AccountNonLocked: true; Granted Authorities: ROLE_ADMIN; Credentials: [PROTECTED]; Authenticated: true; Details: null; Granted Authorities: ROLE_ADMIN
...

My guess is an attempt there was an attempt at getting an existing token which did not return any result - which really shouldn't be because there's an existing token for the authentication_id in the oauth_access_token table.

So my questions:

  1. Why not simply delete any existing user's access-token from the oauth_access_token table whenever a valid request hit the oauth/token endpoint? Doing this will prevent the duplicate issue.

  2. Is there supposed to be a check for an existing token in the first place? As I can see something that looks like it in the logs.

Dependencies:

SpringBoot 2.1.3.RELEASE
spring-security-oauth2 2.3.5.RELEASE

Cheers.

SeunMatt picture SeunMatt on 4 Apr 2019

I'm running into the same problem with automated tests (uses the same credentials concurrently), and I'm not sure the issue has been made clear.

The code seems to delete and re-insert the token upon every token request, also if the token hasn't expired. So the concurrent token access for the same user doesn't only exist when the token has expired but also when it hasn't. This issue can be reproduced easily by concurrently hammering the token endpoint with the same credentials, no matter if a token for a user already exists when the hammering starts or not and no matter what the token TTL is.

Why is delete and insert issued every time? I understand it may be necessary if the token has expired (but even then you could update the existing token, right?), but not if the token is still valid.

Why not use pessimistic locking (SELECT FOR UPDATE) during the processing or optimistic locking (reacting to the key constraint violation exception when it happens by rolling back and retrying)? Whether you want that could be made configurable with a config property.

TranceTip picture TranceTip on 9 May 2019

Awesome analysis guys! Got a lot of idea about this issue which i had been trying to understand since last couple of day. Thanks for analysing the different reasons for this duplication issue for authentication_id.

priyankawagh9 picture priyankawagh9 on 11 Jul 2019

Can confirm that this is still an issue using Spring Cloud Greenwich.SR1 dependency management and Spring Boot 2.1.6.RELEASE. I have decided to try and resort to this solution provided above.

https://github.com/spring-projects/spring-security-oauth/issues/1242#issuecomment-429456384

ronaldewatts picture ronaldewatts on 20 Jul 2019

Coming back on my previous comment using a retry hack does not scale well.
I strongly recommend using Redis as a
TokenStore, it is the best implementation available out of the box.

michaeltecourt picture michaeltecourt on 20 Jul 2019

Thanks for that quick reply @michaeltecourt . You are probably right. Did you find that the problem doesn't manifest itself with the Redis TokenStore at all? Is it just because of the performance of Redis or because the underlying implementation doesn't have the flaws that the JdbcTokenStore implementation has?

ronaldewatts picture ronaldewatts on 20 Jul 2019

Redis is built for high performance and concurrency. We found out that using Redis completely solved the issue, and we got better performance as a bonus.
It鈥檚 a natural choice to store tokens in the end, we don鈥檛 need persistence on disk for ephemeral stuff. I believe the Jdbc version is useful for enterprises where you don鈥檛 pick a new data store easily.

michaeltecourt picture michaeltecourt on 20 Jul 2019

I have same problem in my project and I think i find where is the problem. My project is a spring boot within the transactional already manage by JNDI resources JDBC connection. In my case i get the Datasource by JNDI.

1) The DefaultTokenServices have the methods to create and refresh already transactional so Datasource is not transactional and need to add transaction see 2)

2) remember to put your datasource into the PlatformTransactionManager

@Bean
public PlatformTransactionManager transactionManager(){
...
setDatasource(datasource);
...
}
I think will be working now.

ezadi picture ezadi on 25 Jan 2020
Was this page helpful?
0 / 5 - 0 ratings

Related issues

jzbjyb picture jzbjyb  路  20Comments
rieonke picture rieonke  路  20Comments
sckoh picture sckoh  路  18Comments
rdifrango picture rdifrango  路  19Comments
karwer picture karwer  路  23Comments