Postgres connection failures
Hi,
I’m developing an application using Postgres and when doing a transaction with a bunch of INSERT statements, the connection to the server (on localhost) often suddenly dies. Trying to diagnose the problem, I’ve increased log levels and I’ve run a tcpdump session to find out what’s going on, can someone spot something strange or point me in a direction to continue debugging?
The symptom I notice is that the Postgres server (9.1 from Ubuntu repo) closes the connection, sometimes by sending a TCP FIN, sometimes by sending a TCP RST, but I’m not sure why this happens. The (node.js / node-postgres-pure) client doesn’t report any error message that could have been received from the server; it only complains that the connection unexpectedly closed during query execution.
Log message around the time the connections stops. I’ve looked up some lines in the code on GitHub, but I can’t figure out what’s going on yet. Queries are large, but that doesn’t seem to be a problem, as a lot of those have been added before.
2014-04-04 15:16:33 CEST DEBUG: 00000: parse <unnamed>: INSERT INTO xx (xx
xx, xx, xx, xx, xx) VALUES ($1, $2, $3, $4, $5), ($1, $2, $6, $7,
$8), ($1, $2, $9, $10, $11), ($1, $2, $12, $13, $14), ($1, $2, $15, $16, $17),
($1, $2, $18, $19, $20), ($1, $2, $21, $22, $23), ($1, $2, $24, $25, $26), ($1,
(… cut …)
2014-04-04 15:16:33 CEST LOCATION: exec_parse_message, postgres.c:1146
2014-04-04 15:16:33 CEST DEBUG: 00000: StartTransactionCommand
2014-04-04 15:16:33 CEST LOCATION: start_xact_command, postgres.c:2426
2014-04-04 15:16:33 CEST DEBUG: 00000: bind <unnamed> to <unnamed>
2014-04-04 15:16:33 CEST LOCATION: exec_bind_message, postgres.c:1429
2014-04-04 15:16:33 CEST DEBUG: 00000: ProcessQuery
2014-04-04 15:16:33 CEST LOCATION: ProcessQuery, pquery.c:170
2014-04-04 15:16:34 CEST DEBUG: 00000: shmem_exit(0): 7 callbacks to make
2014-04-04 15:16:34 CEST LOCATION: shmem_exit, ipc.c:211
2014-04-04 15:16:34 CEST DEBUG: 00000: proc_exit(0): 4 callbacks to make
2014-04-04 15:16:34 CEST LOCATION: proc_exit_prepare, ipc.c:183
2014-04-04 15:16:34 CEST LOG: 00000: disconnection: session time: 0:01:04.287 u
ser=postgres database=dev host=127.0.0.1 port=57848
2014-04-04 15:16:34 CEST LOCATION: log_disconnections, postgres.c:4375
2014-04-04 15:16:34 CEST DEBUG: 00000: exit(0)
2014-04-04 15:16:34 CEST LOCATION: proc_exit, ipc.c:135
2014-04-04 15:16:34 CEST DEBUG: 00000: shmem_exit(-1): 0 callbacks to make
2014-04-04 15:16:34 CEST LOCATION: shmem_exit, ipc.c:211
2014-04-04 15:16:34 CEST DEBUG: 00000: proc_exit(-1): 0 callbacks to make
2014-04-04 15:16:34 CEST LOCATION: proc_exit_prepare, ipc.c:183
2014-04-04 15:16:34 CEST DEBUG: 00000: reaping dead processes
2014-04-04 15:16:34 CEST LOCATION: reaper, postmaster.c:2360
2014-04-04 15:16:34 CEST DEBUG: 00000: server process (PID 20677) exited with e
xit code 0
2014-04-04 15:16:34 CEST LOCATION: LogChildExit, postmaster.c:2873
2014-04-04 15:16:37 CEST DEBUG: 00000: attempting to remove WAL segments older
than log file 000000010000003C00000071
2014-04-04 15:16:37 CEST LOCATION: RemoveOldXlogFiles, xlog.c:3364
2014-04-04 15:16:37 CEST DEBUG: 00000: recycled transaction log file "000000010
000003C00000071"
2014-04-04 15:16:37 CEST LOCATION: RemoveOldXlogFiles, xlog.c:3414
2014-04-04 15:16:37 CEST DEBUG: 00000: recycled transaction log file "000000010
000003C0000006F"
2014-04-04 15:16:37 CEST LOCATION: RemoveOldXlogFiles, xlog.c:3414
2014-04-04 15:16:37 CEST DEBUG: 00000: recycled transaction log file "000000010000003C00000070"
2014-04-04 15:16:37 CEST LOCATION: RemoveOldXlogFiles, xlog.c:3414
/Mark
--
Sent via pgsql-general mailing list (pgsql-general@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-general
Mark van Cuijk <postgresql.org-pgsql-general-41@45cents.nl> writes:
I�m developing an application using Postgres and when doing a transaction with a bunch of INSERT statements, the connection to the server (on localhost) often suddenly dies. Trying to diagnose the problem, I�ve increased log levels and I�ve run a tcpdump session to find out what�s going on, can someone spot something strange or point me in a direction to continue debugging?
The symptom I notice is that the Postgres server (9.1 from Ubuntu repo) closes the connection, sometimes by sending a TCP FIN, sometimes by sending a TCP RST, but I�m not sure why this happens. The (node.js / node-postgres-pure) client doesn�t report any error message that could have been received from the server; it only complains that the connection unexpectedly closed during query execution.
Your log extract looks like the server side thought it got a connection
closure command. In particular, the server process seems to have exited
normally, and it did not write "LOG: unexpected EOF on client connection",
which it would have done if the TCP connection dropped without receipt of
such a command.
Based on these facts, I'm going to speculate that your client application
is multi-threaded and some thread is closing a connection out from under
another one. It's usually best to have only one thread touching a
particular connection; or if you want to maintain a connection pool
yourself, be very sure you have clear acquire and release rules.
regards, tom lane
--
Sent via pgsql-general mailing list (pgsql-general@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-general
On 04 Apr 2014, at 16:09 , Tom Lane <tgl@sss.pgh.pa.us> wrote:
Your log extract looks like the server side thought it got a connection
closure command. In particular, the server process seems to have exited
normally, and it did not write "LOG: unexpected EOF on client connection",
which it would have done if the TCP connection dropped without receipt of
such a command.Based on these facts, I'm going to speculate that your client application
is multi-threaded and some thread is closing a connection out from under
another one. It's usually best to have only one thread touching a
particular connection; or if you want to maintain a connection pool
yourself, be very sure you have clear acquire and release rules.
Thanks! I’ve patched the library to print all outgoing messages and indeed it seems one with 0x58 is sent just before the connection is closed. Printing a stack trace over there reveals that the pool code thinks the connection is idle and closes it. I’ll submit a bug report in the node-postgres library.
Thanks for the help!
/Mark
--
Sent via pgsql-general mailing list (pgsql-general@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-general