Server crashes when trying to execute select trace_test()

Question

Server crashes when trying to execute select trace_test()

nkPit opened this issue 4 months ago · 12 comments

Hello!

After building Postgres in the following way:

./configure --enable-tap-tests --enable-debug --enable-cassert && make -j8

And executing the query:

create or replace function nested_trace_test(a int)
	returns int as $$
	begin
	  perform plpgsql_check_pragma('enable:tracer');
	  return a + 1;
	end;
	$$ language plpgsql;

create or replace function trace_test(b int)
	returns int as $$
	declare r int default 0;
	begin
	  for i in 1..b
	  loop
	    r := nested_trace_test(r);
	  end loop;
	  return r;
	end;
	$$ language plpgsql;

select trace_test(3);

The server crashes.

Coredump:

#0  0x00007f6967dde78b in pldbgapi2_func_setup (estate=0x7ffd1eb5c6a0,
    func=0x55aff060ccd8) at src/pldbgapi2.c:831
831		Assert(fcache_plpgsql->magic == FMGR_CACHE_MAGIC);
(gdb) bt
#0  0x00007f6967dde78b in pldbgapi2_func_setup (estate=0x7ffd1eb5c6a0,
    func=0x55aff060ccd8) at src/pldbgapi2.c:831
#1  0x00007f6967e14633 in plpgsql_estate_setup (
    estate=estate@entry=0x7ffd1eb5c6a0, func=func@entry=0x55aff060ccd8,
    rsi=<optimized out>, simple_eval_estate=simple_eval_estate@entry=0x0,
    simple_eval_resowner=simple_eval_resowner@entry=0x0) at pl_exec.c:4126
#2  0x00007f6967e1c6a5 in plpgsql_exec_function (
    func=func@entry=0x55aff060ccd8, fcinfo=fcinfo@entry=0x55aff067b408,
    simple_eval_estate=simple_eval_estate@entry=0x0,
    simple_eval_resowner=simple_eval_resowner@entry=0x0,
    procedure_resowner=procedure_resowner@entry=0x0, atomic=<optimized out>)
    at pl_exec.c:496
#3  0x00007f6967e2674b in plpgsql_call_handler (fcinfo=0x55aff067b408)
    at pl_handler.c:277
#4  0x000055afef18b813 in ExecInterpExpr (state=0x55aff067b328,
    econtext=0x55aff067a468, isnull=<optimized out>) at execExprInterp.c:734
#5  0x00007f6967e15d0c in ExecEvalExpr (isNull=0x7ffd1eb5ca3f,
    econtext=0x55aff067a468, state=<optimized out>)
    at ../../../../src/include/executor/executor.h:336
#6  exec_eval_simple_expr (rettypmod=<optimized out>, rettype=<optimized out>,
    isNull=0x7ffd1eb5ca3f, result=<synthetic pointer>, expr=0x55aff0666228,
    estate=0x7ffd1eb5d080) at pl_exec.c:6224
#7  exec_eval_expr (estate=0x7ffd1eb5d080, expr=0x55aff0666228,
    isNull=0x7ffd1eb5ca3f, rettype=<optimized out>, rettypmod=<optimized out>)
    at pl_exec.c:5705
#8  0x00007f6967e18aea in exec_assign_expr (estate=estate@entry=0x7ffd1eb5d080,
    target=0x55aff0668308, expr=0x55aff0666228) at pl_exec.c:5037
#9  0x00007f6967e19920 in exec_stmt_assign (stmt=0x55aff06661b0, estate=0x7ffd1eb5d080) at pl_exec.c:2156
#10 exec_stmts (estate=0x7ffd1eb5d080, stmts=0x55aff069ac28) at pl_exec.c:2020
#11 0x00007f6967e1cf35 in exec_stmt_fori (estate=0x7ffd1eb5d080, stmt=0x55aff0666108) at pl_exec.c:2785
#12 0x00007f6967e195db in exec_stmts (estate=0x7ffd1eb5d080, stmts=0x55aff06662e8) at pl_exec.c:2052
#13 0x00007f6967e1be7b in exec_stmt_block (estate=0x7ffd1eb5d080, block=0x55aff0666398) at pl_exec.c:1943
#14 0x00007f6967e1bf8d in exec_toplevel_block (estate=estate@entry=0x7ffd1eb5d080, block=0x55aff0666398) at pl_exec.c:1634
#15 0x00007f6967e1c891 in plpgsql_exec_function (func=func@entry=0x55aff060d0e8, fcinfo=fcinfo@entry=0x55aff068d440, simple_eval_estate=simple_eval_estate@entry=0x0, simple_eval_resowner=simple_eval_resowner@entry=0x0, procedure_resowner=procedure_resowner@entry=0x0, atomic=<optimized out>) at pl_exec.c:623
#16 0x00007f6967e2674b in plpgsql_call_handler (fcinfo=0x55aff068d440) at pl_handler.c:277
#17 0x000055afef18b813 in ExecInterpExpr (state=0x55aff068d368, econtext=0x55aff068d090, isnull=<optimized out>) at execExprInterp.c:734
#18 0x000055afef1c4bb9 in ExecEvalExprSwitchContext (isNull=0x7ffd1eb5d3b7, econtext=0x55aff068d090, state=0x55aff068d368) at ../../../src/include/executor/executor.h:355
#19 ExecProject (projInfo=0x55aff068d360) at ../../../src/include/executor/executor.h:389
#20 ExecResult (pstate=<optimized out>) at nodeResult.c:136
#21 0x000055afef19088a in ExecProcNode (node=0x55aff068cf80) at ../../../src/include/executor/executor.h:273
#22 ExecutePlan (execute_once=<optimized out>, dest=0x55aff06915f0, direction=<optimized out>, numberTuples=0, sendTuples=<optimized out>, operation=CMD_SELECT, use_parallel_mode=<optimized out>, planstate=0x55aff068cf80, estate=0x55aff068cd58) at execMain.c:1670
#23 standard_ExecutorRun (queryDesc=0x55aff0660f78, direction=<optimized out>, count=0, execute_once=<optimized out>) at execMain.c:365
#24 0x000055afef35634f in PortalRunSelect (portal=0x55aff05f6a98, forward=<optimized out>, count=0, dest=<optimized out>) at pquery.c:924
#25 0x000055afef357a31 in PortalRun (portal=portal@entry=0x55aff05f6a98, count=count@entry=9223372036854775807, isTopLevel=isTopLevel@entry=true, run_once=run_once@entry=true, dest=dest@entry=0x55aff06915f0, altdest=altdest@entry=0x55aff06915f0, qc=0x7ffd1eb5d650) at pquery.c:768
#26 0x000055afef353904 in exec_simple_query (query_string=0x55aff057d5a8 "select trace_test(3);") at postgres.c:1278
#27 0x000055afef3554a9 in PostgresMain (dbname=<optimized out>, username=<optimized out>) at postgres.c:4701
#28 0x000055afef2bc72f in BackendRun (port=0x55aff05ac430, port=0x55aff05ac430) at postmaster.c:4464
#29 BackendStartup (port=0x55aff05ac430) at postmaster.c:4192
#30 ServerLoop () at postmaster.c:1782
#31 0x000055afef2bd753 in PostmasterMain (argc=argc@entry=3, argv=argv@entry=0x55aff0577bf0) at postmaster.c:1466
#32 0x000055afeefc6651 in main (argc=3, argv=0x55aff0577bf0) at main.c:198

