[QFJ-902] Logon rejected even though within session time (java.io.IOException: Stream Closed) Created: 06/Sep/16  Updated: 22/Nov/17  Resolved: 23/Oct/17

Status: Closed
Project: QuickFIX/J
Component/s: Engine
Affects Version/s: 1.5.3
Fix Version/s: 2.0.0

Type: Bug Priority: Major
Reporter: anurag jain Assignee: Christoph John
Resolution: Fixed Votes: 3
Labels: None
Environment:

Software:
java version "1.8.0_74"
Java(TM) SE Runtime Environment (build 1.8.0_74-b02)
Java HotSpot(TM) 64-Bit Server VM (build 25.74-b02, mixed mode)

Operating System:
Linux earth 2.6.32-358.el6.x86_64 #1 SMP Tue Jan 29 11:47:41 EST 2013 x86_64 x86_64 x86_64 GNU/Linux


 Description   

From time to time we have seen certain fix connection can not login even though within the session times. Please see logs below:

[Session1 details]

2016-09-02 06:03:02,607 [main] INFO  quickfix.SessionSchedule - [FIX.4.4-MDAQOM_session1-session1_MDAQOM] daily, 23:00:00-UTC - 10:00:00-UTC
2016-09-02 06:03:02,607 [main] INFO  quickfixj.event - FIX.4.4-MDAQOM_session1-session1_MDAQOM: Session FIX.4.4-MDAQOM_session1-session1_MDAQOM schedule is daily, 23:00:00-UTC - 10:00:00-UTC
2016-09-02 06:03:02,607 [main] INFO  quickfixj.event - FIX.4.4-MDAQOM_session1-session1_MDAQOM: Session state is not current; resetting FIX.4.4-MDAQOM_session1-session1_MDAQOM
2016-09-02 06:03:02,607 [main] INFO  quickfixj.event - FIX.4.4-MDAQOM_session1-session1_MDAQOM: Created session: FIX.4.4-MDAQOM_session1-session1_MDAQOM

[Session connects before allowed time of 7am Singapore time. First exception noticed]

2016-09-02 06:17:21,636 [QFJ Message Processor] ERROR quickfixj.errorEvent - FIX.4.4-MDAQOM_session1-session1_MDAQOM: Error Reading/Writing in MessageStore
java.io.IOException: Stream Closed
        at java.io.FileOutputStream.writeBytes(Native Method)
        at java.io.FileOutputStream.write(FileOutputStream.java:326)
        at java.io.BufferedOutputStream.flushBuffer(BufferedOutputStream.java:82)
        at java.io.BufferedOutputStream.flush(BufferedOutputStream.java:140)
        at java.io.DataOutputStream.flush(DataOutputStream.java:123)
        at quickfix.FileStore.set(FileStore.java:430)
        at quickfix.SessionState.set(SessionState.java:310)
        at quickfix.Session.sendRaw(Session.java:2433)
        at quickfix.Session.generateLogout(Session.java:1339)
        at quickfix.Session.generateLogout(Session.java:1309)
        at quickfix.Session.next(Session.java:1036)
        at quickfix.mina.SingleThreadedEventHandlingStrategy$SessionMessageEvent.processMessage(SingleThreadedEventHandlingStrategy.java:114)
        at quickfix.mina.SingleThreadedEventHandlingStrategy.block(SingleThreadedEventHandlingStrategy.java:77)
        at quickfix.mina.SingleThreadedEventHandlingStrategy$1.run(SingleThreadedEventHandlingStrategy.java:94)
        at java.lang.Thread.run(Thread.java:745)

2016-09-02 06:17:21,636 [QFJ Message Processor] WARN  quickfixj.errorEvent - FIX.4.4-MDAQOM_session1-session1_MDAQOM: Disconnecting: Logon rejected: quickfix.RejectLogon: Logon attempt not within session time

[Logon happened again this time the stack trace looked like this]

