Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

JdbcStore.storeSequenceNumbers throws exception that is never recovered from #613

Open
techdiver opened this issue Feb 23, 2023 · 2 comments
Open

JdbcStore.storeSequenceNumbers throws exception that is never recovered from #613

techdiver opened this issue Feb 23, 2023 · 2 comments
Labels
bug

Comments

@techdiver
Copy link

techdiver commented Feb 23, 2023 •
edited
Loading

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.1�9=72�35=0�34=7536�49=<sender>�56=<target>�52=20230222-00:33:07.986�10=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.1�9=91�35=A�34=8049�49=application_name�52=20230222-00:34:21.031�56=application_name2�98=0�108=30�1137=7�10=224�
00:34:21.110,INFO ,message,NioProcessor-23,[],8=FIXT.1.1�9=91�35=A�34=7539�49=application_name2�56=application_name�52=20230222-00:34:21.075�98=0�1137=7�108=30�10=235�
00:39:22.054,INFO ,message,QFJ Timer,[],8=FIXT.1.1�9=91�35=A�34=8050�49=application_name�52=20230222-00:39:22.041�56=application_name2�98=0�108=30�1137=7�10=223�
00:39:22.070,INFO ,message,NioProcessor-27,[],8=FIXT.1.1�9=91�35=A�34=7540�49=application_name2�56=application_name�52=20230222-00:39:22.063�98=0�1137=7�108=30�10=230�
00:44:22.139,INFO ,message,QFJ Timer,[],8=FIXT.1.1�9=91�35=A�34=8051�49=application_name�52=20230222-00:44:22.131�56=application_name2�98=0�108=30�1137=7�10=220�
00:44:22.190,INFO ,message,NioProcessor-28,[],8=FIXT.1.1�9=91�35=A�34=7541�49=application_name2�56=application_name�52=20230222-00:44:22.140�98=0�1137=7�108=30�10=223�
@techdiver techdiver added the bug label Feb 23, 2023
@chrjohn
Copy link
Member

chrjohn commented Feb 24, 2023

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.

@chrjohn
Copy link
Member

chrjohn commented Feb 25, 2023

BTW you could also use another connection pool instead of Proxool. Also see here #607

@chrjohn chrjohn mentioned this issue Feb 25, 2023
Closed
@chrjohn chrjohn changed the title JdbcStore.storeSequenceNumbers - Throws exception that is never recovered from JdbcStore.storeSequenceNumbers throws exception that is never recovered from Feb 27, 2023
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
bug
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@chrjohn @techdiver