I am processing security definitions coming from ICE exchange using quickfixj. When I do it for markets which has securities less than 1000/1200, I get it via multiple message (100 securities per request(35=d) ) without any issues. However when it has more securities than after 14 messages, my session get disconnected with below error:
'Socket exception: java.io.IOException: An existing connection was forcibly closed by the remote host'
I can still see message 15 in logs but it does not come inside fromApp method.
I understand that sometimes this kind of issue happens if too much processing is happening in fromAPP method. I checked the fromApp method and I was just putting the message to a queue which gets processed by another thread, I am not doing anything in that method. To troubleshoot this error, I have removed any logic from fromApp method and for now I am just printing number of messages received so far. Even with this, my session gets disconnect after 14 messages. ( whereas more than 50 messages should have come.)
@Override
public void fromApp(quickfix.Message message, SessionID sessionID)
throws FieldNotFound, IncorrectDataFormat, IncorrectTagValue, UnsupportedMessageType {
try {
counter++;
System.out.println("Inside from App, message : " +counter);
} catch (Exception e) {
System.out.println("Failed to process the underlying. Error message: " + e.getMessage());
}
}
I have checked the configuration file as well. I have played with it to see if any of the validation if causing it but no luck. Here is the config file I am using:
[default]
FileStorePath=C:\Test
BeginString=FIX.4.4
ConnectionType=initiator
[session]
SenderCompID=XXXX
SenderSubID=X
SenderLocationID=X
TargetCompID=ICE
SocketConnectHost=XX.XXX.XXX.XXX
SocketConnectPort=80
StartTime=00:00:00
EndTime=23:59:59
HeartBtInt=60
ReconnectInterval=5
UseDataDictionary=Y
ResetOnLogon=Y
ForceResync=Y
CheckLatency=N
I am expecting to receive all the 50 messages instead of 14 message followed by session disconnected error I am getting right now. Any help/ideas on why this issue is happening and how can I fix this would be really appreciated. Thanks.
Logs as mentioned in the comments (total no of securities 19293, expected msg count (35=d) - 193 for 1 security definition request. Received -13, session disconnect after that:
{Inside Logon
2019-09-08 12:43:46 INFO DefaultSessionSchedule:87 - [FIX.4.4:xxxx/x/x->ICE] daily, 00:00:00-UTC - 23:59:59-UTC
<20190908-10:43:46, FIX.4.4:xxxx/x/x->ICE, event> (Session FIX.4.4:xxxx/x/x->ICE schedule is daily, 00:00:00-UTC - 23:59:59-UTC)
<20190908-10:43:46, FIX.4.4:xxxx/x/x->ICE, event> (Created session: FIX.4.4:xxxx/x/x->ICE)
inside oncreate
<20190908-10:43:46, FIX.4.4:xxxx/x/x->ICE, event> (Configured socket addresses for session: [/63.247.113.249:80])
2019-09-08 12:43:46 INFO ThreadedSocketInitiator:321 - SessionTimer started
<20190908-10:43:46, FIX.4.4:xxxx/x/x->ICE, event> (MINA session created: local=/10.72.59.226:54361, class org.apache.mina.transport.socket.nio.NioSocketSession, remote=/63.247.113.249:80)
<20190908-10:43:47, FIX.4.4:xxxx/x/x->ICE, outgoing> (8=FIX.4.4 9=108 35=A 34=1 49=xxxx 50=1 52=20190908-10:43:47.860 56=ICE 142=0 553=xxxxxxxx 554=xxxxxxx 98=0 108=30 141=Y 10=098 )
<20190908-10:43:47, FIX.4.4:xxxx/x/x->ICE, event> (Initiated logon request)
2019-09-08 12:43:48 DEBUG ProtocolCodecFilter:233 - Processing a MESSAGE_RECEIVED for session 1
<20190908-10:43:48, FIX.4.4:xxxx/x/x->ICE, incoming> (8=FIX.4.4 9=73 35=A 49=ICE 34=1 52=20190908-10:43:47.519 56=xxxx 57=1 98=0 108=30 141=Y 10=189 )
<20190908-10:43:48, FIX.4.4:xxxx/x/x->ICE, event> (Logon contains ResetSeqNumFlag=Y, resetting sequence numbers to 1)
<20190908-10:43:48, FIX.4.4:xxxx/x/x->ICE, event> (Received logon)
2019-09-08 12:44:18 DEBUG ProtocolCodecFilter:233 - Processing a MESSAGE_RECEIVED for session 1
<20190908-10:44:18, FIX.4.4:xxxx/x/x->ICE, incoming> (8=FIX.4.4 9=55 35=0 49=ICE 34=2 52=20190908-10:44:17.563 56=xxxx 57=1 10=100 )
<20190908-10:44:18, FIX.4.4:xxxx/x/x->ICE, outgoing> (8=FIX.4.4 9=61 35=0 34=3 49=xxxx 50=1 52=20190908-10:44:18.844 56=ICE 142=0 10=099 )
2019-09-08 12:44:18 DEBUG ProtocolCodecFilter:233 - Processing a MESSAGE_RECEIVED for session 1
<20190908-10:44:18, FIX.4.4:xxxx/x/x->ICE, incoming> (8=FIX.4.4 9=64 35=2 49=ICE 34=3 52=20190908-10:44:18.459 56=xxxx 57=1 7=2 16=2 10=234 )
<20190908-10:44:18, FIX.4.4:xxxx/x/x->ICE, event> (Received ResendRequest FROM: 2 TO: 2)
inside toApp
<20190908-10:44:18, FIX.4.4:xxxx/x/x->ICE, event> (Resending message: 2)
<20190908-10:44:18, FIX.4.4:xxxx/x/x->ICE, outgoing> (8=FIX.4.4 9=134 35=c 34=2 43=Y 49=xxxx 50=1 52=20190908-10:44:18.963 56=ICE 122=20190908-10:43:48.598 142=0 48=2 320=1567939428584_0 321=3 461=FXXXXX 10=178 )
2019-09-08 12:44:19 DEBUG ProtocolCodecFilter:233 - Processing a MESSAGE_RECEIVED for session 1
<20190908-10:44:19, FIX.4.4:xxxx/x/x->ICE, incoming> (8=FIX.4.4 9=61 35=1 49=ICE 34=4 52=20190908-10:44:18.564 56=xxxx 57=1 112=1 10=105 )
<20190908-10:44:19, FIX.4.4:xxxx/x/x->ICE, outgoing> (8=FIX.4.4 9=67 35=0 34=4 49=xxxx 50=1 52=20190908-10:44:19.064 56=ICE 142=0 112=1 10=104 )
2019-09-08 12:44:19 DEBUG ProtocolCodecFilter:233 - Processing a MESSAGE_RECEIVED for session 1
<20190908-10:44:19, FIX.4.4:xxxx/x/x->ICE, incoming> (8=FIX.4.4 9=73 35=1 49=ICE 34=5 52=20190908-10:44:18.578 56=xxxx 57=1 112=1567939458579 10=255 )
<20190908-10:44:19, FIX.4.4:xxxx/x/x->ICE, outgoing> (8=FIX.4.4 9=79 35=0 34=5 49=xxxx 50=1 52=20190908-10:44:19.078 56=ICE 142=0 112=1567939458579 10=254 )
2019-09-08 12:44:20 DEBUG ProtocolCodecFilter:233 - Processing a MESSAGE_RECEIVED for session 1
2019-09-08 12:44:20 DEBUG ProtocolCodecFilter:233 - Processing a MESSAGE_RECEIVED for session 1
2019-09-08 12:44:20 DEBUG ProtocolCodecFilter:233 - Processing a MESSAGE_RECEIVED for session 1
2019-09-08 12:44:20 DEBUG ProtocolCodecFilter:233 - Processing a MESSAGE_RECEIVED for session 1
2019-09-08 12:44:20 DEBUG ProtocolCodecFilter:233 - Processing a MESSAGE_RECEIVED for session 1
2019-09-08 12:44:20 DEBUG ProtocolCodecFilter:233 - Processing a MESSAGE_RECEIVED for session 1
2019-09-08 12:44:20 DEBUG ProtocolCodecFilter:233 - Processing a MESSAGE_RECEIVED for session 1
2019-09-08 12:44:20 DEBUG ProtocolCodecFilter:233 - Processing a MESSAGE_RECEIVED for session 1
2019-09-08 12:44:20 DEBUG ProtocolCodecFilter:233 - Processing a MESSAGE_RECEIVED for session 1
<20190908-10:44:20, FIX.4.4:xxxx/x/x->ICE, incoming> (8=FIX.4.4 9=67593 35=d 49=ICE 34=6 52=20190908-10:44:19.844 56=xxxx 57=1 322=7250 323=4 320=1567939428584_0 393=19238 82=193 67=1 9064=0 711=100 311=5832793 ..
2019-09-08 12:44:20 DEBUG ProtocolCodecFilter:233 - Processing a MESSAGE_RECEIVED for session 1
security message no : 1:
2019-09-08 12:44:20 DEBUG ProtocolCodecFilter:233 - Processing a MESSAGE_RECEIVED for session 1
<20190908-10:44:20, FIX.4.4:xxxx/x/x->ICE, incoming> (8=FIX.4.4 9=60808 35=d 49=ICE 34=7 52=20190908-10:44:19.844 56=xxxx 57=1 322=7251 323=4 320=1567939428584_0 393=19238 82=193 67=2 9064=0 711=100 311=5832754 ...
2019-09-08 12:44:20 DEBUG ProtocolCodecFilter:233 - Processing a MESSAGE_RECEIVED for session 1
security message no : 2:
<20190908-10:44:20, FIX.4.4:xxxx/x/x->ICE, incoming> (8=FIX.4.4 9=56951 35=d 49=ICE 34=8 52=20190908-10:44:19.844 56=xxxx 57=1 322=7252 323=4 320=1567939428584_0 393=19238 82=193 67=3 9064=0 711=100 311=5964169 ...
2019-09-08 12:44:20 DEBUG ProtocolCodecFilter:233 - Processing a MESSAGE_RECEIVED for session 1
security message no : 3:
2019-09-08 12:44:20 DEBUG ProtocolCodecFilter:233 - Processing a MESSAGE_RECEIVED for session 1
2019-09-08 12:44:20 DEBUG ProtocolCodecFilter:233 - Processing a MESSAGE_RECEIVED for session 1
2019-09-08 12:44:20 DEBUG ProtocolCodecFilter:233 - Processing a MESSAGE_RECEIVED for session 1
<20190908-10:44:20, FIX.4.4:xxxx/x/x->ICE, incoming> (8=FIX.4.4 9=60133 35=d 49=ICE 34=9 52=20190908-10:44:20.070 56=xxxx 57=1 322=7253 323=4 320=1567939428584_0 393=19238 82=193 67=4 9064=0 711=100 311=5931984 ...
2019-09-08 12:44:25 DEBUG ProtocolCodecFilter:233 - Processing a MESSAGE_RECEIVED for session 1
security message no : 4:
<20190908-10:44:25, FIX.4.4:xxxx/x/x->ICE, incoming> (8=FIX.4.4 9=59412 35=d 49=ICE 34=10 52=20190908-10:44:20.184 56=xxxx 57=1 322=7254 323=4 320=1567939428584_0 393=19238 82=193 67=5 9064=0 711=100 311=5932131 ...
2019-09-08 12:44:25 DEBUG ProtocolCodecFilter:233 - Processing a MESSAGE_RECEIVED for session 1
security message no : 5:
<20190908-10:44:25, FIX.4.4:xxxx/x/x->ICE, incoming> (8=FIX.4.4 9=58564 35=d 49=ICE 34=11 52=20190908-10:44:20.184 56=xxxx 57=1 322=7255 323=4 320=1567939428584_0 393=19238 82=193 67=6 9064=0 711=100 311=6063274 ..
2019-09-08 12:44:25 DEBUG ProtocolCodecFilter:233 - Processing a MESSAGE_RECEIVED for session 1
security message no : 6:
<20190908-10:44:25, FIX.4.4:xxxx/x/x->ICE, incoming> (8=FIX.4.4 9=58085 35=d 49=ICE 34=12 52=20190908-10:44:20.296 56=xxxx 57=1 322=7256 323=4 320=1567939428584_0 393=19238 82=193 67=7 9064=0 711=100 311=6063858 ...
2019-09-08 12:44:43 DEBUG ProtocolCodecFilter:233 - Processing a MESSAGE_RECEIVED for session 1
security message no : 7:
<20190908-10:44:43, FIX.4.4:xxxx/x/x->ICE, incoming> (8=FIX.4.4 9=58654 35=d 49=ICE 34=13 52=20190908-10:44:20.296 56=xxxx 57=1 322=7257 323=4 320=1567939428584_0 393=19238 82=193 67=8 9064=0 711=100 311=5867472 ....
2019-09-08 12:44:43 DEBUG ProtocolCodecFilter:233 - Processing a MESSAGE_RECEIVED for session 1
security message no : 8:
<20190908-10:44:43, FIX.4.4:xxxx/x/x->ICE, incoming> (8=FIX.4.4 9=59786 35=d 49=ICE 34=14 52=20190908-10:44:20.296 56=xxxx 57=1 322=7258 323=4 320=1567939428584_0 393=19238 82=193 67=9 9064=0 711=100 311=5867638 ..
2019-09-08 12:44:43 DEBUG ProtocolCodecFilter:233 - Processing a MESSAGE_RECEIVED for session 1
security message no : 9:
<20190908-10:44:43, FIX.4.4:xxxx/x/x->ICE, incoming> (8=FIX.4.4 9=57341 35=d 49=ICE 34=15 52=20190908-10:44:20.296 56=xxxx 57=1 322=7259 323=4 320=1567939428584_0 393=19238 82=193 67=10 9064=0 711=100 311=5867886 3..
<20190908-10:45:17, FIX.4.4:xxxx/x/x->ICE, outgoing> (8=FIX.4.4 9=61 35=0 34=6 49=xxxx 50=1 52=20190908-10:44:49.846 56=ICE 142=0 10=108 )
<20190908-10:45:17, FIX.4.4:xxxx/x/x->ICE, incoming> (8=FIX.4.4 9=57999 35=d 49=ICE 34=16 52=20190908-10:44:20.357 56=xxxx 57=1 322=7260 323=4 320=1567939428584_0 393=19238 82=193 67=11 9064=0 711=100 311=6097650 ..
security message no : 10:
2019-09-08 12:45:17 DEBUG ProtocolCodecFilter:233 - Processing a MESSAGE_RECEIVED for session 1
security message no : 11:
<20190908-10:45:17, FIX.4.4:xxxx/x/x->ICE, incoming> (8=FIX.4.4 9=63224 35=d 49=ICE 34=17 52=20190908-10:44:20.357 56=xxxx 57=1 322=7261 323=4 320=1567939428584_0 393=19238 82=193 67=12 9064=0 711=100 311=5770217 ...
2019-09-08 12:45:17 DEBUG ProtocolCodecFilter:233 - Processing a MESSAGE_RECEIVED for session 1
security message no : 12:
<20190908-10:45:17, FIX.4.4:xxxx/x/x->ICE, incoming> (8=FIX.4.4 9=54954 35=d 49=ICE 34=18 52=20190908-10:44:20.357 56=xxxx 57=1 322=7262 323=4 320=1567939428584_0 393=19238 82=193 67=13 9064=0 711=100 311=5868773..
<20190908-10:45:53, FIX.4.4:xxxx/x/x->ICE, outgoing> (8=FIX.4.4 9=61 35=0 34=7 49=xxxx 50=1 52=20190908-10:45:19.846 56=ICE 142=0 10=107 )
<20190908-10:45:53, FIX.4.4:xxxx/x/x->ICE, outgoing> (8=FIX.4.4 9=61 35=0 34=8 49=xxxx 50=1 52=20190908-10:45:53.875 56=ICE 142=0 10=108 )
security message no : 13:
<20190908-10:45:53, FIX.4.4:xxxx/x/x->ICE, event> (Disconnecting: Encountered END_OF_STREAM)
inside onLogOut
java.io.IOException: An existing connection was forcibly closed by the remote host
at sun.nio.ch.SocketDispatcher.write0(Native Method)
at sun.nio.ch.SocketDispatcher.write(Unknown Source)
at sun.nio.ch.IOUtil.writeFromNativeBuffer(Unknown Source)
at sun.nio.ch.IOUtil.write(Unknown Source)
at sun.nio.ch.SocketChannelImpl.write(Unknown Source)
at org.apache.mina.transport.socket.nio.NioProcessor.write(NioProcessor.java:384)
at org.apache.mina.transport.socket.nio.NioProcessor.write(NioProcessor.java:47)
at org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor.writeBuffer(AbstractPollingIoProcessor.java:1107)
at org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor.flushNow(AbstractPollingIoProcessor.java:994)
at org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor.flush(AbstractPollingIoProcessor.java:921)
at org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor.run(AbstractPollingIoProcessor.java:688)
at org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:64)
at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
at java.lang.Thread.run(Unknown Source)
2019-09-08 12:45:54 DEBUG AbstractIoService:338 - awaitTermination on (nio socket connector: managedSessionCount: 0) called by thread=[QFJ Timer]
2019-09-08 12:45:54 DEBUG AbstractIoService:340 - awaitTermination on (nio socket connector: managedSessionCount: 0) finished
<20190908-10:45:54, FIX.4.4:xxxx/x/x->ICE, event> (MINA session created: local=/10.72.59.226:54391, class org.apache.mina.transport.socket.nio.NioSocketSession, remote=/63.247.113.249:80)
inside add credetials
<20190908-10:45:55, FIX.4.4:xxxx/x/x->ICE, outgoing> (8=FIX.4.4 9=108 35=A 34=1 49=xxxx 50=1 52=20190908-10:45:55.850 56=ICE 142=0 553=xxxxxxxx 554=xxxxxxx 98=0 108=30 141=Y 10=098 )
<20190908-10:45:55, FIX.4.4:xxxx/x/x->ICE, event> (Initiated logon request)
2019-09-08 12:45:55 DEBUG ProtocolCodecFilter:233 - Processing a MESSAGE_RECEIVED for session 2
<20190908-10:45:55, FIX.4.4:xxxx/x/x->ICE, incoming> (8=FIX.4.4 9=73 35=A 49=ICE 34=1 52=20190908-10:45:55.495 56=xxxx 57=1 98=0 108=30 141=Y 10=193 )
<20190908-10:45:55, FIX.4.4:xxxx/x/x->ICE, event> (Logon contains ResetSeqNumFlag=Y, resetting sequence numbers to 1)
<20190908-10:45:55, FIX.4.4:xxxx/x/x->ICE, event> (Received logon)
<20190908-10:46:25, FIX.4.4:xxxx/x/x->ICE, outgoing> (8=FIX.4.4 9=61 35=0 34=2 49=xxxx 50=1 52=20190908-10:46:25.848 56=ICE 142=0 10=102 )
2019-09-08 12:46:26 DEBUG ProtocolCodecFilter:233 - Processing a MESSAGE_RECEIVED for session 2
<20190908-10:46:26, FIX.4.4:xxxx/x/x->ICE, incoming> (8=FIX.4.4 9=55 35=0 49=ICE 34=2 52=20190908-10:46:25.684 56=xxxx 57=1 10=105 )
<20190908-10:46:55, FIX.4.4:xxxx/x/x->ICE, outgoing> (8=FIX.4.4 9=61 35=0 34=3 49=xxxx 50=1 52=20190908-10:46:55.848 56=ICE 142=0 10=106 )
2019-09-08 12:46:56 DEBUG ProtocolCodecFilter:233 - Processing a MESSAGE_RECEIVED for session 2
<20190908-10:46:56, FIX.4.4:xxxx/x/x->ICE, incoming> (8=FIX.4.4 9=55 35=0 49=ICE 34=3 52=20190908-10:46:55.689 56=xxxx 57=1 10=114 )
<20190908-10:47:25, FIX.4.4:xxxx/x/x->ICE, outgoing> (8=FIX.4.4 9=61 35=0 34=4 49=xxxx 50=1 52=20190908-10:47:25.848 56=ICE 142=0 10=105 )
2019-09-08 12:47:26 DEBUG ProtocolCodecFilter:233 - Processing a MESSAGE_RECEIVED for session 2
<20190908-10:47:26, FIX.4.4:xxxx/x/x->ICE, incoming> (8=FIX.4.4 9=55 35=0 49=ICE 34=4 52=20190908-10:47:25.692 56=xxxx 57=1 10=107 )
I guess the problem why the connection is dropped is because you do not process your messages in time. ICE is probably waiting for heartbeats that you send out way too late (they probably would have told you that if you asked) and drops the connection because of that. Unfortunately I cannot tell only from the log why it is so slow.
But the slowness starts after incoming message with seqnum 9. You can see that up to that point the log timestamp and the 52/SendingTime of the message nearly match.
Incoming message 10 already has 5 seconds delay.
The heartbeat that you send out with seqnum 6 has a delay of 28 secs.
Incoming message 16 is almost a minute too late.
At first I suspected the "client" through which you connect. But that would not slow down your outgoing heartbeats.
It could be that your application has too little heap space configured and is hence doing a lot of garbage collections. Logging and processing FIX messages of 60kB is probably not so common. Or due to some reason QFJ really needs a long time to process such big messages. A series of stack traces or a profiler would help to diagnose this further.
I would try two things separately: