From d0787fc12fb988643d35a8f25098d9727b11cc32 Mon Sep 17 00:00:00 2001 From: nathan Date: Wed, 9 Sep 2020 12:30:07 +0200 Subject: [PATCH] Made logging easier --- test/dorkboxTest/network/BaseTest.kt | 14 +- .../network/rmi/RmiDelayedInvocationTest.kt | 6 +- ...ocationSpamTest.kt => RmiSpamAsyncTest.kt} | 69 ++------- .../network/rmi/RmiSpamSyncSuspendingTest.kt | 138 +++++++++++++++++ .../network/rmi/RmiSpamSyncTest.kt | 139 ++++++++++++++++++ 5 files changed, 300 insertions(+), 66 deletions(-) rename test/dorkboxTest/network/rmi/{RmiDelayedInvocationSpamTest.kt => RmiSpamAsyncTest.kt} (66%) create mode 100644 test/dorkboxTest/network/rmi/RmiSpamSyncSuspendingTest.kt create mode 100644 test/dorkboxTest/network/rmi/RmiSpamSyncTest.kt diff --git a/test/dorkboxTest/network/BaseTest.kt b/test/dorkboxTest/network/BaseTest.kt index faf2b48f..d8479b87 100644 --- a/test/dorkboxTest/network/BaseTest.kt +++ b/test/dorkboxTest/network/BaseTest.kt @@ -128,6 +128,12 @@ abstract class BaseTest { init { println("---- " + this.javaClass.simpleName) +// setLogLevel(Level.INFO) + setLogLevel(Level.TRACE) +// setLogLevel(Level.DEBUG) + } + + fun setLogLevel(level: Level) { // assume SLF4J is bound to logback in the current environment val rootLogger = LoggerFactory.getLogger(org.slf4j.Logger.ROOT_LOGGER_NAME) as Logger val context = rootLogger.loggerContext @@ -135,13 +141,7 @@ abstract class BaseTest { jc.context = context context.reset() // override default configuration -// rootLogger.setLevel(Level.OFF) - -// rootLogger.level = Level.INFO - rootLogger.level = Level.TRACE -// rootLogger.level = Level.DEBUG -// rootLogger.level = Level.ALL - + rootLogger.level = level // we only want error messages val kryoLogger = LoggerFactory.getLogger("com.esotericsoftware") as Logger diff --git a/test/dorkboxTest/network/rmi/RmiDelayedInvocationTest.kt b/test/dorkboxTest/network/rmi/RmiDelayedInvocationTest.kt index ef91a1bd..d63493e8 100644 --- a/test/dorkboxTest/network/rmi/RmiDelayedInvocationTest.kt +++ b/test/dorkboxTest/network/rmi/RmiDelayedInvocationTest.kt @@ -78,7 +78,7 @@ class RmiDelayedInvocationTest : BaseTest() { val totalRuns = 100 var abort = false - System.err.println("Running for $totalRuns iterations....") + connection.logger.error("Running for $totalRuns iterations....") for (i in 0 until totalRuns) { if (abort) { @@ -94,13 +94,13 @@ class RmiDelayedInvocationTest : BaseTest() { try { (iterateLock as Object).wait(1) } catch (e: InterruptedException) { - System.err.println("Failed after: $i") + connection.logger.error("Failed after: $i") e.printStackTrace() abort = true } } } - System.err.println("Done with delay invocation test") + connection.logger.error("Done with delay invocation test") stopEndPoints() } diff --git a/test/dorkboxTest/network/rmi/RmiDelayedInvocationSpamTest.kt b/test/dorkboxTest/network/rmi/RmiSpamAsyncTest.kt similarity index 66% rename from test/dorkboxTest/network/rmi/RmiDelayedInvocationSpamTest.kt rename to test/dorkboxTest/network/rmi/RmiSpamAsyncTest.kt index 2abb75e9..6689353c 100644 --- a/test/dorkboxTest/network/rmi/RmiDelayedInvocationSpamTest.kt +++ b/test/dorkboxTest/network/rmi/RmiSpamAsyncTest.kt @@ -16,8 +16,6 @@ package dorkboxTest.network.rmi import ch.qos.logback.classic.Level -import ch.qos.logback.classic.Logger -import ch.qos.logback.classic.joran.JoranConfigurator import dorkbox.network.Client import dorkbox.network.Configuration import dorkbox.network.Server @@ -27,74 +25,30 @@ import dorkboxTest.network.BaseTest import kotlinx.coroutines.runBlocking import org.junit.Assert import org.junit.Test -import org.slf4j.LoggerFactory import java.util.concurrent.atomic.AtomicLong -class RmiDelayedInvocationSpamTest : BaseTest() { +class RmiSpamAsyncTest : BaseTest() { private val counter = AtomicLong(0) private val RMI_ID = 12251 - var async = true - - private fun setupLogBefore() { - // assume SLF4J is bound to logback in the current environment - val rootLogger = LoggerFactory.getLogger(org.slf4j.Logger.ROOT_LOGGER_NAME) as Logger - val context = rootLogger.loggerContext - val jc = JoranConfigurator() - jc.context = context - context.reset() // override default configuration - + init { // the logger cannot keep-up if it's on trace - rootLogger.level = Level.DEBUG - } - - private fun setupLogAfter() { - // assume SLF4J is bound to logback in the current environment - val rootLogger = LoggerFactory.getLogger(org.slf4j.Logger.ROOT_LOGGER_NAME) as Logger - val context = rootLogger.loggerContext - val jc = JoranConfigurator() - jc.context = context - context.reset() // override default configuration - - // the logger cannot keep-up if it's on trace - rootLogger.level = Level.TRACE + setLogLevel(Level.DEBUG) } @Test - fun rmiNetwork() { + fun rmiNetworkAsync() { runBlocking { - async = false rmi { configuration -> configuration.enableIpcForLoopback = false } } } - @Test - fun rmiNetworkAync() { - setupLogBefore() - runBlocking { - async = true - rmi { configuration -> - configuration.enableIpcForLoopback = false - } - } - } - - @Test - fun rmiIpc() { - runBlocking { - async = false - rmi() - } - } - @Test fun rmiIpcAsync() { - setupLogBefore() runBlocking { - async = true rmi() } } @@ -106,8 +60,8 @@ class RmiDelayedInvocationSpamTest : BaseTest() { suspend fun rmi(config: (Configuration) -> Unit = {}) { val server: Server - val mod = if (async) 10_000L else 200L - val totalRuns = if (async) 1_000_000 else 1_000 + val mod = 100_000L + val totalRuns = 1_000_000 run { val configuration = serverConfig() @@ -123,23 +77,24 @@ class RmiDelayedInvocationSpamTest : BaseTest() { } + val client: Client run { val configuration = clientConfig() config(configuration) - val client = Client(configuration) + client = Client(configuration) addEndPoint(client) client.onConnect { connection -> val remoteObject = connection.getGlobalObject(RMI_ID) val obj = remoteObject as RemoteObject - obj.async = async + obj.async = true var started = false for (i in 0 until totalRuns) { if (!started) { started = true - System.err.println("Running for $totalRuns iterations....") + connection.logger.error("Running for $totalRuns iterations....") } if (i % mod == 0L) { @@ -150,7 +105,7 @@ class RmiDelayedInvocationSpamTest : BaseTest() { try { remoteObject.setOther(i.toLong()) } catch (e: Exception) { - System.err.println("Timeout when calling RMI method") + connection.logger.error("Timeout when calling RMI method") e.printStackTrace() } } @@ -165,6 +120,8 @@ class RmiDelayedInvocationSpamTest : BaseTest() { waitForThreads(200) Assert.assertEquals(totalRuns.toLong(), counter.get()) + client.logger.error("kryos generated: ${client.config.serialization.getInitializedKryoCount()}") + server.logger.error("kryos generated: ${server.config.serialization.getInitializedKryoCount()}") } private interface TestObject { diff --git a/test/dorkboxTest/network/rmi/RmiSpamSyncSuspendingTest.kt b/test/dorkboxTest/network/rmi/RmiSpamSyncSuspendingTest.kt new file mode 100644 index 00000000..7c2cedae --- /dev/null +++ b/test/dorkboxTest/network/rmi/RmiSpamSyncSuspendingTest.kt @@ -0,0 +1,138 @@ +/* + * Copyright 2020 dorkbox, llc + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ +package dorkboxTest.network.rmi + +import dorkbox.network.Client +import dorkbox.network.Configuration +import dorkbox.network.Server +import dorkbox.network.connection.Connection +import dorkbox.network.rmi.RemoteObject +import dorkboxTest.network.BaseTest +import kotlinx.coroutines.runBlocking +import org.junit.Assert +import org.junit.Test +import java.util.concurrent.atomic.AtomicLong + +class RmiSpamSyncSuspendingTest : BaseTest() { + private val counter = AtomicLong(0) + + private val RMI_ID = 12251 + + init { + // the logger cannot keep-up if it's on trace + setLogLevel(ch.qos.logback.classic.Level.DEBUG) + } + + @Test + fun rmiNetwork() { + runBlocking { + rmi { configuration -> + configuration.enableIpcForLoopback = false + } + } + } + + @Test + fun rmiIpc() { + runBlocking { + rmi() + } + } + + + /** + * In this test the server has two objects in an object space. The client + * uses the first remote object to get the second remote object. + */ + suspend fun rmi(config: (Configuration) -> Unit = {}) { + val server: Server + + val mod = 400L + val totalRuns = 4_000 + + run { + val configuration = serverConfig() + config(configuration) + + configuration.serialization.registerRmi(TestObject::class.java, TestObjectImpl::class.java) + + server = Server(configuration) + addEndPoint(server) + + server.saveGlobalObject(TestObjectImpl(counter), RMI_ID) + server.bind() + } + + + val client: Client + run { + val configuration = clientConfig() + config(configuration) + + client = Client(configuration) + addEndPoint(client) + + client.onConnect { connection -> + val remoteObject = connection.getGlobalObject(RMI_ID) + val obj = remoteObject as RemoteObject + obj.async = false + + var started = false + for (i in 0 until totalRuns) { + if (!started) { + started = true + connection.logger.error("Running for $totalRuns iterations....") + } + + if (i % mod == 0L) { + // this doesn't always output to the console. weird. + client.logger.error("$i") + } + + try { + remoteObject.setOther(i.toLong()) + } catch (e: Exception) { + connection.logger.error("Timeout when calling RMI method") + e.printStackTrace() + } + } + + // have to do this first, so it will wait for the client responses! + // if we close the client first, the connection will be closed, and the responses will never arrive to the server + stopEndPoints() + } + + client.connect() + } + + waitForThreads() + Assert.assertEquals(totalRuns.toLong(), counter.get()) + client.logger.error("kryos generated: ${client.config.serialization.getInitializedKryoCount()}") + server.logger.error("kryos generated: ${server.config.serialization.getInitializedKryoCount()}") + } + + private interface TestObject { + suspend fun setOther(value: Long): Boolean + } + + private class TestObjectImpl(private val counter: AtomicLong) : TestObject { + @Override + override suspend fun setOther(aFloat: Long): Boolean { + counter.getAndIncrement() + return true + } + } +} diff --git a/test/dorkboxTest/network/rmi/RmiSpamSyncTest.kt b/test/dorkboxTest/network/rmi/RmiSpamSyncTest.kt new file mode 100644 index 00000000..64cbbc77 --- /dev/null +++ b/test/dorkboxTest/network/rmi/RmiSpamSyncTest.kt @@ -0,0 +1,139 @@ +/* + * Copyright 2020 dorkbox, llc + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ +package dorkboxTest.network.rmi + +import ch.qos.logback.classic.Level +import dorkbox.network.Client +import dorkbox.network.Configuration +import dorkbox.network.Server +import dorkbox.network.connection.Connection +import dorkbox.network.rmi.RemoteObject +import dorkboxTest.network.BaseTest +import kotlinx.coroutines.runBlocking +import org.junit.Assert +import org.junit.Test +import java.util.concurrent.atomic.AtomicLong + +class RmiSpamSyncTest : BaseTest() { + private val counter = AtomicLong(0) + + private val RMI_ID = 12251 + + init { + // the logger cannot keep-up if it's on trace + setLogLevel(Level.DEBUG) + } + + @Test + fun rmiNetwork() { + runBlocking { + rmi { configuration -> + configuration.enableIpcForLoopback = false + } + } + } + + @Test + fun rmiIpc() { + runBlocking { + rmi() + } + } + + + /** + * In this test the server has two objects in an object space. The client + * uses the first remote object to get the second remote object. + */ + suspend fun rmi(config: (Configuration) -> Unit = {}) { + val server: Server + + val mod = 400L + val totalRuns = 1_000 + + run { + val configuration = serverConfig() + config(configuration) + + configuration.serialization.registerRmi(TestObject::class.java, TestObjectImpl::class.java) + + server = Server(configuration) + addEndPoint(server) + + server.saveGlobalObject(TestObjectImpl(counter), RMI_ID) + server.bind() + } + + + val client: Client + run { + val configuration = clientConfig() + config(configuration) + + client = Client(configuration) + addEndPoint(client) + + client.onConnect { connection -> + val remoteObject = connection.getGlobalObject(RMI_ID) + val obj = remoteObject as RemoteObject + obj.async = false + + var started = false + for (i in 0 until totalRuns) { + if (!started) { + started = true + connection.logger.error("Running for $totalRuns iterations....") + } + + if (i % mod == 0L) { + // this doesn't always output to the console. weird. + client.logger.error("$i") + } + + try { + remoteObject.setOther(i.toLong()) + } catch (e: Exception) { + connection.logger.error("Timeout when calling RMI method") + e.printStackTrace() + } + } + + // have to do this first, so it will wait for the client responses! + // if we close the client first, the connection will be closed, and the responses will never arrive to the server + stopEndPoints() + } + + client.connect() + } + + waitForThreads() + Assert.assertEquals(totalRuns.toLong(), counter.get()) + client.logger.error("kryos generated: ${client.config.serialization.getInitializedKryoCount()}") + server.logger.error("kryos generated: ${server.config.serialization.getInitializedKryoCount()}") + } + + private interface TestObject { + fun setOther(value: Long): Boolean + } + + private class TestObjectImpl(private val counter: AtomicLong) : TestObject { + @Override + override fun setOther(aFloat: Long): Boolean { + counter.getAndIncrement() + return true + } + } +}