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

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




Mike Knowsley <mike.knowsley@bidorbuy.co.za> writes:
> 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.

As far as I can see, there is no such bug; you're just misunderstanding
when the query referenced by the cursor will execute.  The function
test_delay_in_refcursor() sets up the cursor and returns basically
immediately (certainly in much less than 2 seconds), so the timeout
you have in the JDBC code will never fire.  The expected pg_sleep(5)
won't execute till you try to fetch something from the refcursor.

Trying this manually in psql, I get

...
CREATE FUNCTION
regression=# \timing
Timing is on.
regression=# begin;
BEGIN
Time: 0.306 ms
regression=*# select test_delay_in_refcursor();
 test_delay_in_refcursor
-------------------------
 <unnamed portal 1>
(1 row)

Time: 0.314 ms
regression=*# fetch from "<unnamed portal 1>";
 ?column? | pg_sleep
----------+----------
 test     |
(1 row)

Time: 5005.475 ms (00:05.005)

I could have canceled the FETCH (and doing so works);
but I'm way too old and slow to cancel the submillisecond
setup step.