supertokens-core icon indicating copy to clipboard operation
supertokens-core copied to clipboard
verified publisher icon supertokens

Not serialise access in delete passwordless codes cronjob

Open rishabhpoddar opened this issue 3 years ago • 3 comments

Raw error:

    "\u0001\u0000\u0000\u0000\u0000\u0000\u0001a02 Jun 2022 09:28:21:083 +0000 | ERROR | pid: b6e7bd73-7fcc-4c53-8bcb-36032382eb23 | [pool-1-thread-1] thread | io.supertokens.cronjobs.CronTask.run(CronTask.java:47) | io.supertokens.pluginInterface.exceptions.StorageQueryException: org.postgresql.util.PSQLException: ERROR: could not serialize access due to read/write dependencies among transactions",
    "\u0001\u0000\u0000\u0000\u0000\u0000\u0000�02 Jun 2022 09:28:21:083 +0000 | ERROR | pid: b6e7bd73-7fcc-4c53-8bcb-36032382eb23 | [pool-1-thread-1] thread | io.supertokens.cronjobs.CronTask.run(CronTask.java:47) | Cronjob threw an exception: DeleteExpiredPasswordlessDevices"
]

Jun 2022 09:28:21:083 +0000 | ERROR | pid: b6e7bd73-7fcc-4c53-8bcb-36032382eb23 | [pool-1-thread-1] thread | io.supertokens.cronjobs.CronTask.run(CronTask.java:47) | io.supertokens.pluginInterface.exceptions.StorageQueryException: org.postgresql.util.PSQLException: ERROR: could not serialize access due to read/write dependencies among transactions
Detail: Reason code: Canceled on identification as a pivot, during write.
Hint: The transaction might succeed if retried.
at io.supertokens.storage.postgresql.Start.deleteDevice_Transaction(Start.java:1117)
at io.supertokens.storage.postgresql.Start.startTransactionHelper(Start.java:255)
at io.supertokens.storage.postgresql.Start.startTransaction(Start.java:169)
at io.supertokens.storage.postgresql.Start.startTransaction(Start.java:159)
at io.supertokens.cronjobs.deleteExpiredPasswordlessDevices.DeleteExpiredPasswordlessDevices.doTask(DeleteExpiredPasswordlessDevices.java:66)
at io.supertokens.cronjobs.CronTask.run(CronTask.java:44)
at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
at java.base/java.util.concurrent.FutureTask.runAndReset(FutureTask.java:305)
at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:305)
at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130)
at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:630)
at java.base/java.lang.Thread.run(Thread.java:832)
Caused by: org.postgresql.util.PSQLException: ERROR: could not serialize access due to read/write dependencies among transactions
Detail: Reason code: Canceled on identification as a pivot, during write.
Hint: The transaction might succeed if retried.
at org.postgresql.core.v3.QueryExecutorImpl.receiveErrorResponse(QueryExecutorImpl.java:2510)
at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:2245)
at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:311)
at org.postgresql.jdbc.PgStatement.executeInternal(PgStatement.java:447)
at org.postgresql.jdbc.PgStatement.execute(PgStatement.java:368)
at org.postgresql.jdbc.PgPreparedStatement.executeWithFlags(PgPreparedStatement.java:159)
at org.postgresql.jdbc.PgPreparedStatement.executeUpdate(PgPreparedStatement.java:125)
at com.zaxxer.hikari.pool.ProxyPreparedStatement.executeUpdate(ProxyPreparedStatement.java:61)
at com.zaxxer.hikari.pool.HikariProxyPreparedStatement.executeUpdate(HikariProxyPreparedStatement.java)
at io.supertokens.storage.postgresql.QueryExecutorTemplate.update(QueryExecutorTemplate.java:58)
at io.supertokens.storage.postgresql.queries.PasswordlessQueries.deleteDevice_Transaction(PasswordlessQueries.java:150)
at io.supertokens.storage.postgresql.Start.deleteDevice_Transaction(Start.java:1117)
... 12 more

rishabhpoddar avatar Jun 02 '22 18:06 rishabhpoddar

I couldn't reproduce it in tests. I think we should reduce the isolation level if the problem persists. I have two theories:

  1. Something is wrong with the index. Something like this
  2. The row-level locks of devices get upgraded to page locks during the cleanup, and this somehow causes a deadlock when the user is consuming a device (not the one being cleaned up). I'm not sure why this would persist through retries though.

porcellus avatar Jun 16 '22 00:06 porcellus

We've decided to leave this as-is for now. Leaving this issue open and we'll monitor if it pops up again.

porcellus avatar Jun 20 '22 08:06 porcellus

