[Bug]: 2.7.0 crashes when executing multiple IMMUTABLE functions (2.6.0 was fine)

[jflambert]

What type of bug is this?

Crash

What subsystems and features are affected?

Command processing

What happened?

Consider the following SQL

CREATE FUNCTION DEFAULT_UUID(TEXT DEFAULT '') RETURNS UUID AS $$
  BEGIN
    RETURN COALESCE($1, '')::UUID;
  EXCEPTION WHEN invalid_text_representation THEN
    RETURN '00000000-0000-0000-0000-000000000000';
  END;
$$ LANGUAGE PLPGSQL IMMUTABLE;

This function handles invalid/incomplete UUIDs and returns a "default one" when the conversion is impossible. We use it a lot when processing data from third-party sources.

It's marked immutable since it is guaranteed to return the same results given the same arguments forever. This normally provides a minor performance boost, and the execution would be inlined if it was SQL instead of PLPGSQL.

Now let's execute the same function twice in a "transaction".

SELECT DEFAULT_UUID(), DEFAULT_UUID();

With timescale 2.6.1, this would return two "default" UUIDs. With 2.7.0, execution dies after 15 seconds with the error:

ERROR: server closed the connection unexpectedly
	This probably means the server terminated abnormally
	before or while processing the request.

The server logs mention a segmentation fault (see below).

Now, recreate the same function but without IMMUTABLE, and Timescale 2.7.0 will happily execute it twice.

TimescaleDB version affected

2.7.0

PostgreSQL version used

13.7 (also tested on 12)

What operating system did you use?

Ubuntu 18.04

What installation method did you use?

Docker

What platform did you run on?

On prem/Self-hosted

Relevant log output and stack trace

LOG:  server process (PID 108) was terminated by signal 11: Segmentation fault
LOG:  terminating any other active server processes
WARNING:  terminating connection because of crash of another server process
DETAIL:  The postmaster has commanded this server process to roll back the current transaction and exit, because another server process exited abnormally and possibly corrupted shared memory.
HINT:  In a moment you should be able to reconnect to the database and repeat your command.
LOG:  all server processes terminated; reinitializing
LOG:  database system was interrupted; last known up at 2022-07-04 14:29:38 UTC
LOG:  database system was not properly shut down; automatic recovery in progress
LOG:  redo starts at 0/19239E8
LOG:  invalid record length at 0/1A166E8: wanted 24, got 0
LOG:  redo done at 0/1A166B0
LOG:  database system is ready to accept connections
LOG:  TimescaleDB background worker launcher connected to shared catalogs

How can we reproduce the bug?

1. Use `timescale/timescaledb:2.7.0-pg13`
2. Create a custom function tagged IMMUTABLE
3. Call it twice in a same transaction
4. Postgres crashes with segmentation fault
5. Repeat with `timescale/timescaledb:2.6.1-pg13`, no errors

[jnidzwetzki]

Hello @jflambert,

Thanks for opening this issue. The problem seems to be related with calling an exception handler and using default parameters in a function. I was also able to reproduce this problem with a slightly simpler function (without using COALESCE). I attached the example function and the stacktrace for further handling of this issue:

test2=# CREATE FUNCTION FUNCTION_HANDLE_EXCEPTION(TEXT DEFAULT '') RETURNS UUID AS $$
 BEGIN
    return $1::UUID;
  EXCEPTION WHEN invalid_text_representation THEN
    RETURN '00000000-0000-0000-0000-000000000000';
  END;
$$ LANGUAGE PLPGSQL IMMUTABLE;
CREATE FUNCTION
test2=# 

# Works
test2=# SELECT DEFAULT_UUID('d482b36a-fc4a-11ec-b939-0242ac120002'), DEFAULT_UUID('d482b36a-fc4a-11ec-b939-0242ac120002');
             default_uuid             |             default_uuid             
--------------------------------------+--------------------------------------
 d482b36a-fc4a-11ec-b939-0242ac120002 | d482b36a-fc4a-11ec-b939-0242ac120002
(1 row)


# Crashes
test2=# SELECT DEFAULT_UUID(), DEFAULT_UUID();

Stacktrace

(gdb) bt
#0  0x00007f42885d9a3d in BaserelInfo_destroy (tb=0x0) at /home/jan/postgresql-sandbox/bin/REL_14_2/include/server/lib/simplehash.h:461
#1  0x00007f42885db422 in timescaledb_planner (parse=0x55b47c3162c8, query_string=0x55b47c3152c0 "SELECT DEFAULT_UUID(), DEFAULT_UUID();", cursor_opts=2048, 
    bound_params=0x0) at /home/jan/timescaledb/src/planner/planner.c:567
