pg.ddx.io  pgsql-bugs@postgresql.org mailing list archive  
help / color / mirror / Atom feed
BUG #18070: Assertion failed when processing error from plpy's iterator
15+ messages / 4 participants
[nested] [flat]

* BUG #18070: Assertion failed when processing error from plpy's iterator
@ 2023-08-25 14:00  PG Bug reporting form <noreply@postgresql.org>
  0 siblings, 1 reply; 15+ messages in thread

From: PG Bug reporting form @ 2023-08-25 14:00 UTC (permalink / raw)
  To: pgsql-bugs@lists.postgresql.org; +Cc: exclusion@gmail.com

The following bug has been logged on the website:

Bug reference:      18070
Logged by:          Alexander Lakhin
Email address:      exclusion@gmail.com
PostgreSQL version: 16beta3
Operating system:   Ubuntu 22.04
Description:        

The following script:
CREATE EXTENSION plpython3u;

CREATE FUNCTION pyfunc() RETURNS SETOF text AS $$
  plan = plpy.prepare("SELECT * FROM pyfunc()", ["text"])
  for row in plpy.cursor(plan, ["w"]):
    yield row[0]
$$ LANGUAGE plpython3u;

SELECT pyfunc();

triggers the assertion failure:
TRAP: failed Assert("detail == NULL"), File: "plpy_elog.c", Line: 107, PID:
784729

Core was generated by `postgres: law regression [local] SELECT              
                        '.
Program terminated with signal SIGABRT, Aborted.

warning: Section `.reg-xstate/784729' in core file too small.
#0  __pthread_kill_implementation (no_tid=0, signo=6,
threadid=140508500382656)
    at ./nptl/pthread_kill.c:44
44      ./nptl/pthread_kill.c: No such file or directory.
(gdb) bt
#0  __pthread_kill_implementation (no_tid=0, signo=6,
threadid=140508500382656)
    at ./nptl/pthread_kill.c:44
#1  __pthread_kill_internal (signo=6, threadid=140508500382656) at
./nptl/pthread_kill.c:78
#2  __GI___pthread_kill (threadid=140508500382656, signo=signo@entry=6) at
./nptl/pthread_kill.c:89
#3  0x00007fcaae523476 in __GI_raise (sig=sig@entry=6) at
../sysdeps/posix/raise.c:26
#4  0x00007fcaae5097f3 in __GI_abort () at ./stdlib/abort.c:79
#5  0x000055e42de8b7ab in ExceptionalCondition (conditionName=0x7fcaa360d2fc
"detail == NULL", 
    fileName=0x7fcaa360d2f0 "plpy_elog.c", lineNumber=107) at assert.c:66
#6  0x00007fcaa35fd766 in PLy_elog_impl (elevel=21, 
    fmt=0x7fcaa360d830 "error fetching next item from iterator") at
plpy_elog.c:107
#7  0x00007fcaa35ff443 in PLy_exec_function (fcinfo=0x55e432b63818,
proc=0x55e42f100b18)
    at plpy_exec.c:168
#8  0x00007fcaa36025df in plpython3_call_handler (fcinfo=0x55e432b63818) at
plpy_main.c:245
#9  0x000055e42d9f81e5 in ExecMakeTableFunctionResult
(setexpr=0x55e432b5fd60, econtext=0x55e432b5fc30, 
    argContext=0x55e432b63700, expectedDesc=0x55e432b5fe20,
randomAccess=true) at execSRF.c:235
#10 0x000055e42da1506e in FunctionNext (node=0x55e432b5fa20) at
nodeFunctionscan.c:95
#11 0x000055e42d9f9cc6 in ExecScanFetch (node=0x55e432b5fa20,
accessMtd=0x55e42da14fb8 <FunctionNext>, 
    recheckMtd=0x55e42da153bf <FunctionRecheck>) at execScan.c:132
#12 0x000055e42d9f9d3f in ExecScan (node=0x55e432b5fa20,
accessMtd=0x55e42da14fb8 <FunctionNext>, 
    recheckMtd=0x55e42da153bf <FunctionRecheck>) at execScan.c:181
#13 0x000055e42da15418 in ExecFunctionScan (pstate=0x55e432b5fa20) at
nodeFunctionscan.c:270
#14 0x000055e42d9f5689 in ExecProcNodeFirst (node=0x55e432b5fa20) at
execProcnode.c:464
#15 0x000055e42d9e8716 in ExecProcNode (node=0x55e432b5fa20)
    at ../../../src/include/executor/executor.h:273
#16 0x000055e42d9eb6ce in ExecutePlan (estate=0x55e432b5f7f8,
planstate=0x55e432b5fa20, 
    use_parallel_mode=false, operation=CMD_SELECT, sendTuples=true,
numberTuples=1, 
    direction=ForwardScanDirection, dest=0x55e42e2190c0 <spi_printtupDR>,
execute_once=false)
    at execMain.c:1670
...

(gdb) frame 6
#6  0x00007fcaa35fd766 in PLy_elog_impl (elevel=21, 
    fmt=0x7fcaa360d830 "error fetching next item from iterator") at
plpy_elog.c:107
107                     Assert(detail == NULL);
(gdb) p xmsg
$1 = 0x55e432b68300 "spiexceptions.StatementTooComplex: error fetching next
item from iterator"
(gdb) p detail
$2 = 0x7fcaa2d50a70 "spiexceptions.StatementTooComplex: stack depth limit
exceeded"

Without asserts enabled, I get:
ERROR:  error fetching next item from iterator
DETAIL:  spiexceptions.StatementTooComplex: error fetching next item from
iterator
HINT:  Increase the configuration parameter "max_stack_depth" (currently
2048kB), after ensuring the platform's stack depth limit is adequate.
CONTEXT:  Traceback (most recent call last):
PL/Python function "pyfunc"

It looks like the following coding in PLy_elog_impl():
		/* Since we have a format string, we cannot have a SPI detail. */
		Assert(detail == NULL);

		/* If there's an exception message, it goes in the detail. */
		if (xmsg)
			detail = xmsg;

doesn't expect to process a call PLy_elog(LEVEL, "message") when some (SPI)
error occurred before the call.

Reproduced on REL_11_STABLE (with plpython2u) .. master.

Apparently, this coding exists since 2bd78eb8d.



^ permalink  raw  reply  [nested|flat] 15+ messages in thread

* Re: BUG #18070: Assertion failed when processing error from plpy's iterator
@ 2023-09-15 17:00  Alexander Lakhin <exclusion@gmail.com>
  parent: PG Bug reporting form <noreply@postgresql.org>
  0 siblings, 1 reply; 15+ messages in thread

From: Alexander Lakhin @ 2023-09-15 17:00 UTC (permalink / raw)
  To: pgsql-bugs@lists.postgresql.org

25.08.2023 17:00, PG Bug reporting form wrote:
> The following bug has been logged on the website:
>
> Bug reference:      18070
> ...
> It looks like the following coding in PLy_elog_impl():
> 		/* Since we have a format string, we cannot have a SPI detail. */
> 		Assert(detail == NULL);
>
> 		/* If there's an exception message, it goes in the detail. */
> 		if (xmsg)
> 			detail = xmsg;
>
> doesn't expect to process a call PLy_elog(LEVEL, "message") when some (SPI)
> error occurred before the call.
>

Please look at the patch attached, which removes the Assert and changes
the detail message e.g. , for the query:
CREATE EXTENSION plpython3u;
CREATE TYPE tst AS (t text);
CREATE FUNCTION pyfunc() RETURNS SETOF text AS $$
   plan = plpy.prepare("SELECT * FROM tst", ["text"])
   for row in plpy.cursor(plan, ["w"]):
     yield row[0]
$$ LANGUAGE plpython3u;

SELECT pyfunc();

From:
ERROR:  error fetching next item from iterator
LINE 1: SELECT * FROM tst
                       ^
DETAIL:  spiexceptions.WrongObjectType: cannot open relation "tst"
QUERY:  SELECT * FROM tst
CONTEXT:  Traceback (most recent call last):
PL/Python function "pyfunc"

To:
ERROR:  error fetching next item from iterator
LINE 1: SELECT * FROM tst
                       ^
DETAIL:  This operation is not supported for composite types.
QUERY:  SELECT * FROM tst
CONTEXT:  Traceback (most recent call last):
PL/Python function "pyfunc"

Best regards,
Alexander

Attachments:

  [text/x-patch] fix-plpy_elog.patch (645B, ../../9fa9c154-d084-07de-8224-aab7fc8a119e@gmail.com/2-fix-plpy_elog.patch)
  download | inline diff:
diff --git a/src/pl/plpython/plpy_elog.c b/src/pl/plpython/plpy_elog.c
index 7c627eacfb..69359908f8 100644
--- a/src/pl/plpython/plpy_elog.c
+++ b/src/pl/plpython/plpy_elog.c
@@ -103,11 +103,11 @@ PLy_elog_impl(int elevel, const char *fmt,...)
 		}
 		primary = emsg.data;
 
-		/* Since we have a format string, we cannot have a SPI detail. */
-		Assert(detail == NULL);
-
-		/* If there's an exception message, it goes in the detail. */
-		if (xmsg)
+		/*
+		 * When we have no detail from the error data, an exception message,
+		 * if not empty, goes in the detail.
+		 */
+		if (detail == NULL && xmsg != NULL)
 			detail = xmsg;
 	}
 	else


