Reduce Spurious Log Messages (#1678)

Adding the Log4j "jul" (java.util.logging) adapter resulted in many
messages like this at startup:
`main INFO Registered Log4j as the java.util.logging.LogManager.`
These come from the Log4j status logger.  We can get rid of those by
setting the status attribute on all configurations to a higher logging
level.  WARN is the next higher level.

Signed-off-by: Danno Ferrin <danno.ferrin@gmail.com>

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

@@ -53,4 +53,17 @@ default void waitForFile(final Path dataDir, final String fileName) {
               }
             });
   }
+
+  /**
+   * Starts a capture of System.out and System.err. Once getConsole is called the capture will end.
+   */
+  void startConsoleCapture();
+
+  /**
+   * If no capture was started an empty string is returned. After the call the original System.err
+   * and out are restored.
+   *
+   * @return The console output since startConsoleCapture() was called.
+   */
+  String getConsoleContents();
 }

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

@@ -26,9 +26,11 @@
 import org.hyperledger.besu.tests.acceptance.dsl.StaticNodesUtils;
 
 import java.io.BufferedReader;
+import java.io.ByteArrayOutputStream;
 import java.io.File;
 import java.io.IOException;
 import java.io.InputStreamReader;
+import java.io.PrintStream;
 import java.lang.ProcessBuilder.Redirect;
 import java.net.URI;
 import java.nio.file.Files;
