[QFJ-926] Session reset happens after logon Created: 23/May/17  Updated: 23/Dec/19  Resolved: 03/Jul/17

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

Type: Bug Priority: Major
Reporter: Nickolay Dul Assignee: Christoph John
Resolution: Fixed Votes: 0
Labels: None

Issue Links:
Duplicate
is duplicated by QFJ-988 Session reset happens after logon Closed

 Description   

scenario:

application is handling several FIX sessions (initiators)
app started in the off time – FIX sessions are successfully created and reset

{{11 May 23:40:10.450 INFO (Thread-3) Session FIX.4.4:SENDER_ONE->TARGET schedule is THU 04:05:00-UTC - THU 20:30:00-UTC
11 May 23:40:10.452 INFO (Thread-3) Session state is not current; resetting FIX.4.4:SENDER_ONE->TARGET
11 May 23:40:10.459 INFO (Thread-3) Created session: FIX.4.4:SENDER_ONE->TARGET

11 May 23:40:10.501 INFO (Thread-3) Session FIX.4.4:SENDER_TWO->TARGET schedule is THU 04:07:00-UTC - THU 20:30:00-UTC
11 May 23:40:10.502 INFO (Thread-3) Session state is not current; resetting FIX.4.4:SENDER_TWO->TARGET
11 May 23:40:10.509 INFO (Thread-3) Created session: FIX.4.4:SENDER_TWO->TARGET
}}

on the next day logons are initiated according to session’s schedules

but the first session reset is happened in the middle of message handling:
(which is result in re-logon and “MsgSeqNum too low” issue)

  1. SENDER_ONE
    12 May 06:05:00.932 INFO (QFJ Timer) Initiated logon request
    12 May 06:05:01.145 INFO (QFJ Message Processor) Received logon
    12 May 06:05:01.149 INFO (QFJ Message Processor) Sent ResendRequest FROM: 1 TO: 2385
    12 May 06:05:01.150 INFO (QFJ Message Processor) Logon has been established: FIX.4.4:SENDER_ONE->TARGET
    12 May 06:05:01.156 INFO (QFJ Message Processor) Session state is not current; resetting FIX.4.4:SENDER_ONE->TARGET
    12 May 06:05:01.168 INFO (QFJ Message Processor) Session has been logged out: FIX.4.4:SENDER_ONE->TARGET
    12 May 06:05:16.928 INFO (QFJ Timer) Initiated logon request
    12 May 06:05:17.160 INFO (QFJ Message Processor) Received logout request: MsgSeqNum too low, expecting 4 but received 1

on other hand second session starts normally (reset happens before logon):

  1. SENDER_TWO
    12 May 06:07:00.929 INFO (QFJ Timer) Session state is not current; resetting FIX.4.4:SENDER_TWO->TARGET
    12 May 06:07:00.930 INFO (QFJ Timer) Initiated logon request
    12 May 06:07:01.103 INFO (QFJ Message Processor) Received logon
    12 May 06:07:01.103 INFO (QFJ Message Processor) Sent ResendRequest FROM: 1 TO: 2612
    12 May 06:07:01.103 INFO (QFJ Message Processor) Logon has been established: FIX.4.4:SENDER_TWO->TARGET

I guess the problem is how session reset is handled in Session::next() method:
look like sometimes the previous session time check is happenning less then 1 sec ago – it is skipped – and as a result session reset is accured already after logon

 Comments   
Comment by Nickolay Dul [ 23/May/17 ]

I guess the problem is how session reset is handled in Session::next() method:
look like sometimes the previous session time check is happenning less then 1 sec ago – it is skipped – and as a result session reset is accured already after logon

if (sessionSchedule != null && !sessionSchedule.isNonStopSession()) {
    // Only check the session time once per second at most. It isn't
    // necessary to do for every message received.
    final long now = SystemTime.currentTimeMillis();
    if ((now - lastSessionTimeCheck) >= 1000L) {
        lastSessionTimeCheck = now;
        if (!isSessionTime()) {
            if (state.isResetNeeded()) {
                reset(); // only reset if seq nums are != 1
            }
            return; // since we are outside of session time window
        } else {
            resetIfSessionNotCurrent(sessionID, now);
        }
    }
}
Comment by Nickolay Dul [ 23/May/17 ]

extra question:
according to log Session::next() can be called from different threads
so why lastSessionTimeCheck field is not volatile?

12 May 06:05:00.932 INFO (QFJ Timer) Initiated logon request
12 May 06:05:01.156 INFO (QFJ Message Processor) Session state is not current; resetting FIX.4.4:SENDER_ONE->TARGET
Comment by Nickolay Dul [ 23/May/17 ]

still have no reliable fix for this (just because not very familiar with QuickFIX/J code)

perhaps we should add additional check - like: 

if ((now - lastSessionTimeCheck) >= 1000L || (!state.isLogonReceived() && state.isLogonSendNeeded())) {
Comment by Christoph John [ 03/Jul/17 ]

Hi Nickolay Dul,
I looked at this. Your proposed fix seems to correct the problem but only for Initiators. Will take a further look.
Cheers,
Chris.

Comment by Christoph John [ 03/Jul/17 ]

Is now corrected for initiators and acceptors.

Generated at Tue Apr 30 12:53:56 UTC 2024 using JIRA 7.5.2#75007-sha1:9f5725bb824792b3230a5d8716f0c13e296a3cae.