Acceptor dropping logout messages

classic Classic list List threaded Threaded
8 messages Options
Reply | Threaded
Open this post in threaded view
|

Acceptor dropping logout messages

traggatt
Hi there,

We recently upgraded our application to QFJ 1.6.3 (from 1.5.0) and are now encountering an issue with dropped logout messages.

We're using the ThreadedSocketAcceptor to expose a FIX connection endpoint. When stop() is called, I see QFJ generating and then attempting to send the logout message. I never see the message actually being sent though since the connection appears to have already shutdown.

To drill into the code a little, I see QFJ attempting to send the message here:

https://github.com/quickfix-j/quickfixj/blob/ceb3e9d57c4f953f5b3ee2259703a971328ff0b1/quickfixj-core/src/main/java/quickfix/Session.java#L1383

This calls through to:

https://github.com/quickfix-j/quickfixj/blob/ceb3e9d57c4f953f5b3ee2259703a971328ff0b1/quickfixj-core/src/main/java/quickfix/Session.java#L2553

And finally:

https://github.com/quickfix-j/quickfixj/blob/ceb3e9d57c4f953f5b3ee2259703a971328ff0b1/quickfixj-core/src/main/java/quickfix/mina/IoSessionResponder.java#L63

This call to MINA fails because the underlying IoSession has already been closed. (As a side note, this is logged nowhere because synchronousWrites == false).

Stepping back, as far as I can tell through debugging QFJ, the problem originates in the ThreadedSocketAcceptor.stop() call; stopAcceptingConnections() is called before logoutAllSessions():

https://github.com/quickfix-j/quickfixj/blob/ceb3e9d57c4f953f5b3ee2259703a971328ff0b1/quickfixj-core/src/main/java/quickfix/ThreadedSocketAcceptor.java#L83

The damage (in stopAcceptingConnections()) appears to be done in the dispose(true) call:

https://github.com/quickfix-j/quickfixj/blob/ceb3e9d57c4f953f5b3ee2259703a971328ff0b1/quickfixj-core/src/main/java/quickfix/mina/acceptor/AbstractSocketAcceptor.java#L256

I see that this call was added relatively recently:

https://github.com/quickfix-j/quickfixj/commit/3e6eebf2d73aad6cfd38f8954d487af1ad65b1a2

Could this be the cause of the issue?

Feedback/comments/suggestions appreciated!

Thanks
Tim.
Reply | Threaded
Open this post in threaded view
|

Re: Acceptor dropping logout messages

Christoph John
QuickFIX/J Documentation: http://www.quickfixj.org/documentation/
QuickFIX/J Support: http://www.quickfixj.org/support/


Hi Tim,

I think the problem is (as you suggested) that stopAcceptingConnections() is called before
logoutAllSessions(). We had similar problems with Initiators (see
https://github.com/quickfix-j/quickfixj/pull/101 and http://www.quickfixj.org/jira/browse/QFJ-885 
respectively) which are going to be fixed shortly.

Feel free to open a JIRA issue or pull request for the Acceptor correction and maybe you can even
supply a unit test. Otherwise, I will try to look at this during the next weeks.

Thanks in advance and best regards,
Chris.


On 10/04/17 18:12, traggatt wrote:

