quickfixj
quickfixj copied to clipboard
Published
20 hours ago •
quickfix-j
quickfix-j
`JdbcStore.storeSequenceNumbers` throws exception that is never recovered from
trafficstars
Describe the bug A configured quickfix connection throws an exception whilst processing a heartbeat response.
To Reproduce Cannot reproduce locally. Issue reported on client system.
Expected behavior Fix session establish correctly
system information:
- OS: Linux
- Java version JDK 1.8
- QFJ Version 2.3.1
Additional context Initially we get the following exception thrown:
00:33:08.349,ERROR,errorEvent,QFJ Message Processor,[],Closed Connection
java.sql.SQLRecoverableException: Closed Connection
at oracle.jdbc.driver.PhysicalConnection.needLine(PhysicalConnection.java:3247)
at oracle.jdbc.driver.OracleStatement.closeOrCache(OracleStatement.java:1392)
at oracle.jdbc.driver.OracleStatement.close(OracleStatement.java:1375)
at oracle.jdbc.driver.OracleStatementWrapper.close(OracleStatementWrapper.java:119)
at oracle.jdbc.driver.OraclePreparedStatementWrapper.close(OraclePreparedStatementWrapper.java:96)
at org.logicalcobwebs.proxool.AbstractProxyStatement.close(AbstractProxyStatement.java:115)
at org.logicalcobwebs.proxool.ProxyStatement.invoke(ProxyStatement.java:93)
at org.logicalcobwebs.proxool.ProxyStatement.intercept(ProxyStatement.java:57)
at $java.sql.Statement$$EnhancerByProxool$$10c0cac9.close(<generated>)
at quickfix.JdbcUtil.close(JdbcUtil.java:132)
at quickfix.JdbcStore.storeSequenceNumbers(JdbcStore.java:286)
at quickfix.JdbcStore.setNextTargetMsgSeqNum(JdbcStore.java:270)
at quickfix.JdbcStore.incrNextTargetMsgSeqNum(JdbcStore.java:173)
at quickfix.SessionState.incrNextTargetMsgSeqNum(SessionState.java:372)
at quickfix.Session.nextHeartBeat(Session.java:1739)
at quickfix.Session.next(Session.java:1053)
at quickfix.Session.next(Session.java:1228)
at quickfix.mina.SingleThreadedEventHandlingStrategy$SessionMessageEvent.processMessage(SingleThreadedEventHandlingStrategy.java:163)
at quickfix.mina.SingleThreadedEventHandlingStrategy.block(SingleThreadedEventHandlingStrategy.java:113)
at quickfix.mina.SingleThreadedEventHandlingStrategy.lambda$blockInThread$1(SingleThreadedEventHandlingStrategy.java:145)
at quickfix.mina.SingleThreadedEventHandlingStrategy$ThreadAdapter$RunnableWrapper.run(SingleThreadedEventHandlingStrategy.java:267)
at java.base/java.lang.Thread.run(Thread.java:832)
Followed by:
0:33:08.363,ERROR,errorEvent,QFJ Message Processor,[],Error processing message: 8=FIXT.1.19=7235=034=753649=<sender>56=<target>52=20230222-00:33:07.98610=138
java.io.IOException: IO Error: Socket read interrupted
at quickfix.JdbcStore.storeSequenceNumbers(JdbcStore.java:284)
at quickfix.JdbcStore.setNextTargetMsgSeqNum(JdbcStore.java:270)
at quickfix.JdbcStore.incrNextTargetMsgSeqNum(JdbcStore.java:173)
at quickfix.SessionState.incrNextTargetMsgSeqNum(SessionState.java:372)
at quickfix.Session.nextHeartBeat(Session.java:1739)
at quickfix.Session.next(Session.java:1053)
at quickfix.Session.next(Session.java:1228)
at quickfix.mina.SingleThreadedEventHandlingStrategy$SessionMessageEvent.processMessage(SingleThreadedEventHandlingStrategy.java:163)
at quickfix.mina.SingleThreadedEventHandlingStrategy.block(SingleThreadedEventHandlingStrategy.java:113)
at quickfix.mina.SingleThreadedEventHandlingStrategy.lambda$blockInThread$1(SingleThreadedEventHandlingStrategy.java:145)
at quickfix.mina.SingleThreadedEventHandlingStrategy$ThreadAdapter$RunnableWrapper.run(SingleThreadedEventHandlingStrategy.java:267)
at java.base/java.lang.Thread.run(Thread.java:832)
Caused by: java.sql.SQLRecoverableException: IO Error: Socket read interrupted
at oracle.jdbc.driver.T4CPreparedStatement.executeForRows(T4CPreparedStatement.java:932)
at oracle.jdbc.driver.OracleStatement.doExecuteWithTimeout(OracleStatement.java:1119)
at oracle.jdbc.driver.OraclePreparedStatement.executeInternal(OraclePreparedStatement.java:3780)
at oracle.jdbc.driver.T4CPreparedStatement.executeInternal(T4CPreparedStatement.java:1343)
at oracle.jdbc.driver.OraclePreparedStatement.execute(OraclePreparedStatement.java:3887)
at oracle.jdbc.driver.OraclePreparedStatementWrapper.execute(OraclePreparedStatementWrapper.java:1079)
at jdk.internal.reflect.GeneratedMethodAccessor1050.invoke(Unknown Source)
at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.base/java.lang.reflect.Method.invoke(Method.java:564)
at org.logicalcobwebs.proxool.ProxyStatement.invoke(ProxyStatement.java:100)
at org.logicalcobwebs.proxool.ProxyStatement.intercept(ProxyStatement.java:57)
at $java.sql.Statement$$EnhancerByProxool$$10c0cac9.execute(<generated>)
at quickfix.JdbcStore.storeSequenceNumbers(JdbcStore.java:282)
... 11 more
Caused by: java.net.SocketTimeoutException: Socket read interrupted
at oracle.net.nt.TimeoutSocketChannel.read(TimeoutSocketChannel.java:152)
at oracle.net.ns.NIOHeader.readHeaderBuffer(NIOHeader.java:82)
at oracle.net.ns.NIOPacket.readFromSocketChannel(NIOPacket.java:139)
at oracle.net.ns.NIOPacket.readFromSocketChannel(NIOPacket.java:101)
at oracle.net.ns.NIONSDataChannel.readDataFromSocketChannel(NIONSDataChannel.java:80)
at oracle.jdbc.driver.T4CMAREngineNIO.prepareForReading(T4CMAREngineNIO.java:98)
at oracle.jdbc.driver.T4CMAREngineNIO.unmarshalUB1(T4CMAREngineNIO.java:534)
at oracle.jdbc.driver.T4CTTIfun.receive(T4CTTIfun.java:485)
at oracle.jdbc.driver.T4CTTIfun.doRPC(T4CTTIfun.java:252)
at oracle.jdbc.driver.T4C8Oall.doOALL(T4C8Oall.java:612)
at oracle.jdbc.driver.T4CPreparedStatement.doOall8(T4CPreparedStatement.java:226)
at oracle.jdbc.driver.T4CPreparedStatement.doOall8(T4CPreparedStatement.java:59)
at oracle.jdbc.driver.T4CPreparedStatement.executeForRows(T4CPreparedStatement.java:910)
... 23 more
Cause: IO Error: Socket read interrupted
java.sql.SQLRecoverableException: IO Error: Socket read interrupted
at oracle.jdbc.driver.T4CPreparedStatement.executeForRows(T4CPreparedStatement.java:932)
at oracle.jdbc.driver.OracleStatement.doExecuteWithTimeout(OracleStatement.java:1119)
at oracle.jdbc.driver.OraclePreparedStatement.executeInternal(OraclePreparedStatement.java:3780)
at oracle.jdbc.driver.T4CPreparedStatement.executeInternal(T4CPreparedStatement.java:1343)
at oracle.jdbc.driver.OraclePreparedStatement.execute(OraclePreparedStatement.java:3887)
at oracle.jdbc.driver.OraclePreparedStatementWrapper.execute(OraclePreparedStatementWrapper.java:1079)
at jdk.internal.reflect.GeneratedMethodAccessor1050.invoke(Unknown Source)
at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.base/java.lang.reflect.Method.invoke(Method.java:564)
at org.logicalcobwebs.proxool.ProxyStatement.invoke(ProxyStatement.java:100)
at org.logicalcobwebs.proxool.ProxyStatement.intercept(ProxyStatement.java:57)
at $java.sql.Statement$$EnhancerByProxool$$10c0cac9.execute(<generated>)
at quickfix.JdbcStore.storeSequenceNumbers(JdbcStore.java:282)
at quickfix.JdbcStore.setNextTargetMsgSeqNum(JdbcStore.java:270)
at quickfix.JdbcStore.incrNextTargetMsgSeqNum(JdbcStore.java:173)
at quickfix.SessionState.incrNextTargetMsgSeqNum(SessionState.java:372)
at quickfix.Session.nextHeartBeat(Session.java:1739)
at quickfix.Session.next(Session.java:1053)
at quickfix.Session.next(Session.java:1228)
at quickfix.mina.SingleThreadedEventHandlingStrategy$SessionMessageEvent.processMessage(SingleThreadedEventHandlingStrategy.java:163)
at quickfix.mina.SingleThreadedEventHandlingStrategy.block(SingleThreadedEventHandlingStrategy.java:113)
at quickfix.mina.SingleThreadedEventHandlingStrategy.lambda$blockInThread$1(SingleThreadedEventHandlingStrategy.java:145)
at quickfix.mina.SingleThreadedEventHandlingStrategy$ThreadAdapter$RunnableWrapper.run(SingleThreadedEventHandlingStrategy.java:267)
at java.base/java.lang.Thread.run(Thread.java:832)
Caused by: java.net.SocketTimeoutException: Socket read interrupted
at oracle.net.nt.TimeoutSocketChannel.read(TimeoutSocketChannel.java:152)
at oracle.net.ns.NIOHeader.readHeaderBuffer(NIOHeader.java:82)
at oracle.net.ns.NIOPacket.readFromSocketChannel(NIOPacket.java:139)
at oracle.net.ns.NIOPacket.readFromSocketChannel(NIOPacket.java:101)
at oracle.net.ns.NIONSDataChannel.readDataFromSocketChannel(NIONSDataChannel.java:80)
at oracle.jdbc.driver.T4CMAREngineNIO.prepareForReading(T4CMAREngineNIO.java:98)
at oracle.jdbc.driver.T4CMAREngineNIO.unmarshalUB1(T4CMAREngineNIO.java:534)
at oracle.jdbc.driver.T4CTTIfun.receive(T4CTTIfun.java:485)
at oracle.jdbc.driver.T4CTTIfun.doRPC(T4CTTIfun.java:252)
at oracle.jdbc.driver.T4C8Oall.doOALL(T4C8Oall.java:612)
at oracle.jdbc.driver.T4CPreparedStatement.doOall8(T4CPreparedStatement.java:226)
at oracle.jdbc.driver.T4CPreparedStatement.doOall8(T4CPreparedStatement.java:59)
at oracle.jdbc.driver.T4CPreparedStatement.executeForRows(T4CPreparedStatement.java:910)
... 23 more
00:34:20.038,ERROR,errorEvent,QFJ Timer,[],Disconnecting: Timed out waiting for heartbeat
The client reports no connectivity issues at the time and this is backed up by the fact that other resources within our application can communicate with the database fine. Thee might have been a disconnect but the assumption is quickfixj would reconnect once available. Aside from that it seems that reconnect attempts don't work as we see many of these in the logs:
00:34:31.037,ERROR,errorEvent,QFJ Timer,[],Disconnecting: Timed out waiting for logon response
This is despite the fact that the fact that we can see from the logs that those logon attempts are being responded to:
00:34:21.073,INFO ,message,QFJ Timer,[],8=FIXT.1.19=9135=A34=804949=application_name52=20230222-00:34:21.03156=application_name298=0108=301137=710=224
00:34:21.110,INFO ,message,NioProcessor-23,[],8=FIXT.1.19=9135=A34=753949=application_name256=application_name52=20230222-00:34:21.07598=01137=7108=3010=235
00:39:22.054,INFO ,message,QFJ Timer,[],8=FIXT.1.19=9135=A34=805049=application_name52=20230222-00:39:22.04156=application_name298=0108=301137=710=223
00:39:22.070,INFO ,message,NioProcessor-27,[],8=FIXT.1.19=9135=A34=754049=application_name256=application_name52=20230222-00:39:22.06398=01137=7108=3010=230
00:44:22.139,INFO ,message,QFJ Timer,[],8=FIXT.1.19=9135=A34=805149=application_name52=20230222-00:44:22.13156=application_name298=0108=301137=710=220
00:44:22.190,INFO ,message,NioProcessor-28,[],8=FIXT.1.19=9135=A34=754149=application_name256=application_name52=20230222-00:44:22.14098=01137=7108=3010=223
Hard to tell what causes this but the logon and heartbeat timeouts look like a thread is blocked that would normally process these messages. A thread dump would be helpful.
BTW you could also use another connection pool instead of Proxool. Also see here #607