Re: [EXTERNAL] Re: Add non-blocking version of PQcancel - Mailing list pgsql-hackers

Hi,

On 2024-10-01 15:00:00 +0300, Alexander Lakhin wrote:
> Hello Tom and Jelte,
> 
> 31.08.2024 07:04, Alexander Lakhin wrote:
> > I've tested your fix with the modification I proposed upthread:
> >              idle_session_timeout_enabled = false;
> >          }
> > +if (rand() % 10 == 0) pg_usleep(10000);
> >          /*
> >           * (5) disable async signal conditions again.
> > 
> > and can confirm that the issue is gone. On 8749d850f~1, the test failed
> > on iterations 3, 3. 12 for me, but on current REL_17_STABLE, 100 test
> > iterations succeeded.
> > 
> 
> One month later, treehopper has found a way to break that test: [1].
> The failure log contains:
> 2024-09-30 19:34:31.347 UTC [3201034:13] fdw_retry_check LOG: execute <unnamed>: DECLARE c2 CURSOR FOR
>     SELECT count(*) FROM ((("S 1"."T 1" r1 INNER JOIN "S 1"."T 1" r2 ON
> (TRUE)) INNER JOIN "S 1"."T 1" r4 ON (TRUE)) INNER JOIN "S 1"."T 1" r6 ON
> (TRUE))
> 2024-09-30 19:34:31.464 UTC [3201033:10] pg_regress/query_cancel ERROR:  canceling statement due to statement
timeout
> 2024-09-30 19:34:31.464 UTC [3201033:11] pg_regress/query_cancel STATEMENT: 
> SELECT count(*) FROM ft1 a CROSS JOIN ft1 b CROSS JOIN ft1 c CROSS JOIN ft1
> d;
> 2024-09-30 19:34:31.466 UTC [3201035:1] [unknown] LOG:  connection received: host=[local]
> 2024-09-30 19:34:31.474 UTC [3201034:14] fdw_retry_check LOG: statement: FETCH 100 FROM c2
> 2024-09-30 19:35:01.485 UTC [3201033:12] pg_regress/query_cancel WARNING: 
> could not get result of cancel request due to timeout

Another failure in CI, that cleared up after a retry:
https://cirrus-ci.com/task/5725647677423616
https://api.cirrus-ci.com/v1/artifact/task/5725647677423616/log/contrib/postgres_fdw/regression.diffs
https://api.cirrus-ci.com/v1/artifact/task/5725647677423616/log/contrib/postgres_fdw/log/postmaster.log

diff -U3 /tmp/cirrus-ci-build/contrib/postgres_fdw/expected/query_cancel.out
/tmp/cirrus-ci-build/contrib/postgres_fdw/results/query_cancel.out
--- /tmp/cirrus-ci-build/contrib/postgres_fdw/expected/query_cancel.out    2024-11-16 22:13:32.174593005 +0000
+++ /tmp/cirrus-ci-build/contrib/postgres_fdw/results/query_cancel.out    2024-11-16 22:21:20.165877954 +0000
@@ -29,4 +29,5 @@
 -- This would take very long if not canceled:
 SELECT count(*) FROM ft1 a CROSS JOIN ft1 b CROSS JOIN ft1 c CROSS JOIN ft1 d;
 ERROR:  canceling statement due to statement timeout
+WARNING:  could not get result of cancel request due to timeout
 COMMIT;


Statement logging isn't enabled for the test, so the log isn't that helpful:

2024-11-16 22:20:49.962 UTC [38643][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-11-16 22:20:49.964 UTC [38643][client backend] [[unknown]][67/1:0] LOG:  connection authenticated: user="postgres"
method=trust(/tmp/cirrus-ci-build/contrib/postgres_fdw/tmp_check/data/pg_hba.conf:117)
 
2024-11-16 22:20:49.964 UTC [38643][client backend] [[unknown]][67/1:0] LOG:  connection authorized: user=postgres
database=contrib_regressionapplication_name=pg_regress/query_cancel
 
2024-11-16 22:20:50.007 UTC [38645][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-11-16 22:20:50.010 UTC [38645][client backend] [[unknown]][68/1:0] LOG:  connection authenticated: user="postgres"
method=trust(/tmp/cirrus-ci-build/contrib/postgres_fdw/tmp_check/data/pg_hba.conf:117)
 
2024-11-16 22:20:50.010 UTC [38645][client backend] [[unknown]][68/1:0] LOG:  connection authorized: user=postgres
database=contrib_regressionapplication_name=fdw_retry_check
 
2024-11-16 22:20:50.148 UTC [38643][client backend] [pg_regress/query_cancel][67/4:0] ERROR:  canceling statement due
tostatement timeout
 
2024-11-16 22:20:50.148 UTC [38643][client backend] [pg_regress/query_cancel][67/4:0] STATEMENT:  SELECT count(*) FROM
ft1a CROSS JOIN ft1 b CROSS JOIN ft1 c CROSS JOIN ft1 d;
 
2024-11-16 22:20:50.159 UTC [38656][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-11-16 22:21:20.167 UTC [38643][client backend] [pg_regress/query_cancel][67/0:0] WARNING:  could not get result of
cancelrequest due to timeout
 
2024-11-16 22:21:20.170 UTC [38643][client backend] [pg_regress/query_cancel][:0] LOG:  disconnection: session time:
0:00:30.211user=postgres database=contrib_regression host=[local]
 
2024-11-16 22:21:20.315 UTC [36800][postmaster] LOG:  received fast shutdown request

Greetings,

Andres Freund