[Quickfix-developers] SocketConnection session registration BUG

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

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. =20

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=3DFIX.4.0^A9=3D50^A35=3D0^A49=3DSEND^A56=3DRECV
^A34=3D1^A52=3D20050627-13:00:20^A10=3D056^A]
09:00:20.452 {QF::SocketConnection::read} looking for session based on =
[8=3DFIX.4.0^A9=3D50^A35=3D0
^A49=3DSEND^A56=3DRECV^A34=3D1^A52=3D20050627-13:00:20^A10=3D056^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=3DFIX.4.0^A9=3D50^A35
=3D0^A49=3DSEND^A56=3DRECV^A34=3D1^A52=3D20050627-13:00:20^A10=3D056^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=3DFIX.4.0^A9=3D62^A35=3DA^A49=3DSEND^A56=3DRECV
^A34=3D3^A52=3D20050627-13:04:26^A98=3D0^A108=3D20^A10=3D112^A]
09:04:26.745 {QF::SocketConnection::read} looking for session based on =
[8=3DFIX.4.0^A9=3D62^A35=3DA
^A49=3DSEND^A56=3DRECV^A34=3D3^A52=3D20050627-13:04:26^A98=3D0^A108=3D20^=
A10=3D112^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 =3D Session::registerSession( m_pSession->getSessionID() =
);
  }

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

needs to be reversed to be:

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

  if ( m_pSession ) {
    LOGDEBUG(funcname,"registering session =
[%s]",m_pSession->getSessionID().toString().c_str());
    m_pSession =3D 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