[QFJ-902] Logon rejected even though within session time (java.io.IOException: Stream Closed) - QuickFIX/J Jira

Details

Type: Bug
Status: Closed
Priority: Major
Resolution: Fixed
Affects Version/s: 1.5.3
Fix Version/s: 2.0.0
Component/s: Engine
Labels:
None
Environment:

Hide
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

Show
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!

Logon rejected even though within session time (java.io.IOException: Stream Closed)

Details

Description

Attachments

Activity

People

Dates