CORDA-1575, CORDA-1341 - Fix logfiles for out of process nodes, Ensure API can be called concurrently wrt transactions.(#3312)

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

* [CORDA-1341]: Ensure API can be called concurrently wrt transactions.

* [CORDA-1575]: Fixed unstable test.

config/dev/log4j2.xml

@@ -2,18 +2,33 @@
 <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="consoleLogLevel">error</Property>
-        <Property name="defaultLogLevel">info</Property>
+        <Property name="archive">${log-path}/archive</Property>
+        <Property name="consoleLogLevel">${sys:consoleLogLevel:-error}</Property>
+        <Property name="defaultLogLevel">${sys:defaultLogLevel:-info}</Property>
     </Properties>
 
     <ThresholdFilter level="trace"/>
 
     <Appenders>
         <Console name="Console-Appender" target="SYSTEM_OUT">
-            <PatternLayout pattern="%highlight{%level{length=1} %date{HH:mm:ssZ} [%t] %c{2}.%method - %msg %X%n}{INFO=white,WARN=red,FATAL=bright red}" />
+            <PatternLayout>
+                <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) {
+                        result = "WithMDC";
+                    } else {
+                        result = null;
+                    }
+                    result;
+               ]]>
+                    </Script>
+                    <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"/>
         </Console>
 
         <!-- Required for printBasicInfo -->
@@ -21,10 +36,10 @@
             <PatternLayout pattern="%msg%n" />
         </Console>
 
-        <!-- Will generate up to 10 log files for a given day. During every rollover it will delete
+        <!-- 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"/>
@@ -34,7 +49,7 @@
                 <SizeBasedTriggeringPolicy size="10MB"/>
             </Policies>
 
-            <DefaultRolloverStrategy min="1" max="10">
+            <DefaultRolloverStrategy min="1" max="100">
                 <Delete basePath="${archive}" maxDepth="1">
                     <IfFileName glob="${log-name}*.log.gz"/>
                     <IfLastModified age="60d">
@@ -49,15 +64,20 @@
     </Appenders>
 
     <Loggers>
-        <Root level="${sys:defaultLogLevel}">
-            <AppenderRef ref="Console-Appender" level="${sys:consoleLogLevel}"/>
+        <Root level="${defaultLogLevel}">
+            <AppenderRef ref="Console-Appender" level="${consoleLogLevel}"/>
             <AppenderRef ref="RollingFile-Appender" />
         </Root>
         <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,10 @@ release, see :doc:`upgrade-notes`.
 Unreleased
 ==========
 
+* ``ServiceHub`` and ``CordaRPCOps`` can now safely be used from multiple threads without incurring in database transaction problems.
+
+* Fixed an issue preventing out of process nodes started by the ``Driver`` from logging to file.
+
 * The Vault Criteria API has been extended to take a more precise specification of which class contains a field. This primarily impacts Java users; Kotlin users need take no action. The old methods have been deprecated but still work - the new methods avoid bugs that can occur when JPA schemas inherit from each other.
 
 * Removed -xmx VM argument from Explorer's Capsule setup. This helps avoiding out of memory errors.

node-api/src/main/kotlin/net/corda/nodeapi/internal/persistence/CordaPersistence.kt

@@ -42,7 +42,7 @@ enum class TransactionIsolationLevel {
     val jdbcValue: Int = java.sql.Connection::class.java.getField("TRANSACTION_$name").get(null) as Int
 }
 
-private val _contextDatabase = ThreadLocal<CordaPersistence>()
+private val _contextDatabase = InheritableThreadLocal<CordaPersistence>()
 var contextDatabase: CordaPersistence
     get() = _contextDatabase.get() ?: error("Was expecting to find CordaPersistence set on current thread: ${Strand.currentStrand()}")
     set(database) = _contextDatabase.set(database)

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

@@ -5,20 +5,19 @@ import net.corda.client.rpc.CordaRPCClient
 import net.corda.core.flows.FlowLogic
 import net.corda.core.flows.StartableByRPC
 import net.corda.core.internal.div
+import net.corda.core.internal.list
+import net.corda.core.internal.readLines
 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.core.ALICE_NAME
 import net.corda.testing.node.User
-import net.corda.testing.common.internal.ProjectStructure.projectRootDir
 import net.corda.testing.driver.DriverParameters
 import net.corda.testing.driver.driver
-import org.assertj.core.api.Assertions.assertThat
 import org.assertj.core.api.Assertions.assertThatThrownBy
 import org.junit.Test
 import java.io.*
-import java.nio.file.Files
 import kotlin.test.assertEquals
 
 class BootTests {
@@ -35,18 +34,16 @@ class BootTests {
 
     @Test
     fun `double node start doesn't write into log file`() {
-        val logConfigFile = projectRootDir / "config" / "dev" / "log4j2.xml"
-        assertThat(logConfigFile).isRegularFile()
-        driver(DriverParameters(isDebug = true, systemProperties = mapOf("log4j.configurationFile" to logConfigFile.toString()))) {
+        driver(DriverParameters(isDebug = true)) {
             val alice = startNode(providedName = ALICE_NAME).get()
             val logFolder = alice.baseDirectory / NodeStartup.LOGS_DIRECTORY_NAME
-            val logFile = logFolder.toFile().listFiles { _, name -> name.endsWith(".log") }.single()
+            val logFile = logFolder.list { it.filter { it.fileName.toString().endsWith(".log") }.findAny().get() }
             // Start second Alice, should fail
             assertThatThrownBy {
                 startNode(providedName = ALICE_NAME).getOrThrow()
             }
             // We count the number of nodes that wrote into the logfile by counting "Logs can be found in"
-            val numberOfNodesThatLogged = Files.lines(logFile.toPath()).filter { NodeStartup.LOGS_CAN_BE_FOUND_IN_STRING in it }.count()
+            val numberOfNodesThatLogged = logFile.readLines { it.filter { NodeStartup.LOGS_CAN_BE_FOUND_IN_STRING in it }.count() }
             assertEquals(1, numberOfNodesThatLogged)
         }
     }

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

@@ -143,7 +143,7 @@ class SSHServerTest {
 
             val linesWithDoneCount = response.lines().filter { line -> line.contains("Done") }
             // There are ANSI control characters involved, so we want to avoid direct byte to byte matching.
-            assertThat(linesWithDoneCount).hasSize(1)
+            assertThat(linesWithDoneCount.size).isGreaterThanOrEqualTo(1)
         }
     }
 

node/src/test/kotlin/net/corda/node/services/ServiceHubConcurrentUsageTest.kt

@@ -0,0 +1,70 @@
+package net.corda.node.services
+
+import co.paralleluniverse.fibers.Suspendable
+import net.corda.core.contracts.ContractState
+import net.corda.core.flows.FinalityFlow
+import net.corda.core.flows.FlowLogic
+import net.corda.core.identity.Party
+import net.corda.core.internal.packageName
+import net.corda.core.node.services.queryBy
+import net.corda.core.transactions.SignedTransaction
+import net.corda.core.transactions.TransactionBuilder
+import net.corda.core.utilities.OpaqueBytes
+import net.corda.core.utilities.getOrThrow
+import net.corda.finance.DOLLARS
+import net.corda.finance.contracts.asset.Cash
+import net.corda.finance.issuedBy
+import net.corda.testing.node.internal.InternalMockNetwork
+import net.corda.testing.node.internal.startFlow
+import org.assertj.core.api.Assertions.assertThat
+import org.junit.After
+import org.junit.Test
+import rx.schedulers.Schedulers
+import java.util.concurrent.CountDownLatch
+
+class ServiceHubConcurrentUsageTest {
+
+    private val mockNet = InternalMockNetwork(listOf(Cash::class.packageName))
+
+    @After
+    fun stopNodes() {
+        mockNet.stopNodes()
+    }
+
+    @Test
+    fun `operations requiring a transaction work from another thread`() {
+
+        val latch = CountDownLatch(1)
+        var successful = false
+        val initiatingFlow = TestFlow(mockNet.defaultNotaryIdentity)
+        val node = mockNet.createPartyNode()
+
+        node.services.validatedTransactions.updates.observeOn(Schedulers.io()).subscribe { _ ->
+            try {
+                node.services.vaultService.queryBy<ContractState>().states
+                successful = true
+            } finally {
+                latch.countDown()
+            }
+        }
+
+        val flow = node.services.startFlow(initiatingFlow)
+        mockNet.runNetwork()
+        flow.resultFuture.getOrThrow()
+        latch.await()
+        assertThat(successful).isTrue()
+    }
+
+    class TestFlow(private val notary: Party) : FlowLogic<SignedTransaction>() {
+
+        @Suspendable
+        override fun call(): SignedTransaction {
+
+            val builder = TransactionBuilder(notary)
+            val issuer = ourIdentity.ref(OpaqueBytes.of(0))
+            Cash().generateIssue(builder, 10.DOLLARS.issuedBy(issuer), ourIdentity, notary)
+            val stx = serviceHub.signInitialTransaction(builder)
+            return subFlow(FinalityFlow(stx))
+        }
+    }
+}

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

@@ -2,7 +2,9 @@ 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.utilities.getOrThrow
+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
@@ -28,7 +30,12 @@ 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

@@ -1,8 +1,6 @@
 package net.corda.testing.node.internal
 
 import net.corda.core.internal.div
-import net.corda.core.internal.exists
-import java.io.File.pathSeparator
 import java.nio.file.Path
 
 object ProcessUtilities {
@@ -23,9 +21,7 @@ object ProcessUtilities {
             workingDirectory: Path?,
             maximumHeapSize: String
     ): Process {
-        // FIXME: Instead of hacking our classpath, use the correct classpath for className.
-        val classpath = defaultClassPath.split(pathSeparator).filter { !(it / "log4j2-test.xml").exists() }.joinToString(pathSeparator)
-        return startJavaProcessImpl(className, arguments, classpath, jdwpPort, extraJvmArguments, errorLogPath, workingDirectory, maximumHeapSize)
+        return startJavaProcessImpl(className, arguments, defaultClassPath, jdwpPort, extraJvmArguments, errorLogPath, workingDirectory, maximumHeapSize)
     }
 
     fun startJavaProcessImpl(

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

@@ -1,32 +1,90 @@
 <?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 pattern="[%-5level] %date{HH:mm:ss,SSS} [%t] (%F:%L) %c{2}.%method - %msg %X%n" />
+            <PatternLayout>
+                <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) {
+                        result = "WithMDC";
+                    } else {
+                        result = null;
+                    }
+                    result;
+               ]]>
+                    </Script>
+                    <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"/>

+        <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>