|
From: Darren <da...@ic...> - 2020-10-19 03:04:26
|
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= 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 > > -- > 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... |