Menu
▾
▴
Re: [Quickfixj-users] Missing Logout Admin Message
|
From: Christoph J. <chr...@ma...> - 2018-12-03 11:54:25
|
Hi Daniel, thanks for the stack trace and the kudos! :) The stack trace is quite helpful for the diagnosis. So this seems to be a special case that is not covered by the unit test. The problem is that the session is disconnected the "hard way" through the IOException, not waiting for messages to be processed that might still be in flight. This might have to be changed in the AbstractIoHandler to behave similar to the sessionClosed() callback. But this is only a first quick analysis. Of course this has to be made reproducable in a unit test and then fixed. Cheers, Chris. On 03/12/2018 12:17, Daniel Cullender wrote: > Hi Chris, > > Thanks for the response and for all the hard work. > > spot on - it is not in the QFJ log file but I can see it in the tcp dump. > > I did have a case where I received it once, so I think there is a race condition somewhere > > Funnily enough I was actually playing around with that exact test case this weekend trying to > replicate it. The issue though is on the initiator side not receiving the admin logout message, > not the acceptor side. > > The initiator stack trace (ie connection reset) looks like > > "..." > "\tat quickfix.Session.disconnect(Session.java:2028)" > "\tat quickfix.mina.AbstractIoHandler.exceptionCaught(AbstractIoHandler.java:84)" > "\tat > org.apache.mina.core.filterchain.DefaultIoFilterChain$TailFilter.exceptionCaught(DefaultIoFilterChain.java:828)" > "\tat > org.apache.mina.core.filterchain.DefaultIoFilterChain.callNextExceptionCaught(DefaultIoFilterChain.java:590)" > "\tat org.apache.mina.core.filterchain.DefaultIoFilterChain.access$1100(DefaultIoFilterChain.java:48)" > "\tat > org.apache.mina.core.filterchain.DefaultIoFilterChain$EntryImpl$1.exceptionCaught(DefaultIoFilterChain.java:937)" > "\tat org.apache.mina.core.filterchain.IoFilterAdapter.exceptionCaught(IoFilterAdapter.java:102)" > "\tat > org.apache.mina.core.filterchain.DefaultIoFilterChain.callNextExceptionCaught(DefaultIoFilterChain.java:590)" > "\tat org.apache.mina.core.filterchain.DefaultIoFilterChain.access$1100(DefaultIoFilterChain.java:48)" > "\tat > org.apache.mina.core.filterchain.DefaultIoFilterChain$EntryImpl$1.exceptionCaught(DefaultIoFilterChain.java:937)" > "\tat org.apache.mina.core.filterchain.IoFilterAdapter.exceptionCaught(IoFilterAdapter.java:102)" > "\tat > org.apache.mina.core.filterchain.DefaultIoFilterChain.callNextExceptionCaught(DefaultIoFilterChain.java:590)" > "\tat > org.apache.mina.core.filterchain.DefaultIoFilterChain.fireExceptionCaught(DefaultIoFilterChain.java:580)" > "\tat > org.apache.mina.core.polling.AbstractPollingIoProcessor.read(AbstractPollingIoProcessor.java:729)" > "\tat > org.apache.mina.core.polling.AbstractPollingIoProcessor.process(AbstractPollingIoProcessor.java:659)" > "\tat > org.apache.mina.core.polling.AbstractPollingIoProcessor.process(AbstractPollingIoProcessor.java:648)" > "\tat > org.apache.mina.core.polling.AbstractPollingIoProcessor.access$600(AbstractPollingIoProcessor.java:68)" > "\tat > org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor.run(AbstractPollingIoProcessor.java:1120)" > "\tat org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:64)" > "\tat java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1167)" > "\tat java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:641)" > "\tat java.base/java.lang.Thread.run(Thread.java:844)" > > and all I receive on the initiator side is > > "Initiated logon request" > "Disconnecting: Socket exception (/207.239.27.218:25265 <http://207.239.27.218:25265>): > java.io.IOException: Connection reset by peer" > "onLogout: FIX.4.2:blk2->JLQD" > > > Thanks again > Daniel > > > > On Mon, Dec 3, 2018 at 10:38 AM Christoph John <chr...@ma... > <mailto:chr...@ma...>> wrote: > > So you only see the Logout message in the tcpdump but not in the QFJ log file? > > Yes, I actually thought that this has been fixed some time ago and we have unit tests which > test this specific behaviour. > E.g. > https://github.com/quickfix-j/quickfixj/blob/master/quickfixj-core/src/test/java/quickfix/mina/LostLogoutTest.java > > Cheers, > Chris. > > > On 30/11/2018 19:14, Daniel Cullender via Quickfixj-users wrote: >> QuickFIX/J Documentation:http://www.quickfixj.org/documentation/ >> QuickFIX/J Support:http://www.quickfixj.org/support/ >> >> >> >> Hi, >> >> I think this is an old issue, but still seems to be a problem with the latest version of >> quickfixj 2.1.0. >> >> After my initiator sends a Logon message, the acceptor immediately sends back a Logout >> Message followed by closing the connection. Looking at the tcpdump, it is clear why the >> connection is closed >> >> x.x.x.x.56988 > x.x.x.x.25265: Flags [P.], cksum 0x9863 (incorrect -> 0xe431), seq 1:104, ack >> 1, win 21, length 103 >> E.....@.@..t..........b >> <mailto:E.....@.@..t..........b>.(.7.>..+P....c..8=FIX.4.2.9=81.35=A.34=1161.49=XXX.52=20181130-15:08:36.259.56=***.98=0.108=10.554=***.10=026. >> 15:08:36.336321 IP (tos 0x60, ttl 48, id 0, offset 0, flags [DF], proto TCP (6), length 188) >> x.x.x.x.x > x.x.x.x.56988: Flags [P.], cksum 0xdd5d (correct), seq 1:149, ack 104, win >> 4096, length 148 >> E`....@.0...........b...>..+(.8YP....]..*8=FIX.4.2.9=0124.35=5.34=552397.49=XXX.52=20181130-15:08:36.298.56=XXX.789=469881.58=MsgSeqNum >> too low, expecting 469881 but received 1161.10=079*. >> >> The problem is that *fromAdmin*is /never/ called before *onLogout* because of the connection >> reset following the logout message. I really need to access this logout message for a couple >> of internal reasons. >> >> Is there any workaround for this issue available? >> >> Thanks >> Daniel Cullender > -- 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 |