Postgres version:

postgres=# select version();
                                                version
-------------------------------------------------------------------------------------------------------
 PostgreSQL 16.4 on x86_64-pc-linux-gnu, compiled by gcc (Ubuntu 11.4.0-1ubuntu1~22.04) 11.4.0, 64-bit
(1 row)

plpgsql_check version:

postgres=#  \dx plpgsql_check
                      List of installed extensions
     Name      | Version | Schema |             Description
---------------+---------+--------+--------------------------------------
 plpgsql_check | 2.7     | public | extended check for plpgsql functions
(1 row)

commit: be7e77e

Best regards,
Nikita Kalinin
Postgres Professional

Answer 1 · 2024-09-10T06:58:24.000Z

should be fixed by cced0a5

please, check

Answer 2 · 2024-09-10T11:00:03.000Z

Yes. That fixed the problem. Thank you!

Answer 3 · 2024-09-10T11:03:13.000Z

út 10. 9. 2024 v 13:00 odesílatel nkPit ***@***.***> napsal:

Yes. That fixed the problem. Thank you!

Thank you for bug report and check

…

— Reply to this email directly, view it on GitHub <#178 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AAEFO456SXPJNKSJ27EBFATZV3GMTAVCNFSM6AAAAABN35U2IWVHI2DSMVQWIX3LMV43OSLTON2WKQ3PNVWWK3TUHMZDGNBQGM2DKMZXGA> . You are receiving this because you commented.Message ID: ***@***.***>

Answer 4 · 2024-09-16T03:58:45.000Z

I will have to reopen this issue because if we slightly modify the original query as follows:

create or replace function nested_trace_test(a int)
	returns int as $$
	begin
	  perform plpgsql_check_pragma('enable:tracer');

	  return a + 1;	end;
	$$ language plpgsql;

create or replace function trace_test(b int)
	returns int as $$
	declare r int default 0;
	begin
	  for i in 1..b
	  loop
	    r := nested_trace_test(r);
	select trace_test(4);
	  end loop;
	  return r;
	end;
	$$ language plpgsql;

select trace_test(3);

We'll get another server crash:

#0  0x00007fa5f1fd59fc in pthread_kill () from /lib/x86_64-linux-gnu/libc.so.6
#1  0x00007fa5f1f81476 in raise () from /lib/x86_64-linux-gnu/libc.so.6
#2  0x00007fa5f1f677f3 in abort () from /lib/x86_64-linux-gnu/libc.so.6
#3  0x0000562d5e570700 in ExceptionalCondition (conditionName=<optimized out>, fileName=<optimized out>,
    lineNumber=<optimized out>) at assert.c:66
#4  0x00007fa5e6d4a4cc in pldbgapi2_func_setup (estate=0x7ffd1176b840, func=0x562d5f994428) at src/pldbgapi2.c:875
#5  0x00007fa5e6d80553 in plpgsql_estate_setup (estate=estate@entry=0x7ffd1176b840, func=func@entry=0x562d5f994428,
    rsi=<optimized out>, simple_eval_estate=simple_eval_estate@entry=0x0, simple_eval_resowner=simple_eval_resowner@entry=0x0)
    at pl_exec.c:4126
#6  0x00007fa5e6d885c5 in plpgsql_exec_function (func=func@entry=0x562d5f994428, fcinfo=fcinfo@entry=0x562d5fa556e0,
    simple_eval_estate=simple_eval_estate@entry=0x0, simple_eval_resowner=simple_eval_resowner@entry=0x0,
    procedure_resowner=procedure_resowner@entry=0x0, atomic=<optimized out>) at pl_exec.c:496
