NOTICK: Quick and dirty change to stop "Unable to start notaries." error message (#5686)

* Quick and dirty change to stop "Unable to start notaries." error message (#5686)

"Unable to start notaries. A required port might be bound already" is
returned whenever a startup error occurs while starting the notary nodes
in driver tests. This hides the real error.

This change prints the actual error to std_err and read from file
at a later point. This means the real error is not lost and will be
shown in failed builds.

* Suppress detekt warnings

node/src/main/kotlin/net/corda/node/internal/NodeStartup.kt

@@ -35,6 +35,7 @@ import org.slf4j.bridge.SLF4JBridgeHandler
 import picocli.CommandLine.Mixin
 import java.io.IOException
 import java.io.RandomAccessFile
+import java.lang.NullPointerException
 import java.lang.management.ManagementFactory
 import java.net.InetAddress
 import java.nio.channels.UnresolvedAddressException
@@ -440,13 +441,31 @@ interface NodeStartupLogging {
     companion object {
         val logger by lazy { contextLogger() }
         val startupErrors = setOf(MultipleCordappsForFlowException::class, CheckpointIncompatibleException::class, AddressBindingException::class, NetworkParametersReader::class, DatabaseIncompatibleException::class)
+        @Suppress("TooGenericExceptionCaught")
+        val PRINT_ERRORS_TO_STD_ERR = try {
+            System.getProperty("net.corda.node.printErrorsToStdErr") == "true"
+        } catch (e: NullPointerException) {
+            false
+        } catch (e: IllegalArgumentException) {
+            false
+        }
     }
 
     fun <RESULT> attempt(action: () -> RESULT): Try<RESULT> = Try.on(action).throwError()
 
     fun Throwable.logAsExpected(message: String? = this.message, print: (String?) -> Unit = logger::error) = print(message)
 
-    fun Throwable.logAsUnexpected(message: String? = this.message, error: Throwable = this, print: (String?, Throwable) -> Unit = logger::error) {
+    fun Throwable.logAsUnexpected(
+        message: String? = this.message,
+        error: Throwable = this,
+        print: (String?, Throwable) -> Unit = { s, e ->
+            logger.error(s, e)
+            if (PRINT_ERRORS_TO_STD_ERR) {
+                System.err.println(s)
+                e.printStackTrace()
+            }
+        }
+    ) {
         print("$message${this.message?.let { ": $it" } ?: ""}", error)
     }
 

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

@@ -58,12 +58,12 @@ import rx.schedulers.Schedulers
 import java.io.File
 import java.net.ConnectException
 import java.net.URL
-import java.net.URLClassLoader
 import java.nio.file.Path
 import java.security.cert.X509Certificate
 import java.time.Duration
 import java.time.Instant
 import java.time.ZoneOffset.UTC
+import java.time.ZonedDateTime
 import java.time.format.DateTimeFormatter
 import java.util.*
 import java.util.concurrent.Executors
@@ -377,6 +377,13 @@ class DriverDSLImpl(
         }
         try {
             _notaries.map { notary -> notary.map { handle -> handle.nodeHandles } }.getOrThrow(notaryHandleTimeout).forEach { future -> future.getOrThrow(notaryHandleTimeout) }
+        } catch(e: NodeListenProcessDeathException) {
+            val message = if (e.causeFromStdError.isNotBlank()) {
+                "Unable to start notaries. Failed with the following error: ${e.causeFromStdError}"
+            } else {
+                "Unable to start notaries. A required port might be bound already."
+            }
+            throw IllegalStateException(message)
         } catch (e: ListenProcessDeathException) {
             throw IllegalStateException("Unable to start notaries. A required port might be bound already.", e)
         } catch (e: TimeoutException) {
@@ -550,18 +557,20 @@ class DriverDSLImpl(
      * Start the node with the given flag which is expected to start the node for some function, which once complete will
      * terminate the node.
      */
+    @Suppress("SpreadOperator")
     private fun startOutOfProcessMiniNode(config: NodeConfig, vararg extraCmdLineFlag: String): CordaFuture<Unit> {
         val debugPort = if (isDebug) debugPortAllocation.nextPort() else null
         val process = startOutOfProcessNode(
-                config,
-                quasarJarPath,
-                debugPort,
-                bytemanJarPath,
-                null,
-                systemProperties,
-                "512m",
-                null,
-                *extraCmdLineFlag
+            config,
+            quasarJarPath,
+            debugPort,
+            bytemanJarPath,
+            null,
+            systemProperties,
+            "512m",
+            null,
+            ZonedDateTime.now().format(DateTimeFormatter.ofPattern("HHmmss.SSS")),
+            *extraCmdLineFlag
         )
 
         return poll(executorService, "$extraCmdLineFlag (${config.corda.myLegalName})") {
@@ -577,6 +586,7 @@ class DriverDSLImpl(
                                   bytemanPort: Int?): CordaFuture<NodeHandle> {
         val visibilityHandle = networkVisibilityController.register(config.corda.myLegalName)
         val baseDirectory = config.corda.baseDirectory.createDirectories()
+        val identifier = ZonedDateTime.now().format(DateTimeFormatter.ofPattern("HHmmss.SSS"))
         localNetworkMap?.networkParametersCopier?.install(baseDirectory)
         localNetworkMap?.nodeInfosCopier?.addConfig(baseDirectory)
 
@@ -621,14 +631,15 @@ class DriverDSLImpl(
         } else {
             val debugPort = if (isDebug) debugPortAllocation.nextPort() else null
             val process = startOutOfProcessNode(
-                    config,
-                    quasarJarPath,
-                    debugPort,
-                    bytemanJarPath,
-                    bytemanPort,
-                    systemProperties,
-                    parameters.maximumHeapSize,
-                    parameters.logLevelOverride
+                config,
+                quasarJarPath,
+                debugPort,
+                bytemanJarPath,
+                bytemanPort,
+                systemProperties,
+                parameters.maximumHeapSize,
+                parameters.logLevelOverride,
+                identifier
             )
 
             // Destroy the child process when the parent exits.This is needed even when `waitForAllNodesToFinish` is
@@ -646,7 +657,18 @@ class DriverDSLImpl(
                 }
             }
             val effectiveP2PAddress = config.corda.messagingServerAddress ?: config.corda.p2pAddress
-            val p2pReadyFuture = addressMustBeBoundFuture(executorService, effectiveP2PAddress, process)
+            val p2pReadyFuture = nodeMustBeStartedFuture(
+                executorService,
+                effectiveP2PAddress,
+                process
+            ) {
+                NodeListenProcessDeathException(
+                    effectiveP2PAddress,
+                    process,
+                    (config.corda.baseDirectory / "net.corda.node.Corda.$identifier.stderr.log").readText()
+                )
+            }
+
             p2pReadyFuture.flatMap {
                 val processDeathFuture = poll(executorService, "process death while waiting for RPC (${config.corda.myLegalName})") {
                     if (process.isAlive) null else process
@@ -753,17 +775,18 @@ class DriverDSLImpl(
             }
         }
 
-        @Suppress("ComplexMethod", "MaxLineLength")
+        @Suppress("ComplexMethod", "MaxLineLength", "LongParameterList")
         private fun startOutOfProcessNode(
-                config: NodeConfig,
-                quasarJarPath: String,
-                debugPort: Int?,
-                bytemanJarPath: String?,
-                bytemanPort: Int?,
-                overriddenSystemProperties: Map<String, String>,
-                maximumHeapSize: String,
-                logLevelOverride: String?,
-                vararg extraCmdLineFlag: String
+            config: NodeConfig,
+            quasarJarPath: String,
+            debugPort: Int?,
+            bytemanJarPath: String?,
+            bytemanPort: Int?,
+            overriddenSystemProperties: Map<String, String>,
+            maximumHeapSize: String,
+            logLevelOverride: String?,
+            identifier: String,
+            vararg extraCmdLineFlag: String
         ): Process {
             log.info("Starting out-of-process Node ${config.corda.myLegalName.organisation}, " +
                     "debug port is " + (debugPort ?: "not enabled") + ", " +
@@ -832,13 +855,14 @@ class DriverDSLImpl(
             }
 
             return ProcessUtilities.startJavaProcess(
-                    className = "net.corda.node.Corda", // cannot directly get class for this, so just use string
-                    arguments = arguments,
-                    jdwpPort = debugPort,
-                    extraJvmArguments = extraJvmArguments + bytemanJvmArgs,
-                    workingDirectory = config.corda.baseDirectory,
-                    maximumHeapSize = maximumHeapSize,
-                    classPath = cp
+                className = "net.corda.node.Corda", // cannot directly get class for this, so just use string
+                arguments = arguments,
+                jdwpPort = debugPort,
+                extraJvmArguments = extraJvmArguments + bytemanJvmArgs + "-Dnet.corda.node.printErrorsToStdErr=true",
+                workingDirectory = config.corda.baseDirectory,
+                maximumHeapSize = maximumHeapSize,
+                classPath = cp,
+                identifier = identifier
             )
         }
 

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

@@ -167,6 +167,25 @@ fun addressMustBeBoundFuture(executorService: ScheduledExecutorService, hostAndP
     }
 }
 
+fun nodeMustBeStartedFuture(
+    executorService: ScheduledExecutorService,
+    hostAndPort: NetworkHostAndPort,
+    listenProcess: Process? = null,
+    exception: () -> NodeListenProcessDeathException
+): CordaFuture<Unit> {
+    return poll(executorService, "address $hostAndPort to bind") {
+        if (listenProcess != null && !listenProcess.isAlive) {
+            throw exception()
+        }
+        try {
+            Socket(hostAndPort.host, hostAndPort.port).close()
+            Unit
+        } catch (_exception: SocketException) {
+            null
+        }
+    }
+}
+
 /*
  * The default timeout value of 40 seconds have been chosen based on previous node shutdown time estimate.
  * It's been observed that nodes can take up to 30 seconds to shut down, so just to stay on the safe side the 60 seconds
@@ -221,6 +240,14 @@ fun <A> poll(
 class ListenProcessDeathException(hostAndPort: NetworkHostAndPort, listenProcess: Process) :
         CordaException("The process that was expected to listen on $hostAndPort has died with status: ${listenProcess.exitValue()}")
 
+class NodeListenProcessDeathException(hostAndPort: NetworkHostAndPort, listenProcess: Process, val causeFromStdError: String) :
+    CordaException(
+        """
+        The node that was expected to start with $hostAndPort has died with status: ${listenProcess.exitValue()}
+        Error that caused the process to fail -> $causeFromStdError
+        """.trimIndent()
+    )
+
 fun <T> StartedNodeServices.startFlow(logic: FlowLogic<T>): FlowStateMachine<T> = startFlow(logic, newContext()).getOrThrow()
 
 fun StartedNodeServices.newContext(): InvocationContext = testContext(myInfo.chooseIdentity().name)

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

@@ -3,8 +3,6 @@ package net.corda.testing.node.internal
 import net.corda.core.internal.div
 import java.io.File
 import java.nio.file.Path
-import java.time.ZonedDateTime
-import java.time.format.DateTimeFormatter
 
 object ProcessUtilities {
     inline fun <reified C : Any> startJavaProcess(
@@ -18,6 +16,7 @@ object ProcessUtilities {
         return startJavaProcess(C::class.java.name, arguments, classPath, workingDirectory, jdwpPort, extraJvmArguments, maximumHeapSize)
     }
 
+    @Suppress("LongParameterList")
     fun startJavaProcess(
             className: String,
             arguments: List<String>,
@@ -25,7 +24,8 @@ object ProcessUtilities {
             workingDirectory: Path? = null,
             jdwpPort: Int? = null,
             extraJvmArguments: List<String> = emptyList(),
-            maximumHeapSize: String? = null
+            maximumHeapSize: String? = null,
+            identifier: String = ""
     ): Process {
         val command = mutableListOf<String>().apply {
             add(javaPath)
@@ -40,11 +40,10 @@ object ProcessUtilities {
             inheritIO()
             environment()["CLASSPATH"] = classPath.joinToString(File.pathSeparator)
             if (workingDirectory != null) {
-                // Timestamp may be handy if the same process started, killed and then re-started. Without timestamp
-                // StdOut and StdErr will be overwritten.
-                val timestamp = ZonedDateTime.now().format(DateTimeFormatter.ofPattern("HHmmss.SSS"))
-                redirectError((workingDirectory / "$className.$timestamp.stderr.log").toFile())
-                redirectOutput((workingDirectory / "$className.$timestamp.stdout.log").toFile())
+                // An identifier may be handy if the same process started, killed and then re-started. Without the identifier
+                // StdOut and StdErr will be overwritten. By default the identifier is a timestamp passed down to here.
+                redirectError((workingDirectory / "$className.$identifier.stderr.log").toFile())
+                redirectOutput((workingDirectory / "$className.$identifier.stdout.log").toFile())
                 directory(workingDirectory.toFile())
             }
         }.start()