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

OK, let me see if I can change the code and give you a driver that will
print out and not call close.

Dave

Dave Cramer

dave.cramer(at)credativ(dot)ca
http://www.credativ.ca

On 7 October 2015 at 15:08, Leonardo Frittelli <leonardo(dot)frittelli(at)gmail(dot)com
> wrote:

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