#7  0x00007fa5e6d92f3b in plpgsql_call_handler (fcinfo=0x562d5fa556e0) at pl_handler.c:276
#8  0x0000562d5e24d57b in ExecInterpExpr (state=0x562d5fa55600, econtext=0x562d5fa55b40, isnull=<optimized out>)
    at execExprInterp.c:746
#9  0x00007fa5e6d81c1c in ExecEvalExpr (isNull=0x7ffd1176bbdf, econtext=0x562d5fa55b40, state=<optimized out>)
    at ../../../../src/include/executor/executor.h:348
#10 exec_eval_simple_expr (rettypmod=<optimized out>, rettype=<optimized out>, isNull=0x7ffd1176bbdf, result=<synthetic pointer>,
    expr=0x562d5fa48528, estate=0x7ffd1176c220) at pl_exec.c:6226
#11 exec_eval_expr (estate=0x7ffd1176c220, expr=0x562d5fa48528, isNull=0x7ffd1176bbdf, rettype=<optimized out>,
    rettypmod=<optimized out>) at pl_exec.c:5707
#12 0x00007fa5e6d84a0a in exec_assign_expr (estate=estate@entry=0x7ffd1176c220, target=0x562d5fa64c40, expr=0x562d5fa48528)
    at pl_exec.c:5039
#13 0x00007fa5e6d85840 in exec_stmt_assign (stmt=0x562d5fa484b0, estate=0x7ffd1176c220) at pl_exec.c:2156
#14 exec_stmts (estate=0x7ffd1176c220, stmts=0x562d5fa485e8) at pl_exec.c:2020
#15 0x00007fa5e6d88e55 in exec_stmt_fori (estate=0x7ffd1176c220, stmt=0x562d5fa48408) at pl_exec.c:2785
#16 0x00007fa5e6d854fb in exec_stmts (estate=0x7ffd1176c220, stmts=0x562d5fa48780) at pl_exec.c:2052
#17 0x00007fa5e6d87d9b in exec_stmt_block (estate=0x7ffd1176c220, block=0x562d5fa48830) at pl_exec.c:1943
#18 0x00007fa5e6d87ead in exec_toplevel_block (estate=estate@entry=0x7ffd1176c220, block=0x562d5fa48830) at pl_exec.c:1634
#19 0x00007fa5e6d887b1 in plpgsql_exec_function (func=func@entry=0x562d5f994838, fcinfo=fcinfo@entry=0x562d5fa5dd78,
    simple_eval_estate=simple_eval_estate@entry=0x0, simple_eval_resowner=simple_eval_resowner@entry=0x0,
    procedure_resowner=procedure_resowner@entry=0x0, atomic=<optimized out>) at pl_exec.c:623
#20 0x00007fa5e6d92f3b in plpgsql_call_handler (fcinfo=0x562d5fa5dd78) at pl_handler.c:276
#21 0x0000562d5e579b60 in fmgr_security_definer (fcinfo=0x562d5fa5dd78) at fmgr.c:747
#22 0x0000562d5e24d57b in ExecInterpExpr (state=0x562d5fa5dc20, econtext=0x562d5fa5d9c8, isnull=<optimized out>)
    at execExprInterp.c:746
#23 0x0000562d5e286d5c in ExecEvalExprSwitchContext (isNull=0x7ffd1176c6e7, econtext=0x562d5fa5d9c8, state=0x562d5fa5dc20)
--Type <RET> for more, q to quit, c to continue without paging--c
    at ../../../src/include/executor/executor.h:367
