From e33d62762389d3b8ff6b7d6b1469e02204950e3b Mon Sep 17 00:00:00 2001
From: Yang Wang <yang.wang@elastic.co>
Date: Mon, 16 Sep 2024 00:37:12 +1000
Subject: [PATCH] more logging around refresh

---
 .../action/support/replication/PostWriteRefresh.java  | 11 ++++++++++-
 .../org/elasticsearch/index/shard/IndexShard.java     |  2 ++
 2 files changed, 12 insertions(+), 1 deletion(-)

diff --git a/server/src/main/java/org/elasticsearch/action/support/replication/PostWriteRefresh.java b/server/src/main/java/org/elasticsearch/action/support/replication/PostWriteRefresh.java
index 67793fb525644..72d75aa512a99 100644
--- a/server/src/main/java/org/elasticsearch/action/support/replication/PostWriteRefresh.java
+++ b/server/src/main/java/org/elasticsearch/action/support/replication/PostWriteRefresh.java
@@ -22,6 +22,8 @@
 import org.elasticsearch.index.engine.Engine;
 import org.elasticsearch.index.shard.IndexShard;
 import org.elasticsearch.index.translog.Translog;
+import org.elasticsearch.logging.LogManager;
+import org.elasticsearch.logging.Logger;
 import org.elasticsearch.threadpool.ThreadPool;
 import org.elasticsearch.transport.TransportRequestOptions;
 import org.elasticsearch.transport.TransportService;
@@ -29,6 +31,7 @@
 import java.util.concurrent.Executor;
 
 public class PostWriteRefresh {
+    private static final Logger logger = LogManager.getLogger(PostWriteRefresh.class);
 
     public static final String POST_WRITE_REFRESH_ORIGIN = "post_write_refresh";
     public static final String FORCED_REFRESH_AFTER_INDEX = "refresh_flag_index";
@@ -98,6 +101,7 @@ private static void immediate(IndexShard indexShard, ActionListener<Engine.Refre
     }
 
     private static void waitUntil(IndexShard indexShard, Translog.Location location, ActionListener<Boolean> listener) {
+        logger.info("--> waitUntil {} [{}]", indexShard, location);
         if (location != null) {
             indexShard.addRefreshListener(location, listener::onResponse);
         } else {
@@ -112,6 +116,7 @@ private void refreshUnpromotables(
         boolean forced,
         @Nullable TimeValue postWriteRefreshTimeout
     ) {
+        logger.info("--> refreshUnpromotables {}, [{}], [{}]", indexShard, location, forced);
         Engine engineOrNull = indexShard.getEngineOrNull();
         if (engineOrNull == null) {
             listener.onFailure(new AlreadyClosedException("Engine closed during refresh."));
@@ -136,6 +141,7 @@ private void sendUnpromotableRequests(
         ActionListener<Boolean> listener,
         @Nullable TimeValue postWriteRefreshTimeout
     ) {
+        logger.info("--> sendUnpromotableRequests {}, [{}], [{}]", indexShard, generation, wasForced);
         UnpromotableShardRefreshRequest unpromotableReplicaRequest = new UnpromotableShardRefreshRequest(
             indexShard.getReplicationGroup().getRoutingTable(),
             indexShard.getOperationPrimaryTerm(),
@@ -147,7 +153,10 @@ private void sendUnpromotableRequests(
             TransportUnpromotableShardRefreshAction.NAME,
             unpromotableReplicaRequest,
             TransportRequestOptions.timeout(postWriteRefreshTimeout),
-            new ActionListenerResponseHandler<>(listener.safeMap(r -> wasForced), in -> ActionResponse.Empty.INSTANCE, refreshExecutor)
+            new ActionListenerResponseHandler<>(listener.safeMap(r -> {
+                logger.info("--> response got from unpromotable refresh {}, [{}] [{}]", indexShard, generation, wasForced);
+                return wasForced;
+            }), in -> ActionResponse.Empty.INSTANCE, refreshExecutor)
         );
     }
 
diff --git a/server/src/main/java/org/elasticsearch/index/shard/IndexShard.java b/server/src/main/java/org/elasticsearch/index/shard/IndexShard.java
index 75472059f60d7..d4bf7ff518320 100644
--- a/server/src/main/java/org/elasticsearch/index/shard/IndexShard.java
+++ b/server/src/main/java/org/elasticsearch/index/shard/IndexShard.java
@@ -3975,11 +3975,13 @@ && isSearchIdle()
                     return;
                 } else {
                     logger.trace("scheduledRefresh: refresh with source [schedule]");
+                    logger.info("--> scheduledRefresh: refresh with source [schedule]");
                     engine.maybeRefresh("schedule", l.map(Engine.RefreshResult::refreshed));
                     return;
                 }
             }
             logger.trace("scheduledRefresh: no refresh needed");
+            logger.info("--> scheduledRefresh: no refresh needed");
             engine.maybePruneDeletes(); // try to prune the deletes in the engine if we accumulated some
             l.onResponse(false);
         });