^ permalink  raw  reply  [nested|flat] 15+ messages in thread

* Re: BUG #18070: Assertion failed when processing error from plpy's iterator
@ 2023-09-16 08:27  Michael Paquier <michael@paquier.xyz>
  parent: Alexander Lakhin <exclusion@gmail.com>
  0 siblings, 1 reply; 15+ messages in thread

From: Michael Paquier @ 2023-09-16 08:27 UTC (permalink / raw)
  To: Alexander Lakhin <exclusion@gmail.com>; +Cc: pgsql-bugs@lists.postgresql.org

On Fri, Sep 15, 2023 at 08:00:00PM +0300, Alexander Lakhin wrote:
> -        /* Since we have a format string, we cannot have a SPI detail. */
> -        Assert(detail == NULL);
> -
> -        /* If there's an exception message, it goes in the detail. */
> -        if (xmsg)
> +        /*
> +         * When we have no detail from the error data, an exception message,
> +         * if not empty, goes in the detail.
> +         */
> +        if (detail == NULL && xmsg != NULL)
>              detail = xmsg;

Yeah, I think that you're right here to enforce the use of a DETAIL
message if it exists instead of the xmsg.  At least that feels more
natural because we would get the same error when attempting to select
from a composite type.

How about adding a regression test?  Say in plpython_error.sql where
we already check a bunch of error patterns?
--
Michael

Attachments:

  [application/pgp-signature] signature.asc (832B, ../../ZQVm8KponTxqj8G3@paquier.xyz/2-signature.asc)
  download

^ permalink  raw  reply  [nested|flat] 15+ messages in thread

* Re: BUG #18070: Assertion failed when processing error from plpy's iterator
@ 2023-09-16 14:34  Tom Lane <tgl@sss.pgh.pa.us>
  parent: Michael Paquier <michael@paquier.xyz>
  0 siblings, 1 reply; 15+ messages in thread

From: Tom Lane @ 2023-09-16 14:34 UTC (permalink / raw)
  To: Michael Paquier <michael@paquier.xyz>; +Cc: Alexander Lakhin <exclusion@gmail.com>; pgsql-bugs@lists.postgresql.org

Michael Paquier <michael@paquier.xyz> writes:
> On Fri, Sep 15, 2023 at 08:00:00PM +0300, Alexander Lakhin wrote:
>> +        /*
>> +         * When we have no detail from the error data, an exception message,
>> +         * if not empty, goes in the detail.
>> +         */
>> +        if (detail == NULL && xmsg != NULL)
>> 		detail = xmsg;

> Yeah, I think that you're right here to enforce the use of a DETAIL
> message if it exists instead of the xmsg.

I dunno about that.  We're trying to shove three pounds of stuff into
a two-pound sack, which isn't going to work perfectly in any case,
but I'm not sure this is the right priority order for the available
strings.

In the original example with an infinite-recursion error, what we
end up with at the point of the Assert is

(gdb) i locals
save_errno = 2
xmsg = 0x666a8d8 "spiexceptions.StatementTooComplex: error fetching next item from iterator"
tbmsg = 0x666ace8 "Traceback (most recent call last):"
tb_depth = 1
emsg = {data = 0x666b0f8 "error fetching next item from iterator", len = 38, 
  maxlen = 1024, cursor = 0}
exc = 0x18fd448
val = 0x7f1fefe39e88
tb = 0x7f1fef858608
primary = 0x666b0f8 "error fetching next item from iterator"
sqlerrcode = 16777477
detail = 0x7f1fefe21920 "spiexceptions.StatementTooComplex: stack depth limit exceeded"
hint = 0x7f1ffd5c6f78 "Increase the configuration parameter \"max_stack_depth\" (currently 2048kB), after ensuring the platform's stack depth limit is adequate."
query = 0x0
position = 0
schema_name = 0x0
table_name = 0x0
column_name = 0x0
datatype_name = 0x0

Clearly, "detail" offers the key insight here and we don't want to
lose it; but xmsg seems rather duplicative of the fmt string
(which is what is reflected into emsg and primary here).

On the other hand, in Alexander's newer test case we find

(gdb) i locals
save_errno = 2
xmsg = 0x191ef50 "spiexceptions.WrongObjectType: cannot open relation \"tst\""
tbmsg = 0x191f360 "Traceback (most recent call last):"
tb_depth = 1
emsg = {data = 0x191f770 "error fetching next item from iterator", len = 38, 
  maxlen = 1024, cursor = 0}
exc = 0x18f02f8
val = 0x7f1fefda7e88
tb = 0x7f1fefcfd3c8
primary = 0x191f770 "error fetching next item from iterator"
sqlerrcode = 151027844
detail = 0x7f1fefe1fa20 "This operation is not supported for composite types."
hint = 0x0
query = 0x7f1fefcfc3c0 "SELECT * FROM tst"
position = 15
schema_name = 0x0
table_name = 0x0
column_name = 0x0
datatype_name = 0x0

Here, xmsg seems strictly more useful than fmt, but the patch as
proposed would discard xmsg.

I wonder if we shouldn't simply say the rule is that xmsg, if set,
overrides fmt.  This'd likely have some impact on existing test
cases, but perhaps the net result would be no worse?

			regards, tom lane





^ permalink  raw  reply  [nested|flat] 15+ messages in thread

* Re: BUG #18070: Assertion failed when processing error from plpy's iterator
@ 2023-09-16 17:00  Alexander Lakhin <exclusion@gmail.com>
  parent: Tom Lane <tgl@sss.pgh.pa.us>
  0 siblings, 1 reply; 15+ messages in thread

From: Alexander Lakhin @ 2023-09-16 17:00 UTC (permalink / raw)
  To: Tom Lane <tgl@sss.pgh.pa.us>; Michael Paquier <michael@paquier.xyz>; +Cc: pgsql-bugs@lists.postgresql.org

Hello,

16.09.2023 17:34, Tom Lane wrote:
> Michael Paquier<michael@paquier.xyz>  writes:
>> On Fri, Sep 15, 2023 at 08:00:00PM +0300, Alexander Lakhin wrote:
>>> +        /*
>>> +         * When we have no detail from the error data, an exception message,
>>> +         * if not empty, goes in the detail.
>>> +         */
>>> +        if (detail == NULL && xmsg != NULL)
>>> 		detail = xmsg;
>> Yeah, I think that you're right here to enforce the use of a DETAIL
>> message if it exists instead of the xmsg.
> I dunno about that.  We're trying to shove three pounds of stuff into
> a two-pound sack, which isn't going to work perfectly in any case,
> but I'm not sure this is the right priority order for the available
> strings.

Thanks for looking at this!

> In the original example with an infinite-recursion error, what we
> end up with at the point of the Assert is
>
> (gdb) i locals
> save_errno = 2
> xmsg = 0x666a8d8 "spiexceptions.StatementTooComplex: error fetching next item from iterator"
> tbmsg = 0x666ace8 "Traceback (most recent call last):"
> tb_depth = 1
> emsg = {data = 0x666b0f8 "error fetching next item from iterator", len = 38,
>    maxlen = 1024, cursor = 0}
> exc = 0x18fd448
> val = 0x7f1fefe39e88
> tb = 0x7f1fef858608
> primary = 0x666b0f8 "error fetching next item from iterator"
> sqlerrcode = 16777477
> detail = 0x7f1fefe21920 "spiexceptions.StatementTooComplex: stack depth limit exceeded"
> hint = 0x7f1ffd5c6f78 "Increase the configuration parameter \"max_stack_depth\" (currently 2048kB), after ensuring the platform's stack depth limit is adequate."
> query = 0x0
> position = 0
> schema_name = 0x0
> table_name = 0x0
> column_name = 0x0
> datatype_name = 0x0
>
> Clearly, "detail" offers the key insight here and we don't want to
> lose it; but xmsg seems rather duplicative of the fmt string
> (which is what is reflected into emsg and primary here).
>
> On the other hand, in Alexander's newer test case we find
>
> (gdb) i locals
> save_errno = 2
> xmsg = 0x191ef50 "spiexceptions.WrongObjectType: cannot open relation \"tst\""
> tbmsg = 0x191f360 "Traceback (most recent call last):"
> tb_depth = 1
> emsg = {data = 0x191f770 "error fetching next item from iterator", len = 38,
>    maxlen = 1024, cursor = 0}
> exc = 0x18f02f8
> val = 0x7f1fefda7e88
> tb = 0x7f1fefcfd3c8
> primary = 0x191f770 "error fetching next item from iterator"
> sqlerrcode = 151027844
> detail = 0x7f1fefe1fa20 "This operation is not supported for composite types."
> hint = 0x0
> query = 0x7f1fefcfc3c0 "SELECT * FROM tst"
> position = 15
> schema_name = 0x0
> table_name = 0x0
> column_name = 0x0
> datatype_name = 0x0
>
> Here, xmsg seems strictly more useful than fmt, but the patch as
> proposed would discard xmsg.
>
> I wonder if we shouldn't simply say the rule is that xmsg, if set,
> overrides fmt.  This'd likely have some impact on existing test
> cases, but perhaps the net result would be no worse?

When looking for a representative query for a regression test, I've
also discovered that the result is not always appealing.

Yes, for the case "SELECT * FROM some_type" you mentioned, with the patched
version we get "detail" from the underlying exception:
DETAIL:  This operation is not supported for composite types.

