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

[Darren <da...@ic...>]

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