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

[Christoph J. <chr...@ma...>]

Hi,

you're welcome. Thanks for the update, glad that you could fix it.

Cheers,
Chris.

On 19.10.20 04:57, Darren wrote:
>
> Hi everyone,
>
> After reviewing my toApp/toAdmin implementations,
>
> and Session.sendRaw(), SessionConnector.startSessionTimer(),
>
> I think I identified this bug is a thread-safe issue,
>
> I didn't notice the heartbeat process would go through my toAdmin/toApp implementations,
>
> and they modified the message without making sure it's thread-safe.
>
> thanks for Chris's great help :)
>
>
> Regard,
>
> Darren
>
>
> Christoph John 於 2020/10/16 上午 12:51 寫道:
>> And again, it's me: would it be possible for you to share the content of your toApp/toAdmin 
>> implementations?
>> Otherwise I cannot imagine where the messages could get altered.
>> Would be good to have a reproducible test case. :) Never seen this behaviour and we have some 
>> installations with 100+ sessions in one VM.
>>
>> Chris.
>>
>> On 15.10.20 15:05, Christoph John wrote:
>>> 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= 1
59=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=0
60=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-5f881fb9af41
11=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=0
6=0 
60=20201008-13:09:36.457 
77=O
 58=Missing Account(1) 
>>>>>>> 
21=1
10=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=2320
52=20201008-13:08:06.185 
10=191

>>>>>>> 8=FIX.4.2 
9=62 
35=0
34=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=2321
52=20201008-13:08:36.185
 10=195

>>>>>>> 8=FIX.4.2
 9=62 
35=0
34=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=2322
52=20201008-13:09:06.185
 10=194

>>>>>>> 8=FIX.4.2
 9=62 
35=0
34=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=2323
52=20201008-13:09:36.185 
10=198

>>>>>>> 8=FIX.4.2 
9=77 
35=0
34=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=2157
49=XXXX 
52=20201008-13:07:35.953 
56=XXXX
 57=170886 
>>>>>>> 5
1=XXXX
 11=1602107674
21=1
38=1
40=2
44=28344
50=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=TW
18205=A1
10=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=0
60=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
>>
>> -- 
>> 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
> -- 
> 盧賢豪 Darren Lu
> Software Engineer
> 艾揚科技股份有限公司
> ICE Technology Corporation
> Tel:02-25583242 ext 153
> E-mail:da...@ic...

-- 
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