From 47ab2bda72b67afa2695def007c309e135bf06e7 Mon Sep 17 00:00:00 2001 From: Alpar Torok Date: Thu, 11 Jul 2019 14:59:05 +0300 Subject: [PATCH] Improve how log is tailed in testclusters on failure (#40600) * Improoce how log is tailed in testclusters on failure - only print last few lines - print all errors and warnings - compact repeating errors and warnings --- .../testclusters/ElasticsearchNode.java | 81 +++++++++++++++++-- .../testclusters/TestClustersPluginIT.java | 6 +- .../src/testKit/testclusters/build.gradle | 8 +- 3 files changed, 83 insertions(+), 12 deletions(-) diff --git a/buildSrc/src/main/java/org/elasticsearch/gradle/testclusters/ElasticsearchNode.java b/buildSrc/src/main/java/org/elasticsearch/gradle/testclusters/ElasticsearchNode.java index 025cee2ffaf..1a887b45af8 100644 --- a/buildSrc/src/main/java/org/elasticsearch/gradle/testclusters/ElasticsearchNode.java +++ b/buildSrc/src/main/java/org/elasticsearch/gradle/testclusters/ElasticsearchNode.java @@ -46,6 +46,8 @@ import java.io.ByteArrayInputStream; import java.io.File; import java.io.IOException; import java.io.InputStream; +import java.io.LineNumberReader; + import java.io.UncheckedIOException; import java.net.URI; import java.nio.charset.StandardCharsets; @@ -61,6 +63,7 @@ import java.util.Comparator; import java.util.HashMap; import java.util.HashSet; import java.util.LinkedHashMap; +import java.util.LinkedList; import java.util.List; import java.util.Map; import java.util.Objects; @@ -82,6 +85,7 @@ public class ElasticsearchNode implements TestClusterConfiguration { private static final Logger LOGGER = Logging.getLogger(ElasticsearchNode.class); private static final int ES_DESTROY_TIMEOUT = 20; private static final TimeUnit ES_DESTROY_TIMEOUT_UNIT = TimeUnit.SECONDS; + private static final int NODE_UP_TIMEOUT = 2; private static final TimeUnit NODE_UP_TIMEOUT_UNIT = TimeUnit.MINUTES; private static final int ADDITIONAL_CONFIG_TIMEOUT = 15; @@ -89,6 +93,14 @@ public class ElasticsearchNode implements TestClusterConfiguration { private static final List OVERRIDABLE_SETTINGS = Arrays.asList( "path.repo", "discovery.seed_providers" + + ); + + private static final int TAIL_LOG_MESSAGES_COUNT = 40; + private static final List MESSAGES_WE_DONT_CARE_ABOUT = Arrays.asList( + "Option UseConcMarkSweepGC was deprecated", + "is a pre-release version of Elasticsearch", + "max virtual memory areas vm.max_map_count" ); private final String path; @@ -693,14 +705,73 @@ public class ElasticsearchNode implements TestClusterConfiguration { } private void logFileContents(String description, Path from) { - LOGGER.error("{} `{}`", description, this); - try (Stream lines = Files.lines(from, StandardCharsets.UTF_8)) { - lines - .map(line -> " " + line) - .forEach(LOGGER::error); + final Map errorsAndWarnings = new LinkedHashMap<>(); + LinkedList ring = new LinkedList<>(); + try (LineNumberReader reader = new LineNumberReader(Files.newBufferedReader(from))) { + for (String line = reader.readLine(); line != null ; line = reader.readLine()) { + final String lineToAdd; + if (ring.isEmpty()) { + lineToAdd = line; + } else { + if (line.startsWith("[")) { + lineToAdd = line; + // check to see if the previous message (possibly combined from multiple lines) was an error or + // warning as we want to show all of them + String previousMessage = normalizeLogLine(ring.getLast()); + if (MESSAGES_WE_DONT_CARE_ABOUT.stream().noneMatch(previousMessage::contains) && + (previousMessage.contains("ERROR") || previousMessage.contains("WARN"))) { + errorsAndWarnings.put( + previousMessage, + errorsAndWarnings.getOrDefault(previousMessage, 0) + 1 + ); + } + } else { + // We combine multi line log messages to make sure we never break exceptions apart + lineToAdd = ring.removeLast() + "\n" + line; + } + } + ring.add(lineToAdd); + if (ring.size() >= TAIL_LOG_MESSAGES_COUNT) { + ring.removeFirst(); + } + } } catch (IOException e) { throw new UncheckedIOException("Failed to tail log " + this, e); } + + if (errorsAndWarnings.isEmpty() == false || ring.isEmpty() == false) { + LOGGER.error("\n=== {} `{}` ===", description, this); + } + if (errorsAndWarnings.isEmpty() == false) { + LOGGER.lifecycle("\n» ↓ errors and warnings from " + from + " ↓"); + errorsAndWarnings.forEach((message, count) -> { + LOGGER.lifecycle("» " + message.replace("\n", "\n» ")); + if (count > 1) { + LOGGER.lifecycle("» ↑ repeated " + count + " times ↑"); + } + }); + } + + ring.removeIf(line -> MESSAGES_WE_DONT_CARE_ABOUT.stream().anyMatch(line::contains)); + + if (ring.isEmpty() == false) { + LOGGER.lifecycle("» ↓ last " + TAIL_LOG_MESSAGES_COUNT + " non error or warning messages from " + from + " ↓"); + ring.forEach(message -> { + if (errorsAndWarnings.containsKey(normalizeLogLine(message)) == false) { + LOGGER.lifecycle("» " + message.replace("\n", "\n» ")); + } + }); + } + } + + private String normalizeLogLine(String line) { + if (line.contains("ERROR")) { + return line.substring(line.indexOf("ERROR")); + } + if (line.contains("WARN")) { + return line.substring(line.indexOf("WARN")); + } + return line; } private void waitForProcessToExit(ProcessHandle processHandle) { diff --git a/buildSrc/src/test/java/org/elasticsearch/gradle/testclusters/TestClustersPluginIT.java b/buildSrc/src/test/java/org/elasticsearch/gradle/testclusters/TestClustersPluginIT.java index a59f54e1320..6859d9ee858 100644 --- a/buildSrc/src/test/java/org/elasticsearch/gradle/testclusters/TestClustersPluginIT.java +++ b/buildSrc/src/test/java/org/elasticsearch/gradle/testclusters/TestClustersPluginIT.java @@ -68,9 +68,9 @@ public class TestClustersPluginIT extends GradleIntegrationTestCase { public void testUseClusterByUpToDateTask() { // Run it once, ignoring the result and again to make sure it's considered up to date. // Gradle randomly considers tasks without inputs and outputs as as up-to-date or success on the first run - getTestClustersRunner(":upToDate1", ":upToDate2").build(); - BuildResult result = getTestClustersRunner(":upToDate1", ":upToDate2").build(); - assertTaskUpToDate(result, ":upToDate1", ":upToDate2"); + getTestClustersRunner(":upToDate1").build(); + BuildResult result = getTestClustersRunner(":upToDate1").build(); + assertTaskUpToDate(result, ":upToDate1"); assertNotStarted(result); } diff --git a/buildSrc/src/testKit/testclusters/build.gradle b/buildSrc/src/testKit/testclusters/build.gradle index e4f912a3d7a..56bf5c861f3 100644 --- a/buildSrc/src/testKit/testclusters/build.gradle +++ b/buildSrc/src/testKit/testclusters/build.gradle @@ -105,10 +105,10 @@ task printLog { task upToDate1 { useCluster testClusters.myTestCluster -} - -task upToDate2 { - useCluster testClusters.myTestCluster + outputs.upToDateWhen { true } + doLast { + println "Some task action" + } } task skipped1 {