Facing duplicate key errors on high load



  • Hi everybody,

    We are protecting some APIs of our company using an API Gateway and FusionAuth as an Identity Provider. There are some of this APIs that may have, ocassionally, a moderate-high load. What the Gateway does is extracting the Basic Auth credentials received from the client, and exchange these for a token with FusionAuth, by calling at the /oauth2/token endpoint. Basically, the gateway acts as an OAuth2 Client. Note that when the Gateway exchanges the credentials for the token it keeps using the same token for further requests of this user, until it expires.

    On the FusionAuth side, we have implemented a generic connector for these users, because they are currently stored in an specific database that we cannot migrate to FusionAuth yet (so the connector is configured for the Tenant with the Migrate check disabled).

    But when we receive many requests at the same time for a specific user (sometimes we do) that does not have a token issued yet, the token exchange process might be executed at the same time multiple times. That causes many requests to our connector, and to all of them the connector response is successful. But since all of those login attempts are issued for the same usser, our connector responds always with the same UUID, and FusionAuth seems to try to insert this user multiple times in its database, causing errors like the following:

    Failed to synchronize the user.
    Exception encountered.
    
    org.apache.ibatis.exceptions.PersistenceException : Message: 
    ### Error updating database.  Cause: org.postgresql.util.PSQLException: ERROR: duplicate key value violates unique constraint "users_pkey"
      Detail: Key (id)=(cbac44f2-5cc8-37a8-9e7e-c47ab95bbbf3) already exists.
    ### The error may exist in io/fusionauth/api/domain/UserMapper.xml
    ### The error may involve defaultParameterMap
    ### The error occurred while setting parameters
    ### SQL: INSERT INTO users (id, active, birth_date, clean_speak_id, data, expiry, first_name, full_name, image_url, insert_instant, last_name, last_update_instant, middle_name, mobile_phone, parent_email, tenants_id, timezone)       VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?)
    ### Cause: org.postgresql.util.PSQLException: ERROR: duplicate key value violates unique constraint "users_pkey"
      Detail: Key (id)=(cbac44f2-5cc8-37a8-9e7e-c47ab95bbbf3) already exists.
    Cause
    
    org.postgresql.util.PSQLException : Message: ERROR: duplicate key value violates unique constraint "users_pkey"
      Detail: Key (id)=(cbac44f2-5cc8-37a8-9e7e-c47ab95bbbf3) already exists.
    
    org.apache.ibatis.exceptions.PersistenceException: 
    ### Error updating database.  Cause: org.postgresql.util.PSQLException: ERROR: duplicate key value violates unique constraint "users_pkey"
      Detail: Key (id)=(cbac44f2-5cc8-37a8-9e7e-c47ab95bbbf3) already exists.
    ### The error may exist in io/fusionauth/api/domain/UserMapper.xml
    ### The error may involve defaultParameterMap
    ### The error occurred while setting parameters
    ### SQL: INSERT INTO users (id, active, birth_date, clean_speak_id, data, expiry, first_name, full_name, image_url, insert_instant, last_name, last_update_instant, middle_name, mobile_phone, parent_email, tenants_id, timezone)       VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?)
    ### Cause: org.postgresql.util.PSQLException: ERROR: duplicate key value violates unique constraint "users_pkey"
      Detail: Key (id)=(cbac44f2-5cc8-37a8-9e7e-c47ab95bbbf3) already exists.
    	at org.apache.ibatis.exceptions.ExceptionFactory.wrapException(ExceptionFactory.java:30)
    	at org.apache.ibatis.session.defaults.DefaultSqlSession.update(DefaultSqlSession.java:199)
    	at org.apache.ibatis.session.defaults.DefaultSqlSession.insert(DefaultSqlSession.java:184)
    	at jdk.internal.reflect.GeneratedMethodAccessor114.invoke(Unknown Source)
    	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    	at java.base/java.lang.reflect.Method.invoke(Method.java:564)
    	at org.apache.ibatis.session.SqlSessionManager$SqlSessionInterceptor.invoke(SqlSessionManager.java:350)
    	at com.sun.proxy.$Proxy46.insert(Unknown Source)
    	at org.apache.ibatis.session.SqlSessionManager.insert(SqlSessionManager.java:236)
    	at org.apache.ibatis.binding.MapperMethod.execute(MapperMethod.java:62)
    	at org.apache.ibatis.binding.MapperProxy.invoke(MapperProxy.java:93)
    	at com.sun.proxy.$Proxy89.create(Unknown Source)
    	at io.fusionauth.api.service.user.DefaultUserService._create(DefaultUserService.java:284)
    	at org.mybatis.guice.transactional.TransactionalMethodInterceptor.invoke(TransactionalMethodInterceptor.java:96)
    	at org.mybatis.guice.transactional.TransactionalMethodInterceptor.invoke(TransactionalMethodInterceptor.java:96)
    	at org.mybatis.guice.transactional.TransactionalMethodInterceptor.invoke(TransactionalMethodInterceptor.java:96)
    	at org.mybatis.guice.transactional.TransactionalMethodInterceptor.invoke(TransactionalMethodInterceptor.java:96)
    	at io.fusionauth.api.service.user.DefaultUserService.create(DefaultUserService.java:401)
    	at io.fusionauth.api.service.connector.BaseConnector.synchronizeExternalUser(BaseConnector.java:199)
    	at io.fusionauth.api.service.connector.GenericConnector.authenticate(GenericConnector.java:108)
    	at io.fusionauth.api.service.authentication.DefaultAuthenticationService._authenticate(DefaultAuthenticationService.java:136)
    	at org.mybatis.guice.transactional.TransactionalMethodInterceptor.invoke(TransactionalMethodInterceptor.java:96)
    	at org.mybatis.guice.transactional.TransactionalMethodInterceptor.invoke(TransactionalMethodInterceptor.java:96)
    	at org.mybatis.guice.transactional.TransactionalMethodInterceptor.invoke(TransactionalMethodInterceptor.java:96)
    	at org.mybatis.guice.transactional.TransactionalMethodInterceptor.invoke(TransactionalMethodInterceptor.java:96)
    	at io.fusionauth.api.service.authentication.DefaultAuthenticationService.authenticate(DefaultAuthenticationService.java:164)
    	at io.fusionauth.app.action.api.LoginAction.lambda$post$1(LoginAction.java:126)
    	at io.fusionauth.app.action.api.BaseLoginAction.callLogin(BaseLoginAction.java:165)
    	at io.fusionauth.app.action.api.LoginAction.post(LoginAction.java:126)
    	at jdk.internal.reflect.GeneratedMethodAccessor153.invoke(Unknown Source)
    	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    	at java.base/java.lang.reflect.Method.invoke(Method.java:564)
    	at org.primeframework.mvc.util.ReflectionUtils.invoke(ReflectionUtils.java:414)
    	at org.primeframework.mvc.action.DefaultActionInvocationWorkflow.execute(DefaultActionInvocationWorkflow.java:79)
    	at org.primeframework.mvc.action.DefaultActionInvocationWorkflow.perform(DefaultActionInvocationWorkflow.java:62)
    	at org.primeframework.mvc.workflow.SubWorkflowChain.continueWorkflow(SubWorkflowChain.java:51)
    	at org.primeframework.mvc.validation.DefaultValidationWorkflow.perform(DefaultValidationWorkflow.java:47)
    	at org.primeframework.mvc.workflow.SubWorkflowChain.continueWorkflow(SubWorkflowChain.java:51)
    	at org.primeframework.mvc.security.DefaultSecurityWorkflow.perform(DefaultSecurityWorkflow.java:81)
    	at org.primeframework.mvc.workflow.SubWorkflowChain.continueWorkflow(SubWorkflowChain.java:51)
    	at org.primeframework.mvc.parameter.DefaultPostParameterWorkflow.perform(DefaultPostParameterWorkflow.java:50)
    	at org.primeframework.mvc.workflow.SubWorkflowChain.continueWorkflow(SubWorkflowChain.java:51)
    	at org.primeframework.mvc.content.DefaultContentWorkflow.perform(DefaultContentWorkflow.java:52)
    	at org.primeframework.mvc.workflow.SubWorkflowChain.continueWorkflow(SubWorkflowChain.java:51)
    	at org.primeframework.mvc.parameter.DefaultParameterWorkflow.perform(DefaultParameterWorkflow.java:57)
    	at org.primeframework.mvc.workflow.SubWorkflowChain.continueWorkflow(SubWorkflowChain.java:51)
    	at org.primeframework.mvc.parameter.DefaultURIParameterWorkflow.perform(DefaultURIParameterWorkflow.java:102)
    	at org.primeframework.mvc.workflow.SubWorkflowChain.continueWorkflow(SubWorkflowChain.java:51)
    	at org.primeframework.mvc.scope.DefaultScopeRetrievalWorkflow.perform(DefaultScopeRetrievalWorkflow.java:58)
    	at org.primeframework.mvc.workflow.SubWorkflowChain.continueWorkflow(SubWorkflowChain.java:51)
    	at org.primeframework.mvc.message.DefaultMessageWorkflow.perform(DefaultMessageWorkflow.java:44)
    	at org.primeframework.mvc.workflow.SubWorkflowChain.continueWorkflow(SubWorkflowChain.java:51)
    	at io.fusionauth.app.primeframework.FrontEndTenantWorkflow.perform(FrontEndTenantWorkflow.java:73)
    	at org.primeframework.mvc.workflow.SubWorkflowChain.continueWorkflow(SubWorkflowChain.java:51)
    	at org.primeframework.mvc.action.DefaultActionMappingWorkflow.perform(DefaultActionMappingWorkflow.java:126)
    	at org.primeframework.mvc.workflow.SubWorkflowChain.continueWorkflow(SubWorkflowChain.java:51)
    	at org.primeframework.mvc.workflow.StaticResourceWorkflow.perform(StaticResourceWorkflow.java:97)
    	at org.primeframework.mvc.workflow.SubWorkflowChain.continueWorkflow(SubWorkflowChain.java:51)
    	at org.primeframework.mvc.parameter.RequestBodyWorkflow.perform(RequestBodyWorkflow.java:89)
    	at org.primeframework.mvc.workflow.SubWorkflowChain.continueWorkflow(SubWorkflowChain.java:51)
    	at org.primeframework.mvc.security.DefaultSavedRequestWorkflow.perform(DefaultSavedRequestWorkflow.java:64)
    	at org.primeframework.mvc.workflow.SubWorkflowChain.continueWorkflow(SubWorkflowChain.java:51)
    	at io.fusionauth.app.primeframework.CORSFilter.doFilter(CORSFilter.java:240)
    	at io.fusionauth.app.primeframework.CORSRequestWorkflow.perform(CORSRequestWorkflow.java:48)
    	at org.primeframework.mvc.workflow.SubWorkflowChain.continueWorkflow(SubWorkflowChain.java:51)
    	at io.fusionauth.app.primeframework.FusionAuthMVCWorkflow.perform(FusionAuthMVCWorkflow.java:88)
    	at org.primeframework.mvc.workflow.DefaultWorkflowChain.continueWorkflow(DefaultWorkflowChain.java:44)
    	at org.primeframework.mvc.servlet.FilterWorkflowChain.continueWorkflow(FilterWorkflowChain.java:50)
    	at org.primeframework.mvc.servlet.PrimeFilter.doFilter(PrimeFilter.java:78)
    	at com.inversoft.maintenance.servlet.MaintenanceModePrimeFilter.doFilter(MaintenanceModePrimeFilter.java:59)
    	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
    	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
    	at com.inversoft.servlet.UTF8Filter.doFilter(UTF8Filter.java:27)
    	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:543)
    	at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:139)
    	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:343)
    	at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:615)
    	at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:65)
    	at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:818)
    	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1626)
    	at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49)
    	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
    	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:630)
    	at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
    	at java.base/java.lang.Thread.run(Thread.java:832)
    Caused by: org.postgresql.util.PSQLException: ERROR: duplicate key value violates unique constraint "users_pkey"
      Detail: Key (id)=(cbac44f2-5cc8-37a8-9e7e-c47ab95bbbf3) already exists.
    	at org.postgresql.core.v3.QueryExecutorImpl.receiveErrorResponse(QueryExecutorImpl.java:2532)
    	at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:2267)
    	at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:312)
    	at org.postgresql.jdbc.PgStatement.executeInternal(PgStatement.java:448)
    	at org.postgresql.jdbc.PgStatement.execute(PgStatement.java:369)
    	at org.postgresql.jdbc.PgPreparedStatement.executeWithFlags(PgPreparedStatement.java:153)
    	at org.postgresql.jdbc.PgPreparedStatement.execute(PgPreparedStatement.java:142)
    	at com.zaxxer.hikari.pool.ProxyPreparedStatement.execute(ProxyPreparedStatement.java:44)
    	at com.zaxxer.hikari.pool.HikariProxyPreparedStatement.execute(HikariProxyPreparedStatement.java)
    	at org.apache.ibatis.executor.statement.PreparedStatementHandler.update(PreparedStatementHandler.java:47)
    	at org.apache.ibatis.executor.statement.RoutingStatementHandler.update(RoutingStatementHandler.java:74)
    	at org.apache.ibatis.executor.SimpleExecutor.doUpdate(SimpleExecutor.java:50)
    	at org.apache.ibatis.executor.BaseExecutor.update(BaseExecutor.java:117)
    	at org.apache.ibatis.executor.CachingExecutor.update(CachingExecutor.java:76)
    	at org.apache.ibatis.session.defaults.DefaultSqlSession.update(DefaultSqlSession.java:197)
    	... 89 more
    

    The user of course gets created in one of the simultaneous requests:
    fb759cdf-ff04-4e19-983a-358d1c59ba10-image.png

    The requests that fail provoke a failed response in the /oauth2/token (actually it responds with a HTTP 400), which at the same time provokes that the gateway issues an HTTP 401 to our clients for these requests, because they cannot be authenticated.

    Do you have any idea on how we can face this issue? Eventually we will migrate these users to FusionAuth, which would solve our problem since the users would only be synchronized once from the connector to FusionAuth, but this is not something we can accomplish at the moment.



  • @jm-oliver

    Sorry to see that you are having trouble. I am having a hard time determining if this behavior is in fact a bug or perhaps due to some specifics of your implementation of FusionAuth. For now, I am going to err on the side of caution and log a bug report.
    https://github.com/FusionAuth/fusionauth-issues/issues/1231

    If it does turn out to be implementation-related, we can circle back here to see if any other members of the community have any input.

    Do you happen to have the version you are running of FusionAuth? Any other details might prove helpful.

    Thanks,
    Josh



  • Hi @joshua,

    Thank you for your help. At the moment we are using FusionAuth version 1.23.3. We have it deployed on Kubernetes (2 pods at the moment), and using Amazon RDS (PostgreSQL) as database.

    Let me know if there's anything else that might be useful to you.

    Regards,
    Jordi