INFO logging of snapshot restore and completion (#88257)

But DEBUG (silent) logging of snapshot restore/completion when
done in the context of CCR or searchable snapshots.

Author: kingherc

docs/changelog/88257.yaml

@@ -0,0 +1,6 @@
+pr: 88257
+summary: INFO logging of snapshot restore and completion
+area: Snapshot/Restore
+type: enhancement
+issues:
+ - 86610

server/src/internalClusterTest/java/org/elasticsearch/cluster/ClusterStateDiffIT.java

@@ -727,6 +727,7 @@ public ClusterState.Custom randomCreate(String name) {
                             UUIDs.randomBase64UUID(),
                             new Snapshot(randomName("repo"), new SnapshotId(randomName("snap"), UUIDs.randomBase64UUID())),
                             RestoreInProgress.State.fromValue((byte) randomIntBetween(0, 3)),
+                            randomBoolean(),
                             emptyList(),
                             ImmutableOpenMap.of()
                         )

server/src/internalClusterTest/java/org/elasticsearch/snapshots/RestoreSnapshotIT.java

@@ -31,6 +31,7 @@
 import org.elasticsearch.repositories.fs.FsRepository;
 import org.elasticsearch.rest.RestStatus;
 import org.elasticsearch.test.MockLogAppender;
+import org.elasticsearch.test.junit.annotations.TestLogging;
 import org.elasticsearch.xcontent.XContentFactory;
 
 import java.nio.file.Path;
@@ -158,6 +159,67 @@ public void testParallelRestoreOperationsFromSingleSnapshot() throws Exception {
         assertThat(client.prepareGet(restoredIndexName2, sameSourceIndex ? docId : docId2).get().isExists(), equalTo(true));
     }
 
+    @TestLogging(
+        reason = "testing the logging of the start and completion of a snapshot restore",
+        value = "org.elasticsearch.snapshots.RestoreService:INFO"
+    )
+    public void testRestoreLogging() throws IllegalAccessException {
+        final MockLogAppender mockLogAppender = new MockLogAppender();
+        try {
+            String indexName = "testindex";
+            String repoName = "test-restore-snapshot-repo";
+            String snapshotName = "test-restore-snapshot";
+            Path absolutePath = randomRepoPath().toAbsolutePath();
+            logger.info("Path [{}]", absolutePath);
+            String restoredIndexName = indexName + "-restored";
+            String expectedValue = "expected";
+
+            mockLogAppender.start();
+            Loggers.addAppender(LogManager.getLogger(RestoreService.class), mockLogAppender);
+
+            mockLogAppender.addExpectation(
+                new MockLogAppender.PatternSeenEventExpectation(
+                    "not seen start of snapshot restore",
+                    "org.elasticsearch.snapshots.RestoreService",
+                    Level.INFO,
+                    "started restore of snapshot \\[.*" + snapshotName + ".*\\] for indices \\[.*" + indexName + ".*\\]"
+                )
+            );
+
+            mockLogAppender.addExpectation(
+                new MockLogAppender.PatternSeenEventExpectation(
+                    "not seen completion of snapshot restore",
+                    "org.elasticsearch.snapshots.RestoreService",
+                    Level.INFO,
+                    "completed restore of snapshot \\[.*" + snapshotName + ".*\\]"
+                )
+            );
+
+            Client client = client();
+            // Write a document
+            String docId = Integer.toString(randomInt());
+            indexDoc(indexName, docId, "value", expectedValue);
+            createRepository(repoName, "fs", absolutePath);
+            createSnapshot(repoName, snapshotName, Collections.singletonList(indexName));
+
+            RestoreSnapshotResponse restoreSnapshotResponse = client.admin()
+                .cluster()
+                .prepareRestoreSnapshot(repoName, snapshotName)
+                .setWaitForCompletion(false)
+                .setRenamePattern(indexName)
+                .setRenameReplacement(restoredIndexName)
+                .get();
+
+            assertThat(restoreSnapshotResponse.status(), equalTo(RestStatus.ACCEPTED));
+            ensureGreen(restoredIndexName);
+            assertThat(client.prepareGet(restoredIndexName, docId).get().isExists(), equalTo(true));
+            mockLogAppender.assertAllExpectationsMatched();
+        } finally {
+            Loggers.removeAppender(LogManager.getLogger(RestoreService.class), mockLogAppender);
+            mockLogAppender.stop();
+        }
+    }
+
     public void testRestoreIncreasesPrimaryTerms() {
         final String indexName = randomAlphaOfLengthBetween(5, 10).toLowerCase(Locale.ROOT);
         createIndex(indexName, indexSettingsNoReplicas(2).build());

server/src/main/java/org/elasticsearch/action/admin/cluster/snapshots/restore/RestoreSnapshotRequest.java

@@ -8,6 +8,7 @@
 
 package org.elasticsearch.action.admin.cluster.snapshots.restore;
 
+import org.elasticsearch.Version;
 import org.elasticsearch.action.ActionRequestValidationException;
 import org.elasticsearch.action.support.IndicesOptions;
 import org.elasticsearch.action.support.master.MasterNodeRequest;
@@ -48,6 +49,8 @@ public class RestoreSnapshotRequest extends MasterNodeRequest<RestoreSnapshotReq
     private boolean includeGlobalState = false;
     private boolean partial = false;
     private boolean includeAliases = true;
+    public static Version VERSION_SUPPORTING_QUIET_PARAMETER = Version.V_8_4_0;
+    private boolean quiet = false;
     private Settings indexSettings = Settings.EMPTY;
     private String[] ignoreIndexSettings = Strings.EMPTY_ARRAY;
 
@@ -83,6 +86,11 @@ public RestoreSnapshotRequest(StreamInput in) throws IOException {
         includeGlobalState = in.readBoolean();
         partial = in.readBoolean();
         includeAliases = in.readBoolean();
+        if (in.getVersion().onOrAfter(VERSION_SUPPORTING_QUIET_PARAMETER)) {
+            quiet = in.readBoolean();
+        } else {
+            quiet = true;
+        }
         indexSettings = readSettingsFromStream(in);
         ignoreIndexSettings = in.readStringArray();
         snapshotUuid = in.readOptionalString();
@@ -102,6 +110,9 @@ public void writeTo(StreamOutput out) throws IOException {
         out.writeBoolean(includeGlobalState);
         out.writeBoolean(partial);
         out.writeBoolean(includeAliases);
+        if (out.getVersion().onOrAfter(VERSION_SUPPORTING_QUIET_PARAMETER)) {
+            out.writeBoolean(quiet);
+        }
         writeSettingsToStream(indexSettings, out);
         out.writeStringArray(ignoreIndexSettings);
         out.writeOptionalString(snapshotUuid);
@@ -383,6 +394,27 @@ public boolean includeAliases() {
         return includeAliases;
     }
 
+    /**
+     * If {@code false}, report the start and completion of the restore at {@code INFO} log level.
+     * If {@code true}, report the start and completion of the restore at {@code DEBUG} log level.
+     *
+     * @param quiet
+     * @return this request
+     */
+    public RestoreSnapshotRequest quiet(boolean quiet) {
+        this.quiet = quiet;
+        return this;
+    }
+
+    /**
+     *
+     * @return {@code true}  if logging of the start and completion of the restore should happen at {@code DEBUG} log level, else it
+     * happens at {@code INFO} log level.
+     */
+    public boolean quiet() {
+        return quiet;
+    }
+
     /**
      * Sets settings that should be added/changed in all restored indices
      */
@@ -601,6 +633,7 @@ public boolean equals(Object o) {
             && includeGlobalState == that.includeGlobalState
             && partial == that.partial
             && includeAliases == that.includeAliases
+            && quiet == that.quiet
             && Objects.equals(snapshot, that.snapshot)
             && Objects.equals(repository, that.repository)
             && Arrays.equals(indices, that.indices)
@@ -626,6 +659,7 @@ public int hashCode() {
             includeGlobalState,
             partial,
             includeAliases,
+            quiet,
             indexSettings,
             snapshotUuid,
             skipOperatorOnlyState

server/src/main/java/org/elasticsearch/cluster/RestoreInProgress.java

@@ -9,6 +9,7 @@
 package org.elasticsearch.cluster;
 
 import org.elasticsearch.Version;
+import org.elasticsearch.action.admin.cluster.snapshots.restore.RestoreSnapshotRequest;
 import org.elasticsearch.cluster.ClusterState.Custom;
 import org.elasticsearch.common.io.stream.StreamInput;
 import org.elasticsearch.common.io.stream.StreamOutput;
@@ -104,19 +105,36 @@ public RestoreInProgress build() {
     /**
      * Restore metadata
      */
-    public record Entry(String uuid, Snapshot snapshot, State state, List<String> indices, Map<ShardId, ShardRestoreStatus> shards) {
+    public record Entry(
+        String uuid,
+        Snapshot snapshot,
+        State state,
+        boolean quiet,
+        List<String> indices,
+        Map<ShardId, ShardRestoreStatus> shards
+    ) {
         /**
          * Creates new restore metadata
          *
          * @param uuid     uuid of the restore
          * @param snapshot snapshot
          * @param state    current state of the restore process
+         * @param quiet    {@code true} if logging of the start and completion of the snapshot restore should be at {@code DEBUG} log
+         *                 level, else it should be at {@code INFO} log level
          * @param indices  list of indices being restored
          * @param shards   map of shards being restored to their current restore status
          */
-        public Entry(String uuid, Snapshot snapshot, State state, List<String> indices, Map<ShardId, ShardRestoreStatus> shards) {
+        public Entry(
+            String uuid,
+            Snapshot snapshot,
+            State state,
+            boolean quiet,
+            List<String> indices,
+            Map<ShardId, ShardRestoreStatus> shards
+        ) {
             this.snapshot = Objects.requireNonNull(snapshot);
             this.state = Objects.requireNonNull(state);
+            this.quiet = Objects.requireNonNull(quiet);
             this.indices = Objects.requireNonNull(indices);
             if (shards == null) {
                 this.shards = Map.of();
@@ -342,10 +360,24 @@ public RestoreInProgress(StreamInput in) throws IOException {
             uuid = in.readString();
             Snapshot snapshot = new Snapshot(in);
             State state = State.fromValue(in.readByte());
+            boolean quiet;
+            if (in.getVersion().onOrAfter(RestoreSnapshotRequest.VERSION_SUPPORTING_QUIET_PARAMETER)) {
+                quiet = in.readBoolean();
+            } else {
+                // Backwards compatibility: previously there was no logging of the start or completion of a snapshot restore
+                quiet = true;
+            }
             List<String> indices = in.readImmutableList(StreamInput::readString);
             entriesBuilder.put(
                 uuid,
-                new Entry(uuid, snapshot, state, indices, in.readImmutableMap(ShardId::new, ShardRestoreStatus::readShardRestoreStatus))
+                new Entry(
+                    uuid,
+                    snapshot,
+                    state,
+                    quiet,
+                    indices,
+                    in.readImmutableMap(ShardId::new, ShardRestoreStatus::readShardRestoreStatus)
+                )
             );
         }
         this.entries = Collections.unmodifiableMap(entriesBuilder);
@@ -357,6 +389,9 @@ public void writeTo(StreamOutput out) throws IOException {
             o.writeString(entry.uuid);
             entry.snapshot().writeTo(o);
             o.writeByte(entry.state().value());
+            if (out.getVersion().onOrAfter(RestoreSnapshotRequest.VERSION_SUPPORTING_QUIET_PARAMETER)) {
+                o.writeBoolean(entry.quiet());
+            }
             o.writeStringCollection(entry.indices);
             o.writeMap(entry.shards);
         });

server/src/main/java/org/elasticsearch/snapshots/RestoreService.java

@@ -238,7 +238,6 @@ public void restoreSnapshot(
         final BiConsumer<ClusterState, Metadata.Builder> updater
     ) {
         try {
-
             // Try and fill in any missing repository UUIDs in case they're needed during the restore
             final StepListener<Void> repositoryUuidRefreshListener = new StepListener<>();
             refreshRepositoryUuids(refreshRepositoryUuidOnRestore, repositoriesService, repositoryUuidRefreshListener);
@@ -737,6 +736,7 @@ public static RestoreInProgress updateRestoreStateWithDeletedIndices(RestoreInPr
                         entry.uuid(),
                         entry.snapshot(),
                         overallState(RestoreInProgress.State.STARTED, shards),
+                        entry.quiet(),
                         entry.indices(),
                         shards
                     )
@@ -873,7 +873,9 @@ public RestoreInProgress applyChanges(final RestoreInProgress oldRestore) {
 
                         Map<ShardId, ShardRestoreStatus> shards = Map.copyOf(shardsBuilder);
                         RestoreInProgress.State newState = overallState(RestoreInProgress.State.STARTED, shards);
-                        builder.add(new RestoreInProgress.Entry(entry.uuid(), entry.snapshot(), newState, entry.indices(), shards));
+                        builder.add(
+                            new RestoreInProgress.Entry(entry.uuid(), entry.snapshot(), newState, entry.quiet(), entry.indices(), shards)
+                        );
                     } else {
                         builder.add(entry);
                     }
@@ -1051,6 +1053,7 @@ public ClusterState execute(ClusterState currentState) {
                 boolean changed = false;
                 for (RestoreInProgress.Entry entry : currentState.custom(RestoreInProgress.TYPE, RestoreInProgress.EMPTY)) {
                     if (entry.state().completed()) {
+                        logger.log(entry.quiet() ? Level.DEBUG : Level.INFO, "completed restore of snapshot [{}]", entry.snapshot());
                         changed = true;
                     } else {
                         restoreInProgressBuilder.add(entry);
@@ -1373,6 +1376,7 @@ && isSystemIndex(snapshotIndexMetadata) == false) {
                             restoreUUID,
                             snapshot,
                             overallState(RestoreInProgress.State.INIT, shards),
+                            request.quiet(),
                             List.copyOf(indicesToRestore.keySet()),
                             Map.copyOf(shards)
                         )
@@ -1569,6 +1573,12 @@ public void onFailure(Exception e) {
 
         @Override
         public void clusterStateProcessed(ClusterState oldState, ClusterState newState) {
+            logger.log(
+                request.quiet() ? Level.DEBUG : Level.INFO,
+                "started restore of snapshot [{}] for indices {}",
+                snapshot,
+                snapshotInfo.indices()
+            );
             listener.onResponse(new RestoreCompletionResponse(restoreUUID, snapshot, restoreInfo));
         }
     }

server/src/test/java/org/elasticsearch/action/admin/cluster/snapshots/restore/RestoreSnapshotRequestTests.java

@@ -64,6 +64,7 @@ private RestoreSnapshotRequest randomState(RestoreSnapshotRequest instance) {
         }
         instance.partial(randomBoolean());
         instance.includeAliases(randomBoolean());
+        instance.quiet(randomBoolean());
 
         if (randomBoolean()) {
             Map<String, Object> indexSettings = new HashMap<>();
@@ -127,6 +128,7 @@ protected RestoreSnapshotRequest mutateInstance(RestoreSnapshotRequest instance)
     public void testSource() throws IOException {
         RestoreSnapshotRequest original = createTestInstance();
         original.snapshotUuid(null); // cannot be set via the REST API
+        original.quiet(false); // cannot be set via the REST API
         XContentBuilder builder = original.toXContent(XContentFactory.jsonBuilder(), new ToXContent.MapParams(Collections.emptyMap()));
         XContentParser parser = XContentType.JSON.xContent()
             .createParser(NamedXContentRegistry.EMPTY, null, BytesReference.bytes(builder).streamInput());

server/src/test/java/org/elasticsearch/cluster/metadata/MetadataIndexStateServiceTests.java

@@ -343,6 +343,7 @@ private static ClusterState addRestoredIndex(final String index, final int numSh
             "_uuid",
             snapshot,
             RestoreInProgress.State.INIT,
+            false,
             Collections.singletonList(index),
             shardsBuilder
         );

server/src/test/java/org/elasticsearch/cluster/routing/allocation/ThrottlingAllocationTests.java

@@ -413,6 +413,7 @@ private ClusterState createRecoveryStateAndInitializeAllocations(
                 restoreUUID,
                 snapshot,
                 RestoreInProgress.State.INIT,
+                false,
                 new ArrayList<>(snapshotIndices),
                 restoreShards
             );

server/src/test/java/org/elasticsearch/cluster/routing/allocation/decider/DiskThresholdDeciderTests.java

@@ -1212,7 +1212,7 @@ public void testDiskThresholdWithSnapshotShardSizes() {
         Map<ShardId, RestoreInProgress.ShardRestoreStatus> shards = Map.of(shardId, new RestoreInProgress.ShardRestoreStatus("node1"));
 
         final RestoreInProgress.Builder restores = new RestoreInProgress.Builder().add(
-            new RestoreInProgress.Entry("_restore_uuid", snapshot, RestoreInProgress.State.INIT, List.of("test"), shards)
+            new RestoreInProgress.Entry("_restore_uuid", snapshot, RestoreInProgress.State.INIT, false, List.of("test"), shards)
         );
 
         ClusterState clusterState = ClusterState.builder(new ClusterName(getTestName()))