2016-09-02 06:17:26,635 [QFJ Message Processor] ERROR quickfixj.errorEvent - FIX.4.4-MDAQOM_session1-session1_MDAQOM: Error Reading/Writing in MessageStore
java.io.IOException: Stream Closed
        at java.io.FileOutputStream.writeBytes(Native Method)
        at java.io.FileOutputStream.write(FileOutputStream.java:326)
        at java.io.BufferedOutputStream.flushBuffer(BufferedOutputStream.java:82)
        at java.io.BufferedOutputStream.flush(BufferedOutputStream.java:140)
        at java.io.DataOutputStream.flush(DataOutputStream.java:123)
        at quickfix.FileStore.set(FileStore.java:430)
        at quickfix.SessionState.set(SessionState.java:310)
        at quickfix.Session.sendRaw(Session.java:2433)
        at quickfix.Session.generateLogout(Session.java:1339)
        at quickfix.Session.generateLogout(Session.java:1309)
        at quickfix.Session.next(Session.java:1036)
        at quickfix.mina.SingleThreadedEventHandlingStrategy$SessionMessageEvent.processMessage(SingleThreadedEventHandlingStrategy.java:114)
        at quickfix.mina.SingleThreadedEventHandlingStrategy.block(SingleThreadedEventHandlingStrategy.java:77)
        at quickfix.mina.SingleThreadedEventHandlingStrategy$1.run(SingleThreadedEventHandlingStrategy.java:94)
        at java.lang.Thread.run(Thread.java:745)

2016-09-02 06:17:26,635 [QFJ Message Processor] ERROR quickfixj.errorEvent - FIX.4.4-MDAQOM_session1-session1_MDAQOM: Stream Closed
java.io.IOException: Stream Closed
        at java.io.RandomAccessFile.seek0(Native Method)
        at java.io.RandomAccessFile.seek(RandomAccessFile.java:557)
        at quickfix.FileStore.storeSequenceNumbers(FileStore.java:439)
        at quickfix.FileStore.incrNextTargetMsgSeqNum(FileStore.java:333)
        at quickfix.SessionState.incrNextTargetMsgSeqNum(SessionState.java:370)
        at quickfix.Session.next(Session.java:1039)
        at quickfix.mina.SingleThreadedEventHandlingStrategy$SessionMessageEvent.processMessage(SingleThreadedEventHandlingStrategy.java:114)
        at quickfix.mina.SingleThreadedEventHandlingStrategy.block(SingleThreadedEventHandlingStrategy.java:77)
        at quickfix.mina.SingleThreadedEventHandlingStrategy$1.run(SingleThreadedEventHandlingStrategy.java:94)
        at java.lang.Thread.run(Thread.java:745)

2016-09-02 06:17:26,635 [QFJ Timer] ERROR quickfix.SocketAcceptor - Error during timer processing
quickfix.RuntimeError: java.io.IOException: Stream Closed
        at quickfix.SessionState.reset(SessionState.java:381)
        at quickfix.Session.resetState(Session.java:2451)
        at quickfix.Session.reset(Session.java:814)
        at quickfix.Session.next(Session.java:1749)
        at quickfix.mina.SessionConnector$SessionTimerTask.run(SessionConnector.java:283)
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
        at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308)
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180)
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
        at java.lang.Thread.run(Thread.java:745)
Caused by: java.io.IOException: Stream Closed
        at java.io.FileOutputStream.writeBytes(Native Method)
        at java.io.FileOutputStream.write(FileOutputStream.java:326)
        at java.io.BufferedOutputStream.flushBuffer(BufferedOutputStream.java:82)
        at java.io.BufferedOutputStream.flush(BufferedOutputStream.java:140)
        at java.io.DataOutputStream.flush(DataOutputStream.java:123)
        at java.io.FilterOutputStream.close(FilterOutputStream.java:158)
        at quickfix.FileStore.closeOutputStream(FileStore.java:258)
        at quickfix.FileStore.close(FileStore.java:243)
        at quickfix.FileStore.deleteFiles(FileStore.java:263)
        at quickfix.FileStore.initialize(FileStore.java:107)
        at quickfix.FileStore.reset(FileStore.java:481)
        at quickfix.SessionState.reset(SessionState.java:379)
        ... 11 more

[Finally logon within the session time, even then the session could not connect]

