Re: Connection terminated by the server causes deadlock in jdbc client side connection

Dave,

Sadly ExecutorQueryImpl will only print out the exception _after_ closing
the connection :)

catch (IOException e)
{
protoConnection.close();
handler.handleError(new PSQLException(GT.tr("An I/O error
occurred while sending to the backend."), PSQLState.CONNECTION_FAILURE, e));
}

Here is a longer StackTrace in case there is anything else of value. We are
using BoneCP and Hibernate. The next line in the stack trace would be our
application code.

java.lang.Thread.State: RUNNABLE
at java.net.SocketOutputStream.socketWrite0(Native Method)
at java.net.SocketOutputStream.socketWrite(Unknown Source)
at java.net.SocketOutputStream.write(Unknown Source)
at java.io.BufferedOutputStream.flushBuffer(Unknown Source)
at java.io.BufferedOutputStream.flush(Unknown Source)
- locked <0x0000000700742e30> (a java.io.BufferedOutputStream)
at org.postgresql.core.PGStream.flush(PGStream.java:518)
at
org.postgresql.core.v3.ProtocolConnectionImpl.close(ProtocolConnectionImpl.java:136)
at
org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:280)
- locked <0x0000000700742fd0> (a org.postgresql.core.v3.QueryExecutorImpl)
at
org.postgresql.jdbc2.AbstractJdbc2Statement.execute(AbstractJdbc2Statement.java:547)
at
org.postgresql.jdbc2.AbstractJdbc2Statement.executeWithFlags(AbstractJdbc2Statement.java:417)
at
org.postgresql.jdbc2.AbstractJdbc2Statement.executeQuery(AbstractJdbc2Statement.java:302)
at
com.jolbox.bonecp.PreparedStatementHandle.executeQuery(PreparedStatementHandle.java:174)
at
org.hibernate.engine.jdbc.internal.ResultSetReturnImpl.extract(ResultSetReturnImpl.java:56)
at org.hibernate.loader.Loader.getResultSet(Loader.java:2040)
at org.hibernate.loader.Loader.executeQueryStatement(Loader.java:1837)
at org.hibernate.loader.Loader.executeQueryStatement(Loader.java:1816)
at org.hibernate.loader.Loader.doQuery(Loader.java:900)
at
org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:342)
at org.hibernate.loader.Loader.doList(Loader.java:2526)
at org.hibernate.loader.Loader.doList(Loader.java:2512)
at org.hibernate.loader.Loader.listIgnoreQueryCache(Loader.java:2342)
at org.hibernate.loader.Loader.list(Loader.java:2337)
at
org.hibernate.loader.criteria.CriteriaLoader.list(CriteriaLoader.java:124)
at org.hibernate.internal.SessionImpl.list(SessionImpl.java:1662)
at org.hibernate.internal.CriteriaImpl.list(CriteriaImpl.java:374)

Regards,

Leonardo

On 7 October 2015 at 16:01, Dave Cramer <pg(at)fastcrypt(dot)com> wrote:

> Leonardo,
>
> At this point I'm wondering if we get an I/O error if it is feasible to
> attempt to close it. I am leaning towards no.
>
> What is above this in the stack trace. Do you see any information about
> the IOException error that caused it
>
> Dave Cramer
>
> dave.cramer(at)credativ(dot)ca
> http://www.credativ.ca
>
> On 7 October 2015 at 14:43, Leonardo Frittelli <
> leonardo(dot)frittelli(at)gmail(dot)com> wrote:
>
>> Dave,
>>
>> Thank you very much for your prompt response.
>> I am using version postgresql-9.3-1101, but I have checked the latest
>> available 9.4 sources and it appears to have the same code (the code
>> example I pasted was from v2, but I see similar code in v3).
>>
>> Could it be that in this particular scenario we should use
>> ProtocolConnectionImpl.abort() instead of close()?
>>
>> Thanks,
>>
>> Leonardo
>>
>> On 7 October 2015 at 15:23, Dave Cramer <pg(at)fastcrypt(dot)com> wrote:
>>
>>> It could be a problem. What version are you using ?
>>>
>>> Dave Cramer
>>>
>>> dave.cramer(at)credativ(dot)ca
>>> http://www.credativ.ca
>>>
>>> On 7 October 2015 at 12:33, Leonardo Frittelli <
>>> leonardo(dot)frittelli(at)gmail(dot)com> wrote:
>>>
>>>> Hi,
>>>>
>>>> We are experiencing very frequent deadlocks in pgsql jdbc connections.
>>>> The scenario is a replicated database with hot_standby = on
>>>>
>>>> At times of high volumes of queries in both the primary and the
>>>> replicated server, we sometimes get the following log indicating that the
>>>> server has terminated the connection in the replicated database.
>>>> FATAL: terminating connection due to conflict with recovery
>>>> DETAIL: User query might have needed to see row versions that must be
>>>> removed.
>>>> HINT: In a moment you should be able to reconnect to the database and
>>>> repeat your command.
>>>>
>>>> This is expected and we see no issue with that. What I did not expect,
>>>> however, is that in the JDBC client side, the connection is deadlocked.
>>>>
>>>> java.lang.Thread.State: RUNNABLE
>>>> at java.net.SocketOutputStream.socketWrite0(Native Method)
>>>> at java.net.SocketOutputStream.socketWrite(Unknown Source)
>>>> at java.net.SocketOutputStream.write(Unknown Source)
>>>> at java.io.BufferedOutputStream.flushBuffer(Unknown Source)
>>>> at java.io.BufferedOutputStream.flush(Unknown Source)
>>>> - locked <0x0000000700742e30> (a java.io.BufferedOutputStream)
>>>> at org.postgresql.core.PGStream.flush(PGStream.java:518)
>>>> at
>>>> org.postgresql.core.v3.ProtocolConnectionImpl.close(ProtocolConnectionImpl.java:136)
>>>> at
>>>> org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:280)
>>>> - locked <0x0000000700742fd0> (a
>>>> org.postgresql.core.v3.QueryExecutorImpl)
>>>> at
>>>> org.postgresql.jdbc2.AbstractJdbc2Statement.execute(AbstractJdbc2Statement.java:547)
>>>> at
>>>> org.postgresql.jdbc2.AbstractJdbc2Statement.executeWithFlags(AbstractJdbc2Statement.java:417)
>>>> at
>>>> org.postgresql.jdbc2.AbstractJdbc2Statement.executeQuery(AbstractJdbc2Statement.java:302)
>>>> ...
>>>>
>>>> Looking at the Postgres JDBC code, I notice that
>>>> ProtocolConnectionImpl.close() (invoked by the exception handler in
>>>> QueryExecutorImpl.execute) is trying to 'gracefully close' by sending an
>>>> 'X' to the server before actually closing the socket.
>>>>
>>>> ...
>>>> if (logger.logDebug()) logger.debug(" FE=> Terminate");
>>>> pgStream.SendChar('X'); pgStream.flush(); pgStream.close(); ...
>>>>
>>>> Does this make sense in a scenario of a connection which has already
>>>> been terminated by the server side?
>>>>
>>>> At times of high load, all connections in the pool get eventually
>>>> locked with exactly the same stack trace.
>>>>
>>>> I'd appreciate any advice on how to handle this. Could this be a bug in
>>>> the JDBC driver?
>>>>
>>>> Thanks,
>>>>
>>>> Leonardo
>>>>
>>>
>>>
>>
>