Re: [Quickfixj-users] Order request message truncated and affected by heartbeat message

SourceForge Headquarters 1320 Columbia Street Suite 310 San Diego, CA 92101 +1 (858) 422-6466

Just asking because the Heartbeat might only be a logging issue, unless you have proof that the 
Heartbeat was sent out like shown in your log. But if that was the case I would expect the 
counterparty rejected it.

On 15.10.20 14:27, Christoph John via Quickfixj-users wrote:
> QuickFIX/J Documentation: http://www.quickfixj.org/documentation/
> QuickFIX/J Support: http://www.quickfixj.org/support/
>
>
>
> Hi,
>
> one more thing, could you post the original message log? Did I get it right that the heartbeat was 
> not rejected although it contains invalid tags?
>
> Thanks,
> Chris.
>
> On 14.10.20 05:00, Darren wrote:
>>
>> Hi Chris,
>>
>> thanks for the reply,
>>
>> My application just create one session only, and it's a single thread process to send request,
>>
>> I encounter this error after upgrade quickfixj to version 2.1.1,
>>
>> never seem this error when still using 1.5.3,
>>
>> I cant figure out what cause this error so I tried to update to the latest version 2.2.0,
>>
>> but it seems still happened...
>>
>> yes this looks like heartbeat msg is blocked by something,
>>
>> and i think it's not a big deal, but my request content is modified, that's a serious problem XD
>>
>> I traced the message creation process, there is no way one message will be affected by another,
>>
>> especially by the heartbeat message,
>>
>> Session.java
>>
>>     public void generateHeartbeat() {
>>         final Message heartbeat = messageFactory.create(sessionID.getBeginString(),
>>                 MsgType.HEARTBEAT);
>>         initializeHeader(heartbeat.getHeader());
>>         sendRaw(heartbeat, 0);
>>     }
>>
>> this heartbeat generation process looks straightforward and simple,
>>
>> how this heartbeat message get tags from my order request content?
>>
>> checked the sendRaw method but everything looks fine to me XD
>>
>>
>> Regards,
>>
>> Darren
>>
>>
>> Christoph John 於 2020/10/13 下午 08:53 寫道:
>>> Hi,
>>>
>>> some thoughts/questions:
>>>
>>> How many sessions do you operate in the same JVM?
>>> So you are saying you did not encounter that error with older versions of QFJ?
>>> Are you sending messages from several threads concurrently to the same session?
>>>
>>> It could be that heartbeats are off by some time since they are triggered by the timer thread 
>>> which runs about once per second. 200ms is a bit large a delay however.
>>> Since the heartbeat is sent in the same millisecond as the order message it looks like something 
>>> was blocking.
>>>
>>> Cheers,
>>> Chris.
>>>
>>>
>>>
>>> On 13.10.20 08:24, Darren wrote:
>>>> QuickFIX/J Documentation:http://www.quickfixj.org/documentation/
>>>> QuickFIX/J Support:http://www.quickfixj.org/support/
>>>>
>>>>
>>>>
>>>> Hi everyone,
>>>>
>>>> I update my quickfixj-developed project to version 2.2.0 recently,
>>>>
>>>> after a couple of weeks later, i was reported a order request issue,
>>>>
>>>> receive error message(tag58) shows 'Missing Account(1)'
>>>>
>>>> after checking msg log, I noticed the order request and heartbeat message sent at the same time
>>>>
>>>> 8=FIX.4.2 9=77 35=0 34=2161 49=XXXXX 52=20201008-13:09:36.386 56=XXXXX 38= 159=0 77=O 
>>>> 10=240
>>>>
>>>> 8=FIX.4.2 9=137 35=D 34=2162 49=XXXXX 52=20201008-13:09:36.386 56=XXXXX 11=1602107675 
>>>> 21=1 38=1 40=3 54=1 55=YM 59=060=20201008-13:09:36.386 77=O 10=121
>>>>
>>>> 8=FIX.4.2 9=00296 35=8 49=XXXXX 56=XXXXX 34=2324 52=20201008-13:09:36.457 129=NONE 
>>>> 37=3040153c-7a98-4249-bc8f-5f881fb9af4111=1602107675 17=7626495d-aa27-49ae-a4d4-935e2d9e9abb 
>>>> 20=0 150=8 39=8 103=99 55=YM 54=1 38=1 40=3 59=0 32=0 31=0 151=0 14=06=0 
>>>> 60=20201008-13:09:36.457 77=O 58=Missing Account(1) 21=110=017
>>>>
>>>> and a few tags from my order request was missing, so server responsed error msg with Missing 
>>>> Account(1).
>>>>
>>>> I checked the heartbeat msg log before this request
>>>>
>>>> 8=FIX.4.2 9=00062 35=0 49=XXXX 56=XXXX 34=232052=20201008-13:08:06.185 10=191
>>>> 8=FIX.4.2 9=62 35=034=2158 49=XXXX 52=20201008-13:08:06.155 56=XXXX 10=053
>>>> 8=FIX.4.2 9=00062 35=0 49=XXXX 56=XXXX 34=232152=20201008-13:08:36.185 10=195
>>>> 8=FIX.4.2 9=62 35=034=2159 49=XXXX 52=20201008-13:08:36.154 56=XXXX 10=056
>>>> 8=FIX.4.2 9=00062 35=0 49=XXXX 56=XXXX 34=232252=20201008-13:09:06.185 10=194
>>>> 8=FIX.4.2 9=62 35=034=2160 49=XXXX 52=20201008-13:09:06.153 56=XXXX 10=045
>>>> 8=FIX.4.2 9=00062 35=0 49=XXXX 56=XXXX 34=232352=20201008-13:09:36.185 10=198
>>>> 8=FIX.4.2 9=77 35=034=2161 49=XXXX 52=20201008-13:09:36.386 56=XXXX 38=1 59=0 77=O 
>>>> 10=240
>>>>
>>>> my heartbeat interval setting is 30sec, so I thought the last heartbeat msg should be sent at 
>>>> around 20201008-13:09:36.153,
>>>>
>>>> but log shows it was sent at 20201008-13:09:36.386, about 200 ms delayed,
>>>>
>>>> after checking the source of quickfixj, I still cant figure out who delayed the heartbeat msg,
>>>>
>>>> and why this heartbeat msg contains tag37, tag59 and tag77,
>>>>
>>>> these tags looks like copied from my order request, and a few tags from my order request is missing
>>>>
>>>> normal request:
>>>>
>>>> 8=FIX.4.2 9=265 35=D 34=215749=XXXX 52=20201008-13:07:35.953 56=XXXX 57=170886 51=XXXX 
>>>> 11=160210767421=138=140=244=2834450=XXXX 54=1 55=YM 59=0 60=20201008-13:07:35.953 
>>>> 77=O 116=XXXX 167=FUT 207=CME 454=1 455=YM Dec20 456=97 11028=Y 16142=TW18205=A110=182
>>>>
>>>> abnormal request:
>>>>
>>>> 8=FIX.4.2 9=137 35=D 34=2162 49=XXXXX 52=20201008-13:09:36.386 56=XXXXX 11=1602107675 
>>>> 21=1 38=1 40=3 54=1 55=YM 59=060=20201008-13:09:36.386 77=O 10=121
>>>>
>>>> this issue happens about once a month, difficult to duplicate,
>>>>
>>>> any thoughts / ideas would be appreciated. :)
>>>>
>>>>
>>>> Regards,
>>>>
>>>> Darren
>>>>
>>>>

-- 
Christoph John
Software Engineering
T +49 241 557080-28
chr...@ma...

MACD GmbH
Oppenhoffallee 103
52066 Aachen, Germany
www.macd.com

Amtsgericht Aachen: HRB 8151
Ust.-Id: DE 813021663
Geschäftsführer: George Macdonald