Log reindexing failures #112676

ankikuma · 2024-09-09T18:27:31Z

Log number of reindex tasks in flight during a shutdown.

This PR aims to address ES-8850.

Also fixing a small labeling mistake for the reindex metrics.

ankikuma · 2024-09-09T18:32:21Z

A couple of things to consider while reviewing:

Right now I have set the timeout for the wait for reindex tasks to 1 min. Do we want a setting for this so we can tweak it ?
Right now I am exposing reindexing failures by logging a message. Do we want to use APM metrics instead ?

elasticsearchmachine · 2024-09-09T18:33:49Z

Pinging @elastic/es-distributed (Team:Distributed)

elasticsearchmachine · 2024-09-09T18:35:04Z

Hi @ankikuma, I've created a changelog YAML for you.

Tim-Brooks

For a test I would create an IT performing reindex on a specific node. And then wait for the task to appear in the tasks list. And then immediately stop the node. And check that the task still completes.

You would want to try it out without your shutdown wait code here and make sure you are indexing enough data that the test would (at least sometimes) fail without your shutdown wait you are adding here.

Tim-Brooks · 2024-09-11T19:24:32Z

server/src/main/java/org/elasticsearch/node/Node.java

@@ -702,6 +704,52 @@ private void awaitSearchTasksComplete(TimeValue asyncSearchTimeout) {
        }
    }

