Обсуждение: [JDBC] SEGFAULT in HEAD with replication

Поиск
Список
Период
Сортировка

[JDBC] SEGFAULT in HEAD with replication

От
Dave Cramer
Дата:
The travis job https://travis-ci.org/pgjdbc/pgjdbc/jobs/192517342 is seeing a segfault when we are testing against HEAD with REPLICATION turned on.


Regards,

Dave Cramer

Re: [JDBC] SEGFAULT in HEAD with replication

От
Vladimir Gordiychuk
Дата:
Last success build from postgresql HEAD was 20 days ago https://travis-ci.org/pgjdbc/pgjdbc/builds/187764274
We detect this problem 3 days ago.

2017-01-19 17:22 GMT+03:00 Dave Cramer <davecramer@gmail.com>:
The travis job https://travis-ci.org/pgjdbc/pgjdbc/jobs/192517342 is seeing a segfault when we are testing against HEAD with REPLICATION turned on.


Regards,

Dave Cramer

Re: [JDBC] SEGFAULT in HEAD with replication

От
Vladimir Gordiychuk
Дата:
Core dump was extracted from this build https://travis-ci.org/Gordiychuk/pgjdbc/builds/193318018


2017-01-19 17:38 GMT+03:00 Vladimir Gordiychuk <folyga@gmail.com>:
Last success build from postgresql HEAD was 20 days ago https://travis-ci.org/pgjdbc/pgjdbc/builds/187764274
We detect this problem 3 days ago.

2017-01-19 17:22 GMT+03:00 Dave Cramer <davecramer@gmail.com>:
The travis job https://travis-ci.org/pgjdbc/pgjdbc/jobs/192517342 is seeing a segfault when we are testing against HEAD with REPLICATION turned on.


Regards,

Dave Cramer


Re: [JDBC] SEGFAULT in HEAD with replication

От
Jorge Solórzano
Дата:
I have isolated the tests run by the pgjdbc project, I have disabled the replication (wal_level = minimal) and the error is still present so it seems that this error is not related to the replication, the test that cause the error is AutoRollbackTestSuite, I have enable DEBUG mesages in postgresql and pgjdbc and this is what I get:

https://drive.google.com/drive/folders/0ByHbu-sR29gda2d2LUFpV0lPdUk


On Thu, Jan 19, 2017 at 8:42 AM, Vladimir Gordiychuk <folyga@gmail.com> wrote:
Core dump was extracted from this build https://travis-ci.org/Gordiychuk/pgjdbc/builds/193318018


2017-01-19 17:38 GMT+03:00 Vladimir Gordiychuk <folyga@gmail.com>:
Last success build from postgresql HEAD was 20 days ago https://travis-ci.org/pgjdbc/pgjdbc/builds/187764274
We detect this problem 3 days ago.

2017-01-19 17:22 GMT+03:00 Dave Cramer <davecramer@gmail.com>:
The travis job https://travis-ci.org/pgjdbc/pgjdbc/jobs/192517342 is seeing a segfault when we are testing against HEAD with REPLICATION turned on.


Regards,

Dave Cramer



Re: [HACKERS] [JDBC] SEGFAULT in HEAD with replication

От
Robert Haas
Дата:
On Thu, Jan 19, 2017 at 10:59 AM, Jorge Solórzano <jorsol@gmail.com> wrote:
> I have isolated the tests run by the pgjdbc project, I have disabled the
> replication (wal_level = minimal) and the error is still present so it seems
> that this error is not related to the replication, the test that cause the
> error is AutoRollbackTestSuite, I have enable DEBUG mesages in postgresql
> and pgjdbc and this is what I get:
>
> https://drive.google.com/drive/folders/0ByHbu-sR29gda2d2LUFpV0lPdUk

Can somebody paste the stack trace into an email, here?  There's
reference to it upthread, but it's not obvious where it actually is.

--
Robert Haas
EnterpriseDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company

Re: [HACKERS] [JDBC] SEGFAULT in HEAD with replication

От
Jorge Solórzano
Дата:
Robert, the logs I get from postgres (at least the section that matters) is here:
If you need something else just ask...

