Re: Inconsistency in plpgsql's error context reports

I wrote:
> Robert Haas <robertmhaas@gmail.com> writes:
>> On Sun, Dec 10, 2017 at 11:55 AM, Tom Lane <tgl@sss.pgh.pa.us> wrote:
>>> There seem to be two ways we could look at this.  One is that the
>>> new test case just needs to be rejiggered to avoid unstable output
>>> ("\set VERBOSITY terse" would be the easiest way).  But there is
>>> also room to argue that it's bad that plpgsql produces error reports
>>> that vary depending on the phase of the moon, which is pretty much
>>> what this would look like in the field --- cache flushes will occur
>>> unpredictably in most application environments.

>> I am inclined toward the latter view.

> Yeah, me too.  I'll see about patching exec_eval_simple_expr() to
> provide a context line that matches SPI's.  Seems like a HEAD-only
> change though, as this will result in visible behavior change in
> the typical case.

Here's a quick hack at that.  I guess the main question that needs to be
asked is whether we're happy with plpgsql getting so much chattier
(as per all the regression test changes).

If we're not, the alternative that could be considered is to make SPI
expose some way to suppress its use of a context callback, and change
plpgsql to invoke that when dealing with an expression.  That would
be rather more invasive code-wise, but would largely eliminate the
behavioral change as seen by users.

Another angle, if we do keep it like this, is that maybe SPI should
export _SPI_error_callback so that plpgsql can use it directly,
rather than having a copy that needs to be kept in sync.

            regards, tom lane

diff --git a/src/pl/plpgsql/src/pl_exec.c b/src/pl/plpgsql/src/pl_exec.c
index fa4d573..a7c399b 100644
*** a/src/pl/plpgsql/src/pl_exec.c
--- b/src/pl/plpgsql/src/pl_exec.c
*************** static int exec_run_select(PLpgSQL_execs
*** 266,271 ****
--- 266,272 ----
                  PLpgSQL_expr *expr, long maxtuples, Portal *portalP);
  static int exec_for_query(PLpgSQL_execstate *estate, PLpgSQL_stmt_forq *stmt,
                 Portal portal, bool prefetch_ok);
