Improving Acceptance Test logging (#399)

Signed-off-by: Horacio Mijail Anton Quiles <hmijail@gmail.com>

acceptance-tests/dsl/src/main/java/org/hyperledger/besu/tests/acceptance/dsl/AcceptanceTestBase.java

@@ -41,9 +41,23 @@ import org.hyperledger.besu.tests.acceptance.dsl.transaction.perm.PermissioningT
 import org.hyperledger.besu.tests.acceptance.dsl.transaction.privacy.PrivacyTransactions;
 import org.hyperledger.besu.tests.acceptance.dsl.transaction.web3.Web3Transactions;
 
+import java.io.File;
+
+import org.apache.logging.log4j.LogManager;
+import org.apache.logging.log4j.Logger;
+import org.apache.logging.log4j.ThreadContext;
 import org.junit.After;
+import org.junit.Rule;
+import org.junit.rules.TestName;
+import org.junit.rules.TestWatcher;
+import org.junit.runner.Description;
 
 public class AcceptanceTestBase {
+  static {
+    System.setProperty("log4j2.isThreadContextMapInheritable", "true");
+  }
+
+  private static final Logger LOG = LogManager.getLogger();
 
   protected final Accounts accounts;
   protected final AccountTransactions accountTransactions;
@@ -98,6 +112,50 @@ public class AcceptanceTestBase {
     permissionedNodeBuilder = new PermissionedNodeBuilder();
   }
 
+  @Rule public final TestName name = new TestName();
+
+  @Rule
+  public TestWatcher log_eraser =
+      new TestWatcher() {
+
+        @Override
+        protected void starting(final Description description) {
+          ThreadContext.put("test", description.getMethodName());
+          ThreadContext.put("class", description.getClassName());
+
+          final String errorMessage = "Uncaught exception in thread \"{}\"";
+          Thread.currentThread()
+              .setUncaughtExceptionHandler(
+                  (thread, error) -> LOG.error(errorMessage, thread.getName(), error));
+          Thread.setDefaultUncaughtExceptionHandler(
+              (thread, error) -> LOG.error(errorMessage, thread.getName(), error));
+        }
+
+        @Override
+        protected void failed(final Throwable e, final Description description) {
+          // add the result at the end of the log so it is self-sufficient
+          LOG.error(
+              "==========================================================================================");
+          LOG.error("Test failed. Reported Throwable at the point of failure:", e);
+        }
+
+        @Override
+        protected void succeeded(final Description description) {
+          // if so configured, delete logs of successful tests
+          if (!Boolean.getBoolean("acctests.keepLogsOfPassingTests")) {
+            String pathname =
+                "build/acceptanceTestLogs/"
+                    + description.getClassName()
+                    + "."
+                    + description.getMethodName()
+                    + ".log";
+            LOG.info("Test successful, deleting log at {}", pathname);
+            File file = new File(pathname);
+            file.delete();
+          }
+        }
+      };
+
   @After
   public void tearDownAcceptanceTestBase() {
     cluster.close();

acceptance-tests/dsl/src/main/java/org/hyperledger/besu/tests/acceptance/dsl/node/ProcessBesuNodeRunner.java

@@ -45,12 +45,14 @@ import java.util.stream.Collectors;
 
 import org.apache.logging.log4j.LogManager;
 import org.apache.logging.log4j.Logger;
+import org.apache.logging.log4j.ThreadContext;
 import org.awaitility.Awaitility;
 
 public class ProcessBesuNodeRunner implements BesuNodeRunner {
 
-  private final Logger LOG = LogManager.getLogger();
-  private final Logger PROCESS_LOG = LogManager.getLogger("org.hyperledger.besu.SubProcessLog");
+  private static final Logger LOG = LogManager.getLogger();
+  private static final Logger PROCESS_LOG =
+      LogManager.getLogger("org.hyperledger.besu.SubProcessLog");
 
   private final Map<String, Process> besuProcesses = new HashMap<>();
   private final ExecutorService outputProcessorExecutor = Executors.newCachedThreadPool();
@@ -61,6 +63,12 @@ public class ProcessBesuNodeRunner implements BesuNodeRunner {
 
   @Override
   public void startNode(final BesuNode node) {
+
+    if (ThreadContext.containsKey("node")) {
+      LOG.error("ThreadContext node is already set to {}", ThreadContext.get("node"));
+    }
+    ThreadContext.put("node", node.getName());
+
     final Path dataDir = node.homeDirectory();
 
     final List<String> params = new ArrayList<>();
@@ -264,6 +272,11 @@ public class ProcessBesuNodeRunner implements BesuNodeRunner {
     params.add("--auto-log-bloom-caching-enabled");
     params.add("false");
 
+    String level = System.getProperty("root.log.level");
+    if (level != null) {
+      params.add("--logging=" + level);
+    }
+
     LOG.info("Creating besu process with params {}", params);
     final ProcessBuilder processBuilder =
         new ProcessBuilder(params)
@@ -293,6 +306,8 @@ public class ProcessBesuNodeRunner implements BesuNodeRunner {
 
     waitForFile(dataDir, "besu.ports");
     waitForFile(dataDir, "besu.networks");
+
+    ThreadContext.remove("node");
   }
 
   private boolean isNotAliveOrphan(final String name) {
@@ -305,11 +320,16 @@ public class ProcessBesuNodeRunner implements BesuNodeRunner {
         new BufferedReader(new InputStreamReader(process.getInputStream(), UTF_8))) {
       String line = in.readLine();
       while (line != null) {
-        PROCESS_LOG.info("{}: {}", node.getName(), line);
+        // would be nice to pass up the log level of the incoming log line
+        PROCESS_LOG.info(line);
         line = in.readLine();
       }
     } catch (final IOException e) {
-      LOG.error("Failed to read output from process", e);
+      if (besuProcesses.containsKey(node.getName())) {
+        LOG.error("Failed to read output from process for node " + node.getName(), e);
+      } else {
+        LOG.debug("Stdout from process {} closed", node.getName());
+      }
     }
   }
 
@@ -338,6 +358,8 @@ public class ProcessBesuNodeRunner implements BesuNodeRunner {
     if (besuProcesses.containsKey(node.getName())) {
       final Process process = besuProcesses.get(node.getName());
       killBesuProcess(node.getName(), process);
+    } else {
+      LOG.error("There was a request to stop an uknown node: {}", node.getName());
     }
   }
 

acceptance-tests/dsl/src/main/java/org/hyperledger/besu/tests/acceptance/dsl/node/ThreadBesuNodeRunner.java

@@ -58,12 +58,13 @@ import java.util.stream.Collectors;
 import io.vertx.core.Vertx;
 import org.apache.logging.log4j.LogManager;
 import org.apache.logging.log4j.Logger;
+import org.apache.logging.log4j.ThreadContext;
 import picocli.CommandLine;
 import picocli.CommandLine.Model.CommandSpec;
 
 public class ThreadBesuNodeRunner implements BesuNodeRunner {
 
-  private final Logger LOG = LogManager.getLogger();
+  private static final Logger LOG = LogManager.getLogger();
   private final Map<String, Runner> besuRunners = new HashMap<>();
 
   private final Map<Node, BesuPluginContextImpl> besuPluginContextMap = new HashMap<>();
@@ -99,6 +100,11 @@ public class ThreadBesuNodeRunner implements BesuNodeRunner {
   @Override
   public void startNode(final BesuNode node) {
 
+    if (ThreadContext.containsKey("node")) {
+      LOG.error("ThreadContext node is already set to {}", ThreadContext.get("node"));
+    }
+    ThreadContext.put("node", node.getName());
+
     final StorageServiceImpl storageService = new StorageServiceImpl();
     final Path dataDir = node.homeDirectory();
     final BesuConfiguration commonPluginConfiguration =
@@ -194,6 +200,7 @@ public class ThreadBesuNodeRunner implements BesuNodeRunner {
     runner.start();
 
     besuRunners.put(node.getName(), runner);
+    ThreadContext.remove("node");
   }
 
   @Override

acceptance-tests/tests/build.gradle

@@ -64,9 +64,20 @@ sourceSets {
 processTestResources.dependsOn(':besu:testJar')
 
 task acceptanceTest(type: Test) {
+  inputs.property "integration.date", LocalTime.now() // so it runs at every invocation
+
   dependsOn(rootProject.installDist)
+  setSystemProperties(test.getSystemProperties())
   systemProperty 'acctests.runBesuAsProcess', 'true'
   mustRunAfter rootProject.subprojects*.test
   description = 'Runs Besu acceptance tests.'
   group = 'verification'
+
+  testLogging {
+    exceptionFormat = 'full'
+    showStackTraces = true
+    showStandardStreams = Boolean.getBoolean('acctests.showStandardStreams')
+    showExceptions = true
+    showCauses = true
+  }
 }

acceptance-tests/tests/src/test/resources/log4j2.xml

@@ -5,20 +5,51 @@
   </Properties>
   <Appenders>
     <Console name="Console" target="SYSTEM_OUT">
-      <PatternLayout pattern="%d{HH:mm:ss.SSS} | %t | %-5level | %c{1} | %msg%n" />
+      <PatternLayout pattern="%X{test} | %d{HH:mm:ss.SSS} | %t | %-5level | %c{1} | %msg%n" />
     </Console>
     <Console name="SubProcessConsole" target="SYSTEM_OUT">
-      <PatternLayout pattern="Process %msg%n" />
+      <PatternLayout pattern="%X{test} | %X{node} | %msg%n" />
     </Console>
+    <Routing name="PerTestFile">
+      <Routes pattern="${ctx:class}-${ctx:test}">
+        <Route>
+          <File
+                  name="Test-${ctx:class}-${ctx:test}"
+                  filename="build/acceptanceTestLogs/${ctx:class}.${ctx:test}.log"
+                  append="false"
+                  createOnDemand="true"
+          >
+            <PatternLayout pattern="%d{HH:mm:ss.SSS} | %t | %-5level | %c{1} | %msg%n" />
+          </File>
+        </Route>
+      </Routes>
+    </Routing>
+    <Routing name="PerTestSubprocessFile">
+      <Routes pattern="${ctx:class}-${ctx:test}">
+        <Route>
+          <File
+                  name="TestSubprocess-${ctx:class}-${ctx:test}"
+                  filename="build/acceptanceTestLogs/${ctx:class}.${ctx:test}.log"
+                  append="true"
+                  createOnDemand="true"
+          >
+            <PatternLayout pattern="%X{node} | %msg%n" />
+          </File>
+        </Route>
+      </Routes>
+    </Routing>
+
   </Appenders>
   <Loggers>
     <Logger name="org.hyperledger.besu.SubProcessLog" level="INFO" additivity="false">
       <AppenderRef ref="SubProcessConsole" />
+      <AppenderRef ref="PerTestSubprocessFile" />
     </Logger>
     <Logger name="net.consensys.orion" level="OFF" additivity="false">
     </Logger>
     <Root level="${sys:root.log.level}">
       <AppenderRef ref="Console" />
+      <AppenderRef ref="PerTestFile" />
     </Root>
   </Loggers>
 </Configuration>

besu/src/main/java/org/hyperledger/besu/Besu.java

@@ -60,15 +60,19 @@ public final class Besu {
           "vertx.logger-delegate-factory-class-name",
           "io.vertx.core.logging.Log4j2LogDelegateFactory");
     } catch (SecurityException e) {
-      // if the security
       System.out.println(
-          "could not set logging system property as the security manager prevented it.");
+          "Could not set logging system property as the security manager prevented it:"
+              + e.getMessage());
     }
 
     final Logger logger = getLogger();
     Thread.setDefaultUncaughtExceptionHandler(
         (thread, error) ->
             logger.error("Uncaught exception in thread \"" + thread.getName() + "\"", error));
+    Thread.currentThread()
+        .setUncaughtExceptionHandler(
+            (thread, error) ->
+                logger.error("Uncaught exception in thread \"" + thread.getName() + "\"", error));
     return logger;
   }
 }

build.gradle

@@ -248,7 +248,8 @@ allprojects {
       'test.ethereum.include',
       'test.ethereum.state.eip',
       'root.log.level',
-      'evm.log.level'
+      'evm.log.level',
+      'acctests.keepLogsOfPassingTests'
     ]
     for (String name : toImport) {
       if (System.getProperty(name) != null) {