#24 ExecProject (projInfo=0x562d5fa5dc18) at ../../../src/include/executor/executor.h:401
#25 ExecResult (pstate=<optimized out>) at nodeResult.c:135
#26 0x0000562d5e2520da in ExecProcNode (node=0x562d5fa5d8b8) at ../../../src/include/executor/executor.h:278
#27 ExecutePlan (execute_once=<optimized out>, dest=0x562d5e9219e0 <spi_printtupDR>, direction=<optimized out>, numberTuples=0, sendTuples=<optimized out>, operation=CMD_SELECT, use_parallel_mode=<optimized out>, planstate=0x562d5fa5d8b8, estate=0x562d5fa5d690) at execMain.c:1641
#28 standard_ExecutorRun (queryDesc=0x562d5fa4e500, direction=<optimized out>, count=0, execute_once=<optimized out>) at execMain.c:358
#29 0x0000562d5e29457c in _SPI_pquery (tcount=0, fire_triggers=true, queryDesc=0x562d5fa4e500) at spi.c:2926
#30 _SPI_execute_plan (plan=<optimized out>, options=0x7ffd1176c870, snapshot=<optimized out>, crosscheck_snapshot=<optimized out>, fire_triggers=<optimized out>) at spi.c:2693
#31 0x0000562d5e294c76 in SPI_execute_plan_with_paramlist (plan=0x562d5fa82ea0, params=0x0, read_only=<optimized out>, tcount=0) at spi.c:748
#32 0x00007fa5e6d84617 in exec_stmt_execsql (estate=0x7ffd1176cf30, stmt=0x562d5fa48730) at pl_exec.c:4295
#33 0x00007fa5e6d85893 in exec_stmts (estate=0x7ffd1176cf30, stmts=0x562d5fa485e8) at pl_exec.c:2092
#34 0x00007fa5e6d88e55 in exec_stmt_fori (estate=0x7ffd1176cf30, stmt=0x562d5fa48408) at pl_exec.c:2785
#35 0x00007fa5e6d854fb in exec_stmts (estate=0x7ffd1176cf30, stmts=0x562d5fa48780) at pl_exec.c:2052
#36 0x00007fa5e6d87d9b in exec_stmt_block (estate=0x7ffd1176cf30, block=0x562d5fa48830) at pl_exec.c:1943
#37 0x00007fa5e6d87ead in exec_toplevel_block (estate=estate@entry=0x7ffd1176cf30, block=0x562d5fa48830) at pl_exec.c:1634
#38 0x00007fa5e6d887b1 in plpgsql_exec_function (func=func@entry=0x562d5f994838, fcinfo=fcinfo@entry=0x562d5fa3cb98, simple_eval_estate=simple_eval_estate@entry=0x0, simple_eval_resowner=simple_eval_resowner@entry=0x0, procedure_resowner=procedure_resowner@entry=0x0, atomic=<optimized out>) at pl_exec.c:623
#39 0x00007fa5e6d92f3b in plpgsql_call_handler (fcinfo=0x562d5fa3cb98) at pl_handler.c:276
#40 0x0000562d5e24d57b in ExecInterpExpr (state=0x562d5fa3ca40, econtext=0x562d5fa3c7e8, isnull=<optimized out>) at execExprInterp.c:746
#41 0x0000562d5e286d5c in ExecEvalExprSwitchContext (isNull=0x7ffd1176d267, econtext=0x562d5fa3c7e8, state=0x562d5fa3ca40) at ../../../src/include/executor/executor.h:367
#42 ExecProject (projInfo=0x562d5fa3ca38) at ../../../src/include/executor/executor.h:401
#43 ExecResult (pstate=<optimized out>) at nodeResult.c:135
#44 0x0000562d5e2520da in ExecProcNode (node=0x562d5fa3c6d8) at ../../../src/include/executor/executor.h:278
#45 ExecutePlan (execute_once=<optimized out>, dest=0x562d5fa46f90, direction=<optimized out>, numberTuples=0, sendTuples=<optimized out>, operation=CMD_SELECT, use_parallel_mode=<optimized out>, planstate=0x562d5fa3c6d8, estate=0x562d5fa3c4b0) at execMain.c:1641
#46 standard_ExecutorRun (queryDesc=0x562d5f981c80, direction=<optimized out>, count=0, execute_once=<optimized out>) at execMain.c:358
#47 0x0000562d5e42a61f in PortalRunSelect (portal=0x562d5f9d6c70, forward=<optimized out>, count=0, dest=<optimized out>) at pquery.c:924
#48 0x0000562d5e42bd01 in PortalRun (portal=portal@entry=0x562d5f9d6c70, count=count@entry=9223372036854775807, isTopLevel=isTopLevel@entry=true, run_once=run_once@entry=true, dest=dest@entry=0x562d5fa46f90, altdest=altdest@entry=0x562d5fa46f90, qc=0x7ffd1176d500) at pquery.c:768
#49 0x0000562d5e427b27 in exec_simple_query (query_string=0x562d5f957760 "select trace_test(3);") at postgres.c:1284
#50 0x0000562d5e429730 in PostgresMain (dbname=<optimized out>, username=<optimized out>) at postgres.c:4766
#51 0x0000562d5e423b13 in BackendMain (startup_data=<optimized out>, startup_data_len=<optimized out>) at backend_startup.c:107
#52 0x0000562d5e380bd9 in postmaster_child_launch (child_type=child_type@entry=B_BACKEND, startup_data=startup_data@entry=0x7ffd1176d9bc "", startup_data_len=startup_data_len@entry=4, client_sock=client_sock@entry=0x7ffd1176d9c0) at launch_backend.c:274
#53 0x0000562d5e3842d9 in BackendStartup (client_sock=0x7ffd1176d9c0) at postmaster.c:3415
#54 ServerLoop () at postmaster.c:1648
#55 0x0000562d5e385f37 in PostmasterMain (argc=argc@entry=3, argv=argv@entry=0x562d5f951c70) at postmaster.c:1346
#56 0x0000562d5e0741aa in main (argc=3, argv=0x562d5f951c70) at main.c:197

The Postgres version hasn't changed. Got the crash on this commit: a3681e5.

Answer 5 · 2024-09-16T05:51:34.000Z

now, I decided to disallow this situation. Now, is raised an error, and I don't try to allow late initialization of plpgsql_check

Answer 6 · 2024-09-16T06:05:04.000Z

should be fixed by 4662cc6

Answer 7 · 2024-09-16T06:41:54.000Z

Nope, the server is still crashing.
Coredump:

#0  0x00007f4d6bd4c9fc in pthread_kill () from /lib/x86_64-linux-gnu/libc.so.6
#1  0x00007f4d6bcf8476 in raise () from /lib/x86_64-linux-gnu/libc.so.6
#2  0x00007f4d6bcde7f3 in abort () from /lib/x86_64-linux-gnu/libc.so.6
#3  0x0000556433badea2 in ExceptionalCondition (
    conditionName=conditionName@entry=0x7f4d5d8aa6e0 "fcache_plpgsql->funcid == func->fn_oid", fileName=fileName@entry=0x7f4d5d8aa1a0 "src/pldbgapi2.c",
    lineNumber=lineNumber@entry=850) at assert.c:66