2017-01-19 08:54:57.319 CST [31734] DEBUG:  CommitTransaction(1) name: unnamed; blockState: STARTED; state: INPROGR, xid/subid/cid: 0/1/0
2017-01-19 08:54:57.321 CST [31734] DEBUG:  parse S_1: DROP TABLE rollbacktest CASCADE
2017-01-19 08:54:57.321 CST [31734] STATEMENT:  DROP TABLE rollbacktest CASCADE
2017-01-19 08:54:57.321 CST [31734] DEBUG:  StartTransaction(1) name: unnamed; blockState: DEFAULT; state: INPROGR, xid/subid/cid: 0/1/0
2017-01-19 08:54:57.321 CST [31734] STATEMENT:  DROP TABLE rollbacktest CASCADE
2017-01-19 08:54:57.321 CST [31734] LOG:  duration: 0.289 ms
2017-01-19 08:54:57.321 CST [31734] DEBUG:  bind <unnamed> to S_1
2017-01-19 08:54:57.321 CST [31734] LOG:  duration: 0.073 ms
2017-01-19 08:54:57.321 CST [31734] LOG:  execute S_1: DROP TABLE rollbacktest CASCADE
2017-01-19 08:54:57.321 CST [31734] ERROR:  table "rollbacktest" does not exist
2017-01-19 08:54:57.321 CST [31734] STATEMENT:  DROP TABLE rollbacktest CASCADE
2017-01-19 08:54:57.322 CST [31734] DEBUG:  parse S_2: CREATE TABLE rollbacktest (a int, str text)
2017-01-19 08:54:57.322 CST [31734] STATEMENT:  CREATE TABLE rollbacktest (a int, str text)
2017-01-19 08:54:57.322 CST [31734] DEBUG:  StartTransaction(1) name: unnamed; blockState: DEFAULT; state: INPROGR, xid/subid/cid: 0/1/0
2017-01-19 08:54:57.322 CST [31734] STATEMENT:  CREATE TABLE rollbacktest (a int, str text)
2017-01-19 08:54:57.322 CST [31734] LOG:  duration: 0.279 ms
2017-01-19 08:54:57.323 CST [31734] DEBUG:  bind <unnamed> to S_2
2017-01-19 08:54:57.323 CST [31734] LOG:  duration: 0.163 ms
2017-01-19 08:54:57.323 CST [31734] LOG:  execute S_2: CREATE TABLE rollbacktest (a int, str text)
2017-01-19 08:54:57.324 CST [31734] DEBUG:  building index "pg_toast_163960_index" on table "pg_toast_163960"
2017-01-19 08:54:57.324 CST [31734] STATEMENT:  CREATE TABLE rollbacktest (a int, str text)
2017-01-19 08:54:57.327 CST [31734] LOG:  duration: 4.232 ms
2017-01-19 08:54:57.327 CST [31734] DEBUG:  CommitTransaction(1) name: unnamed; blockState: STARTED; state: INPROGR, xid/subid/cid: 270571/1/5
2017-01-19 08:54:57.329 CST [31734] DEBUG:  parse S_3:
2017-01-19 08:54:57.329 CST [31734] STATEMENT: 
2017-01-19 08:54:57.329 CST [31734] DEBUG:  StartTransaction(1) name: unnamed; blockState: DEFAULT; state: INPROGR, xid/subid/cid: 0/1/0
2017-01-19 08:54:57.329 CST [31734] STATEMENT: 
2017-01-19 08:54:57.329 CST [31734] LOG:  duration: 0.148 ms
2017-01-19 08:54:57.329 CST [31734] DEBUG:  bind <unnamed> to S_3
2017-01-19 08:54:57.329 CST [31734] LOG:  duration: 0.088 ms
2017-01-19 08:54:57.329 CST [31734] DEBUG:  CommitTransaction(1) name: unnamed; blockState: STARTED; state: INPROGR, xid/subid/cid: 0/1/0
2017-01-19 08:54:57.330 CST [31734] DEBUG:  parse S_4: BEGIN
2017-01-19 08:54:57.330 CST [31734] STATEMENT:  BEGIN
2017-01-19 08:54:57.330 CST [31734] DEBUG:  StartTransaction(1) name: unnamed; blockState: DEFAULT; state: INPROGR, xid/subid/cid: 0/1/0
2017-01-19 08:54:57.330 CST [31734] STATEMENT:  BEGIN
2017-01-19 08:54:57.331 CST [31734] LOG:  duration: 0.189 ms
2017-01-19 08:54:57.331 CST [31734] DEBUG:  bind <unnamed> to S_4
2017-01-19 08:54:57.331 CST [31734] LOG:  duration: 0.105 ms
2017-01-19 08:54:57.331 CST [31734] LOG:  execute S_4: BEGIN
2017-01-19 08:54:57.331 CST [31734] LOG:  duration: 0.154 ms
2017-01-19 08:54:57.331 CST [31734] DEBUG:  parse S_5: insert into rollbacktest(a, str) values (0, 'test')
2017-01-19 08:54:57.331 CST [31734] STATEMENT:  insert into rollbacktest(a, str) values (0, 'test')
2017-01-19 08:54:57.331 CST [31734] LOG:  duration: 0.277 ms
2017-01-19 08:54:57.332 CST [31734] DEBUG:  bind <unnamed> to S_5
2017-01-19 08:54:57.332 CST [31734] LOG:  duration: 0.168 ms
2017-01-19 08:54:57.332 CST [31734] LOG:  execute S_5: insert into rollbacktest(a, str) values (0, 'test')
2017-01-19 08:54:57.332 CST [31734] LOG:  duration: 0.233 ms
2017-01-19 08:54:57.333 CST [31734] DEBUG:  parse S_6: select * from rollbacktest
2017-01-19 08:54:57.333 CST [31734] STATEMENT:  select * from rollbacktest
2017-01-19 08:54:57.333 CST [31734] LOG:  duration: 0.093 ms
2017-01-19 08:54:57.333 CST [31734] DEBUG:  bind <unnamed> to S_6
2017-01-19 08:54:57.333 CST [31734] LOG:  duration: 0.188 ms
2017-01-19 08:54:57.333 CST [31734] LOG:  execute S_6: select * from rollbacktest
2017-01-19 08:54:57.333 CST [31734] LOG:  duration: 0.094 ms
2017-01-19 08:54:57.334 CST [31734] DEBUG:  parse S_7: select 1/0
2017-01-19 08:54:57.334 CST [31734] STATEMENT:  select 1/0
2017-01-19 08:54:57.334 CST [31734] LOG:  duration: 0.174 ms
2017-01-19 08:54:57.334 CST [31734] DEBUG:  bind <unnamed> to S_7
2017-01-19 08:54:57.334 CST [31734] ERROR:  division by zero
2017-01-19 08:54:57.334 CST [31734] STATEMENT:  select 1/0
2017-01-19 08:54:57.335 CST [31734] DEBUG:  bind <unnamed> to S_3
2017-01-19 08:54:57.412 CST [31690] DEBUG:  reaping dead processes
2017-01-19 08:54:57.412 CST [31690] DEBUG:  server process (PID 31734) was terminated by signal 11: Segmentation fault
2017-01-19 08:54:57.412 CST [31690] LOG:  server process (PID 31734) was terminated by signal 11: Segmentation fault
2017-01-19 08:54:57.412 CST [31690] LOG:  terminating any other active server processes
2017-01-19 08:54:57.412 CST [31690] DEBUG:  sending SIGQUIT to process 31694
2017-01-19 08:54:57.412 CST [31690] DEBUG:  sending SIGQUIT to process 31693
2017-01-19 08:54:57.412 CST [31690] DEBUG:  sending SIGQUIT to process 31695
2017-01-19 08:54:57.412 CST [31690] DEBUG:  sending SIGQUIT to process 31696
2017-01-19 08:54:57.412 CST [31690] DEBUG:  sending SIGQUIT to process 31697
2017-01-19 08:54:57.412 CST [31693] DEBUG:  shmem_exit(-1): 0 before_shmem_exit callbacks to make
2017-01-19 08:54:57.412 CST [31693] DEBUG:  shmem_exit(-1): 0 on_shmem_exit callbacks to make
2017-01-19 08:54:57.412 CST [31693] DEBUG:  proc_exit(-1): 0 callbacks to make
2017-01-19 08:54:57.412 CST [31696] WARNING:  terminating connection because of crash of another server process
2017-01-19 08:54:57.412 CST [31696] 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.
2017-01-19 08:54:57.412 CST [31696] HINT:  In a moment you should be able to reconnect to the database and repeat your command.
2017-01-19 08:54:57.412 CST [31696] DEBUG:  shmem_exit(-1): 0 before_shmem_exit callbacks to make
2017-01-19 08:54:57.412 CST [31696] DEBUG:  shmem_exit(-1): 0 on_shmem_exit callbacks to make
2017-01-19 08:54:57.412 CST [31696] DEBUG:  proc_exit(-1): 0 callbacks to make
2017-01-19 08:54:57.412 CST [31695] DEBUG:  shmem_exit(-1): 0 before_shmem_exit callbacks to make
2017-01-19 08:54:57.412 CST [31695] DEBUG:  shmem_exit(-1): 0 on_shmem_exit callbacks to make
2017-01-19 08:54:57.412 CST [31695] DEBUG:  proc_exit(-1): 0 callbacks to make
2017-01-19 08:54:57.412 CST [31697] DEBUG:  writing stats file "pg_stat/global.stat"
2017-01-19 08:54:57.412 CST [31694] DEBUG:  shmem_exit(-1): 0 before_shmem_exit callbacks to make
2017-01-19 08:54:57.412 CST [31697] DEBUG:  writing stats file "pg_stat/db_12254.stat"
2017-01-19 08:54:57.412 CST [31694] DEBUG:  shmem_exit(-1): 0 on_shmem_exit callbacks to make
2017-01-19 08:54:57.412 CST [31694] DEBUG:  proc_exit(-1): 0 callbacks to make
2017-01-19 08:54:57.412 CST [31697] DEBUG:  removing temporary stats file "pg_stat_tmp/db_12254.stat"
2017-01-19 08:54:57.412 CST [31697] DEBUG:  writing stats file "pg_stat/db_16385.stat"
2017-01-19 08:54:57.413 CST [31697] DEBUG:  removing temporary stats file "pg_stat_tmp/db_16385.stat"
2017-01-19 08:54:57.413 CST [31697] DEBUG:  writing stats file "pg_stat/db_0.stat"
2017-01-19 08:54:57.413 CST [31690] DEBUG:  reaping dead processes
2017-01-19 08:54:57.413 CST [31697] DEBUG:  removing temporary stats file "pg_stat_tmp/db_0.stat"
2017-01-19 08:54:57.413 CST [31690] DEBUG:  reaping dead processes
2017-01-19 08:54:57.413 CST [31697] DEBUG:  shmem_exit(-1): 0 before_shmem_exit callbacks to make
2017-01-19 08:54:57.413 CST [31697] DEBUG:  shmem_exit(-1): 0 on_shmem_exit callbacks to make
2017-01-19 08:54:57.413 CST [31697] DEBUG:  proc_exit(-1): 0 callbacks to make
2017-01-19 08:54:57.413 CST [31690] DEBUG:  reaping dead processes
2017-01-19 08:54:57.413 CST [31690] DEBUG:  reaping dead processes
2017-01-19 08:54:57.413 CST [31690] LOG:  all server processes terminated; reinitializing
2017-01-19 08:54:57.413 CST [31690] DEBUG:  shmem_exit(1): 0 before_shmem_exit callbacks to make
2017-01-19 08:54:57.413 CST [31690] DEBUG:  shmem_exit(1): 5 on_shmem_exit callbacks to make
2017-01-19 08:54:57.413 CST [31690] DEBUG:  cleaning up dynamic shared memory control segment with ID 141917387
2017-01-19 08:54:57.418 CST [31690] DEBUG:  invoking IpcMemoryCreate(size=574734336)
2017-01-19 08:54:57.431 CST [31690] DEBUG:  SlruScanDirectory invoking callback on pg_notify/0000
2017-01-19 08:54:57.431 CST [31690] DEBUG:  removing file "pg_notify/0000"
2017-01-19 08:54:57.431 CST [31690] DEBUG:  dynamic shared memory system will support 288 segments
2017-01-19 08:54:57.431 CST [31690] DEBUG:  created dynamic shared memory control segment 1621489222 (6928 bytes)
2017-01-19 08:54:57.432 CST [31690] DEBUG:  forked new backend, pid=31737 socket=10
2017-01-19 08:54:57.432 CST [31736] LOG:  database system was interrupted; last known up at 2017-01-19 08:54:25 CST
2017-01-19 08:54:57.432 CST [31737] LOG:  connection received: host=172.16.45.144 port=59096
2017-01-19 08:54:57.432 CST [31737] FATAL:  the database system is in recovery mode
2017-01-19 08:54:57.432 CST [31737] DEBUG:  shmem_exit(1): 0 before_shmem_exit callbacks to make
2017-01-19 08:54:57.432 CST [31737] DEBUG:  shmem_exit(1): 0 on_shmem_exit callbacks to make
2017-01-19 08:54:57.432 CST [31737] DEBUG:  proc_exit(1): 1 callbacks to make
2017-01-19 08:54:57.432 CST [31737] DEBUG:  exit(1)
2017-01-19 08:54:57.432 CST [31737] DEBUG:  shmem_exit(-1): 0 before_shmem_exit callbacks to make
2017-01-19 08:54:57.432 CST [31737] DEBUG:  shmem_exit(-1): 0 on_shmem_exit callbacks to make
2017-01-19 08:54:57.432 CST [31737] DEBUG:  proc_exit(-1): 0 callbacks to make
2017-01-19 08:54:57.433 CST [31690] DEBUG:  reaping dead processes
2017-01-19 08:54:57.433 CST [31690] DEBUG:  server process (PID 31737) exited with exit code 1
2017-01-19 08:54:57.437 CST [31690] DEBUG:  forked new backend, pid=31738 socket=10
2017-01-19 08:54:57.437 CST [31738] LOG:  connection received: host=172.16.45.144 port=59098
2017-01-19 08:54:57.437 CST [31738] FATAL:  the database system is in recovery mode
2017-01-19 08:54:57.437 CST [31738] DEBUG:  shmem_exit(1): 0 before_shmem_exit callbacks to make
2017-01-19 08:54:57.437 CST [31738] DEBUG:  shmem_exit(1): 0 on_shmem_exit callbacks to make
2017-01-19 08:54:57.437 CST [31738] DEBUG:  proc_exit(1): 1 callbacks to make
2017-01-19 08:54:57.437 CST [31738] DEBUG:  exit(1)
2017-01-19 08:54:57.437 CST [31738] DEBUG:  shmem_exit(-1): 0 before_shmem_exit callbacks to make
2017-01-19 08:54:57.437 CST [31738] DEBUG:  shmem_exit(-1): 0 on_shmem_exit callbacks to make
2017-01-19 08:54:57.437 CST [31738] DEBUG:  proc_exit(-1): 0 callbacks to make
2017-01-19 08:54:57.438 CST [31690] DEBUG:  reaping dead processes
2017-01-19 08:54:57.438 CST [31690] DEBUG:  server process (PID 31738) exited with exit code 1
2017-01-19 08:54:57.439 CST [31690] DEBUG:  forked new backend, pid=31739 socket=10
2017-01-19 08:54:57.440 CST [31739] LOG:  connection received: host=172.16.45.144 port=59100
2017-01-19 08:54:57.440 CST [31739] FATAL:  the database system is in recovery mode
2017-01-19 08:54:57.440 CST [31739] DEBUG:  shmem_exit(1): 0 before_shmem_exit callbacks to make
2017-01-19 08:54:57.440 CST [31739] DEBUG:  shmem_exit(1): 0 on_shmem_exit callbacks to make
2017-01-19 08:54:57.440 CST [31739] DEBUG:  proc_exit(1): 1 callbacks to make
2017-01-19 08:54:57.440 CST [31739] DEBUG:  exit(1)
2017-01-19 08:54:57.440 CST [31739] DEBUG:  shmem_exit(-1): 0 before_shmem_exit callbacks to make
2017-01-19 08:54:57.440 CST [31739] DEBUG:  shmem_exit(-1): 0 on_shmem_exit callbacks to make
2017-01-19 08:54:57.440 CST [31739] DEBUG:  proc_exit(-1): 0 callbacks to make
2017-01-19 08:54:57.441 CST [31690] DEBUG:  reaping dead processes
2017-01-19 08:54:57.441 CST [31690] DEBUG:  server process (PID 31739) exited with exit code 1
2017-01-19 08:54:57.442 CST [31690] DEBUG:  forked new backend, pid=31740 socket=10
2017-01-19 08:54:57.444 CST [31740] LOG:  connection received: host=172.16.45.144 port=59102
2017-01-19 08:54:57.444 CST [31740] FATAL:  the database system is in recovery mode
2017-01-19 08:54:57.444 CST [31740] DEBUG:  shmem_exit(1): 0 before_shmem_exit callbacks to make
2017-01-19 08:54:57.444 CST [31740] DEBUG:  shmem_exit(1): 0 on_shmem_exit callbacks to make
2017-01-19 08:54:57.444 CST [31740] DEBUG:  proc_exit(1): 1 callbacks to make
2017-01-19 08:54:57.444 CST [31740] DEBUG:  exit(1)
2017-01-19 08:54:57.444 CST [31740] DEBUG:  shmem_exit(-1): 0 before_shmem_exit callbacks to make
2017-01-19 08:54:57.444 CST [31740] DEBUG:  shmem_exit(-1): 0 on_shmem_exit callbacks to make
2017-01-19 08:54:57.444 CST [31740] DEBUG:  proc_exit(-1): 0 callbacks to make
2017-01-19 08:54:57.445 CST [31690] DEBUG:  reaping dead processes
2017-01-19 08:54:57.445 CST [31690] DEBUG:  server process (PID 31740) exited with exit code 1
2017-01-19 08:54:57.448 CST [31690] DEBUG:  forked new backend, pid=31741 socket=10
2017-01-19 08:54:57.449 CST [31741] LOG:  connection received: host=172.16.45.144 port=59104
2017-01-19 08:54:57.450 CST [31741] FATAL:  the database system is in recovery mode
2017-01-19 08:54:57.450 CST [31741] DEBUG:  shmem_exit(1): 0 before_shmem_exit callbacks to make
2017-01-19 08:54:57.450 CST [31741] DEBUG:  shmem_exit(1): 0 on_shmem_exit callbacks to make
2017-01-19 08:54:57.450 CST [31741] DEBUG:  proc_exit(1): 1 callbacks to make
2017-01-19 08:54:57.450 CST [31741] DEBUG:  exit(1)
2017-01-19 08:54:57.450 CST [31741] DEBUG:  shmem_exit(-1): 0 before_shmem_exit callbacks to make
2017-01-19 08:54:57.450 CST [31741] DEBUG:  shmem_exit(-1): 0 on_shmem_exit callbacks to make
2017-01-19 08:54:57.450 CST [31741] DEBUG:  proc_exit(-1): 0 callbacks to make
2017-01-19 08:54:57.452 CST [31690] DEBUG:  reaping dead processes
2017-01-19 08:54:57.453 CST [31690] DEBUG:  server process (PID 31741) exited with exit code 1
2017-01-19 08:54:57.454 CST [31690] DEBUG:  forked new backend, pid=31742 socket=10
2017-01-19 08:54:57.455 CST [31742] LOG:  connection received: host=172.16.45.144 port=59106
2017-01-19 08:54:57.455 CST [31742] FATAL:  the database system is in recovery mode
2017-01-19 08:54:57.455 CST [31742] DEBUG:  shmem_exit(1): 0 before_shmem_exit callbacks to make
2017-01-19 08:54:57.455 CST [31742] DEBUG:  shmem_exit(1): 0 on_shmem_exit callbacks to make
2017-01-19 08:54:57.455 CST [31742] DEBUG:  proc_exit(1): 1 callbacks to make
2017-01-19 08:54:57.455 CST [31742] DEBUG:  exit(1)
2017-01-19 08:54:57.455 CST [31742] DEBUG:  shmem_exit(-1): 0 before_shmem_exit callbacks to make
2017-01-19 08:54:57.455 CST [31742] DEBUG:  shmem_exit(-1): 0 on_shmem_exit callbacks to make
2017-01-19 08:54:57.455 CST [31742] DEBUG:  proc_exit(-1): 0 callbacks to make
2017-01-19 08:54:57.455 CST [31690] DEBUG:  reaping dead processes
2017-01-19 08:54:57.455 CST [31690] DEBUG:  server process (PID 31742) exited with exit code 1
2017-01-19 08:54:57.458 CST [31690] DEBUG:  forked new backend, pid=31743 socket=10



