diff --git a/acceptance-tests/src/test/java/tech/pegasys/pantheon/tests/acceptance/dsl/node/ProcessPantheonNodeRunner.java b/acceptance-tests/src/test/java/tech/pegasys/pantheon/tests/acceptance/dsl/node/ProcessPantheonNodeRunner.java index 21e04f8ead..5021d8e85f 100644 --- a/acceptance-tests/src/test/java/tech/pegasys/pantheon/tests/acceptance/dsl/node/ProcessPantheonNodeRunner.java +++ b/acceptance-tests/src/test/java/tech/pegasys/pantheon/tests/acceptance/dsl/node/ProcessPantheonNodeRunner.java @@ -18,8 +18,11 @@ import tech.pegasys.pantheon.ethereum.jsonrpc.RpcApi; import tech.pegasys.pantheon.ethereum.jsonrpc.RpcApis; +import java.io.BufferedReader; import java.io.File; import java.io.IOException; +import java.io.InputStreamReader; +import java.lang.ProcessBuilder.Redirect; import java.net.URI; import java.nio.file.Files; import java.nio.file.Path; @@ -28,6 +31,8 @@ import java.util.HashMap; import java.util.List; import java.util.Map; +import java.util.concurrent.ExecutorService; +import java.util.concurrent.Executors; import java.util.concurrent.TimeUnit; import java.util.stream.Collectors; @@ -38,8 +43,10 @@ public class ProcessPantheonNodeRunner implements PantheonNodeRunner { private final Logger LOG = LogManager.getLogger(); + private final Logger PROCESS_LOG = LogManager.getLogger("tech.pegasys.pantheon.SubProcessLog"); private final Map pantheonProcesses = new HashMap<>(); + private final ExecutorService outputProcessorExecutor = Executors.newCachedThreadPool(); ProcessPantheonNodeRunner() { Runtime.getRuntime().addShutdownHook(new Thread(this::shutdown)); @@ -157,10 +164,12 @@ public void startNode(final PantheonNode node) { final ProcessBuilder processBuilder = new ProcessBuilder(params) .directory(new File(System.getProperty("user.dir")).getParentFile()) - .inheritIO(); + .redirectErrorStream(true) + .redirectInput(Redirect.INHERIT); try { final Process process = processBuilder.start(); + outputProcessorExecutor.submit(() -> printOutput(node, process)); pantheonProcesses.put(node.getName(), process); } catch (final IOException e) { LOG.error("Error starting PantheonNode process", e); @@ -169,6 +178,19 @@ public void startNode(final PantheonNode node) { waitForPortsFile(dataDir); } + private void printOutput(final PantheonNode node, final Process process) { + try (final BufferedReader in = + new BufferedReader(new InputStreamReader(process.getInputStream(), UTF_8))) { + String line = in.readLine(); + while (line != null) { + PROCESS_LOG.info("{}: {}", node.getName(), line); + line = in.readLine(); + } + } catch (final IOException e) { + LOG.error("Failed to read output from process", e); + } + } + private Path createGenesisFile(final PantheonNode node, final EthNetworkConfig ethNetworkConfig) { try { final Path genesisFile = Files.createTempFile(node.homeDirectory(), "genesis", ""); @@ -197,6 +219,15 @@ public void stopNode(final PantheonNode node) { public synchronized void shutdown() { final HashMap localMap = new HashMap<>(pantheonProcesses); localMap.forEach(this::killPantheonProcess); + outputProcessorExecutor.shutdown(); + try { + if (!outputProcessorExecutor.awaitTermination(5, TimeUnit.SECONDS)) { + LOG.error("Output processor executor did not shutdown cleanly."); + } + } catch (final InterruptedException e) { + LOG.error("Interrupted while already shutting down", e); + Thread.currentThread().interrupt(); + } } @Override diff --git a/acceptance-tests/src/test/resources/log4j2.xml b/acceptance-tests/src/test/resources/log4j2.xml index d357f53d89..cee8a4c7e6 100644 --- a/acceptance-tests/src/test/resources/log4j2.xml +++ b/acceptance-tests/src/test/resources/log4j2.xml @@ -7,8 +7,14 @@ + + + + + + diff --git a/ethereum/p2p/src/main/java/tech/pegasys/pantheon/ethereum/p2p/discovery/PeerDiscoveryAgent.java b/ethereum/p2p/src/main/java/tech/pegasys/pantheon/ethereum/p2p/discovery/PeerDiscoveryAgent.java index cb4b565501..4e04aa061f 100644 --- a/ethereum/p2p/src/main/java/tech/pegasys/pantheon/ethereum/p2p/discovery/PeerDiscoveryAgent.java +++ b/ethereum/p2p/src/main/java/tech/pegasys/pantheon/ethereum/p2p/discovery/PeerDiscoveryAgent.java @@ -201,13 +201,6 @@ protected void handleIncomingPacket(final Endpoint sourceEndpoint, final Packet * @param packet the packet to send */ protected void handleOutgoingPacket(final DiscoveryPeer peer, final Packet packet) { - LOG.trace( - ">>> Sending {} discovery packet to {} ({}): {}", - packet.getType(), - peer.getEndpoint(), - peer.getId().slice(0, 16), - packet); - sendOutgoingPacket(peer, packet) .whenComplete( (res, err) -> { diff --git a/ethereum/p2p/src/main/java/tech/pegasys/pantheon/ethereum/p2p/discovery/internal/DiscoveryProtocolLogger.java b/ethereum/p2p/src/main/java/tech/pegasys/pantheon/ethereum/p2p/discovery/internal/DiscoveryProtocolLogger.java index 0a57c6bda9..496bccfa18 100644 --- a/ethereum/p2p/src/main/java/tech/pegasys/pantheon/ethereum/p2p/discovery/internal/DiscoveryProtocolLogger.java +++ b/ethereum/p2p/src/main/java/tech/pegasys/pantheon/ethereum/p2p/discovery/internal/DiscoveryProtocolLogger.java @@ -23,7 +23,7 @@ public class DiscoveryProtocolLogger { static void logSendingPacket(final Peer peer, final Packet packet) { LOG.trace( - "<<< Sending {} packet from peer {} ({}): {}", + "<<< Sending {} packet to peer {} ({}): {}", shortenPacketType(packet), peer.getId().slice(0, 16), peer.getEndpoint(),