Re: [JDBC] SEGFAULT in HEAD with replication

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(at)gmail(dot)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(at)gmail(dot)com>
> wrote:
>
>> On Thu, Jan 19, 2017 at 10:59 AM, Jorge Solórzano <jorsol(at)gmail(dot)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
>>
>
>