On Thu, Jan 19, 2017 at 10:53 AM, Robert Haas <robertmhaas@gmail.com> wrote:
On Thu, Jan 19, 2017 at 10:59 AM, Jorge Solórzano <jorsol@gmail.com> wrote:
> I have isolated the tests run by the pgjdbc project, I have disabled the
> replication (wal_level = minimal) and the error is still present so it seems
> that this error is not related to the replication, the test that cause the
> error is AutoRollbackTestSuite, I have enable DEBUG mesages in postgresql
> and pgjdbc and this is what I get:
>
> https://drive.google.com/drive/folders/0ByHbu-sR29gda2d2LUFpV0lPdUk

Can somebody paste the stack trace into an email, here?  There's
reference to it upthread, but it's not obvious where it actually is.

--
Robert Haas
EnterpriseDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company

Re: [HACKERS] [JDBC] SEGFAULT in HEAD with replication

От
Dave Cramer
Дата:
I'll try to get the stack trace from the core dump, have to build master first

Dave Cramer

On 19 January 2017 at 12:01, Jorge Solórzano <jorsol@gmail.com> wrote:
Robert, the logs I get from postgres (at least the section that matters) is here:
If you need something else just ask...

2017-01-19 08:54:57.319 CST [31734] DEBUG:  CommitTransaction(1) name: unnamed; blockState: STARTED; state: INPROGR, xid/subid/cid: 0/1/0
2017-01-19 08:54:57.321 CST [31734] DEBUG:  parse S_1: DROP TABLE rollbacktest CASCADE
2017-01-19 08:54:57.321 CST [31734] STATEMENT:  DROP TABLE rollbacktest CASCADE
2017-01-19 08:54:57.321 CST [31734] DEBUG:  StartTransaction(1) name: unnamed; blockState: DEFAULT; state: INPROGR, xid/subid/cid: 0/1/0
2017-01-19 08:54:57.321 CST [31734] STATEMENT:  DROP TABLE rollbacktest CASCADE
2017-01-19 08:54:57.321 CST [31734] LOG:  duration: 0.289 ms
2017-01-19 08:54:57.321 CST [31734] DEBUG:  bind <unnamed> to S_1
2017-01-19 08:54:57.321 CST [31734] LOG:  duration: 0.073 ms
2017-01-19 08:54:57.321 CST [31734] LOG:  execute S_1: DROP TABLE rollbacktest CASCADE
2017-01-19 08:54:57.321 CST [31734] ERROR:  table "rollbacktest" does not exist
2017-01-19 08:54:57.321 CST [31734] STATEMENT:  DROP TABLE rollbacktest CASCADE
2017-01-19 08:54:57.322 CST [31734] DEBUG:  parse S_2: CREATE TABLE rollbacktest (a int, str text)
2017-01-19 08:54:57.322 CST [31734] STATEMENT:  CREATE TABLE rollbacktest (a int, str text)
2017-01-19 08:54:57.322 CST [31734] DEBUG:  StartTransaction(1) name: unnamed; blockState: DEFAULT; state: INPROGR, xid/subid/cid: 0/1/0
2017-01-19 08:54:57.322 CST [31734] STATEMENT:  CREATE TABLE rollbacktest (a int, str text)
2017-01-19 08:54:57.322 CST [31734] LOG:  duration: 0.279 ms
2017-01-19 08:54:57.323 CST [31734] DEBUG:  bind <unnamed> to S_2
2017-01-19 08:54:57.323 CST [31734] LOG:  duration: 0.163 ms
2017-01-19 08:54:57.323 CST [31734] LOG:  execute S_2: CREATE TABLE rollbacktest (a int, str text)
2017-01-19 08:54:57.324 CST [31734] DEBUG:  building index "pg_toast_163960_index" on table "pg_toast_163960"
2017-01-19 08:54:57.324 CST [31734] STATEMENT:  CREATE TABLE rollbacktest (a int, str text)
2017-01-19 08:54:57.327 CST [31734] LOG:  duration: 4.232 ms
2017-01-19 08:54:57.327 CST [31734] DEBUG:  CommitTransaction(1) name: unnamed; blockState: STARTED; state: INPROGR, xid/subid/cid: 270571/1/5
2017-01-19 08:54:57.329 CST [31734] DEBUG:  parse S_3:
2017-01-19 08:54:57.329 CST [31734] STATEMENT: 
2017-01-19 08:54:57.329 CST [31734] DEBUG:  StartTransaction(1) name: unnamed; blockState: DEFAULT; state: INPROGR, xid/subid/cid: 0/1/0
2017-01-19 08:54:57.329 CST [31734] STATEMENT: 
2017-01-19 08:54:57.329 CST [31734] LOG:  duration: 0.148 ms
2017-01-19 08:54:57.329 CST [31734] DEBUG:  bind <unnamed> to S_3
2017-01-19 08:54:57.329 CST [31734] LOG:  duration: 0.088 ms
2017-01-19 08:54:57.329 CST [31734] DEBUG:  CommitTransaction(1) name: unnamed; blockState: STARTED; state: INPROGR, xid/subid/cid: 0/1/0
2017-01-19 08:54:57.330 CST [31734] DEBUG:  parse S_4: BEGIN
2017-01-19 08:54:57.330 CST [31734] STATEMENT:  BEGIN
2017-01-19 08:54:57.330 CST [31734] DEBUG:  StartTransaction(1) name: unnamed; blockState: DEFAULT; state: INPROGR, xid/subid/cid: 0/1/0
2017-01-19 08:54:57.330 CST [31734] STATEMENT:  BEGIN
2017-01-19 08:54:57.331 CST [31734] LOG:  duration: 0.189 ms
2017-01-19 08:54:57.331 CST [31734] DEBUG:  bind <unnamed> to S_4
2017-01-19 08:54:57.331 CST [31734] LOG:  duration: 0.105 ms
2017-01-19 08:54:57.331 CST [31734] LOG:  execute S_4: BEGIN
2017-01-19 08:54:57.331 CST [31734] LOG:  duration: 0.154 ms
2017-01-19 08:54:57.331 CST [31734] DEBUG:  parse S_5: insert into rollbacktest(a, str) values (0, 'test')
2017-01-19 08:54:57.331 CST [31734] STATEMENT:  insert into rollbacktest(a, str) values (0, 'test')
2017-01-19 08:54:57.331 CST [31734] LOG:  duration: 0.277 ms
2017-01-19 08:54:57.332 CST [31734] DEBUG:  bind <unnamed> to S_5
2017-01-19 08:54:57.332 CST [31734] LOG:  duration: 0.168 ms
2017-01-19 08:54:57.332 CST [31734] LOG:  execute S_5: insert into rollbacktest(a, str) values (0, 'test')
2017-01-19 08:54:57.332 CST [31734] LOG:  duration: 0.233 ms
2017-01-19 08:54:57.333 CST [31734] DEBUG:  parse S_6: select * from rollbacktest
2017-01-19 08:54:57.333 CST [31734] STATEMENT:  select * from rollbacktest
2017-01-19 08:54:57.333 CST [31734] LOG:  duration: 0.093 ms
2017-01-19 08:54:57.333 CST [31734] DEBUG:  bind <unnamed> to S_6
2017-01-19 08:54:57.333 CST [31734] LOG:  duration: 0.188 ms
2017-01-19 08:54:57.333 CST [31734] LOG:  execute S_6: select * from rollbacktest
2017-01-19 08:54:57.333 CST [31734] LOG:  duration: 0.094 ms
2017-01-19 08:54:57.334 CST [31734] DEBUG:  parse S_7: select 1/0
2017-01-19 08:54:57.334 CST [31734] STATEMENT:  select 1/0
2017-01-19 08:54:57.334 CST [31734] LOG:  duration: 0.174 ms
2017-01-19 08:54:57.334 CST [31734] DEBUG:  bind <unnamed> to S_7
2017-01-19 08:54:57.334 CST [31734] ERROR:  division by zero
2017-01-19 08:54:57.334 CST [31734] STATEMENT:  select 1/0
2017-01-19 08:54:57.335 CST [31734] DEBUG:  bind <unnamed> to S_3
2017-01-19 08:54:57.412 CST [31690] DEBUG:  reaping dead processes
2017-01-19 08:54:57.412 CST [31690] DEBUG:  server process (PID 31734) was terminated by signal 11: Segmentation fault
2017-01-19 08:54:57.412 CST [31690] LOG:  server process (PID 31734) was terminated by signal 11: Segmentation fault
2017-01-19 08:54:57.412 CST [31690] LOG:  terminating any other active server processes
2017-01-19 08:54:57.412 CST [31690] DEBUG:  sending SIGQUIT to process 31694
2017-01-19 08:54:57.412 CST [31690] DEBUG:  sending SIGQUIT to process 31693
2017-01-19 08:54:57.412 CST [31690] DEBUG:  sending SIGQUIT to process 31695
2017-01-19 08:54:57.412 CST [31690] DEBUG:  sending SIGQUIT to process 31696
2017-01-19 08:54:57.412 CST [31690] DEBUG:  sending SIGQUIT to process 31697
2017-01-19 08:54:57.412 CST [31693] DEBUG:  shmem_exit(-1): 0 before_shmem_exit callbacks to make
2017-01-19 08:54:57.412 CST [31693] DEBUG:  shmem_exit(-1): 0 on_shmem_exit callbacks to make
2017-01-19 08:54:57.412 CST [31693] DEBUG:  proc_exit(-1): 0 callbacks to make
2017-01-19 08:54:57.412 CST [31696] WARNING:  terminating connection because of crash of another server process
2017-01-19 08:54:57.412 CST [31696] 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.
2017-01-19 08:54:57.412 CST [31696] HINT:  In a moment you should be able to reconnect to the database and repeat your command.
2017-01-19 08:54:57.412 CST [31696] DEBUG:  shmem_exit(-1): 0 before_shmem_exit callbacks to make
2017-01-19 08:54:57.412 CST [31696] DEBUG:  shmem_exit(-1): 0 on_shmem_exit callbacks to make
2017-01-19 08:54:57.412 CST [31696] DEBUG:  proc_exit(-1): 0 callbacks to make
2017-01-19 08:54:57.412 CST [31695] DEBUG:  shmem_exit(-1): 0 before_shmem_exit callbacks to make
2017-01-19 08:54:57.412 CST [31695] DEBUG:  shmem_exit(-1): 0 on_shmem_exit callbacks to make
2017-01-19 08:54:57.412 CST [31695] DEBUG:  proc_exit(-1): 0 callbacks to make
2017-01-19 08:54:57.412 CST [31697] DEBUG:  writing stats file "pg_stat/global.stat"
2017-01-19 08:54:57.412 CST [31694] DEBUG:  shmem_exit(-1): 0 before_shmem_exit callbacks to make
2017-01-19 08:54:57.412 CST [31697] DEBUG:  writing stats file "pg_stat/db_12254.stat"
2017-01-19 08:54:57.412 CST [31694] DEBUG:  shmem_exit(-1): 0 on_shmem_exit callbacks to make
2017-01-19 08:54:57.412 CST [31694] DEBUG:  proc_exit(-1): 0 callbacks to make
2017-01-19 08:54:57.412 CST [31697] DEBUG:  removing temporary stats file "pg_stat_tmp/db_12254.stat"
2017-01-19 08:54:57.412 CST [31697] DEBUG:  writing stats file "pg_stat/db_16385.stat"
2017-01-19 08:54:57.413 CST [31697] DEBUG:  removing temporary stats file "pg_stat_tmp/db_16385.stat"
2017-01-19 08:54:57.413 CST [31697] DEBUG:  writing stats file "pg_stat/db_0.stat"
2017-01-19 08:54:57.413 CST [31690] DEBUG:  reaping dead processes
2017-01-19 08:54:57.413 CST [31697] DEBUG:  removing temporary stats file "pg_stat_tmp/db_0.stat"
2017-01-19 08:54:57.413 CST [31690] DEBUG:  reaping dead processes
2017-01-19 08:54:57.413 CST [31697] DEBUG:  shmem_exit(-1): 0 before_shmem_exit callbacks to make
2017-01-19 08:54:57.413 CST [31697] DEBUG:  shmem_exit(-1): 0 on_shmem_exit callbacks to make
2017-01-19 08:54:57.413 CST [31697] DEBUG:  proc_exit(-1): 0 callbacks to make
2017-01-19 08:54:57.413 CST [31690] DEBUG:  reaping dead processes
2017-01-19 08:54:57.413 CST [31690] DEBUG:  reaping dead processes
2017-01-19 08:54:57.413 CST [31690] LOG:  all server processes terminated; reinitializing
2017-01-19 08:54:57.413 CST [31690] DEBUG:  shmem_exit(1): 0 before_shmem_exit callbacks to make
2017-01-19 08:54:57.413 CST [31690] DEBUG:  shmem_exit(1): 5 on_shmem_exit callbacks to make
2017-01-19 08:54:57.413 CST [31690] DEBUG:  cleaning up dynamic shared memory control segment with ID 141917387
2017-01-19 08:54:57.418 CST [31690] DEBUG:  invoking IpcMemoryCreate(size=574734336)
2017-01-19 08:54:57.431 CST [31690] DEBUG:  SlruScanDirectory invoking callback on pg_notify/0000
2017-01-19 08:54:57.431 CST [31690] DEBUG:  removing file "pg_notify/0000"
2017-01-19 08:54:57.431 CST [31690] DEBUG:  dynamic shared memory system will support 288 segments
2017-01-19 08:54:57.431 CST [31690] DEBUG:  created dynamic shared memory control segment 1621489222 (6928 bytes)
2017-01-19 08:54:57.432 CST [31690] DEBUG:  forked new backend, pid=31737 socket=10
2017-01-19 08:54:57.432 CST [31736] LOG:  database system was interrupted; last known up at 2017-01-19 08:54:25 CST
2017-01-19 08:54:57.432 CST [31737] LOG:  connection received: host=172.16.45.144 port=59096
2017-01-19 08:54:57.432 CST [31737] FATAL:  the database system is in recovery mode
2017-01-19 08:54:57.432 CST [31737] DEBUG:  shmem_exit(1): 0 before_shmem_exit callbacks to make
2017-01-19 08:54:57.432 CST [31737] DEBUG:  shmem_exit(1): 0 on_shmem_exit callbacks to make
2017-01-19 08:54:57.432 CST [31737] DEBUG:  proc_exit(1): 1 callbacks to make
2017-01-19 08:54:57.432 CST [31737] DEBUG:  exit(1)
2017-01-19 08:54:57.432 CST [31737] DEBUG:  shmem_exit(-1): 0 before_shmem_exit callbacks to make
2017-01-19 08:54:57.432 CST [31737] DEBUG:  shmem_exit(-1): 0 on_shmem_exit callbacks to make
2017-01-19 08:54:57.432 CST [31737] DEBUG:  proc_exit(-1): 0 callbacks to make
2017-01-19 08:54:57.433 CST [31690] DEBUG:  reaping dead processes
2017-01-19 08:54:57.433 CST [31690] DEBUG:  server process (PID 31737) exited with exit code 1
2017-01-19 08:54:57.437 CST [31690] DEBUG:  forked new backend, pid=31738 socket=10
2017-01-19 08:54:57.437 CST [31738] LOG:  connection received: host=172.16.45.144 port=59098
2017-01-19 08:54:57.437 CST [31738] FATAL:  the database system is in recovery mode
2017-01-19 08:54:57.437 CST [31738] DEBUG:  shmem_exit(1): 0 before_shmem_exit callbacks to make
2017-01-19 08:54:57.437 CST [31738] DEBUG:  shmem_exit(1): 0 on_shmem_exit callbacks to make
2017-01-19 08:54:57.437 CST [31738] DEBUG:  proc_exit(1): 1 callbacks to make
2017-01-19 08:54:57.437 CST [31738] DEBUG:  exit(1)
2017-01-19 08:54:57.437 CST [31738] DEBUG:  shmem_exit(-1): 0 before_shmem_exit callbacks to make
2017-01-19 08:54:57.437 CST [31738] DEBUG:  shmem_exit(-1): 0 on_shmem_exit callbacks to make
2017-01-19 08:54:57.437 CST [31738] DEBUG:  proc_exit(-1): 0 callbacks to make
2017-01-19 08:54:57.438 CST [31690] DEBUG:  reaping dead processes
2017-01-19 08:54:57.438 CST [31690] DEBUG:  server process (PID 31738) exited with exit code 1
2017-01-19 08:54:57.439 CST [31690] DEBUG:  forked new backend, pid=31739 socket=10
2017-01-19 08:54:57.440 CST [31739] LOG:  connection received: host=172.16.45.144 port=59100
2017-01-19 08:54:57.440 CST [31739] FATAL:  the database system is in recovery mode
2017-01-19 08:54:57.440 CST [31739] DEBUG:  shmem_exit(1): 0 before_shmem_exit callbacks to make
2017-01-19 08:54:57.440 CST [31739] DEBUG:  shmem_exit(1): 0 on_shmem_exit callbacks to make
2017-01-19 08:54:57.440 CST [31739] DEBUG:  proc_exit(1): 1 callbacks to make
2017-01-19 08:54:57.440 CST [31739] DEBUG:  exit(1)
2017-01-19 08:54:57.440 CST [31739] DEBUG:  shmem_exit(-1): 0 before_shmem_exit callbacks to make
2017-01-19 08:54:57.440 CST [31739] DEBUG:  shmem_exit(-1): 0 on_shmem_exit callbacks to make
2017-01-19 08:54:57.440 CST [31739] DEBUG:  proc_exit(-1): 0 callbacks to make
2017-01-19 08:54:57.441 CST [31690] DEBUG:  reaping dead processes
2017-01-19 08:54:57.441 CST [31690] DEBUG:  server process (PID 31739) exited with exit code 1
2017-01-19 08:54:57.442 CST [31690] DEBUG:  forked new backend, pid=31740 socket=10
2017-01-19 08:54:57.444 CST [31740] LOG:  connection received: host=172.16.45.144 port=59102
2017-01-19 08:54:57.444 CST [31740] FATAL:  the database system is in recovery mode
2017-01-19 08:54:57.444 CST [31740] DEBUG:  shmem_exit(1): 0 before_shmem_exit callbacks to make
2017-01-19 08:54:57.444 CST [31740] DEBUG:  shmem_exit(1): 0 on_shmem_exit callbacks to make
2017-01-19 08:54:57.444 CST [31740] DEBUG:  proc_exit(1): 1 callbacks to make
2017-01-19 08:54:57.444 CST [31740] DEBUG:  exit(1)
2017-01-19 08:54:57.444 CST [31740] DEBUG:  shmem_exit(-1): 0 before_shmem_exit callbacks to make
2017-01-19 08:54:57.444 CST [31740] DEBUG:  shmem_exit(-1): 0 on_shmem_exit callbacks to make
2017-01-19 08:54:57.444 CST [31740] DEBUG:  proc_exit(-1): 0 callbacks to make
2017-01-19 08:54:57.445 CST [31690] DEBUG:  reaping dead processes
2017-01-19 08:54:57.445 CST [31690] DEBUG:  server process (PID 31740) exited with exit code 1
2017-01-19 08:54:57.448 CST [31690] DEBUG:  forked new backend, pid=31741 socket=10
2017-01-19 08:54:57.449 CST [31741] LOG:  connection received: host=172.16.45.144 port=59104
2017-01-19 08:54:57.450 CST [31741] FATAL:  the database system is in recovery mode
2017-01-19 08:54:57.450 CST [31741] DEBUG:  shmem_exit(1): 0 before_shmem_exit callbacks to make
2017-01-19 08:54:57.450 CST [31741] DEBUG:  shmem_exit(1): 0 on_shmem_exit callbacks to make
2017-01-19 08:54:57.450 CST [31741] DEBUG:  proc_exit(1): 1 callbacks to make
2017-01-19 08:54:57.450 CST [31741] DEBUG:  exit(1)
2017-01-19 08:54:57.450 CST [31741] DEBUG:  shmem_exit(-1): 0 before_shmem_exit callbacks to make
2017-01-19 08:54:57.450 CST [31741] DEBUG:  shmem_exit(-1): 0 on_shmem_exit callbacks to make
2017-01-19 08:54:57.450 CST [31741] DEBUG:  proc_exit(-1): 0 callbacks to make
2017-01-19 08:54:57.452 CST [31690] DEBUG:  reaping dead processes
2017-01-19 08:54:57.453 CST [31690] DEBUG:  server process (PID 31741) exited with exit code 1
2017-01-19 08:54:57.454 CST [31690] DEBUG:  forked new backend, pid=31742 socket=10
2017-01-19 08:54:57.455 CST [31742] LOG:  connection received: host=172.16.45.144 port=59106
2017-01-19 08:54:57.455 CST [31742] FATAL:  the database system is in recovery mode
2017-01-19 08:54:57.455 CST [31742] DEBUG:  shmem_exit(1): 0 before_shmem_exit callbacks to make
2017-01-19 08:54:57.455 CST [31742] DEBUG:  shmem_exit(1): 0 on_shmem_exit callbacks to make
2017-01-19 08:54:57.455 CST [31742] DEBUG:  proc_exit(1): 1 callbacks to make
2017-01-19 08:54:57.455 CST [31742] DEBUG:  exit(1)
2017-01-19 08:54:57.455 CST [31742] DEBUG:  shmem_exit(-1): 0 before_shmem_exit callbacks to make
2017-01-19 08:54:57.455 CST [31742] DEBUG:  shmem_exit(-1): 0 on_shmem_exit callbacks to make
2017-01-19 08:54:57.455 CST [31742] DEBUG:  proc_exit(-1): 0 callbacks to make
2017-01-19 08:54:57.455 CST [31690] DEBUG:  reaping dead processes
2017-01-19 08:54:57.455 CST [31690] DEBUG:  server process (PID 31742) exited with exit code 1
2017-01-19 08:54:57.458 CST [31690] DEBUG:  forked new backend, pid=31743 socket=10