#4  0x00007f4d5d868833 in pldbgapi2_func_setup (estate=<optimized out>,
    func=<optimized out>) at src/pldbgapi2.c:850
#5  0x00007f4d5da1fcfe in plpgsql_estate_setup (estate=estate@entry=0x7ffee8e5f690,
    func=func@entry=0x629000025018, rsi=0x0,
    simple_eval_estate=simple_eval_estate@entry=0x0,
    simple_eval_resowner=simple_eval_resowner@entry=0x0) at pl_exec.c:4126
#6  0x00007f4d5da3e809 in plpgsql_exec_function (func=func@entry=0x629000025018,
    fcinfo=fcinfo@entry=0x62500007bbc8, simple_eval_estate=simple_eval_estate@entry=0x0,
    simple_eval_resowner=simple_eval_resowner@entry=0x0,
    procedure_resowner=procedure_resowner@entry=0x0, atomic=<optimized out>)
    at pl_exec.c:496
#7  0x00007f4d5da68af0 in plpgsql_call_handler (fcinfo=<optimized out>)
    at pl_handler.c:277
#8  0x0000556432f82f2f in ExecInterpExpr (state=0x62500007bae8, econtext=0x62500007c028,
    isnull=0x7ffee8e5fb90) at execExprInterp.c:734
#9  0x00007f4d5da2c5d2 in ExecEvalExpr (isNull=0x7ffee8e5fb90, econtext=0x62500007c028,
    state=<optimized out>) at ../../../../src/include/executor/executor.h:336
#10 exec_eval_simple_expr (estate=estate@entry=0x7ffee8e60060,
    expr=expr@entry=0x62500006ba58, result=result@entry=0x7ffee8e5fb00,
    isNull=isNull@entry=0x7ffee8e5fb90, rettype=rettype@entry=0x7ffee8e5fba0,
    rettypmod=rettypmod@entry=0x7ffee8e5fbb0) at pl_exec.c:6224
#11 0x00007f4d5da2c839 in exec_eval_expr (estate=estate@entry=0x7ffee8e60060,
    expr=expr@entry=0x62500006ba58, isNull=isNull@entry=0x7ffee8e5fb90,
    rettype=rettype@entry=0x7ffee8e5fba0, rettypmod=rettypmod@entry=0x7ffee8e5fbb0)
    at pl_exec.c:5705
#12 0x00007f4d5da38bc9 in exec_assign_expr (estate=<optimized out>,
    target=0x6250000a0348, expr=0x62500006ba58) at pl_exec.c:5037
#13 0x00007f4d5da38fe7 in exec_stmt_assign (estate=estate@entry=0x7ffee8e60060,
    stmt=stmt@entry=0x62500006b9e0) at pl_exec.c:2156