2016-09-02 07:00:00,760 [SocketAcceptorIoProcessor-2.0] INFO  quickfixj.msg.incoming - FIX.4.4-MDAQOM_session1-session1_MDAQOM: 8=FIX.4.4^A9=169^A35=A^A34=1^A49=session1_MDAQOM^A52=20160901-23:00:00.820^A56=MDAQOM_session1^A98=0^A108=30^A141=Y^A553=session1^A554=<masked>^A10=028^A
2016-09-02 07:00:00,760 [SocketAcceptorIoProcessor-2.0] INFO  quickfixj.event - FIX.4.4-MDAQOM_session1-session1_MDAQOM: Accepting session FIX.4.4-MDAQOM_session1-session1_MDAQOM from /192.168.10.16:60121
2016-09-02 07:00:00,760 [SocketAcceptorIoProcessor-2.0] INFO  quickfixj.event - FIX.4.4-MDAQOM_session1-session1_MDAQOM: Acceptor heartbeat set to 30 seconds
2016-09-02 07:00:00,760 [QFJ Message Processor] WARN  quickfixj.errorEvent - FIX.4.4-MDAQOM_session1-session1_MDAQOM: Logon rejected: quickfix.RejectLogon: Logon attempt not within session time
2016-09-02 07:00:00,760 [QFJ Message Processor] INFO  quickfixj.msg.outgoing - FIX.4.4-MDAQOM_session1-session1_MDAQOM: 8=FIX.4.4^A9=108^A35=5^A34=1^A49=MDAQOM_session1^A52=20160901-23:00:00.760^A56=session1_MDAQOM^A58=Logon attempt not within session time^A10=071^A
2016-09-02 07:00:00,760 [QFJ Message Processor] ERROR quickfixj.errorEvent - FIX.4.4-MDAQOM_session1-session1_MDAQOM: Error Reading/Writing in MessageStore
java.io.IOException: Stream Closed
        at java.io.RandomAccessFile.getFilePointer(Native Method)
        at quickfix.FileStore.set(FileStore.java:422)
        at quickfix.SessionState.set(SessionState.java:310)
        at quickfix.Session.sendRaw(Session.java:2433)
        at quickfix.Session.generateLogout(Session.java:1339)
        at quickfix.Session.generateLogout(Session.java:1309)
        at quickfix.Session.next(Session.java:1036)
        at quickfix.mina.SingleThreadedEventHandlingStrategy$SessionMessageEvent.processMessage(SingleThreadedEventHandlingStrategy.java:114)
        at quickfix.mina.SingleThreadedEventHandlingStrategy.block(SingleThreadedEventHandlingStrategy.java:77)
        at quickfix.mina.SingleThreadedEventHandlingStrategy$1.run(SingleThreadedEventHandlingStrategy.java:94)
        at java.lang.Thread.run(Thread.java:745)

2016-09-02 07:00:00,760 [QFJ Message Processor] ERROR quickfixj.errorEvent - FIX.4.4-MDAQOM_session1-session1_MDAQOM: Stream Closed
java.io.IOException: Stream Closed
        at java.io.RandomAccessFile.seek0(Native Method)
        at java.io.RandomAccessFile.seek(RandomAccessFile.java:557)
        at quickfix.FileStore.storeSequenceNumbers(FileStore.java:439)
        at quickfix.FileStore.incrNextTargetMsgSeqNum(FileStore.java:333)
        at quickfix.SessionState.incrNextTargetMsgSeqNum(SessionState.java:370)
        at quickfix.Session.next(Session.java:1039)
        at quickfix.mina.SingleThreadedEventHandlingStrategy$SessionMessageEvent.processMessage(SingleThreadedEventHandlingStrategy.java:114)
        at quickfix.mina.SingleThreadedEventHandlingStrategy.block(SingleThreadedEventHandlingStrategy.java:77)
        at quickfix.mina.SingleThreadedEventHandlingStrategy$1.run(SingleThreadedEventHandlingStrategy.java:94)
        at java.lang.Thread.run(Thread.java:745)

This happens endlessly. Finally we had to bounce to fix this. This has happened more frequently as we have on-boarded more users

Questions:

  • Please tell us what is causing the issue
  • Why does the stream closed issue happen so often?
  • Is this issue fixed in a later version?
  • Any workarounds ?