But without the patch we get "message":
DETAIL:  spiexceptions.WrongObjectType: cannot open relation "tst"

In this case the difference is minor, but I would prefer to get a message
with the relation name.
I've tested another case, with to_date():
                 ereturn(escontext, -1,
(errcode(ERRCODE_INVALID_DATETIME_FORMAT),
                                  errmsg("invalid value \"%s\" for \"%s\"",
                                                 copy, node->key->name),
                                  errdetail("Value must be an integer.")));

With the patched version, the error produced by:
CREATE FUNCTION python_error_detail() RETURNS SETOF text AS $$
   plan = plpy.prepare("SELECT to_date('DD', 'DD') d")
   for row in plpy.cursor(plan):
     yield row['d']
$$ LANGUAGE plpython3u;

SELECT python_error_detail();

looks as follows:
  ERROR:  error fetching next item from iterator
  DETAIL:  Value must be an integer.
  CONTEXT:  Traceback (most recent call last):
  PL/Python function "python_error_detail"

I can't say that the detail info "Value must be an integer" is useful here.

So if we omit the exception message, while keeping the detail, we loose a
higher importance level of information in the stack (or a sack):
1) plpy_elog message
2) underlying exception message
3) underlying exception detail
4) underlying exception hint

I also thought about omitting the underlying exception detail, thus just
doing mapping:
"plpy_elog message" -> message,
"underlying exception message" -> detail,
"underlying exception hint" -> hint,
but it seems that presenting a hint without an intermediate level of
information (detail) could look weird in some cases too.

So my next idea was to concatenate "underlying exception message" +
"underlying exception detail" and to put the result in the detail.

It seems that it works pretty well, e.g. for the case with to_date(), we get:
SELECT python_error_detail();
ERROR:  error fetching next item from iterator
DETAIL:  spiexceptions.InvalidDatetimeFormat: invalid value "DD" for "DD"
Value must be an integer.
CONTEXT:  Traceback (most recent call last):
PL/Python function "python_error_detail"

(I've confirmed that all these strings are localized correctly.)

With the stack overflow case, the function PLy_elog() called recursively,
so the output looks like:
SELECT pyfunc();
ERROR:  error fetching next item from iterator
DETAIL:  spiexceptions.StatementTooComplex: error fetching next item from iterator
spiexceptions.StatementTooComplex: error fetching next item from iterator

...
spiexceptions.StatementTooComplex: error fetching next item from iterator
spiexceptions.StatementTooComplex: error fetching next item from iterator
spiexceptions.StatementTooComplex: stack depth limit exceeded
HINT:  Increase the configuration parameter "max_stack_depth" (currently 2048kB), after ensuring the platform's stack 
depth limit is adequate.
CONTEXT:  Traceback (most recent call last):
PL/Python function "pyfunc"

This lengthy output is similar to what we get with a recursion in plperl,
so I don't consider this as an issue, but may be we could just check
the length of an error message before concatenation...

Please look at the v2 patch, which contains an addition to regression tests for the master.
If you agree with this approach, I'll make patches for back branches as well...

Best regards,
Alexander

Attachments:

  [text/x-patch] v2-01-fix-plpy_elog.patch (3.9K, ../../5eba3ea5-ae13-aab2-35d6-cd3e58dab08b@gmail.com/3-v2-01-fix-plpy_elog.patch)
  download | inline diff:
diff --git a/src/pl/plpython/expected/plpython_error.out b/src/pl/plpython/expected/plpython_error.out
index 9af7ea7292..33b64a0604 100644
--- a/src/pl/plpython/expected/plpython_error.out
+++ b/src/pl/plpython/expected/plpython_error.out
@@ -445,3 +445,17 @@ PL/Python function "notice_outerfunc"
                 1
 (1 row)
 
+/* When an error logged with an underlying exception, the detail should
+*  contain a detail message from the exception
+*/
+CREATE FUNCTION python_error_detail() RETURNS SETOF text AS $$
+  plan = plpy.prepare("SELECT to_date('DD', 'DD') d")
+  for row in plpy.cursor(plan):
+    yield row['d']
+$$ LANGUAGE plpython3u;
+SELECT python_error_detail();
+ERROR:  error fetching next item from iterator
+DETAIL:  spiexceptions.InvalidDatetimeFormat: invalid value "DD" for "DD"
+Value must be an integer.
+CONTEXT:  Traceback (most recent call last):
+PL/Python function "python_error_detail"
diff --git a/src/pl/plpython/expected/plpython_error_5.out b/src/pl/plpython/expected/plpython_error_5.out
index 7fe864a1a5..9cd0c66c55 100644
--- a/src/pl/plpython/expected/plpython_error_5.out
+++ b/src/pl/plpython/expected/plpython_error_5.out
@@ -445,3 +445,17 @@ PL/Python function "notice_outerfunc"
                 1
 (1 row)
 
+/* When an error logged with an underlying exception, the detail should
+*  contain a detail message from the exception
+*/
+CREATE FUNCTION python_error_detail() RETURNS SETOF text AS $$
+  plan = plpy.prepare("SELECT to_date('DD', 'DD') d")
+  for row in plpy.cursor(plan):
+    yield row['d']
+$$ LANGUAGE plpython3u;
+SELECT python_error_detail();
+ERROR:  error fetching next item from iterator
+DETAIL:  spiexceptions.InvalidDatetimeFormat: invalid value "DD" for "DD"
+Value must be an integer.
+CONTEXT:  Traceback (most recent call last):
+PL/Python function "python_error_detail"
diff --git a/src/pl/plpython/plpy_elog.c b/src/pl/plpython/plpy_elog.c
index 7c627eacfb..c88490bf50 100644
--- a/src/pl/plpython/plpy_elog.c
+++ b/src/pl/plpython/plpy_elog.c
@@ -47,6 +47,7 @@ PLy_elog_impl(int elevel, const char *fmt,...)
 	char	   *tbmsg;
 	int			tb_depth;
 	StringInfoData emsg;
+	StringInfoData detailstr;
 	PyObject   *exc,
 			   *val,
 			   *tb;
@@ -62,6 +63,8 @@ PLy_elog_impl(int elevel, const char *fmt,...)
 	char	   *datatype_name = NULL;
 	char	   *constraint_name = NULL;
 
+	detailstr.data = NULL;
+
 	PyErr_Fetch(&exc, &val, &tb);
 
 	if (exc != NULL)
@@ -103,12 +106,19 @@ PLy_elog_impl(int elevel, const char *fmt,...)
 		}
 		primary = emsg.data;
 
-		/* Since we have a format string, we cannot have a SPI detail. */
-		Assert(detail == NULL);
-
-		/* If there's an exception message, it goes in the detail. */
-		if (xmsg)
+		/*
+		 * If there's an exception message, it goes to the detail,
+		 * prepended to the existing detail message, if any.
+		 */
+		if (detail == NULL)
 			detail = xmsg;
