Add logging so we can time the downsampling action (#137496) (#137504)

We suspect that #137148
is caused by a legit timeout and not that it failed to notify the
listener. In order to verify that we added some extra logging lines that
allow us to better track the time. More details in
#137148 (comment)

(cherry picked from commit 9770442)

# Conflicts:
#	x-pack/plugin/downsample/src/main/java/org/elasticsearch/xpack/downsample/TransportDownsampleAction.java

Author: gmarouli

x-pack/plugin/downsample/src/internalClusterTest/java/org/elasticsearch/xpack/downsample/DownsampleTransportFailureIT.java

@@ -30,6 +30,7 @@
 import org.elasticsearch.search.aggregations.bucket.histogram.DateHistogramInterval;
 import org.elasticsearch.test.ESIntegTestCase;
 import org.elasticsearch.test.InternalTestCluster;
+import org.elasticsearch.test.junit.annotations.TestIssueLogging;
 import org.elasticsearch.test.transport.MockTransportService;
 import org.elasticsearch.xcontent.XContentBuilder;
 import org.elasticsearch.xcontent.XContentFactory;
@@ -263,6 +264,10 @@ private void assertIndexDoesNotExist(final String nodeName, final String indexNa
         assertEquals("no such index [" + indexName + "]", targetIndexNotFoundException.getMessage());
     }
 
+    @TestIssueLogging(
+        value = "org.elasticsearch.xpack.downsample.TransportDownsampleAction:DEBUG",
+        issueUrl = "https://github.com/elastic/elasticsearch/issues/137148"
+    )
     public void testNoDisruption() {
         // GIVEN
 
@@ -277,6 +282,7 @@ public void testNoDisruption() {
         // WHEN nothing happens
 
         // THEN
+        logger.info("Executing downsample action from [{}] to [{}]", SOURCE_INDEX_NAME, TARGET_INDEX_NAME);
         final AcknowledgedResponse downsampleResponse = testCluster.masterClient()
             .execute(DownsampleAction.INSTANCE, downsampleRequest)
             .actionGet(TimeValue.timeValueMillis(DOWNSAMPLE_ACTION_TIMEOUT_MILLIS));

x-pack/plugin/downsample/src/main/java/org/elasticsearch/xpack/downsample/TransportDownsampleAction.java

@@ -238,6 +238,11 @@ protected void masterOperation(
         ClusterState state,
         ActionListener<AcknowledgedResponse> listener
     ) {
+        logger.debug(
+            "Starting downsampling [{}] with [{}] interval",
+            request.getSourceIndex(),
+            request.getDownsampleConfig().getFixedInterval()
+        );
         long startTime = nowSupplier.get();
         String sourceIndexName = request.getSourceIndex();
         IndexNameExpressionResolver.assertExpressionHasNullOrDataSelector(sourceIndexName);
@@ -1019,6 +1024,7 @@ private void createDownsampleIndex(
         taskQueue.submitTask("create-downsample-index [" + downsampleIndexName + "]", new DownsampleClusterStateUpdateTask(listener) {
             @Override
             public ClusterState execute(ClusterState currentState) throws Exception {
+                logger.debug("Creating downsample index [{}]", downsampleIndexName);
                 return metadataCreateIndexService.applyCreateIndexRequest(
                     currentState,
                     createIndexClusterStateUpdateRequest,
@@ -1083,6 +1089,7 @@ class UpdateDownsampleIndexSettingsActionListener implements ActionListener<Ackn
 
         @Override
         public void onResponse(final AcknowledgedResponse response) {
+            logger.debug("Preparing to refresh downsample index [{}]", downsampleIndexName);
             final RefreshRequest request = new RefreshRequest(downsampleIndexName);
             request.setParentTask(parentTask);
             client.admin()
@@ -1155,6 +1162,7 @@ public void onResponse(final BroadcastResponse response) {
 
                     @Override
                     public ClusterState execute(ClusterState currentState) {
+                        logger.debug("Updating downsample index status for [{}]", downsampleIndexName);
                         final ProjectMetadata project = currentState.metadata().getProject(projectId);
                         final IndexMetadata downsampleIndex = project.index(downsampleIndexName);
                         if (IndexMetadata.INDEX_DOWNSAMPLE_STATUS.get(downsampleIndex.getSettings()) == DownsampleTaskStatus.SUCCESS) {
@@ -1206,6 +1214,7 @@ class ForceMergeActionListener implements ActionListener<AcknowledgedResponse> {
 
         @Override
         public void onResponse(final AcknowledgedResponse response) {
+            logger.debug("Preparing to force merge downsample index [{}]", downsampleIndexName);
             ForceMergeRequest request = new ForceMergeRequest(downsampleIndexName);
             request.maxNumSegments(1);
             request.setParentTask(parentTask);
@@ -1245,12 +1254,14 @@ class MeasurementActionListener implements ActionListener<AcknowledgedResponse>
         @Override
         public void onResponse(final AcknowledgedResponse response) {
             recordSuccessMetrics(startTime);
+            logger.debug("Downsampling measured successfully");
             actionListener.onResponse(AcknowledgedResponse.TRUE);
         }
 
         @Override
         public void onFailure(Exception e) {
             recordSuccessMetrics(startTime);
+            logger.debug("Downsampling measured successfully", e);
             this.actionListener.onFailure(e);
         }