Thread: Sudden semi-deterministic disconnection between queries
Hello,
I have a difficult-to-debug problem. I will try to keep this as brief as
possible without leaving things out. In a certain situation my application
fails with:
org.postgresql.util.PSQLException: Connection is closed. Operation is not
permitted.
After some debugging I realized that this would happen on the first query,
regardless of what it is, *after* a specific previous query. In other words:
query1
query2
...
queryN <- seems to cause the failure
queryN+1 <- failure
queryN *seemingly* completes successfully without any error messsage, but then
I get the above error when executing queryN+1.
By commenting out N+1 in my code I would get the error on the next query
instead. By not running N at all, there are no errors.
queryN is simple:
INSERT
INTO email (from_header, to_header, subject_header, body)
VALUES (?, ?, ?, ?)
Note that the error *always* appears on the query executed immediately after
the above query - *however* it does not happen on all queries. At first I saw
this happening every now and then but I now have a reproducable situation
where I do something which triggers 10 E-Mails to be inserted into the
database. Exactly after which message it fails seems to vary - so far I've
seen it fail on the third and sevenths iteration.
The first thing I did was to upgrade the JDBC driver to the latest stable
version for 7.4 on jdbc.postgresql.org. Then I upgraded PostgreSQL from 7.3.4
to the latest 7.4 release (with a dump/reload of the database).
Unfortunately the code depends on a lot of other things and all database
access is going through a middle layer I wrote, so I can't produce a simple
few-line example which demonstrates the problem.
* All queries are running in a transaction with SERIALIZABLE isolation level.
* All queries are definitely executed on the same connection - I have verified
this in case there was some bug in my middle layer that would cause
it to suddently switch to another (perhaps stale) connection.
Does anyone have any suggestions at all of what might cause this, or how I
might debug further? Can I make postgresql do extremely verbose logging
somehow? For example, if the postmaster is intentionally closing the
connection it would be interesting to know why.
Someone on IRC suggested the server might be segfaulting, but I don't know of
a good way to check for this.
Thanks!
--
/ Peter Schuller, InfiDyne Technologies HB
PGP userID: 0xE9758B7D or 'Peter Schuller <peter.schuller@infidyne.com>'
Key retrieval: Send an E-Mail to getpgpkey@scode.org
E-Mail: peter.schuller@infidyne.com Web: http://www.scode.org
On Wednesday 10 March 2004 07:34, Peter Schuller wrote: > Hello, > > I have a difficult-to-debug problem. I will try to keep this as brief as > possible without leaving things out. In a certain situation my application > fails with: > > org.postgresql.util.PSQLException: Connection is closed. Operation is > not permitted. > > After some debugging I realized that this would happen on the first query, > regardless of what it is, *after* a specific previous query. In other > words: > > query1 > query2 > ... > queryN <- seems to cause the failure > queryN+1 <- failure > > queryN *seemingly* completes successfully without any error messsage, but > then I get the above error when executing queryN+1. When I get this it's because of bad quoting, which means it never sees queryN finished until queryN+1 happens. Missing semicolon/closing bracket etc. > Does anyone have any suggestions at all of what might cause this, or how I > might debug further? Can I make postgresql do extremely verbose logging > somehow? For example, if the postmaster is intentionally closing the > connection it would be interesting to know why. Assuming you're logging anything, start with LOG_STATEMENT and perhaps follow up with SERVER_MIN_MESSAGES. Note that you can do this with SQL SET LOG_STATEMENT=on; There are details on log settings in the runtime configuration section of the manuals. You can log huge amounts of info if you like. -- Richard Huxton Archonet Ltd
On Wednesday 10 March 2004 07:34, Peter Schuller wrote: > Hello, > > I have a difficult-to-debug problem. I will try to keep this as brief as > possible without leaving things out. In a certain situation my application > fails with: Actually, as a follow-up to my previous reply, I've just realised what you were saying. > org.postgresql.util.PSQLException: Connection is closed. Operation is > not permitted. So - it's complaining the connection is closed! If it's the backend crashing, that must be listed in the logs. -- Richard Huxton Archonet Ltd
Hello, > Assuming you're logging anything, start with LOG_STATEMENT and perhaps > follow up with SERVER_MIN_MESSAGES. Note that you can do this with SQL > SET LOG_STATEMENT=on; > > There are details on log settings in the runtime configuration section of > the manuals. You can log huge amounts of info if you like. [and from your other message: ] >So - it's complaining the connection is closed! If it's the backend crashing, >that must be listed in the logs. I didn't find anything about SERVER_MIN_MESSAGES, but I did add the following to my configuration: log_min_messages = debug5 log_min_error_statement = debug5 log_connections = true I get a lot of information logged as expected, but I still see nothing at all about closed connections or crashed backend processes. I'm wondering if it's the JDBC driver that thinks it's disconnected for some bogus reason. It is worth noting then when I kill off the client I *do* get this in the log: Mar 10 13:12:50 defiant postgres[5427]: [350-1] LOG: unexpected EOF on client connection I just tried restarting the application and giving it some traffic causing it to open two connections to the database. I saw processes for these connections by doing ps aux | grep post. When I triggered the 'not connected' problem there was indeed one server process missing, but the other one had survived and I did get the above message about unexpected EOF for the remaining connection when I killed off the client again. The question is - under circumstances such as these, with the above logging turned on and postgresql being fully alive and well (since other connections still work and postgresql never needs to be started), is postgresql guaranteed to put something in the log in the event of an *unexpected* shutdown of one of the postmasters? If the answer to that question is yes, would not this be indicative that the problem is indeed on the client side becaue the client is apparantly closing the connection cleanly? Is anyone aware of a way to make the JDBC driver do some kind of verbose logging? I have pretty much exhausted the list of possible problems with my code and it would be interesting to see whether the JDBC driver is actively closing the connection for some reason, or if it is receiving some form of terminating sequence from the server. (I have looked at the on-the-wire postgresql protocol before but it's been a while now so I'm not sure if the latter is a possibility.) -- / Peter Schuller, InfiDyne Technologies HB PGP userID: 0xE9758B7D or 'Peter Schuller <peter.schuller@infidyne.com>' Key retrieval: Send an E-Mail to getpgpkey@scode.org E-Mail: peter.schuller@infidyne.com Web: http://www.scode.org
> log_min_messages = debug5 > log_min_error_statement = debug5 > log_connections = true I also have log_statement = true, but forgot to include it above. -- / Peter Schuller, InfiDyne Technologies HB PGP userID: 0xE9758B7D or 'Peter Schuller <peter.schuller@infidyne.com>' Key retrieval: Send an E-Mail to getpgpkey@scode.org E-Mail: peter.schuller@infidyne.com Web: http://www.scode.org
On Wednesday 10 March 2004 12:24, Peter Schuller wrote: > Hello, > > > Assuming you're logging anything, start with LOG_STATEMENT and perhaps > > follow up with SERVER_MIN_MESSAGES. Note that you can do this with SQL > > SET LOG_STATEMENT=on; > > > > There are details on log settings in the runtime configuration section of > > the manuals. You can log huge amounts of info if you like. > > [and from your other message: ] > > >So - it's complaining the connection is closed! If it's the backend > > crashing, that must be listed in the logs. > > I didn't find anything about SERVER_MIN_MESSAGES, but I did add the > following to my configuration: > > log_min_messages = debug5 > log_min_error_statement = debug5 > log_connections = true (And log_statement according to your other post) > I get a lot of information logged as expected, but I still see nothing at > all about closed connections or crashed backend processes. > > I'm wondering if it's the JDBC driver that thinks it's disconnected for > some bogus reason. Sounds like it to me. > The question is - under circumstances such as these, with the above logging > turned on and postgresql being fully alive and well (since other > connections still work and postgresql never needs to be started), is > postgresql guaranteed to put something in the log in the event of an > *unexpected* shutdown of one of the postmasters? > > If the answer to that question is yes, would not this be indicative that > the problem is indeed on the client side becaue the client is apparantly > closing the connection cleanly? It's certainly highly suggestive of a problem on the client side. > Is anyone aware of a way to make the JDBC driver do some kind of verbose > logging? I have pretty much exhausted the list of possible problems with my > code and it would be interesting to see whether the JDBC driver is actively > closing the connection for some reason, or if it is receiving some form of > terminating sequence from the server. Don't use it myself, but there are examples in the source distribution that seem to turn debugging on. Would the line below do anything for you: DriverManager.setLogStream(System.err); -- Richard Huxton Archonet Ltd
Peter Schuller <peter.schuller@infidyne.com> writes:
> The question is - under circumstances such as these, with the above logging
> turned on and postgresql being fully alive and well (since other connections
> still work and postgresql never needs to be started), is postgresql
> guaranteed to put something in the log in the event of an *unexpected*
> shutdown of one of the postmasters?
Yes. At this point I think you are probably dealing with a JDBC issue,
and you ought to take it to the pgsql-jdbc list where the people with
much jdbc-fu hang out.
regards, tom lane
On Wednesday 10 March 2004 14.49, Richard Huxton wrote: > Don't use it myself, but there are examples in the source distribution that > seem to turn debugging on. Would the line below do anything for you: > DriverManager.setLogStream(System.err); I'll have a go and see what I get. Thanks a lot! On Wednesday 10 March 2004 17.15, Tom Lane wrote: > Yes. At this point I think you are probably dealing with a JDBC issue, > and you ought to take it to the pgsql-jdbc list where the people with > much jdbc-fu hang out. Will do. Thanks! -- / Peter Schuller, InfiDyne Technologies HB PGP userID: 0xE9758B7D or 'Peter Schuller <peter.schuller@infidyne.com>' Key retrieval: Send an E-Mail to getpgpkey@scode.org E-Mail: peter.schuller@infidyne.com Web: http://www.scode.org
On Thu, 11 Mar 2004, Peter Schuller wrote: > On Wednesday 10 March 2004 14.49, Richard Huxton wrote: > > > Don't use it myself, but there are examples in the source distribution that > > seem to turn debugging on. Would the line below do anything for you: > > DriverManager.setLogStream(System.err); > > I'll have a go and see what I get. Thanks a lot! > This will only direct the log to a particular location, to actually generate a log you need to add a loglevel=2 parameter to your url, like so: jdbc:postgresql://localhost:5432/dbname?loglevel=2 Kris Jurka