diff --git a/acceptance-tests/dsl/src/main/java/org/hyperledger/besu/tests/acceptance/dsl/AcceptanceTestBase.java b/acceptance-tests/dsl/src/main/java/org/hyperledger/besu/tests/acceptance/dsl/AcceptanceTestBase.java index e11349023c..be0f7bb5a9 100644 --- a/acceptance-tests/dsl/src/main/java/org/hyperledger/besu/tests/acceptance/dsl/AcceptanceTestBase.java +++ b/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(); diff --git a/acceptance-tests/dsl/src/main/java/org/hyperledger/besu/tests/acceptance/dsl/node/ProcessBesuNodeRunner.java b/acceptance-tests/dsl/src/main/java/org/hyperledger/besu/tests/acceptance/dsl/node/ProcessBesuNodeRunner.java index 94deea393f..f0d065707c 100644 --- a/acceptance-tests/dsl/src/main/java/org/hyperledger/besu/tests/acceptance/dsl/node/ProcessBesuNodeRunner.java +++ b/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 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 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()); } } diff --git a/acceptance-tests/dsl/src/main/java/org/hyperledger/besu/tests/acceptance/dsl/node/ThreadBesuNodeRunner.java b/acceptance-tests/dsl/src/main/java/org/hyperledger/besu/tests/acceptance/dsl/node/ThreadBesuNodeRunner.java index b1445580a8..d3c8574946 100644 --- a/acceptance-tests/dsl/src/main/java/org/hyperledger/besu/tests/acceptance/dsl/node/ThreadBesuNodeRunner.java +++ b/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 besuRunners = new HashMap<>(); private final Map 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 diff --git a/acceptance-tests/tests/build.gradle b/acceptance-tests/tests/build.gradle index da628f0091..8b7dcd1eb7 100644 --- a/acceptance-tests/tests/build.gradle +++ b/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 + } } diff --git a/acceptance-tests/tests/src/test/resources/log4j2.xml b/acceptance-tests/tests/src/test/resources/log4j2.xml index 3ae674bfec..2a1d718dfb 100644 --- a/acceptance-tests/tests/src/test/resources/log4j2.xml +++ b/acceptance-tests/tests/src/test/resources/log4j2.xml @@ -5,20 +5,51 @@ - + - + + + + + + + + + + + + + + + + + + + + + + diff --git a/besu/src/main/java/org/hyperledger/besu/Besu.java b/besu/src/main/java/org/hyperledger/besu/Besu.java index e04a0ee2c2..24383ac490 100644 --- a/besu/src/main/java/org/hyperledger/besu/Besu.java +++ b/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; } } diff --git a/build.gradle b/build.gradle index ec056cb081..b7e513999f 100644 --- a/build.gradle +++ b/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) {