Remove BriefLogFormatter as the formatting is now handled by Log4j configuration. Introduce LogHelpers which now handles the custom log level setting for specific loggers.

config/dev/log4j2.xml

@@ -46,10 +46,14 @@
     </Appenders>
 
     <Loggers>
-        <Root level="trace">
-            <AppenderRef ref="Console-Appender" level="info"/>
-            <AppenderRef ref="RollingFile-Appender" level="debug"/>
+        <Root level="info">
+            <AppenderRef ref="Console-Appender"/>
+            <AppenderRef ref="RollingFile-Appender"/>
         </Root>
+        <Logger name="com.r3corda" level="info" additivity="false">
+            <AppenderRef ref="Console-Appender"/>
+            <AppenderRef ref="RollingFile-Appender"/>
+        </Logger>
     </Loggers>
 
 </Configuration>

config/test/log4j2.xml

@@ -11,7 +11,10 @@
     </Appenders>
     <Loggers>
         <Root level="info">
-            <AppenderRef ref="Console-Appender" level="info"/>
+            <AppenderRef ref="Console-Appender"/>
         </Root>
+        <Logger name="com.r3corda" level="info" additivity="false">
+            <AppenderRef ref="Console-Appender"/>
+        </Logger>
     </Loggers>
 </Configuration>

core/src/main/kotlin/com/r3corda/core/utilities/Logging.kt

@@ -1,14 +1,11 @@
 package com.r3corda.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 java.io.PrintWriter
-import java.io.StringWriter
-import java.text.MessageFormat
-import java.util.*
-import java.util.logging.Formatter
-import java.util.logging.Level
-import java.util.logging.LogRecord
-import java.util.logging.Logger
 import kotlin.reflect.KClass
 
 // A couple of inlined utility functions: the first is just a syntax convenience, the second lets us use
@@ -20,74 +17,47 @@ inline fun org.slf4j.Logger.trace(msg: () -> String) {
     if (isTraceEnabled) trace(msg())
 }
 
-/**
- * A Java logging formatter that writes more compact output than the default.
- */
-class BriefLogFormatter : Formatter() {
-    override fun format(logRecord: LogRecord): String {
-        val arguments = arrayOfNulls<Any>(7)
-        arguments[0] = logRecord.threadID
-        arguments[1] = when (logRecord.level) {
-            Level.SEVERE -> " **ERROR** "
-            Level.WARNING -> " (warning) "
-            else -> ""
+/** A configuration helper that allows modifying the log level for specific loggers */
+object LogHelper {
+    /**
+     * Takes a set of strings identifying logger names for which the logging level should be configured.
+     * If the logger name starts with a + or an ordinary character, the level is set to [Level.ALL]. If it starts
+     * with a - then logging is switched off.
+     */
+    fun setLevel(vararg loggerNames: String) {
+        for (spec in loggerNames) {
+            val (name, level) = when (spec[0]) {
+                '+' -> spec.substring(1) to Level.ALL
+                '-' -> spec.substring(1) to Level.OFF
+                else -> spec to Level.ALL
+            }
+            setLevel(name, level)
         }
-        val fullClassName = logRecord.sourceClassName
-        val dollarIndex = fullClassName.lastIndexOf('$')
-        val className = fullClassName.substring(fullClassName.lastIndexOf('.') + 1, if (dollarIndex == -1) fullClassName.length else dollarIndex)
-        arguments[2] = className
-        arguments[3] = logRecord.sourceMethodName
-        arguments[4] = Date(logRecord.millis)
-        arguments[5] = if (logRecord.parameters != null) MessageFormat.format(logRecord.message, *logRecord.parameters) else logRecord.message
-        if (logRecord.thrown != null) {
-            val result = StringWriter()
-            logRecord.thrown.printStackTrace(PrintWriter(result))
-            arguments[6] = result.toString()
-        } else {
-            arguments[6] = ""
-        }
-        return messageFormat.format(arguments)
     }
 
-    companion object {
-        private val messageFormat = MessageFormat("{4,date,HH:mm:ss} {0} {1}{2}.{3}: {5}\n{6}")
+    fun setLevel(vararg classes: KClass<*>) = setLevel(*classes.map { "+" + it.java.`package`.name }.toTypedArray())
 
-        // OpenJDK made a questionable, backwards incompatible change to the Logger implementation. It internally uses
-        // weak references now which means simply fetching the logger and changing its configuration won't work. We must
-        // keep a reference to our custom logger around.
-        private val loggerRefs = ArrayList<Logger>()
+    /** Removes custom configuration for the specified logger names */
+    fun reset(vararg names: String) {
+        val loggerContext = LogManager.getContext(false) as LoggerContext
+        val config = loggerContext.configuration
+        names.forEach { config.removeLogger(it) }
+        loggerContext.updateLoggers(config)
+    }
 
-        /** Configures JDK logging to use this class for everything.  */
-        fun init() {
-            val logger = Logger.getLogger("")
-            val handlers = logger.handlers
-            handlers[0].formatter = BriefLogFormatter()
-            loggerRefs.add(logger)
+    fun reset(vararg classes: KClass<*>) = reset(*classes.map { it.java.`package`.name }.toTypedArray())
+
+    /** Updates logging level for the specified Log4j logger name */
+    private fun setLevel(name: String, level: Level) {
+        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)
         }
-
-        /**
-         * Takes a set of strings identifying logger names for which the logging level should be configured.
-         * If the logger name starts with a + or an ordinary character, the level is set to [Level.ALL]. If it starts
-         * with a - then logging is switched off.
-         */
-        fun initVerbose(vararg loggerNames: String) {
-            init()
-            loggerRefs[0].handlers[0].level = Level.ALL
-            for (spec in loggerNames) {
-                val (name, level) = when (spec[0]) {
-                    '+' -> spec.substring(1) to Level.FINEST
-                    '-' -> spec.substring(1) to Level.OFF
-                    else -> spec to Level.ALL
-                }
-                val logger = Logger.getLogger(name)
-                logger.level = level
-                loggerRefs.add(logger)
-            }
-        }
-
-        fun loggingOn(vararg names: String) = initVerbose(*names)
-        fun loggingOff(vararg names: String) = initVerbose(*names.map { "-" + it }.toTypedArray())
-        fun loggingOn(vararg classes: KClass<*>) = initVerbose(*classes.map { "+" + it.java.`package`.name }.toTypedArray())
-        fun loggingOff(vararg classes: KClass<*>) = initVerbose(*classes.map { "-" + it.java.`package`.name }.toTypedArray())
+        config.removeLogger(name)
+        config.addLogger(name, loggerConfig)
+        loggerContext.updateLoggers(config)
     }
 }

node/src/main/kotlin/com/r3corda/node/internal/testing/MockNode.kt

@@ -36,7 +36,7 @@ import java.util.*
  *
  * You can get a printout of every message sent by using code like:
  *
- *    BriefLogFormatter.initVerbose("+messaging")
+ *    LogHelper.setLevel("+messages")
  */
 class MockNetwork(private val networkSendManuallyPumped: Boolean = false,
                   private val threadPerNode: Boolean = false,

node/src/main/kotlin/com/r3corda/node/utilities/ANSIProgressRenderer.kt

@@ -9,7 +9,6 @@ import org.apache.logging.log4j.core.LoggerContext
 import org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender
 import org.apache.logging.log4j.core.appender.ConsoleAppender
 import org.apache.logging.log4j.core.appender.OutputStreamManager
-import org.apache.logging.log4j.core.config.LoggerConfig
 import org.fusesource.jansi.Ansi
 import org.fusesource.jansi.AnsiConsole
 import org.fusesource.jansi.AnsiOutputStream
@@ -85,10 +84,13 @@ object ANSIProgressRenderer {
             }
             scrollingAppender.start()
             manager.configuration.appenders[consoleAppender.name] = scrollingAppender
-            val loggerConfig: LoggerConfig = manager.configuration.loggers.values.single()
-            val appenderRefs = loggerConfig.appenderRefs
-            loggerConfig.appenders.keys.forEach { loggerConfig.removeAppender(it) }
-            appenderRefs.forEach { loggerConfig.addAppender(manager.configuration.appenders[it.ref], it.level, it.filter) }
+            val loggerConfigs = manager.configuration.loggers.values
+            for (config in loggerConfigs) {
+                val appenderRefs = config.appenderRefs
+                val consoleAppenders = config.appenders.filter { it.value is ConsoleAppender }.keys
+                consoleAppenders.forEach { config.removeAppender(it) }
+                appenderRefs.forEach { config.addAppender(manager.configuration.appenders[it.ref], it.level, it.filter) }
+            }
             manager.updateLoggers()
         }
 

node/src/test/kotlin/com/r3corda/node/messaging/AttachmentTests.kt

@@ -7,7 +7,6 @@ import com.r3corda.core.node.NodeInfo
 import com.r3corda.core.node.services.ServiceType
 import com.r3corda.core.serialization.OpaqueBytes
 import com.r3corda.core.testing.rootCauseExceptions
-import com.r3corda.core.utilities.BriefLogFormatter
 import com.r3corda.node.internal.testing.MockNetwork
 import com.r3corda.node.services.config.NodeConfiguration
 import com.r3corda.node.services.network.NetworkMapService
@@ -32,10 +31,6 @@ import kotlin.test.assertFailsWith
 class AttachmentTests {
     lateinit var network: MockNetwork
 
-    init {
-        BriefLogFormatter.init()
-    }
-
     @Before
     fun setUp() {
         network = MockNetwork()

node/src/test/kotlin/com/r3corda/node/messaging/InMemoryMessagingTests.kt

@@ -16,10 +16,6 @@ import kotlin.test.assertTrue
 class InMemoryMessagingTests {
     lateinit var network: MockNetwork
 
-    init {
-        // BriefLogFormatter.initVerbose()
-    }
-
     @Before
     fun setUp() {
         network = MockNetwork()

node/src/test/kotlin/com/r3corda/node/messaging/TwoPartyTradeProtocolTests.kt

@@ -15,7 +15,7 @@ import com.r3corda.core.node.services.TransactionStorage
 import com.r3corda.core.node.services.Wallet
 import com.r3corda.core.random63BitValue
 import com.r3corda.core.testing.*
-import com.r3corda.core.utilities.BriefLogFormatter
+import com.r3corda.core.utilities.LogHelper
 import com.r3corda.node.internal.testing.MockNetwork
 import com.r3corda.node.services.config.NodeConfiguration
 import com.r3corda.node.services.network.InMemoryMessagingNetwork
@@ -68,12 +68,12 @@ class TwoPartyTradeProtocolTests {
     fun before() {
         net = MockNetwork(false)
         net.identities += MOCK_IDENTITY_SERVICE.identities
-        BriefLogFormatter.loggingOn("platform.trade", "core.contract.TransactionGroup", "recordingmap")
+        LogHelper.setLevel("platform.trade", "core.contract.TransactionGroup", "recordingmap")
     }
 
     @After
     fun after() {
-        BriefLogFormatter.loggingOff("platform.trade", "core.contract.TransactionGroup", "recordingmap")
+        LogHelper.reset("platform.trade", "core.contract.TransactionGroup", "recordingmap")
     }
 
     @Test
@@ -506,7 +506,7 @@ class TwoPartyTradeProtocolTests {
 
     interface TxRecord {
         data class Add(val transaction: SignedTransaction) : TxRecord
-        data class Get(val id: SecureHash): TxRecord
+        data class Get(val id: SecureHash) : TxRecord
     }
 
 

node/src/test/kotlin/com/r3corda/node/services/InMemoryNetworkMapServiceTest.kt

@@ -5,7 +5,6 @@ import com.r3corda.core.crypto.SecureHash
 import com.r3corda.core.node.NodeInfo
 import com.r3corda.core.protocols.ProtocolLogic
 import com.r3corda.core.random63BitValue
-import com.r3corda.core.utilities.BriefLogFormatter
 import com.r3corda.node.internal.testing.MockNetwork
 import com.r3corda.node.services.network.InMemoryNetworkMapService
 import com.r3corda.node.services.network.NetworkMapService
@@ -23,10 +22,6 @@ import kotlin.test.assertTrue
 class InMemoryNetworkMapServiceTest {
     lateinit var network: MockNetwork
 
-    init {
-        BriefLogFormatter.init()
-    }
-
     @Before
     fun setup() {
         network = MockNetwork()

node/src/test/kotlin/com/r3corda/node/services/NodeInterestRatesTest.kt

@@ -15,7 +15,7 @@ import com.r3corda.core.testing.ALICE_PUBKEY
 import com.r3corda.core.testing.DUMMY_NOTARY
 import com.r3corda.core.testing.MEGA_CORP
 import com.r3corda.core.testing.MEGA_CORP_KEY
-import com.r3corda.core.utilities.BriefLogFormatter
+import com.r3corda.core.utilities.LogHelper
 import com.r3corda.node.internal.testing.MockNetwork
 import com.r3corda.node.services.clientapi.NodeInterestRates
 import com.r3corda.protocols.RatesFixProtocol
@@ -109,7 +109,7 @@ class NodeInterestRatesTest {
         val tx = TransactionType.General.Builder()
         val fixOf = NodeInterestRates.parseFixOf("LIBOR 2016-03-16 1M")
         val protocol = RatesFixProtocol(tx, n2.info.identity, fixOf, "0.675".bd, "0.1".bd)
-        BriefLogFormatter.initVerbose("rates")
+        LogHelper.setLevel("rates")
         net.runNetwork()
         val future = n1.smm.add("rates", protocol)
 
@@ -122,5 +122,5 @@ class NodeInterestRatesTest {
         assertEquals("0.678".bd, fix.value)
     }
 
-    private fun makeTX() =  TransactionType.General.Builder().withItems(1000.DOLLARS.CASH `issued by` DUMMY_CASH_ISSUER `owned by` ALICE_PUBKEY `with notary` DUMMY_NOTARY)
+    private fun makeTX() = TransactionType.General.Builder().withItems(1000.DOLLARS.CASH `issued by` DUMMY_CASH_ISSUER `owned by` ALICE_PUBKEY `with notary` DUMMY_NOTARY)
 }

node/src/test/kotlin/com/r3corda/node/services/NodeWalletServiceTest.kt

@@ -8,7 +8,7 @@ import com.r3corda.core.node.services.WalletService
 import com.r3corda.core.node.services.testing.MockServices
 import com.r3corda.core.node.services.testing.makeTestDataSourceProperties
 import com.r3corda.core.testing.DUMMY_NOTARY
-import com.r3corda.core.utilities.BriefLogFormatter
+import com.r3corda.core.utilities.LogHelper
 import com.r3corda.node.services.wallet.NodeWalletService
 import com.r3corda.node.utilities.configureDatabase
 import org.assertj.core.api.Assertions.assertThat
@@ -23,14 +23,14 @@ class NodeWalletServiceTest {
 
     @Before
     fun setUp() {
-        BriefLogFormatter.loggingOn(NodeWalletService::class)
+        LogHelper.setLevel(NodeWalletService::class)
         dataSource = configureDatabase(makeTestDataSourceProperties()).first
     }
 
     @After
     fun tearDown() {
         dataSource.close()
-        BriefLogFormatter.loggingOff(NodeWalletService::class)
+        LogHelper.reset(NodeWalletService::class)
     }
 
     @Test

node/src/test/kotlin/com/r3corda/node/services/WalletWithCashTest.kt

@@ -10,7 +10,7 @@ import com.r3corda.core.node.services.WalletService
 import com.r3corda.core.node.services.testing.MockServices
 import com.r3corda.core.node.services.testing.makeTestDataSourceProperties
 import com.r3corda.core.testing.*
-import com.r3corda.core.utilities.BriefLogFormatter
+import com.r3corda.core.utilities.LogHelper
 import com.r3corda.node.services.wallet.NodeWalletService
 import com.r3corda.node.utilities.configureDatabase
 import org.assertj.core.api.Assertions.assertThatThrownBy
@@ -31,7 +31,7 @@ class WalletWithCashTest {
 
     @Before
     fun setUp() {
-        BriefLogFormatter.loggingOn(NodeWalletService::class)
+        LogHelper.setLevel(NodeWalletService::class)
         dataSource = configureDatabase(makeTestDataSourceProperties()).first
         services = object : MockServices() {
             override val walletService: WalletService = NodeWalletService(this)
@@ -47,8 +47,8 @@ class WalletWithCashTest {
 
     @After
     fun tearDown() {
+        LogHelper.reset(NodeWalletService::class)
         dataSource.close()
-        BriefLogFormatter.loggingOff(NodeWalletService::class)
     }
 
     @Test

node/src/test/kotlin/com/r3corda/node/services/persistence/DataVendingServiceTests.kt

@@ -7,7 +7,6 @@ import com.r3corda.core.contracts.TransactionType
 import com.r3corda.core.contracts.USD
 import com.r3corda.core.testing.DUMMY_NOTARY
 import com.r3corda.core.testing.MEGA_CORP
-import com.r3corda.core.utilities.BriefLogFormatter
 import com.r3corda.node.internal.testing.MockNetwork
 import org.junit.Before
 import org.junit.Test
@@ -22,10 +21,6 @@ import kotlin.test.assertTrue
 class DataVendingServiceTests {
     lateinit var network: MockNetwork
 
-    init {
-        BriefLogFormatter.init()
-    }
-
     @Before
     fun setup() {
         network = MockNetwork()

src/main/kotlin/com/r3corda/demos/IRSDemo.kt

@@ -9,7 +9,7 @@ import com.r3corda.core.node.CordaPluginRegistry
 import com.r3corda.core.node.NodeInfo
 import com.r3corda.core.node.services.ServiceType
 import com.r3corda.core.serialization.deserialize
-import com.r3corda.core.utilities.BriefLogFormatter
+import com.r3corda.core.utilities.LogHelper
 import com.r3corda.demos.api.InterestRateSwapAPI
 import com.r3corda.demos.protocols.AutoOfferProtocol
 import com.r3corda.demos.protocols.ExitServerProtocol
@@ -79,7 +79,7 @@ sealed class CliParams {
     class RunNode(
             val node: IRSDemoNode,
             val dir: Path,
-            val networkAddress : HostAndPort,
+            val networkAddress: HostAndPort,
             val apiAddress: HostAndPort,
             val mapAddress: String,
             val identityFile: Path,
@@ -285,8 +285,8 @@ fun runIRSDemo(args: Array<String>): Int {
         return 1
     }
 
-    // Suppress the Artemis MQ noise, and activate the demo logging.
-    BriefLogFormatter.initVerbose("+demo.irsdemo", "+api-call", "+platform.deal", "-org.apache.activemq")
+    // Suppress the Artemis MQ noise, and activate the demo logging
+    LogHelper.setLevel("+IRSDemo", "+api-call", "+platform.deal", "-org.apache.activemq")
 
     return when (cliParams) {
         is CliParams.SetupNode -> setup(cliParams)
@@ -376,12 +376,12 @@ private fun runTrade(cliParams: CliParams.Trade): Int {
     }
 }
 
-private fun createRecipient(addr: String) : SingleMessageRecipient {
+private fun createRecipient(addr: String): SingleMessageRecipient {
     val hostAndPort = HostAndPort.fromString(addr).withDefaultPort(Node.DEFAULT_PORT)
     return ArtemisMessagingClient.makeRecipient(hostAndPort)
 }
 
-private fun startNode(params: CliParams.RunNode, networkMap: SingleMessageRecipient) : Node {
+private fun startNode(params: CliParams.RunNode, networkMap: SingleMessageRecipient): Node {
     val config = getNodeConfig(params)
     val advertisedServices: Set<ServiceType>
     val networkMapId =
@@ -418,7 +418,7 @@ private fun nodeInfo(recipient: SingleMessageRecipient, identityFile: Path, adve
 private fun runUploadRates(host: HostAndPort) {
     // Note: the getResourceAsStream is an ugly hack to get the jvm to search in the right location
     val fileContents = IOUtils.toString(CliParams::class.java.getResourceAsStream("example.rates.txt"))
-    var timer : Timer? = null
+    var timer: Timer? = null
     timer = fixedRateTimer("upload-rates", false, 0, 5000, {
         try {
             val url = URL("http://${host.toString()}/upload/interest-rates")

src/main/kotlin/com/r3corda/demos/RateFixDemo.kt

@@ -9,8 +9,8 @@ import com.r3corda.core.logElapsedTime
 import com.r3corda.core.node.NodeInfo
 import com.r3corda.core.node.services.ServiceType
 import com.r3corda.core.serialization.deserialize
-import com.r3corda.core.utilities.BriefLogFormatter
 import com.r3corda.core.utilities.Emoji
+import com.r3corda.core.utilities.LogHelper
 import com.r3corda.node.internal.Node
 import com.r3corda.node.services.clientapi.NodeInterestRates
 import com.r3corda.node.services.config.NodeConfiguration
@@ -53,7 +53,7 @@ fun main(args: Array<String>) {
     }
 
     // Suppress the Artemis MQ noise, and activate the demo logging.
-    BriefLogFormatter.initVerbose("+demo.ratefix", "-org.apache.activemq")
+    LogHelper.setLevel("+RatesFixDemo", "-org.apache.activemq")
 
     val dir = Paths.get(options.valueOf(dirArg))
     val networkMapAddr = ArtemisMessagingClient.makeRecipient(options.valueOf(networkMapAddrArg))

src/main/kotlin/com/r3corda/demos/TraderDemo.kt

@@ -19,8 +19,8 @@ import com.r3corda.core.protocols.ProtocolLogic
 import com.r3corda.core.random63BitValue
 import com.r3corda.core.seconds
 import com.r3corda.core.serialization.deserialize
-import com.r3corda.core.utilities.BriefLogFormatter
 import com.r3corda.core.utilities.Emoji
+import com.r3corda.core.utilities.LogHelper
 import com.r3corda.core.utilities.ProgressTracker
 import com.r3corda.node.internal.Node
 import com.r3corda.node.services.config.NodeConfiguration
@@ -115,7 +115,7 @@ fun runTraderDemo(args: Array<String>): Int {
     //
     // The first two strings correspond to the first argument to StateMachineManager.add() but the way we handle logging
     // for protocols will change in future.
-    BriefLogFormatter.initVerbose("+demo.buyer", "+demo.seller", "-org.apache.activemq")
+    LogHelper.setLevel("+demo.buyer", "+demo.seller", "-org.apache.activemq")
 
     val directory = Paths.get(baseDirectory, role.name.toLowerCase())
     log.info("Using base demo directory $directory")

src/test/kotlin/com/r3corda/core/testing/IRSSimulationTest.kt

@@ -1,7 +1,7 @@
 package com.r3corda.core.testing
 
 import com.google.common.base.Throwables
-import com.r3corda.core.utilities.BriefLogFormatter
+import com.r3corda.core.utilities.LogHelper
 import com.r3corda.node.internal.testing.IRSSimulation
 import org.junit.Test
 
@@ -9,7 +9,7 @@ class IRSSimulationTest {
     // TODO: These tests should be a lot more complete.
 
     @Test fun `runs to completion`() {
-        BriefLogFormatter.initVerbose("messaging")
+        LogHelper.setLevel("+messages")
         val sim = IRSSimulation(false, false, null)
         val future = sim.start()
         while (!future.isDone) sim.iterate()