QuickFIX/J - Connection getting forcibly closed by remote host when receiving multiple SecurityDefinitions

1
votes

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 )
1
quickfixj
When the connection is closed by the foreign host I'd ask them why they closed it. Maybe they have some kind of "slow peer detection" or the like. Maybe the problem is simply in the network and not in the application. – Christoph John
Can you verify the QuickFIX/J log file (~.event.log and ~.messages.log), see if that gives you clue? Does it always happen exactly after 14 messages? Does it always happen when receiving security definitions? What version of QuickFIX/J are you using? – TT.
@John - Since this issue is consistent , I don't think its network issue. I think there is some issue on application since I get the messages up until certain point. Its only when I am receiving bigger security definitions where 1 definition is split into multiple message , I see this issue. Not sure what am I missing and since I get the other securities definitions which are smaller in size, I am not sure ICE will be able to help. – Learner_12
@TT - In logs I am only getting this error message. It always happens when securities are more than 1200 in size. For this particular market it is always happening after 14 message. I am using quickfixj-all-2.1.0.jar. – Learner_12
1200 what in size? 1200 securities in one message or 1200 bytes in size? I think unless you give us some example messages it is hard to tell what the problem is. Edit: again, asking the counterparty why they drop the connection should be done anyway. Maybe they know the reason. Does it hurt to ask them? – Christoph John

1 Answers

2
votes

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:

  1. completely disable logging, i.e. set level to WARN or ERROR so that logging of the long messages is prevented and re-test if the problem persists.
  2. increase heap memory of your application and re-test if the problem persists.