Query cancellation can sometimes fail

[kokosing]

2021-01-18T15:48:28.6388882Z [ERROR] Tests run: 2130, Failures: 1, Errors: 0, Skipped: 4, Time elapsed: 1,576.439 s <<< FAILURE! - in TestSuite
2021-01-18T15:48:28.6390800Z [ERROR] close(io.trino.execution.TestUserImpersonationAccessControl)  Time elapsed: 0.116 s  <<< FAILURE!
2021-01-18T15:48:28.6401398Z io.trino.NotInTransactionException: Unknown transaction ID: 71f7a8df-5c45-4722-b627-664f6622dd23. Possibly expired? Commands ignored until end of transaction block
2021-01-18T15:48:28.6404268Z 	at io.trino.transaction.InMemoryTransactionManager.getTransactionMetadata(InMemoryTransactionManager.java:257)
2021-01-18T15:48:28.6407503Z 	at io.trino.transaction.InMemoryTransactionManager.getTransactionInfo(InMemoryTransactionManager.java:155)
2021-01-18T15:48:28.6410162Z 	at io.trino.transaction.TransactionManager.isAutoCommit(TransactionManager.java:37)
2021-01-18T15:48:28.6412266Z 	at io.trino.execution.QueryStateMachine.lambda$transitionToCanceled$15(QueryStateMachine.java:925)
2021-01-18T15:48:28.6413828Z 	at java.base/java.util.Optional.ifPresent(Optional.java:183)
2021-01-18T15:48:28.6415590Z 	at io.trino.execution.QueryStateMachine.transitionToCanceled(QueryStateMachine.java:924)
2021-01-18T15:48:28.6418783Z 	at io.trino.execution.SqlQueryExecution.cancelQuery(SqlQueryExecution.java:540)
2021-01-18T15:48:28.6420306Z 	at java.base/java.util.Optional.ifPresent(Optional.java:183)
2021-01-18T15:48:28.6421744Z 	at io.trino.execution.SqlQueryManager.cancelQuery(SqlQueryManager.java:255)
2021-01-18T15:48:28.6423924Z 	at io.trino.testing.DistributedQueryRunner.cancelAllQueries(DistributedQueryRunner.java:524)
2021-01-18T15:48:28.6426057Z 	at io.trino.testing.DistributedQueryRunner.close(DistributedQueryRunner.java:510)
2021-01-18T15:48:28.6434766Z 	at io.trino.util.AutoCloseableCloser.close(AutoCloseableCloser.java:52)
2021-01-18T15:48:28.6436899Z 	at io.trino.testing.AbstractTestQueryFramework.close(AbstractTestQueryFramework.java:105)
2021-01-18T15:48:28.6438990Z 	at jdk.internal.reflect.GeneratedMethodAccessor1295.invoke(Unknown Source)
2021-01-18T15:48:28.6441344Z 	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
2021-01-18T15:48:28.6443212Z 	at java.base/java.lang.reflect.Method.invoke(Method.java:566)
2021-01-18T15:48:28.6444939Z 	at org.testng.internal.MethodInvocationHelper.invokeMethod(MethodInvocationHelper.java:104)
2021-01-18T15:48:28.6447033Z 	at org.testng.internal.Invoker.invokeConfigurationMethod(Invoker.java:515)
2021-01-18T15:48:28.6448794Z 	at org.testng.internal.Invoker.invokeConfigurations(Invoker.java:217)
2021-01-18T15:48:28.6451935Z 	at org.testng.internal.Invoker.invokeConfigurations(Invoker.java:144)
2021-01-18T15:48:28.6453848Z 	at org.testng.internal.TestMethodWorker.invokeAfterClassMethods(TestMethodWorker.java:217)
2021-01-18T15:48:28.6455943Z 	at org.testng.internal.TestMethodWorker.run(TestMethodWorker.java:115)
2021-01-18T15:48:28.6457790Z 	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
2021-01-18T15:48:28.6459673Z 	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
2021-01-18T15:48:28.6460803Z 	at java.base/java.lang.Thread.run(Thread.java:834)

[kokosing]

FYI @alexjo2144 @findepi

[findepi]

https://github.com/trinodb/trino/runs/1885690834

[lukasz-walkiewicz]

https://github.com/trinodb/trino/actions/runs/597438059

[findepi]

This has been observed in tests, but looking at the code the problem seems general.
cc @dain

[kokosing]

looking at the code the problem seems general.

What do you mean? Is it about that query got finished just before cancellation?

[findepi]

I don't know the exact mechanics yet, but the DistributedQueryRunner is not to be blamed, it just invokes queryManager.cancelQuery which is supposed to resolve concurrent query finish, but apparently it does not always do so.

[findepi]

https://github.com/trinodb/trino/runs/2041436971