This is quite a critical item for us so would appreciate the turnaround, thanks!

 Comments   
Comment by anurag jain [ 06/Sep/16 ]

What I found out is the following:

  • The timer thread tries to reset the state if the session is outside the time. Resetting the state means the store underneath, in this case the FileStore, is deleting the files and creating new persistence files
  • At the same time a client logs in this is the QFJ Message Processor thread. This logon is also rejected as it is outside the session time. We try to increment the targetSequenceNumber when we try to send the logout
  • These two threads create a race on how they are accessing the persistence files, hence might corrupt the file?
  • Also the checkSessionTime will start failing as FileStore throws an exception and never manages to reset the creation time as a consequence

Has this been fixed already in 1.6.x?

Comment by Christoph John [ 06/Sep/16 ]

Hi,
what I can say off the top of my head is that QFJ-773 corrected the issue where the message store is reinitialised every second. This is fixed in 1.6.0. I would suggest to use QFJ 1.6.2 if you upgrade.
If you have further points then please write to the mailing list as suggested.
Thanks,
Chris.

Comment by anurag jain [ 08/Sep/16 ]

Hi Christoph, thanks a lot for getting back. I think this patch might not fix the issue that I am seeing.

There are two threads:

  • Timer Thread. The fix is to reset if the sequence numbers are > 1
  • Message Processor Thread. But in the case where a client logs in outside the session time, there can be a case where we reject the logon and send a logout. This increments the target sequence number

There can still be a race between Timer Thread and MessageProcessor thread

  • Client logins outside session time logout generated, targetSeqNum is 1
  • The timer thread tries to reset at time T
  • Client logins outside session time again and logout generated. Try to increment the targetSeqNum to 2 now at same time T
  • Now both these threads are touching the MessageStore. In case of a FileStore there can be a corruption still

I do not think this issue has been addressed even in 1.6.2

Comment by anurag jain [ 13/Sep/16 ]

Sorry can someone confirm the above please?

Comment by Christoph John [ 15/Sep/16 ]

Confirmed.

Comment by anurag jain [ 20/Sep/16 ]

Christoph could you recommend a good way to fix this? Or any workaround for now

Comment by Christoph John [ 20/Sep/16 ]

I cannot think of a workaround inside of QFJ at the moment. The only possibility I see is to prevent connections from outside during non-session time or do not start the service on your side. But I don't know how the infrastructure on your side supports this kind of workaround. E.g. you could start your processes by cron job at a later time.

IMHO the fix would be to not increment the sequence numbers outside of the session time window since it is useless. The seqnums would get reset once the session is inside the session time window anyway.
When the next connection attempt comes in and the counterparty comes in with too high a sequence number then the resend processing will take place.

Comment by anurag jain [ 21/Sep/16 ]

I agree. Do we just disconnect the counterparty outside the session window then? Currently we are sending a logout to them, I think we might have to stop sending any logouts and just disconnenct

Comment by anurag jain [ 21/Sep/16 ]

Is this going to be fixed in quickfix/j ? Any ETA would be appreciated thanks!

Comment by Christoph John [ 21/Sep/16 ]

Why do you think we should not send the counterparty a Logout? I would propose to send a Logout but always with seqnum 1. This is how it is done already implemented when being outside of the session time window. The only thing that would change is that we do not increment the seqnums internally. The incrementation is now being done but the seqnums are reset each second anyway. So no externally visible change there.

The session time feature is AFAIK not described in the official FIX spec so one cannot really lookup a best practice on what to do when a Logon outside of the session time is received. It is only stated that "if sending a Logout does not create risk or violate security, a Logout message should be sent with a descriptive text message."

I cannot give you an ETA on when this would be fixed. This is an open source project and this issue is not really critical. So you have the following options:

Cheers,
Chris.

Comment by Christoph John [ 23/Oct/17 ]

Fixed with https://github.com/quickfix-j/quickfixj/pull/146 by https://github.com/alexwibowo

Generated at Sat Nov 23 08:54:00 UTC 2024 using JIRA 7.5.2#75007-sha1:9f5725bb824792b3230a5d8716f0c13e296a3cae.