Sending OrderSingle Message Failed and looking for help

[x-leviathan]

Version & Config: quickfixj 2.3.1 with config HeartBtInt=30; EnabledProtocols=TLSv1.2; ProxyType=HTTP; SocketUseSSL=Y

Background: One of our sessions (Session A) failed to send an OrderSingle message to the target, while at the same time, Session B was able to successfully send an OrderSingle message to the target. We conducted some analysis and suspected that there might be a deadlock inside Session.sendToTarget(Message, SessionID) or SSL errors, but we have been unable to identify the cause. Below are some specific details. Could the community assist us on the issue?

1. Session A successfully sent an OrderSingle message to the target at 10:21:02 in the morning. However, at 14:54:18, an OrderSingle message encountered a failure, and subsequently, all 11 OrderSingle attempts by Session A failed, with the last failure occurring at 16:18:47. After we restarted the FIX service at 16:35, Session A successfully sent an OrderSingle at 16:40:22.
2. Between 14:54 and 16:35, Session B sent 3 OrderSingle messages, all of which were successful. After the service restart at 16:35, all subsequent messages were also successful.
3. Our service has been running for a long time, and this issue had only occurred once before in the test environment, where it was resolved by a restart but was not given much attention.
4. The Application corresponding to our Session A has only one line of code in the toApp method, which is used to log the Message information. For successful OrderSingle requests in Session A, we can see this log, but for the failed OrderSingle attempts, no such log appears. I found that in the quickfix.Session#sendRaw method, at Line 2630, the application.toApp(message, sessionID) is called. It is apparent that the program did not reach this line, so I suspect there might be a deadlock occurring in the sendRaw method？
5. Additionally, both Session A and Session B act as initiators. The logs show that at 13:21:10, Session A had a toAdmin message (35=0, 34=705, 49=ME, 56=CPTY), and immediately received a fromAdmin message (35=0, 34=706, 49=CPTY, 56=ME). However, at 13:21:40, there was only a toAdmin message (35=0, 34=706, 49=ME, 56=CPTY), with no corresponding fromAdmin message. In contrast, for Session B, the heartbeat messages consistently show fromAdmin and toAdmin logs every 30 seconds, both before and after the restart.
6. Further observation of the heartbeat logs for Session A reveals that after the toAdmin message at 13:21:10, the logs show multiple entries such as SslFilter: 628 ..., SslFilter: 496 ..., SslHandler: 345 ..., SslFilter: 792 ..., ProtocolCodecFilter: 233 ..., FIXMessageDecoder: 142 ..., etc. However, after the toAdmin message at 13:21:40, only one entry, SslFilter: 628 ... was logged. It seems like SSL errors?

[chrjohn]

Without event logs from the time of the occurrence it is very hard to help you I'm afraid. From the information you provided it sounds a little like one connection went down. Or are session A and B sending to the same host?
Do you have more information on the logs from your point 6?

I don't know how your application is composed. Where are the messages before you hand them over to QFJ?

One advice I always give in such scenarios: before restarting the service, take a thread dump. That way one could tell if there really is a deadlock.

[x-leviathan]

Unfortunately, I can't share our logs due to the customer's privacy. I can only describe the issue in writing and I have made some progress in analyzing.

Although we missed the opportunity to capture a thread dump, based on log analysis with the counterparty, I suspect the issue is likely caused by a deadlock and is very similar(even same) to issue #398

1. We are using jdk8, quickfixj 2.3.1 and its dependency mina-core 2.1.4 with SSL + PROXY settings enabled.
2. We found that the mina filter linked list structure is as follows: ProxyFilter <—> SslFilter <—> ProtocolCodecFilter. When sending messages, the filters are executed from the tail to the head, and when receiving messages, the filters are executed from the head to the tail.
3. We were sending a Session A heartbeat at 13:21:40. Our counterparty told us they were sending a Session A heartbeat to us at the same time(13:21:40).

Therefore, we think that the situation might be as follows:
At 13:21:40
Thread1 (sending heartbeat):

