Segfault during TRUNCATE restart Identity

[hardikm10]

Relevant system information:
OS: [e.g. Ubuntu 16.04, Windows 10 x64, etc]: Docker / timescale/timescaledb:2.4.1-pg13

PostgreSQL version (output of postgres --version): 13.4
TimescaleDB version (output of \dx in psql): 2.4.1
Installation method: [e.g., "using Docker", "apt install", "source"] : "Using Docker"

Describe the bug
Issuing a truncate command causes segfault which is of random occurrence. Sometimes, it happens on the first attempt of TRUNCATE but sometimes calling the same TRUNCATE command again causes the server to crash. The command looks like this:

TRUNCATE TABLE "transaction_records_history","order_records_history","settlement_records_history","records_history"  RESTART IDENTITY;

If you choose to avoid any of the tables from the above command, the segfault doesn't occur and which is why I wasn't able to isolate the segfault with specific tables/instructions.

To Reproduce
SQL Instructions

Expected behavior
The truncate should work as expected

Actual behavior
The truncate causes segfault

Screenshots
If applicable, add screenshots to help explain your problem.

Additional context
Coredump:

Core was generated by `postgres: m0jesnqad4-an: tsdbadmin tsdb 172.20.33.232(53510) TRUNCATE TABLE   '.
Program terminated with signal SIGSEGV, Segmentation fault.
#0  0x00007f25dc186ae3 in process_truncate (args=0x7ffcec35ae90) at /build/timescaledb/src/process_utility.c:931
931	/build/timescaledb/src/process_utility.c: No such file or directory.
(gdb) bt
#0  0x00007f25dc186ae3 in process_truncate (args=0x7ffcec35ae90) at /build/timescaledb/src/process_utility.c:931
#1  0x00007f25dc185cca in process_ddl_command_start (args=0x7ffcec35ae90) at /build/timescaledb/src/process_utility.c:3784
#2  timescaledb_ddl_command_start (pstmt=0x55bd33de5f08, query_string=<optimized out>, context=PROCESS_UTILITY_QUERY, params=0x0, queryEnv=<optimized out>, dest=0x55bd32b5de20 <spi_printtupDR>, completion_tag=0x7ffcec35afb0)
    at /build/timescaledb/src/process_utility.c:4019
#3  0x000055bd32696edf in _SPI_execute_plan (plan=plan@entry=0x55bd33de5a58, paramLI=paramLI@entry=0x0, snapshot=snapshot@entry=0x0, crosscheck_snapshot=crosscheck_snapshot@entry=0x0, read_only=read_only@entry=false,
    fire_triggers=fire_triggers@entry=true, tcount=<optimized out>) at ./build/../src/backend/executor/spi.c:2335
#4  0x000055bd32697794 in SPI_execute_plan_with_paramlist (plan=0x55bd33de5a58, params=0x0, read_only=<optimized out>, tcount=tcount@entry=0) at ./build/../src/backend/executor/spi.c:576
#5  0x00007f25dc04673f in exec_stmt_execsql (estate=estate@entry=0x7ffcec35b530, stmt=stmt@entry=0x55bd33dcd4d8) at ./build/../src/pl/plpgsql/src/pl_exec.c:4234
#6  0x00007f25dc04731b in exec_stmt (estate=estate@entry=0x7ffcec35b530, stmt=0x55bd33dcd4d8) at ./build/../src/pl/plpgsql/src/pl_exec.c:2053
#7  0x00007f25dc04a756 in exec_stmts (estate=0x7ffcec35b530, stmts=0x55bd33dcd528) at ./build/../src/pl/plpgsql/src/pl_exec.c:1944
#8  0x00007f25dc04ab1e in exec_stmt_block (estate=estate@entry=0x7ffcec35b530, block=block@entry=0x55bd33dcd5d8) at ./build/../src/pl/plpgsql/src/pl_exec.c:1885
#9  0x00007f25dc0480fb in exec_stmt (estate=estate@entry=0x7ffcec35b530, stmt=0x55bd33dcd5d8) at ./build/../src/pl/plpgsql/src/pl_exec.c:1977
#10 0x00007f25dc04b309 in plpgsql_exec_trigger (func=func@entry=0x55bd33d0a490, trigdata=0x7ffcec35b920) at ./build/../src/pl/plpgsql/src/pl_exec.c:1027
#11 0x00007f25dc055464 in plpgsql_call_handler (fcinfo=0x7ffcec35b7f0) at ./build/../src/pl/plpgsql/src/pl_handler.c:256
#12 0x000055bd32634963 in ExecCallTriggerFunc (trigdata=trigdata@entry=0x7ffcec35b920, tgindx=tgindx@entry=0, finfo=0x55bd33e53578, instr=0x0, per_tuple_context=0x55bd33dba530) at ./build/../src/backend/commands/trigger.c:2084
#13 0x000055bd3263b5cb in ExecBSTruncateTriggers (estate=estate@entry=0x55bd33dd71b8, relinfo=relinfo@entry=0x55bd33e46958) at ./build/../src/backend/commands/trigger.c:2907
#14 0x000055bd32626bd2 in ExecuteTruncateGuts (explicit_rels=explicit_rels@entry=0x55bd33de9538, relids=<optimized out>, relids@entry=0x55bd33e46d68, relids_logged=relids_logged@entry=0x0, behavior=DROP_RESTRICT,
    restart_seqs=<optimized out>) at ./build/../src/backend/commands/tablecmds.c:1821
#15 0x000055bd3262702d in ExecuteTruncate (stmt=stmt@entry=0x55bd33c8f9f0) at ./build/../src/backend/commands/tablecmds.c:1661
#16 0x000055bd327d90b8 in standard_ProcessUtility (pstmt=0x55bd33c8faa0,
    queryString=0x55bd33c8ed08 "TRUNCATE TABLE \"transaction_records_history\",\"order_records_history\",\"settlement_records_history\",\"records_history\"  RESTART IDENTITY;", context=PROCESS_UTILITY_TOPLEVEL, params=0x0, queryEnv=0x0,
    dest=0x55bd33c8fd60, qc=0x7ffcec35c2f0) at ./build/../src/backend/tcop/utility.c:716
#17 0x00007f25fed9eae2 in loader_process_utility_hook (pstmt=0x55bd33c8faa0,
    query_string=0x55bd33c8ed08 "TRUNCATE TABLE \"transaction_records_history\",\"order_records_history\",\"settlement_records_history\",\"records_history\"  RESTART IDENTITY;", context=<optimized out>, params=0x0,
    queryEnv=<optimized out>, dest=<optimized out>, completion_tag=0x7ffcec35c2f0) at /build/timescaledb/src/loader/loader.c:502
#18 0x00007f25fed945d6 in pgss_ProcessUtility (pstmt=0x55bd33c8faa0,
    queryString=0x55bd33c8ed08 "TRUNCATE TABLE \"transaction_records_history\",\"order_records_history\",\"settlement_records_history\",\"records_history\"  RESTART IDENTITY;", context=PROCESS_UTILITY_TOPLEVEL, params=0x0, queryEnv=0x0,
    dest=0x55bd33c8fd60, qc=0x7ffcec35c2f0) at ./build/../contrib/pg_stat_statements/pg_stat_statements.c:1156
--Type <RET> for more, q to quit, c to continue without paging--
#19 0x00007f25dc1c28cd in ?? () from /usr/lib/postgresql/13/lib/plugins/pgextwlist.so
#20 0x00007f25dc185b73 in prev_ProcessUtility (args=<optimized out>) at /build/timescaledb/src/process_utility.c:89
#21 0x00007f25dc186be9 in process_truncate (args=0x7ffcec35bfd0) at /build/timescaledb/src/process_utility.c:1027
#22 0x00007f25dc185cca in process_ddl_command_start (args=0x7ffcec35bfd0) at /build/timescaledb/src/process_utility.c:3784
#23 timescaledb_ddl_command_start (pstmt=0x55bd33c8faa0, query_string=<optimized out>, context=PROCESS_UTILITY_TOPLEVEL, params=0x0, queryEnv=<optimized out>, dest=0x55bd33c8fd60, completion_tag=0x7ffcec35c2f0)
    at /build/timescaledb/src/process_utility.c:4019
#24 0x000055bd327d741c in PortalRunUtility (portal=portal@entry=0x55bd33d3d688, pstmt=pstmt@entry=0x55bd33c8faa0, isTopLevel=isTopLevel@entry=true, setHoldSnapshot=setHoldSnapshot@entry=false, dest=0x55bd33c8fd60, qc=0x7ffcec35c2f0)
    at ./build/../src/backend/tcop/pquery.c:1145
#25 0x000055bd327d7540 in PortalRunMulti (portal=portal@entry=0x55bd33d3d688, isTopLevel=isTopLevel@entry=true, setHoldSnapshot=setHoldSnapshot@entry=false, dest=dest@entry=0x55bd33c8fd60, altdest=altdest@entry=0x55bd33c8fd60,
    qc=qc@entry=0x7ffcec35c2f0) at ./build/../src/backend/tcop/pquery.c:1301
#26 0x000055bd327d79b8 in PortalRun (portal=0x55bd33d3d688, count=9223372036854775807, isTopLevel=<optimized out>, run_once=<optimized out>, dest=0x55bd33c8fd60, altdest=0x55bd33c8fd60, qc=0x7ffcec35c2f0)
    at ./build/../src/backend/tcop/pquery.c:786
#27 0x000055bd327d3595 in exec_simple_query (query_string=<optimized out>) at ./build/../src/backend/tcop/postgres.c:1239
#28 0x000055bd327d5143 in PostgresMain (argc=<optimized out>, argv=<optimized out>, dbname=<optimized out>, username=<optimized out>) at ./build/../src/backend/tcop/postgres.c:4339
#29 0x000055bd32754bcd in BackendRun (port=0x55bd33cd9a90, port=0x55bd33cd9a90) at ./build/../src/backend/postmaster/postmaster.c:4526
#30 BackendStartup (port=0x55bd33cd9a90) at ./build/../src/backend/postmaster/postmaster.c:4210
#31 ServerLoop () at ./build/../src/backend/postmaster/postmaster.c:1739
#32 0x000055bd32755b41 in PostmasterMain (argc=17, argv=<optimized out>) at ./build/../src/backend/postmaster/postmaster.c:1412
#33 0x000055bd3249ff4f in main (argc=17, argv=0x55bd33c87c60) at ./build/../src/backend/main/main.c:210

[fabriziomello]

I had a quick look and the segfault happen when we have a trigger for truncate and then execute the truncate twice in the same session.

I've created a minimal reproducible test case as following:

CREATE EXTENSION timescaledb;
CREATE TABLE foo(id BIGSERIAL PRIMARY KEY);
CREATE TABLE bar(id BIGSERIAL PRIMARY KEY);

CREATE OR REPLACE FUNCTION truncate_foo()
RETURNS trigger LANGUAGE plpgsql
AS $$
BEGIN
  TRUNCATE foo;
  RETURN NEW;
END;
$$;

CREATE TRIGGER truncate_foo
  BEFORE TRUNCATE ON bar
  FOR EACH STATEMENT EXECUTE FUNCTION truncate_foo();

TRUNCATE bar;
TRUNCATE bar; -- the second call raise the segfault

[hardikm10]

Thanks, @fabriziomello!

[mkindahl]

Adding a printout of information while running the the test reveals this:

mats=# TRUNCATE TABLE bar;
NOTICE:  /home/mats/repos/timescaledb-2.0/src/process_utility.c:920: CurrentMemoryContext=0x5571dac53640 (PortalContext)
NOTICE:  /home/mats/repos/timescaledb-2.0/src/process_utility.c:927: stmt->relations={length=1, elements=0x5571dab1f840}
NOTICE:  /home/mats/repos/timescaledb-2.0/src/process_utility.c:1032: stmt->relations={length=1, elements=0x5571dac53890}
NOTICE:  /home/mats/repos/timescaledb-2.0/src/process_utility.c:920: CurrentMemoryContext=0x5571dac63d90 (SPI Exec)
NOTICE:  /home/mats/repos/timescaledb-2.0/src/process_utility.c:927: stmt->relations={length=1, elements=0x5571dac391f8}
NOTICE:  /home/mats/repos/timescaledb-2.0/src/process_utility.c:1032: stmt->relations={length=1, elements=0x5571dac643d0}
TRUNCATE TABLE
mats=# TRUNCATE TABLE bar;
NOTICE:  /home/mats/repos/timescaledb-2.0/src/process_utility.c:920: CurrentMemoryContext=0x5571dac3b710 (PortalContext)
NOTICE:  /home/mats/repos/timescaledb-2.0/src/process_utility.c:927: stmt->relations={length=1, elements=0x5571dab1f840}
NOTICE:  /home/mats/repos/timescaledb-2.0/src/process_utility.c:1032: stmt->relations={length=1, elements=0x5571dac3b960}
NOTICE:  /home/mats/repos/timescaledb-2.0/src/process_utility.c:920: CurrentMemoryContext=0x5571dac65da0 (SPI Exec)
NOTICE:  /home/mats/repos/timescaledb-2.0/src/process_utility.c:927: stmt->relations={length=2139062143, elements=0x7f7f7f7f7f7f7f7f}
server closed the connection unexpectedly
	This probably means the server terminated abnormally
	before or while processing the request.
The connection to the server was lost. Attempting reset: Failed.

This looks like the smoking gun:

1. When executing the TRUNCATE TABLE statement, PostgreSQL create a TruncateStmt with elements set to the list of tables to truncate. This is allocated in the PortalContext.
2. This is then passed to the TimescaleDB hook, which then eventually goes into the process_truncate function.
3. The process_truncate function iterates over the list stmt->relations of relations and construct a new list of relations without the hypertables. The elements of the list is allocated in the current memory context, which here is PortalContext.
4. The pruned list is assigned to stmt->relations, which then calls standard_ProcessUtility to truncate the non-hypertables.
5. This result in a call of the trigger function, which will eventually call plpgsql_call_handler, which will set up a new, temporary SPI Exec context.
6. The plpgsql_call_handler will compile the function and save the compiled function in a hash table. (This seems to include the list of relations in the TruncateStmt, but it is slightly unclear. It would however explain the segfault.). Memory for this is allocated in TopMemoryContext.
7. It will then call the function block, which recursively leads to a call of process_truncate again.
8. The process_truncate function iterates over the list stmt->relations of relations (again) and construct a new list of relations without the hypertables. The elements of the list is allocated in the current memory context, which here is SPI Exec context.
9. The pruned list is then assigned to stmt->elements, which is in the compiled TruncateStmt inside the compiled function.
10. When unwinding the stack, the SPI Exec context is destroyed, leaving the list of bad pointers in the TruncateStmt in the compiled function.
11. On a second call of the TRUNCATE TABLE, it will find a compiled function, but with pointer to a dropped memory context.