[QFJ-718] Logout message sent after event "resetting sequence numbers to 1" with msgSeqNum too low error Created: 22/Nov/12  Updated: 16/Dec/13  Resolved: 16/Dec/13

Status: Closed
Project: QuickFIX/J
Component/s: Engine
Affects Version/s: 1.5.2
Fix Version/s: None

Type: Bug Priority: Default
Reporter: Ashish Goswami Assignee: Unassigned
Resolution: Fixed Votes: 0
Labels: QuickfixJ, logon
Environment:

Windows7

Issue Links:
Relates
relates to QFJ-444 Logout logic problem Resolved

 Description   

Acceptor program sometimes send logout message with msgSeqNum too low error after receving logon message with reset Seq num flag<TAG 141>=Y.

Expected Behavior: Acceptor program should reset the seq and send the log on message

Config file settings:

ResetOnDisconnect=Y
ResetOnLogout=Y
ResetOnLogon=Y

Entries from Log file When this error happens:

2012-11-10 18:59:13,045 INFO outgoing - FIX.4.4:CD->DLR1: 8=FIX.4.4|9=61|35=0|34=182|49=CD|52=20121110-23:59:13.045|56=DLR1|10=068|
2012-11-10 18:59:33,325 INFO incoming - FIX.4.4:CD->DLR1: 8=FIX.4.4|9=61|35=0|34=189|49=DLR1|52=20121110-23:59:54.923|56=CD|10=085|
2012-11-10 18:59:33,325 INFO outgoing - FIX.4.4:CD->DLR1: 8=FIX.4.4|9=61|35=0|34=183|49=CD|52=20121110-23:59:33.325|56=DLR1|10=072|
2012-11-10 18:59:37,599 INFO incoming - FIX.4.4:CD->DLR1: 8=FIX.4.4|9=61|35=5|34=190|49=DLR1|52=20121110-23:59:59.199|56=CD|10=092|
2012-11-10 18:59:37,599 INFO event - FIX.4.4:CD->DLR1: Received logout request
2012-11-10 18:59:37,599 INFO Session - [FIX.4.4:CD->DLR1] Disconnecting: IO Session closed
2012-11-10 18:59:37,599 INFO outgoing - FIX.4.4:CD->DLR1: 8=FIX.4.4|9=61|35=5|34=184|49=CD|52=20121110-23:59:37.599|56=DLR1|10=095|
2012-11-10 18:59:37,599 INFO event - FIX.4.4:CD->DLR1: No responder, not sending message: 8=FIX.4.4|9=61|35=5|34=184|49=CD|52=20121110-23:59:37.599|56=DLR1|10=095|
2012-11-10 18:59:37,599 INFO event - FIX.4.4:CD->DLR1: Sent logout response
2012-11-10 18:59:37,599 INFO event - FIX.4.4:CD->DLR1: Already disconnected: Received logout request
2012-11-10 19:00:12,700 INFO AcceptorIoHandler - MINA session created: /124.30.187.33:35167
2012-11-10 19:00:12,980 INFO incoming - FIX.4.4:CD->DLR1: 8=FIX.4.4|9=77|35=A|34=1|49=DLR1|52=20121111-00:00:34.573|56=CD|98=0|108=20|141=Y|10=046|
2012-11-10 19:00:12,980 INFO event - FIX.4.4:CD->DLR1: Accepting session FIX.4.4:CD->DLR1 from /124.30.187.33:35167
2012-11-10 19:00:12,980 INFO event - FIX.4.4:CD->DLR1: Acceptor heartbeat set to 20 seconds
2012-11-10 19:00:12,980 INFO event - FIX.4.4:CD->DLR1: Logon contains ResetSeqNumFlag=Y, resetting sequence numbers to 1
2012-11-10 19:00:12,980 INFO outgoing - FIX.4.4:CD->DLR1: 8=FIX.4.4|9=112|35=5|34=185|49=CD|52=20121111-00:00:12.980|56=DLR1|58=MsgSeqNum too low, expecting 191 but received 1|10=110|
2012-11-10 19:00:12,980 ERROR errorEvent - FIX.4.4:CD->DLR1: quickfix.SessionException MsgSeqNum too low, expecting 191 but received 1
2012-11-10 19:00:12,980 ERROR errorEvent - FIX.4.4:CD->DLR1: Disconnecting: Verifying message failed: quickfix.SessionException: MsgSeqNum too low, expecting 191 but received 1

