Corda-1931 Asynchronous logging (#3989)

* Provide AsyncLoggingContextSelector that inhibits use of thread local storage

* Turn on async logging via log4j properties file

* Mention async logging in the documentation and also explain how to turn it off when required.

* Formatting

* Typo

* Add shutdown hook to flush loggers.

* code review rework

* Ring buffer size to 256kB

* Set maximal log file size to 100MB - should slow down the rolling of log files and give us a bit more history on the cluster.
The old limit of max 10GB of compressed log files still stands.

build.gradle

@@ -32,6 +32,7 @@ buildscript {
     ext.bouncycastle_version = constants.getProperty("bouncycastleVersion")
     ext.guava_version = constants.getProperty("guavaVersion")
     ext.caffeine_version = constants.getProperty("caffeineVersion")
+    ext.disruptor_version = constants.getProperty("disruptorVersion")
     ext.metrics_version = constants.getProperty("metricsVersion")
     ext.metrics_new_relic_version = constants.getProperty("metricsNewRelicVersion")
     ext.okhttp_version = '3.5.0'

config/dev/log4j2.xml

@@ -46,7 +46,7 @@
 
             <Policies>
                 <TimeBasedTriggeringPolicy/>
-                <SizeBasedTriggeringPolicy size="10MB"/>
+                <SizeBasedTriggeringPolicy size="100MB"/>
             </Policies>
 
             <DefaultRolloverStrategy min="1" max="100">

constants.properties

@@ -6,6 +6,7 @@ platformVersion=4
 guavaVersion=25.1-jre
 proguardVersion=6.0.3
 bouncycastleVersion=1.60
+disruptorVersion=3.4.2
 typesafeConfigVersion=1.3.1
 jsr305Version=3.0.2
 artifactoryPluginVersion=4.7.3

docs/source/node-administration.rst

@@ -13,6 +13,12 @@ It may be the case that you require to amend the log level of a particular subse
 closer look at hibernate activity). So, for more bespoke logging configuration, the logger settings can be completely overridden
 with a `Log4j 2 <https://logging.apache.org/log4j/2.x>`_ configuration file assigned to the ``log4j.configurationFile`` system property.
 
+The node is using log4j asynchronous logging by default (configured via log4j2 properties file in its resources)
+to ensure that log message flushing is not slowing down the actual processing.
+If you need to switch to synchronous logging (e.g. for debugging/testing purposes), you can override this behaviour
+by adding ``-DLog4jContextSelector=org.apache.logging.log4j.core.selector.ClassLoaderContextSelector`` to the node's
+command line or to the ``jvmArgs`` section of the node configuration (see :doc:`corda-configuration-file`).
+
 Example
 +++++++
 

node/build.gradle

@@ -91,6 +91,9 @@ dependencies {
     // For caches rather than guava
     compile "com.github.ben-manes.caffeine:caffeine:$caffeine_version"
 
+    // For async logging
+    compile "com.lmax:disruptor:$disruptor_version"
+
     // JOpt: for command line flags.
     compile "net.sf.jopt-simple:jopt-simple:$jopt_simple_version"
 

node/src/main/kotlin/net/corda/node/utilities/logging/AsyncLoggerContextSelectorNoThreadLocal.kt

@@ -0,0 +1,43 @@
+package net.corda.node.utilities.logging
+
+import net.corda.nodeapi.internal.addShutdownHook
+import org.apache.logging.log4j.LogManager
+import org.apache.logging.log4j.core.LoggerContext
+import org.apache.logging.log4j.core.async.AsyncLoggerContext
+import org.apache.logging.log4j.core.selector.ClassLoaderContextSelector
+import org.apache.logging.log4j.core.util.Constants
+import org.apache.logging.log4j.util.PropertiesUtil
+import java.net.URI
+
+class AsyncLoggerContextSelectorNoThreadLocal : ClassLoaderContextSelector() {
+    companion object {
+        /**
+         * Returns `true` if the user specified this selector as the Log4jContextSelector, to make all loggers
+         * asynchronous.
+         *
+         * @return `true` if all loggers are asynchronous, `false` otherwise.
+         */
+        @JvmStatic
+        fun isSelected(): Boolean {
+            return AsyncLoggerContextSelectorNoThreadLocal::class.java.name == PropertiesUtil.getProperties().getStringProperty(Constants.LOG4J_CONTEXT_SELECTOR)
+        }
+    }
+
+    init {
+        // if we use async log4j logging, we need to shut down the logging to flush the loggers on exit
+        addShutdownHook { LogManager.shutdown() }
+    }
+
+    override fun createContext(name: String?, configLocation: URI?): LoggerContext {
+        return AsyncLoggerContext(name, null, configLocation).also { it.setUseThreadLocals(false) }
+    }
+
+    override fun toContextMapKey(loader: ClassLoader?): String {
+        // LOG4J2-666 ensure unique name across separate instances created by webapp classloaders
+        return "AsyncContextNoThreadLocal@" + Integer.toHexString(System.identityHashCode(loader))
+    }
+
+    override fun defaultContextName(): String {
+        return "DefaultAsyncContextNoThreadLocal@" + Thread.currentThread().name
+    }
+}

node/src/main/resources/log4j2.component.properties

@@ -0,0 +1,2 @@
+Log4jContextSelector=net.corda.node.utilities.logging.AsyncLoggerContextSelectorNoThreadLocal
+AsyncLogger.RingBufferSize=262144