Re: Can not cancel a call to a function that has opened a refcursor

On Thu, 5 Aug 2021 at 04:49, Mike Knowsley <mike(dot)knowsley(at)bidorbuy(dot)co(dot)za>
wrote:

> *Synopsis*
>
> A request to cancel a call to a function does not cancel the function if
> the function has opened a refcursor which it is returning.
> The cancel request does not result in an error, but the function is not
> cancelled as expected, and continues until it returns normally.
> If the cancel is issued before the function opens the refcursor, the
> request does cancel the function as expected.
>
> I’m not sure if this is a bug or expected behaviour. Although I didn’t
> expect it. And it effectively means timeout and cancel can not be used to
> protect against long running queries using a refcursor.
>
> The essential issue is the same in these 3 test scenarios;
>
> 1) Calling the function via JDBC CallableStatement.execute with a timeout
> set.
> The timeout does not cancel the function if it has opened a refcursor.
> It does cancel the function if the function has not yet opened a refcursor.
>
> 2) Calling the function via JDBC CallableStatement.execute, with a
> separate java ’Timeout/TimeoutTask' thread issuing an explicit
> CallableStatement.cancel().
> The cancel request returns without error but does not cancel the function
> if it has opened a refcursor.
> It does cancel the function if the function has not yet opened a refcursor.
>
> 3) calling select pg_cancel_backend(<pid>);
> From a separate psql client
> pg_cancel_backend() returns without error but does not cancel the function
> if it has opened a refcursor.
> It does cancel the function if the function has not yet opened a refcursor.
>
> I initially thought this was Postgres JDBC client issue, but Dave Cramer
> said the JDBC client does send the cancel request to the Postgres server
> but it has no obvious effect.
> https://github.com/pgjdbc/pgjdbc/issues/2222
> And testing using pg_cancel_backend with no JDBC involvement shows the
> same issue.
>
>
> *Test environment*
>
> Mac OSX development
> Postgres JDBC Driver Version: 43.3.8
> Oracle jdk 1.8.0_231Mac OSX Catalina 10.15.7
> Official Postgres Image from hub.docker.com
> PostgreSQL 12.3 (Debian 12.3-1.pgdg100+1) on x86_64-pc-linux-gnu, compiled
> by gcc (Debian 8.3.0-6) 8.3.0, 64-bit
>
>
> As an aside: Our production environment using AWS Aurora/Postgres seems to
> have the same issue.
>
>
> *Test code*
>
>
> - psql function test_delay_in_refcursor
> - psql function test_delay_before_refcursor
> - java test class CallableStatementCancelTest
> - CallableStatementCancelTest execution trace
>
> -- delay of 10 seconds in the refcursor select
> create or replace function test_delay_in_refcursor()
> returns refcursor
> as $$
> declare
> cursorReference refcursor;
> begin
>
> open cursorReference for
> select 'test', pg_sleep(5);
>
> return cursorReference;
>
> end;
> $$ language plpgsql;
>
> -- delay of 10 seconds in a select into (before opening the refcursor)
> create or replace function test_delay_before_refcursor()
> returns refcursor
> as $$
> declare
> cursorReference refcursor;
> testResult varchar(100);
> begin
>
> select pg_sleep(5) into testResult;
>
> open cursorReference for
> select 'test';
>
> return cursorReference;
>
> end;
> $$ language plpgsql;
>
>
> import java.sql.CallableStatement;
> import java.sql.Connection;
> import java.sql.DriverManager;
> import java.sql.ResultSet;
> import java.sql.Types;
> import java.time.LocalDateTime;
> import java.util.Timer;
> import java.util.TimerTask;
>
> /**
> */
> public class CallableStatementCancelTest {
>
> private static String CONNECTION_URL = "jdbc:postgresql://127.0.0.1:5432/xxx?user=xxx&password=xxx";
>
> /**
> */
> public static void main(String[] aArgs) {
> test1();
> test2();
> test3();
> test4();
> }
>
> /**
> */
> private static void test1() {
>
> log("------ test1 --------");
>
> Connection connection = null;
> CallableStatement callableStatement = null;
> ResultSet resultSet = null;
> try {
> connection = DriverManager.getConnection(CONNECTION_URL);
> connection.setAutoCommit(false);
> callableStatement = connection.prepareCall("{ ? = call test_delay_in_refcursor }");
> callableStatement.setQueryTimeout(2);
> callableStatement.registerOutParameter(1, Types.REF_CURSOR);
> log("test1 callableStatement.execute() test_delay_in_refcursor with 2 second timeout");
> callableStatement.execute();
> log("test1 callableStatement.execute() returned - not cancelled");
> resultSet = (ResultSet) callableStatement.getObject(1);
> }
> catch(Exception e) {
> if(e.getMessage().toLowerCase().contains("canceling statement")) {
> log("test1 callableStatement cancelled");
> }
> else {
> log("test1 Exception : " + e.getMessage());
> }
> }
> finally {
> try {
> if(resultSet != null) resultSet.close();
> if(callableStatement != null) callableStatement.close();
> if(connection != null) connection.close();
> }
> catch(Exception e2) {}
> }
> }
>
> /**
> */
> private static void test2() {
>
> log("------ test2 --------");
>
> Connection connection = null;
> CallableStatement callableStatement = null;
> ResultSet resultSet = null;
> try {
> connection = DriverManager.getConnection(CONNECTION_URL);
> connection.setAutoCommit(false);
> callableStatement = connection.prepareCall("{ ? = call test_delay_before_refcursor }");
> callableStatement.setQueryTimeout(2);
> callableStatement.registerOutParameter(1, Types.REF_CURSOR);
> log("test2 callableStatement.execute() test_delay_before_refcursor with 2 second timeout");
> callableStatement.execute();
> log("test2 callableStatement.execute() returned - not cancelled");
> resultSet = (ResultSet) callableStatement.getObject(1);
> }
> catch(Exception e) {
> if(e.getMessage().toLowerCase().contains("canceling statement")) {
> log("test2 callableStatement cancelled");
> }
> else {
> log("test2 Exception : " + e.getMessage());
> }
> }
> finally {
> try {
> if(resultSet != null) resultSet.close();
> if(callableStatement != null) callableStatement.close();
> if(connection != null) connection.close();
> }
> catch(Exception e2) {}
> }
> }
>
> /**
> */
> private static void test3() {
>
> log("------ test3 --------");
>
> Connection connection = null;
> CallableStatement callableStatement = null;
> ResultSet resultSet = null;
> Timer timer = null;
> try {
> connection = DriverManager.getConnection(CONNECTION_URL);
> connection.setAutoCommit(false);
> callableStatement = connection.prepareCall("{ ? = call test_delay_in_refcursor }");
> callableStatement.registerOutParameter(1, Types.REF_CURSOR);
>
> log("test3 callableStatement.execute() test_delay_in_refcursor with Timer set to call CallableStatement.cancel() after 2 seconds");
>
> final CallableStatement finalCallableStatement = callableStatement;
> timer = new Timer("TimerThread");
> timer.schedule(
> new TimerTask() {
> public void run() {
> try {
> if(!finalCallableStatement.isClosed()) {
> log("test3 Timer calling finalCallableStatement.cancel()");
> finalCallableStatement.cancel();
> log("test3 Timer completed finalCallableStatement.cancel()");
> }
> }
> catch(Exception e) {
> log("test3 TimerTask run exception " + e.getMessage());
> }
> finally {
> cancel();
> }
> }
> },
> 2000
> );
>
> callableStatement.execute();
>
> log("test3 callableStatement.execute() returned - not cancelled");
>
> resultSet = (ResultSet) callableStatement.getObject(1);
> }
> catch(Exception e) {
> if(e.getMessage().toLowerCase().contains("canceling statement")) {
> log("test3 callableStatement cancelled");
> }
> else {
> log("test3 Exception : " + e.getMessage());
> }
> }
> finally {
> try {
> if(timer != null) { timer.cancel(); }
> if(resultSet != null) resultSet.close();
> if(callableStatement != null) callableStatement.close();
> if(connection != null) connection.close();
> }
> catch(Exception e2) {}
> }
> }
>
> /**
> */
> private static void test4() {
>
> log("------ test4 --------");
>
> Connection connection = null;
> CallableStatement callableStatement = null;
> ResultSet resultSet = null;
> Timer timer = null;
> try {
> connection = DriverManager.getConnection(CONNECTION_URL);
> connection.setAutoCommit(false);
> callableStatement = connection.prepareCall("{ ? = call test_delay_before_refcursor }");
> callableStatement.registerOutParameter(1, Types.REF_CURSOR);
>
> log("test4 callableStatement.execute() test_delay_before_refcursor with Timer set to call callableStatement.cancel() after 2 seconds");
>
> final CallableStatement finalCallableStatement = callableStatement;
> timer = new Timer("TimerThread");
> timer.schedule(
> new TimerTask() {
> public void run() {
> try {
> if(!finalCallableStatement.isClosed()) {
> log("test4 Timer calling finalCallableStatement.cancel()");
> finalCallableStatement.cancel();
> log("test4 Timer completed finalCallableStatement.cancel()");
> }
> }
> catch(Exception e) {
> log("test4 TimerTask run exception " + e.getMessage());
> }
> finally {
> cancel();
> }
> }
> },
> 2000
> );
>
> callableStatement.execute();
>
> log("test4 callableStatement.execute() returned - not cancelled");
>
> resultSet = (ResultSet) callableStatement.getObject(1);
> }
> catch(Exception e) {
> if(e.getMessage().toLowerCase().contains("canceling statement")) {
> log("test4 callableStatement cancelled");
> }
> else {
> log("test4 Exception : " + e.getMessage());
> }
> }
> finally {
> try {
> if(timer != null) { timer.cancel(); }
> if(resultSet != null) resultSet.close();
> if(callableStatement != null) callableStatement.close();
> if(connection != null) connection.close();
> }
> catch(Exception e2) {}
> }
> }
>
> /**
> */
> private static void log(String aMessage) {
> System.out.println(LocalDateTime.now() + " " + Thread.currentThread().getName() + " " + aMessage);
> }
> }
>
> $ runide.sh com.xxx.CallableStatementCancelTest
>
> 2021-08-04T16:03:59.940 main ------ test1 --------
> 2021-08-04T16:04:00.058 main test1 callableStatement.execute() test_delay_in_refcursor with 2 second timeout
> 2021-08-04T16:04:05.074 main test1 callableStatement.execute() returned - not cancelled
> 2021-08-04T16:04:05.075 main ------ test2 --------
> 2021-08-04T16:04:05.089 main test2 callableStatement.execute() test_delay_before_refcursor with 2 second timeout
> 2021-08-04T16:04:07.101 main test2 callableStatement cancelled
> 2021-08-04T16:04:07.101 main ------ test3 --------
> 2021-08-04T16:04:07.115 main test3 callableStatement.execute() test_delay_in_refcursor with Timer set to call CallableStatement.cancel() after 2 seconds
> 2021-08-04T16:04:09.119 TimerThread test3 Timer calling finalCallableStatement.cancel()
> 2021-08-04T16:04:09.119 TimerThread test3 Timer completed finalCallableStatement.cancel()
> 2021-08-04T16:04:12.124 main test3 callableStatement.execute() returned - not cancelled
> 2021-08-04T16:04:12.124 main ------ test4 --------
> 2021-08-04T16:04:12.139 main test4 callableStatement.execute() test_delay_before_refcursor with Timer set to call callableStatement.cancel() after 2 seconds
> 2021-08-04T16:04:14.151 TimerThread test4 Timer calling finalCallableStatement.cancel()
> 2021-08-04T16:04:14.155 TimerThread test4 Timer completed finalCallableStatement.cancel()
> 2021-08-04T16:04:14.155 main test4 callableStatement cancelled
>
>
> kind regards
> Mike Knowsley
> bidorbuy
>
>
>
>
I think this is just a protocol issue. The backend isn't looking for cancel
requests at this point.

Dave