+		else if (xmsg != NULL) {
+			initStringInfo(&detailstr);
+			appendStringInfoString(&detailstr, xmsg);
+			appendStringInfoChar(&detailstr, '\n');
+			appendStringInfoString(&detailstr, detail);
+			detail = detailstr.data;
+		}
 	}
 	else
 	{
@@ -141,6 +151,8 @@ PLy_elog_impl(int elevel, const char *fmt,...)
 	{
 		if (fmt)
 			pfree(emsg.data);
+		if (detailstr.data)
+			pfree(detailstr.data);
 		if (xmsg)
 			pfree(xmsg);
 		if (tbmsg)
diff --git a/src/pl/plpython/sql/plpython_error.sql b/src/pl/plpython/sql/plpython_error.sql
index 11f14ec5a7..554eb350b5 100644
--- a/src/pl/plpython/sql/plpython_error.sql
+++ b/src/pl/plpython/sql/plpython_error.sql
@@ -344,3 +344,14 @@ $$ LANGUAGE plpython3u;
 \set SHOW_CONTEXT always
 
 SELECT notice_outerfunc();
+
+/* When an error logged with an underlying exception, the detail should
+*  contain a detail message from the exception
+*/
+CREATE FUNCTION python_error_detail() RETURNS SETOF text AS $$
+  plan = plpy.prepare("SELECT to_date('DD', 'DD') d")
+  for row in plpy.cursor(plan):
+    yield row['d']
+$$ LANGUAGE plpython3u;
+
+SELECT python_error_detail();


^ permalink  raw  reply  [nested|flat] 15+ messages in thread

* Re: BUG #18070: Assertion failed when processing error from plpy's iterator
@ 2023-09-16 23:50  Michael Paquier <michael@paquier.xyz>
  parent: Alexander Lakhin <exclusion@gmail.com>
  0 siblings, 1 reply; 15+ messages in thread

From: Michael Paquier @ 2023-09-16 23:50 UTC (permalink / raw)
  To: Alexander Lakhin <exclusion@gmail.com>; +Cc: Tom Lane <tgl@sss.pgh.pa.us>; pgsql-bugs@lists.postgresql.org

On Sat, Sep 16, 2023 at 08:00:00PM +0300, Alexander Lakhin wrote:
> This lengthy output is similar to what we get with a recursion in plperl,
> so I don't consider this as an issue, but may be we could just check
> the length of an error message before concatenation...
> 
> Please look at the v2 patch, which contains an addition to regression tests for the master.
> If you agree with this approach, I'll make patches for back branches as well...

+DETAIL:  spiexceptions.InvalidDatetimeFormat: invalid value "DD" for "DD"
+Value must be an integer.

That's the kind of things we've been doing for years in libpq.  So
even if there are no proper sentence terminations, that may be enough
for the user.

+		if (detail == NULL)
 			detail = xmsg;
+		else if (xmsg != NULL) {
+			initStringInfo(&detailstr);
+			appendStringInfoString(&detailstr, xmsg);
+			appendStringInfoChar(&detailstr, '\n');
+			appendStringInfoString(&detailstr, detail);
+			detail = detailstr.data;
+		}

Perhaps it would be slightly cleaner to use a StringInfoData all the
time and rely on the presence of fmt to free the detail string?

Btw, backpatching a change in the error infrastructure does not seem a
good idea to me, as there could be applications that depend on the
existing behaviors?  It looks like we'd better just remove the
assertion in back-branches.
--
Michael

Attachments:

  [application/pgp-signature] signature.asc (832B, ../../ZQY%2FNfv20tt4PBzA@paquier.xyz/2-signature.asc)
  download

^ permalink  raw  reply  [nested|flat] 15+ messages in thread

* Re: BUG #18070: Assertion failed when processing error from plpy's iterator
@ 2023-09-17 00:02  Tom Lane <tgl@sss.pgh.pa.us>
  parent: Michael Paquier <michael@paquier.xyz>
  0 siblings, 1 reply; 15+ messages in thread

From: Tom Lane @ 2023-09-17 00:02 UTC (permalink / raw)
  To: Michael Paquier <michael@paquier.xyz>; +Cc: Alexander Lakhin <exclusion@gmail.com>; pgsql-bugs@lists.postgresql.org

Michael Paquier <michael@paquier.xyz> writes:
> Btw, backpatching a change in the error infrastructure does not seem a
> good idea to me, as there could be applications that depend on the
> existing behaviors?  It looks like we'd better just remove the
> assertion in back-branches.

+1.  Not very sure what we want to change this to in HEAD, but
I wouldn't backpatch a behavioral change here.

			regards, tom lane





^ permalink  raw  reply  [nested|flat] 15+ messages in thread

* Re: BUG #18070: Assertion failed when processing error from plpy's iterator
@ 2023-09-17 01:50  Michael Paquier <michael@paquier.xyz>
  parent: Tom Lane <tgl@sss.pgh.pa.us>
  0 siblings, 1 reply; 15+ messages in thread

From: Michael Paquier @ 2023-09-17 01:50 UTC (permalink / raw)
  To: Tom Lane <tgl@sss.pgh.pa.us>; +Cc: Alexander Lakhin <exclusion@gmail.com>; pgsql-bugs@lists.postgresql.org

On Sat, Sep 16, 2023 at 08:02:03PM -0400, Tom Lane wrote:
> +1.  Not very sure what we want to change this to in HEAD, but
> I wouldn't backpatch a behavioral change here.

Please find attached a proposal of patch for a backpatch, that applies
on HEAD.  The backpatch needs a few tweaks for alternate outputs, of
course, depending on the version of python.

Any thoughts?
--
Michael

Attachments:

  [text/x-diff] v3-01-fix-plpy_elog.patch (2.8K, ../../ZQZbbPA7NC5A0f4i@paquier.xyz/2-v3-01-fix-plpy_elog.patch)
  download | inline diff:
diff --git a/src/pl/plpython/expected/plpython_error.out b/src/pl/plpython/expected/plpython_error.out
index 9af7ea7292..77819cb416 100644
--- a/src/pl/plpython/expected/plpython_error.out
+++ b/src/pl/plpython/expected/plpython_error.out
@@ -445,3 +445,16 @@ PL/Python function "notice_outerfunc"
                 1
 (1 row)
 
+/* test error logged with an underlying exception that includes a detail
+ * string (bug #18070).
+ */
+CREATE FUNCTION python_error_detail() RETURNS SETOF text AS $$
+  plan = plpy.prepare("SELECT to_date('DD', 'DD') d")
+  for row in plpy.cursor(plan):
+    yield row['d']
+$$ LANGUAGE plpython3u;
+SELECT python_error_detail();
+ERROR:  error fetching next item from iterator
+DETAIL:  spiexceptions.InvalidDatetimeFormat: invalid value "DD" for "DD"
+CONTEXT:  Traceback (most recent call last):
+PL/Python function "python_error_detail"
diff --git a/src/pl/plpython/expected/plpython_error_5.out b/src/pl/plpython/expected/plpython_error_5.out
index 7fe864a1a5..b1b4eaa375 100644
--- a/src/pl/plpython/expected/plpython_error_5.out
+++ b/src/pl/plpython/expected/plpython_error_5.out
@@ -445,3 +445,16 @@ PL/Python function "notice_outerfunc"
                 1
 (1 row)
 
+/* test error logged with an underlying exception that includes a detail
+ * string (bug #18070).
+ */
+CREATE FUNCTION python_error_detail() RETURNS SETOF text AS $$
+  plan = plpy.prepare("SELECT to_date('DD', 'DD') d")
+  for row in plpy.cursor(plan):
+    yield row['d']
+$$ LANGUAGE plpython3u;
+SELECT python_error_detail();
+ERROR:  error fetching next item from iterator
+DETAIL:  spiexceptions.InvalidDatetimeFormat: invalid value "DD" for "DD"
+CONTEXT:  Traceback (most recent call last):
+PL/Python function "python_error_detail"
diff --git a/src/pl/plpython/plpy_elog.c b/src/pl/plpython/plpy_elog.c
index 7c627eacfb..70de5ba13d 100644
--- a/src/pl/plpython/plpy_elog.c
+++ b/src/pl/plpython/plpy_elog.c
@@ -103,9 +103,6 @@ PLy_elog_impl(int elevel, const char *fmt,...)
 		}
 		primary = emsg.data;
 
-		/* Since we have a format string, we cannot have a SPI detail. */
-		Assert(detail == NULL);
-
 		/* If there's an exception message, it goes in the detail. */
 		if (xmsg)
 			detail = xmsg;
diff --git a/src/pl/plpython/sql/plpython_error.sql b/src/pl/plpython/sql/plpython_error.sql
index 11f14ec5a7..111f62eb27 100644
--- a/src/pl/plpython/sql/plpython_error.sql
+++ b/src/pl/plpython/sql/plpython_error.sql
@@ -344,3 +344,14 @@ $$ LANGUAGE plpython3u;
 \set SHOW_CONTEXT always
 
 SELECT notice_outerfunc();
+
+/* test error logged with an underlying exception that includes a detail
+ * string (bug #18070).
+ */
+CREATE FUNCTION python_error_detail() RETURNS SETOF text AS $$
+  plan = plpy.prepare("SELECT to_date('DD', 'DD') d")
+  for row in plpy.cursor(plan):
+    yield row['d']
+$$ LANGUAGE plpython3u;
+
+SELECT python_error_detail();

  [application/pgp-signature] signature.asc (832B, ../../ZQZbbPA7NC5A0f4i@paquier.xyz/3-signature.asc)
  download

^ permalink  raw  reply  [nested|flat] 15+ messages in thread

* Re: BUG #18070: Assertion failed when processing error from plpy's iterator
@ 2023-09-17 02:03  Tom Lane <tgl@sss.pgh.pa.us>
  parent: Michael Paquier <michael@paquier.xyz>
  0 siblings, 1 reply; 15+ messages in thread

From: Tom Lane @ 2023-09-17 02:03 UTC (permalink / raw)
  To: Michael Paquier <michael@paquier.xyz>; +Cc: Alexander Lakhin <exclusion@gmail.com>; pgsql-bugs@lists.postgresql.org

Michael Paquier <michael@paquier.xyz> writes:
> Please find attached a proposal of patch for a backpatch, that applies
> on HEAD.  The backpatch needs a few tweaks for alternate outputs, of
> course, depending on the version of python.

Yeah, the alternate output files will be a bit of a pain, but
should be straightforward as long as you're paying attention.

My only suggestion is that

+  plan = plpy.prepare("SELECT to_date('DD', 'DD') d")
+...
+DETAIL:  spiexceptions.InvalidDatetimeFormat: invalid value "DD" for "DD"

seems unnecessarily ambiguous, and so confusing as to whether the error
message is correct.  Let's make the input string be something other
than 'DD' here.

			regards, tom lane





^ permalink  raw  reply  [nested|flat] 15+ messages in thread

* Re: BUG #18070: Assertion failed when processing error from plpy's iterator
@ 2023-09-17 02:06  Michael Paquier <michael@paquier.xyz>
  parent: Tom Lane <tgl@sss.pgh.pa.us>
  0 siblings, 1 reply; 15+ messages in thread

From: Michael Paquier @ 2023-09-17 02:06 UTC (permalink / raw)
  To: Tom Lane <tgl@sss.pgh.pa.us>; +Cc: Alexander Lakhin <exclusion@gmail.com>; pgsql-bugs@lists.postgresql.org

On Sat, Sep 16, 2023 at 10:03:10PM -0400, Tom Lane wrote:
> seems unnecessarily ambiguous, and so confusing as to whether the error
> message is correct.  Let's make the input string be something other
> than 'DD' here.

Yep.  Good point to use a different string for the input.
--
Michael

Attachments:

  [application/pgp-signature] signature.asc (832B, ../../ZQZfM94OJttrx432@paquier.xyz/2-signature.asc)
  download

^ permalink  raw  reply  [nested|flat] 15+ messages in thread

* Re: BUG #18070: Assertion failed when processing error from plpy's iterator
@ 2023-09-17 04:00  Alexander Lakhin <exclusion@gmail.com>
  parent: Michael Paquier <michael@paquier.xyz>
  0 siblings, 1 reply; 15+ messages in thread

From: Alexander Lakhin @ 2023-09-17 04:00 UTC (permalink / raw)
  To: Michael Paquier <michael@paquier.xyz>; Tom Lane <tgl@sss.pgh.pa.us>; +Cc: pgsql-bugs@lists.postgresql.org

17.09.2023 05:06, Michael Paquier wrote:
> On Sat, Sep 16, 2023 at 10:03:10PM -0400, Tom Lane wrote:
>> seems unnecessarily ambiguous, and so confusing as to whether the error
>> message is correct.  Let's make the input string be something other
>> than 'DD' here.
> Yep.  Good point to use a different string for the input.

Thanks for paying attention to it!

I agree with all the changes proposed.

I'm going to be off today, so I could prepare all the patches tomorrow,
or if you finish it, I would be very grateful.

Best regards,
Alexander





^ permalink  raw  reply  [nested|flat] 15+ messages in thread

* Re: BUG #18070: Assertion failed when processing error from plpy's iterator
@ 2023-09-17 04:25  Michael Paquier <michael@paquier.xyz>
  parent: Alexander Lakhin <exclusion@gmail.com>
  0 siblings, 1 reply; 15+ messages in thread

From: Michael Paquier @ 2023-09-17 04:25 UTC (permalink / raw)
  To: Alexander Lakhin <exclusion@gmail.com>; +Cc: Tom Lane <tgl@sss.pgh.pa.us>; pgsql-bugs@lists.postgresql.org

On Sun, Sep 17, 2023 at 07:00:00AM +0300, Alexander Lakhin wrote:
> I'm going to be off today, so I could prepare all the patches tomorrow,
> or if you finish it, I would be very grateful.

Thanks.  It's a long weekend here as well, so I'll be able to do
anything serious only in 48 hours or so (aka being able to check on
the buildfarm).  If you have the room to send patches for the
back-branches until then, that would be super helpful, of course!
--
Michael

Attachments:

  [application/pgp-signature] signature.asc (832B, ../../ZQZ%2FnA%2Fkb2XwNfMO@paquier.xyz/2-signature.asc)
  download

^ permalink  raw  reply  [nested|flat] 15+ messages in thread

* Re: BUG #18070: Assertion failed when processing error from plpy's iterator
@ 2023-09-18 09:00  Alexander Lakhin <exclusion@gmail.com>
  parent: Michael Paquier <michael@paquier.xyz>
  0 siblings, 1 reply; 15+ messages in thread

From: Alexander Lakhin @ 2023-09-18 09:00 UTC (permalink / raw)
  To: Michael Paquier <michael@paquier.xyz>; +Cc: Tom Lane <tgl@sss.pgh.pa.us>; pgsql-bugs@lists.postgresql.org

Hi,

17.09.2023 07:25, Michael Paquier wrote:
> Thanks.  It's a long weekend here as well, so I'll be able to do
> anything serious only in 48 hours or so (aka being able to check on
> the buildfarm).  If you have the room to send patches for the
> back-branches until then, that would be super helpful, of course!

Please look at the patches for backpatching (I think they meet our
agreements) and also the new main patch (which perhaps a step closer to
expectations).

Best regards,
Alexander
diff --git a/src/pl/plpython/expected/plpython_error.out b/src/pl/plpython/expected/plpython_error.out
index 4d615b41cc..94874668ba 100644
--- a/src/pl/plpython/expected/plpython_error.out
+++ b/src/pl/plpython/expected/plpython_error.out
@@ -445,3 +445,16 @@ PL/Python function "notice_outerfunc"
                 1
 (1 row)
 
+/* test error logged with an underlying exception that includes a detail
+ * string (bug #18070).
+ */
+CREATE FUNCTION python_error_detail() RETURNS SETOF text AS $$
+  plan = plpy.prepare("SELECT to_date('xy', 'DD') d")
+  for row in plpy.cursor(plan):
+    yield row['d']
+$$ LANGUAGE plpythonu;
+SELECT python_error_detail();
+ERROR:  error fetching next item from iterator
+DETAIL:  spiexceptions.InvalidDatetimeFormat: invalid value "xy" for "DD"
+CONTEXT:  Traceback (most recent call last):
+PL/Python function "python_error_detail"
diff --git a/src/pl/plpython/expected/plpython_error_0.out b/src/pl/plpython/expected/plpython_error_0.out
index 290902b182..66684d94d8 100644
--- a/src/pl/plpython/expected/plpython_error_0.out
+++ b/src/pl/plpython/expected/plpython_error_0.out
@@ -445,3 +445,16 @@ PL/Python function "notice_outerfunc"
                 1
 (1 row)
 
+/* test error logged with an underlying exception that includes a detail
+ * string (bug #18070).
+ */
+CREATE FUNCTION python_error_detail() RETURNS SETOF text AS $$
+  plan = plpy.prepare("SELECT to_date('xy', 'DD') d")
+  for row in plpy.cursor(plan):
+    yield row['d']
+$$ LANGUAGE plpythonu;
+SELECT python_error_detail();
+ERROR:  error fetching next item from iterator
+DETAIL:  spiexceptions.InvalidDatetimeFormat: invalid value "xy" for "DD"
+CONTEXT:  Traceback (most recent call last):
+PL/Python function "python_error_detail"
diff --git a/src/pl/plpython/expected/plpython_error_5.out b/src/pl/plpython/expected/plpython_error_5.out
index bc66ab5534..0e67b5a575 100644
--- a/src/pl/plpython/expected/plpython_error_5.out
+++ b/src/pl/plpython/expected/plpython_error_5.out
@@ -445,3 +445,16 @@ PL/Python function "notice_outerfunc"
                 1
 (1 row)
 
+/* test error logged with an underlying exception that includes a detail
+ * string (bug #18070).
+ */
+CREATE FUNCTION python_error_detail() RETURNS SETOF text AS $$
+  plan = plpy.prepare("SELECT to_date('xy', 'DD') d")
+  for row in plpy.cursor(plan):
+    yield row['d']
+$$ LANGUAGE plpythonu;
+SELECT python_error_detail();
+ERROR:  error fetching next item from iterator
+DETAIL:  spiexceptions.InvalidDatetimeFormat: invalid value "xy" for "DD"
+CONTEXT:  Traceback (most recent call last):
+PL/Python function "python_error_detail"
diff --git a/src/pl/plpython/plpy_elog.c b/src/pl/plpython/plpy_elog.c
index df5caaba48..c052a24c52 100644
--- a/src/pl/plpython/plpy_elog.c
+++ b/src/pl/plpython/plpy_elog.c
@@ -105,9 +105,6 @@ PLy_elog_impl(int elevel, const char *fmt,...)
 		}
 		primary = emsg.data;
 
