Logging fixes, including broken --logging-level cmd line arg

This commit is contained in:
Shams Asari 2017-03-20 15:41:13 +00:00
parent 18c57cf951
commit 209f5c8a25
6 changed files with 70 additions and 61 deletions

View File

@ -3,7 +3,6 @@ package net.corda.core.utilities
import org.apache.logging.log4j.Level
import org.apache.logging.log4j.LogManager
import org.apache.logging.log4j.core.LoggerContext
import org.apache.logging.log4j.core.appender.ConsoleAppender
import org.apache.logging.log4j.core.config.LoggerConfig
import org.slf4j.LoggerFactory
import kotlin.reflect.KClass
@ -56,10 +55,7 @@ object LogHelper {
val loggerContext = LogManager.getContext(false) as LoggerContext
val config = loggerContext.configuration
val loggerConfig = LoggerConfig(name, level, false)
val appender = config.appenders.map { it.value as? ConsoleAppender }.singleOrNull()
appender?.let {
loggerConfig.addAppender(appender, null, null)
}
loggerConfig.addAppender(config.appenders["Console-Appender"], null, null)
config.removeLogger(name)
config.addLogger(name, loggerConfig)
loggerContext.updateLoggers(config)

View File

@ -1,19 +1,24 @@
package net.corda.node.driver
import com.google.common.net.HostAndPort
import net.corda.core.div
import net.corda.core.getOrThrow
import net.corda.core.list
import net.corda.core.node.NodeInfo
import net.corda.core.node.services.ServiceInfo
import net.corda.core.readLines
import net.corda.node.LOGS_DIRECTORY_NAME
import net.corda.node.services.api.RegulatorService
import net.corda.node.services.messaging.ArtemisMessagingComponent
import net.corda.node.services.transactions.SimpleNotaryService
import org.assertj.core.api.Assertions.assertThat
import org.junit.Test
import java.nio.file.Paths
import java.util.concurrent.Executors
import java.util.concurrent.ScheduledExecutorService
class DriverTests {
companion object {
val executorService = Executors.newScheduledThreadPool(2)
val executorService: ScheduledExecutorService = Executors.newScheduledThreadPool(2)
fun nodeMustBeUp(nodeInfo: NodeInfo) {
val hostAndPort = ArtemisMessagingComponent.toHostAndPort(nodeInfo.address)
@ -29,7 +34,7 @@ class DriverTests {
}
@Test
fun simpleNodeStartupShutdownWorks() {
fun `simple node startup and shutdown`() {
val (notary, regulator) = driver {
val notary = startNode("TestNotary", setOf(ServiceInfo(SimpleNotaryService.type)))
val regulator = startNode("Regulator", setOf(ServiceInfo(RegulatorService.type)))
@ -43,7 +48,7 @@ class DriverTests {
}
@Test
fun startingNodeWithNoServicesWorks() {
fun `starting node with no services`() {
val noService = driver {
val noService = startNode("NoService")
nodeMustBeUp(noService.getOrThrow().nodeInfo)
@ -53,12 +58,25 @@ class DriverTests {
}
@Test
fun randomFreePortAllocationWorks() {
val nodeInfo = driver(portAllocation = PortAllocation.RandomFree) {
fun `random free port allocation`() {
val nodeHandle = driver(portAllocation = PortAllocation.RandomFree) {
val nodeInfo = startNode("NoService")
nodeMustBeUp(nodeInfo.getOrThrow().nodeInfo)
nodeInfo.getOrThrow()
}
nodeMustBeDown(nodeInfo.nodeInfo)
nodeMustBeDown(nodeHandle.nodeInfo)
}
@Test
fun `debug mode enables debug logging level`() {
// Make sure we're using the log4j2 config which writes to the log file
val logConfigFile = Paths.get("..", "config", "dev", "log4j2.xml").toAbsolutePath()
assertThat(logConfigFile).isRegularFile()
driver(isDebug = true, systemProperties = mapOf("log4j.configurationFile" to logConfigFile.toString())) {
val baseDirectory = startNode("Alice").getOrThrow().configuration.baseDirectory
val logFile = (baseDirectory / LOGS_DIRECTORY_NAME).list { it.sorted().findFirst().get() }
val debugLinesPresent = logFile.readLines { lines -> lines.anyMatch { line -> line.startsWith("[DEBUG]") } }
assertThat(debugLinesPresent).isTrue()
}
}
}

View File

@ -10,6 +10,7 @@ import java.io.PrintStream
import java.nio.file.Path
import java.nio.file.Paths
// NOTE: Do not use any logger in this class as args parsing is done before the logger is setup.
class ArgsParser {
private val optionParser = OptionParser()
// The intent of allowing a command line configurable directory and config path is to allow deployment flexibility.

View File

@ -1,8 +1,8 @@
@file:JvmName("Corda")
package net.corda.node
import com.typesafe.config.Config
import com.jcabi.manifests.Manifests
import com.typesafe.config.Config
import com.typesafe.config.ConfigException
import joptsimple.OptionException
import net.corda.core.*
@ -31,19 +31,12 @@ fun printBasicNodeInfo(description: String, info: String? = null) {
LoggerFactory.getLogger(loggerName).info(msg)
}
val LOGS_DIRECTORY_NAME = "logs"
fun main(args: Array<String>) {
val startTime = System.currentTimeMillis()
checkJavaVersion()
// Manifest properties are only available if running from the corda jar
fun manifestValue(name: String): String? = if (Manifests.exists(name)) Manifests.read(name) else null
val nodeVersionInfo = NodeVersionInfo(
manifestValue("Corda-Version")?.let { Version.parse(it) } ?: Version(0, 0, false),
manifestValue("Corda-Revision") ?: "Unknown",
manifestValue("Corda-Vendor") ?: "Unknown"
)
val argsParser = ArgsParser()
val cmdlineOptions = try {
@ -54,6 +47,23 @@ fun main(args: Array<String>) {
exitProcess(1)
}
// Set up logging. These properties are referenced from the XML config file.
val loggingLevel = cmdlineOptions.loggingLevel.name.toLowerCase()
System.setProperty("defaultLogLevel", loggingLevel)
if (cmdlineOptions.logToConsole) {
System.setProperty("consoleLogLevel", loggingLevel)
renderBasicInfoToConsole = false
}
// Manifest properties are only available if running from the corda jar
fun manifestValue(name: String): String? = if (Manifests.exists(name)) Manifests.read(name) else null
val nodeVersionInfo = NodeVersionInfo(
manifestValue("Corda-Version")?.let { Version.parse(it) } ?: Version(0, 0, false),
manifestValue("Corda-Revision") ?: "Unknown",
manifestValue("Corda-Vendor") ?: "Unknown"
)
if (cmdlineOptions.isVersion) {
println("${nodeVersionInfo.vendor} ${nodeVersionInfo.version}")
println("Revision ${nodeVersionInfo.revision}")
@ -66,16 +76,9 @@ fun main(args: Array<String>) {
exitProcess(0)
}
// Set up logging. These properties are referenced from the XML config file.
System.setProperty("defaultLogLevel", cmdlineOptions.loggingLevel.name.toLowerCase())
if (cmdlineOptions.logToConsole) {
System.setProperty("consoleLogLevel", cmdlineOptions.loggingLevel.name.toLowerCase())
renderBasicInfoToConsole = false
}
drawBanner(nodeVersionInfo)
System.setProperty("log-path", (cmdlineOptions.baseDirectory / "logs").toString())
System.setProperty("log-path", (cmdlineOptions.baseDirectory / LOGS_DIRECTORY_NAME).toString())
val log = LoggerFactory.getLogger("Main")
printBasicNodeInfo("Logs can be found in", System.getProperty("log-path"))

View File

@ -8,7 +8,6 @@ import com.google.common.util.concurrent.ListenableFuture
import com.google.common.util.concurrent.SettableFuture
import com.typesafe.config.Config
import com.typesafe.config.ConfigRenderOptions
import net.corda.nodeapi.config.SSLConfiguration
import net.corda.core.*
import net.corda.core.crypto.Party
import net.corda.core.messaging.CordaRPCOps
@ -16,6 +15,7 @@ import net.corda.core.node.NodeInfo
import net.corda.core.node.services.ServiceInfo
import net.corda.core.node.services.ServiceType
import net.corda.core.utilities.loggerFor
import net.corda.node.LOGS_DIRECTORY_NAME
import net.corda.node.services.User
import net.corda.node.services.config.ConfigHelper
import net.corda.node.services.config.FullNodeConfiguration
@ -25,6 +25,7 @@ import net.corda.node.services.messaging.NodeMessagingClient
import net.corda.node.services.network.NetworkMapService
import net.corda.node.services.transactions.RaftValidatingNotaryService
import net.corda.node.utilities.ServiceIdentityGenerator
import net.corda.nodeapi.config.SSLConfiguration
import okhttp3.OkHttpClient
import okhttp3.Request
import org.slf4j.Logger
@ -146,6 +147,7 @@ sealed class PortAllocation {
* and may be specified in [DriverDSL.startNode].
* @param portAllocation The port allocation strategy to use for the messaging and the web server addresses. Defaults to incremental.
* @param debugPortAllocation The port allocation strategy to use for jvm debugging. Defaults to incremental.
* @param systemProperties A Map of extra system properties which will be given to each new node. Defaults to empty.
* @param useTestClock If true the test clock will be used in Node.
* @param isDebug Indicates whether the spawned nodes should start in jdwt debug mode and have debug level logging.
* @param dsl The dsl itself.
@ -157,12 +159,14 @@ fun <A> driver(
driverDirectory: Path = Paths.get("build", getTimestampAsDirectoryName()),
portAllocation: PortAllocation = PortAllocation.Incremental(10000),
debugPortAllocation: PortAllocation = PortAllocation.Incremental(5005),
systemProperties: Map<String, String> = emptyMap(),
useTestClock: Boolean = false,
dsl: DriverDSLExposedInterface.() -> A
) = genericDriver(
driverDsl = DriverDSL(
portAllocation = portAllocation,
debugPortAllocation = debugPortAllocation,
systemProperties = systemProperties,
driverDirectory = driverDirectory.toAbsolutePath(),
useTestClock = useTestClock,
isDebug = isDebug
@ -266,6 +270,7 @@ private fun <A> poll(
open class DriverDSL(
val portAllocation: PortAllocation,
val debugPortAllocation: PortAllocation,
val systemProperties: Map<String, String>,
val driverDirectory: Path,
val useTestClock: Boolean,
val isDebug: Boolean
@ -378,7 +383,7 @@ open class DriverDSL(
)
)
val processFuture = startNode(executorService, configuration, quasarJarPath, debugPort)
val processFuture = startNode(executorService, configuration, quasarJarPath, debugPort, systemProperties)
registerProcess(processFuture)
return processFuture.flatMap { process ->
// We continue to use SSL enabled port for RPC when its for node user.
@ -474,7 +479,7 @@ open class DriverDSL(
)
log.info("Starting network-map-service")
val startNode = startNode(executorService, FullNodeConfiguration(baseDirectory, config), quasarJarPath, debugPort)
val startNode = startNode(executorService, FullNodeConfiguration(baseDirectory, config), quasarJarPath, debugPort, systemProperties)
registerProcess(startNode)
return startNode
}
@ -492,7 +497,8 @@ open class DriverDSL(
executorService: ScheduledExecutorService,
nodeConf: FullNodeConfiguration,
quasarJarPath: String,
debugPort: Int?
debugPort: Int?,
overriddenSystemProperties: Map<String, String>
): ListenableFuture<Process> {
// Write node.conf
writeConfig(nodeConf.baseDirectory, "node.conf", nodeConf.config)
@ -507,36 +513,28 @@ open class DriverDSL(
else
""
val inheritedProperties = listOf("amq.delivery.delay.ms")
val systemArgs = mutableMapOf(
val systemProperties = mapOf(
"name" to nodeConf.myLegalName,
"visualvm.display.name" to "Corda"
)
inheritedProperties.forEach {
val property = System.getProperty(it)
if (property != null) systemArgs[it] = property
}
) + overriddenSystemProperties
val loggingLevel = if (debugPort == null) "INFO" else "DEBUG"
val javaArgs = listOf(path) +
systemArgs.map { "-D${it.key}=${it.value}" } +
systemProperties.map { "-D${it.key}=${it.value}" } +
listOf(
"-javaagent:$quasarJarPath",
debugPortArg,
"-Xmx200m",
"-XX:+UseG1GC",
"-cp", classpath,
className,
"-cp", classpath, className,
"--base-directory=${nodeConf.baseDirectory}",
"--logging-level=$loggingLevel"
).filter(String::isNotEmpty)
val builder = ProcessBuilder(javaArgs)
builder.redirectError(Paths.get("error.$className.log").toFile())
builder.inheritIO()
builder.directory(nodeConf.baseDirectory.toFile())
val process = builder.start()
val process = ProcessBuilder(javaArgs)
.redirectError((nodeConf.baseDirectory / LOGS_DIRECTORY_NAME / "error.log").toFile())
.inheritIO()
.directory(nodeConf.baseDirectory.toFile())
.start()
// TODO There is a race condition here. Even though the messaging address is bound it may be the case that
// the handlers for the advertised services are not yet registered. Needs rethinking.
return addressMustBeBound(executorService, nodeConf.p2pAddress).map { process }

View File

@ -55,18 +55,11 @@ class FlowStateMachineImpl<R>(override val id: StateMachineRunId,
@Transient internal var fromCheckpoint: Boolean = false
@Transient private var txTrampoline: Transaction? = null
@Transient private var _logger: Logger? = null
/**
* Return the logger for this state machine. The logger name incorporates [id] and so including it in the log message
* is not necessary.
*/
override val logger: Logger get() {
return _logger ?: run {
val l = LoggerFactory.getLogger("net.corda.flow.$id")
_logger = l
return l
}
}
override val logger: Logger = LoggerFactory.getLogger("net.corda.flow.$id")
@Transient private var _resultFuture: SettableFuture<R>? = SettableFuture.create<R>()
/** This future will complete when the call method returns. */
@ -104,7 +97,7 @@ class FlowStateMachineImpl<R>(override val id: StateMachineRunId,
return
}
// Only sessions which have a single send and nothing else will block here
// Only sessions which have done a single send and nothing else will block here
openSessions.values
.filter { it.state is FlowSessionState.Initiating }
.forEach { it.waitForConfirmation() }