#2  0x000055b47b9767dd in planner (parse=0x55b47c3162c8, query_string=0x55b47c3152c0 "SELECT DEFAULT_UUID(), DEFAULT_UUID();", cursorOptions=2048, 
    boundParams=0x0) at planner.c:269
#3  0x000055b47baaf2e1 in pg_plan_query (querytree=0x55b47c3162c8, query_string=0x55b47c3152c0 "SELECT DEFAULT_UUID(), DEFAULT_UUID();", cursorOptions=2048, 
    boundParams=0x0) at postgres.c:847
#4  0x000055b47baaf42b in pg_plan_queries (querytrees=0x55b47c317160, query_string=0x55b47c3152c0 "SELECT DEFAULT_UUID(), DEFAULT_UUID();", 
    cursorOptions=2048, boundParams=0x0) at postgres.c:939
#5  0x000055b47baaf79c in exec_simple_query (query_string=0x55b47c3152c0 "SELECT DEFAULT_UUID(), DEFAULT_UUID();") at postgres.c:1133
#6  0x000055b47bab4126 in PostgresMain (argc=1, argv=0x7ffe489300e0, dbname=0x55b47c344820 "test2", username=0x55b47c344800 "jan") at postgres.c:4486
#7  0x000055b47b9eac6d in BackendRun (port=0x55b47c33d3b0) at postmaster.c:4530
#8  0x000055b47b9ea59f in BackendStartup (port=0x55b47c33d3b0) at postmaster.c:4252
#9  0x000055b47b9e6781 in ServerLoop () at postmaster.c:1745
#10 0x000055b47b9e5fce in PostmasterMain (argc=3, argv=0x55b47c30ea50) at postmaster.c:1417
#11 0x000055b47b8e3cce in main (argc=3, argv=0x55b47c30ea50) at main.c:209

Full Stacktrace

#0  0x00007f42885d9a3d in BaserelInfo_destroy (tb=0x0) at /home/jan/postgresql-sandbox/bin/REL_14_2/include/server/lib/simplehash.h:461
No locals.
#1  0x00007f42885db422 in timescaledb_planner (parse=0x55b47c3162c8, query_string=0x55b47c3152c0 "SELECT DEFAULT_UUID(), DEFAULT_UUID();", cursor_opts=2048, 
    bound_params=0x0) at /home/jan/timescaledb/src/planner/planner.c:567
        context = {rootquery = 0x55b47c3162c8, current_query = 0x55b47c3162c8, root = 0x7ffe4892fa80, num_distributed_tables = 0}
        glob = {type = T_Invalid, boundParams = 0x0, subplans = 0x0, subroots = 0x0, rewindPlanIDs = 0x0, finalrtable = 0x0, finalrowmarks = 0x0, 
          resultRelations = 0x0, appendRelations = 0x0, relationOids = 0x0, invalItems = 0x0, paramExecTypes = 0x0, lastPHId = 0, lastRowMarkId = 0, 
          lastPlanNodeId = 0, transientPlan = false, dependsOnRole = false, parallelModeOK = false, parallelModeNeeded = false, maxParallelHazard = 0 '\000', 
          partition_directory = 0x0}
        root = {type = T_Invalid, parse = 0x0, glob = 0x7ffe4892f930, query_level = 0, parent_root = 0x0, plan_params = 0x0, outer_params = 0x0, 
          simple_rel_array = 0x0, simple_rel_array_size = 0, simple_rte_array = 0x0, append_rel_array = 0x0, all_baserels = 0x0, nullable_baserels = 0x0, 
          join_rel_list = 0x0, join_rel_hash = 0x0, join_rel_level = 0x0, join_cur_level = 0, init_plans = 0x0, cte_plan_ids = 0x0, multiexpr_params = 0x0, 
          eq_classes = 0x0, ec_merging_done = false, canon_pathkeys = 0x0, left_join_clauses = 0x0, right_join_clauses = 0x0, full_join_clauses = 0x0, 
          join_info_list = 0x0, all_result_relids = 0x0, leaf_result_relids = 0x0, append_rel_list = 0x0, row_identity_vars = 0x0, rowMarks = 0x0, 
          placeholder_list = 0x0, fkey_list = 0x0, query_pathkeys = 0x0, group_pathkeys = 0x0, window_pathkeys = 0x0, distinct_pathkeys = 0x0, 
          sort_pathkeys = 0x0, part_schemes = 0x0, initial_rels = 0x0, upper_rels = {0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0}, upper_targets = {0x0, 0x0, 0x0, 0x0, 
            0x0, 0x0, 0x0}, processed_tlist = 0x0, update_colnos = 0x0, grouping_map = 0x0, minmax_aggs = 0x0, planner_cxt = 0x0, total_table_pages = 0, 
          tuple_fraction = 0, limit_tuples = 0, qual_security_level = 0, hasJoinRTEs = false, hasLateralRTEs = false, hasHavingQual = false, 
          hasPseudoConstantQuals = false, hasAlternativeSubPlans = false, hasRecursion = false, agginfos = 0x0, aggtransinfos = 0x0, numOrderedAggs = 0, 
          hasNonPartialAggs = false, hasNonSerialAggs = false, wt_param_id = 0, non_recursive_path = 0x0, curOuterRels = 0x0, curOuterParams = 0x0, 
          isAltSubplan = 0x0, isUsedSubplan = 0x0, join_search_private = 0x0, partColsUpdated = false}
        _save_exception_stack = 0x7ffe4892ff60
        _save_context_stack = 0x0
        _local_sigjmp_buf = {{__jmpbuf = {0, 7976056273883428241, 94233651972720, 0, 0, 0, 7976056274042811793, 8055010582396597649}, __mask_was_saved = 0, 
            __saved_mask = {__val = {526748, 1, 33188, 94233666258832, 16926788502705416448, 72151827704150752, 94233666258832, 0, 0, 0, 94233659196392, 128, 
                94233666086664, 140730116012688, 139923732162811, 12}}}}
        _do_rethrow = false
        stmt = 0x55b47c3e0d38
        lc = 0x0
        reset_fetcher_type = true
        reset_baserel_info = true
        __func__ = "timescaledb_planner"