> QuickFIX/J Documentation: http://www.quickfixj.org/documentation/
> QuickFIX/J Support: http://www.quickfixj.org/support/
>
>
> Hi there,
>
> We recently upgraded our application to QFJ 1.6.3 (from 1.5.0) and are now
> encountering an issue with dropped logout messages.
>
> We're using the ThreadedSocketAcceptor to expose a FIX connection endpoint.
> When stop() is called, I see QFJ generating and then attempting to send the
> logout message. I never see the message actually being sent though since the
> connection appears to have already shutdown.
>
> To drill into the code a little, I see QFJ attempting to send the message
> here:
>
> https://github.com/quickfix-j/quickfixj/blob/ceb3e9d57c4f953f5b3ee2259703a971328ff0b1/quickfixj-core/src/main/java/quickfix/Session.java#L1383
>
> This calls through to:
>
> https://github.com/quickfix-j/quickfixj/blob/ceb3e9d57c4f953f5b3ee2259703a971328ff0b1/quickfixj-core/src/main/java/quickfix/Session.java#L2553
>
> And finally:
>
> https://github.com/quickfix-j/quickfixj/blob/ceb3e9d57c4f953f5b3ee2259703a971328ff0b1/quickfixj-core/src/main/java/quickfix/mina/IoSessionResponder.java#L63
>
> This call to MINA fails because the underlying IoSession has already been
> closed. (As a side note, this is logged nowhere because synchronousWrites ==
> false).
>
> Stepping back, as far as I can tell through debugging QFJ, the problem
> originates in the ThreadedSocketAcceptor.stop() call;
> stopAcceptingConnections() is called before logoutAllSessions():
>
> https://github.com/quickfix-j/quickfixj/blob/ceb3e9d57c4f953f5b3ee2259703a971328ff0b1/quickfixj-core/src/main/java/quickfix/ThreadedSocketAcceptor.java#L83
>
> The damage (in stopAcceptingConnections()) appears to be done in the
> dispose(true) call:
>
> https://github.com/quickfix-j/quickfixj/blob/ceb3e9d57c4f953f5b3ee2259703a971328ff0b1/quickfixj-core/src/main/java/quickfix/mina/acceptor/AbstractSocketAcceptor.java#L256
>
> I see that this call was added relatively recently:
>
> https://github.com/quickfix-j/quickfixj/commit/3e6eebf2d73aad6cfd38f8954d487af1ad65b1a2
>
> Could this be the cause of the issue?
>
> Feedback/comments/suggestions appreciated!
>
> Thanks
> Tim.
>
>
>
> --
> View this message in context: http://quickfix-j.364392.n2.nabble.com/Acceptor-dropping-logout-messages-tp7579837.html
> Sent from the QuickFIX/J mailing list archive at Nabble.com.
>
> ------------------------------------------------------------------------------
> Check out the vibrant tech community on one of the world's most
> engaging tech sites, Slashdot.org! http://sdm.link/slashdot
> _______________________________________________
> Quickfixj-users mailing list
> [hidden email]
> https://lists.sourceforge.net/lists/listinfo/quickfixj-users

--
Christoph John
Development & Support
Direct: +49 241 557080-28
Mailto:[hidden email]
       


http://www.macd.com <http://www.macd.com/>
----------------------------------------------------------------------------------------------------
       
----------------------------------------------------------------------------------------------------
MACD GmbH
Oppenhoffallee 103
D-52066 Aachen
Tel: +49 241 557080-0 | Fax: +49 241 557080-10
         Amtsgericht Aachen: HRB 8151
Ust.-Id: DE 813021663

Geschäftsführer: George Macdonald
----------------------------------------------------------------------------------------------------
       
----------------------------------------------------------------------------------------------------

take care of the environment - print only if necessary

------------------------------------------------------------------------------
Check out the vibrant tech community on one of the world's most
engaging tech sites, Slashdot.org! http://sdm.link/slashdot
_______________________________________________
Quickfixj-users mailing list
[hidden email]
https://lists.sourceforge.net/lists/listinfo/quickfixj-users
Reply | Threaded
Open this post in threaded view
|

Re: Acceptor dropping logout messages

traggatt
Thanks for the quick response, Chris.

I'd suggest it might also be worth reviewing the dispose() call in the stopAcceptingConnections() method. As far as I can see, it's this call that triggers the IoSession to fully disconnect, preventing the logout message from being sent.

Tim.
Reply | Threaded
Open this post in threaded view
|

Re: Acceptor dropping logout messages

Christoph John
QuickFIX/J Documentation: http://www.quickfixj.org/documentation/
QuickFIX/J Support: http://www.quickfixj.org/support/


Hi Tim,

OK, will take a look. But that call was introduced to correct a file descriptor leak.
http://www.quickfixj.org/jira/browse/QFJ-897
So we need to be able to correct the behaviour without removing that line.

In the meantime, could you do me a favour and re-test the behaviour on your side with a current
1.6.4-SNAPSHOT or 1.7.0-SNAPSHOT build?
https://oss.sonatype.org/content/repositories/snapshots/org/quickfixj/

Thanks,
Chris.


On 11/04/17 10:33, traggatt wrote:

