[Quickfix-developers] Unexpected resend request behavior

[Sean K. <sea...@pi...>]

Hi Everybody,

We had an issue that I've never seen before involving sequence numbers =
with a session in production this morning.  A session failed to respond =
to a test request and was disconnected, as expected. =20

When they logged back in, each side sent a resend request to sync up the =
sequence numbers.  We requested from 40 up, while they requested from 41 =
up.  We sent a reset seq num to 45 message and followed up with a =
heartbeat with seq number 45.  They sent us a reset seq num to 45 =
message, but followed up with a heartbeat with seq number 46.

After this, every subsequent message from the client resulted in an =
error to the event_log like this:

Already sent ResendRequest FROM: 40 TO: 43.  Not sending another.

No messages made it through to our FIX server, but no messages were sent =
to the client either.  I've included the messages below.  Can someone =
let me know what causes this?  How to catch a situation like this in the =
calling app? etc...

Thanks,
Sean


The following is the sequence of messages:

incoming_log
8=3DFIX.4.0=019=3D69=0135=3DA=0134=3D1=0149=3DCLIENT=0152=3D20060713-11:3=
0:16=0156=3DSERVER=0157=3DADMIN=0198=3D0=01108=3D50=0110=3D214=01
8=3DFIX.4.0=019=3D68=0135=3D1=0134=3D2=0149=3DCLIENT=0152=3D20060713-11:3=
0:16=0156=3DSERVER=0157=3DADMIN=01112=3D073016=0110=3D174=01
8=3DFIX.4.0=019=3D58=0135=3D0=0134=3D39=0149=3DCLIENT=0152=3D20060713-12:=
02:26=0156=3DSERVER=0157=3DADMIN=0110=3D228=01
8=3DFIX.4.0=019=3D70=0135=3DA=0134=3D44=0149=3DCLIENT=0152=3D20060713-12:=
06:44=0156=3DSERVER=0157=3DADMIN=0198=3D0=01108=3D50=0110=3D010=01
8=3DFIX.4.0=019=3D73=0135=3D2=0134=3D45=0149=3DCLIENT=0152=3D20060713-12:=
06:44=0156=3DSERVER=0157=3DADMIN=017=3D41=0116=3D999999=0110=3D185=01
8=3DFIX.4.0=019=3D88=0135=3D4=0134=3D40=0143=3DY=0149=3DCLIENT=0152=3D200=
60713-12:06:44=0156=3DSERVER=01122=3D20060713-12:06:44=0136=3D45=01123=3D=
Y=0110=3D071=01
8=3DFIX.4.0=019=3D58=0135=3D0=0134=3D46=0149=3DCLIENT=0152=3D20060713-12:=
07:38=0156=3DSERVER=0157=3DADMIN=0110=3D234=01
8=3DFIX.4.0=019=3D71=0135=3DA=0134=3D823=0149=3DCLIENT=0152=3D20060713-14=
:49:49=0156=3DSERVER=0157=3DADMIN=0198=3D0=01108=3D50=0110=3D078=01
8=3DFIX.4.0=019=3D70=0135=3D1=0134=3D824=0149=3DCLIENT=0152=3D20060713-14=
:49:49=0156=3DSERVER=0157=3DADMIN=01112=3D104949=0110=3D048=01
8=3DFIX.4.0=019=3D70=0135=3D1=0134=3D828=0149=3DCLIENT=0152=3D20060713-14=
:50:50=0156=3DSERVER=0157=3DADMIN=01112=3D105050=0110=3D020=01
8=3DFIX.4.0=019=3D70=0135=3D1=0134=3D829=0149=3DCLIENT=0152=3D20060713-14=
:51:01=0156=3DSERVER=0157=3DADMIN=01112=3D105101=0110=3D015=01

