WINXP

QFJ might not be ignoring the message. It's possible the message is corrupt and the engine incoming sequence number is not incremented. You don't mention whether you searched the application logs for any log messages related to message validation issues.

It's not likely to be a race condition for a couple of reasons. QFJ has been tested under high load without any message loss and messages for a specific session are processed in sequence.

This issue needs to be re-opened, as we are having the exact same problem.

Here is a snippet from the log that clearly demonstrates the issue:

<20110606-07:29:22, FIX.4.2:EKY2Z7N/BFHS/US,IL->CME/G, incoming> (8=FIX.4.2
9=240
35=b
34=1195
369=1197
52=20110606-07:29:22.819
49=CME
50=G
56=EKY2Z7N
57=BFHS
143=US,IL
58=Quote rejected: Not authorized to quote this instrument 'SenderComp EKY2Z7/ TraderID UNKNOWN for group ZE'
117=101
297=5
300=9
1028=Y
9772=0
9774=ZE
10=015
)
<20110606-07:29:22, FIX.4.2:EKY2Z7N/BFHS/US,IL->CME/G, incoming> (8=FIX.4.2
9=240
35=b
34=1196
369=1197
52=20110606-07:29:22.820
49=CME
50=G
56=EKY2Z7N
57=BFHS
143=US,IL
58=Quote rejected: Not authorized to quote this instrument 'SenderComp EKY2Z7/ TraderID UNKNOWN for group U$'
117=102
297=5
300=9
1028=Y
9772=0
9774=U$
10=189
)
<20110606-07:29:22, FIX.4.2:EKY2Z7N/BFHS/US,IL->CME/G, error> (MsgSeqNum too high, expecting 1195 but received 1196)
<20110606-07:29:22, FIX.4.2:EKY2Z7N/BFHS/US,IL->CME/G, outgoing> (8=FIX.4.2
9=91
35=2
34=1198
49=EKY2Z7N
50=BFHS
52=20110606-07:29:22.826
56=CME
57=G
142=US,IL
7=1195
16=0
10=092
)
<20110606-07:29:22, FIX.4.2:EKY2Z7N/BFHS/US,IL->CME/G, event> (Sent ResendRequest FROM: 1195 TO: 0)
<20110606-07:29:22, FIX.4.2:EKY2Z7N/BFHS/US,IL->CME/G, event> (Processing queued message: 1196)
<20110606-07:29:22, FIX.4.2:EKY2Z7N/BFHS/US,IL->CME/G, event> (ResendRequest for messages FROM 1195 TO 1195 has been satisfied.)
<20110606-07:29:22, FIX.4.2:EKY2Z7N/BFHS/US,IL->CME/G, incoming> (8=FIX.4.2
9=271
35=b
34=1195
369=1198
52=20110606-07:29:22.830
43=Y
49=CME
50=G
56=EKY2Z7N
57=BFHS
143=US,IL
122=20110606-07:29:22.819
58=Quote rejected: Not authorized to quote this instrument 'SenderComp EKY2Z7/ TraderID UNKNOWN for group ZE'
117=101
297=5
300=9
1028=Y
9772=0
9774=ZE
10=021
)
<20110606-07:29:22, FIX.4.2:EKY2Z7N/BFHS/US,IL->CME/G, incoming> (8=FIX.4.2
9=271
35=b
34=1196
369=1198
52=20110606-07:29:22.831
43=Y
49=CME
50=G
56=EKY2Z7N
57=BFHS
143=US,IL
122=20110606-07:29:22.820
58=Quote rejected: Not authorized to quote this instrument 'SenderComp EKY2Z7/ TraderID UNKNOWN for group U$'
117=102
297=5
300=9
1028=Y
9772=0
9774=U$
10=196
)

This snippet clearly shows that message 1196 came in before 1195, even though the log shows 1195 first. Here's what happens I believe:

1. 1195 comes in and is logged, not yet on received queue
2. 1196 comes in and is logged, and is put on received queue
3. 1195 is now put on received queue (almost a thread scheduling issue?, but there should only be a single thread...)
4. at this point 1196 is on received queue before 1195
5. consumer now gets 1196 before 1195, so generates an error (asking sender for 1195), and puts 1196 on pending queue
6. system then gets 1195 from received queue and says 'resend satisfied' even before the resend of message 1195 is received (and logged)
7. then reads the out of order 1196 from pending queue
8. the resend of 1195 is received and is ignored

We are using a SocketInitiator (which uses the SingleThreaded reader).

If it is not a bug, can you explain what we could possibly be doing in our code to cause this behavior? Or what we might try to diagnose the problem?

I think the block() method in the SingleThreadedEventHandlingStrategy needs to be synchronized. Otherwise if multiple threads call block(), you can process message out of order. For example:

Thread A is in block(), calls getMessage() - context switch
Thread B calls block(), which calls getMessage(), and calls processMessage()

The messages are now processed out of order. These context switches are more app to happen in a heavily stressed system, with lots of active threads (which is what the original reporter implies).

Now, I don't think an outside thread should be calling block(), but it is public an it appears that some library level housekeeping code does. Could it be a timer type operation that is causing the problems?

Why is block() even exposed? But you also have the same problem if two calls to blockInThread() are made, as there will be multiple reader threads, and that is a problem...

Synchronizing block() would fix both of these cases, and is simple, but I am not sure it is the cause of the problem, or the correct solution.

The block method is exposed because it's part of the original QuickFIX JNI API. Some users apparently process their messages in the thread that calls block.

A method being public doesn't imply it is thread safe and in this case it should never be called from multiple threads. The start method should also never be called from multiple threads. Do you think this is happening in your application?

As a simple check, look for multiple QFJ Message Processor threads. This would happen if start were called from multiple threads. You can also do a thread dump and look for multiple occurrences of threads with the block method in the stack trace.

If this is the problem, we could add a guard in the start method to throw an exception if it is called from multiple threads.

I have done just that and I see only a single processor thread - at least in standard usage. I am afraid there may be a case, whether our code, or in the library, where there is some timeout condition (that gets triggered under heavy stress), and multiple threads are created then. I've looked through our code, and can see no place where this could occur, but I'll admit that it is somewhat complex. The issue is that we never saw this with 1.3.0, only after upgrading to 1.5.0. I'm afraid it has something to do with session handling/identification and the new method in 1.3.1+ is a contributing factor.

Regardless, since the block() is really internal, I don't think there is any performance problem of making it synchronized (since there should only be a single thread in it anyway!), and it would guard against processing messages out of order in ANY case.