Database crash when I run dml queries

Question

Database crash when I run dml queries

Closed this issue 6 years ago · 17 comments

Hi,
When I try to run insert/update/delete queries on the foreign table my database crashes.

For example :
db1 =# CREATE FOREIGN TABLE mariel_test(id integer OPTIONS (key 'true'),b text) SERVER sqlite_server OPTIONS (table 'MARIEL_TEST');
CREATE FOREIGN TABLE
db1 =# select * from mariel_test ;
id | b
----+---
(0 rows)

sqlite> insert into mariel_Test values(1,1);

db1 =# select * from mariel_test ;
id | b
----+---
1 | 1
(1 row)

db1=# insert into mariel_Test values(2,2);
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.
!> \q

From the log of the database :
2018-09-16 08:43:20 EDT 6027 DETAIL: Failed process was running: insert into mariel_Test values(2,2);
2018-09-16 08:43:20 EDT 6027 LOG: terminating any other active server processes
2018-09-16 08:43:20 EDT db1 23253 WARNING: terminating connection because of crash of another server process
2018-09-16 08:43:20 EDT db1 23253 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.
2018-09-16 08:43:20 EDT db1 23253 HINT: In a moment you should be able to reconnect to the database and repeat your command.
2018-09-16 08:43:20 EDT 22311 WARNING: terminating connection because of crash of another server process
2018-09-16 08:43:20 EDT 22311 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.
2018-09-16 08:43:20 EDT 22311 HINT: In a moment you should be able to reconnect to the database and repeat your command.
2018-09-16 08:43:20 EDT db2 22316 WARNING: terminating connection because of crash of another server process
2018-09-16 08:43:20 EDT db2 22316 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.
2018-09-16 08:43:20 EDT db2 22316 HINT: In a moment you should be able to reconnect to the database and repeat your command.
2018-09-16 08:43:20 EDT db2 22318 WARNING: terminating connection because of crash of another server process
2018-09-16 08:43:20 EDT db2 22318 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.
2018-09-16 08:43:20 EDT db2 22318 HINT: In a moment you should be able to reconnect to the database and repeat your command.
2018-09-16 08:43:20 EDT 6027 LOG: all server processes terminated; reinitializing
2018-09-16 08:43:21 EDT 26960 LOG: database system was interrupted; last known up at 2018-09-16 08:39:06 EDT
2018-09-16 08:43:21 EDT 26960 LOG: database system was not properly shut down; automatic recovery in progress
2018-09-16 08:43:21 EDT 26960 LOG: invalid record length at 142/3B33FC8: wanted 24, got 0
2018-09-16 08:43:21 EDT 26960 LOG: redo is not required
2018-09-16 08:43:21 EDT 26960 LOG: checkpoint starting: end-of-recovery immediate

Any idea ?

Answer 1 · 2018-09-18T09:30:59.000Z

Thanks for reporting.

I tried to reproduce, but cannot on my environment.
Could you inform Postgres version and the schema of mariel_Test on SQLite?

Answer 2 · 2018-09-18T11:39:32.000Z

postgresql version is 9.6.10.
I already tried it with every table even with new tables that I create on the sqlite side. For example :

[root@node1_priviledged sqlite-autoconf-3220000]# /usr/local/bin/sqlite3 /var/lib/pgsql/main.sqlite

SQLite version 3.6.20
Enter ".help" for instructions
Enter SQL statements terminated with a ";"

sqlite> create table mariel_Test (id int);
sqlite> insert into mariel_test values(1);
sqlite> select * from mariel_Test;
1
sqlite> .schema mariel_test
CREATE TABLE mariel_Test (id int)

postgresql side :
create server sqlite_server foreign data wrapper sqlite_fdw options(database '/var/lib/pgsql/main.sqlite');
CREATE SERVER
db1=# create foreign table mariel_test_foreign (id integer) server sqlite_server options(table 'mariel_test');
CREATE FOREIGN TABLE
db1=# select * from mariel_test_foreign ;
id

