Java – strange behavior of quickfix / J after “sending test request test”
I am using quickfix / J to receive messages, but a test request has been sent The log file (fix. 4.2-a-b.event. Log) shows:
23:19:05: Sent test request TEST 23:19:32: Disconnecting: Timed out waiting for heartbeat 23:19:33: Initiated logon request 23:19:44: Disconnecting: Timed out waiting for logon response 23:19:45: Initiated logon request 23:19:56: Disconnecting: Timed out waiting for logon response ...
But I found something in another log file (fix. 4.2-a-b.message. Log):
8=FIX.4.2|9=68|35=1|34=250|49=A|52=20140224-23:19:05.909|56=B|112=TEST|10=106 8=FIX.4.2|9=74|35=0|49=B|56=A|43=N|34=1320|52=20140224-23:19:23.381|112=TEST|10=130
This obviously shows that the other Party B has sent back the heartbeat to us
And fix 4.2-A-B.messages. Log files are still growing!!!!!!!!!!! The file continues to receive messages, but the quickfix / J process does not (there is no response in the onmessage() method)!!!!
Please tell me why? After receiving the heartbeat, why is the connection still lost and the log is disconnecting?
Because this problem has not been solved yet This is an update:
My configuration:
[default] FileStorePath=/target/data/fixapplication ConnectionType=initiator SenderCompID=A TargetCompID=B SocketConnectHost=xxx.xxx.xxx.xx StartTime=00:00:00 EndTime=00:00:00 HeartBtInt=30 ReconnectInterval=5 FileLogPath=logs/fix/ [session] BeginString=FIX.4.2 SocketConnectPort=xxx ValidateFieldsOutOfOrder=N ResetOnlogon=Y
This is the code:
@Override
public void fromAdmin(Message message,SessionID sessionID) throws FieldNotFound,IncorrectDataFormat,IncorrectTagValue,Rejectlogon {
if (adminLog.isInfoEnabled())
adminLog.info("Inside fromAdmin(): " + message.getHeader().getString(MsgType.FIELD)
+ " ; " + message);
}
@Override
public void fromApp(Message message,UnsupportedMessageType {
crack(message,sessionID);
}
@Override
public void onCreate(SessionID arg0) {
}
@Override
public void onlogon(SessionID session) {
if (adminLog.isInfoEnabled()) {
adminLog.info("Inside onlogon: logon completed " + session.toString());
}
}
@Override
public void onlogout(SessionID sessionId) {
if (adminLog.isInfoEnabled()) {
adminLog.info("Inside onlogout: logout completed " + sessionId.toString());
}
}
Basically, I let quickfix / J handle the connection itself
The problem is that the application still receives messages but does not process them, and the log file shows that it is not connected All messages are in fix 4.2-A-B.message. Log, which is why it continues to grow
I found some similar cases:
http://www.quickfixj.org/jira/browse/QFJ-668
http://www.quickfixj.org/jira/browse/QFJ-624
http://quickfix-j.364392.n2.nabble.com/Timed-out-waiting-for-heartbeat-td365186.html
http://www.quickfixj.org/jira/browse/QFJ-759
Unfortunately, none of them provide a solution, so please help me
The second update is as follows:
I extract log files (I am a and the other party is b):
8=FIX.4.2|9=58|35=0|34=49|49=A|52=23:23:50.075|56=B|10=030| 8=FIX.4.2|9=58|35=0|34=50|49=A|52=23:24:20.074|56=B|10=019| **8=FIX.4.2|9=67|35=1|34=51|49=A|52=23:24:46.074|56=B|112=TEST|10=047|** **8=FIX.4.2|9=74|35=0|49=B|56=A|43=N|34=1103|52=23:24:59.060|112=TEST|10=125|** 8=FIX.4.2|9=75|35=A|34=1|49=A|52=23:25:14.076|56=B|98=0|108=30|141=Y|10=059| 8=FIX.4.2|9=74|35=A|49=B|56=A|43=N|34=1|52=23:25:27.076|98=0|108=30|10=004| 8=FIX.4.2|9=86|35=1|49=B|56=A|43=N|34=2|52=23:25:27.077|112=03/03/2014-07:25:27|10=117| 8=FIX.4.2|9=75|35=A|34=1|49=A|52=23:25:26.076|56=B|98=0|108=30|141=Y|10=062| 8=FIX.4.2|9=74|35=A|49=B|56=A|43=N|34=1|52=23:25:39.064|98=0|108=30|10=004| 8=FIX.4.2|9=86|35=1|49=B|56=A|43=N|34=2|52=23:25:39.065|112=03/03/2014-07:25:39|10=120| 8=FIX.4.2|9=75|35=A|34=1|49=A|52=23:25:38.076|56=B|98=0|108=30|141=Y|10=065| 8=FIX.4.2|9=74|35=A|49=B|56=A|43=N|34=1|52=23:25:51.064|98=0|108=30|10=254| 8=FIX.4.2|9=86|35=1|49=B|56=A|43=N|34=2|52=23:25:51.065|112=03/03/2014-07:25:51|10=108| 8=FIX.4.2|9=75|35=A|34=1|49=A|52=23:25:50.076|56=B|98=0|108=30|141=Y|10=059| 8=FIX.4.2|9=74|35=A|49=B|56=A|43=N|34=1|52=23:26:03.064|98=0|108=30|10=252| 8=FIX.4.2|9=86|35=1|49=B|56=A|43=N|34=2|52=23:26:03.065|112=03/03/2014-07:26:03|10=104| 8=FIX.4.2|9=75|35=A|34=1|49=A|52=23:26:02.076|56=B|98=0|108=30|141=Y|10=057| 8=FIX.4.2|9=74|35=A|49=B|56=A|43=N|34=1|52=23:26:15.064|98=0|108=30|10=255| 8=FIX.4.2|9=86|35=1|49=B|56=A|43=N|34=2|52=23:26:15.065|112=03/03/2014-07:26:15|10=110| 8=FIX.4.2|9=75|35=A|34=1|49=A|52=23:26:14.076|56=B|98=0|108=30|141=Y|10=060| 8=FIX.4.2|9=74|35=A|49=B|56=A|43=N|34=1|52=23:26:27.064|98=0|108=30|10=002| 8=FIX.4.2|9=86|35=1|49=B|56=A|43=N|34=2|52=23:26:27.065|112=03/03/2014-07:26:27|10=116| 8=FIX.4.2|9=75|35=A|34=1|49=A|52=23:26:26.076|56=B|98=0|108=30|141=Y|10=063| 8=FIX.4.2|9=74|35=A|49=B|56=A|43=N|34=1|52=23:26:39.065|98=0|108=30|10=006|
Please note that it will continue to try to log in to the session again but fail
At the same time, I'm sure the application will continue to receive messages from each other The evidence is fix 4.2-A-B.message. The log file keeps growing along with valid messages (not just heartbeat, but other valid messages) This means that the connection will not be lost
Why can't I log in to the session?
Please help
Third update:
The log that I started successfully for login is as follows:
8=FIX.4.2|9=75|35=A|34=1|49=A|52=23:00:07.095|56=B|98=0|108=30|141=Y|10=055| 8=FIX.4.2|9=74|35=A|49=B|56=A|43=N|34=1|52=23:00:20.221|98=0|108=30|10=238| 8=FIX.4.2|9=86|35=1|49=B|56=A|43=N|34=2|52=23:00:20.222|112=07:00:20|10=081| 8=FIX.4.2|9=81|35=0|34=2|49=A|52=23:00:07.301|56=B|112=07:00:20|10=091| 8=FIX.4.2|9=57|35=0|34=3|49=A|52=23:00:38.075|56=B|10=228| 8=FIX.4.2|9=63|35=0|49=B|56=A|43=N|34=26|52=23:00:51.260|10=00
The third line indicates that the opposite party sent me a test request, but I didn't reply. It seems that there is no problem and the connection is established
Should I explicitly handle the response to the test request? It seems that quickfix / J will handle it for me
Solution
The heartbeat behavior of fix standard is as follows:
1. On logon,the Initiator requests a heartbeat interval (usual default 30 seconds)
2. From Now on every side expects at least one message every 30 seconds (defined heartbeat interval)
3. If there is no application message available,a heartbeat is sent instead
4. If one side does not get neither a heartbeart nor an application message after 30 seconds,a connection issue is SUSPECTed.
5. Therefore,a TestRequest is sent ("Are you still there?"): Sent test request TEST
6. This TestRequest is not answered by a Heartbeat with the supplied TestRequestID,the connection is considered dead.
7. Finally,the network connection is dropped: Disconnecting: Timed out waiting for heartbeat
In the third update, your initiator a did respond to the test request with a heartbeat and provided the requested ID tag 112:
8=FIX.4.2|9=86|35=1|49=B|56=A|43=N|34=2|52=23:00:20.222|112=07:00:20|10=081| 8=FIX.4.2|9=81|35=0|34=2|49=A|52=23:00:07.301|56=B|112=07:00:20|10=091|
That's ok. Since then, a provides heartbeat after 30 seconds:
8=FIX.4.2|9=57|35=0|34=3|49=A|52=23:00:38.075|56=B|10=228|
But B did not reply for 13 seconds:
8=FIX.4.2|9=63|35=0|49=B|56=A|43=N|34=26|52=23:00:51.260|10=00
Is there a network problem between a and B? What's your problem?