On Thu, Jan 19, 2017 at 10:53 AM, Robert Haas <robertmhaas@gmail.com> wrote:
On Thu, Jan 19, 2017 at 10:59 AM, Jorge Solórzano <jorsol@gmail.com> wrote:
> I have isolated the tests run by the pgjdbc project, I have disabled the
> replication (wal_level = minimal) and the error is still present so it seems
> that this error is not related to the replication, the test that cause the
> error is AutoRollbackTestSuite, I have enable DEBUG mesages in postgresql
> and pgjdbc and this is what I get:
>
> https://drive.google.com/drive/folders/0ByHbu-sR29gda2d2LUFpV0lPdUk

Can somebody paste the stack trace into an email, here?  There's
reference to it upthread, but it's not obvious where it actually is.

--
Robert Haas
EnterpriseDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company


Re: [HACKERS] [JDBC] SEGFAULT in HEAD with replication

От
Dave Cramer
Дата:
I would have expected more, but this is what I have

 bt full
#0  InitPredicateLocks () at predicate.c:1250
        i = <optimized out>
        info = {num_partitions = 1, ssize = 140731424825288, dsize = 1, 
          max_dsize = 0, ffactor = 140731424836952, keysize = 140356326474085, 
          entrysize = 140728909791233, hash = 0x7ffe96960d58, 
          match = 0x16da2d1, keycopy = 0x7ffe96960d58, alloc = 0x1703af0, 
          hcxt = 0x16da2d0, hctl = 0x0}
        max_table_size = 117899280
        requestSize = <optimized out>
        found = 0 '\000'