-		/* Since we have a format string, we cannot have a SPI detail. */
-		Assert(detail == NULL);
-
 		/* If there's an exception message, it goes in the detail. */
 		if (xmsg)
 			detail = xmsg;
diff --git a/src/pl/plpython/sql/plpython_error.sql b/src/pl/plpython/sql/plpython_error.sql
index d712eb1078..3f835051e7 100644
--- a/src/pl/plpython/sql/plpython_error.sql
+++ b/src/pl/plpython/sql/plpython_error.sql
@@ -344,3 +344,14 @@ $$ LANGUAGE plpythonu;
 \set SHOW_CONTEXT always
 
 SELECT notice_outerfunc();
+
+/* test error logged with an underlying exception that includes a detail
+ * string (bug #18070).
+ */
+CREATE FUNCTION python_error_detail() RETURNS SETOF text AS $$
+  plan = plpy.prepare("SELECT to_date('xy', 'DD') d")
+  for row in plpy.cursor(plan):
+    yield row['d']
+$$ LANGUAGE plpythonu;
+
+SELECT python_error_detail();

diff --git a/src/pl/plpython/expected/plpython_error.out b/src/pl/plpython/expected/plpython_error.out
index 4d615b41cc..94874668ba 100644
--- a/src/pl/plpython/expected/plpython_error.out
+++ b/src/pl/plpython/expected/plpython_error.out
@@ -445,3 +445,16 @@ PL/Python function "notice_outerfunc"
                 1
 (1 row)
 
+/* test error logged with an underlying exception that includes a detail
+ * string (bug #18070).
+ */
+CREATE FUNCTION python_error_detail() RETURNS SETOF text AS $$
+  plan = plpy.prepare("SELECT to_date('xy', 'DD') d")
+  for row in plpy.cursor(plan):
+    yield row['d']
+$$ LANGUAGE plpythonu;
+SELECT python_error_detail();
+ERROR:  error fetching next item from iterator
+DETAIL:  spiexceptions.InvalidDatetimeFormat: invalid value "xy" for "DD"
+CONTEXT:  Traceback (most recent call last):
+PL/Python function "python_error_detail"
diff --git a/src/pl/plpython/expected/plpython_error_5.out b/src/pl/plpython/expected/plpython_error_5.out
index bc66ab5534..0e67b5a575 100644
--- a/src/pl/plpython/expected/plpython_error_5.out
+++ b/src/pl/plpython/expected/plpython_error_5.out
@@ -445,3 +445,16 @@ PL/Python function "notice_outerfunc"
                 1
 (1 row)
 
