Re: assert in nested SQL procedure call in current HEAD

My colleague Yogesh Sharma discovered an assert in nested SQL procedure
calls after ROLLBACK is used. Minimal test case and backtrace below. I
have not yet tried to figure out exactly what is going on beyond seeing
that it occurs in pg_plan_query() where the comment says "Planner must
have a snapshot in case it calls user-defined functions"...

Joe

----------------------
DROP TABLE IF EXISTS tst_tbl;
CREATE TABLE tst_tbl (a int);
CREATE OR REPLACE PROCEDURE insert_data() AS $$
INSERT INTO tst_tbl VALUES (42);
$$ LANGUAGE SQL;

CREATE OR REPLACE PROCEDURE transaction_test() AS $$
BEGIN
ROLLBACK;
CALL insert_data();
END
$$ LANGUAGE PLPGSQL;
CALL transaction_test();

#0 0x00007fe343cf4428 in __GI_raise (sig=sig(at)entry=6) at
../sysdeps/unix/sysv/linux/raise.c:54
#1 0x00007fe343cf602a in __GI_abort () at abort.c:89
#2 0x0000000000a71951 in ExceptionalCondition (conditionName=0xc9408b
"!(ActiveSnapshotSet())", errorType=0xc93d23 "FailedAssertion",
fileName=0xc93e22 "postgres.c", lineNumber=801) at assert.c:54
#3 0x00000000008ec20f in pg_plan_query (querytree=0x2df1f00,
cursorOptions=256, boundParams=0x0) at postgres.c:801
#4 0x000000000070772e in init_execution_state
(queryTree_list=0x2df2c28, fcache=0x2df12d8, lazyEvalOK=true) at
functions.c:507
#5 0x0000000000707e50 in init_sql_fcache (finfo=0x7fffcbb1fd10,
collation=0, lazyEvalOK=true) at functions.c:770
#6 0x00000000007085d9 in fmgr_sql (fcinfo=0x7fffcbb1fd40) at
functions.c:1064
#7 0x0000000000675c12 in ExecuteCallStmt (stmt=0x2d54b18, params=0x0,
atomic=false, dest=0xfc7380 <spi_printtupDR>) at functioncmds.c:2294
#8 0x00000000008f5067 in standard_ProcessUtility (pstmt=0x2d54a00,
queryString=0x2d4f4e8 "CALL insert_data()",
context=PROCESS_UTILITY_QUERY_NONATOMIC,
params=0x0, queryEnv=0x0, dest=0xfc7380 <spi_printtupDR>,
completionTag=0x7fffcbb20390 "") at utility.c:649
#9 0x00000000008f4852 in ProcessUtility (pstmt=0x2d54a00,
queryString=0x2d4f4e8 "CALL insert_data()",
context=PROCESS_UTILITY_QUERY_NONATOMIC, params=0x0,
queryEnv=0x0, dest=0xfc7380 <spi_printtupDR>,
completionTag=0x7fffcbb20390 "") at utility.c:360
#10 0x000000000074523d in _SPI_execute_plan (plan=0x2d54558,
paramLI=0x0, snapshot=0x0, crosscheck_snapshot=0x0, read_only=false,
fire_triggers=true, tcount=0)
at spi.c:2225
#11 0x0000000000741d9d in SPI_execute_plan_with_paramlist
(plan=0x2d54558, params=0x0, read_only=false, tcount=0) at spi.c:481
#12 0x00007fe33491bcfd in exec_stmt_call (estate=0x7fffcbb20870,
stmt=0x2df6170) at pl_exec.c:2103
#13 0x00007fe33491b7bd in exec_stmt (estate=0x7fffcbb20870,
stmt=0x2df6170) at pl_exec.c:1920
#14 0x00007fe33491b66e in exec_stmts (estate=0x7fffcbb20870,
stmts=0x2df60f0) at pl_exec.c:1875
#15 0x00007fe33491b508 in exec_stmt_block (estate=0x7fffcbb20870,
block=0x2df5c60) at pl_exec.c:1816
#16 0x00007fe334918e50 in plpgsql_exec_function (func=0x2d5ec30,
fcinfo=0x7fffcbb20ba0, simple_eval_estate=0x0, atomic=false) at
pl_exec.c:586
#17 0x00007fe334913119 in plpgsql_call_handler (fcinfo=0x7fffcbb20ba0)
at pl_handler.c:263
#18 0x0000000000675c12 in ExecuteCallStmt (stmt=0x2d2cff8, params=0x0,
atomic=false, dest=0x2d2d420) at functioncmds.c:2294
#19 0x00000000008f5067 in standard_ProcessUtility (pstmt=0x2d2d0c8,
queryString=0x2d2c4e8 "CALL transaction_test();",
context=PROCESS_UTILITY_TOPLEVEL,
params=0x0, queryEnv=0x0, dest=0x2d2d420,
completionTag=0x7fffcbb213a0 "") at utility.c:649
#20 0x00000000008f4852 in ProcessUtility (pstmt=0x2d2d0c8,
queryString=0x2d2c4e8 "CALL transaction_test();",
context=PROCESS_UTILITY_TOPLEVEL, params=0x0,
queryEnv=0x0, dest=0x2d2d420, completionTag=0x7fffcbb213a0 "") at
utility.c:360