+    private void awaitReindexTasksComplete(TimeValue asyncReindexTimeout) {


Can we combine some code here? Something like:

private void awaitSearchTasksComplete(TimeValue asyncSearchTimeout) { waitForTasks(asyncSearchTimeout, TransportSearchAction.NAME); } private void awaitReindexTasksComplete(TimeValue reindexTimeout) { waitForTasks(reindexTimeout, ReindexAction.NAME); } private void waitForTasks(TimeValue timeout, String taskName) { TaskManager taskManager = injector.getInstance(TransportService.class).getTaskManager(); long millisWaited = 0; while (true) { long searchTasksRemaining = taskManager.getTasks().values().stream().filter(task -> taskName.equals(task.getAction())).count(); if (searchTasksRemaining == 0) { logger.debug("all search tasks complete"); return; } else { // Let the system work on those searches for a while. We're on a dedicated thread to manage app shutdown, so we // literally just want to wait and not take up resources on this thread for now. Poll period chosen to allow short // response times, but checking the tasks list is relatively expensive, and we don't want to waste CPU time we could // be spending on finishing those searches. final TimeValue pollPeriod = TimeValue.timeValueMillis(500); millisWaited += pollPeriod.millis(); if (TimeValue.ZERO.equals(timeout) == false && millisWaited >= timeout.millis()) { logger.warn( format( "timed out after waiting [%s] for [%d] " + taskName + " tasks to finish", timeout.toString(), searchTasksRemaining ) ); return; } logger.debug( format("waiting for [%s] " + taskName + " tasks to finish, next poll in [%s]", searchTasksRemaining, pollPeriod) ); try { Thread.sleep(pollPeriod.millis()); } catch (InterruptedException ex) { logger.warn( format( "interrupted while waiting [%s] for [%d] " + taskName + " tasks to finish", timeout.toString(), searchTasksRemaining ) ); return; } } } }

Tim-Brooks · 2024-09-11T19:29:13Z

If it is difficult to get the reindex task to fail from restarting the node, you can always reach in and grab ThreadPool and block some of the threads. But I would start by trying to do the test without that.

ankikuma · 2024-09-11T23:24:22Z

Thanks Tim, I will work on a test case.

henningandersen

Looks good, left a couple comments.

henningandersen · 2024-09-17T11:50:49Z

server/src/main/java/org/elasticsearch/node/Node.java

@@ -629,6 +630,7 @@ boolean isIncomplete() {

            stopperRunner.accept("http-server-transport-stop", injector.getInstance(HttpServerTransport.class)::close);
            stopperRunner.accept("async-search-stop", () -> awaitSearchTasksComplete(maxTimeout));
+            stopperRunner.accept("reindex-stop", () -> awaitReindexTasksComplete(TimeValue.min(TimeValue.timeValueMinutes(1), maxTimeout)));


Let us make the timeout configurable separately from the max-timeout. I think 1 min could be too long by default, I'd go with something like 10secs and we can increase where we need it. The problem is that users do rolling restarts and this could prevent those from completing as fast as before - and the longer it takes to restart the more operations may need to be replayed to re-establish sync'ed replicas.

henningandersen · 2024-09-17T11:56:57Z

server/src/main/java/org/elasticsearch/node/Node.java

@@ -629,6 +630,7 @@ boolean isIncomplete() {

            stopperRunner.accept("http-server-transport-stop", injector.getInstance(HttpServerTransport.class)::close);
            stopperRunner.accept("async-search-stop", () -> awaitSearchTasksComplete(maxTimeout));
+            stopperRunner.accept("reindex-stop", () -> awaitReindexTasksComplete(TimeValue.min(TimeValue.timeValueMinutes(1), maxTimeout)));


maxTimeout=ZERO seems to mean infinite, I wonder if the TimeValue.min here should respect that?

Refresh to latest

ankikuma · 2024-10-18T02:30:08Z

Added a test. Please take a look @henningandersen @Tim-Brooks whenever you get a chance.

I set the default timeout for the reindexing wait to be 10s. Please let me know if you think I should shorten it.

Tim-Brooks · 2024-10-22T00:11:26Z

server/src/main/java/org/elasticsearch/node/ShutdownFenceService.java

+/**
+ * Extracted out the logic from {@link Node#prepareForClose()} to facilitate testing.
+ */
+public class ShutdownFenceService {


I know I was the one who created this name initially 🙃, but I'm not sure it is the best. Maybe let's change it to ShutdownService.

And maybe add a javadoc that describes it in a line or two similar to what you have on the prepareForShutdown method.

Sure, no problem. I will rename it to ShutdownPrepareService since we already have a PluginShutdownService and it might get confusing.

Tim-Brooks

Mostly looks good to me. Just 1 comment.

Refresh to latest

Tim-Brooks

LGTM

henningandersen

Looks good, left a few comments.

henningandersen · 2024-10-22T16:11:14Z

...ndex/src/internalClusterTest/java/org/elasticsearch/index/reindex/ReindexNodeShutdownIT.java

+        assertHitCount(prepareSearch(INDEX).setSize(0).setTrackTotalHits(true), numDocs);
+    }
+
+    private void checkDestinationIndex(String dataNodeName, int numDocs) {


nit: I'd prefer to move this helper method after the test method. Right now we have some helpers before, some after. We typically have the tests prior to the helper methods (at least when they are this large) to make it easy to spot the test methods.

Thanks. Done.

henningandersen · 2024-10-22T16:12:08Z

...ndex/src/internalClusterTest/java/org/elasticsearch/index/reindex/ReindexNodeShutdownIT.java

+    }
+
+    private void createReindexTaskAndShutdown(final String coordNodeName) throws Exception {
+


nit: looks like an extra newline here, can we remove it?

I still see it here?

...ndex/src/internalClusterTest/java/org/elasticsearch/index/reindex/ReindexNodeShutdownIT.java

henningandersen · 2024-10-22T17:03:18Z

...ndex/src/internalClusterTest/java/org/elasticsearch/index/reindex/ReindexNodeShutdownIT.java

+    private static TaskInfo findTask(String actionName, String nodeName) {
+        ListTasksResponse tasks;
+        long start = System.nanoTime();
+        do {


Can we use assertBusy() instead?

henningandersen · 2024-10-22T17:04:05Z

server/src/main/java/org/elasticsearch/node/ShutdownPrepareService.java

+
+            stopperRunner.accept("http-server-transport-stop", httpServerTransport::close);
+            stopperRunner.accept("async-search-stop", () -> awaitSearchTasksComplete(maxTimeout, taskManager));
+            stopperRunner.accept("reindex-stop", () -> awaitReindexTasksComplete(reindexTimeout, taskManager));


Is this the only change in this class? The refactor makes it a bit harder to reason about the change. We can keep it as is, but it might be beneficial to do the refactor separately for future PRs.

The refactor was done for testing purpose as explained above.

Yeah, I understand that. Still, is the line added (plus the method called) the only change here or has other changes sneaked in?

Oh I see, I thought your question was about creating this new class. I only really added the awaitReindexTasksComplete() but in order to reuse the code being used by awaitSearchTasksComplete() I created a new API waitForTasks() to replace awaitSearchTasksComplete()

henningandersen

Left a few comments before realizing the changes were not pushed yet.

henningandersen · 2024-10-23T11:47:46Z

...ndex/src/internalClusterTest/java/org/elasticsearch/index/reindex/ReindexNodeShutdownIT.java

+    }
+
+    private void createReindexTaskAndShutdown(final String coordNodeName) throws Exception {
+


I still see it here?

...ndex/src/internalClusterTest/java/org/elasticsearch/index/reindex/ReindexNodeShutdownIT.java

ankikuma · 2024-10-23T14:04:34Z

I just pushed the changes. I wanted to wait to see if you would suggest a major revamp of the test :)

Refresh to latest

henningandersen

LGTM.

Left a number of smaller comments, but no need for another round.

henningandersen · 2024-10-23T15:13:10Z

...ndex/src/internalClusterTest/java/org/elasticsearch/index/reindex/ReindexNodeShutdownIT.java

+        }, 10, TimeUnit.SECONDS));
+    }
+
+    private static void findTask(String actionName, String nodeName) throws Exception {


nit: I'd call this waitForTask instead.

henningandersen · 2024-10-23T15:16:41Z

...ndex/src/internalClusterTest/java/org/elasticsearch/index/reindex/ReindexNodeShutdownIT.java

+        assertTrue("Number of documents in source and dest indexes does not match", waitUntil(() -> {
+            final TotalHits totalHits = SearchResponseUtils.getTotalHits(
+                client(dataNodeName).prepareSearch(DEST_INDEX).setSize(0).setTrackTotalHits(true)
+            );
+            return totalHits.relation() == TotalHits.Relation.EQUAL_TO && totalHits.value() == numDocs;
+        }, 10, TimeUnit.SECONDS));


I think this can be something like following instead:

assertBusy(() -> assertHitCount(prepareSearch(DEST_INDEX).setSize(0).setTrackTotalHits(true), numDocs));

henningandersen · 2024-10-23T15:23:38Z

...ndex/src/internalClusterTest/java/org/elasticsearch/index/reindex/ReindexNodeShutdownIT.java

+            for (TaskInfo taskInfo : tasks.getTasks()) {
+                // Skip tasks with a parent because those are children of the task we want
+                assertFalse(taskInfo.parentTaskId().isSet());
+            }


I think this does not really wait. As a sidenote I am unsure if we need to wait and also whether skipping child tasks is important. But I think this should be:

Suggested change

for (TaskInfo taskInfo : tasks.getTasks()) {

// Skip tasks with a parent because those are children of the task we want

assertFalse(taskInfo.parentTaskId().isSet());

}

for (TaskInfo taskInfo : tasks.getTasks()) {

// Skip tasks with a parent because those are children of the task we want

if(taskInfo.parentTaskId().isSet()) == false) {

return;

}

fail("not found - yet");

}

You are right. Thanks for catching this, I fixed it and tested it out as well (by holding off submission of the reindexing task).

henningandersen · 2024-10-23T15:24:21Z

modules/reindex/src/main/java/org/elasticsearch/reindex/ReindexMetrics.java

@@ -19,7 +19,7 @@ public class ReindexMetrics {
    private final LongHistogram reindexTimeSecsHistogram;

    public ReindexMetrics(MeterRegistry meterRegistry) {
-        this(meterRegistry.registerLongHistogram(REINDEX_TIME_HISTOGRAM, "Time to reindex by search", "millis"));
+        this(meterRegistry.registerLongHistogram(REINDEX_TIME_HISTOGRAM, "Time to reindex by search", "seconds"));


While I think I agree to the change, I'd prefer to do this in a separate PR.

ok, I will remove it.

henningandersen · 2024-10-23T15:27:52Z

server/src/main/java/org/elasticsearch/node/ShutdownPrepareService.java

+    Settings settings;
+    HttpServerTransport httpServerTransport;
+    TerminationHandler terminationHandler;


We should make all fields as final and private as possible. I think these can be private final?

Yes. Thanks!

henningandersen · 2024-10-23T15:33:03Z

server/src/main/java/org/elasticsearch/node/Node.java

@@ -167,6 +156,12 @@ public class Node implements Closeable {
        Setting.Property.NodeScope
    );

+    public static final Setting<TimeValue> MAXIMUM_REINDEXING_TIMEOUT_SETTING = Setting.positiveTimeSetting(


I think we might as well move these two settings closer to their use, i.e., to ShutdownPrepareService.

henningandersen · 2024-10-23T15:35:17Z

server/src/main/java/org/elasticsearch/node/ShutdownPrepareService.java

+        }
+    }
+
+    private void waitForTasks(TimeValue timeout, String taskName, TaskManager taskManager) {


Looks like we have differing naming for similar things in this class, I'd prefer to name this: awaitTasksComplete, similar to the two other await methods.

Yes, that's a better name. Thanks.

Wait for reindexing tasks to finish during shutdown for an amount of time defined by settings. Also log the number of reindexing tasks still in flight after the wait.

Log reindexing failures

dcd6d74

ankikuma requested a review from a team as a code owner September 9, 2024 18:27

elasticsearchmachine added needs:triage Requires assignment of a team area label v8.16.0 labels Sep 9, 2024

ankikuma requested a review from henningandersen September 9, 2024 18:32

ankikuma added the :Distributed Indexing/Reindex Issues relating to reindex that are not caused by issues further down label Sep 9, 2024

elasticsearchmachine added the Team:Distributed (Obsolete) Meta label for distributed team (obsolete). Replaced by Distributed Indexing/Coordination. label Sep 9, 2024

elasticsearchmachine removed the needs:triage Requires assignment of a team area label label Sep 9, 2024

ankikuma added >enhancement needs:triage Requires assignment of a team area label and removed Team:Distributed (Obsolete) Meta label for distributed team (obsolete). Replaced by Distributed Indexing/Coordination. labels Sep 9, 2024

elasticsearchmachine added the Team:Distributed (Obsolete) Meta label for distributed team (obsolete). Replaced by Distributed Indexing/Coordination. label Sep 9, 2024

elasticsearchmachine removed the needs:triage Requires assignment of a team area label label Sep 9, 2024

ankikuma removed the Team:Distributed (Obsolete) Meta label for distributed team (obsolete). Replaced by Distributed Indexing/Coordination. label Sep 9, 2024

elasticsearchmachine added the Team:Distributed (Obsolete) Meta label for distributed team (obsolete). Replaced by Distributed Indexing/Coordination. label Sep 9, 2024

ankikuma requested review from fcofdez and Tim-Brooks and removed request for fcofdez September 11, 2024 14:25

mark-vieira added v9.0.0 and removed v8.16.0 labels Sep 11, 2024

Tim-Brooks reviewed Sep 11, 2024

View reviewed changes

ankikuma self-assigned this Sep 12, 2024

henningandersen reviewed Sep 17, 2024

View reviewed changes

ankikuma added 2 commits October 8, 2024 10:08

Add test

cfd0848

Address review comments

ebcd40a

ankikuma added 8 commits October 14, 2024 15:57

Commit test

16ccf71

Rewrite test

82904e9

Merge remote-tracking branch 'upstream/main' into feature/ES8850

43f312e

Refresh to latest

Modify test

33f24db

Fix test

102c7ca

Adjust timeout defaults

d4edfc4

Cleanup

17d9279

Merge remote-tracking branch 'upstream/main' into feature/ES8850

d47324e

Refresh to latest

ankikuma added 3 commits October 21, 2024 16:02

Remove shutdown dependency from gradle

f932ce1

Remove taskManager.java

e02f238

Refactor test

9daddef

Tim-Brooks reviewed Oct 22, 2024

View reviewed changes

ankikuma added 2 commits October 21, 2024 21:28

Merge remote-tracking branch 'upstream/main' into feature/ES8850

5e28452

Refresh to latest

Rename ShutdownFenceService to ShutdownCloseService

8d75d0b

Tim-Brooks self-requested a review October 22, 2024 16:42

Tim-Brooks approved these changes Oct 22, 2024

View reviewed changes

henningandersen reviewed Oct 22, 2024

View reviewed changes

henningandersen reviewed Oct 23, 2024

View reviewed changes

Address Review comments

6ac0989

ankikuma added 2 commits October 23, 2024 10:23

code cleanup

5f907b8

Merge remote-tracking branch 'upstream/main' into feature/ES8850

a66eed1

Refresh to latest

henningandersen approved these changes Oct 23, 2024

View reviewed changes

Review comments addressed

1d0f640

ankikuma merged commit c9f995a into elastic:main Oct 23, 2024
16 checks passed

		}

		private void createReindexTaskAndShutdown(final String coordNodeName) throws Exception {

Log reindexing failures #112676

Log reindexing failures #112676

Conversation

ankikuma commented Sep 9, 2024 • edited Loading

ankikuma commented Sep 9, 2024

elasticsearchmachine commented Sep 9, 2024

elasticsearchmachine commented Sep 9, 2024

Tim-Brooks left a comment • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Tim-Brooks commented Sep 11, 2024

ankikuma commented Sep 11, 2024

henningandersen left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

ankikuma commented Oct 18, 2024

Tim-Brooks Oct 22, 2024 • edited Loading

Choose a reason for hiding this comment

ankikuma Oct 22, 2024 • edited Loading

Choose a reason for hiding this comment

Tim-Brooks left a comment

Choose a reason for hiding this comment

Tim-Brooks left a comment

Choose a reason for hiding this comment

henningandersen left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

ankikuma Oct 23, 2024 • edited Loading

Choose a reason for hiding this comment

henningandersen left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

ankikuma commented Oct 23, 2024

henningandersen left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

ankikuma commented Sep 9, 2024 •

edited

Loading

Tim-Brooks left a comment •

edited

Loading

Tim-Brooks Oct 22, 2024 •

edited

Loading

ankikuma Oct 22, 2024 •

edited

Loading

ankikuma Oct 23, 2024 •

edited

Loading