Обсуждение: Re: BUG #17081: Segmentation fault on _PG_init() in a session_preload_library
Re: BUG #17081: Segmentation fault on _PG_init() in a session_preload_library
От
Martin Butter
Дата:
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.
On 02/07/2021 09:10, PG Bug reporting form wrote:
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
--
Martin Butter
Developer
Splendid Data Nederland B.V.
Binnenhof 62A
1412 LC NAARDEN
T: +31 (0)85 773 19 99
M: +31 (0)6 226 946 62
E: martin.butter@splendiddata.com
http://www.splendiddata.com/
Developer
Splendid Data Nederland B.V.
Binnenhof 62A
1412 LC NAARDEN
T: +31 (0)85 773 19 99
M: +31 (0)6 226 946 62
E: martin.butter@splendiddata.com
http://www.splendiddata.com/
Вложения
Martin Butter <martin.butter@splendiddata.com> writes: > 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. I don't believe we have ever considered that (i.e., execution of general SQL from a _PG_init function) to be a supported case. If it seemed to work before, that was completely accidental. There is no transaction context in place when process_session_preload_libraries runs. regards, tom lane