+/* test error logged with an underlying exception that includes a detail
+ * string (bug #18070).
+ */
+CREATE FUNCTION python_error_detail() RETURNS SETOF text AS $$
+  plan = plpy.prepare("SELECT to_date('xy', 'DD') d")
+  for row in plpy.cursor(plan):
+    yield row['d']
+$$ LANGUAGE plpythonu;
+SELECT python_error_detail();
+ERROR:  error fetching next item from iterator
+DETAIL:  spiexceptions.InvalidDatetimeFormat: invalid value "xy" for "DD"
+CONTEXT:  Traceback (most recent call last):
+PL/Python function "python_error_detail"
diff --git a/src/pl/plpython/plpy_elog.c b/src/pl/plpython/plpy_elog.c
index df5caaba48..c052a24c52 100644
--- a/src/pl/plpython/plpy_elog.c
+++ b/src/pl/plpython/plpy_elog.c
@@ -105,9 +105,6 @@ PLy_elog_impl(int elevel, const char *fmt,...)
 		}
 		primary = emsg.data;
 
-		/* Since we have a format string, we cannot have a SPI detail. */
-		Assert(detail == NULL);
-
 		/* If there's an exception message, it goes in the detail. */
 		if (xmsg)
 			detail = xmsg;
diff --git a/src/pl/plpython/sql/plpython_error.sql b/src/pl/plpython/sql/plpython_error.sql
index d712eb1078..3f835051e7 100644
--- a/src/pl/plpython/sql/plpython_error.sql
+++ b/src/pl/plpython/sql/plpython_error.sql
@@ -344,3 +344,14 @@ $$ LANGUAGE plpythonu;
 \set SHOW_CONTEXT always
 
 SELECT notice_outerfunc();
+
+/* test error logged with an underlying exception that includes a detail
+ * string (bug #18070).
+ */
+CREATE FUNCTION python_error_detail() RETURNS SETOF text AS $$
+  plan = plpy.prepare("SELECT to_date('xy', 'DD') d")
+  for row in plpy.cursor(plan):
+    yield row['d']
+$$ LANGUAGE plpythonu;
+
+SELECT python_error_detail();

diff --git a/src/pl/plpython/expected/plpython_error.out b/src/pl/plpython/expected/plpython_error.out
index 4d615b41cc..94874668ba 100644
--- a/src/pl/plpython/expected/plpython_error.out
+++ b/src/pl/plpython/expected/plpython_error.out
@@ -445,3 +445,16 @@ PL/Python function "notice_outerfunc"
                 1
 (1 row)
 
+/* test error logged with an underlying exception that includes a detail
+ * string (bug #18070).
+ */
+CREATE FUNCTION python_error_detail() RETURNS SETOF text AS $$
+  plan = plpy.prepare("SELECT to_date('xy', 'DD') d")
+  for row in plpy.cursor(plan):
+    yield row['d']
+$$ LANGUAGE plpython3u;
+SELECT python_error_detail();
+ERROR:  error fetching next item from iterator
+DETAIL:  spiexceptions.InvalidDatetimeFormat: invalid value "xy" for "DD"
+CONTEXT:  Traceback (most recent call last):
+PL/Python function "python_error_detail"
diff --git a/src/pl/plpython/expected/plpython_error_5.out b/src/pl/plpython/expected/plpython_error_5.out
index bc66ab5534..0e67b5a575 100644
--- a/src/pl/plpython/expected/plpython_error_5.out
+++ b/src/pl/plpython/expected/plpython_error_5.out
@@ -445,3 +445,16 @@ PL/Python function "notice_outerfunc"
                 1
 (1 row)
 
+/* test error logged with an underlying exception that includes a detail
+ * string (bug #18070).
+ */
+CREATE FUNCTION python_error_detail() RETURNS SETOF text AS $$
+  plan = plpy.prepare("SELECT to_date('xy', 'DD') d")
+  for row in plpy.cursor(plan):
+    yield row['d']
+$$ LANGUAGE plpython3u;
+SELECT python_error_detail();
+ERROR:  error fetching next item from iterator
+DETAIL:  spiexceptions.InvalidDatetimeFormat: invalid value "xy" for "DD"
+CONTEXT:  Traceback (most recent call last):
+PL/Python function "python_error_detail"
diff --git a/src/pl/plpython/plpy_elog.c b/src/pl/plpython/plpy_elog.c
index df5caaba48..c052a24c52 100644
--- a/src/pl/plpython/plpy_elog.c
+++ b/src/pl/plpython/plpy_elog.c
@@ -105,9 +105,6 @@ PLy_elog_impl(int elevel, const char *fmt,...)
 		}
 		primary = emsg.data;
 
-		/* Since we have a format string, we cannot have a SPI detail. */
-		Assert(detail == NULL);
-
 		/* If there's an exception message, it goes in the detail. */
 		if (xmsg)
 			detail = xmsg;
diff --git a/src/pl/plpython/sql/plpython_error.sql b/src/pl/plpython/sql/plpython_error.sql
index d712eb1078..3f835051e7 100644
--- a/src/pl/plpython/sql/plpython_error.sql
+++ b/src/pl/plpython/sql/plpython_error.sql
@@ -344,3 +344,14 @@ $$ LANGUAGE plpython3u;
 \set SHOW_CONTEXT always
 
 SELECT notice_outerfunc();
+
+/* test error logged with an underlying exception that includes a detail
+ * string (bug #18070).
+ */
+CREATE FUNCTION python_error_detail() RETURNS SETOF text AS $$
+  plan = plpy.prepare("SELECT to_date('xy', 'DD') d")
+  for row in plpy.cursor(plan):
+    yield row['d']
+$$ LANGUAGE plpython3u;
+
+SELECT python_error_detail();


Attachments:

  [text/plain] v4-01-fix-plpy_elog.backpatch12- (3.7K, ../../9847bd24-7544-9cb3-b4e0-57d37e4f8ce3@gmail.com/2-v4-01-fix-plpy_elog.backpatch12-)
  download | inline diff:
diff --git a/src/pl/plpython/expected/plpython_error.out b/src/pl/plpython/expected/plpython_error.out
index 4d615b41cc..94874668ba 100644
--- a/src/pl/plpython/expected/plpython_error.out
+++ b/src/pl/plpython/expected/plpython_error.out
@@ -445,3 +445,16 @@ PL/Python function "notice_outerfunc"
                 1
 (1 row)
 
+/* test error logged with an underlying exception that includes a detail
+ * string (bug #18070).
+ */
+CREATE FUNCTION python_error_detail() RETURNS SETOF text AS $$
+  plan = plpy.prepare("SELECT to_date('xy', 'DD') d")
+  for row in plpy.cursor(plan):
+    yield row['d']
+$$ LANGUAGE plpythonu;
+SELECT python_error_detail();
+ERROR:  error fetching next item from iterator
+DETAIL:  spiexceptions.InvalidDatetimeFormat: invalid value "xy" for "DD"
+CONTEXT:  Traceback (most recent call last):
+PL/Python function "python_error_detail"
diff --git a/src/pl/plpython/expected/plpython_error_0.out b/src/pl/plpython/expected/plpython_error_0.out
index 290902b182..66684d94d8 100644
--- a/src/pl/plpython/expected/plpython_error_0.out
+++ b/src/pl/plpython/expected/plpython_error_0.out
@@ -445,3 +445,16 @@ PL/Python function "notice_outerfunc"
                 1
 (1 row)
 
+/* test error logged with an underlying exception that includes a detail
+ * string (bug #18070).
+ */
+CREATE FUNCTION python_error_detail() RETURNS SETOF text AS $$
+  plan = plpy.prepare("SELECT to_date('xy', 'DD') d")
+  for row in plpy.cursor(plan):
+    yield row['d']
+$$ LANGUAGE plpythonu;
+SELECT python_error_detail();
+ERROR:  error fetching next item from iterator
+DETAIL:  spiexceptions.InvalidDatetimeFormat: invalid value "xy" for "DD"
+CONTEXT:  Traceback (most recent call last):
+PL/Python function "python_error_detail"
diff --git a/src/pl/plpython/expected/plpython_error_5.out b/src/pl/plpython/expected/plpython_error_5.out
index bc66ab5534..0e67b5a575 100644
--- a/src/pl/plpython/expected/plpython_error_5.out
+++ b/src/pl/plpython/expected/plpython_error_5.out
@@ -445,3 +445,16 @@ PL/Python function "notice_outerfunc"
                 1
 (1 row)
 
