[CORDA-1575]: Out of process nodes started by the driver do not log to file (fix). (#3286)

config/dev/log4j2.xml

@@ -2,11 +2,10 @@
 <Configuration status="info">
 
     <Properties>
-        <Property name="log-path">logs</Property>
+        <Property name="log-path">${sys:log-path:-logs}</Property>
         <Property name="log-name">node-${hostName}</Property>
-        <Property name="archive">${sys:log-path}/archive</Property>
+        <Property name="archive">${log-path}/archive</Property>
-        <Property name="consoleLogLevel">error</Property>
+        <Property name="defaultLogLevel">${sys:defaultLogLevel:-info}</Property>
-        <Property name="defaultLogLevel">info</Property>
     </Properties>
 
     <ThresholdFilter level="trace"/>
@@ -14,7 +13,7 @@
     <Appenders>
         <Console name="Console-Appender" target="SYSTEM_OUT">
             <PatternLayout>
-                <ScriptPatternSelector defaultPattern="%highlight{%level{length=1} %date{HH:mm:ssZ} [%t] %c{2}.%method - %msg%n}{INFO=white,WARN=red,FATAL=bright red}">
+                <ScriptPatternSelector defaultPattern="%highlight{[%level{length=5}] %date{HH:mm:ssZ} [%t] %c{2}.%method - %msg%n}{INFO=white,WARN=red,FATAL=bright red}">
                     <Script name="MDCSelector" language="javascript"><![CDATA[
                     result = null;
                     if (!logEvent.getContextData().size() == 0) {
@@ -25,7 +24,7 @@
                     result;
                ]]>
                     </Script>
-                    <PatternMatch key="WithMDC" pattern="%highlight{%level{length=1} %date{HH:mm:ssZ} [%t] %c{2}.%method - %msg %X%n}{INFO=white,WARN=red,FATAL=bright red}"/>
+                    <PatternMatch key="WithMDC" pattern="%highlight{[%level{length=5}] %date{HH:mm:ssZ} [%t] %c{2}.%method - %msg %X%n}{INFO=white,WARN=red,FATAL=bright red}"/>
                 </ScriptPatternSelector>
             </PatternLayout>
             <ThresholdFilter level="trace"/>
@@ -39,7 +38,7 @@
         <!-- Will generate up to 100 log files for a given day. During every rollover it will delete
              those that are older than 60 days, but keep the most recent 10 GB -->
         <RollingFile name="RollingFile-Appender"
-                     fileName="${sys:log-path}/${log-name}.log"
+                     fileName="${log-path}/${log-name}.log"
                      filePattern="${archive}/${log-name}.%date{yyyy-MM-dd}-%i.log.gz">
 
             <PatternLayout pattern="[%-5level] %date{ISO8601}{UTC}Z [%t] %c{2}.%method - %msg %X%n"/>
@@ -64,15 +63,23 @@
     </Appenders>
 
     <Loggers>
-        <Root level="${sys:defaultLogLevel}">
+        <Root level="info">
-            <AppenderRef ref="Console-Appender" level="${sys:consoleLogLevel}"/>
+            <AppenderRef ref="Console-Appender"/>
-            <AppenderRef ref="RollingFile-Appender" />
         </Root>
+        <Logger name="net.corda" level="${defaultLogLevel}" additivity="false">
+            <AppenderRef ref="Console-Appender"/>
+            <AppenderRef ref="RollingFile-Appender" />
+        </Logger>
         <Logger name="BasicInfo" additivity="false">
             <AppenderRef ref="Console-Appender-Println"/>
             <AppenderRef ref="RollingFile-Appender" />
         </Logger>
+        <Logger name="org.hibernate.SQL" level="info" additivity="false">
+            <AppenderRef ref="Console-Appender"/>
+            <AppenderRef ref="RollingFile-Appender"/>
+        </Logger>
         <Logger name="org.apache.activemq.artemis.core.server" level="error" additivity="false">
+            <AppenderRef ref="Console-Appender"/>
             <AppenderRef ref="RollingFile-Appender"/>
         </Logger>
         <Logger name="org.jolokia" additivity="true" level="warn">

docs/source/changelog.rst

@@ -7,6 +7,8 @@ release, see :doc:`upgrade-notes`.
 Unreleased
 ==========
 
+* Fixed an issue preventing out of process nodes started by the ``Driver`` from logging to file.
+
 * Fixed an issue with ``CashException`` not being able to deserialise after the introduction of AMQP for RPC.
 
 * Removed -xmx VM argument from Explorer's Capsule setup. This helps avoiding out of memory errors.

node/src/integration-test/kotlin/net/corda/node/BootTests.kt

@@ -12,12 +12,10 @@ import net.corda.core.messaging.startFlow
 import net.corda.core.utilities.getOrThrow
 import net.corda.node.internal.NodeStartup
 import net.corda.node.services.Permissions.Companion.startFlow
-import net.corda.testing.common.internal.ProjectStructure.projectRootDir
 import net.corda.testing.core.ALICE_NAME
 import net.corda.testing.driver.DriverParameters
 import net.corda.testing.driver.driver
 import net.corda.testing.node.User
-import org.assertj.core.api.Assertions.assertThat
 import org.assertj.core.api.Assertions.assertThatThrownBy
 import org.junit.Test
 import java.io.*
@@ -38,9 +36,7 @@ class BootTests {
 
     @Test
     fun `double node start doesn't write into log file`() {
-        val logConfigFile = projectRootDir / "config" / "dev" / "log4j2.xml"
+        driver(DriverParameters(isDebug = true)) {
-        assertThat(logConfigFile).isRegularFile()
-        driver(DriverParameters(isDebug = true, systemProperties = mapOf("log4j.configurationFile" to logConfigFile.toString()))) {
             val alice = startNode(providedName = ALICE_NAME).get()
             val logFolder = alice.baseDirectory / NodeStartup.LOGS_DIRECTORY_NAME
             val logFile = logFolder.list { it.filter { it.fileName.toString().endsWith(".log") }.findAny().get() }

samples/simm-valuation-demo/src/integration-test/kotlin/net/corda/vega/SimmValuationTest.kt

@@ -2,9 +2,11 @@ package net.corda.vega
 
 import com.opengamma.strata.product.common.BuySell
 import net.corda.core.identity.CordaX500Name
+import net.corda.core.internal.div
 import net.corda.core.internal.packageName
 import net.corda.core.utilities.getOrThrow
 import net.corda.serialization.internal.amqp.AbstractAMQPSerializationScheme
+import net.corda.testing.common.internal.ProjectStructure.projectRootDir
 import net.corda.testing.core.DUMMY_BANK_A_NAME
 import net.corda.testing.core.DUMMY_BANK_B_NAME
 import net.corda.testing.driver.DriverParameters
@@ -43,7 +45,13 @@ class SimmValuationTest {
 
     @Test
     fun `runs SIMM valuation demo`() {
-        driver(DriverParameters(isDebug = true, extraCordappPackagesToScan = listOf("net.corda.vega.contracts", "net.corda.vega.plugin.customserializers"))) {
+        val logConfigFile = projectRootDir / "samples" / "simm-valuation-demo" / "src" / "main" / "resources" / "log4j2.xml"
+        assertThat(logConfigFile).isRegularFile()
+        driver(DriverParameters(
+                isDebug = true,
+                extraCordappPackagesToScan = listOf("net.corda.vega.contracts", "net.corda.vega.plugin.customserializers"),
+                systemProperties = mapOf("log4j.configurationFile" to logConfigFile.toString()))
+        ) {
             val nodeAFuture = startNode(providedName = nodeALegalName)
             val nodeBFuture = startNode(providedName = nodeBLegalName)
             val (nodeA, nodeB) = listOf(nodeAFuture, nodeBFuture).map { it.getOrThrow() }

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

@@ -22,9 +22,7 @@ object ProcessUtilities {
             workingDirectory: Path?,
             maximumHeapSize: String
     ): Process {
-        // FIXME: Instead of hacking our classpath, use the correct classpath for className.
+        return startJavaProcessImpl(className, arguments, defaultClassPath, jdwpPort, extraJvmArguments, workingDirectory, maximumHeapSize)
-        val classpath = defaultClassPath.split(pathSeparator).filter { !(it / "log4j2-test.xml").exists() }.joinToString(pathSeparator)
-        return startJavaProcessImpl(className, arguments, classpath, jdwpPort, extraJvmArguments, workingDirectory, maximumHeapSize)
     }
 
     fun startJavaProcessImpl(

testing/test-common/src/main/resources/log4j2-test.xml

@@ -1,12 +1,19 @@
 <?xml version="1.0" encoding="UTF-8"?>
 <Configuration status="info">
+
     <Properties>
-        <Property name="defaultLogLevel">info</Property>
+        <Property name="log-path">${sys:log-path:-logs}</Property>
+        <Property name="log-name">node-${hostName}</Property>
+        <Property name="archive">${log-path}/archive</Property>
+        <Property name="defaultLogLevel">${sys:defaultLogLevel:-info}</Property>
     </Properties>
+
+    <ThresholdFilter level="trace"/>
+
     <Appenders>
         <Console name="Console-Appender" target="SYSTEM_OUT">
             <PatternLayout>
-                <ScriptPatternSelector defaultPattern="[%-5level] %date{HH:mm:ss,SSS} [%t] (%F:%L) %c{2}.%method - %msg%n">
+                <ScriptPatternSelector defaultPattern="%highlight{[%level{length=5}] %date{HH:mm:ss,SSS} [%t] %c{2}.%method - %msg%n}{INFO=white,WARN=red,FATAL=bright red}">
                     <Script name="MDCSelector" language="javascript"><![CDATA[
                     result = null;
                     if (!logEvent.getContextData().size() == 0) {
@@ -17,31 +24,67 @@
                     result;
                ]]>
                     </Script>
-                    <PatternMatch key="WithMDC" pattern="[%-5level] %date{HH:mm:ss,SSS} [%t] (%F:%L) %c{2}.%method - %msg %X%n"/>
+                    <PatternMatch key="WithMDC" pattern="%highlight{[%level{length=5}] %date{HH:mm:ss,SSS} [%t] %c{2}.%method - %msg %X%n}{INFO=white,WARN=red,FATAL=bright red}"/>
                 </ScriptPatternSelector>
             </PatternLayout>
             <ThresholdFilter level="trace"/>
         </Console>
+
         <!-- Required for printBasicInfo -->
         <Console name="Console-Appender-Println" target="SYSTEM_OUT">
             <PatternLayout pattern="%msg%n" />
         </Console>
+
+        <!-- Will generate up to 100 log files for a given day. During every rollover it will delete
+             those that are older than 60 days, but keep the most recent 10 GB -->
+        <RollingFile name="RollingFile-Appender"
+                     fileName="${log-path}/${log-name}.log"
+                     filePattern="${archive}/${log-name}.%date{yyyy-MM-dd}-%i.log.gz">
+
+            <PatternLayout pattern="[%-5level] %date{ISO8601}{UTC}Z [%t] %c{2}.%method - %msg %X%n"/>
+
+            <Policies>
+                <TimeBasedTriggeringPolicy/>
+                <SizeBasedTriggeringPolicy size="10MB"/>
+            </Policies>
+
+            <DefaultRolloverStrategy min="1" max="100">
+                <Delete basePath="${archive}" maxDepth="1">
+                    <IfFileName glob="${log-name}*.log.gz"/>
+                    <IfLastModified age="60d">
+                        <IfAny>
+                            <IfAccumulatedFileSize exceeds="10 GB"/>
+                        </IfAny>
+                    </IfLastModified>
+                </Delete>
+            </DefaultRolloverStrategy>
+
+        </RollingFile>
     </Appenders>
+
     <Loggers>
         <Root level="info">
             <AppenderRef ref="Console-Appender"/>
         </Root>
-        <Logger name="net.corda" level="${sys:defaultLogLevel}" additivity="false">
+        <Logger name="net.corda" level="${defaultLogLevel}" additivity="false">
             <AppenderRef ref="Console-Appender"/>
+            <AppenderRef ref="RollingFile-Appender" />
         </Logger>
         <Logger name="BasicInfo" additivity="false">
             <AppenderRef ref="Console-Appender-Println"/>
+            <AppenderRef ref="RollingFile-Appender" />
         </Logger>
         <Logger name="org.hibernate.SQL" level="info" additivity="false">
             <AppenderRef ref="Console-Appender"/>
+            <AppenderRef ref="RollingFile-Appender"/>
+        </Logger>
+        <Logger name="org.apache.activemq.artemis.core.server" level="error" additivity="false">
+            <AppenderRef ref="Console-Appender"/>
+            <AppenderRef ref="RollingFile-Appender"/>
         </Logger>
         <Logger name="org.jolokia" additivity="true" level="warn">
             <AppenderRef ref="Console-Appender-Println"/>
+            <AppenderRef ref="RollingFile-Appender" />
         </Logger>
     </Loggers>
 </Configuration>