Session unable to re-establish logon after disconnect with large message backlog in MessageDispatchingThread queue

[aolesek]

Describe the bug
After a counterparty sends a large burst of messages containing one with a SendingTime accuracy problem, the initiator enters a persistent reconnect loop and never re-establishes a logon. The session stays offline.

To Reproduce

1. Initiator is logged on; counterparty sends a large burst with one message having SendingTime 300+ seconds in the past.
2. Initiator detects the bad SendingTime, sends Reject + Logout.
3. Counterparty acknowledges and closes TCP.
4. IoSessionInitiator opens a new TCP connection, calls setResponder().
5. No Logon is sent on the new connection, cycle repeats multiple times.

I've also attached Reproducer.java that is able to reproduce described behavior.

Expected behavior
After a disconnect, the session should be able to re-establish a logon on the next TCP connection without interference from messages buffered during the previous connection.

System information:

• OS: Linux
• Java version JDK21
• QuickFIX/J version: 3.0.1

Additional context

Root cause (as far as I can tell):

Session.disconnect() clears state.getMessageQueue() but not MessageDispatchingThread.messages. Messages from the dead connection remain in that queue and are processed against the next connection. Additionally, IoSessionInitiator may reconnect while logonReceived is still true, wiring a new TCP to a session that won't send Logon.

If either of the above behaviors is intentional design, I'm happy to be corrected - I may be missing a configuration option that handles this case, or simply misunderstanding how the engine is expected to behave in this scenario.

Behavior observed during analysis of logs generated by Reproducer.java:

Observation A - stale message from previous connection kills new TCP responder:

Immediately after Logout 3 from Observation B - queue still has 247 messages, logonReceived=false, hasResponder=false

[QUEUE AT LOGOUT #3] Mina dispatcher:  247 | QFJ out-of-order:    0

// Dispatcher thread processing stale messages from dead connection, hasResponder = false so disconnect() only logs "already disconnected"
<12:26:13, FIX.4.4:CLIENT->EXCHANGE, error> (quickfix.SessionException Logon state is not valid for message (MsgType=8))
<12:26:13, FIX.4.4:CLIENT->EXCHANGE, event> (Already disconnected: Verifying message failed: quickfix.SessionException: Logon state is not valid for message (MsgType=8))
// Those messages above repeat multiple times (~150 times each)

// IoSessionInitiator reconnects again, setResponder(:52416) called, logonReceived=false, hasResponder=true
// session timer will send Logon in a moment
14:26:13.407 [NioProcessor-10] INFO quickfix.mina.acceptor.AcceptorIoHandler -- MINA session created: local=/127.0.0.1:9876, class org.apache.mina.transport.socket.nio.NioSocketSession, remote=/127.0.0.1:52416

// THIS stale ExecutionReport from dead connection hits AFTER setResponder(:52416) (hasResponder=true, logonReceived=false)
// Session.disconnect() called with active responder, responder killed before Logon was sent
<12:26:13, FIX.4.4:CLIENT->EXCHANGE, error> (quickfix.SessionException Logon state is not valid for message (MsgType=8))
<12:26:13, FIX.4.4:CLIENT->EXCHANGE, error> (Disconnecting: Verifying message failed: quickfix.SessionException: Logon state is not valid for message (MsgType=8))

<12:26:13, FIX.4.4:CLIENT->EXCHANGE, event> (MINA session created: local=/127.0.0.1:52416, class org.apache.mina.transport.socket.nio.NioSocketSession, remote=localhost/127.0.0.1:9876)

Observation B - new TCP wired while logonReceived = true:

Session logged on, counterparty sends 50 000 messages, message 5 has bad SendingTime

<12:26:10, FIX.4.4:CLIENT->EXCHANGE, error> (Reject sent for message 7: SendingTime accuracy problem:52)
<12:26:10, FIX.4.4:EXCHANGE->CLIENT, event> (Received logout request: SendingTime accuracy problem, field=52)
<12:26:10, FIX.4.4:EXCHANGE->CLIENT, event> (Sent logout response)

// exchange closes TCP from its side, ioSession.isConnected() = false
<12:26:10, FIX.4.4:EXCHANGE->CLIENT, event> (Disconnecting: Received logout request: SendingTime accuracy problem, field=52) 
<12:26:10, FIX.4.4:EXCHANGE->CLIENT, event> (No responder, not sending message...

[QUEUE] Mina dispatcher:  813 | QFJ out-of-order: 0
[EXCHANGE] All 50000 messages sent.

[t= 6s] logouts: 2 | isLoggedOn: true | Mina: 640 | QFJ: 0

// IoSessionInitiator reconnects, setResponder(:52406) called
// BUT: logonReceived=true from previous connection, session timer will NOT send Logon
<12:26:11, FIX.4.4:CLIENT->EXCHANGE, event> (MINA session created: local=/127.0.0.1:52406, class org.apache.mina.transport.socket.nio.NioSocketSession, remote=localhost/127.0.0.1:9876)

[QUEUE] Mina dispatcher:  466 | QFJ out-of-order:    0
[t= 7s] logouts: 2 | isLoggedOn: true | Mina: 447 | QFJ: 0
[QUEUE] Mina dispatcher:  290 | QFJ out-of-order:    0
[t= 8s] logouts: 2 | isLoggedOn: true | Mina: 251 | QFJ: 0

// Responder :52406 was alive for 2 seconds - no Logon was ever sent on it (still waiting for logout response)
<12:26:13, FIX.4.4:CLIENT->EXCHANGE, error> (Disconnecting: Timed out waiting for logout response)

// 247 messages remain in queue, NOT cleared by disconnect()
[QUEUE AT LOGOUT #3] Mina dispatcher:  247 | QFJ out-of-order:    0

Reproducer.java

[chrjohn]

@aolesek thank you for the detailed description and reproducer. I'll take a look in due course.

[Ra9huvansh]

I'd like to take a look at this. Will run the reproducer first.. then trace the disconnect / dispatcher path and report back.

[chrjohn]

Thank you @Ra9huvansh , much appreciated.

[Ra9huvansh]

I slipped out but picking this back up.

Reproduced the issue and confirmed the root cause of what I'll call Problem A(the stale dispatcher queue) on current master(73e45db).

Session.disconnect() clears the FIX out-of-order queue (state.getMessageQueue().clear()), but the per-session dispatcher queue (ThreadPerSessionEventHandlingStrategy.MessageDispatchingThread.messages) is never cleared on disconnect.

That dispatcher is keyed by SessionID and reused across reconnects, so with a large backlog its doRun() loop keeps calling Session.next(...) on stale messages from the dead connection. Each stale application message fails validLogonState() (a non-Logon message requires isLogonReceived() == true, which disconnect() has just set to false), which throws in verify() and triggers another disconnect().

Because the backlog drain races the reconnect (ReconnectInterval), a stale message processed after setResponder() but before Logon kills the fresh connection's responder matching @aolesek Observation A.

I am now investigating Problem B but i think once this is resolved, Observation B would then be better scoped.