Dave Cramer

On 19 January 2017 at 12:05, Dave Cramer <davecramer@gmail.com> wrote:
I'll try to get the stack trace from the core dump, have to build master first

Dave Cramer

On 19 January 2017 at 12:01, Jorge Solórzano <jorsol@gmail.com> wrote:
Robert, the logs I get from postgres (at least the section that matters) is here:
If you need something else just ask...

2017-01-19 08:54:57.319 CST [31734] DEBUG:  CommitTransaction(1) name: unnamed; blockState: STARTED; state: INPROGR, xid/subid/cid: 0/1/0
2017-01-19 08:54:57.321 CST [31734] DEBUG:  parse S_1: DROP TABLE rollbacktest CASCADE
2017-01-19 08:54:57.321 CST [31734] STATEMENT:  DROP TABLE rollbacktest CASCADE
2017-01-19 08:54:57.321 CST [31734] DEBUG:  StartTransaction(1) name: unnamed; blockState: DEFAULT; state: INPROGR, xid/subid/cid: 0/1/0
2017-01-19 08:54:57.321 CST [31734] STATEMENT:  DROP TABLE rollbacktest CASCADE
2017-01-19 08:54:57.321 CST [31734] LOG:  duration: 0.289 ms
2017-01-19 08:54:57.321 CST [31734] DEBUG:  bind <unnamed> to S_1
2017-01-19 08:54:57.321 CST [31734] LOG:  duration: 0.073 ms
2017-01-19 08:54:57.321 CST [31734] LOG:  execute S_1: DROP TABLE rollbacktest CASCADE
2017-01-19 08:54:57.321 CST [31734] ERROR:  table "rollbacktest" does not exist
2017-01-19 08:54:57.321 CST [31734] STATEMENT:  DROP TABLE rollbacktest CASCADE
2017-01-19 08:54:57.322 CST [31734] DEBUG:  parse S_2: CREATE TABLE rollbacktest (a int, str text)
2017-01-19 08:54:57.322 CST [31734] STATEMENT:  CREATE TABLE rollbacktest (a int, str text)
2017-01-19 08:54:57.322 CST [31734] DEBUG:  StartTransaction(1) name: unnamed; blockState: DEFAULT; state: INPROGR, xid/subid/cid: 0/1/0
2017-01-19 08:54:57.322 CST [31734] STATEMENT:  CREATE TABLE rollbacktest (a int, str text)
2017-01-19 08:54:57.322 CST [31734] LOG:  duration: 0.279 ms
2017-01-19 08:54:57.323 CST [31734] DEBUG:  bind <unnamed> to S_2
2017-01-19 08:54:57.323 CST [31734] LOG:  duration: 0.163 ms
2017-01-19 08:54:57.323 CST [31734] LOG:  execute S_2: CREATE TABLE rollbacktest (a int, str text)
2017-01-19 08:54:57.324 CST [31734] DEBUG:  building index "pg_toast_163960_index" on table "pg_toast_163960"
2017-01-19 08:54:57.324 CST [31734] STATEMENT:  CREATE TABLE rollbacktest (a int, str text)
2017-01-19 08:54:57.327 CST [31734] LOG:  duration: 4.232 ms
2017-01-19 08:54:57.327 CST [31734] DEBUG:  CommitTransaction(1) name: unnamed; blockState: STARTED; state: INPROGR, xid/subid/cid: 270571/1/5
2017-01-19 08:54:57.329 CST [31734] DEBUG:  parse S_3:
2017-01-19 08:54:57.329 CST [31734] STATEMENT: 
2017-01-19 08:54:57.329 CST [31734] DEBUG:  StartTransaction(1) name: unnamed; blockState: DEFAULT; state: INPROGR, xid/subid/cid: 0/1/0
2017-01-19 08:54:57.329 CST [31734] STATEMENT: 
2017-01-19 08:54:57.329 CST [31734] LOG:  duration: 0.148 ms
2017-01-19 08:54:57.329 CST [31734] DEBUG:  bind <unnamed> to S_3
2017-01-19 08:54:57.329 CST [31734] LOG:  duration: 0.088 ms
2017-01-19 08:54:57.329 CST [31734] DEBUG:  CommitTransaction(1) name: unnamed; blockState: STARTED; state: INPROGR, xid/subid/cid: 0/1/0
2017-01-19 08:54:57.330 CST [31734] DEBUG:  parse S_4: BEGIN
2017-01-19 08:54:57.330 CST [31734] STATEMENT:  BEGIN
2017-01-19 08:54:57.330 CST [31734] DEBUG:  StartTransaction(1) name: unnamed; blockState: DEFAULT; state: INPROGR, xid/subid/cid: 0/1/0
2017-01-19 08:54:57.330 CST [31734] STATEMENT:  BEGIN
2017-01-19 08:54:57.331 CST [31734] LOG:  duration: 0.189 ms
2017-01-19 08:54:57.331 CST [31734] DEBUG:  bind <unnamed> to S_4
2017-01-19 08:54:57.331 CST [31734] LOG:  duration: 0.105 ms
2017-01-19 08:54:57.331 CST [31734] LOG:  execute S_4: BEGIN
2017-01-19 08:54:57.331 CST [31734] LOG:  duration: 0.154 ms
2017-01-19 08:54:57.331 CST [31734] DEBUG:  parse S_5: insert into rollbacktest(a, str) values (0, 'test')
2017-01-19 08:54:57.331 CST [31734] STATEMENT:  insert into rollbacktest(a, str) values (0, 'test')
2017-01-19 08:54:57.331 CST [31734] LOG:  duration: 0.277 ms
2017-01-19 08:54:57.332 CST [31734] DEBUG:  bind <unnamed> to S_5
2017-01-19 08:54:57.332 CST [31734] LOG:  duration: 0.168 ms
2017-01-19 08:54:57.332 CST [31734] LOG:  execute S_5: insert into rollbacktest(a, str) values (0, 'test')
2017-01-19 08:54:57.332 CST [31734] LOG:  duration: 0.233 ms
2017-01-19 08:54:57.333 CST [31734] DEBUG:  parse S_6: select * from rollbacktest
2017-01-19 08:54:57.333 CST [31734] STATEMENT:  select * from rollbacktest
2017-01-19 08:54:57.333 CST [31734] LOG:  duration: 0.093 ms
2017-01-19 08:54:57.333 CST [31734] DEBUG:  bind <unnamed> to S_6
2017-01-19 08:54:57.333 CST [31734] LOG:  duration: 0.188 ms
2017-01-19 08:54:57.333 CST [31734] LOG:  execute S_6: select * from rollbacktest
2017-01-19 08:54:57.333 CST [31734] LOG:  duration: 0.094 ms
2017-01-19 08:54:57.334 CST [31734] DEBUG:  parse S_7: select 1/0
2017-01-19 08:54:57.334 CST [31734] STATEMENT:  select 1/0
2017-01-19 08:54:57.334 CST [31734] LOG:  duration: 0.174 ms
2017-01-19 08:54:57.334 CST [31734] DEBUG:  bind <unnamed> to S_7
2017-01-19 08:54:57.334 CST [31734] ERROR:  division by zero
2017-01-19 08:54:57.334 CST [31734] STATEMENT:  select 1/0
2017-01-19 08:54:57.335 CST [31734] DEBUG:  bind <unnamed> to S_3
2017-01-19 08:54:57.412 CST [31690] DEBUG:  reaping dead processes
2017-01-19 08:54:57.412 CST [31690] DEBUG:  server process (PID 31734) was terminated by signal 11: Segmentation fault
2017-01-19 08:54:57.412 CST [31690] LOG:  server process (PID 31734) was terminated by signal 11: Segmentation fault
2017-01-19 08:54:57.412 CST [31690] LOG:  terminating any other active server processes
2017-01-19 08:54:57.412 CST [31690] DEBUG:  sending SIGQUIT to process 31694
2017-01-19 08:54:57.412 CST [31690] DEBUG:  sending SIGQUIT to process 31693
2017-01-19 08:54:57.412 CST [31690] DEBUG:  sending SIGQUIT to process 31695
2017-01-19 08:54:57.412 CST [31690] DEBUG:  sending SIGQUIT to process 31696
2017-01-19 08:54:57.412 CST [31690] DEBUG:  sending SIGQUIT to process 31697
2017-01-19 08:54:57.412 CST [31693] DEBUG:  shmem_exit(-1): 0 before_shmem_exit callbacks to make
2017-01-19 08:54:57.412 CST [31693] DEBUG:  shmem_exit(-1): 0 on_shmem_exit callbacks to make
2017-01-19 08:54:57.412 CST [31693] DEBUG:  proc_exit(-1): 0 callbacks to make
2017-01-19 08:54:57.412 CST [31696] WARNING:  terminating connection because of crash of another server process
2017-01-19 08:54:57.412 CST [31696] 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.
2017-01-19 08:54:57.412 CST [31696] HINT:  In a moment you should be able to reconnect to the database and repeat your command.
2017-01-19 08:54:57.412 CST [31696] DEBUG:  shmem_exit(-1): 0 before_shmem_exit callbacks to make
2017-01-19 08:54:57.412 CST [31696] DEBUG:  shmem_exit(-1): 0 on_shmem_exit callbacks to make
2017-01-19 08:54:57.412 CST [31696] DEBUG:  proc_exit(-1): 0 callbacks to make
2017-01-19 08:54:57.412 CST [31695] DEBUG:  shmem_exit(-1): 0 before_shmem_exit callbacks to make
2017-01-19 08:54:57.412 CST [31695] DEBUG:  shmem_exit(-1): 0 on_shmem_exit callbacks to make
2017-01-19 08:54:57.412 CST [31695] DEBUG:  proc_exit(-1): 0 callbacks to make
2017-01-19 08:54:57.412 CST [31697] DEBUG:  writing stats file "pg_stat/global.stat"
2017-01-19 08:54:57.412 CST [31694] DEBUG:  shmem_exit(-1): 0 before_shmem_exit callbacks to make
2017-01-19 08:54:57.412 CST [31697] DEBUG:  writing stats file "pg_stat/db_12254.stat"
2017-01-19 08:54:57.412 CST [31694] DEBUG:  shmem_exit(-1): 0 on_shmem_exit callbacks to make
2017-01-19 08:54:57.412 CST [31694] DEBUG:  proc_exit(-1): 0 callbacks to make
2017-01-19 08:54:57.412 CST [31697] DEBUG:  removing temporary stats file "pg_stat_tmp/db_12254.stat"
2017-01-19 08:54:57.412 CST [31697] DEBUG:  writing stats file "pg_stat/db_16385.stat"
2017-01-19 08:54:57.413 CST [31697] DEBUG:  removing temporary stats file "pg_stat_tmp/db_16385.stat"
2017-01-19 08:54:57.413 CST [31697] DEBUG:  writing stats file "pg_stat/db_0.stat"
2017-01-19 08:54:57.413 CST [31690] DEBUG:  reaping dead processes
2017-01-19 08:54:57.413 CST [31697] DEBUG:  removing temporary stats file "pg_stat_tmp/db_0.stat"
2017-01-19 08:54:57.413 CST [31690] DEBUG:  reaping dead processes
2017-01-19 08:54:57.413 CST [31697] DEBUG:  shmem_exit(-1): 0 before_shmem_exit callbacks to make
2017-01-19 08:54:57.413 CST [31697] DEBUG:  shmem_exit(-1): 0 on_shmem_exit callbacks to make
2017-01-19 08:54:57.413 CST [31697] DEBUG:  proc_exit(-1): 0 callbacks to make
2017-01-19 08:54:57.413 CST [31690] DEBUG:  reaping dead processes
2017-01-19 08:54:57.413 CST [31690] DEBUG:  reaping dead processes
2017-01-19 08:54:57.413 CST [31690] LOG:  all server processes terminated; reinitializing
2017-01-19 08:54:57.413 CST [31690] DEBUG:  shmem_exit(1): 0 before_shmem_exit callbacks to make
2017-01-19 08:54:57.413 CST [31690] DEBUG:  shmem_exit(1): 5 on_shmem_exit callbacks to make
2017-01-19 08:54:57.413 CST [31690] DEBUG:  cleaning up dynamic shared memory control segment with ID 141917387
2017-01-19 08:54:57.418 CST [31690] DEBUG:  invoking IpcMemoryCreate(size=574734336)
2017-01-19 08:54:57.431 CST [31690] DEBUG:  SlruScanDirectory invoking callback on pg_notify/0000
2017-01-19 08:54:57.431 CST [31690] DEBUG:  removing file "pg_notify/0000"
2017-01-19 08:54:57.431 CST [31690] DEBUG:  dynamic shared memory system will support 288 segments
2017-01-19 08:54:57.431 CST [31690] DEBUG:  created dynamic shared memory control segment 1621489222 (6928 bytes)
2017-01-19 08:54:57.432 CST [31690] DEBUG:  forked new backend, pid=31737 socket=10
2017-01-19 08:54:57.432 CST [31736] LOG:  database system was interrupted; last known up at 2017-01-19 08:54:25 CST
2017-01-19 08:54:57.432 CST [31737] LOG:  connection received: host=172.16.45.144 port=59096
2017-01-19 08:54:57.432 CST [31737] FATAL:  the database system is in recovery mode
2017-01-19 08:54:57.432 CST [31737] DEBUG:  shmem_exit(1): 0 before_shmem_exit callbacks to make
2017-01-19 08:54:57.432 CST [31737] DEBUG:  shmem_exit(1): 0 on_shmem_exit callbacks to make
2017-01-19 08:54:57.432 CST [31737] DEBUG:  proc_exit(1): 1 callbacks to make
2017-01-19 08:54:57.432 CST [31737] DEBUG:  exit(1)
2017-01-19 08:54:57.432 CST [31737] DEBUG:  shmem_exit(-1): 0 before_shmem_exit callbacks to make
2017-01-19 08:54:57.432 CST [31737] DEBUG:  shmem_exit(-1): 0 on_shmem_exit callbacks to make
2017-01-19 08:54:57.432 CST [31737] DEBUG:  proc_exit(-1): 0 callbacks to make
2017-01-19 08:54:57.433 CST [31690] DEBUG:  reaping dead processes
2017-01-19 08:54:57.433 CST [31690] DEBUG:  server process (PID 31737) exited with exit code 1
2017-01-19 08:54:57.437 CST [31690] DEBUG:  forked new backend, pid=31738 socket=10
2017-01-19 08:54:57.437 CST [31738] LOG:  connection received: host=172.16.45.144 port=59098
2017-01-19 08:54:57.437 CST [31738] FATAL:  the database system is in recovery mode
2017-01-19 08:54:57.437 CST [31738] DEBUG:  shmem_exit(1): 0 before_shmem_exit callbacks to make
2017-01-19 08:54:57.437 CST [31738] DEBUG:  shmem_exit(1): 0 on_shmem_exit callbacks to make
2017-01-19 08:54:57.437 CST [31738] DEBUG:  proc_exit(1): 1 callbacks to make
2017-01-19 08:54:57.437 CST [31738] DEBUG:  exit(1)
2017-01-19 08:54:57.437 CST [31738] DEBUG:  shmem_exit(-1): 0 before_shmem_exit callbacks to make
2017-01-19 08:54:57.437 CST [31738] DEBUG:  shmem_exit(-1): 0 on_shmem_exit callbacks to make
2017-01-19 08:54:57.437 CST [31738] DEBUG:  proc_exit(-1): 0 callbacks to make
2017-01-19 08:54:57.438 CST [31690] DEBUG:  reaping dead processes
2017-01-19 08:54:57.438 CST [31690] DEBUG:  server process (PID 31738) exited with exit code 1
2017-01-19 08:54:57.439 CST [31690] DEBUG:  forked new backend, pid=31739 socket=10
2017-01-19 08:54:57.440 CST [31739] LOG:  connection received: host=172.16.45.144 port=59100
2017-01-19 08:54:57.440 CST [31739] FATAL:  the database system is in recovery mode
2017-01-19 08:54:57.440 CST [31739] DEBUG:  shmem_exit(1): 0 before_shmem_exit callbacks to make
2017-01-19 08:54:57.440 CST [31739] DEBUG:  shmem_exit(1): 0 on_shmem_exit callbacks to make
2017-01-19 08:54:57.440 CST [31739] DEBUG:  proc_exit(1): 1 callbacks to make
2017-01-19 08:54:57.440 CST [31739] DEBUG:  exit(1)
2017-01-19 08:54:57.440 CST [31739] DEBUG:  shmem_exit(-1): 0 before_shmem_exit callbacks to make
2017-01-19 08:54:57.440 CST [31739] DEBUG:  shmem_exit(-1): 0 on_shmem_exit callbacks to make
2017-01-19 08:54:57.440 CST [31739] DEBUG:  proc_exit(-1): 0 callbacks to make
2017-01-19 08:54:57.441 CST [31690] DEBUG:  reaping dead processes
2017-01-19 08:54:57.441 CST [31690] DEBUG:  server process (PID 31739) exited with exit code 1
2017-01-19 08:54:57.442 CST [31690] DEBUG:  forked new backend, pid=31740 socket=10
2017-01-19 08:54:57.444 CST [31740] LOG:  connection received: host=172.16.45.144 port=59102
2017-01-19 08:54:57.444 CST [31740] FATAL:  the database system is in recovery mode
2017-01-19 08:54:57.444 CST [31740] DEBUG:  shmem_exit(1): 0 before_shmem_exit callbacks to make
2017-01-19 08:54:57.444 CST [31740] DEBUG:  shmem_exit(1): 0 on_shmem_exit callbacks to make
2017-01-19 08:54:57.444 CST [31740] DEBUG:  proc_exit(1): 1 callbacks to make
2017-01-19 08:54:57.444 CST [31740] DEBUG:  exit(1)
2017-01-19 08:54:57.444 CST [31740] DEBUG:  shmem_exit(-1): 0 before_shmem_exit callbacks to make
2017-01-19 08:54:57.444 CST [31740] DEBUG:  shmem_exit(-1): 0 on_shmem_exit callbacks to make
2017-01-19 08:54:57.444 CST [31740] DEBUG:  proc_exit(-1): 0 callbacks to make
2017-01-19 08:54:57.445 CST [31690] DEBUG:  reaping dead processes
2017-01-19 08:54:57.445 CST [31690] DEBUG:  server process (PID 31740) exited with exit code 1
2017-01-19 08:54:57.448 CST [31690] DEBUG:  forked new backend, pid=31741 socket=10
2017-01-19 08:54:57.449 CST [31741] LOG:  connection received: host=172.16.45.144 port=59104
2017-01-19 08:54:57.450 CST [31741] FATAL:  the database system is in recovery mode
2017-01-19 08:54:57.450 CST [31741] DEBUG:  shmem_exit(1): 0 before_shmem_exit callbacks to make
2017-01-19 08:54:57.450 CST [31741] DEBUG:  shmem_exit(1): 0 on_shmem_exit callbacks to make
2017-01-19 08:54:57.450 CST [31741] DEBUG:  proc_exit(1): 1 callbacks to make
2017-01-19 08:54:57.450 CST [31741] DEBUG:  exit(1)
2017-01-19 08:54:57.450 CST [31741] DEBUG:  shmem_exit(-1): 0 before_shmem_exit callbacks to make
2017-01-19 08:54:57.450 CST [31741] DEBUG:  shmem_exit(-1): 0 on_shmem_exit callbacks to make
2017-01-19 08:54:57.450 CST [31741] DEBUG:  proc_exit(-1): 0 callbacks to make
2017-01-19 08:54:57.452 CST [31690] DEBUG:  reaping dead processes
2017-01-19 08:54:57.453 CST [31690] DEBUG:  server process (PID 31741) exited with exit code 1
2017-01-19 08:54:57.454 CST [31690] DEBUG:  forked new backend, pid=31742 socket=10
2017-01-19 08:54:57.455 CST [31742] LOG:  connection received: host=172.16.45.144 port=59106
2017-01-19 08:54:57.455 CST [31742] FATAL:  the database system is in recovery mode
2017-01-19 08:54:57.455 CST [31742] DEBUG:  shmem_exit(1): 0 before_shmem_exit callbacks to make
2017-01-19 08:54:57.455 CST [31742] DEBUG:  shmem_exit(1): 0 on_shmem_exit callbacks to make
2017-01-19 08:54:57.455 CST [31742] DEBUG:  proc_exit(1): 1 callbacks to make
2017-01-19 08:54:57.455 CST [31742] DEBUG:  exit(1)
2017-01-19 08:54:57.455 CST [31742] DEBUG:  shmem_exit(-1): 0 before_shmem_exit callbacks to make
2017-01-19 08:54:57.455 CST [31742] DEBUG:  shmem_exit(-1): 0 on_shmem_exit callbacks to make
2017-01-19 08:54:57.455 CST [31742] DEBUG:  proc_exit(-1): 0 callbacks to make
2017-01-19 08:54:57.455 CST [31690] DEBUG:  reaping dead processes
2017-01-19 08:54:57.455 CST [31690] DEBUG:  server process (PID 31742) exited with exit code 1
2017-01-19 08:54:57.458 CST [31690] DEBUG:  forked new backend, pid=31743 socket=10