outgoing_log
8=3DFIX.4.0=019=3D60=0135=3DA=0134=3D1=0149=3DSERVER=0152=3D20060713-11:3=
0:16=0156=3DCLIENT=0198=3D0=01108=3D50=0110=3D186=01
8=3DFIX.4.0=019=3D59=0135=3D0=0134=3D2=0149=3DSERVER=0152=3D20060713-11:3=
0:16=0156=3DCLIENT=01112=3D073016=0110=3D154=01
8=3DFIX.4.0=019=3D49=0135=3D0=0134=3D41=0149=3DSERVER=0152=3D20060713-12:=
02:47=0156=3DCLIENT=0110=3D205=01
8=3DFIX.4.0=019=3D58=0135=3D1=0134=3D42=0149=3DSERVER=0152=3D20060713-12:=
03:26=0156=3DCLIENT=01112=3DTEST=0110=3D223=01
8=3DFIX.4.0=019=3D61=0135=3DA=0134=3D43=0149=3DSERVER=0152=3D20060713-12:=
06:44=0156=3DCLIENT=0198=3D0=01108=3D50=0110=3D246=01
8=3DFIX.4.0=019=3D64=0135=3D2=0134=3D44=0149=3DSERVER=0152=3D20060713-12:=
06:44=0156=3DCLIENT=017=3D40=0116=3D999999=0110=3D164=01
8=3DFIX.4.0=019=3D88=0135=3D4=0134=3D41=0143=3DY=0149=3DSERVER=0152=3D200=
60713-12:06:44=0156=3DCLIENT=01122=3D20060713-12:06:44=0136=3D45=01123=3D=
Y=0110=3D072=01
8=3DFIX.4.0=019=3D49=0135=3D0=0134=3D45=0149=3DSERVER=0152=3D20060713-12:=
07:34=0156=3DCLIENT=0110=3D210=01
8=3DFIX.4.0=019=3D62=0135=3DA=0134=3D238=0149=3DSERVER=0152=3D20060713-14=
:49:49=0156=3DCLIENT=0198=3D0=01108=3D50=0110=3D059=01
8=3DFIX.4.0=019=3D61=0135=3D0=0134=3D239=0149=3DSERVER=0152=3D20060713-14=
:49:49=0156=3DCLIENT=01112=3D104949=0110=3D028=01
8=3DFIX.4.0=019=3D61=0135=3D0=0134=3D241=0149=3DSERVER=0152=3D20060713-14=
:50:50=0156=3DCLIENT=01112=3D105050=0110=3D245=01
8=3DFIX.4.0=019=3D61=0135=3D0=0134=3D242=0149=3DSERVER=0152=3D20060713-14=
:51:02=0156=3DCLIENT=01112=3D105101=0110=3D241=01

event_log
2006-07-13 11:30:05 | Created session
2006-07-13 11:30:16 | Received logon request
2006-07-13 11:30:16 | Responding to logon request
2006-07-13 12:03:26 | Sent test request TEST
2006-07-13 12:04:26 | Timed out waiting for heartbeat
2006-07-13 12:04:26 | Disconnecting
2006-07-13 12:06:44 | Received logon request
2006-07-13 12:06:44 | Responding to logon request
2006-07-13 12:06:44 | MsgSeqNum too high, expecting 40 but received 44
2006-07-13 12:06:44 | Sent ResendRequest FROM: 40 TO: 999999
2006-07-13 12:06:44 | Received ResendRequest FROM: 41 TO: 999999
2006-07-13 12:06:44 | Sent SequenceReset TO: 45
2006-07-13 12:06:44 | Received SequenceReset FROM: 40 TO: 45
2006-07-13 12:07:38 | MsgSeqNum too high, expecting 45 but received 46
2006-07-13 12:07:38 | Already sent ResendRequest FROM: 40 TO: 43.  Not =
sending another.
2006-07-13 12:08:29 | MsgSeqNum too high, expecting 45 but received 47
2006-07-13 12:08:29 | Already sent ResendRequest FROM: 40 TO: 43.  Not =
sending another.