Re: BUG #17081: Segmentation fault on _PG_init() in a session_preload_library

In the attachement you will find the source of a database extension that I used to test this.

Extension test_spi_in_preload_session just executes 'select 1' in its _PG_init() function.
Until Postgres version 14beta1 this works fine, but in version 14beta2 the process dies.

To compile:
make
make install

In postgresql.conf set:

log_min_messages = debug3
session_preload_libraries = 'test_spi_in_preload_session'

To test:
Just try to login to Postgres or execute
make installcheck

Regards,
Martin.

The following bug has been logged on the website:

Bug reference:      17081
Logged by:          Martin Butter
Email address:      martin.butter@splendiddata.com
PostgreSQL version: 14beta2
Operating system:   Fedora 33
Description:        

Code used:

#include "postgres.h"
#include "executor/spi.h"
#include "miscadmin.h"
#include "commands/dbcommands.h"
#include "access/xact.h"

#ifdef PG_MODULE_MAGIC
PG_MODULE_MAGIC;
#endif

void _PG_init(void);
/* Module entry point */
void _PG_init(void)
{	char* dbName;	int startedATransaction = 0;	int spiStatus;	ErrorData *edata;
	elog(DEBUG3,	     "_PG_init() in test_spi_in_preload_session.so, MyProcPid=%d,
MyDatabaseId=%d, IsBackgroundWorker=%d",	     MyProcPid, MyDatabaseId, IsBackgroundWorker);
	/*	 * If no database is selected, don't execute the code	 * This may occur for example in a replication target database.	 */	if (!OidIsValid(MyDatabaseId)) {	    elog(DEBUG1, "No database selected so test_spi_in_preload_session will
not execute");	    return;	}
	/*	 * Don't try to execute in a parallel worker	 */	if (IsBackgroundWorker)	{		elog(DEBUG1,		     "test_spi_in_preload_session did not do anything because we are in a
background worker");		return;	}
	if (GetCurrentTransactionIdIfAny() == InvalidTransactionId)	{		/*		 * If we're not in a transaction, start one.		 */		StartTransactionCommand();		startedATransaction = 1;	}
	dbName = get_database_name(MyDatabaseId);	Assert(dbName); // warning: only active if kernel compiled with
--enable-cassert
        spiStatus = SPI_connect();        if (spiStatus != SPI_OK_CONNECT) {            ereport(ERROR,                    ( errmsg("SPI_connect returned %d for database %s",                            spiStatus,                            dbName)));        }

        // if ones gets error in SPI_execute(), the function does not
return, unless protected by a PG_TRY / PG_CATCH        PG_TRY();        {            elog(DEBUG3,                         "test_spi_in_preload_session will execute 'select
1' in database %s",                         dbName);            spiStatus = SPI_execute("select 1", false, 1);            if (spiStatus < 0) {                ereport(ERROR,                        ( errmsg("SPI_execute returned %d for query 'select
1' in database %s",                                spiStatus,                                dbName)));            }            elog(DEBUG3,                 "test_spi_in_preload_session is back from 'select 1' in
database %s",                 dbName);        }        PG_CATCH();        {            AbortCurrentTransaction();            edata = CopyErrorData();            ereport(WARNING,                ( errcode(edata->sqlerrcode),                  errmsg("test_spi_in_preload_session failed to execute 
'select 1' in database %s",                         dbName),                  errhint("original message = %s", edata->message)));        }        PG_END_TRY();
        SPI_finish();
	if (startedATransaction)	{		/*		 * commit the transaction we started		 */		CommitTransactionCommand();	}
}
<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<

Serverlog:

    .    .
2021-07-02 08:43:43.295 CEST [37478] LOG:  database system is ready to
accept connections
2021-07-02 08:43:43.295 CEST [37487] DEBUG:  InitPostgres
2021-07-02 08:43:43.295 CEST [37488] DEBUG:  removing permanent stats file
"pg_stat/global.stat"
2021-07-02 08:43:43.296 CEST [37489] DEBUG:  logical replication launcher
started
2021-07-02 08:43:43.296 CEST [37489] DEBUG:  InitPostgres
2021-07-02 08:43:43.300 CEST [37488] DEBUG:  received inquiry for database
0
2021-07-02 08:43:43.300 CEST [37488] DEBUG:  writing stats file
"pg_stat_tmp/global.stat"
2021-07-02 08:43:51.664 CEST [37478] DEBUG:  forked new backend, pid=37558
socket=9
2021-07-02 08:43:51.665 CEST [37558] DEBUG:  InitPostgres
2021-07-02 08:43:51.677 CEST [37558] DEBUG:  find_in_dynamic_libpath: trying
"/usr/local/postgresql-14beta2/lib/test_spi_in_preload_session"
2021-07-02 08:43:51.677 CEST [37558] DEBUG:  find_in_dynamic_libpath: trying
"/usr/local/postgresql-14beta2/lib/test_spi_in_preload_session.so"
2021-07-02 08:43:51.677 CEST [37558] DEBUG:  _PG_init() in
test_spi_in_preload_session.so, MyProcPid=37558, MyDatabaseId=13977,
IsBackgroundWorker=0
2021-07-02 08:43:51.677 CEST [37558] DEBUG:  test_spi_in_preload_session
will execute 'select 1' in database postgres
2021-07-02 08:43:51.984 CEST [37478] DEBUG:  server process (PID 37558) was
terminated by signal 11: Segmentation fault
2021-07-02 08:43:51.984 CEST [37478] LOG:  server process (PID 37558) was
terminated by signal 11: Segmentation fault
2021-07-02 08:43:51.984 CEST [37478] LOG:  terminating any other active
server processes
2021-07-02 08:43:51.984 CEST [37478] DEBUG:  sending SIGQUIT to process
37489
2021-07-02 08:43:51.984 CEST [37478] DEBUG:  sending SIGQUIT to process
37485
2021-07-02 08:43:51.984 CEST [37478] DEBUG:  sending SIGQUIT to process
37484
2021-07-02 08:43:51.984 CEST [37478] DEBUG:  sending SIGQUIT to process
37486
2021-07-02 08:43:51.984 CEST [37478] DEBUG:  sending SIGQUIT to process
37487
2021-07-02 08:43:51.984 CEST [37478] DEBUG:  sending SIGQUIT to process
37488
2021-07-02 08:43:51.984 CEST [37488] DEBUG:  writing stats file
"pg_stat/global.stat"
2021-07-02 08:43:51.984 CEST [37488] DEBUG:  shmem_exit(-1): 0
before_shmem_exit callbacks to make
2021-07-02 08:43:51.984 CEST [37488] DEBUG:  shmem_exit(-1): 0 on_shmem_exit
callbacks to make
2021-07-02 08:43:51.984 CEST [37488] DEBUG:  proc_exit(-1): 0 callbacks to
make
2021-07-02 08:43:51.985 CEST [37478] LOG:  all server processes terminated;
reinitializing
2021-07-02 08:43:51.985 CEST [37478] DEBUG:  shmem_exit(1): 0
before_shmem_exit callbacks to make
2021-07-02 08:43:51.985 CEST [37478] DEBUG:  shmem_exit(1): 5 on_shmem_exit
callbacks to make
2021-07-02 08:43:51.985 CEST [37478] DEBUG:  cleaning up dynamic shared
memory control segment with ID 2085192430
2021-07-02 08:43:51.997 CEST [37478] DEBUG:  invoking
IpcMemoryCreate(size=148856832)
2021-07-02 08:43:51.997 CEST [37478] DEBUG:  mmap(148897792) with
MAP_HUGETLB failed, huge pages disabled: Cannot allocate memory
2021-07-02 08:43:52.005 CEST [37478] DEBUG:  dynamic shared memory system
will support 674 segments
2021-07-02 08:43:52.005 CEST [37478] DEBUG:  created dynamic shared memory
control segment 289087702 (26976 bytes)
2021-07-02 08:43:52.006 CEST [37574] LOG:  database system was interrupted;
last known up at 2021-07-02 08:43:43 CEST
2021-07-02 08:43:52.006 CEST [37574] DEBUG:  removing all temporary WAL
segments
2021-07-02 08:43:52.174 CEST [37574] DEBUG:  checkpoint record is at
0/439D020
2021-07-02 08:43:52.174 CEST [37574] DEBUG:  redo record is at 0/439D020;
shutdown true
2021-07-02 08:43:52.174 CEST [37574] DEBUG:  next transaction ID: 19078;
next OID: 111557
2021-07-02 08:43:52.174 CEST [37574] DEBUG:  next MultiXactId: 1; next
MultiXactOffset: 0
2021-07-02 08:43:52.174 CEST [37574] DEBUG:  oldest unfrozen transaction ID:
726, in database 1
2021-07-02 08:43:52.174 CEST [37574] DEBUG:  oldest MultiXactId: 1, in
database 1
2021-07-02 08:43:52.174 CEST [37574] DEBUG:  commit timestamp Xid
oldest/newest: 0/0
2021-07-02 08:43:52.174 CEST [37574] DEBUG:  transaction ID wrap limit is
2147484373, limited by database with OID 1
2021-07-02 08:43:52.174 CEST [37574] DEBUG:  MultiXactId wrap limit is
2147483648, limited by database with OID 1
2021-07-02 08:43:52.174 CEST [37574] DEBUG:  starting up replication slots
2021-07-02 08:43:52.174 CEST [37574] DEBUG:  starting up replication origin
progress state
2021-07-02 08:43:52.174 CEST [37574] LOG:  database system was not properly
shut down; automatic recovery in progress
2021-07-02 08:43:52.176 CEST [37574] DEBUG:  resetting unlogged relations:
cleanup 1 init 0
2021-07-02 08:43:52.176 CEST [37574] LOG:  invalid record length at
0/439D098: wanted 24, got 0
2021-07-02 08:43:52.176 CEST [37574] LOG:  redo is not required
2021-07-02 08:43:52.176 CEST [37574] DEBUG:  resetting unlogged relations:
cleanup 0 init 1
2021-07-02 08:43:52.180 CEST [37574] DEBUG:  performing replication slot
checkpoint
2021-07-02 08:43:52.186 CEST [37574] DEBUG:  attempting to remove WAL
segments older than log file 000000000000000000000003
2021-07-02 08:43:52.186 CEST [37574] DEBUG:  MultiXactId wrap limit is
2147483648, limited by database with OID 1
2021-07-02 08:43:52.186 CEST [37574] DEBUG:  MultiXact member stop limit is
now 4294914944 based on MultiXact 1
2021-07-02 08:43:52.187 CEST [37574] DEBUG:  shmem_exit(0): 1
before_shmem_exit callbacks to make
2021-07-02 08:43:52.187 CEST [37574] DEBUG:  shmem_exit(0): 7 on_shmem_exit
callbacks to make
2021-07-02 08:43:52.187 CEST [37574] DEBUG:  proc_exit(0): 2 callbacks to
make
2021-07-02 08:43:52.187 CEST [37574] DEBUG:  exit(0)
2021-07-02 08:43:52.187 CEST [37574] DEBUG:  shmem_exit(-1): 0
before_shmem_exit callbacks to make
2021-07-02 08:43:52.187 CEST [37574] DEBUG:  shmem_exit(-1): 0 on_shmem_exit
callbacks to make
2021-07-02 08:43:52.187 CEST [37574] DEBUG:  proc_exit(-1): 0 callbacks to
make
2021-07-02 08:43:52.188 CEST [37575] DEBUG:  checkpointer updated shared
memory configuration values
2021-07-02 08:43:52.188 CEST [37478] DEBUG:  starting background worker
process "logical replication launcher"
2021-07-02 08:43:52.189 CEST [37578] DEBUG:  autovacuum launcher started
2021-07-02 08:43:52.189 CEST [37478] LOG:  database system is ready to
accept connections
2021-07-02 08:43:52.189 CEST [37578] DEBUG:  InitPostgres
2021-07-02 08:43:52.189 CEST [37580] DEBUG:  logical replication launcher
started
2021-07-02 08:43:52.189 CEST [37580] DEBUG:  InitPostgres
2021-07-02 08:43:52.189 CEST [37579] DEBUG:  received inquiry for database
0
2021-07-02 08:43:52.189 CEST [37579] DEBUG:  writing stats file
"pg_stat_tmp/global.stat"
2021-07-02 08:44:07.209 CEST [37576] DEBUG:  snapshot of 0+0 running
transaction ids (lsn 0/439D148 oldest xid 19078 latest complete 19077 next
xid 19078)
<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<


Remarks:
Until version 14beta1 this worked fine, but in version 14beta2 the
SPI_execute() call fails