On Thu, Jan 19, 2017 at 10:53 AM, Robert Haas <robertmhaas@gmail.com> wrote:
On Thu, Jan 19, 2017 at 10:59 AM, Jorge Solórzano <jorsol@gmail.com> wrote:
> I have isolated the tests run by the pgjdbc project, I have disabled the
> replication (wal_level = minimal) and the error is still present so it seems
> that this error is not related to the replication, the test that cause the
> error is AutoRollbackTestSuite, I have enable DEBUG mesages in postgresql
> and pgjdbc and this is what I get:
>
> https://drive.google.com/drive/folders/0ByHbu-sR29gda2d2LUFpV0lPdUk

Can somebody paste the stack trace into an email, here?  There's
reference to it upthread, but it's not obvious where it actually is.

--
Robert Haas
EnterpriseDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company



Re: [HACKERS] [JDBC] SEGFAULT in HEAD with replication

От
Robert Haas
Дата:
On Thu, Jan 19, 2017 at 12:01 PM, Jorge Solórzano <jorsol@gmail.com> wrote:
> Robert, the logs I get from postgres (at least the section that matters) is
> here:
> If you need something else just ask...

That shows that there is a crash, but there's no stack trace in there.
Someone needs to get a core dump and use "gdb" to get  stack trace.

