[Quickfixj-users] QFJ suddenly fails to connect, applications are blocked

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

We have a setup that restarts the sender and receiver FIX applications
every day. The applications communicate with each other on the same
machine, they are both written with quickfix/j and there are no external
connections allowed.
We had no problems with this setup until today.

All of a sudden, the connection can no longer be made over FIX. The error
seems to have started after an automated restart that happened on Saturday.

I have restarted the system multiple times today, but it's the same result.
We have multiple fix connections in the same applications, and the other
ones start, only this particular connection will not.

 - certificates are not expired
 - there is no other application connected to the same socket/ fix
connection
 - the compIds have not been modified.

 The application was working perfectly on Friday evening, and no-one
accessed the servers until today. Still, from Saturday, Dec 11, the
application can no longer connect, and the qfj log files do not get updated.

The application logs show the following exception:
12/13/21 12:08:30:605 EET] 0000014e FixMessageCli E [redacted]<init>
!!!---------!!! FAILED LOGON TO FIX SESSION ON SOCKET INITIATOR
                                 quickfix.ConfigError: error during session
initialization
        at
quickfix.mina.initiator.AbstractSocketInitiator.createSessions(AbstractSocketInitiator.java:198)
        at
quickfix.mina.initiator.AbstractSocketInitiator.createSessionInitiators(AbstractSocketInitiator.java:80)
        at quickfix.SocketInitiator.initialize(SocketInitiator.java:117)
        at quickfix.SocketInitiator.start(SocketInitiator.java:111)
       [redacted]
        at java.lang.Thread.run(Thread.java:812)
Caused by: java.lang.RuntimeException: java.io.EOFException
        at quickfix.FileStoreFactory.create(FileStoreFactory.java:82)
        at quickfix.Session.<init>(Session.java:503)
        at
quickfix.DefaultSessionFactory.create(DefaultSessionFactory.java:209)
        at
quickfix.mina.SessionConnector.createSession(SessionConnector.java:182)
        at
quickfix.mina.initiator.AbstractSocketInitiator.createSessions(AbstractSocketInitiator.java:191)
        ... 8 more
Caused by: java.io.EOFException
        at java.io.DataInputStream.readFully(DataInputStream.java:208)
        at java.io.DataInputStream.readInt(DataInputStream.java:398)
        at quickfix.FileStore.initializeMessageIndex(FileStore.java:181)
        at quickfix.FileStore.initializeCache(FileStore.java:117)
        at quickfix.FileStore.initialize(FileStore.java:112)
        at quickfix.FileStore.<init>(FileStore.java:96)
        at quickfix.FileStoreFactory.create(FileStoreFactory.java:80)
        ... 12 more

I've looked at the logs and stores created by qfj and I can't figure out
what the problem could be.

The logs stop on Dec 11:

Sender side:

event.log:

20211211-00:01:11: Initiated logon request
20211211-00:01:11: Received logon
20211211-00:01:11: MsgSeqNum too high, expecting 2 but received 4:
8=FIX.4.4^A9=79^A35=A^A34=4^A49=SENDER^A52=20211211-00:01:11.483^A56=RCVR^A98=0^A108=300^A10=093^A
20211211-00:01:11: Enqueued at pos 4:
8=FIX.4.4^A9=79^A35=A^A34=4^A49=SENDER^A52=20211211-00:01:11.483^A56=RCVR^A98=0^A108=300^A10=093^A
20211211-00:01:11: Sent ResendRequest FROM: 2 TO: 3
20211211-00:01:11: Enqueued at pos 5:
8=FIX.4.4^A9=75^A35=2^A34=5^A49=SENDER^A52=20211211-00:01:11.485^A56=RCVR^A7=1^A16=0^A10=127^A
20211211-00:01:11: Received ResendRequest FROM: 1 TO: infinity
20211211-00:01:11: Error processing message:
8=FIX.4.4^A9=75^A35=2^A34=5^A49=SENDER^A52=20211211-00:01:11.485^A56=RCVR^A7=1^A16=0^A10=127^A
java.io.EOFException
        at java.io.DataInputStream.readFully(DataInputStream.java:208)
        at java.io.DataInputStream.readInt(DataInputStream.java:398)
        at quickfix.FileStore.get(FileStore.java:316)
        at quickfix.SessionState.get(SessionState.java:302)
        at quickfix.Session.resendMessages(Session.java:2258)
        at quickfix.Session.manageGapFill(Session.java:1309)
        at quickfix.Session.nextResendRequest(Session.java:1275)
        at quickfix.Session.next(Session.java:1041)
        at quickfix.Session.next(Session.java:1204)
        at
quickfix.mina.SingleThreadedEventHandlingStrategy$SessionMessageEvent.processMessage(SingleThreadedEventHandlingStrategy.java:163)
        at