#14 0x00007f4d5da3c70d in exec_stmts (estate=estate@entry=0x7ffee8e60060, stmts=0x625000066098) at pl_exec.c:2020
#15 0x00007f4d5da43c00 in exec_stmt_fori (estate=estate@entry=0x7ffee8e60060, stmt=stmt@entry=0x62500006b938) at pl_exec.c:2785
#16 0x00007f4d5da3c7a5 in exec_stmts (estate=estate@entry=0x7ffee8e60060, stmts=0x62500006bc40) at pl_exec.c:2052
#17 0x00007f4d5da3e2f3 in exec_stmt_block (estate=estate@entry=0x7ffee8e60060, block=block@entry=0x62500006bcf0) at pl_exec.c:1943
#18 0x00007f4d5da3e57d in exec_toplevel_block (estate=estate@entry=0x7ffee8e60060, block=0x62500006bcf0) at pl_exec.c:1634
#19 0x00007f4d5da3f2e5 in plpgsql_exec_function (func=func@entry=0x629000025428, fcinfo=fcinfo@entry=0x625000082900, simple_eval_estate=simple_eval_estate@entry=0x0, simple_eval_resowner=simple_eval_resowner@entry=0x0, procedure_resowner=procedure_resowner@entry=0x0, atomic=<optimized out>) at pl_exec.c:623
#20 0x00007f4d5da68af0 in plpgsql_call_handler (fcinfo=<optimized out>) at pl_handler.c:277
#21 0x0000556433bd48f6 in fmgr_security_definer (fcinfo=<optimized out>) at fmgr.c:718
#22 0x0000556432f82f2f in ExecInterpExpr (state=0x625000082828, econtext=0x625000082550, isnull=0x7ffee8e606f0) at execExprInterp.c:734
#23 0x0000556432f6fb0d in ExecInterpExprStillValid (state=0x625000082828, econtext=0x625000082550, isNull=0x7ffee8e606f0) at execExprInterp.c:1870
#24 0x000055643309d73d in ExecEvalExprSwitchContext (isNull=0x7ffee8e606f0, econtext=0x625000082550, state=0x625000082828) at ../../../src/include/executor/executor.h:355
#25 ExecProject (projInfo=0x625000082820) at ../../../src/include/executor/executor.h:389
#26 ExecResult (pstate=<optimized out>) at nodeResult.c:136
#27 0x0000556432fbf5ae in ExecProcNodeFirst (node=0x625000082440) at execProcnode.c:464
#28 0x0000556432f9d774 in ExecProcNode (node=0x625000082440) at ../../../src/include/executor/executor.h:273
#29 ExecutePlan (estate=estate@entry=0x625000082218, planstate=0x625000082440, use_parallel_mode=<optimized out>, use_parallel_mode@entry=false, operation=operation@entry=CMD_SELECT, sendTuples=true, numberTuples=numberTuples@entry=0, direction=ForwardScanDirection, dest=0x5564342ae440 <spi_printtupDR>, execute_once=true) at execMain.c:1670
#30 0x0000556432f9dd75 in standard_ExecutorRun (queryDesc=0x625000073218, direction=ForwardScanDirection, count=0, execute_once=execute_once@entry=true) at execMain.c:365
#31 0x0000556432f9dfd9 in ExecutorRun (queryDesc=queryDesc@entry=0x625000073218, direction=direction@entry=ForwardScanDirection, count=count@entry=0, execute_once=execute_once@entry=true) at execMain.c:309
#32 0x00005564330db182 in _SPI_pquery (queryDesc=queryDesc@entry=0x625000073218, fire_triggers=fire_triggers@entry=true, tcount=0) at spi.c:2922
#33 0x00005564330e2c74 in _SPI_execute_plan (plan=plan@entry=0x61900003df98, options=options@entry=0x7ffee8e60a20, snapshot=snapshot@entry=0x0, crosscheck_snapshot=crosscheck_snapshot@entry=0x0, fire_triggers=fire_triggers@entry=true) at spi.c:2692
#34 0x00005564330e4a5c in SPI_execute_plan_with_paramlist (plan=0x61900003df98, params=<optimized out>, read_only=read_only@entry=false, tcount=0) at spi.c:749
#35 0x00007f4d5da34b2e in exec_stmt_execsql (estate=estate@entry=0x7ffee8e60f40, stmt=stmt@entry=0x62500006bbf0) at pl_exec.c:4295
#36 0x00007f4d5da3c863 in exec_stmts (estate=estate@entry=0x7ffee8e60f40, stmts=0x625000066098) at pl_exec.c:2092
#37 0x00007f4d5da43c00 in exec_stmt_fori (estate=estate@entry=0x7ffee8e60f40, stmt=stmt@entry=0x62500006b938) at pl_exec.c:2785
#38 0x00007f4d5da3c7a5 in exec_stmts (estate=estate@entry=0x7ffee8e60f40, stmts=0x62500006bc40) at pl_exec.c:2052
#39 0x00007f4d5da3e2f3 in exec_stmt_block (estate=estate@entry=0x7ffee8e60f40, block=block@entry=0x62500006bcf0) at pl_exec.c:1943
#40 0x00007f4d5da3e57d in exec_toplevel_block (estate=estate@entry=0x7ffee8e60f40, block=0x62500006bcf0) at pl_exec.c:1634
#41 0x00007f4d5da3f2e5 in plpgsql_exec_function (func=func@entry=0x629000025428, fcinfo=fcinfo@entry=0x62500005a900, simple_eval_estate=simple_eval_estate@entry=0x0, simple_eval_resowner=simple_eval_resowner@entry=0x0, procedure_resowner=procedure_resowner@entry=0x0, atomic=<optimized out>) at pl_exec.c:623
#42 0x00007f4d5da68af0 in plpgsql_call_handler (fcinfo=<optimized out>) at pl_handler.c:277
#43 0x0000556432f82f2f in ExecInterpExpr (state=0x62500005a828, econtext=0x62500005a550, isnull=0x7ffee8e61380) at execExprInterp.c:734
#44 0x0000556432f6fb0d in ExecInterpExprStillValid (state=0x62500005a828, econtext=0x62500005a550, isNull=0x7ffee8e61380) at execExprInterp.c:1870
#45 0x000055643309d73d in ExecEvalExprSwitchContext (isNull=0x7ffee8e61380, econtext=0x62500005a550, state=0x62500005a828) at ../../../src/include/executor/executor.h:355
#46 ExecProject (projInfo=0x62500005a820) at ../../../src/include/executor/executor.h:389
#47 ExecResult (pstate=<optimized out>) at nodeResult.c:136
#48 0x0000556432fbf5ae in ExecProcNodeFirst (node=0x62500005a440) at execProcnode.c:464
#49 0x0000556432f9d774 in ExecProcNode (node=0x62500005a440) at ../../../src/include/executor/executor.h:273
#50 ExecutePlan (estate=estate@entry=0x62500005a218, planstate=0x62500005a440, use_parallel_mode=<optimized out>, use_parallel_mode@entry=false, operation=operation@entry=CMD_SELECT, sendTuples=true, numberTuples=numberTuples@entry=0, direction=ForwardScanDirection, dest=0x62500006ea90, execute_once=true) at execMain.c:1670
#51 0x0000556432f9dd75 in standard_ExecutorRun (queryDesc=0x61900002db98, direction=ForwardScanDirection, count=0, execute_once=execute_once@entry=true) at execMain.c:365
#52 0x0000556432f9dfd9 in ExecutorRun (queryDesc=queryDesc@entry=0x61900002db98, direction=direction@entry=ForwardScanDirection, count=count@entry=0, execute_once=execute_once@entry=true) at execMain.c:309
#53 0x00005564337358e2 in PortalRunSelect (portal=portal@entry=0x625000025a18, forward=forward@entry=true, count=0, count@entry=9223372036854775807, dest=dest@entry=0x62500006ea90) at pquery.c:924
#54 0x000055643373bb79 in PortalRun (portal=portal@entry=0x625000025a18, count=count@entry=9223372036854775807, isTopLevel=isTopLevel@entry=true, run_once=run_once@entry=true, dest=dest@entry=0x62500006ea90, altdest=altdest@entry=0x62500006ea90, qc=<optimized out>) at pquery.c:768
#55 0x000055643372f8bd in exec_simple_query (query_string=query_string@entry=0x625000005218 "select trace_test(3);") at postgres.c:1278
#56 0x00005564337346d4 in PostgresMain (dbname=dbname@entry=0x62900001b358 "postgres", username=username@entry=0x6250000020f8 "test") at postgres.c:4701
#57 0x00005564334d232c in BackendRun (port=port@entry=0x614000000840) at postmaster.c:4464
#58 0x00005564334daab5 in BackendStartup (port=port@entry=0x614000000840) at postmaster.c:4192
#59 0x00005564334db0b2 in ServerLoop () at postmaster.c:1782
#60 0x00005564334dd6dd in PostmasterMain (argc=argc@entry=3, argv=argv@entry=0x603000000310) at postmaster.c:1466
#61 0x000055643312d5be in main (argc=3, argv=0x603000000310) at main.c:198