#2  0x000055b47b9767dd in planner (parse=0x55b47c3162c8, query_string=0x55b47c3152c0 "SELECT DEFAULT_UUID(), DEFAULT_UUID();", cursorOptions=2048, 
    boundParams=0x0) at planner.c:269
        result = 0x191295d90
#3  0x000055b47baaf2e1 in pg_plan_query (querytree=0x55b47c3162c8, query_string=0x55b47c3152c0 "SELECT DEFAULT_UUID(), DEFAULT_UUID();", cursorOptions=2048, 
    boundParams=0x0) at postgres.c:847
        plan = 0xec7baaf212
#4  0x000055b47baaf42b in pg_plan_queries (querytrees=0x55b47c317160, query_string=0x55b47c3152c0 "SELECT DEFAULT_UUID(), DEFAULT_UUID();", 
    cursorOptions=2048, boundParams=0x0) at postgres.c:939
        query = 0x55b47c3162c8
        stmt = 0x55b47c316120
        query_list__state = {l = 0x55b47c317160, i = 0}
        stmt_list = 0x0
        query_list = 0x55b47c317178
#5  0x000055b47baaf79c in exec_simple_query (query_string=0x55b47c3152c0 "SELECT DEFAULT_UUID(), DEFAULT_UUID();") at postgres.c:1133
        snapshot_set = true
        per_parsetree_context = 0x0
        plantree_list = 0x55b47baaeddd <SocketBackend+526>
        parsetree = 0x55b47c316120
        commandTag = CMDTAG_SELECT
        qc = {commandTag = 1217592976, nprocessed = 94233659098021}
        querytree_list = 0x55b47c317160
        portal = 0x7ffe4892fee0
        receiver = 0x55b47bc6b28e <pg_any_to_server+88>
        format = 0
        parsetree_item__state = {l = 0x55b47c316158, i = 0}
        dest = DestRemote
        oldcontext = 0x55b47c39f2d0
        parsetree_list = 0x55b47c316158
        parsetree_item = 0x55b47c316170
        save_log_statement_stats = false
        was_logged = false
        use_implicit_block = false
        msec_str = "\300R1|\264U\000\000&\000\000\000\006\000\000\000\240\376\222H\376\177\000\000Lۍ{&\000\000"
        __func__ = "exec_simple_query"
#6  0x000055b47bab4126 in PostgresMain (argc=1, argv=0x7ffe489300e0, dbname=0x55b47c344820 "test2", username=0x55b47c344800 "jan") at postgres.c:4486
        query_string = 0x55b47c3152c0 "SELECT DEFAULT_UUID(), DEFAULT_UUID();"
        firstchar = 81
        input_message = {data = 0x55b47c3152c0 "SELECT DEFAULT_UUID(), DEFAULT_UUID();", len = 39, maxlen = 1024, cursor = 39}
        local_sigjmp_buf = {{__jmpbuf = {0, 7976056290415277457, 94233651972720, 0, 0, 0, 7976056273952634257, 4189687543954077073}, __mask_was_saved = 1, 
            __saved_mask = {__val = {4194304, 0 <repeats 15 times>}}}}
        send_ready_for_query = false
        idle_in_transaction_timeout_enabled = false
        idle_session_timeout_enabled = false
        __func__ = "PostgresMain"

[jflambert]

thank you for the swift fix, looking forward to 2.7.1