--
Crunchy Data - http://crunchydata.com
PostgreSQL Support for Secure Enterprises
Consulting, Training, & Open Source Development

>>>>> "Joe" == Joe Conway <mail(at)joeconway(dot)com> writes:

Joe> My colleague Yogesh Sharma discovered an assert in nested SQL
Joe> procedure calls after ROLLBACK is used. Minimal test case and
Joe> backtrace below. I have not yet tried to figure out exactly what
Joe> is going on beyond seeing that it occurs in pg_plan_query() where
Joe> the comment says "Planner must have a snapshot in case it calls
Joe> user-defined functions"...

/message-id/29608.1518533639@sss.pgh.pa.us

--
Andrew (irc:RhodiumToad)

>>>>> "Andrew" == Andrew Gierth <andrew(at)tao11(dot)riddles(dot)org(dot)uk> writes:

>>>>> "Joe" == Joe Conway <mail(at)joeconway(dot)com> writes:

Joe> My colleague Yogesh Sharma discovered an assert in nested SQL
Joe> procedure calls after ROLLBACK is used. Minimal test case and
Joe> backtrace below. I have not yet tried to figure out exactly what
Joe> is going on beyond seeing that it occurs in pg_plan_query() where
Joe> the comment says "Planner must have a snapshot in case it calls
Joe> user-defined functions"...

Andrew> /message-id/29608.1518533639@sss.pgh.pa.us

I added it to the open items list since nobody else seems to have taken
notice; from Tom's linked message it seems this should be Peter E's bag?

--
Andrew (irc:RhodiumToad)

> On 8 June 2018 at 06:20, Andrew Gierth <andrew(at)tao11(dot)riddles(dot)org(dot)uk> wrote:

> Joe> My colleague Yogesh Sharma discovered an assert in nested SQL
> Joe> procedure calls after ROLLBACK is used. Minimal test case and
> Joe> backtrace below. I have not yet tried to figure out exactly what
> Joe> is going on beyond seeing that it occurs in pg_plan_query() where
> Joe> the comment says "Planner must have a snapshot in case it calls
> Joe> user-defined functions"...
>
> Andrew> /message-id/29608.1518533639@sss.pgh.pa.us
>
> I added it to the open items list since nobody else seems to have taken
> notice; from Tom's linked message it seems this should be Peter E's bag?

I've taken a look at this - indeed, the situation looks similar to what
described in the linked message, namely after a transaction rollback and
creation of a new one no active snapshot was pushed. But in this particular
case the timeframe without an active snapshot is actually limited and includes
only some initialization and planning activity (after that a new one is
pushed). The commentary says that "Planner must have a snapshot in case it
calls user-defined functions." - I tried to simulate this in order to see what
would happen, but got no errors. Is there a chance that it's an outdated
Assert?

