From 44fff553a73803069a8a720647304cc3ecde4bfa Mon Sep 17 00:00:00 2001 From: Lee Hinman Date: Thu, 20 Feb 2020 07:58:43 -0700 Subject: [PATCH] Add additional ILM history store logging (#52539) This commit adds additional logging as well as applies some test fixes in an attempt to address #50353. --- .../xpack/ilm/TimeSeriesLifecycleActionsIT.java | 10 ++++++---- .../xpack/ilm/history/ILMHistoryStore.java | 14 +++++++++++++- 2 files changed, 19 insertions(+), 5 deletions(-) diff --git a/x-pack/plugin/ilm/qa/multi-node/src/test/java/org/elasticsearch/xpack/ilm/TimeSeriesLifecycleActionsIT.java b/x-pack/plugin/ilm/qa/multi-node/src/test/java/org/elasticsearch/xpack/ilm/TimeSeriesLifecycleActionsIT.java index 4e700e76eb9a0..d48cf795164c8 100644 --- a/x-pack/plugin/ilm/qa/multi-node/src/test/java/org/elasticsearch/xpack/ilm/TimeSeriesLifecycleActionsIT.java +++ b/x-pack/plugin/ilm/qa/multi-node/src/test/java/org/elasticsearch/xpack/ilm/TimeSeriesLifecycleActionsIT.java @@ -25,6 +25,7 @@ import org.elasticsearch.common.xcontent.XContentType; import org.elasticsearch.common.xcontent.json.JsonXContent; import org.elasticsearch.index.IndexSettings; +import org.elasticsearch.test.junit.annotations.TestIssueLogging; import org.elasticsearch.test.rest.ESRestTestCase; import org.elasticsearch.xpack.core.ilm.AllocateAction; import org.elasticsearch.xpack.core.ilm.DeleteAction; @@ -1403,7 +1404,7 @@ public void testHistoryIsWrittenWithSuccess() throws Exception { assertBusy(() -> assertHistoryIsPresent(policy, index + "-000002", true, "check-rollover-ready"), 30, TimeUnit.SECONDS); } - @AwaitsFix(bugUrl = "https://github.com/elastic/elasticsearch/issues/50353") + @TestIssueLogging(value="org.elasticsearch.xpack.ilm.history:TRACE", issueUrl="https://github.com/elastic/elasticsearch/issues/50353") public void testHistoryIsWrittenWithFailure() throws Exception { String index = "failure-index"; @@ -1593,9 +1594,10 @@ private void assertHistoryIsPresent(String policyName, String indexName, boolean // This method should be called inside an assertBusy, it has no retry logic of its own private void assertHistoryIsPresent(String policyName, String indexName, boolean success, @Nullable String phase, @Nullable String action, String stepName) throws IOException { + assertOK(client().performRequest(new Request("POST", indexName + "/_refresh"))); logger.info("--> checking for history item [{}], [{}], success: [{}], phase: [{}], action: [{}], step: [{}]", policyName, indexName, success, phase, action, stepName); - final Request historySearchRequest = new Request("GET", "ilm-history*/_search"); + final Request historySearchRequest = new Request("GET", "ilm-history*/_search?expand_wildcards=all"); historySearchRequest.setJsonEntity("{\n" + " \"query\": {\n" + " \"bool\": {\n" + @@ -1662,7 +1664,7 @@ private void assertHistoryIsPresent(String policyName, String indexName, boolean try (InputStream is = allResultsResp.getEntity().getContent()) { allResultsMap = XContentHelper.convertToMap(XContentType.JSON.xContent(), is, true); } - logger.info("--> expected at least 1 hit, got 0. All history for index [{}]: {}", index, allResultsMap); + logger.info("--> expected at least 1 hit, got 0. All history for index [{}]: {}", indexName, allResultsMap); } assertThat(hits, greaterThanOrEqualTo(1)); } catch (ResponseException e) { @@ -1672,7 +1674,7 @@ private void assertHistoryIsPresent(String policyName, String indexName, boolean } // Finally, check that the history index is in a good state - Step.StepKey stepKey = getStepKeyForIndex("ilm-history-1-000001"); + Step.StepKey stepKey = getStepKeyForIndex("ilm-history-2-000001"); assertEquals("hot", stepKey.getPhase()); assertEquals(RolloverAction.NAME, stepKey.getAction()); assertEquals(WaitForRolloverReadyStep.NAME, stepKey.getName()); diff --git a/x-pack/plugin/ilm/src/main/java/org/elasticsearch/xpack/ilm/history/ILMHistoryStore.java b/x-pack/plugin/ilm/src/main/java/org/elasticsearch/xpack/ilm/history/ILMHistoryStore.java index 96c54e5adfca3..d5ed267e77694 100644 --- a/x-pack/plugin/ilm/src/main/java/org/elasticsearch/xpack/ilm/history/ILMHistoryStore.java +++ b/x-pack/plugin/ilm/src/main/java/org/elasticsearch/xpack/ilm/history/ILMHistoryStore.java @@ -38,6 +38,7 @@ import java.io.IOException; import java.util.Arrays; import java.util.Map; +import java.util.Objects; import java.util.concurrent.CompletableFuture; import java.util.concurrent.TimeUnit; import java.util.stream.Collectors; @@ -91,16 +92,27 @@ public void beforeBulk(long executionId, BulkRequest request) { .collect(Collectors.joining("\n"))), e); throw new ElasticsearchException(e); } + if (logger.isTraceEnabled()) { + logger.info("about to index: {}", + request.requests().stream() + .map(dwr -> ((IndexRequest) dwr).sourceAsMap()) + .map(Objects::toString) + .collect(Collectors.joining(","))); + } } @Override public void afterBulk(long executionId, BulkRequest request, BulkResponse response) { long items = request.numberOfActions(); if (logger.isTraceEnabled()) { - logger.trace("indexed [{}] items into ILM history index [{}]", items, + logger.trace("indexed [{}] items into ILM history index [{}], items: {}", items, Arrays.stream(response.getItems()) .map(BulkItemResponse::getIndex) .distinct() + .collect(Collectors.joining(",")), + request.requests().stream() + .map(dwr -> ((IndexRequest) dwr).sourceAsMap()) + .map(Objects::toString) .collect(Collectors.joining(","))); } if (response.hasFailures()) {