[QFJ-843] Some times QuickFix Message received on Fix session is processed first by Application thread and later by socket connection Processor Thread causing sequence error by later processing Created: 04/May/15  Updated: 07/May/15

Status: Open
Project: QuickFIX/J
Component/s: Engine
Affects Version/s: 1.5.3
Fix Version/s: None

Type: Bug Priority: Default
Reporter: anurag jain Assignee: Unassigned
Resolution: Unresolved Votes: 0
Labels: sequnece, session


 Description   

Message on Fix session received by both Application thread (ProcessQ) and socket connection Processor Thread.
In below example Our Application Thread ProcessQ got the message with 34=158757 and later quickfix thread ScoketConnectionProcessor-0.0 Thread process the same message this happen only 4 time in a whole day.
But Due to this when quickfix's socketConnectionThread thread process the message and give it to QFJMessageProcessor thread to process further it encounters sequence rest error as a result session logged out triggers. In all the other scenarios ScoketConnectionProcessor process the message first and delegate the responsibility to QFJ Message Processor thread and later to application Thread i.e. ProcessQ

Please FInd application logs as below ..
2015-04-28 14:16:03,856 [ProcessQ] INFO quickfixj.msg.incoming - FIX.4.2:MDAQ_DEV2_SANDPIT_MD->ANZD_SANDPIT_MD: 8=FIX.4.2^A9=1500^A35=X^A34=158757^A49=ANZD_SANDPIT_MD^A52=20150428-06:16:03.814^A56=MDAQ_DEV2_SANDPIT_MD^A262=9^A268=26^A279=2^A269=0^A278=7usB0^A55=USD/CHF^A15=USD^A279=2^A269=1^A278=7usA0^A55=USD/CHF^A15=USD^A279=2^A269=0^A278=7usB1^A55=USD/CHF^A15=USD^A279=2^A269=1^A278=7usA1^A55=USD/CHF^A15=USD^A279=2^A269=0^A278=7usB2^A55=USD/CHF^A15=USD^A279=2^A269=1^A278=7usA2^A55=USD/CHF^A15=USD^A279=2^A269=0^A278=7usB3^A55=USD/CHF^A15=USD^A279=2^A269=1^A278=7usA3^A55=USD/CHF^A15=USD^A279=2^A269=0^A278=7usB4^A55=USD/CHF^A15=USD^A279=2^A269=1^A278=7usA4^A55=USD/CHF^A15=USD^A279=2^A269=0^A278=7usB5^A55=USD/CHF^A15=USD^A279=2^A269=1^A278=7usA5^A55=USD/CHF^A15=USD^A279=2^A269=0^A278=7usB6^A55=USD/CHF^A15=USD^A279=2^A269=1^A278=7usA6^A55=USD/CHF^A15=USD^A279=0^A269=0^A278=7utB0^A55=USD/CHF^A270=0.95388^A15=USD^A271=1000000^A346=1^A279=0^A269=1^A278=7utA0^A55=USD/CHF^A270=0.95413^A15=USD^A271=1000000^A346=1^A279=0^A269=0^A278=7utB1^A55=USD/CHF^A270=0.95385^A15=USD^A271=2000000^A346=1^A279=0^A269=1^A278=7utA1^A55=USD/CHF^A270=0.95416^A15=USD^A271=2000000^A346=1^A279=0^A269=0^A278=7utB2^A55=USD/CHF^A270=0.95382^A15=USD^A271=2000000^A346=1^A279=0^A269=1^A278=7utA2^A55=USD/CHF^A270=0.95419^A15=USD^A271=2000000^A346=1^A279=0^A269=0^A278=7utB3^A55=USD/CHF^A270=0.95380^A15=USD^A271=5000000^A346=1^A279=0^A269=1^A278=7utA3^A55=USD/CHF^A270=0.95421^A15=USD^A271=5000000^A346=1^A279=0^A269=0^A278=7utB4^A55=USD/CHF^A270=0.95377^A15=USD^A271=10000000^A346=1^A279=0^A269=1^A278=7utA4^A55=USD/CHF^A270=0.95424^A15=USD^A271=10000000^A346=1^A279=0^A269=0^A278=7utB5^A55=USD/CHF^A270=0.95374^A15=USD^A271=10000000^A346=1^A279=0^A269=1^A278=7utA5^A55=USD/CHF^A270=0.95427^A15=USD^A271=10000000^A346=1^A10=041^A
2015-04-28 14:16:03,856 [SocketConnectorIoProcessor-0.0] INFO quickfixj.msg.incoming - FIX.4.2:MDAQ_DEV2_SANDPIT_MD->ANZD_SANDPIT_MD: 8=FIX.4.2^A9=1500^A35=X^A34=158757^A49=ANZD_SANDPIT_MD^A52=20150428-06:16:03.814^A56=MDAQ_DEV2_SANDPIT_MD^A262=9^A268=26^A279=2^A269=0^A278=7usB0^A55=USD/CHF^A15=USD^A279=2^A269=1^A278=7usA0^A55=USD/CHF^A15=USD^A279=2^A269=0^A278=7usB1^A55=USD/CHF^A15=USD^A279=2^A269=1^A278=7usA1^A55=USD/CHF^A15=USD^A279=2^A269=0^A278=7usB2^A55=USD/CHF^A15=USD^A279=2^A269=1^A278=7usA2^A55=USD/CHF^A15=USD^A279=2^A269=0^A278=7usB3^A55=USD/CHF^A15=USD^A279=2^A269=1^A278=7usA3^A55=USD/CHF^A15=USD^A279=2^A269=0^A278=7usB4^A55=USD/CHF^A15=USD^A279=2^A269=1^A278=7usA4^A55=USD/CHF^A15=USD^A279=2^A269=0^A278=7usB5^A55=USD/CHF^A15=USD^A279=2^A269=1^A278=7usA5^A55=USD/CHF^A15=USD^A279=2^A269=0^A278=7usB6^A55=USD/CHF^A15=USD^A279=2^A269=1^A278=7usA6^A55=USD/CHF^A15=USD^A279=0^A269=0^A278=7utB0^A55=USD/CHF^A270=0.95388^A15=USD^A271=1000000^A346=1^A279=0^A269=1^A278=7utA0^A55=USD/CHF^A270=0.95413^A15=USD^A271=1000000^A346=1^A279=0^A269=0^A278=7utB1^A55=USD/CHF^A270=0.95385^A15=USD^A271=2000000^A346=1^A279=0^A269=1
^A278=7utA1^A55=USD/CHF^A270=0.95416^A15=USD^A271=2000000^A346=1^A279=0^A269=0^A278=7utB2^A55=USD/CHF^A270=0.95382^A15=USD^A271=2000000^A346=1^A279=0^A269=1^A278=7utA2^A55=USD/CHF^A270=0.95419^A15=USD^A271=2000000^A346=1^A279=0^A269=0^A278=7utB3^A55=USD/CHF^A270=0.95380^A15=USD^A271=5000000^A346=1^A279=0^A269=1^A278=7utA3^A55=USD/CHF^A270=0.95421^A15=USD^A271=5000000^A346=1^A279=0^A269=0^A278=7utB4^A55=USD/CHF^A270=0.95377^A15=USD^A271=10000000^A346=1^A279=0^A269=1^A278=7utA4^A55=USD/CHF^A270=0.95424^A15=USD^A271=10000000^A346=1^A279=0^A269=0^A278=7utB5^A55=USD/CHF^A270=0.95374^A15=USD^A271=10000000^A346=1^A279=0^A269=1^A278=7utA5^A55=USD/CHF^A270=0.95427^A15=USD^A271=10000000^A346=1^A10=041^A

 Comments   
