Sequence numbers not being reset about quickfixn HOT 21 CLOSED

I'll take a look at this. Thanks for the info.

from quickfixn.

This still does not seem to be working. I downloaded the kkozel-quickfixn-a615754 source and built the DLL. I had a connection up and running on Friday, and when it reconnected this morning it is still expecting the sequence numbers to resume from where they left off.

Log is as follows:

20120113-17:15:34.142 : 8=FIX.4.4|9=65|35=0|34=294|49=TID|52=20120113-17:15:34.135|56=SID|10=037|
20120113-17:16:03.246 : 8=FIX.4.4|9=65|35=0|34=287|49=SID|52=20120113-17:16:03.243|56=TID|10=036|
20120113-17:16:34.372 : 8=FIX.4.4|9=65|35=0|34=295|49=TID|52=20120113-17:16:34.359|56=SID|10=047|
20120113-17:17:03.476 : 8=FIX.4.4|9=65|35=0|34=288|49=SID|52=20120113-17:17:03.474|56=TID|10=044|
20120113-17:55:31.794 : 8=FIX.4.4|9=77|35=A|34=289|49=SID|52=20120113-17:55:31.786|56=TID|98=0|108=60|10=102|
20120113-17:55:31.836 : 8=FIX.4.4|9=77|35=A|34=296|49=TID|52=20120113-17:55:31.829|56=SID|98=0|108=60|10=098|
20120113-17:56:31.352 : 8=FIX.4.4|9=65|35=0|34=297|49=TID|52=20120113-17:56:31.343|56=SID|10=043|
20120113-17:56:32.367 : 8=FIX.4.4|9=65|35=0|34=290|49=SID|52=20120113-17:56:32.363|56=TID|10=039|
20120113-17:57:31.527 : 8=FIX.4.4|9=65|35=0|34=298|49=TID|52=20120113-17:57:31.519|56=SID|10=050|
20120113-17:57:32.534 : 8=FIX.4.4|9=65|35=0|34=291|49=SID|52=20120113-17:57:32.532|56=TID|10=039|
20120116-08:44:25.219 : 8=FIX.4.4|9=77|35=A|34=292|49=SID|52=20120116-08:44:25.214|56=TID|98=0|108=60|10=086|
20120116-08:44:25.231 : 8=FIX.4.4|9=65|35=5|34=299|49=TID|52=20120116-08:44:25.225|56=SID|10=052|
20120116-08:44:25.275 : 8=FIX.4.4|9=65|35=5|34=293|49=SID|52=20120116-08:44:25.272|56=TID|10=048|
20120116-08:45:25.221 : 8=FIX.4.4|9=77|35=A|34=294|49=SID|52=20120116-08:45:25.198|56=TID|98=0|108=60|10=100|
20120116-08:45:25.641 : 8=FIX.4.4|9=75|35=A|34=1|49=TID|52=20120116-08:45:25.296|56=SID|98=0|108=60|10=243|
20120116-08:45:40.022 : 8=FIX.4.4|9=116|35=5|34=295|49=SID|52=20120116-08:45:25.641|56=TID|58=MsgSeqNum too low, expecting 300 but received 1|10=088|
20120116-08:45:44.575 : 8=FIX.4.4|9=72|35=2|34=2|49=TID|52=20120116-08:45:25.305|56=SID|7=1|16=0|10=056|
20120116-08:46:26.086 : 8=FIX.4.4|9=77|35=A|34=296|49=SID|52=20120116-08:46:26.061|56=TID|98=0|108=60|10=093|
20120116-08:46:29.465 : 8=FIX.4.4|9=75|35=A|34=4|49=TID|52=20120116-08:46:26.118|56=SID|98=0|108=60|10=241|
20120116-08:46:29.475 : 8=FIX.4.4|9=116|35=5|34=297|49=SID|52=20120116-08:46:29.465|56=TID|58=MsgSeqNum too low, expecting 300 but received 4|10=102|
20120116-08:46:32.563 : 8=FIX.4.4|9=72|35=2|34=5|49=TID|52=20120116-08:46:26.124|56=SID|7=2|16=0|10=061|