quickfix.mina.SingleThreadedEventHandlingStrategy.block(SingleThreadedEventHandlingStrategy.java:113)
        at
quickfix.mina.SingleThreadedEventHandlingStrategy.lambda$blockInThread$1(SingleThreadedEventHandlingStrategy.java:145)
        at
quickfix.mina.SingleThreadedEventHandlingStrategy$$Lambda$299.00000000BC19B9E0.run(Unknown
Source)
        at
quickfix.mina.SingleThreadedEventHandlingStrategy$ThreadAdapter$RunnableWrapper.run(SingleThreadedEventHandlingStrategy.java:267)
        at java.lang.Thread.run(Thread.java:812)

20211211-00:01:11: Received SequenceReset FROM: 2 TO: 6
20211211-00:06:12: ResendRequest for messages FROM 2 TO 3 has been
satisfied.
(END)

message.log (again, nothing after Dec 11):
8=FIX.4.4^A9=80^A35=A^A34=14^A49=RCVR^A52=20211211-00:01:01.479^A56=SENDER^A98=0^A108=300^A10=138^A
8=FIX.4.4^A9=79^A35=A^A34=1^A49=SENDER^A52=20211211-00:01:01.486^A56=RCVR^A98=0^A108=300^A10=092^A
8=FIX.4.4^A9=116^A35=5^A34=15^A49=RCVR^A52=20211211-00:01:01.497^A56=SENDER^A58=MsgSeqNum
too low, expecting 2 but received 1^A10=253^A
8=FIX.4.4^A9=80^A35=A^A34=16^A49=RCVR^A52=20211211-00:01:11.479^A56=SENDER^A98=0^A108=300^A10=141^A
8=FIX.4.4^A9=79^A35=A^A34=4^A49=SENDER^A52=20211211-00:01:11.483^A56=RCVR^A98=0^A108=300^A10=093^A
8=FIX.4.4^A9=75^A35=2^A34=5^A49=SENDER^A52=20211211-00:01:11.485^A56=RCVR^A7=1^A16=0^A10=127^A
8=FIX.4.4^A9=76^A35=2^A34=17^A49=RCVR^A52=20211211-00:01:11.505^A56=SENDER^A7=2^A16=0^A10=173^A
8=FIX.4.4^A9=108^A35=4^A34=2^A43=Y^A49=SENDER^A52=20211211-00:01:11.532^A56=RCVR^A122=20211211-00:01:11.520^A36=6^A123=Y^A10=023^A
8=FIX.4.4^A9=66^A35=0^A34=6^A49=SENDER^A52=20211211-00:06:12.402^A56=RCVR^A10=254^A
8=FIX.4.4^A9=67^A35=0^A34=18^A49=RCVR^A52=20211211-00:06:12.418^A56=SENDER^A10=057^A
...continues until
8=FIX.4.4^A9=67^A35=0^A34=17^A49=SENDER^A52=20211211-01:01:12.403^A56=RCVR^A10=046^A
8=FIX.4.4^A9=67^A35=0^A34=29^A49=RCVR^A52=20211211-01:01:12.480^A56=SENDER^A10=054^A

The sequence numbers in the sender side correspond to the last messages in
the log:
cat FIX.4.4-RCVR-SENDER.senderseqnums
30
cat FIX.4.4-RCVR-SENDER.targetseqnums
18

While on the other side, the corresponding files are empty:
cat FIX.4.4-SENDER-RCVR.targetseqnums
cat FIX.4.4-SENDER-RCVR.senderseqnums

But in the events.log for the other side, I have information being written
even after Dec 11:

20211211-00:01:01: Received logon
20211211-00:01:01: Responding to Logon request
20211211-00:01:01: MsgSeqNum too high, expecting 1 but received 14:
8=FIX.4.4^A9=80^A35=A^A34=14^A49=RCVR^A52=20211211-00:01:01.479^A56=SENDER^A98=0^A108=300^A10
=138^A
20211211-00:01:01: Enqueued at pos 14:
8=FIX.4.4^A9=80^A35=A^A34=14^A49=RCVR^A52=20211211-00:01:01.479^A56=SENDER^A98=0^A108=300^A10=138^A
20211211-00:01:01: Sent ResendRequest FROM: 1 TO: 13
20211211-00:01:01: Received logout request: MsgSeqNum too low, expecting 2
but received 1
20211211-00:01:01: Sent logout response
20211211-00:01:01: Disconnecting: Received logout request: MsgSeqNum too
low, expecting 2 but received 1
20211211-00:01:11: Accepting session FIX.4.4:SENDER->RCVR from /
127.0.0.1:44844
20211211-00:01:11: Acceptor heartbeat set to 300 seconds
20211211-00:01:11: Received logon
20211211-00:01:11: Responding to Logon request
20211211-00:01:11: MsgSeqNum too high, expecting 1 but received 16:
8=FIX.4.4^A9=80^A35=A^A34=16^A49=RCVR^A52=20211211-00:01:11.479^A56=SENDER^A98=0^A108=300^A10
=141^A
20211211-00:01:11: Enqueued at pos 16:
8=FIX.4.4^A9=80^A35=A^A34=16^A49=RCVR^A52=20211211-00:01:11.479^A56=SENDER^A98=0^A108=300^A10=141^A
20211211-00:01:11: Sent ResendRequest FROM: 1 TO: 15
20211211-00:01:11: Enqueued at pos 17:
8=FIX.4.4^A9=76^A35=2^A34=17^A49=RCVR^A52=20211211-00:01:11.505^A56=SENDER^A7=2^A16=0^A10=173^A
20211211-00:01:11: Received ResendRequest FROM: 2 TO: infinity
20211211-00:01:11: Sent SequenceReset TO: 6
20211211-00:06:12: MsgSeqNum too high, expecting 1 but received 18:
8=FIX.4.4^A9=67^A35=0^A34=18^A49=RCVR^A52=20211211-00:06:12.418^A56=SENDER^A10=057^A
20211211-00:06:12: Enqueued at pos 18:
8=FIX.4.4^A9=67^A35=0^A34=18^A49=RCVR^A52=20211211-00:06:12.418^A56=SENDER^A10=057^A
20211211-00:06:12: Already sent ResendRequest FROM: 1 TO: 15.  Not sending
another.
20211211-00:11:12: MsgSeqNum too high, expecting 1 but received 19:
8=FIX.4.4^A9=67^A35=0^A34=19^A49=RCVR^A52=20211211-00:11:12.414^A56=SENDER^A10=050^A
20211211-00:11:12: Enqueued at pos 19:
8=FIX.4.4^A9=67^A35=0^A34=19^A49=RCVR^A52=20211211-00:11:12.414^A56=SENDER^A10=050^A
20211211-00:11:12: Already sent ResendRequest FROM: 1 TO: 15.  Not sending
another.
20211211-00:16:12: MsgSeqNum too high, expecting 1 but received 20:
8=FIX.4.4^A9=67^A35=0^A34=20^A49=RCVR^A52=20211211-00:16:12.439^A56=SENDER^A10=054^A
20211211-00:16:12: Enqueued at pos 20:
8=FIX.4.4^A9=67^A35=0^A34=20^A49=RCVR^A52=20211211-00:16:12.439^A56=SENDER^A10=054^A
20211211-00:16:12: Already sent ResendRequest FROM: 1 TO: 15.  Not sending
another.
20211211-00:21:12: MsgSeqNum too high, expecting 1 but received 21:
8=FIX.4.4^A9=67^A35=0^A34=21^A49=RCVR^A52=20211211-00:21:12.480^A56=SENDER^A10=047^A
20211211-00:21:12: Enqueued at pos 21:
8=FIX.4.4^A9=67^A35=0^A34=21^A49=RCVR^A52=20211211-00:21:12.480^A56=SENDER^A10=047^A
20211211-00:21:12: Already sent ResendRequest FROM: 1 TO: 15.  Not sending
another.
20211211-00:26:12: MsgSeqNum too high, expecting 1 but received 22:
8=FIX.4.4^A9=67^A35=0^A34=22^A49=RCVR^A52=20211211-00:26:12.480^A56=SENDER^A10=053^A
20211211-00:26:12: Enqueued at pos 22:
8=FIX.4.4^A9=67^A35=0^A34=22^A49=RCVR^A52=20211211-00:26:12.480^A56=SENDER^A10=053^A
20211211-00:26:12: Already sent ResendRequest FROM: 1 TO: 15.  Not sending
another.
20211211-00:31:12: MsgSeqNum too high, expecting 1 but received 23:
8=FIX.4.4^A9=67^A35=0^A34=23^A49=RCVR^A52=20211211-00:31:12.480^A56=SENDER^A10=050^A
20211211-00:31:12: Enqueued at pos 23:
8=FIX.4.4^A9=67^A35=0^A34=23^A49=RCVR^A52=20211211-00:31:12.480^A56=SENDER^A10=050^A
20211211-00:31:12: Already sent ResendRequest FROM: 1 TO: 15.  Not sending
another.
20211211-00:36:12: MsgSeqNum too high, expecting 1 but received 24:
8=FIX.4.4^A9=67^A35=0^A34=24^A49=RCVR^A52=20211211-00:36:12.480^A56=SENDER^A10=056^A
20211211-00:36:12: Enqueued at pos 24:
8=FIX.4.4^A9=67^A35=0^A34=24^A49=RCVR^A52=20211211-00:36:12.480^A56=SENDER^A10=056^A
20211211-00:36:12: Already sent ResendRequest FROM: 1 TO: 15.  Not sending
another.
20211211-00:41:12: MsgSeqNum too high, expecting 1 but received 25:
8=FIX.4.4^A9=67^A35=0^A34=25^A49=RCVR^A52=20211211-00:41:12.480^A56=SENDER^A10=053^A
20211211-00:41:12: Enqueued at pos 25:
8=FIX.4.4^A9=67^A35=0^A34=25^A49=RCVR^A52=20211211-00:41:12.480^A56=SENDER^A10=053^A
20211211-00:41:12: Already sent ResendRequest FROM: 1 TO: 15.  Not sending
another.
20211211-00:46:12: MsgSeqNum too high, expecting 1 but received 26:
8=FIX.4.4^A9=67^A35=0^A34=26^A49=RCVR^A52=20211211-00:46:12.480^A56=SENDER^A10=059^A
20211211-00:46:12: Enqueued at pos 26:
8=FIX.4.4^A9=67^A35=0^A34=26^A49=RCVR^A52=20211211-00:46:12.480^A56=SENDER^A10=059^A
20211211-00:46:12: Already sent ResendRequest FROM: 1 TO: 15.  Not sending
another.
20211211-00:51:12: MsgSeqNum too high, expecting 1 but received 27:
8=FIX.4.4^A9=67^A35=0^A34=27^A49=RCVR^A52=20211211-00:51:12.480^A56=SENDER^A10=056^A
20211211-00:51:12: Enqueued at pos 27:
8=FIX.4.4^A9=67^A35=0^A34=27^A49=RCVR^A52=20211211-00:51:12.480^A56=SENDER^A10=056^A
20211211-00:51:12: Already sent ResendRequest FROM: 1 TO: 15.  Not sending
another.
20211211-00:56:12: MsgSeqNum too high, expecting 1 but received 28:
8=FIX.4.4^A9=67^A35=0^A34=28^A49=RCVR^A52=20211211-00:56:12.480^A56=SENDER^A10=062^A
20211211-00:56:12: Enqueued at pos 28:
8=FIX.4.4^A9=67^A35=0^A34=28^A49=RCVR^A52=20211211-00:56:12.480^A56=SENDER^A10=062^A
20211211-00:56:12: Already sent ResendRequest FROM: 1 TO: 15.  Not sending
another.
20211211-01:01:12: MsgSeqNum too high, expecting 1 but received 29:
8=FIX.4.4^A9=67^A35=0^A34=29^A49=RCVR^A52=20211211-01:01:12.480^A56=SENDER^A10=054^A
20211211-01:01:12: Enqueued at pos 29:
8=FIX.4.4^A9=67^A35=0^A34=29^A49=RCVR^A52=20211211-01:01:12.480^A56=SENDER^A10=054^A
20211211-01:01:12: Already sent ResendRequest FROM: 1 TO: 15.  Not sending
another.
20211211-01:01:33: Disconnecting: Encountered END_OF_STREAM
20211211-01:03:34: Session FIX.4.4:SENDER->RCVR schedule is daily,
00:01:00-UTC - 00:00:00-UTC
20211211-01:03:34: Created session: FIX.4.4:SENDER->RCVR
20211211-01:03:34: Valid order types: [1, 2, 3, 4, K]
20211212-00:01:00: Session state is not current; resetting
FIX.4.4:SENDER->RCVR
20211212-01:02:31: Session FIX.4.4:SENDER->RCVR schedule is daily,
00:01:00-UTC - 00:00:00-UTC
20211212-01:02:31: Created session: FIX.4.4:SENDER->RCVR
20211212-01:02:31: Valid order types: [1, 2, 3, 4, K]
20211213-00:01:00: Session state is not current; resetting
FIX.4.4:SENDER->RCVR
20211213-01:02:33: Session FIX.4.4:SENDER->RCVR schedule is daily,
00:01:00-UTC - 00:00:00-UTC
20211213-01:02:33: Created session: FIX.4.4:SENDER->RCVR
20211213-01:02:33: Valid order types: [1, 2, 3, 4, K]
20211213-07:33:33: Session FIX.4.4:SENDER->RCVR schedule is daily,
00:01:00-UTC - 00:00:00-UTC
20211213-07:33:33: Created session: FIX.4.4:SENDER->RCVR
20211213-07:33:33: Valid order types: [1, 2, 3, 4, K]
20211213-10:06:17: Session FIX.4.4:SENDER->RCVR schedule is daily,
00:01:00-UTC - 00:00:00-UTC
20211213-10:06:17: Created session: FIX.4.4:SENDER->RCVR
20211213-10:06:17: Valid order types: [1, 2, 3, 4, K]

I would appreciate any insight on this matter, as well as any solution that
would result in the application starting.

I considered deleting all logs & stores generated by QFJ, but that would
result in a loss of data, and if possible I'd like to avoid that.

Is there any solution you can see?

Thank you!