+/* test error logged with an underlying exception that includes a detail
+ * string (bug #18070).
+ */
+CREATE FUNCTION python_error_detail() RETURNS SETOF text AS $$
+  plan = plpy.prepare("SELECT to_date('xy', 'DD') d")
+  for row in plpy.cursor(plan):
+    yield row['d']
+$$ LANGUAGE plpythonu;
+SELECT python_error_detail();
+ERROR:  error fetching next item from iterator
+DETAIL:  spiexceptions.InvalidDatetimeFormat: invalid value "xy" for "DD"
+CONTEXT:  Traceback (most recent call last):
+PL/Python function "python_error_detail"
diff --git a/src/pl/plpython/plpy_elog.c b/src/pl/plpython/plpy_elog.c
index df5caaba48..c052a24c52 100644
--- a/src/pl/plpython/plpy_elog.c
+++ b/src/pl/plpython/plpy_elog.c
@@ -105,9 +105,6 @@ PLy_elog_impl(int elevel, const char *fmt,...)
 		}
 		primary = emsg.data;
 
-		/* Since we have a format string, we cannot have a SPI detail. */
-		Assert(detail == NULL);
-
 		/* If there's an exception message, it goes in the detail. */
 		if (xmsg)
 			detail = xmsg;
diff --git a/src/pl/plpython/sql/plpython_error.sql b/src/pl/plpython/sql/plpython_error.sql
index d712eb1078..3f835051e7 100644
--- a/src/pl/plpython/sql/plpython_error.sql
+++ b/src/pl/plpython/sql/plpython_error.sql
@@ -344,3 +344,14 @@ $$ LANGUAGE plpythonu;
 \set SHOW_CONTEXT always
 
 SELECT notice_outerfunc();
+
+/* test error logged with an underlying exception that includes a detail
+ * string (bug #18070).
+ */
+CREATE FUNCTION python_error_detail() RETURNS SETOF text AS $$
+  plan = plpy.prepare("SELECT to_date('xy', 'DD') d")
+  for row in plpy.cursor(plan):
+    yield row['d']
+$$ LANGUAGE plpythonu;
+
+SELECT python_error_detail();


  [text/plain] v4-01-fix-plpy_elog.backpatch14- (2.8K, ../../9847bd24-7544-9cb3-b4e0-57d37e4f8ce3@gmail.com/3-v4-01-fix-plpy_elog.backpatch14-)
  download | inline diff:
diff --git a/src/pl/plpython/expected/plpython_error.out b/src/pl/plpython/expected/plpython_error.out
index 4d615b41cc..94874668ba 100644
--- a/src/pl/plpython/expected/plpython_error.out
+++ b/src/pl/plpython/expected/plpython_error.out
@@ -445,3 +445,16 @@ PL/Python function "notice_outerfunc"
                 1
 (1 row)
 
+/* test error logged with an underlying exception that includes a detail
+ * string (bug #18070).
+ */
+CREATE FUNCTION python_error_detail() RETURNS SETOF text AS $$
+  plan = plpy.prepare("SELECT to_date('xy', 'DD') d")
+  for row in plpy.cursor(plan):
+    yield row['d']
+$$ LANGUAGE plpythonu;
+SELECT python_error_detail();
+ERROR:  error fetching next item from iterator
+DETAIL:  spiexceptions.InvalidDatetimeFormat: invalid value "xy" for "DD"
+CONTEXT:  Traceback (most recent call last):
+PL/Python function "python_error_detail"
diff --git a/src/pl/plpython/expected/plpython_error_5.out b/src/pl/plpython/expected/plpython_error_5.out
index bc66ab5534..0e67b5a575 100644
--- a/src/pl/plpython/expected/plpython_error_5.out
+++ b/src/pl/plpython/expected/plpython_error_5.out
@@ -445,3 +445,16 @@ PL/Python function "notice_outerfunc"
                 1
 (1 row)
 
+/* test error logged with an underlying exception that includes a detail
+ * string (bug #18070).
+ */
+CREATE FUNCTION python_error_detail() RETURNS SETOF text AS $$
+  plan = plpy.prepare("SELECT to_date('xy', 'DD') d")
+  for row in plpy.cursor(plan):
+    yield row['d']
+$$ LANGUAGE plpythonu;
+SELECT python_error_detail();
+ERROR:  error fetching next item from iterator
+DETAIL:  spiexceptions.InvalidDatetimeFormat: invalid value "xy" for "DD"
+CONTEXT:  Traceback (most recent call last):
+PL/Python function "python_error_detail"
diff --git a/src/pl/plpython/plpy_elog.c b/src/pl/plpython/plpy_elog.c
index df5caaba48..c052a24c52 100644
--- a/src/pl/plpython/plpy_elog.c
+++ b/src/pl/plpython/plpy_elog.c
@@ -105,9 +105,6 @@ PLy_elog_impl(int elevel, const char *fmt,...)
 		}
 		primary = emsg.data;
 
-		/* Since we have a format string, we cannot have a SPI detail. */
-		Assert(detail == NULL);
-
 		/* If there's an exception message, it goes in the detail. */
 		if (xmsg)
 			detail = xmsg;
diff --git a/src/pl/plpython/sql/plpython_error.sql b/src/pl/plpython/sql/plpython_error.sql
index d712eb1078..3f835051e7 100644
--- a/src/pl/plpython/sql/plpython_error.sql
+++ b/src/pl/plpython/sql/plpython_error.sql
@@ -344,3 +344,14 @@ $$ LANGUAGE plpythonu;
 \set SHOW_CONTEXT always
 
 SELECT notice_outerfunc();
+
+/* test error logged with an underlying exception that includes a detail
+ * string (bug #18070).
+ */
+CREATE FUNCTION python_error_detail() RETURNS SETOF text AS $$
+  plan = plpy.prepare("SELECT to_date('xy', 'DD') d")
+  for row in plpy.cursor(plan):
+    yield row['d']
+$$ LANGUAGE plpythonu;
+
+SELECT python_error_detail();


  [text/plain] v4-01-fix-plpy_elog.backpatch16- (2.8K, ../../9847bd24-7544-9cb3-b4e0-57d37e4f8ce3@gmail.com/4-v4-01-fix-plpy_elog.backpatch16-)
  download | inline diff:
diff --git a/src/pl/plpython/expected/plpython_error.out b/src/pl/plpython/expected/plpython_error.out
index 4d615b41cc..94874668ba 100644
--- a/src/pl/plpython/expected/plpython_error.out
+++ b/src/pl/plpython/expected/plpython_error.out
@@ -445,3 +445,16 @@ PL/Python function "notice_outerfunc"
                 1
 (1 row)
 
+/* test error logged with an underlying exception that includes a detail
+ * string (bug #18070).
+ */
+CREATE FUNCTION python_error_detail() RETURNS SETOF text AS $$
+  plan = plpy.prepare("SELECT to_date('xy', 'DD') d")
+  for row in plpy.cursor(plan):
+    yield row['d']
+$$ LANGUAGE plpython3u;
+SELECT python_error_detail();
+ERROR:  error fetching next item from iterator
+DETAIL:  spiexceptions.InvalidDatetimeFormat: invalid value "xy" for "DD"
+CONTEXT:  Traceback (most recent call last):
+PL/Python function "python_error_detail"
diff --git a/src/pl/plpython/expected/plpython_error_5.out b/src/pl/plpython/expected/plpython_error_5.out
index bc66ab5534..0e67b5a575 100644
--- a/src/pl/plpython/expected/plpython_error_5.out
+++ b/src/pl/plpython/expected/plpython_error_5.out
@@ -445,3 +445,16 @@ PL/Python function "notice_outerfunc"
                 1
 (1 row)
 
+/* test error logged with an underlying exception that includes a detail
+ * string (bug #18070).
+ */
+CREATE FUNCTION python_error_detail() RETURNS SETOF text AS $$
+  plan = plpy.prepare("SELECT to_date('xy', 'DD') d")
+  for row in plpy.cursor(plan):
+    yield row['d']
+$$ LANGUAGE plpython3u;
+SELECT python_error_detail();
+ERROR:  error fetching next item from iterator
+DETAIL:  spiexceptions.InvalidDatetimeFormat: invalid value "xy" for "DD"
+CONTEXT:  Traceback (most recent call last):
+PL/Python function "python_error_detail"
diff --git a/src/pl/plpython/plpy_elog.c b/src/pl/plpython/plpy_elog.c
index df5caaba48..c052a24c52 100644
--- a/src/pl/plpython/plpy_elog.c
+++ b/src/pl/plpython/plpy_elog.c
@@ -105,9 +105,6 @@ PLy_elog_impl(int elevel, const char *fmt,...)
 		}
 		primary = emsg.data;
 
-		/* Since we have a format string, we cannot have a SPI detail. */
-		Assert(detail == NULL);
-
 		/* If there's an exception message, it goes in the detail. */
 		if (xmsg)
 			detail = xmsg;
diff --git a/src/pl/plpython/sql/plpython_error.sql b/src/pl/plpython/sql/plpython_error.sql
index d712eb1078..3f835051e7 100644
--- a/src/pl/plpython/sql/plpython_error.sql
+++ b/src/pl/plpython/sql/plpython_error.sql
@@ -344,3 +344,14 @@ $$ LANGUAGE plpython3u;
 \set SHOW_CONTEXT always
 
 SELECT notice_outerfunc();
+
+/* test error logged with an underlying exception that includes a detail
+ * string (bug #18070).
+ */
+CREATE FUNCTION python_error_detail() RETURNS SETOF text AS $$
+  plan = plpy.prepare("SELECT to_date('xy', 'DD') d")
+  for row in plpy.cursor(plan):
+    yield row['d']
+$$ LANGUAGE plpython3u;
+
+SELECT python_error_detail();


  [text/x-patch] v4-01-fix-plpy_elog.patch (3.6K, ../../9847bd24-7544-9cb3-b4e0-57d37e4f8ce3@gmail.com/5-v4-01-fix-plpy_elog.patch)
  download | inline diff:
