Details
Major
Description
I have a problem that QuickFIXJ stops sending the heartbeat. Please see the QuickFIXJ log below.
The heartbeat interval is set to 4.
20150127-01:01:34: 8=FIXT.1.19=7535=034=318541128=949=TR MATCHING56=TMSQ03226252=20150127-01:01:34.78910=197
20150127-01:01:36: 8=FIXT.1.19=9535=034=3237749=TMSQ03226252=20150127-01:01:36.80256=TR MATCHING57=FXM142=TRFXMJP53776xxx10=130
20150127-01:01:38: 8=FIXT.1.19=7535=034=318551128=949=TR MATCHING56=TMSQ03226252=20150127-01:01:38.89910=204
20150127-01:01:41: 8=FIXT.1.19=9535=034=3237849=TMSQ03226252=20150127-01:01:41.73956=TR MATCHING57=FXM142=TRFXMJP53776xxx10=136
----- After this time FIXQuickJ stops sending the heartbeart ---- only receive the heartbeat from other side. ----
20150127-01:01:42: 8=FIXT.1.19=7535=034=318561128=949=TR MATCHING56=TMSQ03226252=20150127-01:01:42.96410=193
20150127-01:01:50: 8=FIXT.1.19=7535=034=318571128=949=TR MATCHING56=TMSQ03226252=20150127-01:01:47.03910=192
20150127-01:01:51: 8=FIXT.1.19=9035=134=318581128=949=TR MATCHING56=TMSQ03226252=20150127-01:01:48.063112=HBTO-3185810=242
20150127-01:01:52: 8=FIXT.1.19=7535=034=318591128=949=TR MATCHING56=TMSQ03226252=20150127-01:01:52.12910=190
------ It seems that FIXQuickJ received heartbeat and testrequest but FIXQuickJ does not process them as QuickFIXJ send the testrequest to other side. -----
20150127-01:01:51: 8=FIXT.1.19=10435=134=3237949=TMSQ03226252=20150127-01:01:51.89656=TR MATCHING57=FXM142=TRFXMJP53776xxx112=TEST10=200
------ The other side disconnect because it does not receive heartbeat -------
Do you have any idea why QuickFIXJ stops sending the heartbeat and also does not process the message from other side.
Attachments
Activity
From the sniffer message, I can see that the ACK of the heartbeat is sent immediately after the heartbeat arrived. Then I think the QuickFIXJ process the heartbeat delayed.
The last activity from QuickFIXJ was sending the Test Request. You can see that QuickFIXJ has already received heatbeat but QuickFIXJ sent test request. Then I think QuickFIXJ does not process the heartbeat.
I do not understand why QuickFIXJ can send the test request but does not send the heartbeat.
---------------------------------------------------------------------
20150127-00:59:56: 8=FIXT.1.19=7535=034=318301128=949=TR MATCHING56=TMSQ03226252=20150127-00:59:56.96010=198
20150127-00:59:58: 8=FIXT.1.19=9535=034=3235349=TMSQ03226252=20150127-00:59:58.67356=TR MATCHING57=FXM142=TRFXMJP53776xxx10=146
20150127-01:00:00: 8=FIXT.1.19=7535=034=318311128=949=TR MATCHING56=TMSQ03226252=20150127-01:00:01.04410=169
20150127-01:00:02: 8=FIXT.1.19=9535=034=3235449=TMSQ03226252=20150127-01:00:02.67456=TR MATCHING57=FXM142=TRFXMJP53776xxx10=124
20150127-01:00:05: 8=FIXT.1.19=7535=034=318321128=949=TR MATCHING56=TMSQ03226252=20150127-01:00:05.11910=177
20150127-01:00:06: 8=FIXT.1.19=9535=034=3235549=TMSQ03226252=20150127-01:00:06.67456=TR MATCHING57=FXM142=TRFXMJP53776xxx10=129
20150127-01:00:09: 8=FIXT.1.19=7535=034=318331128=949=TR MATCHING56=TMSQ03226252=20150127-01:00:09.21410=178
20150127-01:00:10: 8=FIXT.1.19=9535=034=3235649=TMSQ03226252=20150127-01:00:10.67456=TR MATCHING57=FXM142=TRFXMJP53776xxx10=125
20150127-01:00:13: 8=FIXT.1.19=7535=034=318341128=949=TR MATCHING56=TMSQ03226252=20150127-01:00:13.29710=185
20150127-01:00:14: 8=FIXT.1.19=9535=034=3235749=TMSQ03226252=20150127-01:00:14.67456=TR MATCHING57=FXM142=TRFXMJP53776xxx10=130
20150127-01:00:17: 8=FIXT.1.19=7535=034=318351128=949=TR MATCHING56=TMSQ03226252=20150127-01:00:17.39210=186
20150127-01:00:18: 8=FIXT.1.19=9535=034=3235849=TMSQ03226252=20150127-01:00:18.67456=TR MATCHING57=FXM142=TRFXMJP53776xxx10=135
20150127-01:00:21: 8=FIXT.1.19=7535=034=318361128=949=TR MATCHING56=TMSQ03226252=20150127-01:00:21.46610=184
20150127-01:00:22: 8=FIXT.1.19=9535=034=3235949=TMSQ03226252=20150127-01:00:22.67456=TR MATCHING57=FXM142=TRFXMJP53776xxx10=131
20150127-01:00:25: 8=FIXT.1.19=7535=034=318371128=949=TR MATCHING56=TMSQ03226252=20150127-01:00:25.54110=183
20150127-01:00:26: 8=FIXT.1.19=9535=034=3236049=TMSQ03226252=20150127-01:00:26.67456=TR MATCHING57=FXM142=TRFXMJP53776xxx10=127
20150127-01:00:29: 8=FIXT.1.19=7535=034=318381128=949=TR MATCHING56=TMSQ03226252=20150127-01:00:29.61710=192
20150127-01:00:30: 8=FIXT.1.19=9535=034=3236149=TMSQ03226252=20150127-01:00:30.67456=TR MATCHING57=FXM142=TRFXMJP53776xxx10=123
20150127-01:00:33: 8=FIXT.1.19=7535=034=318391128=949=TR MATCHING56=TMSQ03226252=20150127-01:00:33.68210=190
20150127-01:00:34: 8=FIXT.1.19=9535=034=3236249=TMSQ03226252=20150127-01:00:34.67556=TR MATCHING57=FXM142=TRFXMJP53776xxx10=129
20150127-01:00:37: 8=FIXT.1.19=7535=034=318401128=949=TR MATCHING56=TMSQ03226252=20150127-01:00:37.74810=189
20150127-01:00:38: 8=FIXT.1.19=9535=034=3236349=TMSQ03226252=20150127-01:00:38.67556=TR MATCHING57=FXM142=TRFXMJP53776xxx10=134
20150127-01:00:41: 8=FIXT.1.19=7535=034=318411128=949=TR MATCHING56=TMSQ03226252=20150127-01:00:41.81410=179
20150127-01:00:42: 8=FIXT.1.19=9535=034=3236449=TMSQ03226252=20150127-01:00:42.67556=TR MATCHING57=FXM142=TRFXMJP53776xxx10=130
20150127-01:00:45: 8=FIXT.1.19=7535=034=318421128=949=TR MATCHING56=TMSQ03226252=20150127-01:00:45.87910=195
20150127-01:00:46: 8=FIXT.1.19=9535=034=3236549=TMSQ03226252=20150127-01:00:46.67556=TR MATCHING57=FXM142=TRFXMJP53776xxx10=135
20150127-01:00:49: 8=FIXT.1.19=7535=034=318431128=949=TR MATCHING56=TMSQ03226252=20150127-01:00:49.95310=193
20150127-01:00:50: 8=FIXT.1.19=9535=034=3236649=TMSQ03226252=20150127-01:00:50.67556=TR MATCHING57=FXM142=TRFXMJP53776xxx10=131
20150127-01:00:53: 8=FIXT.1.19=7535=034=318441128=949=TR MATCHING56=TMSQ03226252=20150127-01:00:54.01810=182
20150127-01:00:54: 8=FIXT.1.19=9535=034=3236749=TMSQ03226252=20150127-01:00:54.67556=TR MATCHING57=FXM142=TRFXMJP53776xxx10=136
20150127-01:00:58: 8=FIXT.1.19=7535=034=318451128=949=TR MATCHING56=TMSQ03226252=20150127-01:00:58.09310=190
20150127-01:00:58: 8=FIXT.1.19=9535=034=3236849=TMSQ03226252=20150127-01:00:58.67556=TR MATCHING57=FXM142=TRFXMJP53776xxx10=141
20150127-01:01:02: 8=FIXT.1.19=7535=034=318461128=949=TR MATCHING56=TMSQ03226252=20150127-01:01:02.15810=183
20150127-01:01:02: 8=FIXT.1.19=9535=034=3236949=TMSQ03226252=20150127-01:01:02.67556=TR MATCHING57=FXM142=TRFXMJP53776xxx10=132
20150127-01:01:06: 8=FIXT.1.19=7535=034=318471128=949=TR MATCHING56=TMSQ03226252=20150127-01:01:06.25310=184
20150127-01:01:06: 8=FIXT.1.19=9535=034=3237049=TMSQ03226252=20150127-01:01:06.67656=TR MATCHING57=FXM142=TRFXMJP53776xxx10=129
20150127-01:01:10: 8=FIXT.1.19=7535=034=318481128=949=TR MATCHING56=TMSQ03226252=20150127-01:01:10.31810=182
20150127-01:01:10: 8=FIXT.1.19=9535=034=3237149=TMSQ03226252=20150127-01:01:10.67656=TR MATCHING57=FXM142=TRFXMJP53776xxx10=125
20150127-01:01:14: 8=FIXT.1.19=7535=034=318491128=949=TR MATCHING56=TMSQ03226252=20150127-01:01:14.40210=181
20150127-01:01:14: 8=FIXT.1.19=9535=034=3237249=TMSQ03226252=20150127-01:01:14.67656=TR MATCHING57=FXM142=TRFXMJP53776xxx10=130
20150127-01:01:18: 8=FIXT.1.19=7535=034=318501128=949=TR MATCHING56=TMSQ03226252=20150127-01:01:18.47810=190
20150127-01:01:18: 8=FIXT.1.19=9535=034=3237349=TMSQ03226252=20150127-01:01:18.84856=TR MATCHING57=FXM142=TRFXMJP53776xxx10=136
20150127-01:01:22: 8=FIXT.1.19=7535=034=318511128=949=TR MATCHING56=TMSQ03226252=20150127-01:01:22.53310=178
20150127-01:01:23: 8=FIXT.1.19=9535=034=3237449=TMSQ03226252=20150127-01:01:23.72356=TR MATCHING57=FXM142=TRFXMJP53776xxx10=125
20150127-01:01:26: 8=FIXT.1.19=7535=034=318521128=949=TR MATCHING56=TMSQ03226252=20150127-01:01:26.61010=179
20150127-01:01:27: 8=FIXT.1.19=9535=034=3237549=TMSQ03226252=20150127-01:01:27.81756=TR MATCHING57=FXM142=TRFXMJP53776xxx10=134
20150127-01:01:30: 8=FIXT.1.19=7535=034=318531128=949=TR MATCHING56=TMSQ03226252=20150127-01:01:30.73410=182
20150127-01:01:32: 8=FIXT.1.19=9535=034=3237649=TMSQ03226252=20150127-01:01:32.67656=TR MATCHING57=FXM142=TRFXMJP53776xxx10=134
20150127-01:01:34: 8=FIXT.1.19=7535=034=318541128=949=TR MATCHING56=TMSQ03226252=20150127-01:01:34.78910=197
20150127-01:01:36: 8=FIXT.1.19=9535=034=3237749=TMSQ03226252=20150127-01:01:36.80256=TR MATCHING57=FXM142=TRFXMJP53776xxx10=130
20150127-01:01:38: 8=FIXT.1.19=7535=034=318551128=949=TR MATCHING56=TMSQ03226252=20150127-01:01:38.89910=204
20150127-01:01:41: 8=FIXT.1.19=9535=034=3237849=TMSQ03226252=20150127-01:01:41.73956=TR MATCHING57=FXM142=TRFXMJP53776xxx10=136
20150127-01:01:42: 8=FIXT.1.19=7535=034=318561128=949=TR MATCHING56=TMSQ03226252=20150127-01:01:42.96410=193
20150127-01:01:50: 8=FIXT.1.19=7535=034=318571128=949=TR MATCHING56=TMSQ03226252=20150127-01:01:47.03910=192
20150127-01:01:51: 8=FIXT.1.19=9035=134=318581128=949=TR MATCHING56=TMSQ03226252=20150127-01:01:48.063112=HBTO-3185810=242
20150127-01:01:52: 8=FIXT.1.19=7535=034=318591128=949=TR MATCHING56=TMSQ03226252=20150127-01:01:52.12910=190
20150127-01:01:51: 8=FIXT.1.19=10435=134=3237949=TMSQ03226252=20150127-01:01:51.89656=TR MATCHING57=FXM142=TRFXMJP53776xxx112=TEST10=200
20150127-01:02:06: 8=FIXT.1.19=15435=A34=3238049=TMSQ03226252=20150127-01:01:58.11556=TR MATCHING57=FXM142=TRFXMJP53776xxx98=0108=4553=DCUA554=BTMU1234789=318581137=91407=10010=071
---------------------------------------------------------------------
I do not understand why QuickFIXJ can send the test request but does not send the heartbeat.
This is triggered by two different threads. There is a separate thread which sends out heartbeats. The processing of incoming messages is in a separate thread (message processor thread). Incoming messages are also handled on the message processor thread. This will also call your application callbacks fromAdmin/fromApp. So I would start searching there.
When looking at your log it starts to "get slow" at 01:01:50:
20150127-01:01:50: 8=FIXT.1.19=7535=034=318571128=949=TR MATCHING56=TMSQ03226252=20150127-01:01:47.03910=192 20150127-01:01:51: 8=FIXT.1.19=9035=134=318581128=949=TR MATCHING56=TMSQ03226252=20150127-01:01:48.063112=HBTO-3185810=242
The 52/SendingTime is off by three seconds. So actually you "simply" have to find out what happens there. Maybe it is not even within your application but the machine starts to get slow.
Moreover, at the end of the log there is a message from 01:01:51 again??
20150127-01:01:52: 8=FIXT.1.19=7535=034=318591128=949=TR MATCHING56=TMSQ03226252=20150127-01:01:52.12910=190 20150127-01:01:51: 8=FIXT.1.19=10435=134=3237949=TMSQ03226252=20150127-01:01:51.89656=TR MATCHING57=FXM142=TRFXMJP53776xxx112=TEST10=200
So the log file goes "backwards"?! In my opinion you are doing something nasty that you probably shouldn't do. I think the problem might be somewhere in your application. You are either doing something concurrently that shouldn't be done or your application is doing some time-consuming logic at some point. Are you concurrently modifying quickfix.Message objects? What are you doing anyway in your application code?
garima gangwar, Anupam Sinha: what is bufferSize config? Is it SocketSend/ReceiveBufferSize??
This value is now not being used anymore. What is SocketSend/ReceiveBufferSize?
@all: what was the last application message that was processed prior to this problem?
There was no application message that was received between the occurrences of the problem.
Is it always the same app message or is the time span after the last application message the same before the session breaks?
Does it always break at the same time? Or after same intervals?
No specific time. Sometimes it goes on for hours together and then sometimes it occurs within an interval of around 2 mins.
Is there only one FIX session configured? I assume there are not much messages transmitted? So this should be no performance problem, shouldn't it?
There is only one FIX session.
Closing due to inactivity and old version used.
Hi,
a heartbeat is no application message. An ExecutionReport/NewOrderSingle/... are application messages. However, you said that only heartbeats were received.
Regarding your initial log output in the issue description: you say that the engine does receive Heartbeats/TestRequests but does not answer them. So I would change the fromAdmin method of your application to check if the received message is a TestRequest. If yes, then create a stack trace and/or check for deadlocked threads. This can be achieved with some MBeans which are included in Java6 and up (ManagementFactory.getThreadMXBean())
Moreover, when I look at the log there seems to be a problem with the times. E.g. the first messages arrive in time (comparing the log time stamp and field 52/SendingTime). However, afterwards there is a gap of about three seconds. So this either means your network is flaky or the application/computer is heavily loaded and does not get the messages in time.