--
Robert Haas
EnterpriseDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company

Re: [HACKERS] [JDBC] SEGFAULT in HEAD with replication

От
Robert Haas
Дата:
On Thu, Jan 19, 2017 at 12:09 PM, Dave Cramer <davecramer@gmail.com> wrote:
> I would have expected more, but this is what I have
>
>  bt full
> #0  InitPredicateLocks () at predicate.c:1250
>         i = <optimized out>
>         info = {num_partitions = 1, ssize = 140731424825288, dsize = 1,
>           max_dsize = 0, ffactor = 140731424836952, keysize =
> 140356326474085,
>           entrysize = 140728909791233, hash = 0x7ffe96960d58,
>           match = 0x16da2d1, keycopy = 0x7ffe96960d58, alloc = 0x1703af0,
>           hcxt = 0x16da2d0, hctl = 0x0}
>         max_table_size = 117899280
>         requestSize = <optimized out>
>         found = 0 '\000'

I would say that's not a valid stack trace.  There hasn't been a
change made to that file since October of last year, and the crash is
apparently recent; also, line 1250 in that file doesn't look like
something that can crash.  I would guess that you're using an
executable which doesn't match the core dump, or perhaps that you
don't have complete debug symbols.  Building with -O0 might help.

--
Robert Haas
EnterpriseDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company

Re: [HACKERS] [JDBC] SEGFAULT in HEAD with replication

От
Craig Ringer
Дата:


On 20 Jan. 2017 04:13, "Robert Haas" <robertmhaas@gmail.com> wrote:
On Thu, Jan 19, 2017 at 12:09 PM, Dave Cramer <davecramer@gmail.com> wrote:
> I would have expected more, but this is what I have
>
>  bt full
> #0  InitPredicateLocks () at predicate.c:1250
>         i = <optimized out>
>         info = {num_partitions = 1, ssize = 140731424825288, dsize = 1,
>           max_dsize = 0, ffactor = 140731424836952, keysize =
> 140356326474085,
>           entrysize = 140728909791233, hash = 0x7ffe96960d58,
>           match = 0x16da2d1, keycopy = 0x7ffe96960d58, alloc = 0x1703af0,
>           hcxt = 0x16da2d0, hctl = 0x0}
>         max_table_size = 117899280
>         requestSize = <optimized out>
>         found = 0 '\000'