I also attempted to reproduce this but wasn't able to locally. My tests passed every time. I tried the following:

  • Having a random order of several INSERT / DELETES (transactions) but directly in SQL. Was not able to repro. I explicitly set the transaction isolated level to serializable
  • Used the executor pool to do the inserts (random UUIDs) at low msec intervals (on order of thousands). Set the deletes to 1 sec interval for the cronjob.
  • Same as above but set the cron job interval to much higher, 60 secs, to try and lessen deletes and fill up more rows.
  • Used two separate runnable threads to do lots of inserts as well, very low intervals, along with running the cron.
  • Also tried inserting rows via direct SQL but deleting via the test.

gauravtokens avatar Jul 18 '22 05:07 gauravtokens

Hey everyone, I can confirm the same issue is happening when using passwordless on supertokens-postgresql:4.1 with PostgreSQL v14.4.0. We have 3000+ users, the issue happens once every 3-4 days.

Python exception message:

SuperTokens core threw an error for a POST request to path: /recipe/signinup/code/consume with status code: 500 and message: Internal Error

Supertokens Core logs:

11 Oct 2022 09:01:41:510 +0000 | ERROR | pid: d09335b5-1c8b-4a47-b0ed-7df00b263327 | [http-nio-0.0.0.0-3567-exec-10] thread | io.supertokens.webserver.WebserverAPI.service(WebserverAPI.java:167) | javax.servlet.ServletException: io.supertokens.pluginInterface.exceptions.StorageQueryException: org.postgresql.util.PSQLException: ERROR: could not serialize access due to read/write dependencies among transactions
  Detail: Reason code: Canceled on identification as a pivot, during write.
  Hint: The transaction might succeed if retried.
	at io.supertokens.webserver.api.passwordless.ConsumeCodeAPI.doPost(ConsumeCodeAPI.java:124)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:660)
	at io.supertokens.webserver.WebserverAPI.service(WebserverAPI.java:165)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:741)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:231)
	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:528)
	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:798)
	at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:66)
	at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:810)
	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1500)
	at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49)
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130)
	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: io.supertokens.pluginInterface.exceptions.StorageQueryException: org.postgresql.util.PSQLException: ERROR: could not serialize access due to read/write dependencies among transactions
  Detail: Reason code: Canceled on identification as a pivot, during write.
  Hint: The transaction might succeed if retried.
	at io.supertokens.storage.postgresql.Start.deleteDevicesByPhoneNumber_Transaction(Start.java:1231)
	at io.supertokens.passwordless.Passwordless.lambda$consumeCode$0(Passwordless.java:246)
	at io.supertokens.storage.postgresql.Start.startTransactionHelper(Start.java:268)
	at io.supertokens.storage.postgresql.Start.startTransaction(Start.java:187)
	at io.supertokens.storage.postgresql.Start.startTransaction(Start.java:177)
	at io.supertokens.passwordless.Passwordless.consumeCode(Passwordless.java:203)
	at io.supertokens.webserver.api.passwordless.ConsumeCodeAPI.doPost(ConsumeCodeAPI.java:86)
	... 21 more
Caused by: org.postgresql.util.PSQLException: ERROR: could not serialize access due to read/write dependencies among transactions
  Detail: Reason code: Canceled on identification as a pivot, during write.
  Hint: The transaction might succeed if retried.
	at org.postgresql.core.v3.QueryExecutorImpl.receiveErrorResponse(QueryExecutorImpl.java:2510)
	at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:2245)
	at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:311)
	at org.postgresql.jdbc.PgStatement.executeInternal(PgStatement.java:447)
	at org.postgresql.jdbc.PgStatement.execute(PgStatement.java:368)
	at org.postgresql.jdbc.PgPreparedStatement.executeWithFlags(PgPreparedStatement.java:159)
	at org.postgresql.jdbc.PgPreparedStatement.executeUpdate(PgPreparedStatement.java:125)
	at com.zaxxer.hikari.pool.ProxyPreparedStatement.executeUpdate(ProxyPreparedStatement.java:61)
	at com.zaxxer.hikari.pool.HikariProxyPreparedStatement.executeUpdate(HikariProxyPreparedStatement.java)
	at io.supertokens.storage.postgresql.QueryExecutorTemplate.update(QueryExecutorTemplate.java:58)
	at io.supertokens.storage.postgresql.queries.PasswordlessQueries.deleteDevicesByPhoneNumber_Transaction(PasswordlessQueries.java:158)
	at io.supertokens.storage.postgresql.Start.deleteDevicesByPhoneNumber_Transaction(Start.java:1229)
	... 27 more

execreate avatar Oct 11 '22 09:10 execreate

This should have been fixed in core version >= 6.0

rishabhpoddar avatar Jul 22 '23 16:07 rishabhpoddar