1. holding lock senderMsgSeqNumLock: quickfix.Session#sendRaw Line2580 state.lockSenderMsgSeqNum()
2. holding lock SslHandler: org.apache.mina.filter.ssl.SslFilter#filterWrite Line635 sychronized(sslHandler)
3. try to lock ProxyLogicHandler but blocked: org.apache.mina.proxy.filter.ProxyFilter#writeData Line 214 sychronized(handler)

Thread2 (receiving heartbeat):

1. holding lock ProxyLogicHandler: org.apache.mina.proxy.filter.ProxyFilter#messageReceived Line 148 synchronized (handler)
2. try to lock SslHandler but blocked: org.apache.mina.filter.ssl.SslFilter#messageReceived Line 501 synchronized (sslHandler)

At 14:54:18
Thread3 (sending newOrderSingle)

1. try to lock senderMsgSeqNumLock but blocked: quickfix.Session#sendRaw Line2580 state.lockSenderMsgSeqNum()

Given the situation mentioned above, I would like to ask whether excluding mina 2.1.4 from the dependencies and include mina 2.2.2 by myself would be an appropriate solution for our case?

[x-leviathan]

BTW, Session A and B are sending to the same host. Our fix initiator received orders from restful API call by other services.

[chrjohn]

You cannot simply include MINA 2.2.2 since it is not compatible with the QFJ code, see #635

What happened when the order could not be sent and the deadlock occurred? Actually I would expect that the connection got dropped because you did not send heartbeats to your counterparty anymore and also did not reply to their test requests, but you did not mention this. I could imagine that a connection drop could have resolved the deadlock.
But as said, without any thread dump it is hard to tell. But yes, it could be that MINA issue.

[x-leviathan]

Thanks for your reply :)
Yes, I tried to include MINA 2.2.2 but found it's not compatible. Now I include MINA 2.0.20 and do some tests.
After that case happened, we can't send or receive any fix messages through session A. To resolve it, we must restart the whole service and this will affect our deals sometimes.
We have a spring schedule to execute every 2 minutes:

1. use Session.lookupSession(sessionId).isLoggedOn() to query connection status and log
2. if connection status is false, try to restart the initiator and session. The restart code is like:

if (initiatorStart) {
    initiatorStart = false;
    for (SessionID sessionId : initiator.getSessions()) {
        boolean status = Session.lookupSession(sessionId).isLoggedOn();
        log ...
        if (status) {
            Session.lookupSession(sessionId).logout("user request");
            log ...
        }
}
initiator.stop();
try {
    initiator.start();
    initiatorStart = true;
} catch (Exception e) {
    log ...
}

Back to your question: After possible deadlock heartbeat, we can't find any sending or receiving in session A(no fix message like 35=... 34=... 49=... 50=... in our log). But the above spring schedule showed Session.lookupSession(sessionId).isLoggedOn() always return true for session A after possible deadlock timepoint. Is this right? It looks like this connection do not get dropped.

Based on your suggestion, can I just use initiator.stop(); initiator.start(); (ignoring isLoggedOn() and logout() for Session), to forcibly reconnect the entire initiator, allowing session A to drop and then become active again? This initiator only contains session A and no other sessions.

I missed the chance to capture thread dump. I will check it if this case happens next time :(

[chrjohn]

Back to your question: After possible deadlock heartbeat, we can't find any sending or receiving in session A(no fix message like 35=... 34=... 49=... 50=... in our log). But the above spring schedule showed Session.lookupSession(sessionId).isLoggedOn() always return true for session A after possible deadlock timepoint. Is this right? It looks like this connection do not get dropped.

This sounds strange, probably it really is a deadlock. Actually the session should realize that there were no heartbeats for some time and then time out. Could you check with your counterparty what they were seeing in their log after that time? When the counterparty received no heartbeats for some time, they also should drop the connection from their side.

If you want to stop the initiator brute-force way you could use stop(true) which will disconnect the sessions without waiting for logout. But I cannot tell if that will resolve the deadlock.