ENT-3057: Log hibernate warns and errors in different log (#4889)

* ENT-3057: Log hibernate warns and errors in different log

If a hibernate error occurs (deadlock, for example) that would cause a flow to be sent to the hospital, hibernate logs the warnings and errors before we do. This results in duplication in the logs, and pollutes the log. To solve this, we create a new log appender named diagnostic-{node-name}.log and log any org.hibernate messages of warn and above to that file. This way, messages are not lost, which means that the information can be retrieved if need be.

* Corrected indentation of comment (changed tab to space)

* Updated node-administration document to mention diagnostic logging change

* Fixed integration test. It was breaking because it was fetching the first log file in the folder, assuming there would be only one. This assumption is now invalid because the diagnostic log file that was introduced. Two tests were found that used similar logic to find a log file to examine, hence both were corrected to look for log files beginning with "node"

* Updated documentation as per review comments.

config/dev/log4j2.xml

@@ -4,6 +4,7 @@
     <Properties>
         <Property name="log-path">${sys:log-path:-logs}</Property>
         <Property name="log-name">node-${hostName}</Property>
+        <Property name="diagnostic-log-name">diagnostic-${hostName}</Property>
         <Property name="archive">${log-path}/archive</Property>
         <Property name="defaultLogLevel">${sys:defaultLogLevel:-info}</Property>
         <Property name="consoleLogLevel">${sys:consoleLogLevel:-error}</Property>
@@ -105,6 +106,46 @@
 
         </RollingRandomAccessFile>
 
+        <!-- Will generate up to 100 log files for a given day. During every rollover it will delete
+             those that are older than 60 days, but keep the most recent 10 GB -->
+        <RollingRandomAccessFile name="Diagnostic-RollingFile-Appender"
+                     fileName="${log-path}/${diagnostic-log-name}.log"
+                     filePattern="${archive}/${diagnostic-log-name}.%date{yyyy-MM-dd}-%i.log.gz">
+
+            <PatternLayout>
+                <ScriptPatternSelector defaultPattern="[%-5level] %date{ISO8601}{UTC}Z [%t] %c{2}.%method - %msg%n">
+                    <Script name="MDCSelector" language="javascript"><![CDATA[
+                    result = null;
+                    if (!logEvent.getContextData().size() == 0) {
+                        result = "WithMDC";
+                    } else {
+                        result = null;
+                    }
+                    result;
+               ]]>
+                    </Script>
+                    <PatternMatch key="WithMDC" pattern="[%-5level] %date{ISO8601}{UTC}Z [%t] %c{2}.%method - %msg %X%n"/>
+                </ScriptPatternSelector>
+            </PatternLayout>
+
+            <Policies>
+                <TimeBasedTriggeringPolicy/>
+                <SizeBasedTriggeringPolicy size="100MB"/>
+            </Policies>
+
+            <DefaultRolloverStrategy min="1" max="100">
+                <Delete basePath="${archive}" maxDepth="1">
+                    <IfFileName glob="${log-name}*.log.gz"/>
+                    <IfLastModified age="60d">
+                        <IfAny>
+                            <IfAccumulatedFileSize exceeds="10 GB"/>
+                        </IfAny>
+                    </IfLastModified>
+                </Delete>
+            </DefaultRolloverStrategy>
+
+        </RollingRandomAccessFile>
+
         <Rewrite name="Console-ErrorCode-Selector">
             <AppenderRef ref="Console-Selector"/>
             <ErrorCodeRewritePolicy/>
@@ -119,6 +160,10 @@
             <AppenderRef ref="RollingFile-Appender"/>
             <ErrorCodeRewritePolicy/>
         </Rewrite>
+        <Rewrite name="Diagnostic-RollingFile-ErrorCode-Appender">
+            <AppenderRef ref="Diagnostic-RollingFile-Appender"/>
+            <ErrorCodeRewritePolicy/>
+        </Rewrite>
     </Appenders>
 
     <Loggers>
@@ -130,6 +175,9 @@
             <AppenderRef ref="Console-ErrorCode-Appender-Println"/>
             <AppenderRef ref="RollingFile-ErrorCode-Appender"/>
         </Logger>
+        <Logger name="org.hibernate" level="warn" additivity="false">
+            <AppenderRef ref="Diagnostic-RollingFile-ErrorCode-Appender"/>
+        </Logger>
         <Logger name="org.hibernate.SQL" level="info" additivity="false">
             <AppenderRef ref="Console-ErrorCode-Selector"/>
             <AppenderRef ref="RollingFile-ErrorCode-Appender"/>

docs/source/node-administration.rst

@@ -10,7 +10,10 @@ Logging
 By default the node log files are stored to the ``logs`` subdirectory of the working directory and are rotated from time
 to time. You can have logging printed to the console as well by passing the ``--log-to-console`` command line flag.
 The default logging level is ``INFO`` which can be adjusted by the ``--logging-level`` command line argument. This configuration
-option will affect all modules.
+option will affect all modules. Hibernate (the JPA provider used by Corda) specific log messages of level ``WARN`` and above 
+will be logged to the diagnostic log file, which is stored in the same location as other log files (``logs`` subdirectory 
+by default). This is because Hibernate may log messages at WARN and ERROR that are handled internally by Corda and do not 
+need operator attention. If they do, they will be logged by Corda itself in the main node log file.
 
 It may be the case that you require to amend the log level of a particular subset of modules (e.g., if you'd like to take a
 closer look at hibernate activity). So, for more bespoke logging configuration, the logger settings can be completely overridden

node/src/integration-test/kotlin/net/corda/node/BootTests.kt

@@ -6,6 +6,7 @@ import net.corda.core.CordaRuntimeException
 import net.corda.core.flows.FlowLogic
 import net.corda.core.flows.StartableByRPC
 import net.corda.core.internal.div
+import net.corda.core.internal.isRegularFile
 import net.corda.core.internal.list
 import net.corda.core.internal.readLines
 import net.corda.core.messaging.startFlow
@@ -53,7 +54,7 @@ class BootTests {
         driver(DriverParameters(notarySpecs = emptyList())) {
             val alice = startNode(providedName = ALICE_NAME).get()
             val logFolder = alice.baseDirectory / NodeStartup.LOGS_DIRECTORY_NAME
-            val logFile = logFolder.list { it.filter { it.fileName.toString().endsWith(".log") }.findAny().get() }
+            val logFile = logFolder.list { it.filter { a -> a.isRegularFile() && a.fileName.toString().startsWith("node") }.findFirst().get() }
             // Start second Alice, should fail
             assertThatThrownBy {
                 startNode(providedName = ALICE_NAME).getOrThrow()

testing/node-driver/src/integration-test/kotlin/net/corda/testing/driver/DriverTests.kt

@@ -92,7 +92,7 @@ class DriverTests {
                 systemProperties = mapOf("log4j.configurationFile" to logConfigFile.toString())
         )) {
             val baseDirectory = startNode(providedName = DUMMY_BANK_A_NAME).getOrThrow().baseDirectory
-            val logFile = (baseDirectory / NodeStartup.LOGS_DIRECTORY_NAME).list { it.sorted().findFirst().get() }
+            val logFile = (baseDirectory / NodeStartup.LOGS_DIRECTORY_NAME).list { it.filter { a -> a.isRegularFile() && a.fileName.toString().startsWith("node") }.findFirst().get() }
             val debugLinesPresent = logFile.readLines { lines -> lines.anyMatch { line -> line.startsWith("[DEBUG]") } }
             assertThat(debugLinesPresent).isTrue()
         }