diff --git a/config/dev/log4j2.xml b/config/dev/log4j2.xml index b1969e8c25..414498aba9 100644 --- a/config/dev/log4j2.xml +++ b/config/dev/log4j2.xml @@ -13,7 +13,7 @@ - [%-5level] %d{HH:mm:ss.SSS} [%t] %c{1}.%M - %msg%n + %highlight{%level{length=1} %d{HH:mm:ss} %T %c{1}.%M - %msg%n}{INFO=white,WARN=red,FATAL=bright red blink} > diff --git a/node/src/main/kotlin/com/r3corda/node/utilities/ANSIProgressRenderer.kt b/node/src/main/kotlin/com/r3corda/node/utilities/ANSIProgressRenderer.kt index e9bcf5bf99..3e66d93531 100644 --- a/node/src/main/kotlin/com/r3corda/node/utilities/ANSIProgressRenderer.kt +++ b/node/src/main/kotlin/com/r3corda/node/utilities/ANSIProgressRenderer.kt @@ -1,48 +1,35 @@ package com.r3corda.node.utilities -import com.r3corda.core.utilities.BriefLogFormatter import com.r3corda.core.utilities.Emoji import com.r3corda.core.utilities.ProgressTracker +import com.r3corda.node.utilities.ANSIProgressRenderer.progressTracker +import org.apache.logging.log4j.LogManager +import org.apache.logging.log4j.core.LogEvent +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 import rx.Subscription -import java.util.logging.ConsoleHandler -import java.util.logging.Formatter -import java.util.logging.LogRecord -import java.util.logging.Logger /** * Knows how to render a [ProgressTracker] to the terminal using coloured, emoji-fied output. Useful when writing small * command line tools, demos, tests etc. Just set the [progressTracker] field and it will go ahead and start drawing * if the terminal supports it. Otherwise it just prints out the name of the step whenever it changes. * - * TODO: Thread safety + * When a progress tracker is on the screen, it takes over the bottom part and reconfigures logging so that, assuming + * 1 log event == 1 line, the progress tracker is always glued to the bottom and logging scrolls above it. + * + * TODO: More thread safety */ object ANSIProgressRenderer { private var installedYet = false private var subscription: Subscription? = null - private class LineBumpingConsoleHandler : ConsoleHandler() { - override fun getFormatter(): Formatter = BriefLogFormatter() - - override fun publish(r: LogRecord?) { - if (progressTracker != null) { - val ansi = Ansi.ansi() - repeat(prevLinesDrawn) { ansi.eraseLine().cursorUp(1).eraseLine() } - System.out.print(ansi) - System.out.flush() - } - - super.publish(r) - - if (progressTracker != null) - draw(false) - } - } - private var usingANSI = false - private var loggerRef: Logger? = null var progressTracker: ProgressTracker? = null set(value) { @@ -50,24 +37,7 @@ object ANSIProgressRenderer { field = value if (!installedYet) { - AnsiConsole.systemInstall() - - // This line looks weird as hell because the magic code to decide if we really have a TTY or not isn't - // actually exposed anywhere as a function (weak sauce). So we have to rely on our knowledge of jansi - // implementation details. - usingANSI = AnsiConsole.wrapOutputStream(System.out) !is AnsiOutputStream - - if (usingANSI) { - loggerRef = Logger.getLogger("").apply { - val current = handlers[0] - removeHandler(current) - val new = LineBumpingConsoleHandler() - new.level = current.level - addHandler(new) - } - } - - installedYet = true + setup() } // Reset the state when a new tracker is wired up. @@ -77,12 +47,60 @@ object ANSIProgressRenderer { subscription = value?.changes?.subscribe { draw(true) } } + private fun setup() { + AnsiConsole.systemInstall() + + // This line looks weird as hell because the magic code to decide if we really have a TTY or not isn't + // actually exposed anywhere as a function (weak sauce). So we have to rely on our knowledge of jansi + // implementation details. + usingANSI = AnsiConsole.wrapOutputStream(System.out) !is AnsiOutputStream + + if (usingANSI) { + // This super ugly code hacks into log4j and swaps out its console appender for our own. It's a bit simpler + // than doing things the official way with a dedicated plugin, etc, as it avoids mucking around with all + // the config XML and lifecycle goop. + val manager = LogManager.getContext(false) as LoggerContext + val consoleAppender = manager.configuration.appenders.values.filterIsInstance().single() + val scrollingAppender = object : AbstractOutputStreamAppender( + consoleAppender.name, consoleAppender.layout, consoleAppender.filter, + consoleAppender.ignoreExceptions(), true, consoleAppender.manager) { + override fun append(event: LogEvent) { + // We lock on the renderer to avoid threads that are logging to the screen simultaneously messing + // things up. Of course this slows stuff down a bit, but only whilst this little utility is in use. + // Eventually it will be replaced with a real GUI and we can delete all this. + synchronized(ANSIProgressRenderer) { + if (progressTracker != null) { + val ansi = Ansi.ansi() + repeat(prevLinesDrawn) { ansi.eraseLine().cursorUp(1).eraseLine() } + System.out.print(ansi) + System.out.flush() + } + + super.append(event) + + if (progressTracker != null) + draw(false) + } + } + } + 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) } + manager.updateLoggers() + } + + installedYet = true + } + // prevMessagePrinted is just for non-ANSI mode. private var prevMessagePrinted: String? = null // prevLinesDraw is just for ANSI mode. private var prevLinesDrawn = 0 - private fun draw(moveUp: Boolean) { + @Synchronized private fun draw(moveUp: Boolean) { val pt = progressTracker!! if (!usingANSI) { diff --git a/src/main/kotlin/com/r3corda/demos/TraderDemo.kt b/src/main/kotlin/com/r3corda/demos/TraderDemo.kt index e3db2518b8..ebdbde4689 100644 --- a/src/main/kotlin/com/r3corda/demos/TraderDemo.kt +++ b/src/main/kotlin/com/r3corda/demos/TraderDemo.kt @@ -188,14 +188,16 @@ private fun runSeller(node: Node, amount: Amount>, otherSide: P } } + var tradeTX: SignedTransaction? = null if (node.isPreviousCheckpointsPresent) { node.smm.findStateMachines(TraderDemoProtocolSeller::class.java).forEach { - it.second.get() + tradeTX = it.second.get() } } else { val seller = TraderDemoProtocolSeller(otherSide, amount) - node.smm.add("demo.seller", seller).get() + tradeTX = node.smm.add("demo.seller", seller).get() } + println("Sale completed - we have a happy customer!\n\nFinal transaction is:\n\n${Emoji.renderIfSupported(tradeTX!!.tx)}") node.stop() } @@ -261,7 +263,7 @@ private class TraderDemoProtocolBuyer(val otherSide: Party, // TODO: This should be moved into the protocol itself. serviceHub.recordTransactions(listOf(tradeTX)) - logger.info("Purchase complete - we are a happy customer! Final transaction is: " + + println("Purchase complete - we are a happy customer! Final transaction is: " + "\n\n${Emoji.renderIfSupported(tradeTX.tx)}") logIssuanceAttachment(tradeTX) @@ -281,7 +283,7 @@ private class TraderDemoProtocolBuyer(val otherSide: Party, cpIssuance.attachments.first().let { val p = attachmentsPath.toAbsolutePath().resolve("$it.jar") - logger.info(""" + println(""" The issuance of the commercial paper came with an attachment. You can find it expanded in this directory: $p @@ -293,7 +295,7 @@ ${Emoji.renderIfSupported(cpIssuance)}""") private class TraderDemoProtocolSeller(val otherSide: Party, val amount: Amount>, - override val progressTracker: ProgressTracker = TraderDemoProtocolSeller.tracker()) : ProtocolLogic() { + override val progressTracker: ProgressTracker = TraderDemoProtocolSeller.tracker()) : ProtocolLogic() { companion object { val PROSPECTUS_HASH = SecureHash.parse("decd098666b9657314870e192ced0c3519c2c9d395507a238338f8d003929de9") @@ -314,7 +316,7 @@ private class TraderDemoProtocolSeller(val otherSide: Party, override val topic: String get() = DEMO_TOPIC @Suspendable - override fun call() { + override fun call(): SignedTransaction { progressTracker.currentStep = ANNOUNCING val sessionID = sendAndReceive(otherSide, 0, 0, serviceHub.storageService.myLegalIdentity).validate { it } @@ -332,7 +334,7 @@ private class TraderDemoProtocolSeller(val otherSide: Party, val tradeTX: SignedTransaction = subProtocol(seller) serviceHub.recordTransactions(listOf(tradeTX)) - logger.info("Sale completed - we have a happy customer!\n\nFinal transaction is:\n\n${Emoji.renderIfSupported(tradeTX.tx)}") + return tradeTX } @Suspendable