Answer 8 · 2024-09-16T07:01:10.000Z

please check c4c0b94

Answer 9 · 2024-09-16T07:09:07.000Z

Yes, that fixed the issue. But is it normal that I get this after reusing the request?

test=# create or replace function nested_trace_test(a int)
        returns int as $$
        begin
          perform plpgsql_check_pragma('enable:tracer');
          return a + 1;
        end;
        $$ language plpgsql;
create or replace function trace_test(b int)
        returns int as $$
        declare r int default 0;
        begin
          for i in 1..b
          loop
            r := nested_trace_test(r);
        select trace_test(4);
          end loop;
          return r;
        end;
        $$ language plpgsql;
select trace_test(3);
CREATE FUNCTION
CREATE FUNCTION
ERROR:  function plpgsql_check_pragma(unknown) does not exist
LINE 1: SELECT plpgsql_check_pragma('enable:tracer')
               ^
HINT:  No function matches the given name and argument types. You might need to add explicit type casts.
QUERY:  SELECT plpgsql_check_pragma('enable:tracer')
CONTEXT:  PL/pgSQL function nested_trace_test(integer) line 3 at PERFORM
PL/pgSQL function trace_test(integer) line 6 at assignment

test=# create or replace function nested_trace_test(a int)
        returns int as $$
        begin
          perform plpgsql_check_pragma('enable:tracer');
          return a + 1;
        end;
        $$ language plpgsql;
create or replace function trace_test(b int)
        returns int as $$
        declare r int default 0;
        begin
          for i in 1..b
          loop
            r := nested_trace_test(r);
        select trace_test(4);
          end loop;
          return r;
        end;
        $$ language plpgsql;
select trace_test(3);

SQL statement "select trace_test(4)"
PL/pgSQL function trace_test(integer) line 7 at SQL statement
SQL statement "select trace_test(4)"
PL/pgSQL function trace_test(integer) line 7 at SQL statement
SQL statement "select trace_test(4)"
PL/pgSQL function trace_test(integer) line 7 at SQL statement
SQL statement "select trace_test(4)"
PL/pgSQL function trace_test(integer) line 7 at SQL statement
SQL statement "select trace_test(4)"
PL/pgSQL function trace_test(integer) line 7 at SQL statement
SQL statement "select trace_test(4)"
PL/pgSQL function trace_test(integer) line 7 at SQL statement
SQL statement "select trace_test(4)"
PL/pgSQL function trace_test(integer) line 7 at SQL statement
SQL statement "select trace_test(4)"
PL/pgSQL function trace_test(integer) line 7 at SQL statement
SQL statement "select trace_test(4)"
PL/pgSQL function trace_test(integer) line 7 at SQL statement
SQL statement "select trace_test(4)"
PL/pgSQL function trace_test(integer) line 7 at SQL statement
SQL statement "select trace_test(4)"
PL/pgSQL function trace_test(integer) line 7 at SQL statement
SQL statement "select trace_test(4)"
PL/pgSQL function trace_test(integer) line 7 at SQL statement
SQL statement "select trace_test(4)"
PL/pgSQL function trace_test(integer) line 7 at SQL statement
...
PL/pgSQL function trace_test(integer) line 7 at SQL statement
SQL statement "select trace_test(4)"
PL/pgSQL function trace_test(integer) line 7 at SQL statement
SQL statement "select trace_test(4)"
PL/pgSQL function trace_test(integer) line 7 at SQL statement
SQL statement "select trace_test(4)"
PL/pgSQL function trace_test(integer) line 7 at SQL statement
SQL statement "select trace_test(4)"
PL/pgSQL function trace_test(integer) line 7 at SQL statement

Answer 10 · 2024-09-16T08:33:28.000Z

po 16. 9. 2024 v 9:09 odesílatel nkPit ***@***.***> napsal:

Yes, that fixed the issue. But is it normal that I get this after reusing the request?

