Обсуждение: Postgres connection failures

Hi,

I’m developing an application using Postgres and when doing a transaction with a bunch of INSERT statements, the
connectionto the server (on localhost) often suddenly dies. Trying to diagnose the problem, I’ve increased log levels
andI’ve run a tcpdump session to find out what’s going on, can someone spot something strange or point me in a
directionto continue debugging? 

The symptom I notice is that the Postgres server (9.1 from Ubuntu repo) closes the connection, sometimes by sending a
TCPFIN, sometimes by sending a TCP RST, but I’m not sure why this happens. The (node.js / node-postgres-pure) client
doesn’treport any error message that could have been received from the server; it only complains that the connection
unexpectedlyclosed 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
outwhat’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

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
connectionto the server (on localhost) often suddenly dies. Trying to diagnose the problem, I�ve increased log levels
andI�ve run a tcpdump session to find out what�s going on, can someone spot something strange or point me in a
directionto continue debugging? 

> The symptom I notice is that the Postgres server (9.1 from Ubuntu repo) closes the connection, sometimes by sending a
TCPFIN, sometimes by sending a TCP RST, but I�m not sure why this happens. The (node.js / node-postgres-pure) client
doesn�treport any error message that could have been received from the server; it only complains that the connection
unexpectedlyclosed 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

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
theconnection is closed. Printing a stack trace over there reveals that the pool code thinks the connection is idle and
closesit. I’ll submit a bug report in the node-postgres library. 

Thanks for the help!

/Mark