0

I am trying to create 50 users simultaneously through parallel POST /api/user calls. Getting sql timeout exception. Is there any way to increase timeout ? Is there any better solution to achieve this.

FusionAuth on AKS 1.14.6. Enough hardware resources available on Node.

Postgres 9.6

 Sep 16, 2019 8:23:12.859 PM ERROR io.fusionauth.app.primeframework.error.ExceptionExceptionHandler - An unhandled exception was thrown
    org.apache.ibatis.exceptions.PersistenceException: 
    ### Error updating database.  Cause: java.sql.SQLTransientConnectionException: HikariPool-2 - Connection is not available, request timed out after 2000ms.
    ### Cause: java.sql.SQLTransientConnectionException: HikariPool-2 - Connection is not available, request timed out after 2000ms.
        at org.apache.ibatis.exceptions.ExceptionFactory.wrapException(ExceptionFactory.java:30)
        at org.apache.ibatis.session.defaults.DefaultSqlSession.update(DefaultSqlSession.java:200)
        at org.apache.ibatis.session.defaults.DefaultSqlSession.insert(DefaultSqlSession.java:185)
        at sun.reflect.GeneratedMethodAccessor73.invoke(Unknown Source)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:498)
        at org.apache.ibatis.session.SqlSessionManager$SqlSessionInterceptor.invoke(SqlSessionManager.java:350)
        at com.sun.proxy.$Proxy79.insert(Unknown Source)
        at org.apache.ibatis.session.SqlSessionManager.insert(SqlSessionManager.java:236)
        at org.apache.ibatis.binding.MapperMethod.execute(MapperMethod.java:58)
        at org.apache.ibatis.binding.MapperProxy.invoke(MapperProxy.java:59)
        at com.sun.proxy.$Proxy114.create(Unknown Source)
        at io.fusionauth.api.service.user.DefaultUserService.create(DefaultUserService.java:256)
        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.app.action.api.UserAction.post(UserAction.java:115)
        at sun.reflect.GeneratedMethodAccessor180.invoke(Unknown Source)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:498)
        at org.primeframework.mvc.util.ReflectionUtils.invoke(ReflectionUtils.java:436)
        at org.primeframework.mvc.action.DefaultActionInvocationWorkflow.execute(DefaultActionInvocationWorkflow.java:84)
        at org.primeframework.mvc.action.DefaultActionInvocationWorkflow.perform(DefaultActionInvocationWorkflow.java:64)
        at org.primeframework.mvc.workflow.SubWorkflowChain.continueWorkflow(SubWorkflowChain.java:43)
        at org.primeframework.mvc.validation.DefaultValidationWorkflow.perform(DefaultValidationWorkflow.java:47)
        at org.primeframework.mvc.workflow.SubWorkflowChain.continueWorkflow(SubWorkflowChain.java:43)
        at org.primeframework.mvc.security.DefaultSecurityWorkflow.perform(DefaultSecurityWorkflow.java:81)
        at org.primeframework.mvc.workflow.SubWorkflowChain.continueWorkflow(SubWorkflowChain.java:43)
        at org.primeframework.mvc.parameter.DefaultPostParameterWorkflow.perform(DefaultPostParameterWorkflow.java:50)
        at org.primeframework.mvc.workflow.SubWorkflowChain.continueWorkflow(SubWorkflowChain.java:43)
        at org.primeframework.mvc.content.DefaultContentWorkflow.perform(DefaultContentWorkflow.java:52)
        at org.primeframework.mvc.workflow.SubWorkflowChain.continueWorkflow(SubWorkflowChain.java:43)
        at org.primeframework.mvc.parameter.DefaultParameterWorkflow.perform(DefaultParameterWorkflow.java:57)
        at org.primeframework.mvc.workflow.SubWorkflowChain.continueWorkflow(SubWorkflowChain.java:43)
        at org.primeframework.mvc.parameter.DefaultURIParameterWorkflow.perform(DefaultURIParameterWorkflow.java:102)
        at org.primeframework.mvc.workflow.SubWorkflowChain.continueWorkflow(SubWorkflowChain.java:43)
        at org.primeframework.mvc.scope.DefaultScopeRetrievalWorkflow.perform(DefaultScopeRetrievalWorkflow.java:58)
        at org.primeframework.mvc.workflow.SubWorkflowChain.continueWorkflow(SubWorkflowChain.java:43)
        at org.primeframework.mvc.message.DefaultMessageWorkflow.perform(DefaultMessageWorkflow.java:45)
        at org.primeframework.mvc.workflow.SubWorkflowChain.continueWorkflow(SubWorkflowChain.java:43)
        at org.primeframework.mvc.action.DefaultActionMappingWorkflow.perform(DefaultActionMappingWorkflow.java:126)
        at org.primeframework.mvc.workflow.SubWorkflowChain.continueWorkflow(SubWorkflowChain.java:43)
        at org.primeframework.mvc.workflow.StaticResourceWorkflow.perform(StaticResourceWorkflow.java:97)
        at org.primeframework.mvc.workflow.SubWorkflowChain.continueWorkflow(SubWorkflowChain.java:43)
        at org.primeframework.mvc.parameter.RequestBodyWorkflow.perform(RequestBodyWorkflow.java:89)
        at org.primeframework.mvc.workflow.SubWorkflowChain.continueWorkflow(SubWorkflowChain.java:43)
        at org.primeframework.mvc.security.DefaultSavedRequestWorkflow.perform(DefaultSavedRequestWorkflow.java:57)
        at org.primeframework.mvc.workflow.SubWorkflowChain.continueWorkflow(SubWorkflowChain.java:43)
        at io.fusionauth.api.primeframework.CORSFilter.handleNonCORS(CORSFilter.java:317)
        at io.fusionauth.api.primeframework.CORSFilter.doFilter(CORSFilter.java:278)
        at io.fusionauth.api.primeframework.CORSRequestWorkflow.perform(CORSRequestWorkflow.java:48)
        at org.primeframework.mvc.workflow.SubWorkflowChain.continueWorkflow(SubWorkflowChain.java:43)
        at io.fusionauth.api.primeframework.FusionAuthMVCWorkflow.perform(FusionAuthMVCWorkflow.java:87)
        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:84)
        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:493)
        at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:137)
        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:798)
        at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:66)
        at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:808)
        at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1498)
        at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
        at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
        at java.lang.Thread.run(Thread.java:748)
    Caused by: java.sql.SQLTransientConnectionException: HikariPool-2 - Connection is not available, request timed out after 2000ms.
        at com.zaxxer.hikari.pool.HikariPool.createTimeoutException(HikariPool.java:602)
        at com.zaxxer.hikari.pool.HikariPool.getConnection(HikariPool.java:195)
        at com.zaxxer.hikari.pool.HikariPool.getConnection(HikariPool.java:145)
        at com.zaxxer.hikari.HikariDataSource.getConnection(HikariDataSource.java:85)
        at org.apache.ibatis.transaction.jdbc.JdbcTransaction.openConnection(JdbcTransaction.java:139)
        at org.apache.ibatis.transaction.jdbc.JdbcTransaction.getConnection(JdbcTransaction.java:61)
        at org.apache.ibatis.executor.BaseExecutor.getConnection(BaseExecutor.java:338)
        at org.apache.ibatis.executor.SimpleExecutor.prepareStatement(SimpleExecutor.java:84)
        at org.apache.ibatis.executor.SimpleExecutor.doUpdate(SimpleExecutor.java:49)
        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:198)
