[QFJ-673] QFJ sequence problem following inbound SequenceReset - a previously received ResendRequest not "queued"? Created: 30/Mar/12  Updated: 16/Jul/18  Resolved: 18/Dec/13

Status: Closed
Project: QuickFIX/J
Component/s: Engine
Affects Version/s: 1.5.0
Fix Version/s: 1.6.0

Type: Bug Priority: Default
Reporter: John Peng Assignee: Christoph John
Resolution: Fixed Votes: 2
Labels: Reconnect, ResendRequest,, SequnceReset,, queued, sequence,

Attachments: Text File QFJ_bug_report.log    
Issue Links:
Duplicate
is duplicated by QFJ-658 Sequence numbers not checked for inco... Closed
is duplicated by QFJ-766 FIX Resend Issue Closed
is duplicated by QFJ-814 Sequence Reset Fails Closed

 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
-------------------------------------------------------------------

 Comments   
Comment by John Peng [ 30/Mar/12 ]

Log excerpt attached as file.

Comment by John Peng [ 30/Mar/12 ]

After doing a quick trace-through into the 1.6 code – I now have a better idea as to why this was happening:

1. Session.State.enqueue() is only called via Session.doTargetTooHigh();
2. Session.doTargetTooHigh() in turn is only called in Session.nextLogon() or Session.verify(msg, checkTooHigh, checkTooLow) - when checkTooHigh=true;
3. When Session.verify(msg, checkTooHigh, checkTooLow) is applied to ResendRequest in Session.nextResendRequest(), the "checkTooHigh" parameter is always false!

Therefore, a ResendRequest that comes after an outstanding sequence gap is NEVER enqueued!

I believe the following code in Session.java should be improved in order to fix the bug:
-----------------------------------------------------------------------------------------
private void nextResendRequest(Message resendRequest) throws IOException, RejectLogon,
FieldNotFound, IncorrectDataFormat, IncorrectTagValue, UnsupportedMessageType,
InvalidMessage {
if (!verify(resendRequest, false, false))

{ return; }

..........
}
-----------------------------------------------------------------------------------------

In particular, verify() shouldn't always be called with "false, false". More conditional check on the Session state should be carried out to determine the right value for the parameters.

Comment by John Peng [ 30/Mar/12 ]

Given the above, this issue would affect version 1.6 as well. Can someone help modify "Affects Version/s" to also include 1.6? Thanks.

Comment by Heribert Steuer [ 13/Dec/13 ]

Being still an open bug, can someone confirm that Johns patch addresses this problem correctly? Its pretty annoying as we have a couple of FIX sessions using VPN, broken network connections regularily bring up this problems and
leave failed sessions. Thanks!

Comment by Christoph John [ 13/Dec/13 ]

Calling verify with "true", "true" is likely to correct the problem and will adhere to the spec (see QFJ-658), however then there are some acceptance tests that fail. Will have to check further.

Comment by Christoph John [ 16/Dec/13 ]

There are two problems here:
1. verify is called without checking for too high seqnums
2. when point 1 has been corrected the queued ResendRequest is not processed

Problem 2 can be corrected by changing method Session.nextQueued(int num) to also process queued ResendRequests and not just increment the target seqnum.

Proposed fix is:
1. to check sequence numbers also on ResendRequests based on configuration ValidateSequenceNumbers as this is also done for other messages as well.
2. to process queued ResendRequest if ValidateSequenceNumbers=Y. Otherwise discard ResendRequest and just increment target seqnum since ResendRequest processing already took place (former behaviour).

Comment by Christoph John [ 18/Dec/13 ]

Committed as rev1127: http://sourceforge.net/p/quickfixj/code/1127/

Just enabling the "tooHigh"-check in verify() would have solved the original problem. However, this could have lead to kind of a deadlock in which the counterparty waited for our messages to be resent and we were also waiting for our ResendRequest to be satisfied in order to process the queued ResendRequest of the counterparty (and only then send the missing messages to the counterparty).
So the former behaviour has been kept and another condition has been introduced outside of the verify() method in nextResendRequest() which will simply enqueue the ResendRequest and method nextQueued(int) will later just increase the target seqnum (this was already present in nextQueued(int) so the new behaviour was probably intended from the beginning but it was forgotten to enqueue the ResendRequest).

Generated at Sat May 04 11:52:39 UTC 2024 using JIRA 7.5.2#75007-sha1:9f5725bb824792b3230a5d8716f0c13e296a3cae.