Add additional ILM history store logging

This commit adds additional logging as well as applies some test fixes in an attempt to address elastic#50353.
dakrone · Feb 19, 2020 · 171955f · 171955f
1 parent 18c98ea
commit 171955f
Show file tree

Hide file tree

Showing 2 changed files with 19 additions and 5 deletions.
diff --git a/...qa/multi-node/src/test/java/org/elasticsearch/xpack/ilm/TimeSeriesLifecycleActionsIT.java b/...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;
@@ -1383,7 +1384,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";
 
@@ -1573,9 +1574,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" +
@@ -1642,7 +1644,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) {
@@ -1652,7 +1654,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
@@ -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()) {