Venkata Dorisala
  • 4,783
  • 7
  • 49
  • 90

1 Answers1

3

The Import API is the best solution for creating multiple users in a single call. This API is documented here:

https://fusionauth.io/docs/v1/tech/apis/users#import-users

However, I'm confused that PostgreSQL was backing up like that and causing timeouts in FusionAuth's database connection pool. Normally, timeouts are caused by table locking, so unless you have tons of users in the table already, you shouldn't run into any issues.

If you do have a bunch of users in the database already, then you could be hitting an issue where the unique key indexes for the users table (email and username) are not able to fit in memory in PostgreSQL and it is going to disk to ensure that new records don't violate constraints.

You might want to check the processes and transaction that are running inside PostgreSQL to see what is causing the timeouts.

If you think this is a bug, feel free to open an issue on the FusionAuth GitHub Issue tracker and provide as much detail as possible.

voidmain
  • 1,625
  • 1
  • 14
  • 14
  • I have only 150 users in the database. Is there anyway we can increase that timeout in fusionauth configuration? – Venkata Dorisala Sep 16 '19 at 21:10
  • @Venky you can extend the default connection timeout for the connection pool. I would hesitate to recommend this for a production scenario, it is more likely there is something else going on that is causing this timeout to occur as Brian mentioned. If you want to mess with it anyway, to increase the timeout, add `database.connection-timeout=` to the `fusionauth.properties` file. We default to 2000 milliseconds (2 seconds), in order to increase it to 30 seconds for example the property would be `database.connection-timeout= 30000`. – robotdan Sep 17 '19 at 01:34
  • 2s for a transaction is really high. Inserts for users should take a few milliseconds and that would mean you should be able to do hundreds of inserts per second. My guess is that your database or your network has something else causing the timeouts. If this is easy to reproduce, you should just run the test and then start dumping the state of the database to see what is happening. You can also turn on logging in the database to see what statements might be causing issues. – voidmain Sep 17 '19 at 02:23
  • Event log is throwing this error per insert: `html : freemarker.core.InvalidReferenceException: The following has evaluated to null or missing: ==> changePasswordId [in nameless template at line 1, column 166]` – David Wilson Sep 17 '19 at 13:34
  • As a test we have email templates disabled for this tenant (1.8.1). We are registering an app for user immediately after creation of the user but had skipRegistrationVerification at default. It is odd that the reported template is 'nameless'. Error continues when skipRegistrationVerification is set to true. I'll open a GitHub issue. – David Wilson Sep 17 '19 at 13:41