Add more debugging information to rethrottles

I'm still trying to track down failures like:
https://elasticsearch-ci.elastic.co/job/elastic+elasticsearch+master+dockeralpine-periodic/1180/console

It looks like a task is hanging but I'm not sure why. So this
adds more logging for next time.

Author: nik9000

core/src/main/java/org/elasticsearch/action/bulk/byscroll/WorkingBulkByScrollTask.java

@@ -211,16 +211,12 @@ private void setRequestsPerSecond(float requestsPerSecond) {
     @Override
     public void rethrottle(float newRequestsPerSecond) {
         synchronized (delayedPrepareBulkRequestReference) {
-            if (logger.isDebugEnabled()) {
-                logger.debug("[{}]: Rethrottling to [{}] requests per second", getId(), newRequestsPerSecond);
-            }
+            logger.debug("[{}]: rethrottling to [{}] requests per second", getId(), newRequestsPerSecond);
             setRequestsPerSecond(newRequestsPerSecond);
 
             DelayedPrepareBulkRequest delayedPrepareBulkRequest = this.delayedPrepareBulkRequestReference.get();
             if (delayedPrepareBulkRequest == null) {
-                if (logger.isDebugEnabled()) {
-                    logger.debug("[{}]: Skipping rescheduling because there is no scheduled task", getId());
-                }
+                logger.debug("[{}]: skipping rescheduling because there is no scheduled task", getId());
                 // No request has been queued yet so nothing to reschedule.
                 return;
             }
@@ -259,20 +255,16 @@ DelayedPrepareBulkRequest rethrottle(float newRequestsPerSecond) {
                  * The user is attempting to slow the request down. We'll let the change in throttle take effect the next time we delay
                  * prepareBulkRequest. We can't just reschedule the request further out in the future the bulk context might time out.
                  */
-                if (logger.isDebugEnabled()) {
-                    logger.debug("[{}]: Skipping rescheduling because the new throttle [{}] is slower than the old one [{}].", getId(),
-                            newRequestsPerSecond, requestsPerSecond);
-                }
+                logger.debug("[{}]: skipping rescheduling because the new throttle [{}] is slower than the old one [{}]", getId(),
+                        newRequestsPerSecond, requestsPerSecond);
                 return this;
             }
 
             long remainingDelay = future.getDelay(TimeUnit.NANOSECONDS);
             // Actually reschedule the task
             if (false == FutureUtils.cancel(future)) {
                 // Couldn't cancel, probably because the task has finished or been scheduled. Either way we have nothing to do here.
-                if (logger.isDebugEnabled()) {
-                    logger.debug("[{}]: Skipping rescheduling we couldn't cancel the task.", getId());
-                }
+                logger.debug("[{}]: skipping rescheduling because we couldn't cancel the task", getId());
                 return this;
             }
 
@@ -281,9 +273,7 @@ DelayedPrepareBulkRequest rethrottle(float newRequestsPerSecond) {
              * test it you'll find that requests sneak through. So each request is given a runOnce boolean to prevent that.
              */
             TimeValue newDelay = newDelay(remainingDelay, newRequestsPerSecond);
-            if (logger.isDebugEnabled()) {
-                logger.debug("[{}]: Rescheduling for [{}] in the future.", getId(), newDelay);
-            }
+            logger.debug("[{}]: rescheduling for [{}] in the future", getId(), newDelay);
             return new DelayedPrepareBulkRequest(threadPool, requestsPerSecond, newDelay, command);
         }
 

core/src/test/java/org/elasticsearch/action/bulk/byscroll/WorkingBulkByScrollTaskTests.java

@@ -168,7 +168,7 @@ public void onFailure(Exception e) {
                 }
             });
 
-            // Rethrottle on a random number of threads, on of which is this thread.
+            // Rethrottle on a random number of threads, one of which is this thread.
             Runnable test = () -> {
                 try {
                     int rethrottles = 0;

modules/reindex/src/main/java/org/elasticsearch/index/reindex/TransportRethrottleAction.java

@@ -19,6 +19,7 @@
 
 package org.elasticsearch.index.reindex;
 
+import org.apache.logging.log4j.Logger;
 import org.elasticsearch.action.ActionListener;
 import org.elasticsearch.action.FailedNodeException;
 import org.elasticsearch.action.TaskOperationFailure;
@@ -54,21 +55,22 @@ public TransportRethrottleAction(Settings settings, ThreadPool threadPool, Clust
 
     @Override
     protected void taskOperation(RethrottleRequest request, BulkByScrollTask task, ActionListener<TaskInfo> listener) {
-        rethrottle(clusterService.localNode().getId(), client, task, request.getRequestsPerSecond(), listener);
+        rethrottle(logger, clusterService.localNode().getId(), client, task, request.getRequestsPerSecond(), listener);
     }
 
-    static void rethrottle(String localNodeId, Client client, BulkByScrollTask task, float newRequestsPerSecond,
+    static void rethrottle(Logger logger, String localNodeId, Client client, BulkByScrollTask task, float newRequestsPerSecond,
             ActionListener<TaskInfo> listener) {
         int runningSubTasks = task.runningSliceSubTasks();
         if (runningSubTasks == 0) {
-            // Nothing to do, all sub tasks are done
+            logger.debug("rethrottling local task [{}] to [{}] requests per second", task.getId(), newRequestsPerSecond);
             task.rethrottle(newRequestsPerSecond);
             listener.onResponse(task.taskInfo(localNodeId, true));
             return;
         }
         RethrottleRequest subRequest = new RethrottleRequest();
         subRequest.setRequestsPerSecond(newRequestsPerSecond / runningSubTasks);
         subRequest.setParentTaskId(new TaskId(localNodeId, task.getId()));
+        logger.debug("rethrottling children of task [{}] to [{}] requests per second", task.getId(), subRequest.getRequestsPerSecond());
         client.execute(RethrottleAction.INSTANCE, subRequest, ActionListener.wrap(r -> {
             r.rethrowFailures("Rethrottle");
             listener.onResponse(task.getInfoGivenSliceInfo(localNodeId, r.getTasks()));

modules/reindex/src/test/java/org/elasticsearch/index/reindex/CancelTests.java

@@ -37,6 +37,7 @@
 import org.elasticsearch.ingest.IngestTestPlugin;
 import org.elasticsearch.plugins.Plugin;
 import org.elasticsearch.tasks.TaskInfo;
+import org.elasticsearch.test.junit.annotations.TestLogging;
 import org.hamcrest.Matcher;
 import org.junit.Before;
 
@@ -59,6 +60,7 @@
  * different cancellation places - that is the responsibility of AsyncBulkByScrollActionTests which have more precise control to
  * simulate failures but do not exercise important portion of the stack like transport and task management.
  */
+@TestLogging("org.elasticsearch.action.bulk.byscroll:DEBUG,org.elasticsearch.index.reindex:DEBUG")
 public class CancelTests extends ReindexTestCase {
 
     protected static final String INDEX = "reindex-cancel-index";

modules/reindex/src/test/java/org/elasticsearch/index/reindex/TransportRethrottleActionTests.java

@@ -73,7 +73,7 @@ private void rethrottleTestCase(int runningSlices, Consumer<ActionListener<ListT
         @SuppressWarnings("unchecked")
         ActionListener<TaskInfo> listener = mock(ActionListener.class);
 
-        TransportRethrottleAction.rethrottle(localNodeId, client, task, newRequestsPerSecond, listener);
+        TransportRethrottleAction.rethrottle(logger, localNodeId, client, task, newRequestsPerSecond, listener);
 
         // Capture the sub request and the listener so we can verify they are sane
         ArgumentCaptor<RethrottleRequest> subRequest = ArgumentCaptor.forClass(RethrottleRequest.class);