diff --git a/node/src/main/kotlin/net/corda/node/internal/NodeStartup.kt b/node/src/main/kotlin/net/corda/node/internal/NodeStartup.kt index 937296c4ea..01b62d0a1b 100644 --- a/node/src/main/kotlin/net/corda/node/internal/NodeStartup.kt +++ b/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 attempt(action: () -> RESULT): Try = 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) } diff --git a/testing/node-driver/src/main/kotlin/net/corda/testing/node/internal/DriverDSLImpl.kt b/testing/node-driver/src/main/kotlin/net/corda/testing/node/internal/DriverDSLImpl.kt index b331087f85..67eeab2f99 100644 --- a/testing/node-driver/src/main/kotlin/net/corda/testing/node/internal/DriverDSLImpl.kt +++ b/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 { 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 { 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, - maximumHeapSize: String, - logLevelOverride: String?, - vararg extraCmdLineFlag: String + config: NodeConfig, + quasarJarPath: String, + debugPort: Int?, + bytemanJarPath: String?, + bytemanPort: Int?, + overriddenSystemProperties: Map, + 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 ) } diff --git a/testing/node-driver/src/main/kotlin/net/corda/testing/node/internal/InternalTestUtils.kt b/testing/node-driver/src/main/kotlin/net/corda/testing/node/internal/InternalTestUtils.kt index 7408017067..33df4fb933 100644 --- a/testing/node-driver/src/main/kotlin/net/corda/testing/node/internal/InternalTestUtils.kt +++ b/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 { + 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 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 StartedNodeServices.startFlow(logic: FlowLogic): FlowStateMachine = startFlow(logic, newContext()).getOrThrow() fun StartedNodeServices.newContext(): InvocationContext = testContext(myInfo.chooseIdentity().name) diff --git a/testing/node-driver/src/main/kotlin/net/corda/testing/node/internal/ProcessUtilities.kt b/testing/node-driver/src/main/kotlin/net/corda/testing/node/internal/ProcessUtilities.kt index 224d525ca4..a6ba45a5b2 100644 --- a/testing/node-driver/src/main/kotlin/net/corda/testing/node/internal/ProcessUtilities.kt +++ b/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 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, @@ -25,7 +24,8 @@ object ProcessUtilities { workingDirectory: Path? = null, jdwpPort: Int? = null, extraJvmArguments: List = emptyList(), - maximumHeapSize: String? = null + maximumHeapSize: String? = null, + identifier: String = "" ): Process { val command = mutableListOf().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()