Entries from log file when it works fine

2012-11-21 00:19:36,335 INFO outgoing - FIX.4.4:CD->DLR1: 8=FIX.4.4|9=60|35=0|34=12|49=CD|52=20121121-05:19:36.335|56=DLR1|10=016|
2012-11-21 00:19:48,597 INFO incoming - FIX.4.4:CD->DLR1: 8=FIX.4.4|9=60|35=0|34=13|49=DLR1|52=20121121-05:19:58.465|56=CD|10=025|
2012-11-21 00:19:56,335 INFO outgoing - FIX.4.4:CD->DLR1: 8=FIX.4.4|9=60|35=0|34=13|49=CD|52=20121121-05:19:56.335|56=DLR1|10=019|
2012-11-21 00:19:57,598 INFO incoming - FIX.4.4:CD->DLR1: 8=FIX.4.4|9=60|35=5|34=14|49=DLR1|52=20121121-05:20:07.458|56=CD|10=019|
2012-11-21 00:19:57,598 INFO event - FIX.4.4:CD->DLR1: Received logout request
2012-11-21 00:19:57,598 INFO outgoing - FIX.4.4:CD->DLR1: 8=FIX.4.4|9=60|35=5|34=14|49=CD|52=20121121-05:19:57.598|56=DLR1|10=037|
2012-11-21 00:19:57,598 INFO event - FIX.4.4:CD->DLR1: Sent logout response
2012-11-21 00:19:57,598 INFO Session - [FIX.4.4:CD->DLR1] Disconnecting: Received logout request
2012-11-21 00:20:34,274 INFO AcceptorIoHandler - MINA session created: /124.30.187.33:4995
2012-11-21 00:20:55,162 INFO incoming - FIX.4.4:CD->DLR1: 8=FIX.4.4|9=77|35=A|34=1|49=DLR1|52=20121121-05:21:05.042|56=CD|98=0|108=20|141=Y|10=044|
2012-11-21 00:20:55,162 INFO event - FIX.4.4:CD->DLR1: Accepting session FIX.4.4:CD->DLR1 from /124.30.187.33:4995
2012-11-21 00:20:55,162 INFO event - FIX.4.4:CD->DLR1: Acceptor heartbeat set to 20 seconds
2012-11-21 00:20:55,162 INFO event - FIX.4.4:CD->DLR1: Logon contains ResetSeqNumFlag=Y, resetting sequence numbers to 1
2012-11-21 00:20:55,162 INFO event - FIX.4.4:CD->DLR1: Received logon
2012-11-21 00:20:55,162 INFO outgoing - FIX.4.4:CD->DLR1: 8=FIX.4.4|9=77|35=A|34=1|49=CD|52=20121121-05:20:55.162|56=DLR1|98=0|108=20|141=Y|10=051|
2012-11-21 00:20:55,162 INFO event - FIX.4.4:CD->DLR1: Responding to logon request

 Comments   
Comment by Christoph John [ 22/Nov/12 ]

At first sight this looks a lot like QFJ-444 where some state flags were not reset. Could you please check if the behaviour can still be observed with QF/J 1.5.3 (should be out in the next few weeks)?

Comment by Ashish Goswami [ 22/Nov/12 ]

Thanks for the update, It looks like i have similar issue, Will wait for QF/J 1.5.3

Generated at Sat Nov 23 11:19:42 UTC 2024 using JIRA 7.5.2#75007-sha1:9f5725bb824792b3230a5d8716f0c13e296a3cae.