From db07b40f19ed6e73182ba49effed490caca2663c Mon Sep 17 00:00:00 2001 From: Christoph John Date: Thu, 17 Dec 2020 14:08:01 +0100 Subject: [PATCH 01/41] - added logging to analyze flaky test --- .../java/quickfix/test/acceptance/timer/TimerTestClient.java | 4 ++-- .../java/quickfix/test/acceptance/timer/TimerTestServer.java | 4 ++-- 2 files changed, 4 insertions(+), 4 deletions(-) diff --git a/quickfixj-core/src/test/java/quickfix/test/acceptance/timer/TimerTestClient.java b/quickfixj-core/src/test/java/quickfix/test/acceptance/timer/TimerTestClient.java index 55765bcd83..14a3b583cd 100644 --- a/quickfixj-core/src/test/java/quickfix/test/acceptance/timer/TimerTestClient.java +++ b/quickfixj-core/src/test/java/quickfix/test/acceptance/timer/TimerTestClient.java @@ -36,7 +36,6 @@ import quickfix.MessageStoreFactory; import quickfix.RejectLogon; import quickfix.RuntimeError; -import quickfix.SLF4JLogFactory; import quickfix.SessionID; import quickfix.SessionNotFound; import quickfix.SessionSettings; @@ -49,6 +48,7 @@ import java.util.Timer; import java.util.TimerTask; import java.util.concurrent.CountDownLatch; +import quickfix.ScreenLogFactory; /** * @author John Hensley @@ -107,7 +107,7 @@ public void run() throws ConfigError, SessionNotFound, InterruptedException { MessageStoreFactory storeFactory = new MemoryStoreFactory(); Initiator initiator = new SocketInitiator(this, storeFactory, settings, - new SLF4JLogFactory(settings), new DefaultMessageFactory()); + new ScreenLogFactory(true, true, true, true), new DefaultMessageFactory()); initiator.start(); try { diff --git a/quickfixj-core/src/test/java/quickfix/test/acceptance/timer/TimerTestServer.java b/quickfixj-core/src/test/java/quickfix/test/acceptance/timer/TimerTestServer.java index f6ca060b9b..e99eb8cd84 100644 --- a/quickfixj-core/src/test/java/quickfix/test/acceptance/timer/TimerTestServer.java +++ b/quickfixj-core/src/test/java/quickfix/test/acceptance/timer/TimerTestServer.java @@ -33,7 +33,6 @@ import quickfix.MessageCracker; import quickfix.MessageStoreFactory; import quickfix.RejectLogon; -import quickfix.SLF4JLogFactory; import quickfix.Session; import quickfix.SessionID; import quickfix.SessionNotFound; @@ -48,6 +47,7 @@ import java.util.Timer; import java.util.TimerTask; import java.util.concurrent.CountDownLatch; +import quickfix.ScreenLogFactory; /** * @author John Hensley @@ -130,7 +130,7 @@ public void run() { settings.setString(sessionID, "DataDictionary", FixVersions.BEGINSTRING_FIX44.replaceAll("\\.", "") + ".xml"); MessageStoreFactory factory = new MemoryStoreFactory(); - acceptor = new SocketAcceptor(this, factory, settings, new SLF4JLogFactory(settings), + acceptor = new SocketAcceptor(this, factory, settings, new ScreenLogFactory(true, true, true, true), new DefaultMessageFactory()); acceptor.start(); try { From a34b0ea0ec1578e92b34f6b82e6cbb10f9a133db Mon Sep 17 00:00:00 2001 From: Christoph John Date: Thu, 17 Dec 2020 14:55:16 +0100 Subject: [PATCH 02/41] - added stack dump after two seconds --- .../quickfix/test/acceptance/timer/TimerTestClient.java | 8 ++++++++ 1 file changed, 8 insertions(+) diff --git a/quickfixj-core/src/test/java/quickfix/test/acceptance/timer/TimerTestClient.java b/quickfixj-core/src/test/java/quickfix/test/acceptance/timer/TimerTestClient.java index 14a3b583cd..bd546f7b04 100644 --- a/quickfixj-core/src/test/java/quickfix/test/acceptance/timer/TimerTestClient.java +++ b/quickfixj-core/src/test/java/quickfix/test/acceptance/timer/TimerTestClient.java @@ -49,6 +49,7 @@ import java.util.TimerTask; import java.util.concurrent.CountDownLatch; import quickfix.ScreenLogFactory; +import quickfix.test.util.ReflectionUtil; /** * @author John Hensley @@ -118,6 +119,13 @@ public void run() { } }, 5000); + Timer timer2 = new Timer(); + timer2.schedule(new TimerTask() { + public void run() { + ReflectionUtil.dumpStackTraces(); + } + }, 2000); + try { shutdownLatch.await(); } catch (InterruptedException e) { From b60173c8606991db1ed9d3c1a13edb550ca2ae5c Mon Sep 17 00:00:00 2001 From: Christoph John Date: Mon, 21 Dec 2020 01:21:11 +0100 Subject: [PATCH 03/41] - start thread to create thread dump after Logon --- .../test/acceptance/timer/TimerTestClient.java | 16 +++++++++------- 1 file changed, 9 insertions(+), 7 deletions(-) diff --git a/quickfixj-core/src/test/java/quickfix/test/acceptance/timer/TimerTestClient.java b/quickfixj-core/src/test/java/quickfix/test/acceptance/timer/TimerTestClient.java index bd546f7b04..3e5c0aef54 100644 --- a/quickfixj-core/src/test/java/quickfix/test/acceptance/timer/TimerTestClient.java +++ b/quickfixj-core/src/test/java/quickfix/test/acceptance/timer/TimerTestClient.java @@ -43,6 +43,7 @@ import quickfix.UnsupportedMessageType; import quickfix.fix44.ListStatusRequest; import quickfix.fix44.TestRequest; +import quickfix.fix44.Logon; import java.util.HashMap; import java.util.Timer; @@ -62,6 +63,14 @@ public class TimerTestClient extends MessageCracker implements Application { public void fromAdmin(Message message, SessionID sessionId) throws FieldNotFound, IncorrectDataFormat, IncorrectTagValue, RejectLogon { + if (message instanceof Logon) { + Timer timer2 = new Timer(); + timer2.schedule(new TimerTask() { + public void run() { + ReflectionUtil.dumpStackTraces(); + } + }, 2500); + } } public void fromApp(Message message, SessionID sessionID) throws FieldNotFound, @@ -119,13 +128,6 @@ public void run() { } }, 5000); - Timer timer2 = new Timer(); - timer2.schedule(new TimerTask() { - public void run() { - ReflectionUtil.dumpStackTraces(); - } - }, 2000); - try { shutdownLatch.await(); } catch (InterruptedException e) { From 97bb50d5755c8055d189bffa8a1a805f9f771e8f Mon Sep 17 00:00:00 2001 From: Christoph John Date: Tue, 29 Dec 2020 00:52:53 +0100 Subject: [PATCH 04/41] - add information on started test to SocketAcceptorTest --- .../java/quickfix/SocketAcceptorTest.java | 19 +++++++++++++++++++ 1 file changed, 19 insertions(+) diff --git a/quickfixj-core/src/test/java/quickfix/SocketAcceptorTest.java b/quickfixj-core/src/test/java/quickfix/SocketAcceptorTest.java index 0d0ff175e8..d061e36b60 100644 --- a/quickfixj-core/src/test/java/quickfix/SocketAcceptorTest.java +++ b/quickfixj-core/src/test/java/quickfix/SocketAcceptorTest.java @@ -36,6 +36,11 @@ import java.util.logging.Level; import static org.junit.Assert.*; +import org.junit.Before; +import org.junit.Rule; +import org.junit.rules.TestRule; +import org.junit.rules.TestWatcher; +import org.junit.runner.Description; /** * QFJ-643: Unable to restart a stopped acceptor (SocketAcceptor) @@ -54,6 +59,20 @@ public class SocketAcceptorTest { private final SessionID initiatorSessionID = new SessionID(FixVersions.BEGINSTRING_FIX42, "INITIATOR", "ACCEPTOR"); + + @Rule + public TestRule watcher = new TestWatcher() { + @Override + protected void starting(Description description) { + System.out.println("Starting test: " + description.getMethodName()); + } + }; + + @Before + public void check() { + checkThreads(ManagementFactory.getThreadMXBean(), 0); + } + @After public void cleanup() { try { From 0a05a2aa1cda0481569df9956e0dd92c147e5918 Mon Sep 17 00:00:00 2001 From: Christoph John Date: Thu, 31 Dec 2020 01:07:57 +0100 Subject: [PATCH 05/41] - added some ugly debug logging --- quickfixj-core/src/main/java/quickfix/Session.java | 2 +- .../src/main/java/quickfix/SessionState.java | 10 ++++++++-- 2 files changed, 9 insertions(+), 3 deletions(-) diff --git a/quickfixj-core/src/main/java/quickfix/Session.java b/quickfixj-core/src/main/java/quickfix/Session.java index 536f9290c2..bcd33a491f 100644 --- a/quickfixj-core/src/main/java/quickfix/Session.java +++ b/quickfixj-core/src/main/java/quickfix/Session.java @@ -1967,7 +1967,7 @@ public void next() throws IOException { generateTestRequest("TEST"); getLog().onEvent("Sent test request TEST"); stateListener.onMissedHeartBeat(); - } else if (state.isHeartBeatNeeded()) { + } else if (state.isHeartBeatNeeded(sessionID)) { generateHeartbeat(); } } diff --git a/quickfixj-core/src/main/java/quickfix/SessionState.java b/quickfixj-core/src/main/java/quickfix/SessionState.java index 3dcbb94ace..7269688dfa 100644 --- a/quickfixj-core/src/main/java/quickfix/SessionState.java +++ b/quickfixj-core/src/main/java/quickfix/SessionState.java @@ -106,10 +106,16 @@ long getHeartBeatMillis() { } } - public boolean isHeartBeatNeeded() { + SessionID sessionID1 = new SessionID(FixVersions.BEGINSTRING_FIX44, "ISLD", "TW"); + SessionID sessionID2 = new SessionID(FixVersions.BEGINSTRING_FIX44, "TW", "ISLD"); + public boolean isHeartBeatNeeded(SessionID sessionID) { long millisSinceLastSentTime = SystemTime.currentTimeMillis() - getLastSentTime(); + boolean name = millisSinceLastSentTime + 10 > getHeartBeatMillis() && getTestRequestCounter() == 0; // QFJ-448: allow 10 ms leeway since exact comparison causes skipped heartbeats occasionally - return millisSinceLastSentTime + 10 > getHeartBeatMillis() && getTestRequestCounter() == 0; + if ( sessionID.equals(sessionID1) || sessionID.equals(sessionID2)) { + System.out.println("XXX " + sessionID + " isHeartBeatNeeded() = " + name); + } + return name; } public boolean isInitiator() { From 20149e13b9a53c7caccec0c9d6adecf2da45b7c0 Mon Sep 17 00:00:00 2001 From: Christoph John Date: Mon, 19 Apr 2021 00:22:03 +0200 Subject: [PATCH 06/41] Update maven.yml disabled NTP for MacOS --- .github/workflows/maven.yml | 8 ++++++++ 1 file changed, 8 insertions(+) diff --git a/.github/workflows/maven.yml b/.github/workflows/maven.yml index 16d661570b..3d4c2c8542 100644 --- a/.github/workflows/maven.yml +++ b/.github/workflows/maven.yml @@ -18,10 +18,18 @@ jobs: steps: - uses: actions/checkout@v1 + - name: Set up JDK uses: actions/setup-java@v1 with: java-version: ${{ matrix.java }} + + - name: Disable NTP on macOS (https://github.com/actions/virtual-environments/issues/820) + run: | + sudo systemsetup -setusingnetworktime off + sudo rm -rf /etc/ntp.conf + if: runner.os == 'macOS' + - name: Test with Maven env: MAVEN_OPTS: "-Xms3g -Xmx3g" From c979cd76dee78cc4aa690cf0c3ecd45ffc3da656 Mon Sep 17 00:00:00 2001 From: Christoph John Date: Tue, 20 Apr 2021 00:39:00 +0200 Subject: [PATCH 07/41] code cleanup --- .../test/acceptance/timer/TimerTest.java | 13 ++++++---- .../acceptance/timer/TimerTestClient.java | 24 +++++++------------ .../acceptance/timer/TimerTestServer.java | 22 ++++++++++------- 3 files changed, 30 insertions(+), 29 deletions(-) diff --git a/quickfixj-core/src/test/java/quickfix/test/acceptance/timer/TimerTest.java b/quickfixj-core/src/test/java/quickfix/test/acceptance/timer/TimerTest.java index 5d6600d192..593e04ecb0 100644 --- a/quickfixj-core/src/test/java/quickfix/test/acceptance/timer/TimerTest.java +++ b/quickfixj-core/src/test/java/quickfix/test/acceptance/timer/TimerTest.java @@ -19,25 +19,30 @@ package quickfix.test.acceptance.timer; -import junit.framework.TestCase; +import org.junit.After; +import org.junit.Before; +import org.junit.Test; import quickfix.ConfigError; import quickfix.SessionNotFound; -public class TimerTest extends TestCase { +public class TimerTest { TimerTestServer server; + @Test public void testAcceptorTimer() throws ConfigError, SessionNotFound, InterruptedException { new TimerTestClient().run(); } - protected void setUp() throws Exception { + @Before + public void setUp() throws Exception { server = new TimerTestServer(); server.start(); server.waitForInitialization(); } - protected void tearDown() throws Exception { + @After + public void tearDown() throws Exception { server.stop(); } } diff --git a/quickfixj-core/src/test/java/quickfix/test/acceptance/timer/TimerTestClient.java b/quickfixj-core/src/test/java/quickfix/test/acceptance/timer/TimerTestClient.java index 3e5c0aef54..b3418167df 100644 --- a/quickfixj-core/src/test/java/quickfix/test/acceptance/timer/TimerTestClient.java +++ b/quickfixj-core/src/test/java/quickfix/test/acceptance/timer/TimerTestClient.java @@ -43,14 +43,12 @@ import quickfix.UnsupportedMessageType; import quickfix.fix44.ListStatusRequest; import quickfix.fix44.TestRequest; -import quickfix.fix44.Logon; import java.util.HashMap; import java.util.Timer; import java.util.TimerTask; import java.util.concurrent.CountDownLatch; import quickfix.ScreenLogFactory; -import quickfix.test.util.ReflectionUtil; /** * @author John Hensley @@ -61,29 +59,26 @@ public class TimerTestClient extends MessageCracker implements Application { private final CountDownLatch shutdownLatch = new CountDownLatch(1); private boolean failed; + @Override public void fromAdmin(Message message, SessionID sessionId) throws FieldNotFound, IncorrectDataFormat, IncorrectTagValue, RejectLogon { - if (message instanceof Logon) { - Timer timer2 = new Timer(); - timer2.schedule(new TimerTask() { - public void run() { - ReflectionUtil.dumpStackTraces(); - } - }, 2500); - } } + @Override public void fromApp(Message message, SessionID sessionID) throws FieldNotFound, IncorrectDataFormat, IncorrectTagValue, UnsupportedMessageType { crack(message, sessionID); } + @Override public void onCreate(SessionID sessionId) { } + @Override public void onLogon(SessionID sessionId) { } + @Override public void onLogout(SessionID sessionId) { } @@ -123,6 +118,7 @@ public void run() throws ConfigError, SessionNotFound, InterruptedException { try { Timer timer = new Timer(); timer.schedule(new TimerTask() { + @Override public void run() { stop(false); } @@ -143,18 +139,14 @@ public void run() { } } + @Override public void toAdmin(Message message, SessionID sessionId) { if (message instanceof TestRequest) { stop(true); } } + @Override public void toApp(Message message, SessionID sessionId) throws DoNotSend { } - - public static void main(String[] args) throws ConfigError, SessionNotFound, - InterruptedException { - TimerTestClient ttc = new TimerTestClient(); - ttc.run(); - } } diff --git a/quickfixj-core/src/test/java/quickfix/test/acceptance/timer/TimerTestServer.java b/quickfixj-core/src/test/java/quickfix/test/acceptance/timer/TimerTestServer.java index e99eb8cd84..ce9316ddbc 100644 --- a/quickfixj-core/src/test/java/quickfix/test/acceptance/timer/TimerTestServer.java +++ b/quickfixj-core/src/test/java/quickfix/test/acceptance/timer/TimerTestServer.java @@ -61,23 +61,25 @@ public class TimerTestServer extends MessageCracker implements Application, Runn private final CountDownLatch shutdownLatch = new CountDownLatch(1); private class DelayedTestRequest extends TimerTask { - final SessionID session; + final SessionID sessionID; DelayedTestRequest(SessionID sessionID) { - this.session = sessionID; + this.sessionID = sessionID; } + @Override public void run() { try { log.info("Sending offset message"); ListStatusRequest lsr = new ListStatusRequest(new ListID("somelist")); - Session.sendToTarget(lsr, this.session); + Session.sendToTarget(lsr, this.sessionID); } catch (SessionNotFound sessionNotFound) { // not going to happen } } } + @Override public void fromAdmin(Message message, SessionID sessionId) throws FieldNotFound, IncorrectDataFormat, IncorrectTagValue, RejectLogon { // sleep to move our timer off from the client's @@ -86,16 +88,20 @@ public void fromAdmin(Message message, SessionID sessionId) throws FieldNotFound } } + @Override public void fromApp(Message message, SessionID sessionId) throws FieldNotFound, IncorrectDataFormat, IncorrectTagValue, UnsupportedMessageType { } + @Override public void onCreate(SessionID sessionId) { } + @Override public void onLogon(SessionID sessionId) { } + @Override public void onLogout(SessionID sessionId) { log.info("logout"); shutdownLatch.countDown(); @@ -111,6 +117,7 @@ public void stop() { shutdownLatch.countDown(); } + @Override public void run() { try { HashMap defaults = new HashMap<>(); @@ -127,7 +134,7 @@ public void run() { SessionID sessionID = new SessionID(FixVersions.BEGINSTRING_FIX44, "ISLD", "TW"); settings.setString(sessionID, "BeginString", FixVersions.BEGINSTRING_FIX44); - settings.setString(sessionID, "DataDictionary", FixVersions.BEGINSTRING_FIX44.replaceAll("\\.", "") + ".xml"); + settings.setString(sessionID, "DataDictionary", FixVersions.BEGINSTRING_FIX44.replaceAll("\\.", "") + ".xml"); MessageStoreFactory factory = new MemoryStoreFactory(); acceptor = new SocketAcceptor(this, factory, settings, new ScreenLogFactory(true, true, true, true), @@ -152,18 +159,15 @@ public void run() { } } + @Override public void toAdmin(Message message, SessionID sessionId) { } + @Override public void toApp(Message message, SessionID sessionId) throws DoNotSend { } public void waitForInitialization() throws InterruptedException { initializationLatch.await(); } - - public static void main(String[] args) { - TimerTestServer server = new TimerTestServer(); - server.run(); - } } From b7431bd72b8adf6c45c7bb7d548c714c7f853b7a Mon Sep 17 00:00:00 2001 From: Christoph John Date: Wed, 21 Apr 2021 01:20:45 +0200 Subject: [PATCH 08/41] AcceptanceTest changes --- .../quickfix/test/acceptance/ATServer.java | 5 ++-- .../test/acceptance/AcceptanceTestSuite.java | 3 +- .../test/acceptance/TestConnection.java | 30 ++++++++++--------- 3 files changed, 19 insertions(+), 19 deletions(-) diff --git a/quickfixj-core/src/test/java/quickfix/test/acceptance/ATServer.java b/quickfixj-core/src/test/java/quickfix/test/acceptance/ATServer.java index cbed9a2bac..78714240fc 100644 --- a/quickfixj-core/src/test/java/quickfix/test/acceptance/ATServer.java +++ b/quickfixj-core/src/test/java/quickfix/test/acceptance/ATServer.java @@ -53,6 +53,7 @@ import java.util.Set; import java.util.concurrent.CountDownLatch; import java.util.concurrent.TimeUnit; +import quickfix.Session; public class ATServer implements Runnable { private final Logger log = LoggerFactory.getLogger(ATServer.class); @@ -107,6 +108,7 @@ public void run() { defaults.put("SocketTcpNoDelay", "Y"); defaults.put("StartTime", "00:00:00"); defaults.put("EndTime", "00:00:00"); + defaults.put(Session.SETTING_NON_STOP_SESSION, "Y"); defaults.put("SenderCompID", "ISLD"); defaults.put("TargetCompID", "TW"); defaults.put("JdbcDriver", "com.mysql.jdbc.Driver"); @@ -162,10 +164,7 @@ public void run() { MessageStoreFactory factory = usingMemoryStore ? new MemoryStoreFactory() : new FileStoreFactory(settings); - //MessageStoreFactory factory = new JdbcStoreFactory(settings); - //LogFactory logFactory = new CommonsLogFactory(settings); quickfix.LogFactory logFactory = new SLF4JLogFactory(new SessionSettings()); - //quickfix.LogFactory logFactory = new JdbcLogFactory(settings); if (threaded) { acceptor = new ThreadedSocketAcceptor(application, factory, settings, logFactory, new DefaultMessageFactory()); diff --git a/quickfixj-core/src/test/java/quickfix/test/acceptance/AcceptanceTestSuite.java b/quickfixj-core/src/test/java/quickfix/test/acceptance/AcceptanceTestSuite.java index 72317fb7bd..32b0143454 100644 --- a/quickfixj-core/src/test/java/quickfix/test/acceptance/AcceptanceTestSuite.java +++ b/quickfixj-core/src/test/java/quickfix/test/acceptance/AcceptanceTestSuite.java @@ -38,7 +38,7 @@ public class AcceptanceTestSuite extends TestSuite { private static final String acceptanceTestBaseDir = AcceptanceTestSuite.class.getClassLoader().getResource(acceptanceTestResourcePath).getPath(); private static int transportType = ProtocolFactory.SOCKET; - private static int port = 9887; + private static int port = AvailablePortFinder.getNextAvailable(); private final boolean skipSlowTests; private final boolean multithreaded; @@ -247,7 +247,6 @@ protected void tearDown() throws Exception { public static Test suite() { transportType = ProtocolFactory.getTransportType(System.getProperty(ATEST_TRANSPORT_KEY, ProtocolFactory.getTypeString(ProtocolFactory.SOCKET))); - port = AvailablePortFinder.getNextAvailable(port); TestSuite acceptanceTests = new TestSuite(AcceptanceTestSuite.class.getSimpleName()); // default server acceptanceTests.addTest(new AcceptanceTestServerSetUp(new AcceptanceTestSuite("server", false))); diff --git a/quickfixj-core/src/test/java/quickfix/test/acceptance/TestConnection.java b/quickfixj-core/src/test/java/quickfix/test/acceptance/TestConnection.java index 36fc4f0403..e31fb55148 100644 --- a/quickfixj-core/src/test/java/quickfix/test/acceptance/TestConnection.java +++ b/quickfixj-core/src/test/java/quickfix/test/acceptance/TestConnection.java @@ -44,16 +44,19 @@ import java.util.ArrayList; import java.util.HashMap; import java.util.List; +import java.util.Map; import java.util.concurrent.BlockingQueue; +import java.util.concurrent.ConcurrentHashMap; +import java.util.concurrent.ConcurrentMap; import java.util.concurrent.CountDownLatch; import java.util.concurrent.LinkedBlockingQueue; import java.util.concurrent.TimeUnit; import quickfix.mina.SessionConnector; public class TestConnection { - private static final HashMap connectors = new HashMap<>(); + private static final Map connectors = new HashMap<>(); private final Logger log = LoggerFactory.getLogger(getClass()); - private final HashMap ioHandlers = new HashMap<>(); + private final ConcurrentMap ioHandlers = new ConcurrentHashMap<>(); public void sendMessage(int clientId, String message) throws IOException { TestIoHandler handler = getIoHandler(clientId); @@ -61,15 +64,16 @@ public void sendMessage(int clientId, String message) throws IOException { } private TestIoHandler getIoHandler(int clientId) { - synchronized (ioHandlers) { - return ioHandlers.get(clientId); - } + return ioHandlers.get(clientId); } public void tearDown() { for (TestIoHandler testIoHandler : ioHandlers.values()) { - CloseFuture closeFuture = testIoHandler.getSession().closeNow(); - closeFuture.awaitUninterruptibly(); + IoSession session = testIoHandler.getSession(); + if (session != null) { + CloseFuture closeFuture = session.closeNow(); + closeFuture.awaitUninterruptibly(); + } } ioHandlers.clear(); } @@ -102,13 +106,11 @@ public void connect(int clientId, int transportType, int port) connectors.put(Integer.toString(clientId), connector); TestIoHandler testIoHandler = new TestIoHandler(); - synchronized (ioHandlers) { - ioHandlers.put(clientId, testIoHandler); - connector.setHandler(testIoHandler); - ConnectFuture future = connector.connect(address); - future.awaitUninterruptibly(5000L); - Assert.assertTrue("connection to server failed", future.isConnected()); - } + ioHandlers.put(clientId, testIoHandler); + connector.setHandler(testIoHandler); + ConnectFuture future = connector.connect(address); + future.awaitUninterruptibly(5000L); + Assert.assertTrue("connection to server failed", future.isConnected()); } private class TestIoHandler extends IoHandlerAdapter { From 11c3c70acc6778422d6d41440f25bd5aa43605da Mon Sep 17 00:00:00 2001 From: Christoph John Date: Thu, 1 Jul 2021 12:10:04 +0200 Subject: [PATCH 09/41] bogus change to test commit - please ignore --- README.md | 1 + 1 file changed, 1 insertion(+) diff --git a/README.md b/README.md index 95c3b7bb42..b03533034c 100644 --- a/README.md +++ b/README.md @@ -6,6 +6,7 @@ QuickFIX/J [![Total alerts](https://img.shields.io/lgtm/alerts/g/quickfix-j/quickfixj.svg?logo=lgtm&logoWidth=18)](https://lgtm.com/projects/g/quickfix-j/quickfixj/alerts/) [![Language grade: Java](https://img.shields.io/lgtm/grade/java/g/quickfix-j/quickfixj.svg?logo=lgtm&logoWidth=18)](https://lgtm.com/projects/g/quickfix-j/quickfixj/context:java) + This is the official QuickFIX/J project repository. ## intro From 3ae5967f53787328d94c7905228aa3a78190d2c4 Mon Sep 17 00:00:00 2001 From: Christoph John Date: Thu, 1 Jul 2021 15:02:35 +0200 Subject: [PATCH 10/41] Make isHeartBeatNeeded() use System.nanoTime() --- .../src/main/java/quickfix/SessionState.java | 13 +++++++++++-- 1 file changed, 11 insertions(+), 2 deletions(-) diff --git a/quickfixj-core/src/main/java/quickfix/SessionState.java b/quickfixj-core/src/main/java/quickfix/SessionState.java index b026c7e60d..c75b9642cf 100644 --- a/quickfixj-core/src/main/java/quickfix/SessionState.java +++ b/quickfixj-core/src/main/java/quickfix/SessionState.java @@ -54,6 +54,7 @@ public final class SessionState { private boolean logoutReceived = false; private int testRequestCounter; private long lastSentTime; + private long lastSentTimeNanos; private long lastReceivedTime; private final double testRequestDelayMultiplier; private final double heartBeatTimeoutMultiplier; @@ -115,10 +116,11 @@ long getHeartBeatMillis() { SessionID sessionID1 = new SessionID(FixVersions.BEGINSTRING_FIX44, "ISLD", "TW"); SessionID sessionID2 = new SessionID(FixVersions.BEGINSTRING_FIX44, "TW", "ISLD"); public boolean isHeartBeatNeeded(SessionID sessionID) { - long millisSinceLastSentTime = SystemTime.currentTimeMillis() - getLastSentTime(); + long millisSinceLastSentTime = TimeUnit.NANOSECONDS.toMillis(System.nanoTime() - getLastSentTimeNanos()); +// long millisSinceLastSentTime = SystemTime.currentTimeMillis() - getLastSentTime(); boolean name = millisSinceLastSentTime + 10 > getHeartBeatMillis() && getTestRequestCounter() == 0; // QFJ-448: allow 10 ms leeway since exact comparison causes skipped heartbeats occasionally - if ( sessionID.equals(sessionID1) || sessionID.equals(sessionID2)) { + if (sessionID.equals(sessionID1) || sessionID.equals(sessionID2)) { System.out.println("XXX " + sessionID + " isHeartBeatNeeded() = " + name); } return name; @@ -146,9 +148,16 @@ public long getLastSentTime() { } } + public long getLastSentTimeNanos() { + synchronized (lock) { + return lastSentTimeNanos; + } + } + public void setLastSentTime(long lastSentTime) { synchronized (lock) { this.lastSentTime = lastSentTime; + this.lastSentTimeNanos = System.nanoTime(); } } From ae5848a404faf5c935688634e039ff31c7c886eb Mon Sep 17 00:00:00 2001 From: Christoph John Date: Fri, 2 Jul 2021 00:46:08 +0200 Subject: [PATCH 11/41] replaced Timer by ScheduledExecutorService --- .../acceptance/timer/TimerTestClient.java | 24 ++++++++++++------- .../acceptance/timer/TimerTestServer.java | 14 +++++++---- 2 files changed, 25 insertions(+), 13 deletions(-) diff --git a/quickfixj-core/src/test/java/quickfix/test/acceptance/timer/TimerTestClient.java b/quickfixj-core/src/test/java/quickfix/test/acceptance/timer/TimerTestClient.java index b3418167df..43d51ffad0 100644 --- a/quickfixj-core/src/test/java/quickfix/test/acceptance/timer/TimerTestClient.java +++ b/quickfixj-core/src/test/java/quickfix/test/acceptance/timer/TimerTestClient.java @@ -45,9 +45,10 @@ import quickfix.fix44.TestRequest; import java.util.HashMap; -import java.util.Timer; -import java.util.TimerTask; import java.util.concurrent.CountDownLatch; +import java.util.concurrent.Executors; +import java.util.concurrent.ScheduledExecutorService; +import java.util.concurrent.TimeUnit; import quickfix.ScreenLogFactory; /** @@ -58,6 +59,7 @@ public class TimerTestClient extends MessageCracker implements Application { private final SessionSettings settings = new SessionSettings(); private final CountDownLatch shutdownLatch = new CountDownLatch(1); private boolean failed; + private final ScheduledExecutorService scheduledExecutor = Executors.newSingleThreadScheduledExecutor(); @Override public void fromAdmin(Message message, SessionID sessionId) throws FieldNotFound, @@ -116,13 +118,17 @@ public void run() throws ConfigError, SessionNotFound, InterruptedException { initiator.start(); try { - Timer timer = new Timer(); - timer.schedule(new TimerTask() { - @Override - public void run() { - stop(false); - } - }, 5000); + scheduledExecutor.schedule(() -> { + stop(false); + }, 5000, TimeUnit.MILLISECONDS); + +// Timer timer = new Timer(); +// timer.schedule(new TimerTask() { +// @Override +// public void run() { +// stop(false); +// } +// }, 5000); try { shutdownLatch.await(); diff --git a/quickfixj-core/src/test/java/quickfix/test/acceptance/timer/TimerTestServer.java b/quickfixj-core/src/test/java/quickfix/test/acceptance/timer/TimerTestServer.java index ce9316ddbc..a1303b33c3 100644 --- a/quickfixj-core/src/test/java/quickfix/test/acceptance/timer/TimerTestServer.java +++ b/quickfixj-core/src/test/java/quickfix/test/acceptance/timer/TimerTestServer.java @@ -44,9 +44,10 @@ import quickfix.fix44.Logon; import java.util.HashMap; -import java.util.Timer; -import java.util.TimerTask; import java.util.concurrent.CountDownLatch; +import java.util.concurrent.Executors; +import java.util.concurrent.ScheduledExecutorService; +import java.util.concurrent.TimeUnit; import quickfix.ScreenLogFactory; /** @@ -59,8 +60,9 @@ public class TimerTestServer extends MessageCracker implements Application, Runn private Thread serverThread; private final CountDownLatch initializationLatch = new CountDownLatch(1); private final CountDownLatch shutdownLatch = new CountDownLatch(1); + private final ScheduledExecutorService scheduledExecutor = Executors.newSingleThreadScheduledExecutor(); - private class DelayedTestRequest extends TimerTask { + private class DelayedTestRequest implements Runnable { final SessionID sessionID; DelayedTestRequest(SessionID sessionID) { @@ -84,7 +86,11 @@ public void fromAdmin(Message message, SessionID sessionId) throws FieldNotFound IncorrectDataFormat, IncorrectTagValue, RejectLogon { // sleep to move our timer off from the client's if (message instanceof Logon) { - new Timer().schedule(new DelayedTestRequest(sessionId), 3000); + scheduledExecutor.schedule(() -> { + new DelayedTestRequest(sessionId); + }, 3000, TimeUnit.MILLISECONDS); + +// new Timer().schedule(new DelayedTestRequest(sessionId), 3000); } } From a59c1e4e9a339859fbbdb093c7ae58d462042eff Mon Sep 17 00:00:00 2001 From: Christoph John Date: Fri, 2 Jul 2021 01:06:35 +0200 Subject: [PATCH 12/41] make timeSinceLastReceivedMessage use System.nanoTime() --- .../src/main/java/quickfix/SessionState.java | 11 ++++++++++- 1 file changed, 10 insertions(+), 1 deletion(-) diff --git a/quickfixj-core/src/main/java/quickfix/SessionState.java b/quickfixj-core/src/main/java/quickfix/SessionState.java index c75b9642cf..8f11456f08 100644 --- a/quickfixj-core/src/main/java/quickfix/SessionState.java +++ b/quickfixj-core/src/main/java/quickfix/SessionState.java @@ -56,6 +56,7 @@ public final class SessionState { private long lastSentTime; private long lastSentTimeNanos; private long lastReceivedTime; + private long lastReceivedTimeNanos; private final double testRequestDelayMultiplier; private final double heartBeatTimeoutMultiplier; private long heartBeatMillis = Long.MAX_VALUE; @@ -136,9 +137,16 @@ public long getLastReceivedTime() { } } + public long getLastReceivedTimeNanos() { + synchronized (lock) { + return lastReceivedTimeNanos; + } + } + public void setLastReceivedTime(long lastReceivedTime) { synchronized (lock) { this.lastReceivedTime = lastReceivedTime; + this.lastReceivedTimeNanos = System.nanoTime(); } } @@ -304,7 +312,8 @@ public boolean isTestRequestNeeded() { } private long timeSinceLastReceivedMessage() { - return SystemTime.currentTimeMillis() - getLastReceivedTime(); + return TimeUnit.NANOSECONDS.toMillis(System.nanoTime() - getLastReceivedTimeNanos()); +// return SystemTime.currentTimeMillis() - getLastReceivedTime(); } public boolean isTimedOut() { From a967699a29778ee98b7ed3899da6c97137f62518 Mon Sep 17 00:00:00 2001 From: Christoph John Date: Sat, 3 Jul 2021 01:22:33 +0200 Subject: [PATCH 13/41] added support for using nanoseconds to SystemTime(Source) --- .../src/main/java/quickfix/SessionState.java | 16 +++++++++---- .../src/main/java/quickfix/SystemTime.java | 9 ++++++++ .../main/java/quickfix/SystemTimeSource.java | 2 ++ .../java/quickfix/MockSystemTimeSource.java | 23 +++++++++++++++++-- .../test/java/quickfix/SessionStateTest.java | 11 +++++---- 5 files changed, 49 insertions(+), 12 deletions(-) diff --git a/quickfixj-core/src/main/java/quickfix/SessionState.java b/quickfixj-core/src/main/java/quickfix/SessionState.java index 8f11456f08..03b7034d78 100644 --- a/quickfixj-core/src/main/java/quickfix/SessionState.java +++ b/quickfixj-core/src/main/java/quickfix/SessionState.java @@ -117,7 +117,7 @@ long getHeartBeatMillis() { SessionID sessionID1 = new SessionID(FixVersions.BEGINSTRING_FIX44, "ISLD", "TW"); SessionID sessionID2 = new SessionID(FixVersions.BEGINSTRING_FIX44, "TW", "ISLD"); public boolean isHeartBeatNeeded(SessionID sessionID) { - long millisSinceLastSentTime = TimeUnit.NANOSECONDS.toMillis(System.nanoTime() - getLastSentTimeNanos()); + long millisSinceLastSentTime = TimeUnit.NANOSECONDS.toMillis(SystemTime.currentTimeMillisFromNanos() - getLastSentTimeNanos()); // long millisSinceLastSentTime = SystemTime.currentTimeMillis() - getLastSentTime(); boolean name = millisSinceLastSentTime + 10 > getHeartBeatMillis() && getTestRequestCounter() == 0; // QFJ-448: allow 10 ms leeway since exact comparison causes skipped heartbeats occasionally @@ -146,10 +146,14 @@ public long getLastReceivedTimeNanos() { public void setLastReceivedTime(long lastReceivedTime) { synchronized (lock) { this.lastReceivedTime = lastReceivedTime; - this.lastReceivedTimeNanos = System.nanoTime(); + this.lastReceivedTimeNanos = TimeUnit.MILLISECONDS.toNanos(lastReceivedTime); } } + public void setLastReceivedTimeNanos(long lastReceivedTimeNanos) { + this.lastReceivedTimeNanos = lastReceivedTimeNanos; + } + public long getLastSentTime() { synchronized (lock) { return lastSentTime; @@ -165,7 +169,7 @@ public long getLastSentTimeNanos() { public void setLastSentTime(long lastSentTime) { synchronized (lock) { this.lastSentTime = lastSentTime; - this.lastSentTimeNanos = System.nanoTime(); + this.lastSentTimeNanos = SystemTime.currentTimeMillisFromNanos(); } } @@ -312,8 +316,10 @@ public boolean isTestRequestNeeded() { } private long timeSinceLastReceivedMessage() { - return TimeUnit.NANOSECONDS.toMillis(System.nanoTime() - getLastReceivedTimeNanos()); -// return SystemTime.currentTimeMillis() - getLastReceivedTime(); + long lastReceivedTimeNanos1 = getLastReceivedTimeNanos(); + long currentTimeMillisFromNanos = SystemTime.currentTimeMillisFromNanos(); + long timeSinceLastReceivedMessage = TimeUnit.NANOSECONDS.toMillis(currentTimeMillisFromNanos - lastReceivedTimeNanos1); + return timeSinceLastReceivedMessage; } public boolean isTimedOut() { diff --git a/quickfixj-core/src/main/java/quickfix/SystemTime.java b/quickfixj-core/src/main/java/quickfix/SystemTime.java index 85d73c47bc..fb577f8332 100644 --- a/quickfixj-core/src/main/java/quickfix/SystemTime.java +++ b/quickfixj-core/src/main/java/quickfix/SystemTime.java @@ -37,6 +37,11 @@ public long getTime() { return System.currentTimeMillis(); } + @Override + public long getTimeFromNanos() { + return System.nanoTime(); + } + @Override public LocalDateTime getNow() { return LocalDateTime.now(ZoneOffset.UTC); @@ -48,6 +53,10 @@ public LocalDateTime getNow() { public static long currentTimeMillis() { return systemTimeSource.getTime(); } + + public static long currentTimeMillisFromNanos() { + return systemTimeSource.getTimeFromNanos(); + } public static LocalDateTime now() { return systemTimeSource.getNow(); diff --git a/quickfixj-core/src/main/java/quickfix/SystemTimeSource.java b/quickfixj-core/src/main/java/quickfix/SystemTimeSource.java index c14af90f8f..179a6b2ccb 100644 --- a/quickfixj-core/src/main/java/quickfix/SystemTimeSource.java +++ b/quickfixj-core/src/main/java/quickfix/SystemTimeSource.java @@ -33,6 +33,8 @@ public interface SystemTimeSource { * @return current (possible simulated) time */ long getTime(); + + long getTimeFromNanos(); /** * Obtain current LocalDateTime. diff --git a/quickfixj-core/src/test/java/quickfix/MockSystemTimeSource.java b/quickfixj-core/src/test/java/quickfix/MockSystemTimeSource.java index 3c9dea46c4..768bb6e3ea 100644 --- a/quickfixj-core/src/test/java/quickfix/MockSystemTimeSource.java +++ b/quickfixj-core/src/test/java/quickfix/MockSystemTimeSource.java @@ -23,9 +23,12 @@ import java.time.LocalDateTime; import java.time.ZoneOffset; import java.util.Calendar; +import java.util.concurrent.TimeUnit; public class MockSystemTimeSource implements SystemTimeSource { - private long[] systemTimes = { System.currentTimeMillis() }; + + private long[] systemTimes = {System.currentTimeMillis()}; + private long[] systemTimesNanos = {System.nanoTime()}; private int offset; public MockSystemTimeSource() { @@ -34,6 +37,7 @@ public MockSystemTimeSource() { public MockSystemTimeSource(long time) { setSystemTimes(time); + setSystemTimesNanos(TimeUnit.MILLISECONDS.toNanos(time)); } public void setSystemTimes(long[] times) { @@ -41,7 +45,11 @@ public void setSystemTimes(long[] times) { } void setSystemTimes(long time) { - systemTimes = new long[] { time }; + systemTimes = new long[]{time}; + } + + void setSystemTimesNanos(long time) { + systemTimesNanos = new long[]{time}; } public void setTime(Calendar c) { @@ -56,10 +64,21 @@ public long getTime() { return systemTimes[offset]; } + @Override + public long getTimeFromNanos() { + if (systemTimesNanos.length - offset > 1) { + offset++; + } + return systemTimesNanos[offset]; + } + public void increment(long delta) { if (systemTimes.length - offset == 1) { systemTimes[offset] += delta; } + if (systemTimesNanos.length - offset == 1) { + systemTimesNanos[offset] += TimeUnit.MILLISECONDS.toNanos(delta); + } } @Override diff --git a/quickfixj-core/src/test/java/quickfix/SessionStateTest.java b/quickfixj-core/src/test/java/quickfix/SessionStateTest.java index dc0a5e8440..adf93079cf 100644 --- a/quickfixj-core/src/test/java/quickfix/SessionStateTest.java +++ b/quickfixj-core/src/test/java/quickfix/SessionStateTest.java @@ -19,6 +19,7 @@ package quickfix; +import java.util.concurrent.TimeUnit; import org.junit.After; import org.junit.Before; import org.junit.Test; @@ -57,7 +58,7 @@ public void testTimeoutDefaultsAreNonzero() { public void testTestRequestTiming() { SessionState state = new SessionState(new Object(), null, 0, false, null, Session.DEFAULT_TEST_REQUEST_DELAY_MULTIPLIER, Session.DEFAULT_HEARTBEAT_TIMEOUT_MULTIPLIER); - state.setLastReceivedTime(950); + state.setLastReceivedTimeNanos(TimeUnit.MILLISECONDS.toNanos(950)); state.setHeartBeatInterval(50); assertFalse("testRequest shouldn't be needed yet", state.isTestRequestNeeded()); for (int i = 0; i < 5; i++) { @@ -76,15 +77,15 @@ public void testSessionTimeout() { Session.DEFAULT_TEST_REQUEST_DELAY_MULTIPLIER, Session.DEFAULT_HEARTBEAT_TIMEOUT_MULTIPLIER); // session should timeout after 2.4 * 30 = 72 seconds - state.setLastReceivedTime(950_000); + state.setLastReceivedTimeNanos(TimeUnit.MILLISECONDS.toNanos(950_000)); - timeSource.setSystemTimes(1_000_000L); + timeSource.setSystemTimesNanos(TimeUnit.MILLISECONDS.toNanos(1_000_000L)); assertFalse("session is still valid", state.isTimedOut()); - timeSource.setSystemTimes(1_021_999L); + timeSource.setSystemTimesNanos(TimeUnit.MILLISECONDS.toNanos(1_021_999L)); assertFalse("session is still valid", state.isTimedOut()); - timeSource.setSystemTimes(1_022_000L); + timeSource.setSystemTimesNanos(TimeUnit.MILLISECONDS.toNanos(1_022_000L)); assertTrue("session timed out", state.isTimedOut()); } } From 93a11d3c1611b4cb8f8c92f4150f4da5bc2a220f Mon Sep 17 00:00:00 2001 From: Christoph John Date: Sun, 4 Jul 2021 00:40:50 +0200 Subject: [PATCH 14/41] Set state.setLastReceivedTimeNanos in Session --- quickfixj-core/src/main/java/quickfix/Session.java | 2 ++ quickfixj-core/src/test/java/quickfix/SessionStateTest.java | 1 + 2 files changed, 3 insertions(+) diff --git a/quickfixj-core/src/main/java/quickfix/Session.java b/quickfixj-core/src/main/java/quickfix/Session.java index 5a065fb3cc..d3cf2f52db 100644 --- a/quickfixj-core/src/main/java/quickfix/Session.java +++ b/quickfixj-core/src/main/java/quickfix/Session.java @@ -1745,6 +1745,7 @@ private boolean verify(Message msg, boolean checkTooHigh, boolean checkTooLow) UnsupportedMessageType, IOException { state.setLastReceivedTime(SystemTime.currentTimeMillis()); + state.setLastReceivedTimeNanos(SystemTime.currentTimeMillisFromNanos()); state.clearTestRequestCounter(); String msgType; @@ -2028,6 +2029,7 @@ private boolean generateLogon() throws IOException { logon.setBoolean(ResetSeqNumFlag.FIELD, true); } state.setLastReceivedTime(SystemTime.currentTimeMillis()); + state.setLastReceivedTimeNanos(SystemTime.currentTimeMillisFromNanos()); state.clearTestRequestCounter(); state.setLogonSent(true); logonAttempts++; diff --git a/quickfixj-core/src/test/java/quickfix/SessionStateTest.java b/quickfixj-core/src/test/java/quickfix/SessionStateTest.java index adf93079cf..7f1efdd573 100644 --- a/quickfixj-core/src/test/java/quickfix/SessionStateTest.java +++ b/quickfixj-core/src/test/java/quickfix/SessionStateTest.java @@ -47,6 +47,7 @@ public void testTimeoutDefaultsAreNonzero() { SessionState state = new SessionState(new Object(), null, 0, false, null, Session.DEFAULT_TEST_REQUEST_DELAY_MULTIPLIER, Session.DEFAULT_HEARTBEAT_TIMEOUT_MULTIPLIER); state.setLastReceivedTime(900); + state.setLastReceivedTimeNanos(TimeUnit.MILLISECONDS.toNanos(900)); assertFalse("logon timeout not init'ed", state.isLogonTimedOut()); state.setLogoutSent(true); From 1f075b7a396e5e8fa0026ace2035a8d8819081b5 Mon Sep 17 00:00:00 2001 From: Christoph John Date: Sun, 4 Jul 2021 16:19:13 +0200 Subject: [PATCH 15/41] Update maven.yml try to use AdoptOpenJDK --- .github/workflows/maven.yml | 5 +++-- 1 file changed, 3 insertions(+), 2 deletions(-) diff --git a/.github/workflows/maven.yml b/.github/workflows/maven.yml index 3d4c2c8542..29cafc88a0 100644 --- a/.github/workflows/maven.yml +++ b/.github/workflows/maven.yml @@ -17,11 +17,12 @@ jobs: name: Test JDK ${{ matrix.java }}, ${{ matrix.os }} steps: - - uses: actions/checkout@v1 + - uses: actions/checkout@v2 - name: Set up JDK - uses: actions/setup-java@v1 + uses: actions/setup-java@v2 with: + distribution: 'adopt' java-version: ${{ matrix.java }} - name: Disable NTP on macOS (https://github.com/actions/virtual-environments/issues/820) From e3c489b7a5dac59e847addc1c0d096e64e66b5aa Mon Sep 17 00:00:00 2001 From: Christoph John Date: Mon, 5 Jul 2021 00:51:41 +0200 Subject: [PATCH 16/41] Only call initializeHeader() (and setLastSentTime()) once per message --- quickfixj-core/src/main/java/quickfix/Session.java | 5 +++-- 1 file changed, 3 insertions(+), 2 deletions(-) diff --git a/quickfixj-core/src/main/java/quickfix/Session.java b/quickfixj-core/src/main/java/quickfix/Session.java index d3cf2f52db..13929d113a 100644 --- a/quickfixj-core/src/main/java/quickfix/Session.java +++ b/quickfixj-core/src/main/java/quickfix/Session.java @@ -752,7 +752,7 @@ private void setEnabled(boolean enabled) { } private void initializeHeader(Message.Header header) { - state.setLastSentTime(SystemTime.currentTimeMillis()); +// state.setLastSentTime(SystemTime.currentTimeMillis()); move to sendRaw() header.setString(BeginString.FIELD, sessionID.getBeginString()); header.setString(SenderCompID.FIELD, sessionID.getSenderCompID()); optionallySetID(header, SenderSubID.FIELD, sessionID.getSenderSubID()); @@ -2330,6 +2330,7 @@ private void resendMessages(Message receivedMessage, int beginSeqNo, int endSeqN generateSequenceReset(receivedMessage, begin, msgSeqNum); } getLog().onEvent("Resending message: " + msgSeqNum); + state.setLastSentTime(SystemTime.currentTimeMillis()); send(msg.toString()); begin = 0; appMessageJustSent = true; @@ -2641,7 +2642,7 @@ private boolean sendRaw(Message message, int num) { result = send(messageString); } } - + state.setLastSentTime(SystemTime.currentTimeMillis()); return result; } catch (final IOException e) { logThrowable(getLog(), "Error reading/writing in MessageStore", e); From 6f0e17e6b630ec97c49da020a7e6160440f8bd88 Mon Sep 17 00:00:00 2001 From: Christoph John Date: Mon, 5 Jul 2021 12:32:22 +0200 Subject: [PATCH 17/41] made `failed` volatile since it is read/written by different threads --- .../java/quickfix/test/acceptance/timer/TimerTestClient.java | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/quickfixj-core/src/test/java/quickfix/test/acceptance/timer/TimerTestClient.java b/quickfixj-core/src/test/java/quickfix/test/acceptance/timer/TimerTestClient.java index 43d51ffad0..e28ff0f833 100644 --- a/quickfixj-core/src/test/java/quickfix/test/acceptance/timer/TimerTestClient.java +++ b/quickfixj-core/src/test/java/quickfix/test/acceptance/timer/TimerTestClient.java @@ -58,7 +58,7 @@ public class TimerTestClient extends MessageCracker implements Application { private final Logger log = LoggerFactory.getLogger(TimerTestServer.class); private final SessionSettings settings = new SessionSettings(); private final CountDownLatch shutdownLatch = new CountDownLatch(1); - private boolean failed; + private volatile boolean failed; private final ScheduledExecutorService scheduledExecutor = Executors.newSingleThreadScheduledExecutor(); @Override From c15d0d89037f1c8abe7872e613f4f9c4ba6c1147 Mon Sep 17 00:00:00 2001 From: Christoph John Date: Mon, 5 Jul 2021 13:22:48 +0200 Subject: [PATCH 18/41] corrected sending of delayed message --- .../test/acceptance/timer/TimerTestServer.java | 14 ++++++-------- 1 file changed, 6 insertions(+), 8 deletions(-) diff --git a/quickfixj-core/src/test/java/quickfix/test/acceptance/timer/TimerTestServer.java b/quickfixj-core/src/test/java/quickfix/test/acceptance/timer/TimerTestServer.java index a1303b33c3..569ce3f77c 100644 --- a/quickfixj-core/src/test/java/quickfix/test/acceptance/timer/TimerTestServer.java +++ b/quickfixj-core/src/test/java/quickfix/test/acceptance/timer/TimerTestServer.java @@ -1,4 +1,4 @@ -/******************************************************************************* +/** ***************************************************************************** * Copyright (c) quickfixengine.org All rights reserved. * * This file is part of the QuickFIX FIX Engine @@ -15,8 +15,7 @@ * * Contact ask@quickfixengine.org if any conditions of this licensing * are not clear to you. - ******************************************************************************/ - + ***************************************************************************** */ package quickfix.test.acceptance.timer; import org.slf4j.Logger; @@ -54,6 +53,7 @@ * @author John Hensley */ public class TimerTestServer extends MessageCracker implements Application, Runnable { + SocketAcceptor acceptor; private final Logger log = LoggerFactory.getLogger(TimerTestServer.class); private final SessionSettings settings = new SessionSettings(); @@ -63,6 +63,7 @@ public class TimerTestServer extends MessageCracker implements Application, Runn private final ScheduledExecutorService scheduledExecutor = Executors.newSingleThreadScheduledExecutor(); private class DelayedTestRequest implements Runnable { + final SessionID sessionID; DelayedTestRequest(SessionID sessionID) { @@ -86,10 +87,7 @@ public void fromAdmin(Message message, SessionID sessionId) throws FieldNotFound IncorrectDataFormat, IncorrectTagValue, RejectLogon { // sleep to move our timer off from the client's if (message instanceof Logon) { - scheduledExecutor.schedule(() -> { - new DelayedTestRequest(sessionId); - }, 3000, TimeUnit.MILLISECONDS); - + scheduledExecutor.schedule(new DelayedTestRequest(sessionId), 3000, TimeUnit.MILLISECONDS); // new Timer().schedule(new DelayedTestRequest(sessionId), 3000); } } @@ -128,7 +126,7 @@ public void run() { try { HashMap defaults = new HashMap<>(); defaults.put("ConnectionType", "acceptor"); - defaults.put("SocketAcceptPort", "19888" ); + defaults.put("SocketAcceptPort", "19888"); defaults.put("StartTime", "00:00:00"); defaults.put("EndTime", "00:00:00"); defaults.put("SenderCompID", "ISLD"); From cca92086eab63851ed7c8e61b1ee247fff5d2a82 Mon Sep 17 00:00:00 2001 From: Christoph John Date: Mon, 5 Jul 2021 13:34:21 +0200 Subject: [PATCH 19/41] corrected usage of setLastSentTimeNanos --- quickfixj-core/src/main/java/quickfix/SessionState.java | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/quickfixj-core/src/main/java/quickfix/SessionState.java b/quickfixj-core/src/main/java/quickfix/SessionState.java index 03b7034d78..f2c4b9d0a1 100644 --- a/quickfixj-core/src/main/java/quickfix/SessionState.java +++ b/quickfixj-core/src/main/java/quickfix/SessionState.java @@ -146,7 +146,6 @@ public long getLastReceivedTimeNanos() { public void setLastReceivedTime(long lastReceivedTime) { synchronized (lock) { this.lastReceivedTime = lastReceivedTime; - this.lastReceivedTimeNanos = TimeUnit.MILLISECONDS.toNanos(lastReceivedTime); } } @@ -211,7 +210,8 @@ public void setLogonSent(boolean logonSent) { public boolean isLogonTimedOut() { synchronized (lock) { - return isLogonSent() && SystemTime.currentTimeMillis() - getLastReceivedTime() >= getLogonTimeoutMs(); +// return isLogonSent() && SystemTime.currentTimeMillis() - getLastReceivedTime() >= getLogonTimeoutMs(); + return isLogonSent() && SystemTime.currentTimeMillisFromNanos() - getLastReceivedTimeNanos()>= getLogonTimeoutMs(); } } From 47c0184bee6776483a5e356615be3a3088c2c9c5 Mon Sep 17 00:00:00 2001 From: Christoph John Date: Mon, 5 Jul 2021 14:41:00 +0200 Subject: [PATCH 20/41] added conversion from nano to millis --- quickfixj-core/src/main/java/quickfix/SessionState.java | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/quickfixj-core/src/main/java/quickfix/SessionState.java b/quickfixj-core/src/main/java/quickfix/SessionState.java index f2c4b9d0a1..2d9c096ea6 100644 --- a/quickfixj-core/src/main/java/quickfix/SessionState.java +++ b/quickfixj-core/src/main/java/quickfix/SessionState.java @@ -211,7 +211,7 @@ public void setLogonSent(boolean logonSent) { public boolean isLogonTimedOut() { synchronized (lock) { // return isLogonSent() && SystemTime.currentTimeMillis() - getLastReceivedTime() >= getLogonTimeoutMs(); - return isLogonSent() && SystemTime.currentTimeMillisFromNanos() - getLastReceivedTimeNanos()>= getLogonTimeoutMs(); + return isLogonSent() && TimeUnit.NANOSECONDS.toMillis(SystemTime.currentTimeMillisFromNanos() - getLastReceivedTimeNanos()) >= getLogonTimeoutMs(); } } From 090bb5baab8576bbdd792903ca41480ac1843a5d Mon Sep 17 00:00:00 2001 From: Christoph John Date: Mon, 5 Jul 2021 14:45:35 +0200 Subject: [PATCH 21/41] debug logging in failing test --- .../test/java/quickfix/SessionDisconnectConcurrentlyTest.java | 1 + 1 file changed, 1 insertion(+) diff --git a/quickfixj-core/src/test/java/quickfix/SessionDisconnectConcurrentlyTest.java b/quickfixj-core/src/test/java/quickfix/SessionDisconnectConcurrentlyTest.java index 815d5676d9..a28f1e6924 100644 --- a/quickfixj-core/src/test/java/quickfix/SessionDisconnectConcurrentlyTest.java +++ b/quickfixj-core/src/test/java/quickfix/SessionDisconnectConcurrentlyTest.java @@ -127,6 +127,7 @@ public void assertTestRequestOnSession(String text, SessionID sessionID) throws FieldNotFound { Message testRequest = sessionMessages.get(sessionID); assertNotNull("no message", testRequest); + System.out.println("XXXXX " + testRequest); assertEquals("wrong message", text, testRequest.getString(TestReqID.FIELD)); } From 31fdf84c64af8f2f7a77fe66ad07c103a2775708 Mon Sep 17 00:00:00 2001 From: Christoph John Date: Mon, 5 Jul 2021 23:33:03 +0200 Subject: [PATCH 22/41] improved test --- .../SessionDisconnectConcurrentlyTest.java | 44 ++++++------------- 1 file changed, 14 insertions(+), 30 deletions(-) diff --git a/quickfixj-core/src/test/java/quickfix/SessionDisconnectConcurrentlyTest.java b/quickfixj-core/src/test/java/quickfix/SessionDisconnectConcurrentlyTest.java index a28f1e6924..c9c54cacf8 100644 --- a/quickfixj-core/src/test/java/quickfix/SessionDisconnectConcurrentlyTest.java +++ b/quickfixj-core/src/test/java/quickfix/SessionDisconnectConcurrentlyTest.java @@ -19,7 +19,6 @@ package quickfix; -import org.junit.After; import org.junit.Assert; import org.junit.Test; import quickfix.field.BeginString; @@ -48,22 +47,15 @@ import static junit.framework.TestCase.assertNotNull; import static org.junit.Assert.assertEquals; import static org.junit.Assert.fail; +import quickfix.fix42.Heartbeat; public class SessionDisconnectConcurrentlyTest { - private TestAcceptorApplication testAcceptorApplication; - - @After - public void tearDown() throws Exception { - if (testAcceptorApplication != null) { - testAcceptorApplication.tearDown(); - } - } // QFJ-738 @Test(timeout = 15000) public void testConcurrentDisconnection() throws Exception { - testAcceptorApplication = new TestAcceptorApplication(1); - final Acceptor acceptor = createAcceptor(); + TestAcceptorApplication testAcceptorApplication = new TestAcceptorApplication(1); + final Acceptor acceptor = createAcceptor(testAcceptorApplication); final Initiator initiator = createInitiator(); try { acceptor.start(); @@ -71,7 +63,7 @@ public void testConcurrentDisconnection() throws Exception { testAcceptorApplication.waitForLogon(); - doSessionDispatchingTest(1); + doSessionDispatchingTest(1, testAcceptorApplication); } finally { MyThread thread = new MyThread(); thread.setDaemon(true); @@ -84,13 +76,11 @@ public void testConcurrentDisconnection() throws Exception { } } - private void doSessionDispatchingTest(int i) throws SessionNotFound, InterruptedException, + private void doSessionDispatchingTest(int i, TestAcceptorApplication testAcceptorApplication) throws SessionNotFound, InterruptedException, FieldNotFound { TestRequest message = new TestRequest(); message.set(new TestReqID("TEST" + i)); SessionID sessionID = getSessionIDForClient(i); - - testAcceptorApplication.setMessageLatch(new CountDownLatch(1)); Session.sendToTarget(message, sessionID); testAcceptorApplication.waitForMessages(); @@ -104,10 +94,11 @@ private SessionID getSessionIDForClient(int i) { private static class TestAcceptorApplication extends ApplicationAdapter { private final HashMap sessionMessages = new HashMap<>(); private final CountDownLatch logonLatch; - private CountDownLatch messageLatch; + private final CountDownLatch messageLatch; public TestAcceptorApplication(int countDown) { logonLatch = new CountDownLatch(countDown); + messageLatch = new CountDownLatch(1); } public void onLogon(SessionID sessionId) { @@ -117,9 +108,11 @@ public void onLogon(SessionID sessionId) { public void fromAdmin(Message message, SessionID sessionId) throws FieldNotFound, IncorrectDataFormat, IncorrectTagValue, RejectLogon { - sessionMessages.put(sessionId, message); - if (messageLatch != null) { - messageLatch.countDown(); + if (message instanceof Heartbeat) { + sessionMessages.put(sessionId, message); + if (messageLatch != null) { + messageLatch.countDown(); + } } } @@ -127,7 +120,6 @@ public void assertTestRequestOnSession(String text, SessionID sessionID) throws FieldNotFound { Message testRequest = sessionMessages.get(sessionID); assertNotNull("no message", testRequest); - System.out.println("XXXXX " + testRequest); assertEquals("wrong message", text, testRequest.getString(TestReqID.FIELD)); } @@ -139,11 +131,7 @@ public void waitForLogon() { } } - public synchronized void setMessageLatch(CountDownLatch messageLatch) { - this.messageLatch = messageLatch; - } - - public synchronized void waitForMessages() { + public void waitForMessages() { try { if (!messageLatch.await(10, TimeUnit.SECONDS)) { fail("Timed out waiting for message"); @@ -152,10 +140,6 @@ public synchronized void waitForMessages() { fail(e.getMessage()); } } - - public void tearDown() { - sessionMessages.clear(); - } } private Initiator createInitiator() throws ConfigError { @@ -188,7 +172,7 @@ private void configureInitiatorForSession(SessionSettings settings, int i, int p settings.setString(sessionID, "SocketConnectPort", Integer.toString(port)); } - private Acceptor createAcceptor() throws ConfigError { + private Acceptor createAcceptor(TestAcceptorApplication testAcceptorApplication) throws ConfigError { SessionSettings settings = new SessionSettings(); HashMap defaults = new HashMap<>(); defaults.put("ConnectionType", "acceptor"); From e155cc97b99cc3704da719fd9ae8737d2a058a89 Mon Sep 17 00:00:00 2001 From: Christoph John Date: Tue, 6 Jul 2021 00:08:23 +0200 Subject: [PATCH 23/41] again debug logging --- .../java/quickfix/SessionDisconnectConcurrentlyTest.java | 5 ++--- 1 file changed, 2 insertions(+), 3 deletions(-) diff --git a/quickfixj-core/src/test/java/quickfix/SessionDisconnectConcurrentlyTest.java b/quickfixj-core/src/test/java/quickfix/SessionDisconnectConcurrentlyTest.java index c9c54cacf8..e2bd9ccf81 100644 --- a/quickfixj-core/src/test/java/quickfix/SessionDisconnectConcurrentlyTest.java +++ b/quickfixj-core/src/test/java/quickfix/SessionDisconnectConcurrentlyTest.java @@ -110,9 +110,7 @@ public void fromAdmin(Message message, SessionID sessionId) throws FieldNotFound IncorrectDataFormat, IncorrectTagValue, RejectLogon { if (message instanceof Heartbeat) { sessionMessages.put(sessionId, message); - if (messageLatch != null) { - messageLatch.countDown(); - } + messageLatch.countDown(); } } @@ -120,6 +118,7 @@ public void assertTestRequestOnSession(String text, SessionID sessionID) throws FieldNotFound { Message testRequest = sessionMessages.get(sessionID); assertNotNull("no message", testRequest); + System.out.println("XXXXXX " + testRequest); assertEquals("wrong message", text, testRequest.getString(TestReqID.FIELD)); } From 2b7a21284795ccd57a00e3aa89aa867b7a7a7272 Mon Sep 17 00:00:00 2001 From: Christoph John Date: Tue, 6 Jul 2021 00:15:06 +0200 Subject: [PATCH 24/41] added missing synchronization around lastReceivedTimeNanos --- quickfixj-core/src/main/java/quickfix/SessionState.java | 4 +++- 1 file changed, 3 insertions(+), 1 deletion(-) diff --git a/quickfixj-core/src/main/java/quickfix/SessionState.java b/quickfixj-core/src/main/java/quickfix/SessionState.java index 2d9c096ea6..f9e8af8a6b 100644 --- a/quickfixj-core/src/main/java/quickfix/SessionState.java +++ b/quickfixj-core/src/main/java/quickfix/SessionState.java @@ -150,7 +150,9 @@ public void setLastReceivedTime(long lastReceivedTime) { } public void setLastReceivedTimeNanos(long lastReceivedTimeNanos) { - this.lastReceivedTimeNanos = lastReceivedTimeNanos; + synchronized (lock) { + this.lastReceivedTimeNanos = lastReceivedTimeNanos; + } } public long getLastSentTime() { From eac3519b8f0db1e7c0819ff38256d20da669d968 Mon Sep 17 00:00:00 2001 From: Christoph John Date: Tue, 6 Jul 2021 11:04:09 +0200 Subject: [PATCH 25/41] increased logging on maven build --- .github/workflows/maven.yml | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/.github/workflows/maven.yml b/.github/workflows/maven.yml index 29cafc88a0..482f20a13d 100644 --- a/.github/workflows/maven.yml +++ b/.github/workflows/maven.yml @@ -34,4 +34,4 @@ jobs: - name: Test with Maven env: MAVEN_OPTS: "-Xms3g -Xmx3g" - run: mvn test -B -V -D"java.util.logging.config.file"="logging.properties" -D"http.keepAlive"="false" -D"maven.wagon.http.pool"="false" -D"maven.wagon.httpconnectionManager.ttlSeconds"="120" + run: mvn test -B -V -D"http.keepAlive"="false" -D"maven.wagon.http.pool"="false" -D"maven.wagon.httpconnectionManager.ttlSeconds"="120" From bd01a0edd064a5a6f61b85bce1225852b424beba Mon Sep 17 00:00:00 2001 From: Christoph John Date: Tue, 6 Jul 2021 23:55:30 +0200 Subject: [PATCH 26/41] changed SessionConnector to use nanotime in waitForLogout() --- .../src/main/java/quickfix/mina/SessionConnector.java | 5 +++-- 1 file changed, 3 insertions(+), 2 deletions(-) diff --git a/quickfixj-core/src/main/java/quickfix/mina/SessionConnector.java b/quickfixj-core/src/main/java/quickfix/mina/SessionConnector.java index 29c09d7cba..49fc8225e1 100644 --- a/quickfixj-core/src/main/java/quickfix/mina/SessionConnector.java +++ b/quickfixj-core/src/main/java/quickfix/mina/SessionConnector.java @@ -53,6 +53,7 @@ import java.util.concurrent.ConcurrentHashMap; import org.apache.mina.core.future.CloseFuture; import org.apache.mina.core.service.IoService; +import quickfix.SystemTime; /** * An abstract base class for acceptors and initiators. Provides support for common functionality and also serves as an @@ -265,7 +266,7 @@ protected void logoutAllSessions(boolean forceDisconnect) { } protected void waitForLogout() { - long start = System.currentTimeMillis(); + long start = SystemTime.currentTimeMillisFromNanos(); Set loggedOnSessions; while (!(loggedOnSessions = getLoggedOnSessions()).isEmpty()) { try { @@ -273,7 +274,7 @@ protected void waitForLogout() { } catch (InterruptedException e) { log.error(e.getMessage(), e); } - final long elapsed = System.currentTimeMillis() - start; + final long elapsed = TimeUnit.NANOSECONDS.toMillis(SystemTime.currentTimeMillisFromNanos() - start); Iterator sessionItr = loggedOnSessions.iterator(); while (sessionItr.hasNext()) { Session session = sessionItr.next(); From ea33e9f1eeb4672448c02013843b247e2ccdb53f Mon Sep 17 00:00:00 2001 From: Christoph John Date: Wed, 7 Jul 2021 13:51:50 +0200 Subject: [PATCH 27/41] more debug output --- .../src/main/java/quickfix/Session.java | 2 +- .../src/main/java/quickfix/SessionState.java | 9 +++++--- .../SessionDisconnectConcurrentlyTest.java | 22 ++++++++++++++++++- .../test/java/quickfix/SessionStateTest.java | 7 +++--- 4 files changed, 32 insertions(+), 8 deletions(-) diff --git a/quickfixj-core/src/main/java/quickfix/Session.java b/quickfixj-core/src/main/java/quickfix/Session.java index 13929d113a..4372ddb525 100644 --- a/quickfixj-core/src/main/java/quickfix/Session.java +++ b/quickfixj-core/src/main/java/quickfix/Session.java @@ -1968,7 +1968,7 @@ public void next() throws IOException { LOG.warn("Heartbeat failure detected but deactivated"); } } else { - if (state.isTestRequestNeeded()) { + if (state.isTestRequestNeeded(sessionID)) { generateTestRequest("TEST"); getLog().onEvent("Sent test request TEST"); stateListener.onMissedHeartBeat(); diff --git a/quickfixj-core/src/main/java/quickfix/SessionState.java b/quickfixj-core/src/main/java/quickfix/SessionState.java index f9e8af8a6b..36f61e6742 100644 --- a/quickfixj-core/src/main/java/quickfix/SessionState.java +++ b/quickfixj-core/src/main/java/quickfix/SessionState.java @@ -121,8 +121,8 @@ public boolean isHeartBeatNeeded(SessionID sessionID) { // long millisSinceLastSentTime = SystemTime.currentTimeMillis() - getLastSentTime(); boolean name = millisSinceLastSentTime + 10 > getHeartBeatMillis() && getTestRequestCounter() == 0; // QFJ-448: allow 10 ms leeway since exact comparison causes skipped heartbeats occasionally - if (sessionID.equals(sessionID1) || sessionID.equals(sessionID2)) { - System.out.println("XXX " + sessionID + " isHeartBeatNeeded() = " + name); + if (sessionID.equals(sessionID1) || sessionID.equals(sessionID2) || "ACCEPTOR-1".equals(sessionID.getTargetCompID()) ) { + getLog().onEvent("isHeartBeatNeeded() = " + name + " millisSinceLastSent = " + millisSinceLastSentTime); } return name; } @@ -311,8 +311,11 @@ public void incrementTestRequestCounter() { } } - public boolean isTestRequestNeeded() { + public boolean isTestRequestNeeded(SessionID sessionID) { long millisSinceLastReceivedTime = timeSinceLastReceivedMessage(); + if (sessionID.equals(sessionID1) || sessionID.equals(sessionID2) || "ACCEPTOR-1".equals(sessionID.getTargetCompID()) ) { + getLog().onEvent("isTestRequestNeeded() - millisSinceLastReceived = " + millisSinceLastReceivedTime); + } return millisSinceLastReceivedTime >= ((1 + testRequestDelayMultiplier) * (getTestRequestCounter() + 1)) * getHeartBeatMillis(); } diff --git a/quickfixj-core/src/test/java/quickfix/SessionDisconnectConcurrentlyTest.java b/quickfixj-core/src/test/java/quickfix/SessionDisconnectConcurrentlyTest.java index e2bd9ccf81..d097f9269c 100644 --- a/quickfixj-core/src/test/java/quickfix/SessionDisconnectConcurrentlyTest.java +++ b/quickfixj-core/src/test/java/quickfix/SessionDisconnectConcurrentlyTest.java @@ -30,6 +30,7 @@ import quickfix.field.SendingTime; import quickfix.field.TargetCompID; import quickfix.field.TestReqID; +import quickfix.fix42.Heartbeat; import quickfix.fix42.TestRequest; import quickfix.mina.ProtocolFactory; @@ -47,10 +48,29 @@ import static junit.framework.TestCase.assertNotNull; import static org.junit.Assert.assertEquals; import static org.junit.Assert.fail; -import quickfix.fix42.Heartbeat; public class SessionDisconnectConcurrentlyTest { + + @Test + public void main() { + for (int i = 0; i < 100_000_000; i++) { + timeInvocation(); + } + } + + private static void timeInvocation() { + final long start = System.nanoTime(); + final long end = System.nanoTime(); + checkResult(end - start); + } + + private static void checkResult(final long l) { + if (l < 0) { + System.out.println("should not get here " + l); // removing reference to l parameter here "fixes" the bug + fail(); + } + } // QFJ-738 @Test(timeout = 15000) public void testConcurrentDisconnection() throws Exception { diff --git a/quickfixj-core/src/test/java/quickfix/SessionStateTest.java b/quickfixj-core/src/test/java/quickfix/SessionStateTest.java index 7f1efdd573..70a89f40d8 100644 --- a/quickfixj-core/src/test/java/quickfix/SessionStateTest.java +++ b/quickfixj-core/src/test/java/quickfix/SessionStateTest.java @@ -57,19 +57,20 @@ public void testTimeoutDefaultsAreNonzero() { @Test public void testTestRequestTiming() { + SessionID sessionID1 = new SessionID(FixVersions.BEGINSTRING_FIX44, "ISLD", "TW"); SessionState state = new SessionState(new Object(), null, 0, false, null, Session.DEFAULT_TEST_REQUEST_DELAY_MULTIPLIER, Session.DEFAULT_HEARTBEAT_TIMEOUT_MULTIPLIER); state.setLastReceivedTimeNanos(TimeUnit.MILLISECONDS.toNanos(950)); state.setHeartBeatInterval(50); - assertFalse("testRequest shouldn't be needed yet", state.isTestRequestNeeded()); + assertFalse("testRequest shouldn't be needed yet", state.isTestRequestNeeded(sessionID1)); for (int i = 0; i < 5; i++) { state.incrementTestRequestCounter(); } - assertFalse("testRequest should be needed", state.isTestRequestNeeded()); + assertFalse("testRequest should be needed", state.isTestRequestNeeded(sessionID1)); // set the heartbeat interval to something small and we shouldn't need it again state.setHeartBeatInterval(3); - assertFalse("testRequest shouldn't be needed yet", state.isTestRequestNeeded()); + assertFalse("testRequest shouldn't be needed yet", state.isTestRequestNeeded(sessionID1)); } @Test From d483b727bf75ac96b05ed2f686b1c7e16cc38805 Mon Sep 17 00:00:00 2001 From: Christoph John Date: Thu, 8 Jul 2021 00:13:56 +0200 Subject: [PATCH 28/41] even more debug logging --- .../src/main/java/quickfix/SessionState.java | 10 +++++++--- 1 file changed, 7 insertions(+), 3 deletions(-) diff --git a/quickfixj-core/src/main/java/quickfix/SessionState.java b/quickfixj-core/src/main/java/quickfix/SessionState.java index 36f61e6742..70806d1d70 100644 --- a/quickfixj-core/src/main/java/quickfix/SessionState.java +++ b/quickfixj-core/src/main/java/quickfix/SessionState.java @@ -115,13 +115,15 @@ long getHeartBeatMillis() { } SessionID sessionID1 = new SessionID(FixVersions.BEGINSTRING_FIX44, "ISLD", "TW"); - SessionID sessionID2 = new SessionID(FixVersions.BEGINSTRING_FIX44, "TW", "ISLD"); +// SessionID sessionID2 = new SessionID(FixVersions.BEGINSTRING_FIX44, "TW", "ISLD"); public boolean isHeartBeatNeeded(SessionID sessionID) { long millisSinceLastSentTime = TimeUnit.NANOSECONDS.toMillis(SystemTime.currentTimeMillisFromNanos() - getLastSentTimeNanos()); // long millisSinceLastSentTime = SystemTime.currentTimeMillis() - getLastSentTime(); boolean name = millisSinceLastSentTime + 10 > getHeartBeatMillis() && getTestRequestCounter() == 0; // QFJ-448: allow 10 ms leeway since exact comparison causes skipped heartbeats occasionally - if (sessionID.equals(sessionID1) || sessionID.equals(sessionID2) || "ACCEPTOR-1".equals(sessionID.getTargetCompID()) ) { + if (sessionID1.getSenderCompID().equals(sessionID.getSenderCompID()) + || sessionID1.getSenderCompID().equals(sessionID.getTargetCompID()) + || "ACCEPTOR-1".equals(sessionID.getTargetCompID())) { getLog().onEvent("isHeartBeatNeeded() = " + name + " millisSinceLastSent = " + millisSinceLastSentTime); } return name; @@ -313,7 +315,9 @@ public void incrementTestRequestCounter() { public boolean isTestRequestNeeded(SessionID sessionID) { long millisSinceLastReceivedTime = timeSinceLastReceivedMessage(); - if (sessionID.equals(sessionID1) || sessionID.equals(sessionID2) || "ACCEPTOR-1".equals(sessionID.getTargetCompID()) ) { + if (sessionID.getSenderCompID().equals(sessionID1.getSenderCompID()) + || sessionID.getTargetCompID().equals(sessionID1.getSenderCompID()) + || "ACCEPTOR-1".equals(sessionID.getTargetCompID())) { getLog().onEvent("isTestRequestNeeded() - millisSinceLastReceived = " + millisSinceLastReceivedTime); } return millisSinceLastReceivedTime >= ((1 + testRequestDelayMultiplier) * (getTestRequestCounter() + 1)) From 255e12f4a609a086e51d4c59eecf20c219d809d2 Mon Sep 17 00:00:00 2001 From: Christoph John Date: Thu, 8 Jul 2021 14:10:49 +0200 Subject: [PATCH 29/41] - removed unneded synchronization in ATApplication - use ScreenLogFactory in ATServer to see all logging --- .../quickfix/test/acceptance/ATApplication.java | 15 ++++++++------- .../java/quickfix/test/acceptance/ATServer.java | 4 ++-- 2 files changed, 10 insertions(+), 9 deletions(-) diff --git a/quickfixj-core/src/test/java/quickfix/test/acceptance/ATApplication.java b/quickfixj-core/src/test/java/quickfix/test/acceptance/ATApplication.java index 0d994ed124..f51a94919f 100644 --- a/quickfixj-core/src/test/java/quickfix/test/acceptance/ATApplication.java +++ b/quickfixj-core/src/test/java/quickfix/test/acceptance/ATApplication.java @@ -19,6 +19,7 @@ package quickfix.test.acceptance; +import java.util.concurrent.atomic.AtomicBoolean; import org.junit.Assert; import quickfix.Application; @@ -36,17 +37,17 @@ public class ATApplication implements Application { private final ATMessageCracker inboundCracker = new ATMessageCracker(); private final MessageCracker outboundCracker = new MessageCracker(new Object()); - private boolean isLoggedOn; + private AtomicBoolean isLoggedOn = new AtomicBoolean(false); public void onCreate(SessionID sessionID) { assertNoSessionLock(sessionID); Session.lookupSession(sessionID).reset(); } - public synchronized void onLogon(SessionID sessionID) { + public void onLogon(SessionID sessionID) { assertNoSessionLock(sessionID); - Assert.assertFalse("Already logged on", isLoggedOn); - isLoggedOn = true; + Assert.assertFalse("Already logged on", isLoggedOn.get()); + isLoggedOn.set(true); } private void assertNoSessionLock(SessionID sessionID) { @@ -56,11 +57,11 @@ private void assertNoSessionLock(SessionID sessionID) { Thread.holdsLock(session)); } - public synchronized void onLogout(SessionID sessionID) { + public void onLogout(SessionID sessionID) { assertNoSessionLock(sessionID); inboundCracker.reset(); - Assert.assertTrue("No logged on when logout is received", isLoggedOn); - isLoggedOn = false; + Assert.assertTrue("Not logged on when logout is received", isLoggedOn.get()); + isLoggedOn.set(false); } public void toAdmin(Message message, SessionID sessionID) { diff --git a/quickfixj-core/src/test/java/quickfix/test/acceptance/ATServer.java b/quickfixj-core/src/test/java/quickfix/test/acceptance/ATServer.java index 78714240fc..b094e46752 100644 --- a/quickfixj-core/src/test/java/quickfix/test/acceptance/ATServer.java +++ b/quickfixj-core/src/test/java/quickfix/test/acceptance/ATServer.java @@ -30,7 +30,6 @@ import quickfix.MemoryStoreFactory; import quickfix.MessageStoreFactory; import quickfix.RuntimeError; -import quickfix.SLF4JLogFactory; import quickfix.SessionID; import quickfix.SessionSettings; import quickfix.SocketAcceptor; @@ -53,6 +52,7 @@ import java.util.Set; import java.util.concurrent.CountDownLatch; import java.util.concurrent.TimeUnit; +import quickfix.ScreenLogFactory; import quickfix.Session; public class ATServer implements Runnable { @@ -164,7 +164,7 @@ public void run() { MessageStoreFactory factory = usingMemoryStore ? new MemoryStoreFactory() : new FileStoreFactory(settings); - quickfix.LogFactory logFactory = new SLF4JLogFactory(new SessionSettings()); + quickfix.LogFactory logFactory = new ScreenLogFactory(true, true, true, true); if (threaded) { acceptor = new ThreadedSocketAcceptor(application, factory, settings, logFactory, new DefaultMessageFactory()); From b20c490eedce54c63b87c21727c3324ac870aa85 Mon Sep 17 00:00:00 2001 From: Christoph John Date: Fri, 9 Jul 2021 00:26:55 +0200 Subject: [PATCH 30/41] - more debug logging on isHeartBeatNeeded() - set lastSentTime earlier in sendRaw() --- quickfixj-core/src/main/java/quickfix/Session.java | 5 ++--- quickfixj-core/src/main/java/quickfix/SessionState.java | 8 ++++++-- 2 files changed, 8 insertions(+), 5 deletions(-) diff --git a/quickfixj-core/src/main/java/quickfix/Session.java b/quickfixj-core/src/main/java/quickfix/Session.java index 4372ddb525..e175743b3f 100644 --- a/quickfixj-core/src/main/java/quickfix/Session.java +++ b/quickfixj-core/src/main/java/quickfix/Session.java @@ -2586,8 +2586,8 @@ private boolean sendRaw(Message message, int num) { final Message.Header header = message.getHeader(); final String msgType = header.getString(MsgType.FIELD); - initializeHeader(header); - + initializeHeader(header); // TODO still duplicate to generateXXX methods + state.setLastSentTime(SystemTime.currentTimeMillis()); if (num > 0) { header.setInt(MsgSeqNum.FIELD, num); } @@ -2642,7 +2642,6 @@ private boolean sendRaw(Message message, int num) { result = send(messageString); } } - state.setLastSentTime(SystemTime.currentTimeMillis()); return result; } catch (final IOException e) { logThrowable(getLog(), "Error reading/writing in MessageStore", e); diff --git a/quickfixj-core/src/main/java/quickfix/SessionState.java b/quickfixj-core/src/main/java/quickfix/SessionState.java index 70806d1d70..3965209da1 100644 --- a/quickfixj-core/src/main/java/quickfix/SessionState.java +++ b/quickfixj-core/src/main/java/quickfix/SessionState.java @@ -117,14 +117,18 @@ long getHeartBeatMillis() { SessionID sessionID1 = new SessionID(FixVersions.BEGINSTRING_FIX44, "ISLD", "TW"); // SessionID sessionID2 = new SessionID(FixVersions.BEGINSTRING_FIX44, "TW", "ISLD"); public boolean isHeartBeatNeeded(SessionID sessionID) { - long millisSinceLastSentTime = TimeUnit.NANOSECONDS.toMillis(SystemTime.currentTimeMillisFromNanos() - getLastSentTimeNanos()); + long currentTimeMillisFromNanos = SystemTime.currentTimeMillisFromNanos(); + long lastSentTimeNanos = getLastSentTimeNanos(); + long millisSinceLastSentTime = TimeUnit.NANOSECONDS.toMillis(currentTimeMillisFromNanos - lastSentTimeNanos); // long millisSinceLastSentTime = SystemTime.currentTimeMillis() - getLastSentTime(); boolean name = millisSinceLastSentTime + 10 > getHeartBeatMillis() && getTestRequestCounter() == 0; // QFJ-448: allow 10 ms leeway since exact comparison causes skipped heartbeats occasionally if (sessionID1.getSenderCompID().equals(sessionID.getSenderCompID()) || sessionID1.getSenderCompID().equals(sessionID.getTargetCompID()) || "ACCEPTOR-1".equals(sessionID.getTargetCompID())) { - getLog().onEvent("isHeartBeatNeeded() = " + name + " millisSinceLastSent = " + millisSinceLastSentTime); + getLog().onEvent("isHeartBeatNeeded() = " + name + " current=" + currentTimeMillisFromNanos + + " - lastSentTime=" + lastSentTimeNanos + + "= millisSinceLastSent=" + millisSinceLastSentTime); } return name; } From 0529659d62094568241f57279dd46e2ebf427e1d Mon Sep 17 00:00:00 2001 From: Christoph John Date: Fri, 9 Jul 2021 13:16:25 +0200 Subject: [PATCH 31/41] - prevent NPE on stopHandlingMessages() --- .../quickfix/mina/SingleThreadedEventHandlingStrategy.java | 4 +++- 1 file changed, 3 insertions(+), 1 deletion(-) diff --git a/quickfixj-core/src/main/java/quickfix/mina/SingleThreadedEventHandlingStrategy.java b/quickfixj-core/src/main/java/quickfix/mina/SingleThreadedEventHandlingStrategy.java index 8d2e88d3ea..81ed1cf872 100644 --- a/quickfixj-core/src/main/java/quickfix/mina/SingleThreadedEventHandlingStrategy.java +++ b/quickfixj-core/src/main/java/quickfix/mina/SingleThreadedEventHandlingStrategy.java @@ -194,7 +194,9 @@ public void stopHandlingMessages(boolean join) { stopHandlingMessages(); if (join) { try { - messageProcessingThread.join(); + if (messageProcessingThread != null) { + messageProcessingThread.join(); + } } catch (InterruptedException e) { sessionConnector.log.error("{} interrupted.", MESSAGE_PROCESSOR_THREAD_NAME); } From 08110c816a6267c01379ad20c83114748903af17 Mon Sep 17 00:00:00 2001 From: Christoph John Date: Fri, 9 Jul 2021 13:31:49 +0200 Subject: [PATCH 32/41] ignore Exception on stop since it spams the logs --- .../src/test/java/quickfix/test/acceptance/ATServer.java | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/quickfixj-core/src/test/java/quickfix/test/acceptance/ATServer.java b/quickfixj-core/src/test/java/quickfix/test/acceptance/ATServer.java index b094e46752..073fee1226 100644 --- a/quickfixj-core/src/test/java/quickfix/test/acceptance/ATServer.java +++ b/quickfixj-core/src/test/java/quickfix/test/acceptance/ATServer.java @@ -228,7 +228,7 @@ public void run() { acceptor.stop(true); } } catch (RuntimeException e) { - log.warn("Encountered Exception on stop", e); + // ignore on stop } finally { tearDownLatch.countDown(); } From c267e084e8691c37523c19cd19a6d04b5a510922 Mon Sep 17 00:00:00 2001 From: Christoph John Date: Fri, 9 Jul 2021 13:36:43 +0200 Subject: [PATCH 33/41] converted to JUnit4 test --- .../java/quickfix/mina/ssl/SecureSocketTest.java | 15 ++++++++++++--- 1 file changed, 12 insertions(+), 3 deletions(-) diff --git a/quickfixj-core/src/test/java/quickfix/mina/ssl/SecureSocketTest.java b/quickfixj-core/src/test/java/quickfix/mina/ssl/SecureSocketTest.java index f2012aea84..4b73184acc 100644 --- a/quickfixj-core/src/test/java/quickfix/mina/ssl/SecureSocketTest.java +++ b/quickfixj-core/src/test/java/quickfix/mina/ssl/SecureSocketTest.java @@ -19,7 +19,6 @@ package quickfix.mina.ssl; -import junit.framework.TestCase; import org.apache.mina.core.filterchain.IoFilterAdapter; import org.apache.mina.core.session.IoSession; import org.slf4j.Logger; @@ -43,14 +42,21 @@ import java.util.concurrent.CountDownLatch; import java.util.concurrent.TimeUnit; -public class SecureSocketTest extends TestCase { +import static org.junit.Assert.assertNotNull; +import static org.junit.Assert.assertTrue; +import org.junit.Before; +import org.junit.Test; + +public class SecureSocketTest { private final Logger log = LoggerFactory.getLogger(getClass()); private final int transportProtocol = ProtocolFactory.SOCKET; - protected void setUp() throws Exception { + @Before + public void setUp() throws Exception { SystemTime.setTimeSource(null); } + @Test public void testLogonWithBadCertificate() throws Exception { ServerThread serverThread = new ServerThread("nonexistent", "pwd"); try { @@ -85,10 +91,12 @@ public void exceptionCaught(NextFilter nextFilter, IoSession session, Throwable } } + @Test public void testLogonWithDefaultCertificate() throws Exception { doLogonTest(null, null); } + @Test public void testLogonWithCustomCertificate() throws Exception { doLogonTest("test.keystore", "quickfixjtestpw"); } @@ -103,6 +111,7 @@ public void testLogonWithCustomCertificate() throws Exception { * so that it's not cached by another test so that there are no false failures. * The test-client.keystore key store is just a copy of test.keystore under a different name. */ + @Test public void testLogonWithBadCertificateOnInitiatorSide() throws Exception { SessionID clientSessionID = new SessionID(FixVersions.BEGINSTRING_FIX42, "TW", "ISLD"); SessionSettings settings = getClientSessionSettings(clientSessionID); From a864f76a710a9e3a94be6e839ee803a41e3ceaa3 Mon Sep 17 00:00:00 2001 From: Christoph John Date: Fri, 9 Jul 2021 13:48:12 +0200 Subject: [PATCH 34/41] use free port to avoid using already used addresses --- .../quickfix/mina/ssl/SecureSocketTest.java | 25 +++++++++++-------- 1 file changed, 15 insertions(+), 10 deletions(-) diff --git a/quickfixj-core/src/test/java/quickfix/mina/ssl/SecureSocketTest.java b/quickfixj-core/src/test/java/quickfix/mina/ssl/SecureSocketTest.java index 4b73184acc..f54f70e3d4 100644 --- a/quickfixj-core/src/test/java/quickfix/mina/ssl/SecureSocketTest.java +++ b/quickfixj-core/src/test/java/quickfix/mina/ssl/SecureSocketTest.java @@ -21,6 +21,7 @@ import org.apache.mina.core.filterchain.IoFilterAdapter; import org.apache.mina.core.session.IoSession; +import org.apache.mina.util.AvailablePortFinder; import org.slf4j.Logger; import org.slf4j.LoggerFactory; import quickfix.ApplicationAdapter; @@ -39,6 +40,7 @@ import quickfix.test.util.ExpectedTestFailure; import java.util.HashMap; +import java.util.Map; import java.util.concurrent.CountDownLatch; import java.util.concurrent.TimeUnit; @@ -58,14 +60,15 @@ public void setUp() throws Exception { @Test public void testLogonWithBadCertificate() throws Exception { - ServerThread serverThread = new ServerThread("nonexistent", "pwd"); + int freePort = AvailablePortFinder.getNextAvailable(); + ServerThread serverThread = new ServerThread("nonexistent", "pwd", freePort); try { serverThread.setDaemon(true); serverThread.start(); serverThread.waitForInitialization(); SessionID clientSessionID = new SessionID(FixVersions.BEGINSTRING_FIX42, "TW", "ISLD"); - SessionSettings settings = getClientSessionSettings(clientSessionID); + SessionSettings settings = getClientSessionSettings(clientSessionID, freePort); ClientApplication clientApplication = new ClientApplication(); ThreadedSocketInitiator initiator = new ThreadedSocketInitiator(clientApplication, new MemoryStoreFactory(), settings, new DefaultMessageFactory()); @@ -113,8 +116,9 @@ public void testLogonWithCustomCertificate() throws Exception { */ @Test public void testLogonWithBadCertificateOnInitiatorSide() throws Exception { + int freePort = AvailablePortFinder.getNextAvailable(); SessionID clientSessionID = new SessionID(FixVersions.BEGINSTRING_FIX42, "TW", "ISLD"); - SessionSettings settings = getClientSessionSettings(clientSessionID); + SessionSettings settings = getClientSessionSettings(clientSessionID, freePort); // reset client side to invalid certs settings.setString(SSLSupport.SETTING_KEY_STORE_NAME, "test-client.keystore"); settings.setString(SSLSupport.SETTING_KEY_STORE_PWD, "wrong-pwd"); @@ -131,14 +135,15 @@ protected void execute() throws Throwable { } private void doLogonTest(String keyStoreName, String keyStorePassword) throws InterruptedException, ConfigError { - ServerThread serverThread = new ServerThread(keyStoreName, keyStorePassword); + int freePort = AvailablePortFinder.getNextAvailable(); + ServerThread serverThread = new ServerThread(keyStoreName, keyStorePassword, freePort); try { serverThread.setDaemon(true); serverThread.start(); serverThread.waitForInitialization(); SessionID clientSessionID = new SessionID(FixVersions.BEGINSTRING_FIX42, "TW", "ISLD"); - SessionSettings settings = getClientSessionSettings(clientSessionID); + SessionSettings settings = getClientSessionSettings(clientSessionID, freePort); ClientApplication clientApplication = new ClientApplication(); ThreadedSocketInitiator initiator = new ThreadedSocketInitiator(clientApplication, new MemoryStoreFactory(), settings, new DefaultMessageFactory()); @@ -158,14 +163,14 @@ private void doLogonTest(String keyStoreName, String keyStorePassword) throws In } } - private SessionSettings getClientSessionSettings(SessionID clientSessionID) { + private SessionSettings getClientSessionSettings(SessionID clientSessionID, int freePort) { SessionSettings settings = new SessionSettings(); - HashMap defaults = new HashMap<>(); + Map defaults = new HashMap<>(); defaults.put("ConnectionType", "initiator"); defaults.put("SocketConnectProtocol", ProtocolFactory.getTypeString(transportProtocol)); defaults.put("SocketUseSSL", "Y"); defaults.put("SocketConnectHost", "localhost"); - defaults.put("SocketConnectPort", "9877"); + defaults.put("SocketConnectPort", String.valueOf(freePort)); defaults.put("StartTime", "00:00:00"); defaults.put("EndTime", "00:00:00"); defaults.put("HeartBtInt", "30"); @@ -214,9 +219,9 @@ public void onLogon(SessionID sessionId) { private class ServerThread extends Thread { private final ATServer server; - public ServerThread(String keyStoreName, String keyStorePassword) { + public ServerThread(String keyStoreName, String keyStorePassword, int freePort) { super("test server"); - server = new ATServer(); + server = new ATServer(freePort, transportProtocol); server.setUseSSL(true); server.setKeyStoreName(keyStoreName); server.setKeyStorePassword(keyStorePassword); From 60bb3262f16ce352a3a9b7a5c447b9b69c5d777b Mon Sep 17 00:00:00 2001 From: Christoph John Date: Fri, 9 Jul 2021 14:54:25 +0200 Subject: [PATCH 35/41] prevent throwing RuntimeException, interrupt current thread instead --- .../java/quickfix/mina/SingleThreadedEventHandlingStrategy.java | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/quickfixj-core/src/main/java/quickfix/mina/SingleThreadedEventHandlingStrategy.java b/quickfixj-core/src/main/java/quickfix/mina/SingleThreadedEventHandlingStrategy.java index 81ed1cf872..e5174de215 100644 --- a/quickfixj-core/src/main/java/quickfix/mina/SingleThreadedEventHandlingStrategy.java +++ b/quickfixj-core/src/main/java/quickfix/mina/SingleThreadedEventHandlingStrategy.java @@ -76,7 +76,7 @@ public void onMessage(Session quickfixSession, Message message) { queueTracker.put(new SessionMessageEvent(quickfixSession, message)); } catch (InterruptedException e) { isStopped = true; - throw new RuntimeException(e); + Thread.currentThread().interrupt(); } } From 8f817cb7ea48a8024aabe5605404ad63f90e548b Mon Sep 17 00:00:00 2001 From: Christoph John Date: Sat, 10 Jul 2021 00:29:10 +0200 Subject: [PATCH 36/41] use ScreenLogFactory to see logging in github Java CI build --- quickfixj-core/src/test/java/quickfix/SocketAcceptorTest.java | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/quickfixj-core/src/test/java/quickfix/SocketAcceptorTest.java b/quickfixj-core/src/test/java/quickfix/SocketAcceptorTest.java index 6bee4e5b57..6d4a1eadd1 100644 --- a/quickfixj-core/src/test/java/quickfix/SocketAcceptorTest.java +++ b/quickfixj-core/src/test/java/quickfix/SocketAcceptorTest.java @@ -407,7 +407,7 @@ private Acceptor createAcceptor(TestAcceptorApplication testAcceptorApplication) SessionSettings settings = createAcceptorSettings(); MessageStoreFactory factory = new MemoryStoreFactory(); - quickfix.LogFactory logFactory = new SLF4JLogFactory(new SessionSettings()); + quickfix.LogFactory logFactory = new ScreenLogFactory(true, true, true, true); return new SocketAcceptor(testAcceptorApplication, factory, settings, logFactory, new DefaultMessageFactory()); } @@ -418,7 +418,7 @@ private Acceptor createAcceptorThreaded(TestAcceptorApplication testAcceptorAppl SessionSettings settings = createAcceptorSettings(); MessageStoreFactory factory = new MemoryStoreFactory(); - quickfix.LogFactory logFactory = new SLF4JLogFactory(new SessionSettings()); + quickfix.LogFactory logFactory = new ScreenLogFactory(true, true, true, true); return new ThreadedSocketAcceptor(testAcceptorApplication, factory, settings, logFactory, new DefaultMessageFactory()); } From ab146f90a08b1ec8596337c8c1a2e60cea9a9d4d Mon Sep 17 00:00:00 2001 From: Christoph John Date: Thu, 29 Jul 2021 12:07:11 +0200 Subject: [PATCH 37/41] increased logging --- quickfixj-core/src/test/resources/logging.properties | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/quickfixj-core/src/test/resources/logging.properties b/quickfixj-core/src/test/resources/logging.properties index 059a6959f2..353d97cee2 100644 --- a/quickfixj-core/src/test/resources/logging.properties +++ b/quickfixj-core/src/test/resources/logging.properties @@ -1,5 +1,5 @@ handlers=java.util.logging.ConsoleHandler -java.util.logging.ConsoleHandler.level=WARN +java.util.logging.ConsoleHandler.level=ALL java.util.logging.ConsoleHandler.formatter=java.util.logging.SimpleFormatter -.level=WARN \ No newline at end of file +.level=ALL From 2db46022ecf8429cf46150cc6293a2e6f88cf07f Mon Sep 17 00:00:00 2001 From: Christoph John Date: Thu, 29 Jul 2021 12:38:54 +0200 Subject: [PATCH 38/41] increased logging in ExpectMessageStep --- .../test/java/quickfix/test/acceptance/ExpectMessageStep.java | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/quickfixj-core/src/test/java/quickfix/test/acceptance/ExpectMessageStep.java b/quickfixj-core/src/test/java/quickfix/test/acceptance/ExpectMessageStep.java index ba4e3ac33e..9a821e40b3 100644 --- a/quickfixj-core/src/test/java/quickfix/test/acceptance/ExpectMessageStep.java +++ b/quickfixj-core/src/test/java/quickfix/test/acceptance/ExpectMessageStep.java @@ -73,7 +73,7 @@ private Map simpleParse(String data) { } public void run(TestResult result, final TestConnection connection) throws InterruptedException { - log.debug("expecting from client " + clientId + ": " + data + " " + expectedFields); + log.info("expecting from client " + clientId + ": " + data + " " + expectedFields); CharSequence message = connection.readMessage(clientId, TIMEOUT_IN_MS); if (message == null) { log.info("Dumping threads due to timeout when expecting a message..."); From bd1d7346a88afa2568011842fa0aa688c9364d5f Mon Sep 17 00:00:00 2001 From: Christoph John Date: Thu, 29 Jul 2021 12:39:45 +0200 Subject: [PATCH 39/41] increased logging in ConnectToServerStep --- .../test/java/quickfix/test/acceptance/ConnectToServerStep.java | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/quickfixj-core/src/test/java/quickfix/test/acceptance/ConnectToServerStep.java b/quickfixj-core/src/test/java/quickfix/test/acceptance/ConnectToServerStep.java index f64e7a084d..dc40f3c002 100644 --- a/quickfixj-core/src/test/java/quickfix/test/acceptance/ConnectToServerStep.java +++ b/quickfixj-core/src/test/java/quickfix/test/acceptance/ConnectToServerStep.java @@ -55,7 +55,7 @@ public void run(TestResult result, TestConnection connection) { } else { Assert.fail("incorrect connect command: " + command); } - log.debug("connecting to client {}", clientId); + log.info("connecting to client {}", clientId); long reconnectDelay = Long.getLong("atest.reconnectDelay", 50L); if (reconnectDelay > 0) { try { From 8831e32369a2906125274da8dbd971cbdb0bbcba Mon Sep 17 00:00:00 2001 From: Christoph John Date: Thu, 29 Jul 2021 12:40:46 +0200 Subject: [PATCH 40/41] increased logging in InitiateMessageStep --- .../test/java/quickfix/test/acceptance/InitiateMessageStep.java | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/quickfixj-core/src/test/java/quickfix/test/acceptance/InitiateMessageStep.java b/quickfixj-core/src/test/java/quickfix/test/acceptance/InitiateMessageStep.java index 030b3e5e74..3d4b0f25dd 100644 --- a/quickfixj-core/src/test/java/quickfix/test/acceptance/InitiateMessageStep.java +++ b/quickfixj-core/src/test/java/quickfix/test/acceptance/InitiateMessageStep.java @@ -96,7 +96,7 @@ public void run(TestResult result, TestConnection connection) { if (!message.contains("\00110=")) { message += "10=" + CHECKSUM_FORMAT.format(MessageUtils.checksum(message)) + '\001'; } - log.debug("sending to client " + clientId + ": " + message); + log.info("sending to client " + clientId + ": " + message); try { connection.sendMessage(clientId, message); } catch (IOException e) { From af5c5b0143035090e6a46b2be3f5063a5bbb64b8 Mon Sep 17 00:00:00 2001 From: Christoph John Date: Sat, 31 Jul 2021 23:26:42 +0200 Subject: [PATCH 41/41] correct SessionStateTest --- .../src/test/java/quickfix/SessionStateTest.java | 7 ++++--- 1 file changed, 4 insertions(+), 3 deletions(-) diff --git a/quickfixj-core/src/test/java/quickfix/SessionStateTest.java b/quickfixj-core/src/test/java/quickfix/SessionStateTest.java index d998ecdb8b..52406d191f 100644 --- a/quickfixj-core/src/test/java/quickfix/SessionStateTest.java +++ b/quickfixj-core/src/test/java/quickfix/SessionStateTest.java @@ -75,6 +75,7 @@ public void testTestRequestTiming() { @Test public void testHeartbeatTiming() { + SessionID sessionID1 = new SessionID(FixVersions.BEGINSTRING_FIX44, "ISLD", "TW"); // we set a HB interval of 2 seconds = 2000ms SessionState state = new SessionState(new Object(), null, 2 /* HB interval */, false, null, Session.DEFAULT_TEST_REQUEST_DELAY_MULTIPLIER, Session.DEFAULT_HEARTBEAT_TIMEOUT_MULTIPLIER); @@ -82,12 +83,12 @@ public void testHeartbeatTiming() { long now = System.currentTimeMillis(); timeSource.setSystemTimes(now); state.setLastSentTime(now); - assertFalse("heartbeat shouldn't be needed yet", state.isHeartBeatNeeded()); + assertFalse("heartbeat shouldn't be needed yet", state.isHeartBeatNeeded(sessionID1)); timeSource.increment(1000); - assertFalse("heartbeat shouldn't be needed yet", state.isHeartBeatNeeded()); + assertFalse("heartbeat shouldn't be needed yet", state.isHeartBeatNeeded(sessionID1)); timeSource.increment(1000); // current time is now 2000ms further since the start, i.e. the HB interval has elapsed - assertTrue("heartbeat should be needed", state.isHeartBeatNeeded()); + assertTrue("heartbeat should be needed", state.isHeartBeatNeeded(sessionID1)); } @Test