Re: BUG #18070: Assertion failed when processing error from plpy's iterator

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