On 6/10/18 15:06, Dmitry Dolgov wrote:
>> I added it to the open items list since nobody else seems to have taken
>> notice; from Tom's linked message it seems this should be Peter E's bag?
> I've taken a look at this - indeed, the situation looks similar to what
> described in the linked message, namely after a transaction rollback and
> creation of a new one no active snapshot was pushed. But in this particular
> case the timeframe without an active snapshot is actually limited and includes
> only some initialization and planning activity (after that a new one is
> pushed). The commentary says that "Planner must have a snapshot in case it
> calls user-defined functions." - I tried to simulate this in order to see what
> would happen, but got no errors. Is there a chance that it's an outdated
> Assert?

The problem with these nested procedure calls is that if the nested call
does a commit, you would get the dreaded "snapshot %p still active"
warning. So PL/pgSQL in combination with SPI is going out of its way to
make sure that there is no active snapshot when we call out to
ProcessUtility() for the nested CALL. However, if whatever the nested
CALL executes requires an active snapshot to be set, then there is this
problem. Apparently, the LANGUAGE SQL procedure requires a snapshot to
be set previously. This is not a problem, for example, if you replace
the example procedure with LANGUAGE plpgsql, which does its own snapshot
management. So perhaps a fix here is to teach the LANGUAGE SQL handler
to set a snapshot if there isn't one already. That would make the
different language handlers behave consistently. (The alternative is to
get rid of the warning in snapmgr.c.)

--
Peter Eisentraut http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

>>>>> "Peter" == Peter Eisentraut <peter(dot)eisentraut(at)2ndquadrant(dot)com> writes:

Peter> The problem with these nested procedure calls is that if the
Peter> nested call

Did you miss the fact that the issue only occurs when the top-level
procedure does a rollback? The problem is not with nested calls, but
rather with the fact that commit or rollback is leaving ActiveSnapshot
unset, which is (as Tom pointed out at the linked post) not the expected
condition inside PL code.

--
Andrew (irc:RhodiumToad)

On 6/12/18 10:03, Andrew Gierth wrote:
>>>>>> "Peter" == Peter Eisentraut <peter(dot)eisentraut(at)2ndquadrant(dot)com> writes:
>
> Peter> The problem with these nested procedure calls is that if the
> Peter> nested call
>
> Did you miss the fact that the issue only occurs when the top-level
> procedure does a rollback? The problem is not with nested calls, but
> rather with the fact that commit or rollback is leaving ActiveSnapshot
> unset, which is (as Tom pointed out at the linked post) not the expected
> condition inside PL code.

We need that so that we can run things like SET TRANSACTION ISOLATION.

--
Peter Eisentraut http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

>>>>> "Peter" == Peter Eisentraut <peter(dot)eisentraut(at)2ndquadrant(dot)com> writes:

>> Did you miss the fact that the issue only occurs when the top-level
>> procedure does a rollback? The problem is not with nested calls, but
>> rather with the fact that commit or rollback is leaving
>> ActiveSnapshot unset, which is (as Tom pointed out at the linked
>> post) not the expected condition inside PL code.

Peter> We need that so that we can run things like SET TRANSACTION
Peter> ISOLATION.

While testing this, I ran into another semi-related issue:
shmem_exit_inprogress isn't ever being cleared in the postmaster, which
means that if you ever have a crash-restart, any attempt to do a
rollback in a procedure will then crash or get some other form of
corruption again every time until you manually restart the cluster.

--
Andrew (irc:RhodiumToad)

Hi Peter,

