Details
Description
Sequence of events - from the perspective of an Acceptor:
0. Acceptor is restarted with inbound sequence number reset to 0 - all missed messages were session messages.
1. Incoming Logon@sequence=6; responded with Logon response.
2. Outgoing ResendRequest for sequence gap 1-5.
3. Incoming ResendRequest@sequence=7 for sequence range 1005 to infinity.
4. Incoming SequenceReset from 1 to 6 – i.e. gap 1-5 now filled. "Processing queued message: 6".
5. Outgoing SequenceReset - requested gap starting 1005 filled.
6. Incoming Heartbeat@sequence=8. --> At this point Acceptor complains "MsgSeqNum too high, expecting 7 but received 9". WRONG!
7. Acceptor claims that "Already sent ResendRequest FROM: 1 TO: 5. Not sending another." --> and hence all subsequent inbound messages are considered out of sequence. PROBLEM!
This problem seems to be due to that QFJ failed to "queue" the received ResendRequest at step 3 above, and hence treated sequence 7 as never received.
Log excerpt below:
--------------------------------------------------------------
2012-03-29 18:56:43,999 INFO [SocketAcceptorIoProcessor-0.0] AbstractIoHandler.messageReceived(AbstractIoHandler.java:106): FIX.4.2:TRS_OUT->TRS: 8=FIX.4.29=6535=A34=649=TRS52=20120329-22:56:43.62056=TRS_OUT98=0108=3010=078
2012-03-29 18:56:44,037 INFO [QF/J Session dispatcher: FIX.4.2:TRS_OUT->TRS] Session.send(Session.java:2217): FIX.4.2:TRS_OUT->TRS: 8=FIX.4.29=6835=A34=100649=TRS_OUT52=20120329-22:56:44.03756=TRS98=0108=3010=229
2012-03-29 18:56:44,047 INFO [QF/J Session dispatcher: FIX.4.2:TRS_OUT->TRS] Session.send(Session.java:2217): FIX.4.2:TRS_OUT->TRS: 8=FIX.4.29=6535=234=100749=TRS_OUT52=20120329-22:56:44.04656=TRS7=116=510=059
2012-03-29 18:56:44,047 INFO [QF/J Session dispatcher: FIX.4.2:TRS_OUT->TRS] ?.?(?:?): FIX.4.2:TRS_OUT->TRS: Sent ResendRequest FROM: 1 TO: 5
2012-03-29 18:56:44,050 INFO [SocketAcceptorIoProcessor-0.0] AbstractIoHandler.messageReceived(AbstractIoHandler.java:106): FIX.4.2:TRS_OUT->TRS: 8=FIX.4.29=6535=234=749=TRS52=20120329-22:56:44.04956=TRS_OUT7=100516=010=061
2012-03-29 18:56:44,052 INFO [QF/J Session dispatcher: FIX.4.2:TRS_OUT->TRS] ?.?(?:?): FIX.4.2:TRS_OUT->TRS: Received ResendRequest FROM: 1005 TO: infinity
2012-03-29 18:56:44,054 INFO [SocketAcceptorIoProcessor-0.0] AbstractIoHandler.messageReceived(AbstractIoHandler.java:106): FIX.4.2:TRS_OUT->TRS: 8=FIX.4.29=9135=434=143=Y49=TRS52=20120329-22:56:44.05256=TRS_OUT122=20120329-22:56:4436=6123=Y10=104
2012-03-29 18:56:44,055 INFO [QF/J Session dispatcher: FIX.4.2:TRS_OUT->TRS] Session.send(Session.java:2217): FIX.4.2:TRS_OUT->TRS: 8=FIX.4.29=9735=434=100543=Y49=TRS_OUT52=20120329-22:56:44.05456=TRS122=20120329-22:56:4436=1008123=Y10=152
2012-03-29 18:56:44,055 INFO [QF/J Session dispatcher: FIX.4.2:TRS_OUT->TRS] ?.?(?:?): FIX.4.2:TRS_OUT->TRS: Sent SequenceReset TO: 1008
2012-03-29 18:56:44,056 INFO [QF/J Session dispatcher: FIX.4.2:TRS_OUT->TRS] ?.?(?:?): FIX.4.2:TRS_OUT->TRS: Received SequenceReset FROM: 1 TO: 6
2012-03-29 18:56:44,056 INFO [QF/J Session dispatcher: FIX.4.2:TRS_OUT->TRS] ?.?(?:?): FIX.4.2:TRS_OUT->TRS: Processing queued message: 6
2012-03-29 18:57:14,623 INFO [SocketAcceptorIoProcessor-0.0] AbstractIoHandler.messageReceived(AbstractIoHandler.java:106): FIX.4.2:TRS_OUT->TRS: 8=FIX.4.29=5335=034=849=TRS52=20120329-22:57:14.62156=TRS_OUT10=035
2012-03-29 18:57:14,626 ERROR [QF/J Session dispatcher: FIX.4.2:TRS_OUT->TRS] SLF4JLog.logError(SLF4JLog.java:133): FIX.4.2:TRS_OUT->TRS: MsgSeqNum too high, expecting 7 but received 8
2012-03-29 18:57:14,626 INFO [QF/J Session dispatcher: FIX.4.2:TRS_OUT->TRS] ?.?(?:?): FIX.4.2:TRS_OUT->TRS: Already sent ResendRequest FROM: 1 TO: 5. Not sending another.
2012-03-29 18:57:14,627 INFO [QF/J Session dispatcher: FIX.4.2:TRS_OUT->TRS] Session.send(Session.java:2217): FIX.4.2:TRS_OUT->TRS: 8=FIX.4.29=5635=034=100849=TRS_OUT52=20120329-22:57:14.62756=TRS10=189
2012-03-29 18:57:45,623 INFO [SocketAcceptorIoProcessor-0.0] AbstractIoHandler.messageReceived(AbstractIoHandler.java:106): FIX.4.2:TRS_OUT->TRS: 8=FIX.4.29=5335=034=949=TRS52=20120329-22:57:45.62156=TRS_OUT10=040
2012-03-29 18:57:45,625 ERROR [QF/J Session dispatcher: FIX.4.2:TRS_OUT->TRS] SLF4JLog.logError(SLF4JLog.java:133): FIX.4.2:TRS_OUT->TRS: MsgSeqNum too high, expecting 7 but received 9
2012-03-29 18:57:45,625 INFO [QF/J Session dispatcher: FIX.4.2:TRS_OUT->TRS] ?.?(?:?): FIX.4.2:TRS_OUT->TRS: Already sent ResendRequest FROM: 1 TO: 5. Not sending another.
2012-03-29 18:57:45,626 INFO [QF/J Session dispatcher: FIX.4.2:TRS_OUT->TRS] Session.send(Session.java:2217): FIX.4.2:TRS_OUT->TRS: 8=FIX.4.29=5635=034=100949=TRS_OUT52=20120329-22:57:45.62656=TRS10=193
-------------------------------------------------------------------