> QuickFIX/J Documentation: http://www.quickfixj.org/documentation/
> QuickFIX/J Support: http://www.quickfixj.org/support/
>
>
> Thanks for the quick response, Chris.
>
> I'd suggest it might also be worth reviewing the dispose() call in the
> stopAcceptingConnections() method. As far as I can see, it's this call that
> triggers the IoSession to fully disconnect, preventing the logout message
> from being sent.
>
> Tim.
>
>
--
Christoph John
Development & Support
Direct: +49 241 557080-28
Mailto:[hidden email]
       


http://www.macd.com <http://www.macd.com/>
----------------------------------------------------------------------------------------------------
       
----------------------------------------------------------------------------------------------------
MACD GmbH
Oppenhoffallee 103
D-52066 Aachen
Tel: +49 241 557080-0 | Fax: +49 241 557080-10
         Amtsgericht Aachen: HRB 8151
Ust.-Id: DE 813021663

Geschäftsführer: George Macdonald
----------------------------------------------------------------------------------------------------
       
----------------------------------------------------------------------------------------------------

take care of the environment - print only if necessary

------------------------------------------------------------------------------
Check out the vibrant tech community on one of the world's most
engaging tech sites, Slashdot.org! http://sdm.link/slashdot
_______________________________________________
Quickfixj-users mailing list
[hidden email]
https://lists.sourceforge.net/lists/listinfo/quickfixj-users
Reply | Threaded
Open this post in threaded view
|

Re: Acceptor dropping logout messages

Christoph John
QuickFIX/J Documentation: http://www.quickfixj.org/documentation/
QuickFIX/J Support: http://www.quickfixj.org/support/


Hi again,

I am currently checking this and from aunit test perspective it looks fine after implementing the
necessary changes for QFJ-885.
This should be ready for testing during the next daysvia one of the snapshot releases.

Cheers,
Chris.


On 11/04/17 10:42, Christoph John wrote:

> Hi Tim,
>
> OK, will take a look. But that call was introduced to correct a file descriptor leak.
> http://www.quickfixj.org/jira/browse/QFJ-897
> So we need to be able to correct the behaviour without removing that line.
>
> In the meantime, could you do me a favour and re-test the behaviour on your side with a current
> 1.6.4-SNAPSHOT or 1.7.0-SNAPSHOT build?
> https://oss.sonatype.org/content/repositories/snapshots/org/quickfixj/
>
> Thanks,
> Chris.
>
>
> On 11/04/17 10:33, traggatt wrote:
>> QuickFIX/J Documentation: http://www.quickfixj.org/documentation/
>> QuickFIX/J Support: http://www.quickfixj.org/support/
>>
>>
>> Thanks for the quick response, Chris.
>>
>> I'd suggest it might also be worth reviewing the dispose() call in the
>> stopAcceptingConnections() method. As far as I can see, it's this call that
>> triggers the IoSession to fully disconnect, preventing the logout message
>> from being sent.
>>
>> Tim.
>>
>>

--
Christoph John
Development & Support
Direct: +49 241 557080-28
Mailto:[hidden email]
       


http://www.macd.com <http://www.macd.com/>
----------------------------------------------------------------------------------------------------
       
----------------------------------------------------------------------------------------------------
MACD GmbH
Oppenhoffallee 103
D-52066 Aachen
Tel: +49 241 557080-0 | Fax: +49 241 557080-10
         Amtsgericht Aachen: HRB 8151
Ust.-Id: DE 813021663

Geschäftsführer: George Macdonald
----------------------------------------------------------------------------------------------------
       
----------------------------------------------------------------------------------------------------

take care of the environment - print only if necessary

------------------------------------------------------------------------------
Check out the vibrant tech community on one of the world's most
engaging tech sites, Slashdot.org! http://sdm.link/slashdot
_______________________________________________
Quickfixj-users mailing list
[hidden email]
https://lists.sourceforge.net/lists/listinfo/quickfixj-users
Reply | Threaded
Open this post in threaded view
|

Re: Acceptor dropping logout messages

Christoph John
QuickFIX/J Documentation: http://www.quickfixj.org/documentation/
QuickFIX/J Support: http://www.quickfixj.org/support/


Hi Tim,

if you like you could now download the newest snapshot from the links posted earlier and let me know
if the behaviour is fixed or if you still experience issues.