@@ -57,6 +59,9 @@ public class ProcessBesuNodeRunner implements BesuNodeRunner {
 
   private final Map<String, Process> besuProcesses = new HashMap<>();
   private final ExecutorService outputProcessorExecutor = Executors.newCachedThreadPool();
+  private boolean capturingConsole;
+  private final ByteArrayOutputStream consoleContents = new ByteArrayOutputStream();
+  private final PrintStream consoleOut = new PrintStream(consoleContents);
 
   ProcessBesuNodeRunner() {
     Runtime.getRuntime().addShutdownHook(new Thread(this::shutdown));
@@ -350,6 +355,9 @@ private void printOutput(final BesuNode node, final Process process) {
       while (line != null) {
         // would be nice to pass up the log level of the incoming log line
         PROCESS_LOG.info(line);
+        if (capturingConsole) {
+          consoleOut.println(line);
+        }
         line = in.readLine();
       }
     } catch (final IOException e) {
@@ -441,4 +449,16 @@ private void killBesuProcess(final String name) {
       LOG.info("Process exited with code {}", process.exitValue());
     }
   }
+
+  @Override
+  public void startConsoleCapture() {
+    consoleContents.reset();
+    capturingConsole = true;
+  }
+
+  @Override
+  public String getConsoleContents() {
+    capturingConsole = false;
+    return consoleContents.toString(UTF_8);
+  }
 }

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

@@ -49,7 +49,12 @@
 import org.hyperledger.besu.services.SecurityModuleServiceImpl;
 import org.hyperledger.besu.services.StorageServiceImpl;
 
+import java.io.ByteArrayOutputStream;
 import java.io.File;
+import java.io.IOException;
+import java.io.OutputStream;
+import java.io.PrintStream;
+import java.nio.charset.StandardCharsets;
 import java.nio.file.Path;
 import java.time.Clock;
 import java.util.HashMap;
@@ -58,6 +63,7 @@
 import java.util.Map;
 import java.util.concurrent.ConcurrentHashMap;
 import java.util.stream.Collectors;
+import javax.annotation.Nonnull;
 
 import io.vertx.core.Vertx;
 import org.apache.logging.log4j.LogManager;
@@ -72,6 +78,9 @@ public class ThreadBesuNodeRunner implements BesuNodeRunner {
   private final Map<String, Runner> besuRunners = new HashMap<>();
 
   private final Map<Node, BesuPluginContextImpl> besuPluginContextMap = new ConcurrentHashMap<>();
+  private final PrintStream originalOut = System.out;
+  private final PrintStream originalErr = System.err;
+  private final ByteArrayOutputStream consoleContents = new ByteArrayOutputStream();
 
   private BesuPluginContextImpl buildPluginContext(
       final BesuNode node,
@@ -207,6 +216,7 @@ public void startNode(final BesuNode node) {
             .storageProvider(storageProvider)
             .build();
 
+    System.setOut(null);
     runner.start();
 
     besuRunners.put(node.getName(), runner);
@@ -252,4 +262,45 @@ private void killRunner(final String name) {
       LOG.error("There was a request to kill an unknown node: {}", name);
     }
   }
+
+  static class SplittingStream extends OutputStream {
+    final OutputStream one;
+    final OutputStream two;
+
+    SplittingStream(final OutputStream one, final OutputStream two) {
+      this.one = one;
+      this.two = two;
+    }
+
+    @Override
+    public void write(final int b) throws IOException {
+      one.write(b);
+      two.write(b);
+    }
+
+    @Override
+    public void write(@Nonnull final byte[] b) throws IOException {
+      one.write(b);
+      two.write(b);
+    }
+
+    @Override
+    public void write(@Nonnull final byte[] b, final int off, final int len) throws IOException {
+      one.write(b, off, len);
+      two.write(b, off, len);
+    }
+  }
+
+  @Override
+  public void startConsoleCapture() {
+    System.setOut(new PrintStream(new SplittingStream(consoleContents, originalOut)));
+    System.setErr(new PrintStream(new SplittingStream(consoleContents, originalErr)));
+  }
+
+  @Override
+  public String getConsoleContents() {
+    System.setOut(originalOut);
+    System.setErr(originalErr);
+    return consoleContents.toString(StandardCharsets.UTF_8);
+  }
 }

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

@@ -195,4 +195,21 @@ public void verifyOnActiveNodes(final Condition condition) {
         .filter(node -> besuNodeRunner.isActive(node.getName()))
         .forEach(condition::verify);
   }
+
+  /**
+   * Starts a capture of System.out and System.err. Once getConsole is called the capture will end.
+   */
+  public void startConsoleCapture() {
+    besuNodeRunner.startConsoleCapture();
+  }
+
+  /**
+   * If no capture was started an empty string is returned. After the call the original System.err
+   * and out are restored.
+   *
+   * @return The console output since startConsoleCapture() was called.
+   */
+  public String getConsoleContents() {
+    return besuNodeRunner.getConsoleContents();
+  }
 }

acceptance-tests/tests/src/test/java/org/hyperledger/besu/tests/acceptance/RunHelpTest.java

@@ -14,6 +14,8 @@
  */
 package org.hyperledger.besu.tests.acceptance;
 
+import static org.assertj.core.api.Assertions.assertThat;
+
 import org.hyperledger.besu.tests.acceptance.dsl.AcceptanceTestBase;
 import org.hyperledger.besu.tests.acceptance.dsl.WaitUtils;
 import org.hyperledger.besu.tests.acceptance.dsl.node.BesuNode;
@@ -27,7 +29,15 @@ public class RunHelpTest extends AcceptanceTestBase {
   @Test
   public void testShowsHelpAndExits() throws IOException {
     final BesuNode node = besu.runCommand("--help");
+    cluster.startConsoleCapture();
     cluster.runNodeStart(node);
     WaitUtils.waitFor(5000, () -> node.verify(exitedSuccessfully));
+
+    // assert that no random startup or ending logging appears.
+    // if the help text changes then updates are appropriate.
+    final String consoleContents = cluster.getConsoleContents();
+    assertThat(consoleContents)
+        .startsWith("Usage:\n\nbesu [OPTIONS] [COMMAND]\n\nDescription:\n\n");
+    assertThat(consoleContents).endsWith("\nBesu is licensed under the Apache License 2.0\n");
   }
 }

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

@@ -1,5 +1,5 @@
 <?xml version="1.0" encoding="UTF-8"?>
-<Configuration status="INFO" monitorInterval="30">
+<Configuration status="WARN" monitorInterval="30">
   <Properties>
     <Property name="root.log.level">INFO</Property>
   </Properties>

besu/src/main/resources/log4j2.xml

@@ -1,5 +1,5 @@
 <?xml version="1.0" encoding="UTF-8"?>
-<Configuration status="INFO">
+<Configuration status="WARN">
     <Properties>
         <Property name="root.log.level">${env:LOG_LEVEL:-INFO}</Property>
         <Property name="root.log.logger">${env:LOGGER:-Console}</Property>
@@ -38,6 +38,7 @@
         </Routing>
     </Appenders>
     <Loggers>
+        <Logger name="org.apache.logging.log4j.status.StatusLogger" level="OFF"/>
         <Root level="${sys:root.log.level}">
             <AppenderRef ref="Router" />
         </Root>

besu/src/test/resources/log4j2.xml

@@ -1,5 +1,5 @@
 <?xml version="1.0" encoding="UTF-8"?>
-<Configuration status="INFO" monitorInterval="30">
+<Configuration status="WARN" monitorInterval="30">
     <Properties>
         <Property name="root.log.level">INFO</Property>
     </Properties>

crypto/src/test/resources/log4j2.xml

@@ -1,5 +1,5 @@
 <?xml version="1.0" encoding="UTF-8"?>
-<Configuration status="INFO" monitorInterval="30">
+<Configuration status="WARN" monitorInterval="30">
     <Properties>
         <Property name="root.log.level">INFO</Property>
     </Properties>

ethereum/core/src/test/resources/log4j2.xml

@@ -1,5 +1,5 @@
 <?xml version="1.0" encoding="UTF-8"?>
-<Configuration status="INFO" monitorInterval="30">
+<Configuration status="WARN" monitorInterval="30">
     <Properties>
         <Property name="root.log.level">INFO</Property>
     </Properties>

ethereum/eth/src/test/resources/log4j2.xml

@@ -1,5 +1,5 @@
 <?xml version="1.0" encoding="UTF-8"?>
-<Configuration status="INFO">
+<Configuration status="WARN">
   <Properties>
     <Property name="root.log.level">INFO</Property>
   </Properties>

ethereum/evmtool/src/main/resources/log4j2.xml

@@ -1,5 +1,5 @@
 <?xml version="1.0" encoding="UTF-8"?>
-<Configuration status="INFO">
+<Configuration status="WARN">
     <Properties>
         <Property name="root.log.level">INFO</Property>
     </Properties>

ethereum/p2p/src/test/resources/log4j2.xml

@@ -1,5 +1,5 @@
 <?xml version="1.0" encoding="UTF-8"?>
-<Configuration status="INFO" monitorInterval="30">
+<Configuration status="WARN" monitorInterval="30">
     <Properties>
         <Property name="root.log.level">INFO</Property>
     </Properties>

services/kvstore/src/main/resources/log4j2.xml

@@ -1,5 +1,5 @@
 <?xml version="1.0" encoding="UTF-8"?>
-<Configuration status="INFO" monitorInterval="30">
+<Configuration status="WARN" monitorInterval="30">
   <Properties>
     <Property name="root.log.level">INFO</Property>
   </Properties>

services/pipeline/src/test/resources/log4j2.xml

@@ -1,5 +1,5 @@
 <?xml version="1.0" encoding="UTF-8"?>
-<Configuration status="INFO">
+<Configuration status="WARN">
     <Properties>
         <Property name="root.log.level">INFO</Property>
     </Properties>

services/tasks/src/main/resources/log4j2.xml

@@ -1,5 +1,5 @@
 <?xml version="1.0" encoding="UTF-8"?>
-<Configuration status="INFO" monitorInterval="30">
+<Configuration status="WARN" monitorInterval="30">
   <Properties>
     <Property name="root.log.level">INFO</Property>
   </Properties>

testutil/src/main/resources/log4j2.xml

@@ -1,5 +1,5 @@
 <?xml version="1.0" encoding="UTF-8"?>
-<Configuration status="INFO">
+<Configuration status="WARN">
   <Properties>
     <Property name="root.log.level">INFO</Property>
   </Properties>