diff --git a/docs/changelog/88257.yaml b/docs/changelog/88257.yaml new file mode 100644 index 0000000000000..feb5df85feafb --- /dev/null +++ b/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 diff --git a/server/src/internalClusterTest/java/org/elasticsearch/cluster/ClusterStateDiffIT.java b/server/src/internalClusterTest/java/org/elasticsearch/cluster/ClusterStateDiffIT.java index 5b995482f6fa7..b669cbf11bffc 100644 --- a/server/src/internalClusterTest/java/org/elasticsearch/cluster/ClusterStateDiffIT.java +++ b/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() ) diff --git a/server/src/internalClusterTest/java/org/elasticsearch/snapshots/RestoreSnapshotIT.java b/server/src/internalClusterTest/java/org/elasticsearch/snapshots/RestoreSnapshotIT.java index c9c0c4a6cd60c..23c43a16308bd 100644 --- a/server/src/internalClusterTest/java/org/elasticsearch/snapshots/RestoreSnapshotIT.java +++ b/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()); diff --git a/server/src/main/java/org/elasticsearch/action/admin/cluster/snapshots/restore/RestoreSnapshotRequest.java b/server/src/main/java/org/elasticsearch/action/admin/cluster/snapshots/restore/RestoreSnapshotRequest.java index 8eb5f6d48ecc2..c383b2d610e5f 100644 --- a/server/src/main/java/org/elasticsearch/action/admin/cluster/snapshots/restore/RestoreSnapshotRequest.java +++ b/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 indices, Map shards) { + public record Entry( + String uuid, + Snapshot snapshot, + State state, + boolean quiet, + List indices, + Map 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 indices, Map shards) { + public Entry( + String uuid, + Snapshot snapshot, + State state, + boolean quiet, + List indices, + Map 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 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); }); diff --git a/server/src/main/java/org/elasticsearch/snapshots/RestoreService.java b/server/src/main/java/org/elasticsearch/snapshots/RestoreService.java index 6a2f49f99a2d7..512fe1766133f 100644 --- a/server/src/main/java/org/elasticsearch/snapshots/RestoreService.java +++ b/server/src/main/java/org/elasticsearch/snapshots/RestoreService.java @@ -238,7 +238,6 @@ public void restoreSnapshot( final BiConsumer updater ) { try { - // Try and fill in any missing repository UUIDs in case they're needed during the restore final StepListener 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 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)); } } diff --git a/server/src/test/java/org/elasticsearch/action/admin/cluster/snapshots/restore/RestoreSnapshotRequestTests.java b/server/src/test/java/org/elasticsearch/action/admin/cluster/snapshots/restore/RestoreSnapshotRequestTests.java index ae730ed4d4a64..922e7e03c7600 100644 --- a/server/src/test/java/org/elasticsearch/action/admin/cluster/snapshots/restore/RestoreSnapshotRequestTests.java +++ b/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 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()); diff --git a/server/src/test/java/org/elasticsearch/cluster/metadata/MetadataIndexStateServiceTests.java b/server/src/test/java/org/elasticsearch/cluster/metadata/MetadataIndexStateServiceTests.java index 43cad5e994326..21f41912e9514 100644 --- a/server/src/test/java/org/elasticsearch/cluster/metadata/MetadataIndexStateServiceTests.java +++ b/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 ); diff --git a/server/src/test/java/org/elasticsearch/cluster/routing/allocation/ThrottlingAllocationTests.java b/server/src/test/java/org/elasticsearch/cluster/routing/allocation/ThrottlingAllocationTests.java index e616b81bebc8e..4077c878d3c4e 100644 --- a/server/src/test/java/org/elasticsearch/cluster/routing/allocation/ThrottlingAllocationTests.java +++ b/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 ); diff --git a/server/src/test/java/org/elasticsearch/cluster/routing/allocation/decider/DiskThresholdDeciderTests.java b/server/src/test/java/org/elasticsearch/cluster/routing/allocation/decider/DiskThresholdDeciderTests.java index 582521729fdea..8793f6f9c63e5 100644 --- a/server/src/test/java/org/elasticsearch/cluster/routing/allocation/decider/DiskThresholdDeciderTests.java +++ b/server/src/test/java/org/elasticsearch/cluster/routing/allocation/decider/DiskThresholdDeciderTests.java @@ -1212,7 +1212,7 @@ public void testDiskThresholdWithSnapshotShardSizes() { Map 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())) diff --git a/server/src/test/java/org/elasticsearch/cluster/routing/allocation/decider/RestoreInProgressAllocationDeciderTests.java b/server/src/test/java/org/elasticsearch/cluster/routing/allocation/decider/RestoreInProgressAllocationDeciderTests.java index 6fda78125b8ed..2562d367cb6f1 100644 --- a/server/src/test/java/org/elasticsearch/cluster/routing/allocation/decider/RestoreInProgressAllocationDeciderTests.java +++ b/server/src/test/java/org/elasticsearch/cluster/routing/allocation/decider/RestoreInProgressAllocationDeciderTests.java @@ -150,6 +150,7 @@ public void testCanAllocatePrimaryExistingInRestoreInProgress() { recoverySource.restoreUUID(), snapshot, restoreState, + false, singletonList("test"), shards ); diff --git a/server/src/test/java/org/elasticsearch/cluster/serialization/ClusterSerializationTests.java b/server/src/test/java/org/elasticsearch/cluster/serialization/ClusterSerializationTests.java index 1bffc1931d840..f57627649706d 100644 --- a/server/src/test/java/org/elasticsearch/cluster/serialization/ClusterSerializationTests.java +++ b/server/src/test/java/org/elasticsearch/cluster/serialization/ClusterSerializationTests.java @@ -137,6 +137,7 @@ public void testSnapshotDeletionsInProgressSerialization() throws Exception { UUIDs.randomBase64UUID(), new Snapshot("repo2", new SnapshotId("snap2", UUIDs.randomBase64UUID())), RestoreInProgress.State.STARTED, + false, Collections.singletonList("index_name"), Map.of() ) diff --git a/server/src/test/java/org/elasticsearch/snapshots/InternalSnapshotsInfoServiceTests.java b/server/src/test/java/org/elasticsearch/snapshots/InternalSnapshotsInfoServiceTests.java index 45d9f37bd054b..72fb1f17a4b1e 100644 --- a/server/src/test/java/org/elasticsearch/snapshots/InternalSnapshotsInfoServiceTests.java +++ b/server/src/test/java/org/elasticsearch/snapshots/InternalSnapshotsInfoServiceTests.java @@ -451,6 +451,7 @@ private ClusterState addUnassignedShards(final ClusterState currentState, String recoverySource.restoreUUID(), recoverySource.snapshot(), RestoreInProgress.State.INIT, + false, Collections.singletonList(indexName), shards ) diff --git a/x-pack/plugin/ccr/src/internalClusterTest/java/org/elasticsearch/xpack/ccr/CcrRepositoryIT.java b/x-pack/plugin/ccr/src/internalClusterTest/java/org/elasticsearch/xpack/ccr/CcrRepositoryIT.java index 55e0e5a614962..65192908c28ed 100644 --- a/x-pack/plugin/ccr/src/internalClusterTest/java/org/elasticsearch/xpack/ccr/CcrRepositoryIT.java +++ b/x-pack/plugin/ccr/src/internalClusterTest/java/org/elasticsearch/xpack/ccr/CcrRepositoryIT.java @@ -158,7 +158,8 @@ public void testThatRepositoryRecoversEmptyIndexBasedOnLeaderSettings() throws I .renamePattern("^(.*)$") .renameReplacement(followerIndex) .masterNodeTimeout(TimeValue.MAX_VALUE) - .indexSettings(settingsBuilder); + .indexSettings(settingsBuilder) + .quiet(true); PlainActionFuture future = PlainActionFuture.newFuture(); restoreService.restoreSnapshot(restoreRequest, waitForRestore(clusterService, future)); @@ -230,7 +231,8 @@ public void testDocsAreRecovered() throws Exception { .renamePattern("^(.*)$") .renameReplacement(followerIndex) .masterNodeTimeout(new TimeValue(1L, TimeUnit.HOURS)) - .indexSettings(settingsBuilder); + .indexSettings(settingsBuilder) + .quiet(true); PlainActionFuture future = PlainActionFuture.newFuture(); restoreService.restoreSnapshot(restoreRequest, waitForRestore(clusterService, future)); @@ -298,7 +300,8 @@ public void testRateLimitingIsEmployed() throws Exception { .renamePattern("^(.*)$") .renameReplacement(followerIndex) .masterNodeTimeout(TimeValue.MAX_VALUE) - .indexSettings(settingsBuilder); + .indexSettings(settingsBuilder) + .quiet(true); PlainActionFuture future = PlainActionFuture.newFuture(); restoreService.restoreSnapshot(restoreRequest, waitForRestore(clusterService, future)); @@ -364,7 +367,8 @@ public void testIndividualActionsTimeout() throws Exception { .renamePattern("^(.*)$") .renameReplacement(followerIndex) .masterNodeTimeout(new TimeValue(1L, TimeUnit.HOURS)) - .indexSettings(settingsBuilder); + .indexSettings(settingsBuilder) + .quiet(true); try { final RestoreService restoreService = getFollowerCluster().getCurrentMasterNodeInstance(RestoreService.class); @@ -427,7 +431,8 @@ public void testFollowerMappingIsUpdated() throws IOException { .renamePattern("^(.*)$") .renameReplacement(followerIndex) .masterNodeTimeout(new TimeValue(1L, TimeUnit.HOURS)) - .indexSettings(settingsBuilder); + .indexSettings(settingsBuilder) + .quiet(true); List transportServices = new ArrayList<>(); CountDownLatch latch = new CountDownLatch(1); @@ -586,7 +591,8 @@ public void testCcrRepositoryFetchesSnapshotShardSizeFromIndexShardStoreStats() Settings.builder() .put(IndexMetadata.SETTING_INDEX_PROVIDED_NAME, followerIndex) .put(CcrSettings.CCR_FOLLOWING_INDEX_SETTING.getKey(), true) - ); + ) + .quiet(true); restoreService.restoreSnapshot(restoreRequest, PlainActionFuture.newFuture()); waitForRestoreInProgress.get(30L, TimeUnit.SECONDS); diff --git a/x-pack/plugin/ccr/src/internalClusterTest/java/org/elasticsearch/xpack/ccr/CcrRetentionLeaseIT.java b/x-pack/plugin/ccr/src/internalClusterTest/java/org/elasticsearch/xpack/ccr/CcrRetentionLeaseIT.java index a3cd5750f0d39..8d8fc8120c36b 100644 --- a/x-pack/plugin/ccr/src/internalClusterTest/java/org/elasticsearch/xpack/ccr/CcrRetentionLeaseIT.java +++ b/x-pack/plugin/ccr/src/internalClusterTest/java/org/elasticsearch/xpack/ccr/CcrRetentionLeaseIT.java @@ -157,7 +157,8 @@ private RestoreSnapshotRequest setUpRestoreSnapshotRequest( .indicesOptions(indicesOptions) .renamePattern("^(.*)$") .renameReplacement(followerIndex) - .masterNodeTimeout(TimeValue.MAX_VALUE); + .masterNodeTimeout(TimeValue.MAX_VALUE) + .quiet(true); } public void testRetentionLeaseIsTakenAtTheStartOfRecovery() throws Exception { diff --git a/x-pack/plugin/ccr/src/main/java/org/elasticsearch/xpack/ccr/action/TransportPutFollowAction.java b/x-pack/plugin/ccr/src/main/java/org/elasticsearch/xpack/ccr/action/TransportPutFollowAction.java index a22ac0abc9e03..88301c49c2101 100644 --- a/x-pack/plugin/ccr/src/main/java/org/elasticsearch/xpack/ccr/action/TransportPutFollowAction.java +++ b/x-pack/plugin/ccr/src/main/java/org/elasticsearch/xpack/ccr/action/TransportPutFollowAction.java @@ -194,7 +194,8 @@ private void createFollowerIndex( .renamePattern("^(.*)$") .renameReplacement(request.getFollowerIndex()) .masterNodeTimeout(request.masterNodeTimeout()) - .indexSettings(overrideSettings); + .indexSettings(overrideSettings) + .quiet(true); final Client clientWithHeaders = CcrLicenseChecker.wrapClient( this.client, diff --git a/x-pack/plugin/searchable-snapshots/src/main/java/org/elasticsearch/xpack/searchablesnapshots/action/TransportMountSearchableSnapshotAction.java b/x-pack/plugin/searchable-snapshots/src/main/java/org/elasticsearch/xpack/searchablesnapshots/action/TransportMountSearchableSnapshotAction.java index 1b8bf8c991efc..ae476d6f8539c 100644 --- a/x-pack/plugin/searchable-snapshots/src/main/java/org/elasticsearch/xpack/searchablesnapshots/action/TransportMountSearchableSnapshotAction.java +++ b/x-pack/plugin/searchable-snapshots/src/main/java/org/elasticsearch/xpack/searchablesnapshots/action/TransportMountSearchableSnapshotAction.java @@ -272,7 +272,9 @@ protected void masterOperation( // Pass through the master-node timeout .masterNodeTimeout(request.masterNodeTimeout()) // Fail the restore if the snapshot found above is swapped out from under us before the restore happens - .snapshotUuid(snapshotId.getUUID()), + .snapshotUuid(snapshotId.getUUID()) + // Log snapshot restore at the DEBUG log level + .quiet(true), listener ); }, listener::onFailure), threadPool.executor(ThreadPool.Names.SNAPSHOT_META), null);