Обсуждение: BUG #17227: segmentation fault with jsonb_to_recordset
The following bug has been logged on the website:
Bug reference: 17227
Logged by: Bernd Dorn
Email address: bernddorn@gmail.com
PostgreSQL version: 14.0
Operating system: docker postgres:14 on osx
Description:
to reproduce :
```
docker run --name pg -p 5432:5432 --rm -e POSTGRES_PASSWORD=pw postgres:14
docker exec -ti pg psql --user postgres
```
run this query:
```
select *
from (
select jsonb_path_query_array(module -> 'lectures', '$[*]') as
lecture
from unnest(
array[$${
"lectures": [
{
"id": "1"
}
]
}$$::jsonb]) as unnested_modules(module)
) as l,
jsonb_to_recordset(l.lecture) as (id text)
limit 1;
```
output in logs:
```
2021-10-13 09:07:58.073 UTC [1] LOG: server process (PID 83) was terminated
by signal 11: Segmentation fault
2021-10-13 09:07:58.073 UTC [1] DETAIL: Failed process was running: select
*
from (
select jsonb_path_query_array(module -> 'lectures', '$[*]') as
lecture
from unnest(
array[$${
"lectures": [
{
"id": "1"
}
]
}$$::jsonb]) as unnested_modules(module)
) as l,
jsonb_to_recordset(l.lecture) as (id text)
limit 1;
2021-10-13 09:07:58.073 UTC [1] LOG: terminating any other active server
processes
2021-10-13 09:07:58.074 UTC [84] FATAL: the database system is in recovery
mode
2021-10-13 09:07:58.076 UTC [1] LOG: all server processes terminated;
reinitializing
2021-10-13 09:07:58.089 UTC [85] LOG: database system was interrupted; last
known up at 2021-10-13 09:07:34 UTC
2021-10-13 09:07:58.180 UTC [85] LOG: database system was not properly shut
down; automatic recovery in progress
2021-10-13 09:07:58.182 UTC [85] LOG: redo starts at 0/16FAB48
2021-10-13 09:07:58.182 UTC [85] LOG: invalid record length at 0/16FAB80:
wanted 24, got 0
2021-10-13 09:07:58.182 UTC [85] LOG: redo done at 0/16FAB48 system usage:
CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s
2021-10-13 09:07:58.192 UTC [1] LOG: database system is ready to accept
connections
```
On 2021-Oct-13, PG Bug reporting form wrote:
> ```
> select *
> from (
> select jsonb_path_query_array(module -> 'lectures', '$[*]') as
> lecture
> from unnest(
> array[$${
> "lectures": [
> {
> "id": "1"
> }
> ]
> }$$::jsonb]) as unnested_modules(module)
> ) as l,
> jsonb_to_recordset(l.lecture) as (id text)
> limit 1;
> ```
Can you provide some sample data that would reproduce the crash?
--
Álvaro Herrera Valdivia, Chile — https://www.EnterpriseDB.com/
"It takes less than 2 seconds to get to 78% complete; that's a good sign.
A few seconds later it's at 90%, but it seems to have stuck there. Did
somebody make percentages logarithmic while I wasn't looking?"
Alvaro Herrera <alvherre@alvh.no-ip.org> writes:
> Can you provide some sample data that would reproduce the crash?
Huh? It's a self-contained example. I'm seeing this back-trace
on HEAD:
#0 pg_detoast_datum (datum=0x40) at fmgr.c:1724
#1 0x00000000008a2c9a in jsonb_path_query_array_internal (fcinfo=0x19767d8,
tz=<optimized out>) at jsonpath_exec.c:463
#2 0x00000000006ab46e in ExecInterpExpr (state=0x19766e8, econtext=0x1976560,
isnull=<optimized out>) at execExprInterp.c:1260
#3 0x00000000006b8c04 in ExecEvalExpr (isNull=0x1991688, econtext=0x1976560,
state=<optimized out>) at ../../../src/include/executor/executor.h:320
#4 ExecEvalFuncArgs (fcinfo=0x1991660, argList=0x198dd78, econtext=0x1976560)
at execSRF.c:846
#5 0x00000000006b8f42 in ExecMakeTableFunctionResult (setexpr=0x1976650,
econtext=0x1976560, argContext=0x1991540, expectedDesc=0x198de28,
randomAccess=false) at execSRF.c:181
#6 0x00000000006cb5ef in FunctionNext (node=node@entry=0x1976348)
at nodeFunctionscan.c:94
#7 0x00000000006b9b91 in ExecScanFetch (
recheckMtd=0x6cb2e0 <FunctionRecheck>, accessMtd=0x6cb2f0 <FunctionNext>,
node=0x1976348) at execScan.c:133
#8 ExecScan (node=0x1976348, accessMtd=0x6cb2f0 <FunctionNext>,
recheckMtd=0x6cb2e0 <FunctionRecheck>) at execScan.c:182
#9 0x00000000006e06d4 in ExecProcNode (node=0x1976348)
at ../../../src/include/executor/executor.h:257
#10 ExecNestLoop (pstate=0x1975060) at nodeNestloop.c:160
regards, tom lane
I wrote:
> Huh? It's a self-contained example. I'm seeing this back-trace
> on HEAD:
Digging deeper, it seems jsonb_path_query_array_internal is being
called with just two arguments:
Breakpoint 1, jsonb_path_query_array_internal (fcinfo=0x2e6a4e8, tz=false)
at jsonpath_exec.c:460
460 Jsonb *jb = PG_GETARG_JSONB_P(0);
(gdb) p *fcinfo
$1 = {flinfo = 0x2e6a490, context = 0x0, resultinfo = 0x0, fncollation = 0,
isnull = false, nargs = 2, args = 0x2e6a508}
It's expecting four arguments, and naturally goes off the deep end
when the last two aren't there. Evidently the planner has failed
to perform default-argument insertion on this particular function
call.
EXPLAIN VERBOSE shows the query plan as
Nested Loop (cost=0.01..2.52 rows=100 width=64)
Output: jsonb_path_query_array((unnested_modules.module -> 'lectures'::text), '$[*]'::jsonpath, '{}'::jsonb, false),
jsonb_to_recordset.id
-> Function Scan on pg_catalog.unnest unnested_modules (cost=0.00..0.01 rows=1 width=32)
Output: unnested_modules.module
Function Call: unnest('{"{\"lectures\": [{\"id\": \"1\"}]}"}'::jsonb[])
-> Function Scan on pg_catalog.jsonb_to_recordset (cost=0.01..1.01 rows=100 width=32)
Output: jsonb_to_recordset.id
Function Call: jsonb_to_recordset(jsonb_path_query_array((unnested_modules.module -> 'lectures'::text),
'$[*]'::jsonpath))
so it looks like we have flattened the "as l" sub-select into the parent
query and missed performing expression pre-processing on the expressions
that were pulled up ... but only in the FunctionScan node. The call
appearing in the output tlist has the default arguments in the right
places.
This works OK in v12, so somebody broke it between v12 and v13.
More to follow ...
regards, tom lane
I wrote:
> This works OK in v12, so somebody broke it between v12 and v13.
Looks like the somebody was me. git bisect pins the blame on
commit 7266d0997dd2a0632da38a594c78e25ff21df67e
Author: Tom Lane <tgl@sss.pgh.pa.us>
Date: Thu Aug 1 18:50:22 2019 -0400
Allow functions-in-FROM to be pulled up if they reduce to constants.
A relevant-looking part of the commit message is
To do this, we need to rearrange when eval_const_expressions()
happens for expressions in function RTEs. I moved it to
inline_set_returning_functions(), which already has to iterate over
every function RTE, and in consequence renamed that function to
preprocess_function_rtes().
Apparently this idea failed to account for subexpressions pulled up
during later processing. Back to the drawing board.
regards, tom lane
I wrote:
> Apparently this idea failed to account for subexpressions pulled up
> during later processing. Back to the drawing board.
After further study of 7266d0997, it seems we could fix this by
the expedient of repeating eval_const_expressions on a function
RTE whenever it contains LATERAL references. The code already
understood that lateral join aliases were trouble, but it didn't
account for the case of subexpressions inserted by subquery
pullup (which'd have to have been lateral refs originally).
The whole thing makes me itch a little bit, because this logic is
assuming that eval_const_expressions is idempotent, something
we can't test very well and (AFAIR) are not assuming anywhere else.
If somebody made some sub-case not idempotent, we'd not notice until
that case got used in a lateral function RTE. That could be a long
time, as evidenced by the fact that this bug went undetected for a
year since v13 release. However, we had that assumption in the code
7266d0997 replaced too, so this isn't adding any real new risk.
I looked briefly at whether the planner's preprocessing steps
could be re-ordered to eliminate the need for sometimes reprocessing
function RTEs. It looks like it'd be a mess though, a conclusion
I think I also reached before committing 7266d0997.
Anyway, unless somebody has a better idea, I'll flesh out the
attached with a test case and push it.
regards, tom lane
diff --git a/src/backend/optimizer/plan/planner.c b/src/backend/optimizer/plan/planner.c
index 1e42d75465..56722616a3 100644
--- a/src/backend/optimizer/plan/planner.c
+++ b/src/backend/optimizer/plan/planner.c
@@ -1085,7 +1085,8 @@ preprocess_expression(PlannerInfo *root, Node *expr, int kind)
/*
* Simplify constant expressions. For function RTEs, this was already
* done by preprocess_function_rtes ... but we have to do it again if the
- * RTE is LATERAL and might have contained join alias variables.
+ * RTE is LATERAL, as it might contain un-simplified subexpressions
+ * inserted by flattening of subqueries or join alias variables.
*
* Note: an essential effect of this is to convert named-argument function
* calls to positional notation and insert the current actual values of
@@ -1099,8 +1100,7 @@ preprocess_expression(PlannerInfo *root, Node *expr, int kind)
* careful to maintain AND/OR flatness --- that is, do not generate a tree
* with AND directly under AND, nor OR directly under OR.
*/
- if (!(kind == EXPRKIND_RTFUNC ||
- (kind == EXPRKIND_RTFUNC_LATERAL && !root->hasJoinRTEs)))
+ if (kind != EXPRKIND_RTFUNC)
expr = eval_const_expressions(root, expr);
/*
I wrote:
> The whole thing makes me itch a little bit, because this logic is
> assuming that eval_const_expressions is idempotent, something
> we can't test very well and (AFAIR) are not assuming anywhere else.
> If somebody made some sub-case not idempotent, we'd not notice until
> that case got used in a lateral function RTE.
It occurred to me that we could test for problems with double
execution of eval_const_expressions by making planner.c deliberately
call it twice in all cases. A quick hack later, I can say that
"make check-world" doesn't reveal any such problem. While that's
hardly conclusive, it's pretty strong evidence, since the code
coverage report shows eval_const_expressions as well covered (and
the lines not reached are mostly returning simplified Const nodes,
so hardly likely to be a problem here).
We could make a persistent check for that by enclosing the extra
calls in something like "#ifdef DOUBLE_EVAL_CONST_EXPRESSIONS"
and setting up some buildfarm member to define that. But since
(AFAIR) we've never actually had such a bug, it seems unlikely
to be worth the trouble.
I'll go ahead with the patch as presented.
regards, tom lane