Thanks,
Chris.


On 11/04/17 15:57, Christoph John wrote:

> Hi again,
>
> I am currently checking this and from aunit test perspective it looks fine after implementing the
> necessary changes for QFJ-885.
> This should be ready for testing during the next daysvia one of the snapshot releases.
>
> Cheers,
> Chris.
>
>
> On 11/04/17 10:42, Christoph John wrote:
>> Hi Tim,
>>
>> OK, will take a look. But that call was introduced to correct a file descriptor leak.
>> http://www.quickfixj.org/jira/browse/QFJ-897
>> So we need to be able to correct the behaviour without removing that line.
>>
>> In the meantime, could you do me a favour and re-test the behaviour on your side with a current
>> 1.6.4-SNAPSHOT or 1.7.0-SNAPSHOT build?
>> https://oss.sonatype.org/content/repositories/snapshots/org/quickfixj/
>>
>> Thanks,
>> Chris.
>>
>>
>> On 11/04/17 10:33, traggatt wrote:
>>> QuickFIX/J Documentation: http://www.quickfixj.org/documentation/
>>> QuickFIX/J Support: http://www.quickfixj.org/support/
>>>
>>>
>>> Thanks for the quick response, Chris.
>>>
>>> I'd suggest it might also be worth reviewing the dispose() call in the
>>> stopAcceptingConnections() method. As far as I can see, it's this call that
>>> triggers the IoSession to fully disconnect, preventing the logout message
>>> from being sent.
>>>
>>> Tim.
>>>
>>>
>

--
Christoph John
Development & Support
Direct: +49 241 557080-28
Mailto:[hidden email]
       


http://www.macd.com <http://www.macd.com/>
----------------------------------------------------------------------------------------------------
       
----------------------------------------------------------------------------------------------------
MACD GmbH
Oppenhoffallee 103
D-52066 Aachen
Tel: +49 241 557080-0 | Fax: +49 241 557080-10
         Amtsgericht Aachen: HRB 8151
Ust.-Id: DE 813021663

Geschäftsführer: George Macdonald
----------------------------------------------------------------------------------------------------
       
----------------------------------------------------------------------------------------------------

take care of the environment - print only if necessary

------------------------------------------------------------------------------
Check out the vibrant tech community on one of the world's most
engaging tech sites, Slashdot.org! http://sdm.link/slashdot
_______________________________________________
Quickfixj-users mailing list
[hidden email]
https://lists.sourceforge.net/lists/listinfo/quickfixj-users
Reply | Threaded
Open this post in threaded view
|

Re: Acceptor dropping logout messages

traggatt
Hi Chris,

Apologies for the long delay in responding here.

I tested the new 1.6.4 release and the issue is still there. After a little debugging, I have a new explanation for the behaviour - please see below.

When a FIX acceptor is shutdown, a call is made to SessionConnector.logoutAllSessions(). This calls Session.logout() on all sessions in turn, regardless of prior status. The logout() method is asynchronous and merely sets a private flag in Session. The actual logout message is sent later when the flag is picked up by a background thread (see Session.next()).

After the SessionConnector.logout() call completes, the SessionConnector should wait for all sessions to be logged out. However, due to incorrect use of SessionConnector.isLoggedOn(), waitForLogout() is never called.

isLoggedOn() performs an AND-style operation on the results of all session.isLoggedOn() methods. This means that if one or more sessions are not logged on, we do not wait for those that are.

In our configuration, we run multiple sessions which are not necessarily all connected at once. Thus we do not see the shutdown routine wait for the logout message to be sent.

Testing with our application, if I override the SessionConnector class and switch in an OR-style operation for the isLoggedOn() call, I always see the logout being sent.

FYI: latest 1.6.x version of SessionConnector: https://github.com/quickfix-j/quickfixj/blob/QFJ_1_6_x/quickfixj-core/src/main/java/quickfix/mina/SessionConnector.java

Thanks
Tim.
Reply | Threaded
Open this post in threaded view
|

Re: Acceptor dropping logout messages

traggatt
This post has NOT been accepted by the mailing list yet.
FYI - I added a PR with the fix and a test. See https://github.com/quickfix-j/quickfixj/pull/130.