Comment by anurag jain [ 04/May/15 ]

Please note that ProcessQ Thread is application thread which read objects from application Queue and not the the Quick Fix internal queue .

Comment by Christoph John [ 04/May/15 ]

When this happens, do you have to restart your application or does the problem correct itself? Are you starting/stopping your Initiator/Acceptor at certain times? This sounds a little like QFJ-825.
Would it be possible to create a stack dump with the program "jstack" once the error appears?

Comment by anurag jain [ 04/May/15 ]

Sorry rephrasing the above JIRA:

  • We noticed 2 threads logging the string --> "quickfixj.msg.incoming" at the same time. One of the threads to log this was SocketConnectorIoProcessor-0.0, Surprisingly the second thread which logs this is the ProcesQ thread
  • The ProcessQ thread is our own application thread so we are not sure how this could happen?
  • This does not seem to be a logging issue, we are using log4j2 as our logger. I say that because of the 2 consecutive messages received one after the other, Quickfix/J complains when the second message comes in: 
    2015-04-28 14:16:03,857 [QFJ Message Processor] INFO  quickfixj.msg.outgoing - FIX.4.2:MDAQ_DEV2_SANDPIT_MD->ANZD_SANDPIT_MD: 8=FIX.4.2^A9=141^A35=5^A34=11955^A49=MDAQ_DEV2_SANDPIT_MD^A52=20150428-06:16:03.857^A56=ANZD_SANDPIT_MD^A58=MsgSeqNum too low, expecting 158758 but received 158757^A10=030^A

