RE: [Quickfix-developers] SocketConnection session registration BUG

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

Thanks!

> -----Original Message-----
> From: Oren Miller [mailto:or...@qu...]
> Sent: Monday, June 27, 2005 6:16 PM
> To: Sean Kirkpatrick; qui...@li...
> Subject: Re: [Quickfix-developers] SocketConnection session=20
> registration
> BUG
>=20
>=20
> Sean, I'll try to design a test that duplicates this scenario.
>=20
> --oren
>=20
> ----- Original Message -----=20
> From: "Sean Kirkpatrick" <Sea...@Pi...>
> To: <qui...@li...>
> Sent: Monday, June 27, 2005 10:34 AM
> Subject: [Quickfix-developers] SocketConnection session=20
> registration BUG
>=20
>=20
> QuickFIX Documentation:=20
> http://www.quickfixengine.org/quickfix/doc/html/index.html
> QuickFIX FAQ:=20
> http://www.quickfixengine.org/wikifix/index.php?QuickFixFAQ
> QuickFIX Support: http://www.quickfixengine.org/services.html
>=20
> 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:
>=20
> 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=20
> 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=20
> returned [72]=20
> bytes
> 09:00:20.452 {QF::Parser::readFromStream} recv [72] bytes on=20
> 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=20
> [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=20
> based on=20
> [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:=20
> [FIX.4.0:RECV->SEND]
> 09:00:20.452 {QF::Session::lookupSession} FOUND IT!
> 09:00:20.452 {QF::SocketConnection::read} registering session=20
> [FIX.4.0:RECV->SEND]
> 09:00:20.453 {QF::Session::lookupSession} Looking for session:=20
> [FIX.4.0:RECV->SEND]
> 09:00:20.453 {QF::Session::lookupSession} FOUND IT!
> 09:00:20.453 {QF::Session::registerSession} found session=20
> [FIX.4.0:RECV->SEND]
> 09:00:20.453 {QF::Session::registerSession} registering session
> ----
> 09:00:20.453 {QF::SocketConnection::read} getting=20
> SocketAcceptor session=20
> [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=20
> socket: [393]
> 09:00:20.453 {QF::SocketConnection::~SocketConnection} destroying=20
> SocketConnection
>=20
> The problem occurs between the "----" separated log lines. =20
> The library
> registers the session, but then attempts to validate that the=20
> 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=20
> 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,=20
> and the object
> is never unregistered.  Subsequent attempts to connect to=20
> this session log
> the following:
>=20
> 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=20
> 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=20
> returned [84]=20
> bytes
> 09:04:26.744 {QF::Parser::readFromStream} recv [84] bytes on=20
> 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=20
> [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=20
> based on=20
> [8=3DFIX.4.0^A9=3D62^A35=3DA
> =
^A49=3DSEND^A56=3DRECV^A34=3D3^A52=3D20050627-13:04:26^A98=3D0^A108=3D20^=
A
> 10=3D112^A]
> 09:04:26.745 {QF::Session::lookupSession} Looking for session:=20
> [FIX.4.0:RECV->SEND]
> 09:04:26.745 {QF::Session::lookupSession} FOUND IT!
> 09:04:26.745 {QF::SocketConnection::read} registering session=20
> [FIX.4.0:RECV->SEND]
> 09:04:26.745 {QF::Session::lookupSession} Looking for session:=20
> [FIX.4.0:RECV->SEND]
> 09:04:26.745 {QF::Session::lookupSession} FOUND IT!
> 09:04:26.745 {QF::Session::registerSession} found session=20
> [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=20
> socket: [393]
> 09:04:26.745 {QF::SocketConnection::~SocketConnection} destroying=20
> SocketConnection
>=20
> In between the "----" separated log lines, the session is detected as=20
> already
> registered and the m_pSession member is again set to NULL and=20
> the socket is
> dropped.
>=20
> I believe that there is a very simple fix that will correct=20
> this issue.  The
> order of the following code in SocketConnection::read (the=20
> LOGDEBUG lines=20
> are
> for the logging I added):
>=20
>   if ( m_pSession ) {
>     LOGDEBUG(funcname,"registering session=20
> [%s]",m_pSession->getSessionID().toString().c_str());
>     m_pSession =3D Session::registerSession(=20
> m_pSession->getSessionID() );
>   }
>=20
>   if ( m_pSession ) {
>     LOGDEBUG(funcname,"getting SocketAcceptor session=20
> [%s]",msg.c_str());
>     m_pSession =3D a.getSession( msg, *this );
>   }
>=20
> needs to be reversed to be:
>=20
>   if ( m_pSession ) {
>     LOGDEBUG(funcname,"getting SocketAcceptor session=20
> [%s]",msg.c_str());
>     m_pSession =3D a.getSession( msg, *this );
>   }
>=20
>   if ( m_pSession ) {
>     LOGDEBUG(funcname,"registering session=20
> [%s]",m_pSession->getSessionID().toString().c_str());
>     m_pSession =3D Session::registerSession(=20
> m_pSession->getSessionID() );
>   }
>=20
> If this is the case, any invalid initial messages will invalidate the
> m_pSession member prior to attempting to register the=20
> session.  Only valid
> connections will be registered, and the disconnect logic works fine so
> long as the registration is done properly.  A week of=20
> 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=20
> in the past.
>=20
> Please provide feedback.
>=20
> --Sean
>=20
>=20
> -------------------------------------------------------
> 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_id=16492&op=3Dick
> _______________________________________________
> Quickfix-developers mailing list
> Qui...@li...
> https://lists.sourceforge.net/lists/listinfo/quickfix-developers
>=20
>=20