I would say that's not a valid stack trace.  There hasn't been a
change made to that file since October of last year, and the crash is
apparently recent; also, line 1250 in that file doesn't look like
something that can crash.  I would guess that you're using an
executable which doesn't match the core dump, or perhaps that you
don't have complete debug symbols.

You really need the same compiler flags, configure opts and preferably much the same compiler. Similar or same C library etc. 

Can't we get the executables from Travis CI or from whoever produced the core? Or get them to obtain a bt ?

Re: [HACKERS] [JDBC] SEGFAULT in HEAD with replication

От
Dave Cramer
Дата:
Not sure you can get the exec. We are working on producing the BT from Travis-CI or I will build and run the test locally and get the trace

Dave Cramer

On 19 January 2017 at 15:31, Craig Ringer <craig.ringer@2ndquadrant.com> wrote:


On 20 Jan. 2017 04:13, "Robert Haas" <robertmhaas@gmail.com> wrote:
On Thu, Jan 19, 2017 at 12:09 PM, Dave Cramer <davecramer@gmail.com> wrote:
> I would have expected more, but this is what I have
>
>  bt full
> #0  InitPredicateLocks () at predicate.c:1250
>         i = <optimized out>
>         info = {num_partitions = 1, ssize = 140731424825288, dsize = 1,
>           max_dsize = 0, ffactor = 140731424836952, keysize =
> 140356326474085,
>           entrysize = 140728909791233, hash = 0x7ffe96960d58,
>           match = 0x16da2d1, keycopy = 0x7ffe96960d58, alloc = 0x1703af0,
>           hcxt = 0x16da2d0, hctl = 0x0}
>         max_table_size = 117899280
>         requestSize = <optimized out>
>         found = 0 '\000'

I would say that's not a valid stack trace.  There hasn't been a
change made to that file since October of last year, and the crash is
apparently recent; also, line 1250 in that file doesn't look like
something that can crash.  I would guess that you're using an
executable which doesn't match the core dump, or perhaps that you
don't have complete debug symbols.

You really need the same compiler flags, configure opts and preferably much the same compiler. Similar or same C library etc. 

Can't we get the executables from Travis CI or from whoever produced the core? Or get them to obtain a bt ?

Re: [HACKERS] [JDBC] SEGFAULT in HEAD with replication

От
Jorge Solórzano
Дата:
After many tries I get this:

#0  0x0000000000836950 in exec_bind_message (input_message=0x7ffce81048a0) at postgres.c:1562
#1  0x000000000083a23d in PostgresMain (argc=1, argv=0x2bd93d8, dbname=0x2bd9130 "test", username=0x2bd9110 "test") at postgres.c:4113
#2  0x00000000007aacd4 in BackendRun (port=0x2bd02d0) at postmaster.c:4300
#3  0x00000000007aa3fe in BackendStartup (port=0x2bd02d0) at postmaster.c:3972
#4  0x00000000007a6a6c in ServerLoop () at postmaster.c:1712
#5  0x00000000007a6058 in PostmasterMain (argc=3, argv=0x2bac970) at postmaster.c:1320
#6  0x00000000006ee046 in main (argc=3, argv=0x2bac970) at main.c:228


*********


#0  0x0000000000836950 in exec_bind_message (input_message=0x7ffce81048a0) at postgres.c:1562
        portal_name = 0x2c248c8 ""
        stmt_name = 0x2c248c9 "S_3"
        numPFormats = 0
        pformats = 0x0
        numParams = 0
        numRFormats = 0
        rformats = 0x0
        psrc = 0x2c698a8
        cplan = 0x0
        portal = 0x2bacc50
        query_string = 0x0
        saved_stmt_name = 0x0
        params = 0x0
        oldContext = 0x7ffce81047a0
        save_log_statement_stats = 0 '\000'
        snapshot_set = 0 '\000'
        msec_str = "\000H\020\350\374\177\000\000\345\b\224\000\000\000\000\000\020H\020\350\374\177\000\000\277ӿ\373w\351\001"
        __func__ = "exec_bind_message"
#1  0x000000000083a23d in PostgresMain (argc=1, argv=0x2bd93d8, dbname=0x2bd9130 "test", username=0x2bd9110 "test") at postgres.c:4113
        firstchar = 66
        input_message = {data = 0x2c248c8 "", len = 11, maxlen = 1024, cursor = 9, long_ok = 0 '\000'}
        local_sigjmp_buf = {{__jmpbuf = {0, -8329243729337072925, 4625744, 140724201868624, 0, 0, -8329243729320295709, 8327513958265701091}, __mask_was_saved = 1, __saved_mask = {__val = {0, 0,
                15404064, 45969600, 51539607562, 140724201867680, 10064130, 0, 11951218, 11944554, 51539611844, 72198318239795616, 10292727, 15403032, 15402848, 15402848}}}}
        send_ready_for_query = 0 '\000'
        disable_idle_in_transaction_timeout = 0 '\000'
        __func__ = "PostgresMain"
#2  0x00000000007aacd4 in BackendRun (port=0x2bd02d0) at postmaster.c:4300
        av = 0x2bd93d8
        maxac = 2
        ac = 1
        secs = 538176510
        usecs = 721824
        i = 1
        __func__ = "BackendRun"
#3  0x00000000007aa3fe in BackendStartup (port=0x2bd02d0) at postmaster.c:3972
        bn = 0x2bd0490
        pid = 0
        __func__ = "BackendStartup"
#4  0x00000000007a6a6c in ServerLoop () at postmaster.c:1712
        port = 0x2bd02d0
        i = 0
        rmask = {fds_bits = {8, 0 <repeats 15 times>}}
        selres = 1
        now = 1484861310
        readmask = {fds_bits = {56, 0 <repeats 15 times>}}
        nSockets = 6
        last_lockfile_recheck_time = 1484861307
        last_touch_time = 1484861007
        __func__ = "ServerLoop"
#5  0x00000000007a6058 in PostmasterMain (argc=3, argv=0x2bac970) at postmaster.c:1320
        opt = -1
        status = 0
        userDoption = 0x2bce450 "/usr/local/pgsql/data"
        listen_addr_saved = 1 '\001'
        i = 64
        output_config_variable = 0x0
        __func__ = "PostmasterMain"
#6  0x00000000006ee046 in main (argc=3, argv=0x2bac970) at main.c:228

I hope this helps.

Jorge Solórzano
me.jorsol.com

On Thu, Jan 19, 2017 at 11:13 AM, Robert Haas <robertmhaas@gmail.com> wrote:
On Thu, Jan 19, 2017 at 12:09 PM, Dave Cramer <davecramer@gmail.com> wrote:
> I would have expected more, but this is what I have
>
>  bt full
> #0  InitPredicateLocks () at predicate.c:1250
>         i = <optimized out>
>         info = {num_partitions = 1, ssize = 140731424825288, dsize = 1,
>           max_dsize = 0, ffactor = 140731424836952, keysize =
> 140356326474085,
>           entrysize = 140728909791233, hash = 0x7ffe96960d58,
>           match = 0x16da2d1, keycopy = 0x7ffe96960d58, alloc = 0x1703af0,
>           hcxt = 0x16da2d0, hctl = 0x0}
>         max_table_size = 117899280
>         requestSize = <optimized out>
>         found = 0 '\000'

I would say that's not a valid stack trace.  There hasn't been a
change made to that file since October of last year, and the crash is
apparently recent; also, line 1250 in that file doesn't look like
something that can crash.  I would guess that you're using an
executable which doesn't match the core dump, or perhaps that you
don't have complete debug symbols.  Building with -O0 might help.

--
Robert Haas
EnterpriseDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company

Re: [HACKERS] [JDBC] SEGFAULT in HEAD with replication

От
Tom Lane
Дата:
=?UTF-8?Q?Jorge_Sol=C3=B3rzano?= <jorsol@gmail.com> writes:
> After many tries I get this:
> #0  0x0000000000836950 in exec_bind_message (input_message=0x7ffce81048a0)
> at postgres.c:1562

Hmm ... that line was last touched by ab1f0c822, so I'm betting that
I broke it somehow, but I'm not sure how.

It looks like S_3 might have been parsed from a totally empty source
string?  But if that's the trigger, I'd think it'd be entirely trivial
to reproduce.

            regards, tom lane

Re: [HACKERS] [JDBC] SEGFAULT in HEAD with replication

От
Jorge Solórzano
Дата:
Yes, in fact it's a totally empty string:
https://github.com/pgjdbc/pgjdbc/blob/master/pgjdbc/src/main/java/org/postgresql/jdbc/PgConnection.java#L1317

Jorge Solórzano
me.jorsol.com

On Thu, Jan 19, 2017 at 3:57 PM, Tom Lane <tgl@sss.pgh.pa.us> wrote:
Jorge Sol\xC3=B3rzano <jorsol@gmail.com> writes:
> After many tries I get this:
> #0  0x0000000000836950 in exec_bind_message (input_message=0x7ffce81048a0)
> at postgres.c:1562

Hmm ... that line was last touched by ab1f0c822, so I'm betting that
I broke it somehow, but I'm not sure how.

It looks like S_3 might have been parsed from a totally empty source
string?  But if that's the trigger, I'd think it'd be entirely trivial
to reproduce.

                        regards, tom lane

Re: [HACKERS] [JDBC] SEGFAULT in HEAD with replication

От
Tom Lane
Дата:
I wrote:
> Hmm ... that line was last touched by ab1f0c822, so I'm betting that
> I broke it somehow, but I'm not sure how.
> It looks like S_3 might have been parsed from a totally empty source
> string?  But if that's the trigger, I'd think it'd be entirely trivial
> to reproduce.

Oh, duh: the reason it's not trivial to reproduce is you have to try
to bind an empty prepared statement *in an already-aborted transaction*.

Will push a fix in a bit.

            regards, tom lane

Re: [HACKERS] [JDBC] SEGFAULT in HEAD with replication

От
Jorge Solórzano
Дата:
Thanks tom, I confirm that ba61a04 fixes the issue. Now CI is passing.

Jorge Solórzano
me.jorsol.com

On Thu, Jan 19, 2017 at 6:09 PM, Tom Lane <tgl@sss.pgh.pa.us> wrote:
I wrote:
> Hmm ... that line was last touched by ab1f0c822, so I'm betting that
> I broke it somehow, but I'm not sure how.
> It looks like S_3 might have been parsed from a totally empty source
> string?  But if that's the trigger, I'd think it'd be entirely trivial
> to reproduce.

Oh, duh: the reason it's not trivial to reproduce is you have to try
to bind an empty prepared statement *in an already-aborted transaction*.

Will push a fix in a bit.

                        regards, tom lane