All the log files below:

2015-04-28 14:16:03,856 [ProcessQ] INFO quickfixj.msg.incoming - FIX.4.2:MDAQ_DEV2_SANDPIT_MD->ANZD_SANDPIT_MD: 8=FIX.4.2^A9=1500^A35=X^A34=158757^A49=ANZD_SANDPIT_MD^A52=20150428-06:16:03.814^A56=MDAQ_DEV2_SANDPIT_MD^A262=9^A268=26^A279=2^A269=0^A278=7usB0^A55=USD/CHF^A15=USD^A279=2^A269=1^A278=7usA0^A55=USD/CHF^A15=USD^A279=2^A269=0^A278=7usB1^A55=USD/CHF^A15=USD^A279=2^A269=1^A278=7usA1^A55=USD/CHF^A15=USD^A279=2^A269=0^A278=7usB2^A55=USD/CHF^A15=USD^A279=2^A269=1^A278=7usA2^A55=USD/CHF^A15=USD^A279=2^A269=0^A278=7usB3^A55=USD/CHF^A15=USD^A279=2^A269=1^A278=7usA3^A55=USD/CHF^A15=USD^A279=2^A269=0^A278=7usB4^A55=USD/CHF^A15=USD^A279=2^A269=1^A278=7usA4^A55=USD/CHF^A15=USD^A279=2^A269=0^A278=7usB5^A55=USD/CHF^A15=USD^A279=2^A269=1^A278=7usA5^A55=USD/CHF^A15=USD^A279=2^A269=0^A278=7usB6^A55=USD/CHF^A15=USD^A279=2^A269=1^A278=7usA6^A55=USD/CHF^A15=USD^A279=0^A269=0^A278=7utB0^A55=USD/CHF^A270=0.95388^A15=USD^A271=1000000^A346=1^A279=0^A269=1^A278=7utA0^A55=USD/CHF^A270=0.95413^A15=USD^A271=1000000^A346=1^A279=0^A269=0^A278=7utB1^A55=USD/CHF^A270=0.95385^A15=USD^A271=2000000^A346=1^A279=0^A269=1^A278=7utA1^A55=USD/CHF^A270=0.95416^A15=USD^A271=2000000^A346=1^A279=0^A269=0^A278=7utB2^A55=USD/CHF^A270=0.95382^A15=USD^A271=2000000^A346=1^A279=0^A269=1^A278=7utA2^A55=USD/CHF^A270=0.95419^A15=USD^A271=2000000^A346=1^A279=0^A269=0^A278=7utB3^A55=USD/CHF^A270=0.95380^A15=USD^A271=5000000^A346=1^A279=0^A269=1^A278=7utA3^A55=USD/CHF^A270=0.95421^A15=USD^A271=5000000^A346=1^A279=0^A269=0^A278=7utB4^A55=USD/CHF^A270=0.95377^A15=USD^A271=10000000^A346=1^A279=0^A269=1^A278=7utA4^A55=USD/CHF^A270=0.95424^A15=USD^A271=10000000^A346=1^A279=0^A269=0^A278=7utB5^A55=USD/CHF^A270=0.95374^A15=USD^A271=10000000^A346=1^A279=0^A269=1^A278=7utA5^A55=USD/CHF^A270=0.95427^A15=USD^A271=10000000^A346=1^A10=041^A