+ static void simple_expr_error_callback(void *arg);
  static ParamListInfo setup_param_list(PLpgSQL_execstate *estate,
                   PLpgSQL_expr *expr);
  static ParamListInfo setup_unshared_param_list(PLpgSQL_execstate *estate,
*************** exec_eval_simple_expr(PLpgSQL_execstate
*** 5504,5509 ****
--- 5505,5511 ----
      ExprContext *econtext = estate->eval_econtext;
      LocalTransactionId curlxid = MyProc->lxid;
      CachedPlan *cplan;
+     ErrorContextCallback simpleerrcontext;
      ParamListInfo paramLI;
      void       *save_setup_arg;
      MemoryContext oldcontext;
*************** exec_eval_simple_expr(PLpgSQL_execstate
*** 5579,5584 ****
--- 5581,5594 ----
      }

      /*
+      * Also setup error traceback support for ereport()
+      */
+     simpleerrcontext.callback = simple_expr_error_callback;
+     simpleerrcontext.arg = expr;
+     simpleerrcontext.previous = error_context_stack;
+     error_context_stack = &simpleerrcontext;
+
+     /*
       * Set up ParamListInfo to pass to executor.  We need an unshared list if
       * it's going to include any R/W expanded-object pointer.  For safety,
       * save and restore estate->paramLI->parserSetupArg around our use of the
*************** exec_eval_simple_expr(PLpgSQL_execstate
*** 5612,5617 ****
--- 5622,5629 ----

      estate->paramLI->parserSetupArg = save_setup_arg;

+     error_context_stack = simpleerrcontext.previous;
+
      if (!estate->readonly_func)
          PopActiveSnapshot();

*************** exec_eval_simple_expr(PLpgSQL_execstate
*** 5628,5633 ****
--- 5640,5674 ----
      return true;
  }

+ /*
+  * simple_expr_error_callback
+  *
+  * Add context information when a simple expression fails.  This should
+  * match the behavior of spi.c's _SPI_error_callback, else users will see
+  * different behavior for errors in simple and not-simple expressions.
+  */
+ static void
+ simple_expr_error_callback(void *arg)
+ {
+     PLpgSQL_expr *expr = (PLpgSQL_expr *) arg;
+     const char *query = expr->query;
+     int            syntaxerrposition;
+
+     /*
+      * If there is a syntax error position, convert to internal syntax error;
+      * otherwise treat the query as an item of context stack
+      */
+     syntaxerrposition = geterrposition();
+     if (syntaxerrposition > 0)
+     {
+         errposition(0);
+         internalerrposition(syntaxerrposition);
+         internalerrquery(query);
+     }
+     else
+         errcontext("SQL statement \"%s\"", query);
+ }
+

  /*
   * Create a ParamListInfo to pass to SPI
diff --git a/src/test/regress/expected/plpgsql.out b/src/test/regress/expected/plpgsql.out
index 26f6e43..4a384b0 100644
*** a/src/test/regress/expected/plpgsql.out
--- b/src/test/regress/expected/plpgsql.out
*************** DETAIL:  Key (name)=(PF1_1) already exis
*** 1519,1536 ****
--- 1519,1540 ----
  update PSlot set backlink = 'WS.not.there' where slotname = 'PS.base.a1';
  ERROR:  WS.not.there         does not exist
  CONTEXT:  PL/pgSQL function tg_backlink_set(character,character) line 30 at RAISE
+ SQL statement "SELECT tg_backlink_set(new.backlink, new.slotname)"
  PL/pgSQL function tg_backlink_a() line 17 at assignment
  update PSlot set backlink = 'XX.illegal' where slotname = 'PS.base.a1';
  ERROR:  illegal backlink beginning with XX
  CONTEXT:  PL/pgSQL function tg_backlink_set(character,character) line 47 at RAISE
+ SQL statement "SELECT tg_backlink_set(new.backlink, new.slotname)"
  PL/pgSQL function tg_backlink_a() line 17 at assignment
  update PSlot set slotlink = 'PS.not.there' where slotname = 'PS.base.a1';
  ERROR:  PS.not.there         does not exist
  CONTEXT:  PL/pgSQL function tg_slotlink_set(character,character) line 30 at RAISE
+ SQL statement "SELECT tg_slotlink_set(new.slotlink, new.slotname)"
  PL/pgSQL function tg_slotlink_a() line 17 at assignment
  update PSlot set slotlink = 'XX.illegal' where slotname = 'PS.base.a1';
  ERROR:  illegal slotlink beginning with XX
  CONTEXT:  PL/pgSQL function tg_slotlink_set(character,character) line 77 at RAISE
+ SQL statement "SELECT tg_slotlink_set(new.slotlink, new.slotname)"
  PL/pgSQL function tg_slotlink_a() line 17 at assignment
  insert into HSlot values ('HS', 'base.hub1', 1, '');
  ERROR:  duplicate key value violates unique constraint "hslot_name"
*************** exception when others then
*** 4273,4279 ****
  end;
  $$ language plpgsql;
  select stacked_diagnostics_test();
! NOTICE:  sqlstate: 22012, message: division by zero, context: [PL/pgSQL function zero_divide() line 4 at RETURN <-
SQLstatement "SELECT zero_divide()" <- PL/pgSQL function stacked_diagnostics_test() line 6 at PERFORM] 
   stacked_diagnostics_test
  --------------------------

--- 4277,4283 ----
  end;
  $$ language plpgsql;
  select stacked_diagnostics_test();
! NOTICE:  sqlstate: 22012, message: division by zero, context: [SQL statement "SELECT 10 / v" <- PL/pgSQL function
zero_divide()line 4 at RETURN <- SQL statement "SELECT zero_divide()" <- PL/pgSQL function stacked_diagnostics_test()
line6 at PERFORM] 
   stacked_diagnostics_test
  --------------------------

*************** SAVEPOINT a;
*** 4772,4777 ****
--- 4776,4782 ----
  select error2('nonexistent.stuffs');
  ERROR:  schema "nonexistent" does not exist
  CONTEXT:  SQL function "error1" statement 1
+ SQL statement "SELECT error1(p_name_table)"
  PL/pgSQL function error2(text) line 3 at RETURN
  ROLLBACK TO a;
  select error2('public.stuffs');
*************** select scope_test();
*** 5026,5032 ****

  drop function scope_test();
  -- Check that variables are reinitialized on block re-entry.
- \set VERBOSITY terse   \\ -- needed for output stability
  do $$
  begin
    for i in 1..3 loop
--- 5031,5036 ----
*************** NOTICE:  r = (1,2)
*** 5051,5057 ****
  NOTICE:  x = <NULL>
  NOTICE:  y = 2
  ERROR:  record "r" is not assigned yet
! \set VERBOSITY default
  -- Check handling of conflicts between plpgsql vars and table columns.
  set plpgsql.variable_conflict = error;
  create function conflict_test() returns setof int8_tbl as $$
--- 5055,5063 ----
  NOTICE:  x = <NULL>
  NOTICE:  y = 2
  ERROR:  record "r" is not assigned yet
! DETAIL:  The tuple structure of a not-yet-assigned record is indeterminate.
! CONTEXT:  SQL statement "SELECT r"
! PL/pgSQL function inline_code_block line 15 at RAISE
  -- Check handling of conflicts between plpgsql vars and table columns.
  set plpgsql.variable_conflict = error;
  create function conflict_test() returns setof int8_tbl as $$
*************** select outer_outer_func(10);
*** 5507,5516 ****
--- 5513,5526 ----
  NOTICE:  calling down into outer_func()
  NOTICE:  calling down into inner_func()
  NOTICE:  ***PL/pgSQL function inner_func(integer) line 4 at GET DIAGNOSTICS
+ SQL statement "SELECT inner_func($1)"
  PL/pgSQL function outer_func(integer) line 6 at assignment
+ SQL statement "SELECT outer_func($1)"
  PL/pgSQL function outer_outer_func(integer) line 6 at assignment***
  NOTICE:  ***PL/pgSQL function inner_func(integer) line 7 at GET DIAGNOSTICS
+ SQL statement "SELECT inner_func($1)"
  PL/pgSQL function outer_func(integer) line 6 at assignment
+ SQL statement "SELECT outer_func($1)"
  PL/pgSQL function outer_outer_func(integer) line 6 at assignment***
  NOTICE:  lets make sure we didnt break anything
  NOTICE:  inner_func() done
*************** select outer_outer_func(20);
*** 5525,5534 ****
--- 5535,5548 ----
  NOTICE:  calling down into outer_func()
  NOTICE:  calling down into inner_func()
  NOTICE:  ***PL/pgSQL function inner_func(integer) line 4 at GET DIAGNOSTICS
+ SQL statement "SELECT inner_func($1)"
  PL/pgSQL function outer_func(integer) line 6 at assignment
+ SQL statement "SELECT outer_func($1)"
  PL/pgSQL function outer_outer_func(integer) line 6 at assignment***
  NOTICE:  ***PL/pgSQL function inner_func(integer) line 7 at GET DIAGNOSTICS
+ SQL statement "SELECT inner_func($1)"
  PL/pgSQL function outer_func(integer) line 6 at assignment
+ SQL statement "SELECT outer_func($1)"
  PL/pgSQL function outer_outer_func(integer) line 6 at assignment***
  NOTICE:  lets make sure we didnt break anything
  NOTICE:  inner_func() done
*************** select outer_outer_func(10);
*** 5589,5598 ****
--- 5603,5616 ----
  NOTICE:  calling down into outer_func()
  NOTICE:  calling down into inner_func()
  NOTICE:  ***PL/pgSQL function inner_func(integer) line 10 at GET DIAGNOSTICS
+ SQL statement "SELECT inner_func($1)"
  PL/pgSQL function outer_func(integer) line 6 at assignment
+ SQL statement "SELECT outer_func($1)"
  PL/pgSQL function outer_outer_func(integer) line 6 at assignment***
  NOTICE:  ***PL/pgSQL function inner_func(integer) line 15 at GET DIAGNOSTICS
+ SQL statement "SELECT inner_func($1)"
  PL/pgSQL function outer_func(integer) line 6 at assignment
+ SQL statement "SELECT outer_func($1)"
  PL/pgSQL function outer_outer_func(integer) line 6 at assignment***
  NOTICE:  lets make sure we didnt break anything
  NOTICE:  inner_func() done
*************** select outer_outer_func(20);
*** 5607,5616 ****
--- 5625,5638 ----
  NOTICE:  calling down into outer_func()
  NOTICE:  calling down into inner_func()
  NOTICE:  ***PL/pgSQL function inner_func(integer) line 10 at GET DIAGNOSTICS
+ SQL statement "SELECT inner_func($1)"
  PL/pgSQL function outer_func(integer) line 6 at assignment
+ SQL statement "SELECT outer_func($1)"
  PL/pgSQL function outer_outer_func(integer) line 6 at assignment***
  NOTICE:  ***PL/pgSQL function inner_func(integer) line 15 at GET DIAGNOSTICS
+ SQL statement "SELECT inner_func($1)"
  PL/pgSQL function outer_func(integer) line 6 at assignment
+ SQL statement "SELECT outer_func($1)"
  PL/pgSQL function outer_outer_func(integer) line 6 at assignment***
  NOTICE:  lets make sure we didnt break anything
  NOTICE:  inner_func() done
diff --git a/src/test/regress/expected/transactions.out b/src/test/regress/expected/transactions.out
index a7fdcf4..9e30ea2 100644
*** a/src/test/regress/expected/transactions.out
--- b/src/test/regress/expected/transactions.out
*************** FETCH ok;  -- should work
*** 644,650 ****

  FETCH ctt; -- error occurs here
  ERROR:  division by zero
! CONTEXT:  PL/pgSQL function invert(double precision) line 1 at RETURN
  SQL statement "INSERT INTO new_table SELECT invert(0.0)"
  PL/pgSQL function create_temp_tab() line 6 at SQL statement
  ROLLBACK TO s1;
--- 644,651 ----

  FETCH ctt; -- error occurs here
  ERROR:  division by zero
! CONTEXT:  SQL statement "SELECT 1/x"
! PL/pgSQL function invert(double precision) line 1 at RETURN
  SQL statement "INSERT INTO new_table SELECT invert(0.0)"
  PL/pgSQL function create_temp_tab() line 6 at SQL statement
  ROLLBACK TO s1;
diff --git a/src/test/regress/sql/plpgsql.sql b/src/test/regress/sql/plpgsql.sql
index bb09b2d..07b6fc8 100644
*** a/src/test/regress/sql/plpgsql.sql
--- b/src/test/regress/sql/plpgsql.sql
*************** drop function scope_test();
*** 4016,4022 ****

  -- Check that variables are reinitialized on block re-entry.

- \set VERBOSITY terse   \\ -- needed for output stability
  do $$
  begin
    for i in 1..3 loop
--- 4016,4021 ----
*************** begin
*** 4035,4041 ****
      end;
    end loop;
  end$$;
- \set VERBOSITY default

  -- Check handling of conflicts between plpgsql vars and table columns.

--- 4034,4039 ----