Cheers,
Campbell

from quickfixn.

Not fixed, reopen.

from quickfixn.

More context for this issue:

What's supposed to happen
QF/n application config files have two settings StartTime and EndTime that define the start and end of a session. A QF/n application will use the same seq# (field 34) progression through all connections within that sesssion. If it disconnects with seq#=6, then it'll reconnect with seq#=7. Optionally, StartDay/EndDay can also be used, which cause the session to be a weekly instead of daily.

(NOTE: There are some config setting that alter this behavior, specifically ResetOnLogon, ResetOnLogout, and ResetOnDisconnect. This issue is for situations where all three of these settings are disabled (i.e. set to N).)

During the time period outside of the start and end of a session, QF/n apps are dormant. Initiators won't try to connect, and Acceptors will refuse any connections.

Current bad behavior
Right now, when the session restarts, apps are not resetting the seq# back to 1. If they disconnect at EndTime with seq#=25, they'll try to reconnect at the next StartTime with seq#=26. That's the bug.

To reproduce
It's easy to reproduce with a pair of initiator/acceptor apps. Set the StartTime/EndTime to be the same for both apps (make sure the current time falls between them). Connect them to each other, and let them heartbeat a few times. If you kill the initiator and restart it, it should resume the seq# where it left off.

Now stop both apps and change EndTime to be soon, maybe 2 or 3 minutes away. Restart both apps. Wait for EndTime and watch them both disconnect.

Kill the apps again. Change StartTime to be soon (a few minutes away), and EndTime to be after that. Restart both apps. When StartTime occurs, the Initiator will start trying to connect to the Acceptor. The initiator should have seq# (field 34) set to 1. With this bug in effect, it will be not 1.