Yes, it can be normal. The problem is in the timing of initialization of plpgsql_check. The extensions are initialized when you first use any function or operator from the extension. The profiler and tracer uses pldbgapi2 - this is a combination of pldbgapi and fmgr api. It is necessary to initialize the pldbgapi before you start a traced or profiled function. pldbgapi2 is initialized when plpgsql_check is initialized. So the first time the pldbgapi2 is not initialized at the correct time, and the select fails, the second select is ok, because pldbgapi2 is already initialized. It is not nice, but it is maximum what is possible because pldbgapi2 uses two really independent API (and nobody expected so one functionality will use both api together). pldbgapi doesn't allow to handle an exceptions. fmgr api allows to handle an exceptions, but on second hand has not detailed informations about plpgsql. I need to ensure so fmgr api is called before pldbgapi. Probably there is a another way how to combinate it, but there is higher risks of memory leaks. ERROR: function plpgsql_check_pragma(unknown) does not exist LINE 1: SELECT plpgsql_check_pragma('enable:tracer') I don't understand to this error message well. Looks so you didn't install plpgsql_check yet, or maybe you have wrong SEARCH_PATH. It is strange, because I get (for your example) (2024-09-16 10:31:35) xx=# select trace_test(3); ERROR: too late initialization of fmgr_plpgsql_cache HINT: Use "load 'plpgsql_check'" before you use plpgsql_check functionality. CONTEXT: PL/pgSQL function trace_test(integer) line 6 at assignment SQL statement "select trace_test(4)" PL/pgSQL function trace_test(integer) line 7 at SQL statement test=# create or replace function nested_trace_test(a int)

…

returns int as $$ begin perform plpgsql_check_pragma('enable:tracer'); return a + 1; end; $$ language plpgsql; create or replace function trace_test(b int) returns int as $$ declare r int default 0; begin for i in 1..b loop r := nested_trace_test(r); select trace_test(4); end loop; return r; end; $$ language plpgsql; select trace_test(3); CREATE FUNCTION CREATE FUNCTION ERROR: function plpgsql_check_pragma(unknown) does not exist LINE 1: SELECT plpgsql_check_pragma('enable:tracer') ^ HINT: No function matches the given name and argument types. You might need to add explicit type casts. QUERY: SELECT plpgsql_check_pragma('enable:tracer') CONTEXT: PL/pgSQL function nested_trace_test(integer) line 3 at PERFORM PL/pgSQL function trace_test(integer) line 6 at assignment test=# create or replace function nested_trace_test(a int) returns int as $$ begin perform plpgsql_check_pragma('enable:tracer'); return a + 1; end; $$ language plpgsql; create or replace function trace_test(b int) returns int as $$ declare r int default 0; begin for i in 1..b loop r := nested_trace_test(r); select trace_test(4); end loop; return r; end; $$ language plpgsql; select trace_test(3); SQL statement "select trace_test(4)" PL/pgSQL function trace_test(integer) line 7 at SQL statement SQL statement "select trace_test(4)" PL/pgSQL function trace_test(integer) line 7 at SQL statement SQL statement "select trace_test(4)" PL/pgSQL function trace_test(integer) line 7 at SQL statement SQL statement "select trace_test(4)" PL/pgSQL function trace_test(integer) line 7 at SQL statement SQL statement "select trace_test(4)" PL/pgSQL function trace_test(integer) line 7 at SQL statement SQL statement "select trace_test(4)" PL/pgSQL function trace_test(integer) line 7 at SQL statement SQL statement "select trace_test(4)" PL/pgSQL function trace_test(integer) line 7 at SQL statement SQL statement "select trace_test(4)" PL/pgSQL function trace_test(integer) line 7 at SQL statement SQL statement "select trace_test(4)" PL/pgSQL function trace_test(integer) line 7 at SQL statement SQL statement "select trace_test(4)" PL/pgSQL function trace_test(integer) line 7 at SQL statement SQL statement "select trace_test(4)" PL/pgSQL function trace_test(integer) line 7 at SQL statement SQL statement "select trace_test(4)" PL/pgSQL function trace_test(integer) line 7 at SQL statement SQL statement "select trace_test(4)" PL/pgSQL function trace_test(integer) line 7 at SQL statement ... PL/pgSQL function trace_test(integer) line 7 at SQL statement SQL statement "select trace_test(4)" PL/pgSQL function trace_test(integer) line 7 at SQL statement SQL statement "select trace_test(4)" PL/pgSQL function trace_test(integer) line 7 at SQL statement SQL statement "select trace_test(4)" PL/pgSQL function trace_test(integer) line 7 at SQL statement SQL statement "select trace_test(4)" PL/pgSQL function trace_test(integer) line 7 at SQL statement — Reply to this email directly, view it on GitHub <#178 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AAEFO432BQ3H3IMJ3BL2O2TZWZ72RAVCNFSM6AAAAABN35U2IWVHI2DSMVQWIX3LMV43OSLTON2WKQ3PNVWWK3TUHMZDGNJSGE2TQNZVGU> . You are receiving this because you commented.Message ID: ***@***.***>

Answer 11 · 2024-09-16T08:43:41.000Z

I don't understand to this error message well. Looks so you didn't install
plpgsql_check yet, or maybe you have wrong SEARCH_PATH.

Yes, that's strange. I just double-checked, and the error is no longer there.
Thanks for the fix! I'm closing the issue.

Answer 12 · 2024-09-16T08:49:06.000Z

po 16. 9. 2024 v 10:44 odesílatel nkPit ***@***.***> napsal:

I don't understand to this error message well. Looks so you didn't install plpgsql_check yet, or maybe you have wrong SEARCH_PATH. Yes, that's strange. I just double-checked, and the error is no longer there. Thanks for the fix! I'm closing the issue.

Thank you for report and fix

…

— Reply to this email directly, view it on GitHub <#178 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AAEFO47HXXSCXVM3CLKU4ELZW2K5HAVCNFSM6AAAAABN35U2IWVHI2DSMVQWIX3LMV43OSLTON2WKQ3PNVWWK3TUHMZDGNJSGMZDMMRTHA> . You are receiving this because you commented.Message ID: ***@***.***>