CORDA-2176 - test that logging is not broken. (#5224)

* Initial commit with a test that can detect a logger that isn't initialised with by lazy that gets called during startup.

* Test improvement. Test fix for api stability.

* Added explanatory comment for the test.

* Changes according to PR review. Added empty file check to make test more robust.

node/src/integration-test/kotlin/net/corda/node/logging/ErrorCodeLoggingTests.kt

@@ -6,7 +6,9 @@ import net.corda.core.flows.StartableByRPC
 import net.corda.core.internal.div
 import net.corda.core.messaging.FlowHandle
 import net.corda.core.messaging.startFlow
+import net.corda.core.utilities.contextLogger
 import net.corda.core.utilities.getOrThrow
+import net.corda.core.utilities.loggerFor
 import net.corda.testing.driver.DriverParameters
 import net.corda.testing.driver.NodeHandle
 import net.corda.testing.driver.driver
@@ -28,6 +30,30 @@ class ErrorCodeLoggingTests {
         }
     }
 
+    // This is used to detect broken logging which can be caused by loggers being initialized
+    // before the initLogging() call is made
+    @Test
+    fun `When logging is set to error level, there are no other levels logged after node startup`() {
+        driver(DriverParameters(notarySpecs = emptyList())) {
+            val node = startNode(startInSameProcess = false, logLevelOverride = "ERROR").getOrThrow()
+            node.rpc.startFlow(::MyFlow).waitForCompletion()
+            val logFile = node.logFile()
+            assertThat(logFile.length()).isGreaterThan(0)
+
+            val linesWithoutError = logFile.useLines { lines ->
+                lines.filterNot {
+                    it.contains("[ERROR")
+                }.filter{
+                    it.contains("[INFO")
+                        .or(it.contains("[WARN"))
+                        .or(it.contains("[DEBUG"))
+                        .or(it.contains("[TRACE"))
+                }.toList()
+            }
+            assertThat(linesWithoutError.isEmpty()).isTrue()
+        }
+    }
+
     @StartableByRPC
     @InitiatingFlow
     class MyFlow : FlowLogic<String>() {

testing/node-driver/src/main/kotlin/net/corda/testing/driver/DriverDSL.kt

@@ -89,8 +89,51 @@ interface DriverDSL {
      * @param maximumHeapSize The maximum JVM heap size to use for the node as a [String]. By default a number is interpreted
      *     as being in bytes. Append the letter 'k' or 'K' to the value to indicate Kilobytes, 'm' or 'M' to indicate
      *     megabytes, and 'g' or 'G' to indicate gigabytes. The default value is "512m" = 512 megabytes.
+     * @param logLevelOverride log4j log level used to override the default value of info.
      * @return A [CordaFuture] on the [NodeHandle] to the node. The future will complete when the node is available and
-     * it sees all previously started nodes, including the notaries.
+     *     it sees all previously started nodes, including the notaries.
+     */
+    fun startNode(
+            defaultParameters: NodeParameters = NodeParameters(),
+            providedName: CordaX500Name? = defaultParameters.providedName,
+            rpcUsers: List<User> = defaultParameters.rpcUsers,
+            verifierType: VerifierType = defaultParameters.verifierType,
+            customOverrides: Map<String, Any?> = defaultParameters.customOverrides,
+            startInSameProcess: Boolean? = defaultParameters.startInSameProcess,
+            maximumHeapSize: String = defaultParameters.maximumHeapSize,
+            logLevelOverride: String? = defaultParameters.logLevelOverride
+    ): CordaFuture<NodeHandle> {
+        return startNode(defaultParameters.copy(
+                providedName = providedName,
+                rpcUsers = rpcUsers,
+                verifierType = verifierType,
+                customOverrides = customOverrides,
+                startInSameProcess = startInSameProcess,
+                maximumHeapSize = maximumHeapSize,
+                logLevelOverride = logLevelOverride
+        ))
+    }
+
+    /**
+     * Start a node.
+     *
+     * NOTE: This method does not provide all the node parameters that are available and only exists for backwards compatibility. It is
+     * recommended you use [NodeParameters].
+     *
+     * @param defaultParameters The default parameters for the node. If any of the remaining parameters to this method are specified then
+     * their values are taken instead of the corresponding value in [defaultParameters].
+     * @param providedName Optional name of the node, which will be its legal name in [Party]. Defaults to something
+     *     random. Note that this must be unique as the driver uses it as a primary key!
+     * @param rpcUsers List of users who are authorised to use the RPC system. Defaults to empty list.
+     * @param verifierType The type of transaction verifier to use. See: [VerifierType].
+     * @param customOverrides A map of custom node configuration overrides.
+     * @param startInSameProcess Determines if the node should be started inside the same process the Driver is running
+     *     in. If null the Driver-level value will be used.
+     * @param maximumHeapSize The maximum JVM heap size to use for the node as a [String]. By default a number is interpreted
+     *     as being in bytes. Append the letter 'k' or 'K' to the value to indicate Kilobytes, 'm' or 'M' to indicate
+     *     megabytes, and 'g' or 'G' to indicate gigabytes. The default value is "512m" = 512 megabytes.
+     * @return A [CordaFuture] on the [NodeHandle] to the node. The future will complete when the node is available and
+     *     it sees all previously started nodes, including the notaries.
      */
     fun startNode(
             defaultParameters: NodeParameters = NodeParameters(),

testing/node-driver/src/main/kotlin/net/corda/testing/driver/NodeParameters.kt

@@ -20,6 +20,8 @@ import net.corda.testing.node.User
  * @property maximumHeapSize The maximum JVM heap size to use for the node. Defaults to 512 MB.
  * @property additionalCordapps Additional [TestCordapp]s that this node will have available, in addition to the ones common to all nodes
  * managed by the [DriverDSL].
+ * @property logLevelOverride log level to be passed as parameter to an out of process node. ERROR, WARN, INFO, DEBUG, TRACE. This overrides debug port
+ * log level argument.
  */
 @Suppress("unused")
 data class NodeParameters(
@@ -30,7 +32,8 @@ data class NodeParameters(
         val startInSameProcess: Boolean? = null,
         val maximumHeapSize: String = "512m",
         val additionalCordapps: Collection<TestCordapp> = emptySet(),
-        val flowOverrides: Map<out Class<out FlowLogic<*>>, Class<out FlowLogic<*>>> = emptyMap()
+        val flowOverrides: Map<out Class<out FlowLogic<*>>, Class<out FlowLogic<*>>> = emptyMap(),
+        val logLevelOverride : String? = null
 ) {
     /**
      * Create a new node parameters object with default values. Each parameter can be specified with its wither method which returns a copy
@@ -46,6 +49,7 @@ data class NodeParameters(
     fun withMaximumHeapSize(maximumHeapSize: String): NodeParameters = copy(maximumHeapSize = maximumHeapSize)
     fun withAdditionalCordapps(additionalCordapps: Set<TestCordapp>): NodeParameters = copy(additionalCordapps = additionalCordapps)
     fun withFlowOverrides(flowOverrides: Map<Class<out FlowLogic<*>>, Class<out FlowLogic<*>>>): NodeParameters = copy(flowOverrides = flowOverrides)
+    fun withLogLevelOverride(logLevelOverride : String?) : NodeParameters = copy(logLevelOverride = logLevelOverride)
 
     constructor(
             providedName: CordaX500Name?,
@@ -79,4 +83,44 @@ data class NodeParameters(
             maximumHeapSize = maximumHeapSize,
             additionalCordapps = additionalCordapps
     )
+    constructor(
+            providedName: CordaX500Name?,
+            rpcUsers: List<User>,
+            verifierType: VerifierType,
+            customOverrides: Map<String, Any?>,
+            startInSameProcess: Boolean?,
+            maximumHeapSize: String,
+            additionalCordapps: Collection<TestCordapp> = emptySet(),
+            flowOverrides: Map<out Class<out FlowLogic<*>>, Class<out FlowLogic<*>>>
+    ) : this(
+            providedName,
+            rpcUsers,
+            verifierType,
+            customOverrides,
+            startInSameProcess,
+            maximumHeapSize,
+            additionalCordapps,
+            flowOverrides,
+            logLevelOverride = null)
+
+    fun copy(
+            providedName: CordaX500Name?,
+            rpcUsers: List<User>,
+            verifierType: VerifierType,
+            customOverrides: Map<String, Any?>,
+            startInSameProcess: Boolean?,
+            maximumHeapSize: String,
+            additionalCordapps: Collection<TestCordapp> = emptySet(),
+            flowOverrides: Map<out Class<out FlowLogic<*>>, Class<out FlowLogic<*>>>
+    ) = this.copy(
+            providedName = providedName,
+            rpcUsers = rpcUsers,
+            verifierType = verifierType,
+            customOverrides = customOverrides,
+            startInSameProcess = startInSameProcess,
+            maximumHeapSize = maximumHeapSize,
+            additionalCordapps = additionalCordapps,
+            flowOverrides = flowOverrides,
+            logLevelOverride = logLevelOverride)
+
 }

testing/node-driver/src/main/kotlin/net/corda/testing/node/internal/DriverDSLImpl.kt

@@ -548,6 +548,7 @@ class DriverDSLImpl(
                 debugPort,
                 systemProperties,
                 "512m",
+                null,
                 *extraCmdLineFlag
         )
 
@@ -605,7 +606,7 @@ class DriverDSLImpl(
             nodeFuture
         } else {
             val debugPort = if (isDebug) debugPortAllocation.nextPort() else null
-            val process = startOutOfProcessNode(config, quasarJarPath, debugPort, systemProperties, parameters.maximumHeapSize)
+            val process = startOutOfProcessNode(config, quasarJarPath, debugPort, systemProperties, parameters.maximumHeapSize, parameters.logLevelOverride)
 
             // Destroy the child process when the parent exits.This is needed even when `waitForAllNodesToFinish` is
             // true because we don't want orphaned processes in the case that the parent process is terminated by the
@@ -732,6 +733,7 @@ class DriverDSLImpl(
                 debugPort: Int?,
                 overriddenSystemProperties: Map<String, String>,
                 maximumHeapSize: String,
+                logLevelOverride: String?,
                 vararg extraCmdLineFlag: String
         ): Process {
             log.info("Starting out-of-process Node ${config.corda.myLegalName.organisation}, debug port is " + (debugPort ?: "not enabled"))
@@ -761,7 +763,13 @@ class DriverDSLImpl(
                     "com.lmax**;picocli**;liquibase**;com.github.benmanes**;org.json**;org.postgresql**;nonapi.io.github.classgraph**;)"
             val extraJvmArguments = systemProperties.removeResolvedClasspath().map { "-D${it.key}=${it.value}" } +
                     "-javaagent:$quasarJarPath=$excludePattern"
-            val loggingLevel = if (debugPort == null) "INFO" else "DEBUG"
+
+            val loggingLevel = when {
+                logLevelOverride != null -> logLevelOverride
+                debugPort == null -> "INFO"
+                else -> "DEBUG"
+            }
+
 
             val arguments = mutableListOf(
                     "--base-directory=${config.corda.baseDirectory}",