[QFJ-762] Message stores can become corrupted on acceptor/initiator shutdown Created: 09/Dec/13  Updated: 21/Apr/17

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

Type: Bug Priority: Default
Reporter: Alexey Ermakov Assignee: Unassigned
Resolution: Unresolved Votes: 1
Labels: None

Issue Links:
Relates
relates to QFJ-552 Message Stores expected to be thread ... Open
is related to QFJ-923 FileStore is leaking file handles Closed

 Description   

Since MessageStore implementations aren't thread safe, all operations on them should be performed from the session thread only. However, all 4 acceptor and initiator implementations perform shutdown (and thus call Session.unregisterSessions) in the calling thread. Since that calls MessageStore.close(), it can easily lead to store corruption if, for example, FileStore.close() gets called while the session thread is in the middle of persisting a Logout response.

 Comments   
Comment by Constantin Florescu [ 20/Apr/17 ]

The same issue could be reproduced when the logon request is timing out.

There are 2 threads trying to do the same thing:
16:18:28.763 [QFJ Timer] INFO quickfix.FileStore - initialize() called from.
at quickfix.FileStore.initialize(FileStore.java:111) [quickfixj-core-1.6.2.jar:1.6.2]
at quickfix.FileStore.reset(FileStore.java:465) [quickfixj-core-1.6.2.jar:1.6.2]
at quickfix.SessionState.reset(SessionState.java:382) [quickfixj-core-1.6.2.jar:1.6.2]
at quickfix.Session.resetState(Session.java:2503) [quickfixj-core-1.6.2.jar:1.6.2]
at quickfix.Session.disconnect(Session.java:1968) [quickfixj-core-1.6.2.jar:1.6.2]
at quickfix.Session.next(Session.java:1808) [quickfixj-core-1.6.2.jar:1.6.2]
at quickfix.mina.SessionConnector$SessionTimerTask.run(SessionConnector.java:278) [quickfixj-core-1.6.2.jar:1.6.2]

And from:
16:18:28.788 [QFJ Message Processor] INFO quickfix.FileStore - initialize() called from.
at quickfix.FileStore.initialize(FileStore.java:111) [quickfixj-core-1.6.2.jar:1.6.2]
at quickfix.FileStore.reset(FileStore.java:465) [quickfixj-core-1.6.2.jar:1.6.2]
at quickfix.SessionState.reset(SessionState.java:382) [quickfixj-core-1.6.2.jar:1.6.2]
at quickfix.Session.resetState(Session.java:2503) [quickfixj-core-1.6.2.jar:1.6.2]
at quickfix.Session.disconnect(Session.java:1968) [quickfixj-core-1.6.2.jar:1.6.2]
at quickfix.Session.next(Session.java:882) [quickfixj-core-1.6.2.jar:1.6.2]
at quickfix.Session.next(Session.java:1109) [quickfixj-core-1.6.2.jar:1.6.2]
at quickfix.mina.SingleThreadedEventHandlingStrategy$SessionMessageEvent.processMessage(SingleThreadedEventHandlingStrategy.java:144) [quickfixj-core-1.6.2.jar:1.6.2]
at quickfix.mina.SingleThreadedEventHandlingStrategy.block(SingleThreadedEventHandlingStrategy.java:91) [quickfixj-core-1.6.2.jar:1.6.2]
at quickfix.mina.SingleThreadedEventHandlingStrategy$1.run(SingleThreadedEventHandlingStrategy.java:125) [quickfixj-core-1.6.2.jar:1.6.2]

This causes unexpected behaviour and leaks File Descriptors.
Example:
ERROR [QFJ Timer] quickfix.SocketInitiator Error during timer processing
quickfix.RuntimeError: java.io.FileNotFoundException: [/..../Session].header (Too many open files)
at quickfix.SessionState.reset(SessionState.java:384) ~[quickfixj-core-1.6.2.jar:1.6.2]
at quickfix.Session.resetState(Session.java:2499) ~[quickfixj-core-1.6.2.jar:1.6.2]
at quickfix.Session.disconnect(Session.java:1967) ~[quickfixj-core-1.6.2.jar:1.6.2]
at quickfix.Session.next(Session.java:1808) ~[quickfixj-core-1.6.2.jar:1.6.2]
at quickfix.mina.SessionConnector$SessionTimerTask.run(SessionConnector.java:278) [quickfixj-core-1.6.2.jar:1.6.2]
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [?:1.8.0_74]
at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308) [?:1.8.0_74]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180) [?:1.8.0_74]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294) [?:1.8.0_74]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [?:1.8.0_74]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [?:1.8.0_74]
at java.lang.Thread.run(Thread.java:745) [?:1.8.0_74]
Caused by: java.io.FileNotFoundException: [/.../Session].header (Too many open files)
at java.io.FileOutputStream.open0(Native Method) ~[?:1.8.0_74]
at java.io.FileOutputStream.open(FileOutputStream.java:270) ~[?:1.8.0_74]
at java.io.FileOutputStream.<init>(FileOutputStream.java:213) ~[?:1.8.0_74]
at java.io.FileOutputStream.<init>(FileOutputStream.java:133) ~[?:1.8.0_74]
at quickfix.FileStore.initializeMessageIndex(FileStore.java:198) ~[quickfixj-core-1.6.2.jar:1.6.2]
at quickfix.FileStore.initializeCache(FileStore.java:121) ~[quickfixj-core-1.6.2.jar:1.6.2]
at quickfix.FileStore.initialize(FileStore.java:116) ~[quickfixj-core-1.6.2.jar:1.6.2]
at quickfix.FileStore.reset(FileStore.java:442) ~[quickfixj-core-1.6.2.jar:1.6.2]
at quickfix.SessionState.reset(SessionState.java:382) ~[quickfixj-core-1.6.2.jar:1.6.2]
... 11 more

Generated at Tue May 07 03:48:32 UTC 2024 using JIRA 7.5.2#75007-sha1:9f5725bb824792b3230a5d8716f0c13e296a3cae.