2015-04-28 14:16:03,856 [SocketConnectorIoProcessor-0.0] INFO quickfixj.msg.incoming - FIX.4.2:MDAQ_DEV2_SANDPIT_MD->ANZD_SANDPIT_MD: 8=FIX.4.2^A9=1500^A35=X^A34=158757^A49=ANZD_SANDPIT_MD^A52=20150428-06:16:03.814^A56=MDAQ_DEV2_SANDPIT_MD^A262=9^A268=26^A279=2^A269=0^A278=7usB0^A55=USD/CHF^A15=USD^A279=2^A269=1^A278=7usA0^A55=USD/CHF^A15=USD^A279=2^A269=0^A278=7usB1^A55=USD/CHF^A15=USD^A279=2^A269=1^A278=7usA1^A55=USD/CHF^A15=USD^A279=2^A269=0^A278=7usB2^A55=USD/CHF^A15=USD^A279=2^A269=1^A278=7usA2^A55=USD/CHF^A15=USD^A279=2^A269=0^A278=7usB3^A55=USD/CHF^A15=USD^A279=2^A269=1^A278=7usA3^A55=USD/CHF^A15=USD^A279=2^A269=0^A278=7usB4^A55=USD/CHF^A15=USD^A279=2^A269=1^A278=7usA4^A55=USD/CHF^A15=USD^A279=2^A269=0^A278=7usB5^A55=USD/CHF^A15=USD^A279=2^A269=1^A278=7usA5^A55=USD/CHF^A15=USD^A279=2^A269=0^A278=7usB6^A55=USD/CHF^A15=USD^A279=2^A269=1^A278=7usA6^A55=USD/CHF^A15=USD^A279=0^A269=0^A278=7utB0^A55=USD/CHF^A270=0.95388^A15=USD^A271=1000000^A346=1^A279=0^A269=1^A278=7utA0^A55=USD/CHF^A270=0.95413^A15=USD^A271=1000000^A346=1^A279=0^A269=0^A278=7utB1^A55=USD/CHF^A270=0.95385^A15=USD^A271=2000000^A346=1^A279=0^A269=1
^A278=7utA1^A55=USD/CHF^A270=0.95416^A15=USD^A271=2000000^A346=1^A279=0^A269=0^A278=7utB2^A55=USD/CHF^A270=0.95382^A15=USD^A271=2000000^A346=1^A279=0^A269=1^A278=7utA2^A55=USD/CHF^A270=0.95419^A15=USD^A271=2000000^A346=1^A279=0^A269=0^A278=7utB3^A55=USD/CHF^A270=0.95380^A15=USD^A271=5000000^A346=1^A279=0^A269=1^A278=7utA3^A55=USD/CHF^A270=0.95421^A15=USD^A271=5000000^A346=1^A279=0^A269=0^A278=7utB4^A55=USD/CHF^A270=0.95377^A15=USD^A271=10000000^A346=1^A279=0^A269=1^A278=7utA4^A55=USD/CHF^A270=0.95424^A15=USD^A271=10000000^A346=1^A279=0^A269=0^A278=7utB5^A55=USD/CHF^A270=0.95374^A15=USD^A271=10000000^A346=1^A279=0^A269=1^A278=7utA5^A55=USD/CHF^A270=0.95427^A15=USD^A271=10000000^A346=1^A10=041^A