Testing
We like to have automated tests around behavior. Ideally, we'd like to have an automated test that will fail when this bug is in effect, and pass when the bug is fixed. An acceptance test for this might be kind of tricky, and I'm not sure the best way to do it (if someone comes up with something elegant for this purpose, we'd be very impressed). If nothing else, there should be some Unit Tests around functions that are changed as part of this fix.

from quickfixn.

I am not able to reproduce this bug.

Explicit steps in my attempt to reproduce.

1. Build all examples programs. We're going to use TradeClient and Executor.
2. Open two command prompt windows.
3. In one prompt window:

• cd Examples\Executor\bin\Debug
• rmdir /S store (DO THIS BEFORE EVERY ATTEMPT)
• edit executor.cfg:
  • set EndTime=(now+10 minutes) and StartTime=(now+12 minutes)
  • VERY IMPORTANT: remove "ResetOnLogon=Y"
• Executor.exe executor.cfg

4. In the other window:

• cd Examples\TradeClient\bin\Debug
• rmdir /S store (DO THIS BEFORE EVERY ATTEMPT)
• edit tradeclient.cfg:
  • set EndTime/StartTime same as Executor above
  • VERY IMPORTANT: remove "ResetOnLogon=Y", "ResetOnLogout=Y", "ResetOnDisconnect=Y"
• run "TradeClient.exe tradeclient.cfg"

Let them run.

Observe: They should be sending heartbeats (35=0) to each other every 30 seconds. TradeClient will print the messages to the terminal.

Observe: When EndTime is reached, TradeClient will log out.

Observe: When StartTime is reached, TradeClient will attempt to log back in again. If there was a bug, it would try to login with (previous seq num+1). I am seeing it try to log in with seq=1.

Conclusion: Not a bug.

from quickfixn.

Jcwild, can you please comment? If your scenario is somehow different from what I tried, please let me know.

Unless we get further information, we will close this as not-a-bug.

from quickfixn.

Jcwild, we suspect that perhaps the StartTime/EndTime of your Acceptor is not the same as that of the initiator.

Specifically, we think that the Initiator rolled over its session, but the Acceptor did not. Thus, the Initiator was starting a new session with 1, and the Acceptor was still thinking it was the old session and expecting higher-than-1. This would produce results similar your log.

from quickfixn.

I always connect as an Initiator. Therefore when I reconnect at the Start time, I am connecting with 1 and would be expecting the other side to connect with 1 also. But for whatever reason, although the other side did respond with 1, whatever keeps track of the expected incoming number had not been reset to 1 and so QuickFIX/n rejected it, incorrectly.

from quickfixn.

Hey jcwild,

I'm a little confused looking at your logs. You say your side is sending 1, but I don't see that in the logs. The only sequence number of one looks to be coming from your counter party (sender TID). Can you post the config file you used in the earlier mentioned sequence?

from quickfixn.

Email from Matt Wood on May 23, 2012:
"I believe I'm also encountering this. Basically if I'm manually disconnecting a session before EndTime, then manually starting it up again after StartTime on the following day, my session doesn't get reset. QuickfixN throws the "MsgSeqNum too low, expecting... " message."

Not sure if we've tried manually disconnecting/reconnecting. Maybe that's the detail we were lacking when we tried to reproduce?

Need to try it.

from quickfixn.

While I do believe that my previous suggestion may be relevant for this bug, I think my problem is caused by a different issue (which may require an enhancement):

I just looked through the code and realized that when a StartDay and EndDay are configured (in addition to a StartTime/EndTime), I'm setting up for a "weekly session". My intent was to use the day in addition to time to create a daily session that didn't also run on the weekends (thus needing the day information).

from quickfixn.

That is a common mistake. Too common, really. We should probably improve the documentation to make it absolutely clear.

from quickfixn.

I recall reading it now that you mention it. If I end up needing this I'll do it and submit a pull request.

from quickfixn.

If you did this, I think we'd want a new config setting for it, so as to not have different behavior than other QFs for the existing settings. And feel free to open a new issue for it for further discussion.

I think it's definitely a feature that people would use. On Unix, cron jobs are an easy workaround, but Windows is so much more annoying.

from quickfixn.

I have the same kind of issue.

I'm developing an acceptor app, config is this:

[DEFAULT]
SenderCompID=XXX
ConnectionType=acceptor
SocketAcceptPort=6010
SocketReuseAddress=Y
UseDataDictionary=Y
DataDictionary=QuickFixN\FIX42.xml

[SESSION]
BeginString=FIX.4.2
TargetCompID=YYY
StartTime=01:00:00
EndTime=23:00:00
FileStorePath=QuickFixN\store
FileLogPath=QuickFixN\log

Yesterday I started the acceptor app and tested to it from a third party fix msg sender app.
Today I started acceptor again, it should reset the seq nums right after startup, but did not happened.
Is this a bug, or did I misconfigured my acceptor?

20120619-16:17:12.750 : 8=FIX.4.2�9=82�35=A�49=YYY�56=XXX�34=3�52=20120619-16:17:12�98=0�108=120�95=9�96=null/null�10=065�
20120619-16:17:12.780 : 8=FIX.4.2�9=68�35=A�34=1�49=XXX�52=20120619-16:17:12.773�56=YYY�98=0�108=120�10=219�
20120619-16:17:12.783 : 8=FIX.4.2�9=64�35=2�34=2�49=XXX�52=20120619-16:17:12.783�56=YYY�7=1�16=0�10=252�
20120619-16:17:12.786 : 8=FIX.4.2�9=69�35=1�49=YYY�56=XXX�34=4�52=20120619-16:17:12�112=synchronized?�10=232�
20120619-16:17:12.787 : 8=FIX.4.2�9=89�35=4�49=YYY�56=XXX�34=1�52=20120619-16:17:12�43=Y�122=20120619-16:17:12�123=Y�36=5�10=251�
20120619-16:17:12.788 : 8=FIX.4.2�9=69�35=1�49=YYY�56=XXX�34=5�52=20120619-16:17:12�112=synchronized?�10=233�
20120619-16:17:12.789 : 8=FIX.4.2�9=73�35=0�34=3�49=XXX�52=20120619-16:17:12.789�56=YYY�112=synchronized?�10=183�
20120619-16:17:48.375 : 8=FIX.4.2�9=143�35=D�49=YYY�56=XXX�34=6�52=20120619-16:17:48�11=1�21=1�55=BMW�54=1�40=2�100=XETR�38=1�44=1�59=1�60=20120619-16:06:00.000�48=DE0005190003�10=101�
20120619-16:19:12.852 : 8=FIX.4.2�9=55�35=0�34=4�49=XXX�52=20120619-16:19:12.852�56=YYY�10=128�
20120619-16:19:48.376 : 8=FIX.4.2�9=51�35=0�49=YYY�56=XXX�34=7�52=20120619-16:19:48�10=187�
20120619-16:21:13.025 : 8=FIX.4.2�9=55�35=0�34=5�49=XXX�52=20120619-16:21:13.025�56=YYY�10=115�
20120619-16:21:48.383 : 8=FIX.4.2�9=51�35=0�49=YYY�56=XXX�34=8�52=20120619-16:21:48�10=181�
20120619-16:23:08.888 : 8=FIX.4.2�9=59�35=5�49=YYY�56=XXX�34=9�52=20120619-16:23:08�58=Quit�10=015�
20120619-16:23:08.903 : 8=FIX.4.2�9=55�35=5�34=6�49=XXX�52=20120619-16:23:08.903�56=YYY�10=132�
20120619-16:39:25.456 : 8=FIX.4.2�9=83�35=A�49=YYY�56=XXX�34=10�52=20120619-16:39:25�98=0�108=120�95=9�96=null/null�10=120�
20120619-16:39:25.486 : 8=FIX.4.2�9=68�35=A�34=7�49=XXX�52=20120619-16:39:25.480�56=YYY�98=0�108=120�10=228�
20120619-16:39:25.492 : 8=FIX.4.2�9=70�35=1�49=YYY�56=XXX�34=11�52=20120619-16:39:25�112=synchronized?�10=022�
20120619-16:39:25.493 : 8=FIX.4.2�9=73�35=0�34=8�49=XXX�52=20120619-16:39:25.493�56=YYY�112=synchronized?�10=188�
20120619-16:41:25.494 : 8=FIX.4.2�9=52�35=0�49=YYY�56=XXX�34=12�52=20120619-16:41:25�10=222�
20120619-16:41:25.497 : 8=FIX.4.2�9=55�35=0�34=9�49=XXX�52=20120619-16:41:25.496�56=YYY�10=136�
20120619-16:42:57.181 : 8=FIX.4.2�9=60�35=5�49=YYY�56=XXX�34=13�52=20120619-16:42:57�58=Quit�10=055�
20120619-16:42:57.187 : 8=FIX.4.2�9=56�35=5�34=10�49=XXX�52=20120619-16:42:57.187�56=YYY�10=185�
20120620-12:22:22.735 : 8=FIX.4.2�9=82�35=A�49=YYY�56=XXX�34=1�52=20120620-12:22:22�98=0�108=120�95=9�96=null/null�10=048�
20120620-12:22:22.819 : 8=FIX.4.2�9=106�35=5�34=11�49=XXX�52=20120620-12:22:22.798�56=YYY�58=MsgSeqNum too low, expecting 14 but received 1�10=162�
20120620-12:22:54.523 : 8=FIX.4.2�9=82�35=A�49=YYY�56=XXX�34=2�52=20120620-12:22:54�98=0�108=120�95=9�96=null/null�10=054�
20120620-12:22:54.523 : 8=FIX.4.2�9=106�35=5�34=12�49=XXX�52=20120620-12:22:54.523�56=YYY�58=MsgSeqNum too low, expecting 14 but received 2�10=155�
20120620-12:22:59.381 : 8=FIX.4.2�9=82�35=A�49=YYY�56=XXX�34=3�52=20120620-12:22:59�98=0�108=120�95=9�96=null/null�10=060�
20120620-12:22:59.382 : 8=FIX.4.2�9=106�35=5�34=13�49=XXX�52=20120620-12:22:59.382�56=YYY�58=MsgSeqNum too low, expecting 14 but received 3�10=165�

from quickfixn.

There seems to be a fundamental problem here: the library does not persist the session creation time. The C++ version does. Consider this...

The IsSessionTime function is called with the current UTC time. That checks the Time and the Day as follows:

    public bool IsSessionTime(System.DateTime time)
    {
        return CheckTime(time.TimeOfDay) && CheckDay(time);
    }

    private bool CheckDay(System.DateTime time)
    {
        if (!WeeklySession)
            return true;

        if (StartTime.CompareTo(EndTime) > 0)
        {
            //if session goes over midnight and it's the start session day,
            //make sure start day occurs in session
            if (time.DayOfWeek == StartDay)
            {
                return time.TimeOfDay.CompareTo(StartTime) >= 0;
            }

            //likewise, if day is the end part of a session, verify
            //time occurs in session
            System.DateTime yesterday = time.AddDays(-1);
            if (yesterday.DayOfWeek == EndDay)
            {
                return time.TimeOfDay.CompareTo(EndTime) <= 0;
            }
        }

        if(StartDay <= EndDay)
            return time.DayOfWeek.CompareTo(StartDay) >= 0 && 
                time.DayOfWeek.CompareTo(EndDay) <= 0; 
        else
            return time.DayOfWeek.CompareTo(EndDay) <=0 ||
                time.DayOfWeek.CompareTo(StartDay) >=0;
    }

    private bool CheckTime(System.TimeSpan time)
    {
        if (StartTime.CompareTo(EndTime) < 0)
        {
            return (time.CompareTo(StartTime) >= 0 &&
                time.CompareTo(EndTime) <= 0);
        }
        else if (StartTime.CompareTo(EndTime) > 0)
        {
            return (time.CompareTo(StartTime) >= 0 ||
                time.CompareTo(EndTime) <= 0);
        }

        return true;
    }

Consider a transient client (a trading app for example) and a persistent server (a trading gateway for example). The client disconnects before the end of the session - entirely valid if the trader logs off. The next day, they log back in after the session start time. The code above does not take into account the fact that the day has changed. The client has been correctly configured as having a daily session (ie: no StartDay and EndDay), however the code above will only check the time and return TRUE for the day as it's not a weekly session. As a result, the sequence numbers are not reset as they should be for the new Daily session. That's not good.

If you use the C++ version on the server side, that will reset correctly. If you then use this .NET version on the client side, the session does not get reset and will possibly replay everything on reconnect the next day.

The C++ version gets around this by storing a .session file alongside the .seqnums, .header and .body files. It then uses that time when determining whether a Daily session has rolled over between restarts:

        bool checkSessionTime( const UtcTimeStamp& timeStamp )
        {
                    UtcTimeStamp creationTime = m_state.getCreationTime();
                    return m_sessionTime.isInSameRange( timeStamp, creationTime );
        }

from quickfixn.

I'm having this issue too, if the application is shut down when it should reset the seq-numbers. Is there any solution in sight or do I have to handle it myself by manullay resetting the numbers? I think this issue should at least be highlighted in the documentation since it is a different behavior than in the c++ library which is very confusing.

from quickfixn.

The issue is still open, and we certainly intend to fix it. We do not intend for this implementation to differ from C++.

Unfortunately, when this free open-source work competes with billed work, the billed work wins, and we have a lot of it right now. We are always willing to accept patches, though, so if you have some time to kill, feel free to fork and work on a solution.

from quickfixn.

I've investigated this issue.
I've found in the Session constructor, line 229:

            if (!IsSessionTime)
                Reset();

If FIX engine is stopped in a session, and started in a new session, this condition will not fire the Reset.
I suggest to implement new "IsNewSession" property, and use it to solve this problem:

            if (!IsSessionTime || IsNewSession)
                Reset();

"IsNewSession" will be true, if the creation time of current session will be after the end of last session:

        public bool IsNewSession
        {
            get
            {
                var creationTime = this.state_.GetCreationTime();
                var lastEndTime = this.schedule_.LastEndTime(DateTime.UtcNow).ToUniversalTime();

                return !creationTime.HasValue || creationTime.Value.ToUniversalTime() <= lastEndTime;
            }
        }

For this solution, I've implemented GetCreationTime in all of MessageStores, and LastEndTime calculation in SessionSchedule.

Please see the complete solution in this branch: https://github.com/ligu/quickfixn/tree/issue22

from quickfixn.

Finally was able to reproduce. To reproduce, you need to manually kill the initiator before the next day's session, and manually start it after StartTime.

The misunderstanding was because we thought it was supposed to occur during automatic start/stop as the session ended/began.

Fix is coming soon. Thanks to @ligu for his work.

from quickfixn.

I'm also finding that the sequence numbers are being reset whenever the application is restarted. Unless it's a new day with distinct start and end times in the QuickFIX config, the sequence numbers should resume from where they left off. Has this been addressed also? This is a critical problem as it would mean manually having to correct the sequence numbers every time the service was restarted, which could occur multiple times in a trading day. I'm using v1.3.0.

20121102-10:04:35.217 : 8=FIX.4.4 | 9=64 | 35=0 | 34=42 | 49=TARGET | 52=20121102-10:04:35.190 | 56=SENDER | 10=227 |
20121102-10:05:35.256 : 8=FIX.4.4 | 9=64 | 35=0 | 34=43 | 49=TARGET | 52=20121102-10:05:35.249 | 56=SENDER | 10=234 |
20121102-10:05:35.260 : 8=FIX.4.4 | 9=64 | 35=0 | 34=31 | 49=SENDER | 52=20121102-10:05:35.258 | 56=TARGET | 10=231 |
(restarted app here)
20121102-10:57:58.046 : 8=FIX.4.4 | 9=75 | 35=A | 34=1 | 49=SENDER | 52=20121102-10:57:58.045 | 56=TARGET | 98=0 | 108=60 | 10=233 |
20121102-10:57:58.074 : 8=FIX.4.4 | 9=114 | 35=5 | 34=44 | 49=TARGET | 52=20121102-10:57:58.047 | 56=SENDER | 58=MsgSeqNum too low, expecting 32 but received 1 | 10=238 |
20121102-10:57:58.096 : 8=FIX.4.4 | 9=63 | 35=5 | 34=2 | 49=SENDER | 52=20121102-10:57:58.095 | 56=TARGET | 10=196 |
20121102-10:58:58.094 : 8=FIX.4.4 | 9=75 | 35=A | 34=3 | 49=SENDER | 52=20121102-10:58:58.093 | 56=TARGET | 98=0 | 108=60 | 10=239 |
20121102-10:58:58.111 : 8=FIX.4.4 | 9=114 | 35=5 | 34=45 | 49=TARGET | 52=20121102-10:58:58.094 | 56=SENDER | 58=MsgSeqNum too low, expecting 32 but received 3 | 10=244 |
20121102-10:58:58.111 : 8=FIX.4.4 | 9=63 | 35=5 | 34=4 | 49=SENDER | 52=20121102-10:58:58.111 | 56=TARGET | 10=188 |
20121102-10:59:58.144 : 8=FIX.4.4 | 9=75 | 35=A | 34=5 | 49=SENDER | 52=20121102-10:59:58.144 | 56=TARGET | 98=0 | 108=60 | 10=239 |
20121102-10:59:58.181 : 8=FIX.4.4 | 9=114 | 35=5 | 34=46 | 49=TARGET | 52=20121102-10:59:58.145 | 56=SENDER | 58=MsgSeqNum too low, expecting 32 but received 5 | 10=245 |
20121102-10:59:58.181 : 8=FIX.4.4 | 9=63 | 35=5 | 34=6 | 49=SENDER | 52=20121102-10:59:58.181 | 56=TARGET | 10=198 |
(restarted app here)
20121102-11:00:11.883 : 8=FIX.4.4 | 9=75 | 35=A | 34=1 | 49=SENDER | 52=20121102-11:00:11.882 | 56=TARGET | 98=0 | 108=60 | 10=220 |
20121102-11:00:11.905 : 8=FIX.4.4 | 9=114 | 35=5 | 34=47 | 49=TARGET | 52=20121102-11:00:11.884 | 56=SENDER | 58=MsgSeqNum too low, expecting 32 but received 1 | 10=228 |
20121102-11:00:11.924 : 8=FIX.4.4 | 9=63 | 35=5 | 34=2 | 49=SENDER | 52=20121102-11:00:11.924 | 56=TARGET | 10=175 |

from quickfixn.