Merge pull request #392 from corda/shams-logging-fix

Logging fixes, including broken --logging-level cmd line arg

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()
+        loggerConfig.addAppender(config.appenders["Console-Appender"], null, null)
-        appender?.let {
-            loggerConfig.addAppender(appender, null, null)
-        }
         config.removeLogger(name)
         config.addLogger(name, loggerConfig)
         loggerContext.updateLoggers(config)

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() {
+    fun `random free port allocation`() {
-        val nodeInfo = driver(portAllocation = PortAllocation.RandomFree) {
+        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()
+        }
     }
 }

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.

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<String>) {
     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<String>) {
         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<String>) {
         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"))

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 <A> driver(
         driverDirectory: Path = Paths.get("build", getTimestampAsDirectoryName()),
         portAllocation: PortAllocation = PortAllocation.Incremental(10000),
         debugPortAllocation: PortAllocation = PortAllocation.Incremental(5005),
+        systemProperties: Map<String, String> = 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 <A> poll(
 open class DriverDSL(
         val portAllocation: PortAllocation,
         val debugPortAllocation: PortAllocation,
+        val systemProperties: Map<String, String>,
         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<String, String>
         ): ListenableFuture<Process> {
             // 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 systemProperties = mapOf(
-
-            val systemArgs = mutableMapOf(
                     "name" to nodeConf.myLegalName,
                     "visualvm.display.name" to "Corda"
-            )
+            ) + overriddenSystemProperties
-
-            inheritedProperties.forEach {
-                val property = System.getProperty(it)
-                if (property != null) systemArgs[it] = property
-            }
 
             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,
+                            "-cp", classpath, className,
-                            className,
                             "--base-directory=${nodeConf.baseDirectory}",
                             "--logging-level=$loggingLevel"
                     ).filter(String::isNotEmpty)
-            val builder = ProcessBuilder(javaArgs)
+            val process = ProcessBuilder(javaArgs)
-            builder.redirectError(Paths.get("error.$className.log").toFile())
+                    .redirectError((nodeConf.baseDirectory / LOGS_DIRECTORY_NAME / "error.log").toFile())
-            builder.inheritIO()
+                    .inheritIO()
-            builder.directory(nodeConf.baseDirectory.toFile())
+                    .directory(nodeConf.baseDirectory.toFile())
-            val process = builder.start()
+                    .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 }

node/src/main/kotlin/net/corda/node/services/statemachine/FlowStateMachineImpl.kt

@@ -55,18 +55,11 @@ class FlowStateMachineImpl<R>(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() {
+    override val logger: Logger = LoggerFactory.getLogger("net.corda.flow.$id")
-        return _logger ?: run {
-            val l = LoggerFactory.getLogger("net.corda.flow.$id")
-            _logger = l
-            return l
-        }
-    }
 
     @Transient private var _resultFuture: SettableFuture<R>? = SettableFuture.create<R>()
     /** This future will complete when the call method returns. */
@@ -104,7 +97,7 @@ class FlowStateMachineImpl<R>(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() }