Re: [Quickfix-developers] SocketConnection session registration BUG

SourceForge Headquarters 1320 Columbia Street Suite 310 San Diego, CA 92101 +1 (858) 422-6466

Sean, I'll try to design a test that duplicates this scenario.

--oren

----- Original Message ----- 
From: "Sean Kirkpatrick" <Sea...@Pi...>
To: <qui...@li...>
Sent: Monday, June 27, 2005 10:34 AM
Subject: [Quickfix-developers] SocketConnection session registration BUG

QuickFIX Documentation: 
http://www.quickfixengine.org/quickfix/doc/html/index.html
QuickFIX FAQ: http://www.quickfixengine.org/wikifix/index.php?QuickFixFAQ
QuickFIX Support: http://www.quickfixengine.org/services.html

I have added proprietary logging to the quickfix library to help debug
an issue we have been having with a client not being able to log in.
We could see the logon message coming across via tethereal, but were
unable to determine the reason why the socket was being dropped.

The following logs expose where the logic error in quickfix occurs:

09:00:20.452 {QF::SocketMonitor::block} Socket [393] has data
09:00:20.452 {QF::ServerWrapper::onEvent} data found on socket [393]
09:00:20.452 {QF::SocketAcceptor::onData} getting SocketConnection [393]
09:00:20.452 {QF::SocketAcceptor::onData} found SocketConnection [393]
09:00:20.452 {QF::SocketConnection::read} reading message
09:00:20.452 {QF::Parser::readFromStream} socket_fionread returned [72] 
bytes
09:00:20.452 {QF::Parser::readFromStream} recv [72] bytes on socket [393]
09:00:20.452 {QF::Parser::readFixMessage} found BeginString tag 8
09:00:20.452 {QF::Parser::readFixMessage} found CheckSum tag 10
09:00:20.452 {QF::Parser::readFixMessage} found final SOH char
09:00:20.452 {QF::Parser::readFixMessage} message 
[8=FIX.4.0^A9=50^A35=0^A49=SEND^A56=RECV
^A34=1^A52=20050627-13:00:20^A10=056^A]
09:00:20.452 {QF::SocketConnection::read} looking for session based on 
[8=FIX.4.0^A9=50^A35=0
^A49=SEND^A56=RECV^A34=1^A52=20050627-13:00:20^A10=056^A]
09:00:20.452 {QF::Session::lookupSession} Looking for session: 
[FIX.4.0:RECV->SEND]
09:00:20.452 {QF::Session::lookupSession} FOUND IT!
09:00:20.452 {QF::SocketConnection::read} registering session 
[FIX.4.0:RECV->SEND]
09:00:20.453 {QF::Session::lookupSession} Looking for session: 
[FIX.4.0:RECV->SEND]
09:00:20.453 {QF::Session::lookupSession} FOUND IT!
09:00:20.453 {QF::Session::registerSession} found session 
[FIX.4.0:RECV->SEND]
09:00:20.453 {QF::Session::registerSession} registering session
----
09:00:20.453 {QF::SocketConnection::read} getting SocketAcceptor session 
[8=FIX.4.0^A9=50^A35
=0^A49=SEND^A56=RECV^A34=1^A52=20050627-13:00:20^A10=056^A]
09:00:20.453 {QF::Acceptor::getSession} msgType [0] not valid
09:00:20.453 {QF::SocketConnection::read} Dropping socket connection
09:00:20.453 {QF::SocketConnection::read} reading message
09:00:20.453 {QF::Parser::readFromStream} socket_fionread failed
09:00:20.453 {QF::SocketMonitor::block} queue has sockets to drop
09:00:20.453 {QF::SocketAcceptor::onDisconnect} Disconnecting socket: [393]
09:00:20.453 {QF::SocketConnection::~SocketConnection} destroying 
SocketConnection

The problem occurs between the "----" separated log lines.  The library
registers the session, but then attempts to validate that the recvd message
is a logon.  If it is not, the function return NULL as the m_pSession
variable.  The next section of the SocketConnection read checks for a valid
m_pSession.  If the session is NULL, the socket is dropped.  When the
SocketConnection is destroyed, it's m_pSession is still NULL, and the object
is never unregistered.  Subsequent attempts to connect to this session log
the following:

09:04:26.744 {QF::SocketMonitor::block} Socket [393] has data
09:04:26.744 {QF::ServerWrapper::onEvent} data found on socket [393]
09:04:26.744 {QF::SocketAcceptor::onData} getting SocketConnection [393]
09:04:26.744 {QF::SocketAcceptor::onData} found SocketConnection [393]
09:04:26.744 {QF::SocketConnection::read} reading message
09:04:26.744 {QF::Parser::readFromStream} socket_fionread returned [84] 
bytes
09:04:26.744 {QF::Parser::readFromStream} recv [84] bytes on socket [393]
09:04:26.745 {QF::Parser::readFixMessage} found BeginString tag 8
09:04:26.745 {QF::Parser::readFixMessage} found CheckSum tag 10
09:04:26.745 {QF::Parser::readFixMessage} found final SOH char
09:04:26.745 {QF::Parser::readFixMessage} message 
[8=FIX.4.0^A9=62^A35=A^A49=SEND^A56=RECV
^A34=3^A52=20050627-13:04:26^A98=0^A108=20^A10=112^A]
09:04:26.745 {QF::SocketConnection::read} looking for session based on 
[8=FIX.4.0^A9=62^A35=A
^A49=SEND^A56=RECV^A34=3^A52=20050627-13:04:26^A98=0^A108=20^A10=112^A]
09:04:26.745 {QF::Session::lookupSession} Looking for session: 
[FIX.4.0:RECV->SEND]
09:04:26.745 {QF::Session::lookupSession} FOUND IT!
09:04:26.745 {QF::SocketConnection::read} registering session 
[FIX.4.0:RECV->SEND]
09:04:26.745 {QF::Session::lookupSession} Looking for session: 
[FIX.4.0:RECV->SEND]
09:04:26.745 {QF::Session::lookupSession} FOUND IT!
09:04:26.745 {QF::Session::registerSession} found session 
[FIX.4.0:RECV->SEND]
----
09:04:26.745 {QF::SocketConnection::read} Dropping socket connection
09:04:26.745 {QF::SocketConnection::read} reading message
09:04:26.745 {QF::Parser::readFromStream} socket_fionread failed
09:04:26.745 {QF::SocketMonitor::block} queue has sockets to drop
09:04:26.745 {QF::SocketAcceptor::onDisconnect} Disconnecting socket: [393]
09:04:26.745 {QF::SocketConnection::~SocketConnection} destroying 
SocketConnection

In between the "----" separated log lines, the session is detected as 
already
registered and the m_pSession member is again set to NULL and the socket is
dropped.

I believe that there is a very simple fix that will correct this issue.  The
order of the following code in SocketConnection::read (the LOGDEBUG lines 
are
for the logging I added):

  if ( m_pSession ) {
    LOGDEBUG(funcname,"registering session 
[%s]",m_pSession->getSessionID().toString().c_str());
    m_pSession = Session::registerSession( m_pSession->getSessionID() );
  }

  if ( m_pSession ) {
    LOGDEBUG(funcname,"getting SocketAcceptor session [%s]",msg.c_str());
    m_pSession = a.getSession( msg, *this );
  }

needs to be reversed to be:

  if ( m_pSession ) {
    LOGDEBUG(funcname,"getting SocketAcceptor session [%s]",msg.c_str());
    m_pSession = a.getSession( msg, *this );
  }

  if ( m_pSession ) {
    LOGDEBUG(funcname,"registering session 
[%s]",m_pSession->getSessionID().toString().c_str());
    m_pSession = Session::registerSession( m_pSession->getSessionID() );
  }

If this is the case, any invalid initial messages will invalidate the
m_pSession member prior to attempting to register the session.  Only valid
connections will be registered, and the disconnect logic works fine so
long as the registration is done properly.  A week of development was lost
due to the lack of engine-level logging in the quickfix library, and I
know that this is an issue that has been raised several times in the past.

Please provide feedback.

--Sean

-------------------------------------------------------
SF.Net email is sponsored by: Discover Easy Linux Migration Strategies
from IBM. Find simple to follow Roadmaps, straightforward articles,
informative Webcasts and more! Get everything you need to get up to
speed, fast. http://ads.osdn.com/?ad_idt77&alloc_id492&op=ick
_______________________________________________
Quickfix-developers mailing list
Qui...@li...
https://lists.sourceforge.net/lists/listinfo/quickfix-developers