On 2018-06-10 21:06:59 +0200, Dmitry Dolgov wrote:
> > On 8 June 2018 at 06:20, Andrew Gierth <andrew(at)tao11(dot)riddles(dot)org(dot)uk> wrote:
>
> > Joe> My colleague Yogesh Sharma discovered an assert in nested SQL
> > Joe> procedure calls after ROLLBACK is used. Minimal test case and
> > Joe> backtrace below. I have not yet tried to figure out exactly what
> > Joe> is going on beyond seeing that it occurs in pg_plan_query() where
> > Joe> the comment says "Planner must have a snapshot in case it calls
> > Joe> user-defined functions"...
> >
> > Andrew> /message-id/29608.1518533639@sss.pgh.pa.us
> >
> > I added it to the open items list since nobody else seems to have taken
> > notice; from Tom's linked message it seems this should be Peter E's bag?
>
> I've taken a look at this - indeed, the situation looks similar to what
> described in the linked message, namely after a transaction rollback and
> creation of a new one no active snapshot was pushed. But in this particular
> case the timeframe without an active snapshot is actually limited and includes
> only some initialization and planning activity (after that a new one is
> pushed). The commentary says that "Planner must have a snapshot in case it
> calls user-defined functions." - I tried to simulate this in order to see what
> would happen, but got no errors. Is there a chance that it's an outdated
> Assert?

This hasn't progressed in a while. Peter, since you committed the
relevant change, could you update us please?

Greetings,

Andres Freund

On 6/27/18 17:44, Andres Freund wrote:
> This hasn't progressed in a while. Peter, since you committed the
> relevant change, could you update us please?

I've been on vacation for a bit. I will work on this next. I hope to
have a solution in a few days.

--
Peter Eisentraut http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

On 6/27/18 18:51, Peter Eisentraut wrote:
> On 6/27/18 17:44, Andres Freund wrote:
>> This hasn't progressed in a while. Peter, since you committed the
>> relevant change, could you update us please?
>
> I've been on vacation for a bit. I will work on this next. I hope to
> have a solution in a few days.

Proposed patch attached.

--
Peter Eisentraut http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

On 12.06.18 18:47, Andrew Gierth wrote:
> While testing this, I ran into another semi-related issue:
> shmem_exit_inprogress isn't ever being cleared in the postmaster, which
> means that if you ever have a crash-restart, any attempt to do a
> rollback in a procedure will then crash or get some other form of
> corruption again every time until you manually restart the cluster.

I think we could unset shmem_exit_inprogress at the end of shmem_exit().
I'm trying to remember why we didn't just use proc_exit_inprogress for
this. I'll need to test this more.

--
Peter Eisentraut http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

Hi,

On 2018-06-29 13:52:23 +0200, Peter Eisentraut wrote:
> From 95fc7156afe521b715fab08d44606774df875e92 Mon Sep 17 00:00:00 2001
> From: Peter Eisentraut <peter_e(at)gmx(dot)net>
> Date: Fri, 29 Jun 2018 13:28:39 +0200
> Subject: [PATCH] Fix assert in nested SQL procedure call

Andrew, Peter, are you happy with this? It'd be good to close this open
item.

- Andres

On 12.06.18 18:47, Andrew Gierth wrote:
> While testing this, I ran into another semi-related issue:
> shmem_exit_inprogress isn't ever being cleared in the postmaster, which
> means that if you ever have a crash-restart, any attempt to do a
> rollback in a procedure will then crash or get some other form of
> corruption again every time until you manually restart the cluster.

I have committed a fix for this.

--
Peter Eisentraut http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

On 12.07.18 18:43, Andres Freund wrote:
> On 2018-06-29 13:52:23 +0200, Peter Eisentraut wrote:
>> From 95fc7156afe521b715fab08d44606774df875e92 Mon Sep 17 00:00:00 2001
>> From: Peter Eisentraut <peter_e(at)gmx(dot)net>
>> Date: Fri, 29 Jun 2018 13:28:39 +0200
>> Subject: [PATCH] Fix assert in nested SQL procedure call
>
> Andrew, Peter, are you happy with this? It'd be good to close this open
> item.

Yes, it's done. I'm going to update the wiki.

--
Peter Eisentraut http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services