Re: [Quickfixj-users] Missing Logout Admin Message

[Daniel C. <da...@bl...>]

Hi Christopher,

Looking at the code, I agree with the approach, The Exception should be
handed off to the eventHandlingStrategy to ensure that any pending messages
are processed before disconnecting.

I have created a JIRA issue for this :
https://www.quickfixj.org/jira/browse/QFJ-966

I will see if i can find some time to try replicate and fix.

Regards
Daniel

On Mon, Dec 3, 2018 at 11:54 AM Christoph John <chr...@ma...>
wrote:

> 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):
> 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...>
> 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
>> .(.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 557...@ma...
>
> MACD GmbH
> Oppenhoffallee 103
> 52066 Aachen, Germanywww.macd.com
>
> Amtsgericht Aachen: HRB 8151
> Ust.-Id: DE 813021663
> Geschäftsführer: George Macdonald
>
>