diff --git a/src/pl/plpython/expected/plpython_error.out b/src/pl/plpython/expected/plpython_error.out
index 9af7ea7292..fd99278766 100644
--- a/src/pl/plpython/expected/plpython_error.out
+++ b/src/pl/plpython/expected/plpython_error.out
@@ -445,3 +445,17 @@ PL/Python function "notice_outerfunc"
                 1
 (1 row)
 
+/* test error logged with an underlying exception that includes a detail
+ * string (bug #18070).
+ */
+CREATE FUNCTION python_error_detail() RETURNS SETOF text AS $$
+  plan = plpy.prepare("SELECT to_date('xy', 'DD') d")
+  for row in plpy.cursor(plan):
+    yield row['d']
+$$ LANGUAGE plpython3u;
+SELECT python_error_detail();
+ERROR:  error fetching next item from iterator
+DETAIL:  spiexceptions.InvalidDatetimeFormat: invalid value "xy" for "DD"
+Value must be an integer.
+CONTEXT:  Traceback (most recent call last):
+PL/Python function "python_error_detail"
diff --git a/src/pl/plpython/expected/plpython_error_5.out b/src/pl/plpython/expected/plpython_error_5.out
index 7fe864a1a5..9b50c058ac 100644
--- a/src/pl/plpython/expected/plpython_error_5.out
+++ b/src/pl/plpython/expected/plpython_error_5.out
@@ -445,3 +445,17 @@ PL/Python function "notice_outerfunc"
                 1
 (1 row)
 
+/* test error logged with an underlying exception that includes a detail
+ * string (bug #18070).
+ */
+CREATE FUNCTION python_error_detail() RETURNS SETOF text AS $$
+  plan = plpy.prepare("SELECT to_date('xy', 'DD') d")
+  for row in plpy.cursor(plan):
+    yield row['d']
+$$ LANGUAGE plpython3u;
+SELECT python_error_detail();
+ERROR:  error fetching next item from iterator
+DETAIL:  spiexceptions.InvalidDatetimeFormat: invalid value "xy" for "DD"
+Value must be an integer.
+CONTEXT:  Traceback (most recent call last):
+PL/Python function "python_error_detail"
diff --git a/src/pl/plpython/plpy_elog.c b/src/pl/plpython/plpy_elog.c
index 7c627eacfb..55d4ad689a 100644
--- a/src/pl/plpython/plpy_elog.c
+++ b/src/pl/plpython/plpy_elog.c
@@ -47,6 +47,7 @@ PLy_elog_impl(int elevel, const char *fmt,...)
 	char	   *tbmsg;
 	int			tb_depth;
 	StringInfoData emsg;
+	StringInfoData edtl;
 	PyObject   *exc,
 			   *val,
 			   *tb;
@@ -103,12 +104,20 @@ PLy_elog_impl(int elevel, const char *fmt,...)
 		}
 		primary = emsg.data;
 
-		/* Since we have a format string, we cannot have a SPI detail. */
-		Assert(detail == NULL);
-
-		/* If there's an exception message, it goes in the detail. */
-		if (xmsg)
-			detail = xmsg;
+		/* 
+		 * The detail composed of a message, concatenated with a detail, if
+		 * any, from an underlying exception.
+		 */
+		initStringInfo(&edtl);
+		if (xmsg != NULL)
+			appendStringInfoString(&edtl, xmsg);
+		if (detail != NULL)
+		{
+			if (edtl.len > 0)
+				appendStringInfoChar(&edtl, '\n');
+			appendStringInfoString(&edtl, detail);
+		}
+		detail = edtl.data;
 	}
 	else
 	{
@@ -140,7 +149,10 @@ PLy_elog_impl(int elevel, const char *fmt,...)
 	PG_FINALLY();
 	{
 		if (fmt)
+		{
 			pfree(emsg.data);
+			pfree(edtl.data);
+		}
 		if (xmsg)
 			pfree(xmsg);
 		if (tbmsg)
diff --git a/src/pl/plpython/sql/plpython_error.sql b/src/pl/plpython/sql/plpython_error.sql
index 11f14ec5a7..9bb1c0b085 100644
--- a/src/pl/plpython/sql/plpython_error.sql
+++ b/src/pl/plpython/sql/plpython_error.sql
@@ -344,3 +344,14 @@ $$ LANGUAGE plpython3u;
 \set SHOW_CONTEXT always
 
 SELECT notice_outerfunc();
+
+/* test error logged with an underlying exception that includes a detail
+ * string (bug #18070).
+ */
+CREATE FUNCTION python_error_detail() RETURNS SETOF text AS $$
+  plan = plpy.prepare("SELECT to_date('xy', 'DD') d")
+  for row in plpy.cursor(plan):
+    yield row['d']
+$$ LANGUAGE plpython3u;
+
+SELECT python_error_detail();


^ permalink  raw  reply  [nested|flat] 15+ messages in thread

* Re: BUG #18070: Assertion failed when processing error from plpy's iterator
@ 2023-09-18 10:13  Michael Paquier <michael@paquier.xyz>
  parent: Alexander Lakhin <exclusion@gmail.com>
  0 siblings, 1 reply; 15+ messages in thread

From: Michael Paquier @ 2023-09-18 10:13 UTC (permalink / raw)
  To: Alexander Lakhin <exclusion@gmail.com>; +Cc: Tom Lane <tgl@sss.pgh.pa.us>; pgsql-bugs@lists.postgresql.org

On Mon, Sep 18, 2023 at 12:00:00PM +0300, Alexander Lakhin wrote:
> Please look at the patches for backpatching (I think they meet our
> agreements) and also the new main patch (which perhaps a step closer to
> expectations).

Thanks for the patch set.  I'll look at the backpatch materials
tomorrow in more details!
--
Michael

Attachments:

  [application/pgp-signature] signature.asc (832B, ../../ZQgi3lnn2O1GL06R@paquier.xyz/2-signature.asc)
  download

^ permalink  raw  reply  [nested|flat] 15+ messages in thread

* Re: BUG #18070: Assertion failed when processing error from plpy's iterator
@ 2023-09-19 00:28  Michael Paquier <michael@paquier.xyz>
  parent: Michael Paquier <michael@paquier.xyz>
  0 siblings, 0 replies; 15+ messages in thread

From: Michael Paquier @ 2023-09-19 00:28 UTC (permalink / raw)
  To: Alexander Lakhin <exclusion@gmail.com>; +Cc: Tom Lane <tgl@sss.pgh.pa.us>; pgsql-bugs@lists.postgresql.org

On Mon, Sep 18, 2023 at 07:13:50PM +0900, Michael Paquier wrote:
> Thanks for the patch set.  I'll look at the backpatch materials
> tomorrow in more details!

Applied and backpatched.

I was wondering for a sec what's the business of the diffs between
plpython_error_5.out and plpython_error.out on 11 and 12, though.  We
make sure that _5.out uses plpython3u as language in the output
generated, but e748e902de has also proved that the buildfarm did not
flinch when the test broke the assumption behind the test diffs.  With
plpython_error_0.out gone in 13~ and out in one year, I am not
planning to stick my nose into this one and spend more time on it. 
Just noted in passing..

The test added by this thread does not matter much, I guess, as the
error string is generated by plpython itself.
--
Michael

Attachments:

  [application/pgp-signature] signature.asc (832B, ../../ZQjrQQzVuUpLu8nN@paquier.xyz/2-signature.asc)
  download

^ permalink  raw  reply  [nested|flat] 15+ messages in thread


end of thread, other threads:[~2023-09-19 00:28 UTC | newest]

Thread overview: 15+ messages (download: mbox mbox.gz follow: Atom feed)
-- links below jump to the message on this page --
2023-08-25 14:00 BUG #18070: Assertion failed when processing error from plpy's iterator PG Bug reporting form <noreply@postgresql.org>
2023-09-15 17:00 ` Alexander Lakhin <exclusion@gmail.com>
2023-09-16 08:27   ` Michael Paquier <michael@paquier.xyz>
2023-09-16 14:34     ` Tom Lane <tgl@sss.pgh.pa.us>
2023-09-16 17:00       ` Alexander Lakhin <exclusion@gmail.com>
2023-09-16 23:50         ` Michael Paquier <michael@paquier.xyz>
2023-09-17 00:02           ` Tom Lane <tgl@sss.pgh.pa.us>
2023-09-17 01:50             ` Michael Paquier <michael@paquier.xyz>
2023-09-17 02:03               ` Tom Lane <tgl@sss.pgh.pa.us>
2023-09-17 02:06                 ` Michael Paquier <michael@paquier.xyz>
2023-09-17 04:00                   ` Alexander Lakhin <exclusion@gmail.com>
2023-09-17 04:25                     ` Michael Paquier <michael@paquier.xyz>
2023-09-18 09:00                       ` Alexander Lakhin <exclusion@gmail.com>
2023-09-18 10:13                         ` Michael Paquier <michael@paquier.xyz>
2023-09-19 00:28                           ` Michael Paquier <michael@paquier.xyz>

This inbox is served by DDX for PostgreSQL; see mirroring instructions
for how to clone and mirror all data and code used for this inbox