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

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

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