Flaky test PGJobContextTest.testRunQueryAfterCancellingPreviousInTheSameConnection

[jerrinot]

To reproduce

Linux other

2024-04-04T18:10:46.9033240Z 2024-04-04T18:10:46.903147Z I i.q.t.AbstractTest Starting test PGJobContextTest#testRunQueryAfterCancellingPreviousInTheSameConnection[NO_WAL]
2024-04-04T18:10:46.9042726Z 2024-04-04T18:10:46.904029Z I i.q.c.TableNameRegistryStore reloading tables file [path=/tmp/junit7253654805486969647/dbRoot/tables.d.0, threadId=7582]
2024-04-04T18:10:46.9043814Z 2024-04-04T18:10:46.904065Z I i.q.t.c.p.PGJobContextTest fragmentation params [sendBufferSize=5632, forceSendFragmentationChunkSize=76, recvBufferSize=6656, forceRecvFragmentationChunkSize=61]
2024-04-04T18:10:46.9050749Z 2024-04-04T18:10:46.904904Z I i.q.g.SqlCompilerImpl parse [fd=-1, thread=7582, q=create table if not exists tab as (select x::timestamp ts,         x,         rnd_double() d  from long_sequence(10)) timestamp(ts) partition by day]
2024-04-04T18:10:46.9076735Z 2024-04-04T18:10:46.905731Z I i.q.c.CairoEngine locked [table=`tab~`, thread=7582]
2024-04-04T18:10:46.9145870Z 2024-04-04T18:10:46.913932Z I i.q.c.TableWriter open 'tab'
2024-04-04T18:10:46.9169060Z 2024-04-04T18:10:46.915732Z I i.q.c.TableWriter switched partition [path='/tmp/junit7253654805486969647/dbRoot/tab~/1970-01-01']
2024-04-04T18:10:46.9170090Z 2024-04-04T18:10:46.915896Z I i.q.c.CairoEngine unlocked [table=`tab`]
2024-04-04T18:10:46.9171992Z 2024-04-04T18:10:46.916064Z I i.q.g.SqlCompilerImpl parse [fd=-1, thread=7582, q=CREATE TABLE IF NOT EXISTS "sys.text_import_log" (ts timestamp, id string, table_name symbol, file symbol, phase symbol, status symbol, message string,rows_handled long,rows_imported long,errors long) timestamp(ts) partition by DAY BYPASS WAL]
2024-04-04T18:10:46.9173118Z 2024-04-04T18:10:46.916315Z I i.q.c.CairoEngine locked [table=`sys.text_import_log~`, thread=7582]
2024-04-04T18:10:46.9364065Z 2024-04-04T18:10:46.936218Z I i.q.c.p.WriterPool created [table=`sys.text_import_log~`, thread=7582]
2024-04-04T18:10:46.9365037Z 2024-04-04T18:10:46.936233Z I i.q.c.TableWriter open 'sys.text_import_log'
2024-04-04T18:10:46.9392280Z 2024-04-04T18:10:46.939048Z I i.q.c.CairoEngine unlocked [table=`sys.text_import_log`]
2024-04-04T18:10:46.9393412Z 2024-04-04T18:10:46.939060Z I i.q.c.p.WriterPool >> [table=`sys.text_import_log~`, thread=7582]
2024-04-04T18:10:46.9397678Z 2024-04-04T18:10:46.939626Z A pg-server listening on 0.0.0.0:0 [fd=59 backlog=64]
2024-04-04T18:10:46.9403774Z 2024-04-04T18:10:46.940222Z I i.q.t.c.p.PGJobContextTest os scheduled worker started [name=testing_0]
2024-04-04T18:10:46.9430796Z 2024-04-04T18:10:46.942544Z I i.q.t.c.p.PGJobContextTest worker pool started [pool=testing]
2024-04-04T18:10:46.9436512Z 2024-04-04T18:10:46.943386Z I pg-server connected [ip=127.0.0.1, fd=62]
2024-04-04T18:10:46.9444363Z 2024-04-04T18:10:46.944247Z I i.q.g.SqlCompilerImpl parse [fd=62, thread=7583, q=SET extra_float_digits = 3]
2024-04-04T18:10:46.9451700Z 2024-04-04T18:10:46.944797Z I i.q.g.SqlCompilerImpl parse [fd=62, thread=7583, q=SET application_name = 'PostgreSQL JDBC Driver']
2024-04-04T18:10:46.9457259Z 2024-04-04T18:10:46.945572Z I i.q.t.c.p.PGJobContextTest os scheduled worker started [name=testing_1]
2024-04-04T18:10:46.9469353Z 2024-04-04T18:10:46.946747Z I i.q.g.SqlCompilerImpl parse [fd=62, thread=7583, q=select count(*) from tab t1 join tab t2 on t1.x = t2.x where sleep(120000)]
2024-04-04T18:10:46.9483463Z 2024-04-04T18:10:46.948060Z I i.q.g.SqlCompilerImpl plan [q=`select-group-by count() count from (select [x] from tab t1 timestamp (ts) join select [x] from tab t2 timestamp (ts) on t2.x = t1.x const-where sleep(120000)) t1`, fd=62]
2024-04-04T18:10:46.9495536Z 2024-04-04T18:10:46.949355Z I i.q.c.TableReader open partition /tmp/junit7253654805486969647/dbRoot/tab~/1970-01-01 [rowCount=10, partitionNameTxn=-1, transientRowCount=10, partitionIndex=0, partitionCount=1]
2024-04-04T18:10:46.9500152Z 2024-04-04T18:10:46.949869Z I pg-server connected [ip=127.0.0.1, fd=75]
2024-04-04T18:10:46.9501257Z 2024-04-04T18:10:46.949938Z I i.q.c.p.CleartextPasswordPgWireAuthenticator cancel request [pid=63]
2024-04-04T18:10:46.9508141Z 2024-04-04T18:10:46.950536Z I pg-server scheduling disconnect [fd=75, reason=15]
2024-04-04T18:10:46.9508948Z 2024-04-04T18:10:46.950542Z I pg-server disconnected [ip=127.0.0.1, fd=75, src=queue]
2024-04-04T18:10:46.9513318Z 2024-04-04T18:10:46.951173Z I i.q.g.SqlCompilerImpl parse [fd=62, thread=7583, q=select count(*) from tab where x > 0]
2024-04-04T18:10:46.9519850Z 2024-04-04T18:10:46.951818Z I i.q.g.SqlCompilerImpl plan [q=`select-group-by count() count from (select [x] from tab timestamp (ts) where x > 0)`, fd=62]
2024-04-04T18:10:46.9525838Z 2024-04-04T18:10:46.952419Z I i.q.g.SqlCodeGenerator JIT enabled for (sub)query [tableName=tab, fd=62]
2024-04-04T18:10:46.9569628Z 2024-04-04T18:10:46.953165Z I pg-server scheduling disconnect [fd=62, reason=11]
2024-04-04T18:10:46.9570498Z 2024-04-04T18:10:46.953186Z I i.q.t.c.p.PGJobContextTest cleaned worker [name=testing, worker=0]
2024-04-04T18:10:46.9571414Z 2024-04-04T18:10:46.953187Z I i.q.t.c.p.PGJobContextTest os scheduled worker stopped [name=testing_0]
2024-04-04T18:10:46.9572016Z 2024-04-04T18:10:46.953301Z I i.q.t.c.p.PGJobContextTest cleaned worker [name=testing, worker=1]
2024-04-04T18:10:46.9572433Z 2024-04-04T18:10:46.953340Z I i.q.c.p.WriterPool << [table=`sys.text_import_log~`, thread=7582]
2024-04-04T18:10:46.9572869Z 2024-04-04T18:10:46.953351Z I pg-server disconnected [ip=127.0.0.1, fd=62, src=queue]
2024-04-04T18:10:46.9573198Z 2024-04-04T18:10:46.953452Z I pg-server closed
2024-04-04T18:10:46.9573505Z 2024-04-04T18:10:46.953459Z E i.q.t.AbstractCairoTest Error in test: 
2024-04-04T18:10:46.9573759Z org.postgresql.util.PSQLException: ERROR: cancelled by user [fd=62]
2024-04-04T18:10:46.9574183Z   Position: 1
2024-04-04T18:10:46.9574439Z 	at org.postgresql.core.v3.QueryExecutorImpl.receiveErrorResponse(QueryExecutorImpl.java:2676)
2024-04-04T18:10:46.9574764Z 	at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:2366)
2024-04-04T18:10:46.9575074Z 	at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:356)
2024-04-04T18:10:46.9575353Z 	at org.postgresql.jdbc.PgStatement.executeInternal(PgStatement.java:496)
2024-04-04T18:10:46.9575631Z 	at org.postgresql.jdbc.PgStatement.execute(PgStatement.java:413)
2024-04-04T18:10:46.9575920Z 	at org.postgresql.jdbc.PgPreparedStatement.executeWithFlags(PgPreparedStatement.java:190)
2024-04-04T18:10:46.9576406Z 	at org.postgresql.jdbc.PgPreparedStatement.executeQuery(PgPreparedStatement.java:134)
2024-04-04T18:10:46.9576784Z 	at io.questdb.test.cutlass.pgwire.PGJobContextTest.lambda$testRunQueryAfterCancellingPreviousInTheSameConnection$119(PGJobContextTest.java:7540)
2024-04-04T18:10:46.9577165Z 	at io.questdb.test.AbstractCairoTest.lambda$assertMemoryLeak$7(AbstractCairoTest.java:927)
2024-04-04T18:10:46.9577454Z 	at io.questdb.test.tools.TestUtils.assertMemoryLeak(TestUtils.java:639)
2024-04-04T18:10:46.9577944Z 	at io.questdb.test.AbstractCairoTest.assertMemoryLeak(AbstractCairoTest.java:924)
2024-04-04T18:10:46.9578261Z 	at io.questdb.test.AbstractCairoTest.assertMemoryLeak(AbstractCairoTest.java:918)
2024-04-04T18:10:46.9578873Z 	at io.questdb.test.cutlass.pgwire.PGJobContextTest.testRunQueryAfterCancellingPreviousInTheSameConnection(PGJobContextTest.java:7520)
2024-04-04T18:10:46.9579387Z 	at jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
2024-04-04T18:10:46.9579680Z 	at jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
2024-04-04T18:10:46.9580195Z 	at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
2024-04-04T18:10:46.9580485Z 	at java.lang.reflect.Method.invoke(Method.java:566)
2024-04-04T18:10:46.9580778Z 	at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:59)
2024-04-04T18:10:46.9581397Z 	at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
2024-04-04T18:10:46.9581718Z 	at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:56)
2024-04-04T18:10:46.9582039Z 	at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
2024-04-04T18:10:46.9582347Z 	at org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:26)
2024-04-04T18:10:46.9582652Z 	at org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:27)
2024-04-04T18:10:46.9582922Z 	at org.junit.rules.TestWatcher$1.evaluate(TestWatcher.java:61)
2024-04-04T18:10:46.9583234Z 	at org.junit.internal.runners.statements.FailOnTimeout$CallableStatement.call(FailOnTimeout.java:299)
2024-04-04T18:10:46.9583579Z 	at org.junit.internal.runners.statements.FailOnTimeout$CallableStatement.call(FailOnTimeout.java:293)
2024-04-04T18:10:46.9584073Z 	at java.util.concurrent.FutureTask.run(FutureTask.java:264)
2024-04-04T18:10:46.9584336Z 	at java.lang.Thread.run(Thread.java:829)
2024-04-04T18:10:46.9584738Z 2024-04-04T18:10:46.953870Z I i.q.c.p.ReaderPool closed 'tab~' [at=0:0, reason=POOL_CLOSED]
2024-04-04T18:10:46.9585150Z 2024-04-04T18:10:46.953955Z I i.q.c.p.ReaderPool closed 'tab~' [at=0:1, reason=POOL_CLOSED]
2024-04-04T18:10:46.9585546Z 2024-04-04T18:10:46.954980Z I i.q.c.TableWriter closed 'sys.text_import_log'
2024-04-04T18:10:46.9586019Z 2024-04-04T18:10:46.954984Z I i.q.c.p.WriterPool closed [table=`sys.text_import_log~`, reason=POOL_CLOSED, by=7582]
2024-04-04T18:10:46.9586571Z 2024-04-04T18:10:46.955320Z I i.q.c.TableWriter closed 'tab'
2024-04-04T18:10:46.9586955Z 2024-04-04T18:10:46.955323Z I i.q.c.p.WriterPool closed [table=`tab~`, reason=POOL_CLOSED, by=7582]
2024-04-04T18:10:46.9587436Z 2024-04-04T18:10:46.955379Z I i.q.t.AbstractCairoTest Tearing down test PGJobContextTest#testRunQueryAfterCancellingPreviousInTheSameConnection[NO_WAL]
2024-04-04T18:10:46.9587944Z 2024-04-04T18:10:46.955455Z I i.q.t.AbstractTest Finished test PGJobContextTest#testRunQueryAfterCancellingPreviousInTheSameConnection[NO_WAL]
2024-04-04T18:10:46.9588386Z 2024-04-04T18:10:46.956345Z I i.q.t.c.p.PGJobContextTest os scheduled worker stopped [name=testing_1]
2024-04-04T18:10:46.9694975Z random seeds: 1252836394570L, 1712254246965L
2024-04-04T18:10:46.9695715Z 2024-04-04T18:10:46.965629Z E i.q.t.TestListener ***** Test Failed *****io.questdb.test.cutlass.pgwire.PGJobContextTest.testRunQueryAfterCancellingPreviousInTheSameConnection[NO_WAL] duration_ms=65 : 
2024-04-04T18:10:46.9696129Z org.postgresql.util.PSQLException: ERROR: cancelled by user [fd=62]
2024-04-04T18:10:46.9697189Z   Position: 1
2024-04-04T18:10:46.9697504Z 	at org.postgresql.core.v3.QueryExecutorImpl.receiveErrorResponse(QueryExecutorImpl.java:2676)
2024-04-04T18:10:46.9697844Z 	at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:2366)
2024-04-04T18:10:46.9698150Z 	at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:356)
2024-04-04T18:10:46.9698433Z 	at org.postgresql.jdbc.PgStatement.executeInternal(PgStatement.java:496)
2024-04-04T18:10:46.9698711Z 	at org.postgresql.jdbc.PgStatement.execute(PgStatement.java:413)
2024-04-04T18:10:46.9699236Z 	at org.postgresql.jdbc.PgPreparedStatement.executeWithFlags(PgPreparedStatement.java:190)
2024-04-04T18:10:46.9699557Z 	at org.postgresql.jdbc.PgPreparedStatement.executeQuery(PgPreparedStatement.java:134)
2024-04-04T18:10:46.9699962Z 	at io.questdb.test.cutlass.pgwire.PGJobContextTest.lambda$testRunQueryAfterCancellingPreviousInTheSameConnection$119(PGJobContextTest.java:7540)
2024-04-04T18:10:46.9700492Z 	at io.questdb.test.AbstractCairoTest.lambda$assertMemoryLeak$7(AbstractCairoTest.java:927)
2024-04-04T18:10:46.9700783Z 	at io.questdb.test.tools.TestUtils.assertMemoryLeak(TestUtils.java:639)
2024-04-04T18:10:46.9701064Z 	at io.questdb.test.AbstractCairoTest.assertMemoryLeak(AbstractCairoTest.java:924)
2024-04-04T18:10:46.9701336Z 	at io.questdb.test.AbstractCairoTest.assertMemoryLeak(AbstractCairoTest.java:918)
2024-04-04T18:10:46.9701808Z 	at io.questdb.test.cutlass.pgwire.PGJobContextTest.testRunQueryAfterCancellingPreviousInTheSameConnection(PGJobContextTest.java:7520)
2024-04-04T18:10:46.9702130Z 	at jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
2024-04-04T18:10:46.9702411Z 	at jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
2024-04-04T18:10:46.9702727Z 	at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
2024-04-04T18:10:46.9703006Z 	at java.lang.reflect.Method.invoke(Method.java:566)
2024-04-04T18:10:46.9703274Z 	at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:59)
2024-04-04T18:10:46.9703559Z 	at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
2024-04-04T18:10:46.9703856Z 	at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:56)
2024-04-04T18:10:46.9704150Z 	at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
2024-04-04T18:10:46.9704443Z 	at org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:26)
2024-04-04T18:10:46.9704728Z 	at org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:27)
2024-04-04T18:10:46.9705002Z 	at org.junit.rules.TestWatcher$1.evaluate(TestWatcher.java:61)
2024-04-04T18:10:46.9705276Z 	at org.junit.internal.runners.statements.FailOnTimeout$CallableStatement.call(FailOnTimeout.java:299)
2024-04-04T18:10:46.9705606Z 	at org.junit.internal.runners.statements.FailOnTimeout$CallableStatement.call(FailOnTimeout.java:293)
2024-04-04T18:10:46.9705892Z 	at java.util.concurrent.FutureTask.run(FutureTask.java:264)
2024-04-04T18:10:46.9706124Z 	at java.lang.Thread.run(Thread.java:829)
2024-04-04T18:10:46.9706613Z 2024-04-04T18:10:46.965691Z I i.q.t.TestListener <<<< io.questdb.test.cutlass.pgwire.PGJobContextTest.testRunQueryAfterCancellingPreviousInTheSameConnection[NO_WAL] duration_ms=65

QuestDB version:

7.4.1-snapshot

OS, in case of Docker specify Docker and the Host OS:

CI: Linux-other

File System, in case of Docker specify Host File System:

not sure

Full Name:

Jaromir Hamala

Affiliation:

QuestDB

Have you followed Linux, MacOs kernel configuration steps to increase Maximum open files and Maximum virtual memory areas limit?

• Yes, I have

Additional context

No response

[bluestreak01]

@jerrinot this one is unsolvable i think, it has to be re-imagined