Uploaded image for project: 'QuickFIX/J'
  1. QuickFIX/J
  2. QFJ-966

Initiator Logout does not appear in QFJ log file on connection reset

    Details

    • Type: Bug
    • Status: Open
    • Priority: Major
    • Resolution: Unresolved
    • Affects Version/s: 2.1.0
    • Fix Version/s: None
    • Component/s: Engine
    • Environment:
      linux

      Description

      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.....@[email protected].(.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`[email protected]...>..+(.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. IE: it is not in the QFJ log file but I can see it in the tcp dump.

      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 (/x.x.x.x:25265): java.io.IOException: Connection reset by peer"
      "onLogout: FIX.4.2:XXX->XXX"

      message from Christoph John

      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.

        Attachments

          Activity

            People

            • Assignee:
              Unassigned
              Reporter:
              Cullender Daniel
            • Votes:
              0 Vote for this issue
              Watchers:
              2 Start watching this issue

              Dates

              • Created:
                Updated: