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

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)

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;
@@ -264,6 +265,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
 
@@ -278,6 +283,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);
@@ -1025,6 +1030,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,
@@ -1086,6 +1092,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()
@@ -1150,6 +1157,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) {
@@ -1201,6 +1209,7 @@ class FlushActionListener implements ActionListener<AcknowledgedResponse> {
 
         @Override
         public void onResponse(final AcknowledgedResponse response) {
+            logger.debug("Preparing to flush downsample index [{}]", downsampleIndexName);
             FlushRequest request = new FlushRequest(downsampleIndexName);
             request.setParentTask(parentTask);
             client.admin()
@@ -1239,12 +1248,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);
         }