From: Alexander Lakhin <exclusion@gmail.com>
To: Tom Lane <tgl@sss.pgh.pa.us>
To: Michael Paquier <michael@paquier.xyz>
Cc: pgsql-bugs@lists.postgresql.org
Subject: Re: BUG #18070: Assertion failed when processing error from plpy's iterator
Date: Sat, 16 Sep 2023 20:00:00 +0300
Message-ID: <5eba3ea5-ae13-aab2-35d6-cd3e58dab08b@gmail.com> (raw)
In-Reply-To: <3920993.1694874885@sss.pgh.pa.us>
References: <18070-ab9c171cbf4ebb0f@postgresql.org>
<9fa9c154-d084-07de-8224-aab7fc8a119e@gmail.com>
<ZQVm8KponTxqj8G3@paquier.xyz>
<3920993.1694874885@sss.pgh.pa.us>
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.outindex 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.outindex 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.cindex 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.sqlindex 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();
Reply instructions:
You may reply publicly to this message via plain-text email
using any one of the following methods:
* Reply to all the recipients using the --to and --cc options:
reply via email
To: pgsql-bugs@postgresql.org
Cc: exclusion@gmail.com, tgl@sss.pgh.pa.us, michael@paquier.xyz, pgsql-bugs@lists.postgresql.org
Subject: Re: BUG #18070: Assertion failed when processing error from plpy's iterator
In-Reply-To: <5eba3ea5-ae13-aab2-35d6-cd3e58dab08b@gmail.com>
* Save the following mbox file, import it into your mail client,
and reply-to-all from there: mbox
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