From 209f5c8a259e3faa84c2fd86436e59541fd689e2 Mon Sep 17 00:00:00 2001 From: Shams Asari Date: Mon, 20 Mar 2017 15:41:13 +0000 Subject: [PATCH] Logging fixes, including broken --logging-level cmd line arg --- .../net/corda/core/utilities/Logging.kt | 6 +-- .../net/corda/node/driver/DriverTests.kt | 34 ++++++++++++---- .../main/kotlin/net/corda/node/ArgsParser.kt | 1 + node/src/main/kotlin/net/corda/node/Corda.kt | 39 +++++++++--------- .../kotlin/net/corda/node/driver/Driver.kt | 40 +++++++++---------- .../statemachine/FlowStateMachineImpl.kt | 11 +---- 6 files changed, 70 insertions(+), 61 deletions(-) diff --git a/core/src/main/kotlin/net/corda/core/utilities/Logging.kt b/core/src/main/kotlin/net/corda/core/utilities/Logging.kt index b126728e6b..c34039a4c6 100644 --- a/core/src/main/kotlin/net/corda/core/utilities/Logging.kt +++ b/core/src/main/kotlin/net/corda/core/utilities/Logging.kt @@ -3,7 +3,6 @@ package net.corda.core.utilities import org.apache.logging.log4j.Level import org.apache.logging.log4j.LogManager import org.apache.logging.log4j.core.LoggerContext -import org.apache.logging.log4j.core.appender.ConsoleAppender import org.apache.logging.log4j.core.config.LoggerConfig import org.slf4j.LoggerFactory import kotlin.reflect.KClass @@ -56,10 +55,7 @@ object LogHelper { val loggerContext = LogManager.getContext(false) as LoggerContext val config = loggerContext.configuration val loggerConfig = LoggerConfig(name, level, false) - val appender = config.appenders.map { it.value as? ConsoleAppender }.singleOrNull() - appender?.let { - loggerConfig.addAppender(appender, null, null) - } + loggerConfig.addAppender(config.appenders["Console-Appender"], null, null) config.removeLogger(name) config.addLogger(name, loggerConfig) loggerContext.updateLoggers(config) diff --git a/node/src/integration-test/kotlin/net/corda/node/driver/DriverTests.kt b/node/src/integration-test/kotlin/net/corda/node/driver/DriverTests.kt index 0b4c8d0210..c4c61ffed7 100644 --- a/node/src/integration-test/kotlin/net/corda/node/driver/DriverTests.kt +++ b/node/src/integration-test/kotlin/net/corda/node/driver/DriverTests.kt @@ -1,19 +1,24 @@ package net.corda.node.driver -import com.google.common.net.HostAndPort +import net.corda.core.div import net.corda.core.getOrThrow +import net.corda.core.list import net.corda.core.node.NodeInfo import net.corda.core.node.services.ServiceInfo +import net.corda.core.readLines +import net.corda.node.LOGS_DIRECTORY_NAME import net.corda.node.services.api.RegulatorService import net.corda.node.services.messaging.ArtemisMessagingComponent import net.corda.node.services.transactions.SimpleNotaryService +import org.assertj.core.api.Assertions.assertThat import org.junit.Test +import java.nio.file.Paths import java.util.concurrent.Executors - +import java.util.concurrent.ScheduledExecutorService class DriverTests { companion object { - val executorService = Executors.newScheduledThreadPool(2) + val executorService: ScheduledExecutorService = Executors.newScheduledThreadPool(2) fun nodeMustBeUp(nodeInfo: NodeInfo) { val hostAndPort = ArtemisMessagingComponent.toHostAndPort(nodeInfo.address) @@ -29,7 +34,7 @@ class DriverTests { } @Test - fun simpleNodeStartupShutdownWorks() { + fun `simple node startup and shutdown`() { val (notary, regulator) = driver { val notary = startNode("TestNotary", setOf(ServiceInfo(SimpleNotaryService.type))) val regulator = startNode("Regulator", setOf(ServiceInfo(RegulatorService.type))) @@ -43,7 +48,7 @@ class DriverTests { } @Test - fun startingNodeWithNoServicesWorks() { + fun `starting node with no services`() { val noService = driver { val noService = startNode("NoService") nodeMustBeUp(noService.getOrThrow().nodeInfo) @@ -53,12 +58,25 @@ class DriverTests { } @Test - fun randomFreePortAllocationWorks() { - val nodeInfo = driver(portAllocation = PortAllocation.RandomFree) { + fun `random free port allocation`() { + val nodeHandle = driver(portAllocation = PortAllocation.RandomFree) { val nodeInfo = startNode("NoService") nodeMustBeUp(nodeInfo.getOrThrow().nodeInfo) nodeInfo.getOrThrow() } - nodeMustBeDown(nodeInfo.nodeInfo) + nodeMustBeDown(nodeHandle.nodeInfo) + } + + @Test + fun `debug mode enables debug logging level`() { + // Make sure we're using the log4j2 config which writes to the log file + val logConfigFile = Paths.get("..", "config", "dev", "log4j2.xml").toAbsolutePath() + assertThat(logConfigFile).isRegularFile() + driver(isDebug = true, systemProperties = mapOf("log4j.configurationFile" to logConfigFile.toString())) { + val baseDirectory = startNode("Alice").getOrThrow().configuration.baseDirectory + val logFile = (baseDirectory / LOGS_DIRECTORY_NAME).list { it.sorted().findFirst().get() } + val debugLinesPresent = logFile.readLines { lines -> lines.anyMatch { line -> line.startsWith("[DEBUG]") } } + assertThat(debugLinesPresent).isTrue() + } } } diff --git a/node/src/main/kotlin/net/corda/node/ArgsParser.kt b/node/src/main/kotlin/net/corda/node/ArgsParser.kt index e8c30d11c8..3aadc5fa8d 100644 --- a/node/src/main/kotlin/net/corda/node/ArgsParser.kt +++ b/node/src/main/kotlin/net/corda/node/ArgsParser.kt @@ -10,6 +10,7 @@ import java.io.PrintStream import java.nio.file.Path import java.nio.file.Paths +// NOTE: Do not use any logger in this class as args parsing is done before the logger is setup. class ArgsParser { private val optionParser = OptionParser() // The intent of allowing a command line configurable directory and config path is to allow deployment flexibility. diff --git a/node/src/main/kotlin/net/corda/node/Corda.kt b/node/src/main/kotlin/net/corda/node/Corda.kt index 1425936ba2..105eaed8b8 100644 --- a/node/src/main/kotlin/net/corda/node/Corda.kt +++ b/node/src/main/kotlin/net/corda/node/Corda.kt @@ -1,8 +1,8 @@ @file:JvmName("Corda") package net.corda.node -import com.typesafe.config.Config import com.jcabi.manifests.Manifests +import com.typesafe.config.Config import com.typesafe.config.ConfigException import joptsimple.OptionException import net.corda.core.* @@ -31,19 +31,12 @@ fun printBasicNodeInfo(description: String, info: String? = null) { LoggerFactory.getLogger(loggerName).info(msg) } +val LOGS_DIRECTORY_NAME = "logs" + fun main(args: Array) { val startTime = System.currentTimeMillis() checkJavaVersion() - // Manifest properties are only available if running from the corda jar - fun manifestValue(name: String): String? = if (Manifests.exists(name)) Manifests.read(name) else null - - val nodeVersionInfo = NodeVersionInfo( - manifestValue("Corda-Version")?.let { Version.parse(it) } ?: Version(0, 0, false), - manifestValue("Corda-Revision") ?: "Unknown", - manifestValue("Corda-Vendor") ?: "Unknown" - ) - val argsParser = ArgsParser() val cmdlineOptions = try { @@ -54,6 +47,23 @@ fun main(args: Array) { exitProcess(1) } + // Set up logging. These properties are referenced from the XML config file. + val loggingLevel = cmdlineOptions.loggingLevel.name.toLowerCase() + System.setProperty("defaultLogLevel", loggingLevel) + if (cmdlineOptions.logToConsole) { + System.setProperty("consoleLogLevel", loggingLevel) + renderBasicInfoToConsole = false + } + + // Manifest properties are only available if running from the corda jar + fun manifestValue(name: String): String? = if (Manifests.exists(name)) Manifests.read(name) else null + + val nodeVersionInfo = NodeVersionInfo( + manifestValue("Corda-Version")?.let { Version.parse(it) } ?: Version(0, 0, false), + manifestValue("Corda-Revision") ?: "Unknown", + manifestValue("Corda-Vendor") ?: "Unknown" + ) + if (cmdlineOptions.isVersion) { println("${nodeVersionInfo.vendor} ${nodeVersionInfo.version}") println("Revision ${nodeVersionInfo.revision}") @@ -66,16 +76,9 @@ fun main(args: Array) { exitProcess(0) } - // Set up logging. These properties are referenced from the XML config file. - System.setProperty("defaultLogLevel", cmdlineOptions.loggingLevel.name.toLowerCase()) - if (cmdlineOptions.logToConsole) { - System.setProperty("consoleLogLevel", cmdlineOptions.loggingLevel.name.toLowerCase()) - renderBasicInfoToConsole = false - } - drawBanner(nodeVersionInfo) - System.setProperty("log-path", (cmdlineOptions.baseDirectory / "logs").toString()) + System.setProperty("log-path", (cmdlineOptions.baseDirectory / LOGS_DIRECTORY_NAME).toString()) val log = LoggerFactory.getLogger("Main") printBasicNodeInfo("Logs can be found in", System.getProperty("log-path")) diff --git a/node/src/main/kotlin/net/corda/node/driver/Driver.kt b/node/src/main/kotlin/net/corda/node/driver/Driver.kt index 78daed52dc..58ec2c0cb7 100644 --- a/node/src/main/kotlin/net/corda/node/driver/Driver.kt +++ b/node/src/main/kotlin/net/corda/node/driver/Driver.kt @@ -8,7 +8,6 @@ import com.google.common.util.concurrent.ListenableFuture import com.google.common.util.concurrent.SettableFuture import com.typesafe.config.Config import com.typesafe.config.ConfigRenderOptions -import net.corda.nodeapi.config.SSLConfiguration import net.corda.core.* import net.corda.core.crypto.Party import net.corda.core.messaging.CordaRPCOps @@ -16,6 +15,7 @@ import net.corda.core.node.NodeInfo import net.corda.core.node.services.ServiceInfo import net.corda.core.node.services.ServiceType import net.corda.core.utilities.loggerFor +import net.corda.node.LOGS_DIRECTORY_NAME import net.corda.node.services.User import net.corda.node.services.config.ConfigHelper import net.corda.node.services.config.FullNodeConfiguration @@ -25,6 +25,7 @@ import net.corda.node.services.messaging.NodeMessagingClient import net.corda.node.services.network.NetworkMapService import net.corda.node.services.transactions.RaftValidatingNotaryService import net.corda.node.utilities.ServiceIdentityGenerator +import net.corda.nodeapi.config.SSLConfiguration import okhttp3.OkHttpClient import okhttp3.Request import org.slf4j.Logger @@ -146,6 +147,7 @@ sealed class PortAllocation { * and may be specified in [DriverDSL.startNode]. * @param portAllocation The port allocation strategy to use for the messaging and the web server addresses. Defaults to incremental. * @param debugPortAllocation The port allocation strategy to use for jvm debugging. Defaults to incremental. + * @param systemProperties A Map of extra system properties which will be given to each new node. Defaults to empty. * @param useTestClock If true the test clock will be used in Node. * @param isDebug Indicates whether the spawned nodes should start in jdwt debug mode and have debug level logging. * @param dsl The dsl itself. @@ -157,12 +159,14 @@ fun driver( driverDirectory: Path = Paths.get("build", getTimestampAsDirectoryName()), portAllocation: PortAllocation = PortAllocation.Incremental(10000), debugPortAllocation: PortAllocation = PortAllocation.Incremental(5005), + systemProperties: Map = emptyMap(), useTestClock: Boolean = false, dsl: DriverDSLExposedInterface.() -> A ) = genericDriver( driverDsl = DriverDSL( portAllocation = portAllocation, debugPortAllocation = debugPortAllocation, + systemProperties = systemProperties, driverDirectory = driverDirectory.toAbsolutePath(), useTestClock = useTestClock, isDebug = isDebug @@ -266,6 +270,7 @@ private fun poll( open class DriverDSL( val portAllocation: PortAllocation, val debugPortAllocation: PortAllocation, + val systemProperties: Map, val driverDirectory: Path, val useTestClock: Boolean, val isDebug: Boolean @@ -378,7 +383,7 @@ open class DriverDSL( ) ) - val processFuture = startNode(executorService, configuration, quasarJarPath, debugPort) + val processFuture = startNode(executorService, configuration, quasarJarPath, debugPort, systemProperties) registerProcess(processFuture) return processFuture.flatMap { process -> // We continue to use SSL enabled port for RPC when its for node user. @@ -474,7 +479,7 @@ open class DriverDSL( ) log.info("Starting network-map-service") - val startNode = startNode(executorService, FullNodeConfiguration(baseDirectory, config), quasarJarPath, debugPort) + val startNode = startNode(executorService, FullNodeConfiguration(baseDirectory, config), quasarJarPath, debugPort, systemProperties) registerProcess(startNode) return startNode } @@ -492,7 +497,8 @@ open class DriverDSL( executorService: ScheduledExecutorService, nodeConf: FullNodeConfiguration, quasarJarPath: String, - debugPort: Int? + debugPort: Int?, + overriddenSystemProperties: Map ): ListenableFuture { // Write node.conf writeConfig(nodeConf.baseDirectory, "node.conf", nodeConf.config) @@ -507,36 +513,28 @@ open class DriverDSL( else "" - val inheritedProperties = listOf("amq.delivery.delay.ms") - - val systemArgs = mutableMapOf( + val systemProperties = mapOf( "name" to nodeConf.myLegalName, "visualvm.display.name" to "Corda" - ) - - inheritedProperties.forEach { - val property = System.getProperty(it) - if (property != null) systemArgs[it] = property - } + ) + overriddenSystemProperties val loggingLevel = if (debugPort == null) "INFO" else "DEBUG" val javaArgs = listOf(path) + - systemArgs.map { "-D${it.key}=${it.value}" } + + systemProperties.map { "-D${it.key}=${it.value}" } + listOf( "-javaagent:$quasarJarPath", debugPortArg, "-Xmx200m", "-XX:+UseG1GC", - "-cp", classpath, - className, + "-cp", classpath, className, "--base-directory=${nodeConf.baseDirectory}", "--logging-level=$loggingLevel" ).filter(String::isNotEmpty) - val builder = ProcessBuilder(javaArgs) - builder.redirectError(Paths.get("error.$className.log").toFile()) - builder.inheritIO() - builder.directory(nodeConf.baseDirectory.toFile()) - val process = builder.start() + val process = ProcessBuilder(javaArgs) + .redirectError((nodeConf.baseDirectory / LOGS_DIRECTORY_NAME / "error.log").toFile()) + .inheritIO() + .directory(nodeConf.baseDirectory.toFile()) + .start() // TODO There is a race condition here. Even though the messaging address is bound it may be the case that // the handlers for the advertised services are not yet registered. Needs rethinking. return addressMustBeBound(executorService, nodeConf.p2pAddress).map { process } diff --git a/node/src/main/kotlin/net/corda/node/services/statemachine/FlowStateMachineImpl.kt b/node/src/main/kotlin/net/corda/node/services/statemachine/FlowStateMachineImpl.kt index 91138fa7a2..e79ea6b7f9 100644 --- a/node/src/main/kotlin/net/corda/node/services/statemachine/FlowStateMachineImpl.kt +++ b/node/src/main/kotlin/net/corda/node/services/statemachine/FlowStateMachineImpl.kt @@ -55,18 +55,11 @@ class FlowStateMachineImpl(override val id: StateMachineRunId, @Transient internal var fromCheckpoint: Boolean = false @Transient private var txTrampoline: Transaction? = null - @Transient private var _logger: Logger? = null /** * Return the logger for this state machine. The logger name incorporates [id] and so including it in the log message * is not necessary. */ - override val logger: Logger get() { - return _logger ?: run { - val l = LoggerFactory.getLogger("net.corda.flow.$id") - _logger = l - return l - } - } + override val logger: Logger = LoggerFactory.getLogger("net.corda.flow.$id") @Transient private var _resultFuture: SettableFuture? = SettableFuture.create() /** This future will complete when the call method returns. */ @@ -104,7 +97,7 @@ class FlowStateMachineImpl(override val id: StateMachineRunId, return } - // Only sessions which have a single send and nothing else will block here + // Only sessions which have done a single send and nothing else will block here openSessions.values .filter { it.state is FlowSessionState.Initiating } .forEach { it.waitForConfirmation() }