1
(1 row)
db1=# insert into mariel_test_foreign values(1);
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.

I had a core that was created and its content :

the core content :
[root@node1_priviledged data]# gdb -q -c core-postmaster-11-22870-1537273706
BFD: Warning: /data/pgsql/data/core-postmaster-11-22870-1537273706 is truncated: expected core file size >= 3268317184, found: 3141574656.
[New Thread 22870]
Failed to read a valid object file image from memory.
Core was generated by `postgres: postgres db1 [local] INSERT '.
Program terminated with signal 11, Segmentation fault.
#0 0x00007f128d3269df in ?? ()
(gdb) bt
#0 0x00007f128d3269df in ?? ()
Cannot access memory at address 0x7ffec280b4b8
(gdb) bt full
#0 0x00007f128d3269df in ?? ()
No symbol table info available.
Cannot access memory at address 0x7ffec280b4b8

Answer 3 · 2018-09-19T05:14:49.000Z

I committed fix of possible cause. Could you check?
If the issue is not solved, could you attach detailed logs by below setting?
postgres=# set log_min_messages to debug1;

If possible, could you attach crash point by building postgres with --enable-debug?

Answer 4 · 2018-09-19T05:16:35.000Z

Indeed, I will check in a few minutes and update you asap. I installed postgres from packages so in order to build postgres with --enable-debug I should use the sources right ?

Answer 5 · 2018-09-19T05:26:35.000Z

psql :
db1=# CREATE FOREIGN TABLE my_table_foreign(my_tableID integer options(key 'true'), IP text,InterfaceID integer) SERVER sqlite_server OPTIONS (table 'my_table');
CREATE FOREIGN TABLE

db1=# select * from my_table_foreign;
my_tableid | ip | interfaceid
-------+----+-------------
1 | 1 | 1
(1 row)

db1=# insert into my_table_foreign values(2,2,2);
ERROR: failed to execute remote SQL: rc=1 SQL logic error or missing database
sql=
db1=#

postgresql log :
2018-09-19 05:22:32 UTC db1 70180 DEBUG: sqlite_fdw : sqlite_fdw_handler
2018-09-19 05:22:32 UTC db1 70180 DEBUG: sqlite_fdw : sqlitePlanForeignModify
2018-09-19 05:22:32 UTC db1 70180 DEBUG: sqlite_fdw : sqlite_fdw_handler
2018-09-19 05:22:32 UTC db1 70180 DEBUG: sqlite_fdw : sqliteBeginForeignModify
2018-09-19 05:22:32 UTC db1 70180 DEBUG: sqlite_fdw : sqlite_prepare_wrapper INSERT INTO main."my_table"("my_tableid", "ip", "interfaceid") VALUES (?, ?, ?)

2018-09-19 05:22:32 UTC db1 70180 DEBUG: sqlite_fdw : sqliteExecForeignInsert
2018-09-19 05:22:32 UTC db1 70180 ERROR: failed to execute remote SQL: rc=1 SQL logic error or missing database
sql=
2018-09-19 05:22:32 UTC db1 70180 STATEMENT: insert into my_table_foreign values(2,2,2);
2018-09-19 05:22:32 UTC db1 70180 DEBUG: xact_callback 2
2018-09-19 05:22:51 UTC 36275 DEBUG: received inquiry for database 0
2018-09-19 05:22:51 UTC 36275 DEBUG: writing stats file "pg_stat_tmp/global.stat"
2018-09-19 05:22:51 UTC 36275 DEBUG: writing stats file "pg_stat_tmp/db_0.stat"
2018-09-19 05:22:51 UTC 70348 DEBUG: autovacuum: processing database "db1"
2018-09-19 05:22:51 UTC 36275 DEBUG: received inquiry for database 16384
2018-09-19 05:22:51 UTC 36275 DEBUG: writing stats file "pg_stat_tmp/global.stat"
2018-09-19 05:22:51 UTC 36275 DEBUG: writing stats file "pg_stat_tmp/db_16384.stat"
2018-09-19 05:22:51 UTC 36275 DEBUG: writing stats file "pg_stat_tmp/db_0.stat"
2018-09-19 05:22:51 UTC 12351 DEBUG: server process (PID 70348) exited with exit code 0

Answer 6 · 2018-09-19T05:51:26.000Z

Thanks for the information.
I will investigate.

Answer 7 · 2018-09-19T06:12:33.000Z

Could you check permission of SQLite database?

Answer 8 · 2018-09-19T06:45:18.000Z

I granted 777 on the file :
ls -l map.sqlite
-rwxrwxrwx 1 user1 user1 3072 Sep 18 15:23 map.sqlite

and I still got the same error :
db1=# insert into my_table_foreign values(2,2,2);
ERROR: failed to execute remote SQL: rc=1 SQL logic error or missing database
sql=

postgresql log :

2018-09-19 06:44:19 UTC 12351 LOG: received SIGHUP, reloading configuration files
2018-09-19 06:44:19 UTC 12351 LOG: parameter "log_min_messages" changed to "debug1"
2018-09-19 06:44:23 UTC db1 6573 DEBUG: sqlite_fdw : sqlite_fdw_handler
2018-09-19 06:44:23 UTC db1 6573 DEBUG: sqlite_fdw : sqlitePlanForeignModify
2018-09-19 06:44:23 UTC db1 6573 DEBUG: sqlite_fdw : sqlite_fdw_handler
2018-09-19 06:44:23 UTC db1 6573 DEBUG: sqlite_fdw : sqliteBeginForeignModify
2018-09-19 06:44:23 UTC db1 6573 DEBUG: sqlite_fdw : sqlite_prepare_wrapper INSERT INTO main."my_table"("mytableid", "ip", "interfaceid") VALUES (?, ?, ?)

2018-09-19 06:44:23 UTC db1 6573 DEBUG: sqlite_fdw : sqliteExecForeignInsert
2018-09-19 06:44:23 UTC db1 6573 ERROR: failed to execute remote SQL: rc=1 SQL logic error or missing database
sql=
2018-09-19 06:44:23 UTC db1 6573 STATEMENT: insert into my_table_foreign values(2,2,2);
2018-09-19 06:44:23 UTC db1 6573 DEBUG: xact_callback 2

Answer 9 · 2018-09-19T07:20:05.000Z

Thanks for trying.
Could you attach schema of my_table?
One integer column table causes the same issue?

Answer 10 · 2018-09-19T08:14:57.000Z

Yes indeed one column table causes the same issue :

sqlite> create table test(cola integer);
sqlite> .schema test
CREATE TABLE test(cola integer);
sqlite> insert into test values (1);
sqlite> select * from test;
1
sqlite>

db1=# CREATE FOREIGN TABLE test_foreign(cola integer) SERVER sqlite_server OPTIONS (table 'test'); CREATE FOREIGN TABLE
db1=# select * from test_foreign ;
cola

(1 row)

db1=# insert into test_foreign values(2);
ERROR: failed to execute remote SQL: rc=1 SQL logic error or missing database
sql=
db1=#

postgresql log :
2018-09-19 08:14:03 UTC db1 46759 DEBUG: sqlite_fdw : sqlite_fdw_handler
2018-09-19 08:14:03 UTC db1 46759 DEBUG: sqlite_fdw : sqlitePlanForeignModify
2018-09-19 08:14:03 UTC db1 46759 DEBUG: sqlite_fdw : sqliteBeginForeignModify
2018-09-19 08:14:03 UTC db1 46759 DEBUG: sqlite_fdw : sqlite_prepare_wrapper INSERT INTO main."test"("cola") VALUES (?)

2018-09-19 08:14:03 UTC db1 46759 DEBUG: sqlite_fdw : sqliteExecForeignInsert
2018-09-19 08:14:03 UTC db1 46759 ERROR: failed to execute remote SQL: rc=1 SQL logic error or missing database
sql=
2018-09-19 08:14:03 UTC db1 46759 STATEMENT: insert into test_foreign values(2);
2018-09-19 08:14:03 UTC db1 46759 DEBUG: xact_callback 2

Answer 11 · 2018-09-20T02:17:37.000Z

Thanks for checking.

Could you check below?

Close SQLite shell before PostgreSQL is started
Use latest SQLite (3.25)

If above does not solve the issue, please use the sqlite_fdw latest version with set to debug2.
I committed change for more error log.
postgres=# set log_min_messages to debug2;

Answer 12 · 2018-09-20T06:41:53.000Z

Do you think that the sqlite version matters ? I used sqlite 3.22 and even 3.6 but in both cases got errors. I set the log_min_messages to debug2 and did the insert but still got errors :

db1=# insert into test_foreign values(1);
ERROR: failed to execute remote SQL: rc=14 unable to open database file
sql=INSERT INTO main."test"("cola") VALUES (?)

2018-09-20 06:39:16 UTC db1 22640 DEBUG: sqlite_fdw : sqlite_fdw_handler
2018-09-20 06:39:16 UTC db1 22640 DEBUG: sqlite_fdw : sqlitePlanForeignModify
2018-09-20 06:39:16 UTC db1 22640 DEBUG: sqlite_fdw : sqlite_fdw_handler
2018-09-20 06:39:16 UTC db1 22640 DEBUG: sqlite_fdw : sqliteBeginForeignModify
2018-09-20 06:39:16 UTC db1 22640 DEBUG: sqlite_fdw : sqlite_prepare_wrapper INSERT INTO main."test"("cola") VALUES (?)

2018-09-20 06:39:16 UTC db1 22640 DEBUG: sqlite_fdw : sqliteExecForeignInsert
2018-09-20 06:39:16 UTC db1 22640 DEBUG: sqlite_fdw : sqlite_bind_sql_var 1 type=23
2018-09-20 06:39:16 UTC db1 22640 ERROR: failed to execute remote SQL: rc=14 unable to open database file
sql=INSERT INTO main."test"("cola") VALUES (?)
2018-09-20 06:39:16 UTC db1 22640 STATEMENT: insert into test_foreign values(1);
2018-09-20 06:39:16 UTC db1 22640 DEBUG: xact_callback 2

If it will be helpfull, we can make a skype session / webex or something similar.

Answer 13 · 2018-09-20T07:34:58.000Z

Thanks for checking.
I'm not sure sqlite version matters, but would like to the possibility.

From this error,
ERROR: failed to execute remote SQL: rc=14 unable to open database file
directory permission is not enough.
Please see
https://serverfault.com/questions/57596/why-do-i-get-sqlite-error-unable-to-open-database-file

Answer 14 · 2018-09-20T07:40:26.000Z

Yes! Granting write permissions on the directory that contains the database file was the solution. Thanks !

One more question, I saw in your examples that in all the foreign tables that you created you must have at least one column configured as primary key. You did that to allow yourself use update /delete on the foreign tables ?

Answer 15 · 2018-09-20T07:55:10.000Z

Glad to hear that!
I should have noticed earlier I used SQLite API which return less error info.

You did that to allow yourself use update /delete on the foreign tables ?

Yes, OPTIONS (key 'true') is for update/delete. Not necessary if only reading.

Answer 16 · 2018-09-20T07:55:56.000Z

Thank you very much !

Answer 17 · 2018-09-20T08:13:20.000Z

Thank you.

db1=# CREATE FOREIGN TABLE test_foreign(cola integer) SERVER sqlite_server OPTIONS (table 'test'); CREATE FOREIGN TABLE db1=# select * from test_foreign ; cola

db1=# CREATE FOREIGN TABLE test_foreign(cola integer) SERVER sqlite_server OPTIONS (table 'test'); CREATE FOREIGN TABLE
db1=# select * from test_foreign ;
cola