SEGFAULT in HEAD with replication

Started by Dave Crameralmost 9 years ago17 messages

davecramer@gmail.com

almost 9 years ago

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.

Logs can be found here
https://drive.google.com/drive/folders/0B-Heg5ZYCWbreEE4Uk5LdnJ5eWM?usp=sharing

Regards,

Dave Cramer

Vladimir Gordiychuk

folyga@gmail.com

almost 9 years ago

In reply to: Dave Cramer (#1)

Re: SEGFAULT in HEAD with replication

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>:

Show quoted text

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.

Logs can be found here https://drive.google.com/drive/folders/0B-
Heg5ZYCWbreEE4Uk5LdnJ5eWM?usp=sharing

Regards,

Dave Cramer

Vladimir Gordiychuk

folyga@gmail.com

almost 9 years ago

In reply to: Vladimir Gordiychuk (#2)

Re: [JDBC] SEGFAULT in HEAD with replication

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>:

Show quoted text

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.

Logs can be found here https://drive.google.com/
drive/folders/0B-Heg5ZYCWbreEE4Uk5LdnJ5eWM?usp=sharing

Regards,

Dave Cramer

Jorge Solórzano

jorsol@gmail.com

almost 9 years ago

In reply to: Vladimir Gordiychuk (#3)

Re: [JDBC] SEGFAULT in HEAD with replication

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:

Show quoted text

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.

Logs can be found here https://drive.google.com/
drive/folders/0B-Heg5ZYCWbreEE4Uk5LdnJ5eWM?usp=sharing

Regards,

Dave Cramer

Robert Haas

robertmhaas@gmail.com

almost 9 years ago

In reply to: Jorge Solórzano (#4)

Re: [HACKERS] SEGFAULT in HEAD with replication

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

--
Sent via pgsql-jdbc mailing list (pgsql-jdbc@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-jdbc

Jorge Solórzano

jorsol@gmail.com

almost 9 years ago

In reply to: Robert Haas (#5)

Re: [JDBC] SEGFAULT in HEAD with replication

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

Dave Cramer

davecramer@gmail.com

almost 9 years ago

In reply to: Jorge Solórzano (#6)

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@gmail.com> wrote:

Show quoted text

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

Dave Cramer

davecramer@gmail.com

almost 9 years ago

In reply to: Dave Cramer (#7)

Re: [JDBC] SEGFAULT in HEAD with replication

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:

Show quoted text

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

Robert Haas

robertmhaas@gmail.com

almost 9 years ago

In reply to: Jorge Solórzano (#6)

Re: [JDBC] SEGFAULT in HEAD with replication

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

--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

#10

Robert Haas

robertmhaas@gmail.com

almost 9 years ago

In reply to: Dave Cramer (#8)

Re: [HACKERS] SEGFAULT in HEAD with replication

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

--
Sent via pgsql-jdbc mailing list (pgsql-jdbc@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-jdbc

#11

Craig Ringer

craig.ringer@2ndquadrant.com

almost 9 years ago

In reply to: Robert Haas (#10)

Re: [HACKERS] SEGFAULT in HEAD with replication

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'

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 ?

#12

Dave Cramer

davecramer@gmail.com

almost 9 years ago

In reply to: Craig Ringer (#11)

Re: [JDBC] SEGFAULT in HEAD with replication

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:

Show quoted text

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 ?

#13

Jorge Solórzano

jorsol@gmail.com

almost 9 years ago

In reply to: Robert Haas (#10)

Re: [HACKERS] SEGFAULT in HEAD with replication

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:

Show quoted text

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

#14

Tom Lane

tgl@sss.pgh.pa.us

almost 9 years ago

In reply to: Jorge Solórzano (#13)

Re: [HACKERS] SEGFAULT in HEAD with replication

=?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

--
Sent via pgsql-jdbc mailing list (pgsql-jdbc@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-jdbc

#15

Jorge Solórzano

jorsol@gmail.com

almost 9 years ago

In reply to: Tom Lane (#14)

Re: [HACKERS] SEGFAULT in HEAD with replication

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:

Show quoted text

=?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

#16

Tom Lane

tgl@sss.pgh.pa.us

almost 9 years ago

In reply to: Tom Lane (#14)

Re: [JDBC] SEGFAULT in HEAD with replication

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

--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

#17

Jorge Solórzano

jorsol@gmail.com

almost 9 years ago

In reply to: Tom Lane (#16)

Re: [JDBC] SEGFAULT in HEAD with replication

Thanks tom, I confirm that ba61a04
<https://github.com/postgres/postgres/commit/ba61a04bc7fefeee03416d9911eb825c4897c223>
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:

Show quoted text

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