Skip to content

Commit

Permalink
Improve how log is tailed in testclusters on failure (#40600)
Browse files Browse the repository at this point in the history
* Improoce how log is tailed in testclusters on failure

- only print last few lines
- print all errors and warnings
- compact repeating errors and warnings
  • Loading branch information
alpar-t committed Jul 11, 2019
1 parent eace735 commit 47ab2bd
Show file tree
Hide file tree
Showing 3 changed files with 83 additions and 12 deletions.
Original file line number Diff line number Diff line change
Expand Up @@ -46,6 +46,8 @@
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;
Expand All @@ -61,6 +63,7 @@
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;
Expand All @@ -82,13 +85,22 @@ 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;
private static final TimeUnit ADDITIONAL_CONFIG_TIMEOUT_UNIT = TimeUnit.SECONDS;
private static final List<String> OVERRIDABLE_SETTINGS = Arrays.asList(
"path.repo",
"discovery.seed_providers"

);

private static final int TAIL_LOG_MESSAGES_COUNT = 40;
private static final List<String> 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;
Expand Down Expand Up @@ -693,14 +705,73 @@ private void logProcessInfo(String prefix, ProcessHandle.Info info) {
}

private void logFileContents(String description, Path from) {
LOGGER.error("{} `{}`", description, this);
try (Stream<String> lines = Files.lines(from, StandardCharsets.UTF_8)) {
lines
.map(line -> " " + line)
.forEach(LOGGER::error);
final Map<String, Integer> errorsAndWarnings = new LinkedHashMap<>();
LinkedList<String> 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) {
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -68,9 +68,9 @@ public void testUseClusterByTwo() {
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);
}

Expand Down
8 changes: 4 additions & 4 deletions buildSrc/src/testKit/testclusters/build.gradle
Original file line number Diff line number Diff line change
Expand Up @@ -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 {
Expand Down

0 comments on commit 47ab2bd

Please sign in to comment.