2015-04-28 14:16:03,857 [QFJ Message Processor] INFO  quickfixj.msg.outgoing - FIX.4.2:MDAQ_DEV2_SANDPIT_MD->ANZD_SANDPIT_MD: 8=FIX.4.2^A9=141^A35=5^A34=11955^A49=MDAQ_DEV2_SANDPIT_MD^A52=20150428-06:16:03.857^A56=ANZD_SANDPIT_MD^A58=MsgSeqNum too low, expecting 158758 but received 158757^A10=030^A

Could you please tell us:

  • If this is a bug in 1.5.3 version of Quickfix/J?
  • We only notice this happening 4 times a day during peak load, 2000 market data messages a second
  • We did not seem to encounter this in 1.5.2
Comment by Christoph John [ 05/May/15 ]

Could you please answer my questions from the last comment?
As already said, the only thing I could imagine is that you are hitting QFJ-825. But to be sure I would need a stack dump.
Are you able to try without log4j2? It's probably not the problem, but just to be sure... Are you using asynchronous logging?

Comment by anurag jain [ 06/May/15 ]

Please find my answer here:

  • No we are not stopping are starting Initiator/Acceptor at certain times.
  • Also When this happened, we didn't restart the application as mention above due to this we get the sequence error as a result of that log-out has sent to target session after a while it connect back again as part of login retry attempts.
  • This is not happening daily basis, we are trying to reproduce the problem at our end if succeeds we will share the JStack's stack dump with you. However No luck so far.
  • We are using synchronous logging also this is unlikely to have log4j2 issue as its result in sequence error.
Comment by Christoph John [ 06/May/15 ]

OK, without the stack dump I cannot really tell anything. Just let me know once you have it.
More questions: are you using a ThreadedSocketAcceptor/Initiator? Or the default SocketAcceptor/Initiator? is there only one session that you have configured? Could you please post your session config?

And I guess you are certain that the counterparty did not just send the same message twice?

Comment by anurag jain [ 07/May/15 ]

1) We are using default Socket Initiator.
2) Have just one session .
3) Session config is as here
DataDictionary=config/FIX42.xml
ResetOnLogon=Y
ScreenLogShowOutgoing=N
FileLogHeartbeats=N
ResetOnDisconnect=Y
ScreenLogEvents=N
ConnectionType=initiator
SocketKeyStore=config/SummitInvt.pem
TargetCompID=ANZD_SANDPIT_MD
SenderCompID=MDAQ_DEV2_SANDPIT_MD
SocketConnectHost=1.x.x.x
ReconnectInterval=10
ScreenLogShowIncoming=N
SocketConnectPort=xxxx
SocketUseSSL=Y
FileStorePath=var/fix/fxlp
PersistMessages=N
EndTime=17:00:00
SocketKeyStorePassword=*******
TimeZone=America/New_York
StartTime=17:10:00
HeartBtInt=20
UseDataDictionary=Y
ResetOnLogout=Y
Username=TODO
e-mail=
SessionID= FIX.4.2:MDAQ_DEV2_SANDPIT_MD->ANZD_SANDPIT_MD

4)and yes there is no replay of same message from counter party .

Comment by Christoph John [ 07/May/15 ]

Hmm, now that I see that you are using SSL I am asking myself if it could be the same problem as in QFJ-745. However, there is not really much information to find the problem and the issue creator did not come back with answers.

Generated at Tue Apr 30 22:08:35 UTC 2024 using JIRA 7.5.2#75007-sha1:9f5725bb824792b3230a5d8716f0c13e296a3cae.