[QFJ-669] Initiator interprets logout response as logout request. Created: 02/Mar/12  Updated: 24/Jan/13

Status: Open
Project: QuickFIX/J
Component/s: None
Affects Version/s: 1.5.2, 1.5.3
Fix Version/s: Future Releases

Type: Bug Priority: Default
Reporter: Bogdan Dornean Assignee: Unassigned
Resolution: Unresolved Votes: 0
Labels: None


 Description   

Steps:
1.INITIATOR sends logout request.
2.ACCEPTOR sends logout response.
3.INITIATOR interprets received logout message as logout REQUEST
4.INITIATOR sends logout response.

INFO: Logging out all sessions
<20120302-14:43:55, FIX.4.2:INITIATOR->ACCEPTOR, event> (Initiated logout request)
<20120302-14:43:55, FIX.4.2:INITIATOR->ACCEPTOR, outgoing> (8=FIX.4.29=5535=534=5549=INITIATOR52=20120302-14:43:55.80556=ACCEPTOR10=100)
<20120302-14:43:55, FIX.4.2:INITIATOR->ACCEPTOR, incoming> (8=FIX.4.29=8135=552=20120302-14:43:55.80849=ACCEPTOR34=17156=INITIATOR58=At the opposite wish.10=242)
<20120302-14:43:55, FIX.4.2:INITIATOR->ACCEPTOR, event> (Received logout request)
<20120302-14:43:55, FIX.4.2:INITIATOR->ACCEPTOR, outgoing> (8=FIX.4.29=5535=534=5649=INITIATOR52=20120302-14:43:55.81356=ACCEPTOR10=100)
Mar 2, 2012 11:43:55 PM quickfix.Session disconnect
INFO: [FIX.4.2:INITIATOR->ACCEPTOR] Disconnecting: IO Session closed

<20120302-14:43:55, FIX.4.2:INITIATOR->ACCEPTOR, error> (Error Reading/Writing in MessageStore
java.io.IOException: Bad file descriptor
at java.io.RandomAccessFile.writeBytes(Native Method)
Mar 2, 2012 11:43:55 PM quickfix.mina.SessionConnector stopSessionTimer
at java.io.RandomAccessFile.write(RandomAccessFile.java:453)
INFO: SessionTimer canceled
at quickfix.FileStore.set(FileStore.java:409)
at quickfix.SessionState.set(SessionState.java:308)
at quickfix.Session.sendRaw(Session.java:2307)
at quickfix.Session.generateLogout(Session.java:1350)
at quickfix.Session.generateLogout(Session.java:1323)
at quickfix.Session.nextLogout(Session.java:1301)
at quickfix.Session.next(Session.java:965)
at quickfix.mina.SingleThreadedEventHandlingStrategy$SessionMessageEvent.processMessage(SingleThreadedEventHandlingStrategy.java:114)
at quickfix.mina.SingleThreadedEventHandlingStrategy.block(SingleThreadedEventHandlingStrategy.java:77)
at quickfix.mina.SingleThreadedEventHandlingStrategy$1.run(SingleThreadedEventHandlingStrategy.java:94)
at java.lang.Thread.run(Thread.java:619)

<20120302-14:43:55, FIX.4.2:INITIATOR->ACCEPTOR, event> (Sent logout response)
<20120302-14:43:55, FIX.4.2:INITIATOR->ACCEPTOR, error> (Error processing message: 8=FIX.4.29=8135=534=17149=ACCEPTOR52=20120302-14:43:55.80856=INITIATOR58=At the opposite wish.10=242
ava.io.IOException: Bad file descriptor
at java.io.RandomAccessFile.seek(Native Method)
at quickfix.FileStore.storeSequenceNumbers(FileStore.java:414)
at quickfix.FileStore.incrNextTargetMsgSeqNum(FileStore.java:307)
at quickfix.SessionState.incrNextTargetMsgSeqNum(SessionState.java:368)
at quickfix.Session.nextLogout(Session.java:1310)
at quickfix.Session.next(Session.java:965)
at quickfix.mina.SingleThreadedEventHandlingStrategy$SessionMessageEvent.processMessage(SingleThreadedEventHandlingStrategy.java:114)
at quickfix.mina.SingleThreadedEventHandlingStrategy.block(SingleThreadedEventHandlingStrategy.java:77)
at quickfix.mina.SingleThreadedEventHandlingStrategy$1.run(SingleThreadedEventHandlingStrategy.java:94)
at java.lang.Thread.run(Thread.java:619)

 Comments   
Comment by Krzysztof Szalast [ 14/Sep/12 ]

I also have this error. After second unnecessary LogOut, when I am sending LogOn, in field 34 is bad value (to high).

Scenario:
Me (initiator): Logout t34=204
Counterparty (acceptor): Logout t34=315
Me: Logout* t34=205 (counterparty don't receive this message, but my outgoing_seqnum is incremented)
Me: Logon t34=206, t789=316
Counterparty: t34=316, t789=205 (205 was second Logout*)
Me: SequenceReset t34=205, 36=207 <-- this message sould not be sent. This is side effect of Logout* (t34=205)

Very sorry for my English

Comment by Krzysztof Szalast [ 14/Sep/12 ]

I've resolved problem by add "synchronized" modifier to methods:
quickfix.Session::next()
quickfix.Session::next(Message)
ugly, but looks work properly.

Comment by Jörg Thönnes [ 24/Jan/13 ]

I could reproduce this issue. It seems to happen if there is a very low latency in the network connection between client and server (e.g. on the same host).

Two things happen very quickly:

  • Incoming Logout is processed before the sentLogout flag in the session state is set / published.
  • Shortly after that the socket is closed: "Disconnecting: IO Session closed"

QFJ tries to answer the Logout it considers as request and fails:

  • event : No responder, not sending message: 8=FIX.4.4|9=53|35=5|34=...

But this message is kept in the message store and leads to a ResendRequest at the next logon.

IHMO, syncing on next() is too brute-force. On the other hand, correcting the already complicated state handling is tricky.

Comment by Jörg Thönnes [ 24/Jan/13 ]

Lowering priority since this is a race condition in a very specific situation and does not affect general functionality.

Generated at Sat Nov 23 10:58:11 UTC 2024 using JIRA 7.5.2#75007-sha1:9f5725bb824792b3230a5d8716f0c13e296a3cae.