From 866d810f262143a916a6cdf7ddd2cb7f94772521 Mon Sep 17 00:00:00 2001 From: Iraklis Psaroudakis Date: Thu, 30 Jun 2022 15:06:16 +0300 Subject: [PATCH 1/9] INFO logging of snapshot restore and completion But DEBUG (silent) logging of snapshot restore/completion when done in the context of CCR or searchable snapshots. Fixes #86610 --- .../apis/restore-snapshot-api.asciidoc | 4 +++ .../cluster/ClusterStateDiffIT.java | 1 + .../restore/RestoreSnapshotRequest.java | 28 ++++++++++++++++ .../RestoreSnapshotRequestBuilder.java | 11 +++++++ .../cluster/RestoreInProgress.java | 32 +++++++++++++++++-- .../snapshots/RestoreService.java | 14 ++++++-- .../restore/RestoreSnapshotRequestTests.java | 1 + .../MetadataIndexStateServiceTests.java | 1 + .../allocation/ThrottlingAllocationTests.java | 1 + .../decider/DiskThresholdDeciderTests.java | 2 +- ...storeInProgressAllocationDeciderTests.java | 1 + .../ClusterSerializationTests.java | 1 + .../InternalSnapshotsInfoServiceTests.java | 1 + .../xpack/ccr/CcrRepositoryIT.java | 18 +++++++---- .../xpack/ccr/CcrRetentionLeaseIT.java | 3 +- .../ccr/action/TransportPutFollowAction.java | 3 +- ...ransportMountSearchableSnapshotAction.java | 4 ++- 17 files changed, 111 insertions(+), 15 deletions(-) diff --git a/docs/reference/snapshot-restore/apis/restore-snapshot-api.asciidoc b/docs/reference/snapshot-restore/apis/restore-snapshot-api.asciidoc index 5c1b38e779880..7224e1983687b 100644 --- a/docs/reference/snapshot-restore/apis/restore-snapshot-api.asciidoc +++ b/docs/reference/snapshot-restore/apis/restore-snapshot-api.asciidoc @@ -144,6 +144,10 @@ backing indices are configured using the data stream's matching index template. If `true`, the request restores aliases for any restored data streams and indices. If `false`, the request doesn't restore aliases. Defaults to `true`. +`silent`:: +(Optional, Boolean) +If `true`, logging happens at a lower level. Defaults to `false`. + [[restore-snapshot-api-include-global-state]] `include_global_state`:: + 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/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..baa5d569a03bd 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 @@ -48,6 +48,7 @@ public class RestoreSnapshotRequest extends MasterNodeRequest source) { includeGlobalState = nodeBooleanValue(entry.getValue(), "include_global_state"); } else if (name.equals("include_aliases")) { includeAliases = nodeBooleanValue(entry.getValue(), "include_aliases"); + } else if (name.equals("silent")) { + silent = nodeBooleanValue(entry.getValue(), "silent"); } else if (name.equals("rename_pattern")) { if (entry.getValue() instanceof String) { renamePattern((String) entry.getValue()); @@ -573,6 +598,7 @@ private void toXContentFragment(XContentBuilder builder, Params params) throws I builder.field("include_global_state", includeGlobalState); builder.field("partial", partial); builder.field("include_aliases", includeAliases); + builder.field("silent", silent); if (indexSettings != null) { builder.startObject("index_settings"); if (indexSettings.isEmpty() == false) { @@ -601,6 +627,7 @@ public boolean equals(Object o) { && includeGlobalState == that.includeGlobalState && partial == that.partial && includeAliases == that.includeAliases + && silent == that.silent && Objects.equals(snapshot, that.snapshot) && Objects.equals(repository, that.repository) && Arrays.equals(indices, that.indices) @@ -626,6 +653,7 @@ public int hashCode() { includeGlobalState, partial, includeAliases, + silent, indexSettings, snapshotUuid, skipOperatorOnlyState diff --git a/server/src/main/java/org/elasticsearch/action/admin/cluster/snapshots/restore/RestoreSnapshotRequestBuilder.java b/server/src/main/java/org/elasticsearch/action/admin/cluster/snapshots/restore/RestoreSnapshotRequestBuilder.java index 04e67a86e4a7a..938c2040059a3 100644 --- a/server/src/main/java/org/elasticsearch/action/admin/cluster/snapshots/restore/RestoreSnapshotRequestBuilder.java +++ b/server/src/main/java/org/elasticsearch/action/admin/cluster/snapshots/restore/RestoreSnapshotRequestBuilder.java @@ -162,6 +162,17 @@ public RestoreSnapshotRequestBuilder setIncludeAliases(boolean restoreAliases) { return this; } + /** + * If set to true the logging should be at a lower level + * + * @param silent true if logging should be at a lower level + * @return this builder + */ + public RestoreSnapshotRequestBuilder setSilent(boolean silent) { + request.silent(silent); + return this; + } + /** * Sets index settings that should be added or replaced during restore * diff --git a/server/src/main/java/org/elasticsearch/cluster/RestoreInProgress.java b/server/src/main/java/org/elasticsearch/cluster/RestoreInProgress.java index df34d0babf9d8..316880a5e1f9c 100644 --- a/server/src/main/java/org/elasticsearch/cluster/RestoreInProgress.java +++ b/server/src/main/java/org/elasticsearch/cluster/RestoreInProgress.java @@ -104,19 +104,35 @@ public RestoreInProgress build() { /** * Restore metadata */ - public record Entry(String uuid, Snapshot snapshot, State state, List indices, Map shards) { + public record Entry( + String uuid, + Snapshot snapshot, + State state, + boolean silent, + 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 silent boolean for whether logging should be at a lower or higher 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 silent, + List indices, + Map shards + ) { this.snapshot = Objects.requireNonNull(snapshot); this.state = Objects.requireNonNull(state); + this.silent = Objects.requireNonNull(silent); this.indices = Objects.requireNonNull(indices); if (shards == null) { this.shards = Map.of(); @@ -342,10 +358,18 @@ public RestoreInProgress(StreamInput in) throws IOException { uuid = in.readString(); Snapshot snapshot = new Snapshot(in); State state = State.fromValue(in.readByte()); + boolean silent = in.readBoolean(); 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, + silent, + indices, + in.readImmutableMap(ShardId::new, ShardRestoreStatus::readShardRestoreStatus) + ) ); } this.entries = Collections.unmodifiableMap(entriesBuilder); @@ -357,6 +381,7 @@ public void writeTo(StreamOutput out) throws IOException { o.writeString(entry.uuid); entry.snapshot().writeTo(o); o.writeByte(entry.state().value()); + o.writeBoolean(entry.silent()); o.writeStringCollection(entry.indices); o.writeMap(entry.shards); }); @@ -383,6 +408,7 @@ public static void toXContent(Entry entry, XContentBuilder builder) throws IOExc builder.field("snapshot", entry.snapshot().getSnapshotId().getName()); builder.field("repository", entry.snapshot().getRepository()); builder.field("state", entry.state()); + builder.field("silent", entry.silent()); builder.startArray("indices"); { for (String index : entry.indices()) { diff --git a/server/src/main/java/org/elasticsearch/snapshots/RestoreService.java b/server/src/main/java/org/elasticsearch/snapshots/RestoreService.java index c1307e8706833..b8b2afe46d51f 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.silent(), 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.silent(), 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.silent() ? Level.DEBUG : Level.INFO, "restore of snapshot [{}] completed", entry.snapshot()); changed = true; } else { restoreInProgressBuilder.add(entry); @@ -1373,6 +1376,7 @@ && isSystemIndex(snapshotIndexMetadata) == false) { restoreUUID, snapshot, overallState(RestoreInProgress.State.INIT, shards), + request.silent(), 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.silent() ? Level.DEBUG : Level.INFO, + "restore of snapshot [{}] started 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..2c18a695cf524 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.silent(randomBoolean()); if (randomBoolean()) { Map indexSettings = new HashMap<>(); 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 08b876165ff7b..447999a928f84 100644 --- a/server/src/test/java/org/elasticsearch/cluster/metadata/MetadataIndexStateServiceTests.java +++ b/server/src/test/java/org/elasticsearch/cluster/metadata/MetadataIndexStateServiceTests.java @@ -344,6 +344,7 @@ private static ClusterState addRestoredIndex(final String index, final int numSh "_uuid", snapshot, RestoreInProgress.State.INIT, + false, Collections.singletonList(index), shardsBuilder.build() ); 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 840881bb7a7dd..d5d7d72c84b10 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 @@ -414,6 +414,7 @@ private ClusterState createRecoveryStateAndInitializeAllocations( restoreUUID, snapshot, RestoreInProgress.State.INIT, + false, new ArrayList<>(snapshotIndices), restoreShards.build() ); 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 ad28fcb6c5c7f..a29814cda1d01 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 @@ -1199,7 +1199,7 @@ public void testDiskThresholdWithSnapshotShardSizes() { shards.put(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.build()) + new RestoreInProgress.Entry("_restore_uuid", snapshot, RestoreInProgress.State.INIT, false, List.of("test"), shards.build()) ); 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 30d1823808dc8..50de9d06dd448 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 @@ -148,6 +148,7 @@ public void testCanAllocatePrimaryExistingInRestoreInProgress() { recoverySource.restoreUUID(), snapshot, restoreState, + false, singletonList("test"), shards.build() ); 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 9471da8aae0bb..c1b4ef480dc16 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"), ImmutableOpenMap.of() ) diff --git a/server/src/test/java/org/elasticsearch/snapshots/InternalSnapshotsInfoServiceTests.java b/server/src/test/java/org/elasticsearch/snapshots/InternalSnapshotsInfoServiceTests.java index 34683440a6762..66eb205a94d6f 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.build() ) 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..13808b787b79d 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) + .silent(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) + .silent(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) + .silent(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) + .silent(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) + .silent(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) - ); + ) + .silent(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..aa992bdb0c85b 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) + .silent(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..bfb11004c825a 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) + .silent(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..a25d3910ff61e 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 a lower level + .silent(true), listener ); }, listener::onFailure), threadPool.executor(ThreadPool.Names.SNAPSHOT_META), null); From 77f27be047df6d4c79e883e59ce76666cb76fea2 Mon Sep 17 00:00:00 2001 From: Iraklis Psaroudakis Date: Mon, 4 Jul 2022 18:55:06 +0300 Subject: [PATCH 2/9] Update docs/changelog/88257.yaml --- docs/changelog/88257.yaml | 6 ++++++ 1 file changed, 6 insertions(+) create mode 100644 docs/changelog/88257.yaml 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 From 2836e5dbeb944f81e714423d841944950abb22e6 Mon Sep 17 00:00:00 2001 From: Iraklis Psaroudakis Date: Tue, 5 Jul 2022 12:53:46 +0300 Subject: [PATCH 3/9] Do not expose in XContext and fix backwards compat --- .../apis/restore-snapshot-api.asciidoc | 4 ---- .../snapshots/restore/RestoreSnapshotRequest.java | 15 ++++++++++----- 2 files changed, 10 insertions(+), 9 deletions(-) diff --git a/docs/reference/snapshot-restore/apis/restore-snapshot-api.asciidoc b/docs/reference/snapshot-restore/apis/restore-snapshot-api.asciidoc index 7224e1983687b..5c1b38e779880 100644 --- a/docs/reference/snapshot-restore/apis/restore-snapshot-api.asciidoc +++ b/docs/reference/snapshot-restore/apis/restore-snapshot-api.asciidoc @@ -144,10 +144,6 @@ backing indices are configured using the data stream's matching index template. If `true`, the request restores aliases for any restored data streams and indices. If `false`, the request doesn't restore aliases. Defaults to `true`. -`silent`:: -(Optional, Boolean) -If `true`, logging happens at a lower level. Defaults to `false`. - [[restore-snapshot-api-include-global-state]] `include_global_state`:: + 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 baa5d569a03bd..ed39505acf121 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,7 @@ public class RestoreSnapshotRequest extends MasterNodeRequest source) { includeGlobalState = nodeBooleanValue(entry.getValue(), "include_global_state"); } else if (name.equals("include_aliases")) { includeAliases = nodeBooleanValue(entry.getValue(), "include_aliases"); - } else if (name.equals("silent")) { - silent = nodeBooleanValue(entry.getValue(), "silent"); } else if (name.equals("rename_pattern")) { if (entry.getValue() instanceof String) { renamePattern((String) entry.getValue()); @@ -598,7 +604,6 @@ private void toXContentFragment(XContentBuilder builder, Params params) throws I builder.field("include_global_state", includeGlobalState); builder.field("partial", partial); builder.field("include_aliases", includeAliases); - builder.field("silent", silent); if (indexSettings != null) { builder.startObject("index_settings"); if (indexSettings.isEmpty() == false) { From 13eb54a84a3576ac0d7a4f26fe35ae2240469eed Mon Sep 17 00:00:00 2001 From: Iraklis Psaroudakis Date: Tue, 5 Jul 2022 13:20:06 +0300 Subject: [PATCH 4/9] Also the same for RestoreInProgress.Entry --- .../org/elasticsearch/cluster/RestoreInProgress.java | 11 ++++++++--- 1 file changed, 8 insertions(+), 3 deletions(-) diff --git a/server/src/main/java/org/elasticsearch/cluster/RestoreInProgress.java b/server/src/main/java/org/elasticsearch/cluster/RestoreInProgress.java index 316880a5e1f9c..5df13b4aaa920 100644 --- a/server/src/main/java/org/elasticsearch/cluster/RestoreInProgress.java +++ b/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; @@ -358,7 +359,10 @@ public RestoreInProgress(StreamInput in) throws IOException { uuid = in.readString(); Snapshot snapshot = new Snapshot(in); State state = State.fromValue(in.readByte()); - boolean silent = in.readBoolean(); + boolean silent = true; + if (in.getVersion().onOrAfter(RestoreSnapshotRequest.VERSION_SUPPORTING_SILENT_PARAMETER)) { + silent = in.readBoolean(); + } List indices = in.readImmutableList(StreamInput::readString); entriesBuilder.put( uuid, @@ -381,7 +385,9 @@ public void writeTo(StreamOutput out) throws IOException { o.writeString(entry.uuid); entry.snapshot().writeTo(o); o.writeByte(entry.state().value()); - o.writeBoolean(entry.silent()); + if (out.getVersion().onOrAfter(RestoreSnapshotRequest.VERSION_SUPPORTING_SILENT_PARAMETER)) { + o.writeBoolean(entry.silent()); + } o.writeStringCollection(entry.indices); o.writeMap(entry.shards); }); @@ -408,7 +414,6 @@ public static void toXContent(Entry entry, XContentBuilder builder) throws IOExc builder.field("snapshot", entry.snapshot().getSnapshotId().getName()); builder.field("repository", entry.snapshot().getRepository()); builder.field("state", entry.state()); - builder.field("silent", entry.silent()); builder.startArray("indices"); { for (String index : entry.indices()) { From 2144beb084ffabe430752af209503895021fb13f Mon Sep 17 00:00:00 2001 From: Iraklis Psaroudakis Date: Tue, 5 Jul 2022 15:54:05 +0300 Subject: [PATCH 5/9] Fix a test --- .../cluster/snapshots/restore/RestoreSnapshotRequestTests.java | 1 + 1 file changed, 1 insertion(+) 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 2c18a695cf524..2f7e9339443b6 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 @@ -128,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.silent(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()); From dccb19954780d3e3a808a29c5ef112723ad10c56 Mon Sep 17 00:00:00 2001 From: Iraklis Psaroudakis Date: Wed, 6 Jul 2022 17:57:08 +0300 Subject: [PATCH 6/9] Incorporate reviewer feedback --- .../restore/RestoreSnapshotRequest.java | 35 ++++++++++--------- .../RestoreSnapshotRequestBuilder.java | 11 ------ .../cluster/RestoreInProgress.java | 24 +++++++------ .../snapshots/RestoreService.java | 10 +++--- .../restore/RestoreSnapshotRequestTests.java | 4 +-- .../xpack/ccr/CcrRepositoryIT.java | 12 +++---- .../xpack/ccr/CcrRetentionLeaseIT.java | 2 +- .../ccr/action/TransportPutFollowAction.java | 2 +- ...ransportMountSearchableSnapshotAction.java | 4 +-- 9 files changed, 49 insertions(+), 55 deletions(-) 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 ed39505acf121..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 @@ -49,8 +49,8 @@ public class RestoreSnapshotRequest extends MasterNodeRequest indices, Map shards ) { @@ -119,7 +119,8 @@ public record Entry( * @param uuid uuid of the restore * @param snapshot snapshot * @param state current state of the restore process - * @param silent boolean for whether logging should be at a lower or higher level + * @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 */ @@ -127,13 +128,13 @@ public Entry( String uuid, Snapshot snapshot, State state, - boolean silent, + boolean quiet, List indices, Map shards ) { this.snapshot = Objects.requireNonNull(snapshot); this.state = Objects.requireNonNull(state); - this.silent = Objects.requireNonNull(silent); + this.quiet = Objects.requireNonNull(quiet); this.indices = Objects.requireNonNull(indices); if (shards == null) { this.shards = Map.of(); @@ -359,9 +360,12 @@ public RestoreInProgress(StreamInput in) throws IOException { uuid = in.readString(); Snapshot snapshot = new Snapshot(in); State state = State.fromValue(in.readByte()); - boolean silent = true; - if (in.getVersion().onOrAfter(RestoreSnapshotRequest.VERSION_SUPPORTING_SILENT_PARAMETER)) { - silent = in.readBoolean(); + 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( @@ -370,7 +374,7 @@ public RestoreInProgress(StreamInput in) throws IOException { uuid, snapshot, state, - silent, + quiet, indices, in.readImmutableMap(ShardId::new, ShardRestoreStatus::readShardRestoreStatus) ) @@ -385,8 +389,8 @@ 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_SILENT_PARAMETER)) { - o.writeBoolean(entry.silent()); + 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 b8b2afe46d51f..ff76b6f20a53d 100644 --- a/server/src/main/java/org/elasticsearch/snapshots/RestoreService.java +++ b/server/src/main/java/org/elasticsearch/snapshots/RestoreService.java @@ -736,7 +736,7 @@ public static RestoreInProgress updateRestoreStateWithDeletedIndices(RestoreInPr entry.uuid(), entry.snapshot(), overallState(RestoreInProgress.State.STARTED, shards), - entry.silent(), + entry.quiet(), entry.indices(), shards ) @@ -874,7 +874,7 @@ 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.silent(), entry.indices(), shards) + new RestoreInProgress.Entry(entry.uuid(), entry.snapshot(), newState, entry.quiet(), entry.indices(), shards) ); } else { builder.add(entry); @@ -1053,7 +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.silent() ? Level.DEBUG : Level.INFO, "restore of snapshot [{}] completed", entry.snapshot()); + logger.log(entry.quiet() ? Level.DEBUG : Level.INFO, "restore of snapshot [{}] completed", entry.snapshot()); changed = true; } else { restoreInProgressBuilder.add(entry); @@ -1376,7 +1376,7 @@ && isSystemIndex(snapshotIndexMetadata) == false) { restoreUUID, snapshot, overallState(RestoreInProgress.State.INIT, shards), - request.silent(), + request.quiet(), List.copyOf(indicesToRestore.keySet()), Map.copyOf(shards) ) @@ -1574,7 +1574,7 @@ public void onFailure(Exception e) { @Override public void clusterStateProcessed(ClusterState oldState, ClusterState newState) { logger.log( - request.silent() ? Level.DEBUG : Level.INFO, + request.quiet() ? Level.DEBUG : Level.INFO, "restore of snapshot [{}] started for indices {}", snapshot, snapshotInfo.indices() 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 2f7e9339443b6..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,7 +64,7 @@ private RestoreSnapshotRequest randomState(RestoreSnapshotRequest instance) { } instance.partial(randomBoolean()); instance.includeAliases(randomBoolean()); - instance.silent(randomBoolean()); + instance.quiet(randomBoolean()); if (randomBoolean()) { Map indexSettings = new HashMap<>(); @@ -128,7 +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.silent(false); // 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/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 13808b787b79d..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 @@ -159,7 +159,7 @@ public void testThatRepositoryRecoversEmptyIndexBasedOnLeaderSettings() throws I .renameReplacement(followerIndex) .masterNodeTimeout(TimeValue.MAX_VALUE) .indexSettings(settingsBuilder) - .silent(true); + .quiet(true); PlainActionFuture future = PlainActionFuture.newFuture(); restoreService.restoreSnapshot(restoreRequest, waitForRestore(clusterService, future)); @@ -232,7 +232,7 @@ public void testDocsAreRecovered() throws Exception { .renameReplacement(followerIndex) .masterNodeTimeout(new TimeValue(1L, TimeUnit.HOURS)) .indexSettings(settingsBuilder) - .silent(true); + .quiet(true); PlainActionFuture future = PlainActionFuture.newFuture(); restoreService.restoreSnapshot(restoreRequest, waitForRestore(clusterService, future)); @@ -301,7 +301,7 @@ public void testRateLimitingIsEmployed() throws Exception { .renameReplacement(followerIndex) .masterNodeTimeout(TimeValue.MAX_VALUE) .indexSettings(settingsBuilder) - .silent(true); + .quiet(true); PlainActionFuture future = PlainActionFuture.newFuture(); restoreService.restoreSnapshot(restoreRequest, waitForRestore(clusterService, future)); @@ -368,7 +368,7 @@ public void testIndividualActionsTimeout() throws Exception { .renameReplacement(followerIndex) .masterNodeTimeout(new TimeValue(1L, TimeUnit.HOURS)) .indexSettings(settingsBuilder) - .silent(true); + .quiet(true); try { final RestoreService restoreService = getFollowerCluster().getCurrentMasterNodeInstance(RestoreService.class); @@ -432,7 +432,7 @@ public void testFollowerMappingIsUpdated() throws IOException { .renameReplacement(followerIndex) .masterNodeTimeout(new TimeValue(1L, TimeUnit.HOURS)) .indexSettings(settingsBuilder) - .silent(true); + .quiet(true); List transportServices = new ArrayList<>(); CountDownLatch latch = new CountDownLatch(1); @@ -592,7 +592,7 @@ public void testCcrRepositoryFetchesSnapshotShardSizeFromIndexShardStoreStats() .put(IndexMetadata.SETTING_INDEX_PROVIDED_NAME, followerIndex) .put(CcrSettings.CCR_FOLLOWING_INDEX_SETTING.getKey(), true) ) - .silent(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 aa992bdb0c85b..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 @@ -158,7 +158,7 @@ private RestoreSnapshotRequest setUpRestoreSnapshotRequest( .renamePattern("^(.*)$") .renameReplacement(followerIndex) .masterNodeTimeout(TimeValue.MAX_VALUE) - .silent(true); + .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 bfb11004c825a..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 @@ -195,7 +195,7 @@ private void createFollowerIndex( .renameReplacement(request.getFollowerIndex()) .masterNodeTimeout(request.masterNodeTimeout()) .indexSettings(overrideSettings) - .silent(true); + .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 a25d3910ff61e..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 @@ -273,8 +273,8 @@ protected void masterOperation( .masterNodeTimeout(request.masterNodeTimeout()) // Fail the restore if the snapshot found above is swapped out from under us before the restore happens .snapshotUuid(snapshotId.getUUID()) - // Log snapshot restore at a lower level - .silent(true), + // Log snapshot restore at the DEBUG log level + .quiet(true), listener ); }, listener::onFailure), threadPool.executor(ThreadPool.Names.SNAPSHOT_META), null); From 5bf00fb1b62bf675301ba9b73f7a31d6e9ea1ab6 Mon Sep 17 00:00:00 2001 From: Iraklis Psaroudakis Date: Thu, 7 Jul 2022 13:34:28 +0300 Subject: [PATCH 7/9] Add test for ensuring log of snapshot restore --- .../snapshots/RestoreSnapshotIT.java | 70 +++++++++++++++++++ .../snapshots/RestoreService.java | 4 +- 2 files changed, 72 insertions(+), 2 deletions(-) diff --git a/server/src/internalClusterTest/java/org/elasticsearch/snapshots/RestoreSnapshotIT.java b/server/src/internalClusterTest/java/org/elasticsearch/snapshots/RestoreSnapshotIT.java index c9c0c4a6cd60c..74199bd252d15 100644 --- a/server/src/internalClusterTest/java/org/elasticsearch/snapshots/RestoreSnapshotIT.java +++ b/server/src/internalClusterTest/java/org/elasticsearch/snapshots/RestoreSnapshotIT.java @@ -11,6 +11,7 @@ import org.apache.logging.log4j.Level; import org.apache.logging.log4j.LogManager; import org.apache.logging.log4j.Logger; +import org.apache.logging.log4j.core.LogEvent; import org.elasticsearch.Version; import org.elasticsearch.action.ActionFuture; import org.elasticsearch.action.admin.cluster.snapshots.restore.RestoreSnapshotResponse; @@ -31,6 +32,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; @@ -62,6 +64,7 @@ import static org.hamcrest.Matchers.not; import static org.hamcrest.Matchers.notNullValue; import static org.hamcrest.Matchers.nullValue; +import static org.hamcrest.Matchers.startsWith; public class RestoreSnapshotIT extends AbstractSnapshotIntegTestCase { @@ -158,6 +161,73 @@ 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.LoggingExpectation() { + String startMessageSnapshot; + Object startMessageIndicesList; + String completionMessageSnapshot; + + @Override + public void match(LogEvent event) { + final String message = event.getMessage().getFormattedMessage(); + if (message.startsWith("started restore of snapshot")) { + startMessageSnapshot = event.getMessage().getParameters()[0].toString(); + startMessageIndicesList = event.getMessage().getParameters()[1]; + } else if (message.startsWith("completed restore of snapshot")) { + completionMessageSnapshot = event.getMessage().getParameters()[0].toString(); + } + } + + @Override + public void assertMatched() { + assertThat(startMessageSnapshot, startsWith(snapshotName)); + assertEquals(Arrays.asList(indexName), startMessageIndicesList); + assertThat(completionMessageSnapshot, startsWith(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/snapshots/RestoreService.java b/server/src/main/java/org/elasticsearch/snapshots/RestoreService.java index ff76b6f20a53d..7ae4cca375834 100644 --- a/server/src/main/java/org/elasticsearch/snapshots/RestoreService.java +++ b/server/src/main/java/org/elasticsearch/snapshots/RestoreService.java @@ -1053,7 +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, "restore of snapshot [{}] completed", entry.snapshot()); + logger.log(entry.quiet() ? Level.DEBUG : Level.INFO, "completed restore of snapshot [{}]", entry.snapshot()); changed = true; } else { restoreInProgressBuilder.add(entry); @@ -1575,7 +1575,7 @@ public void onFailure(Exception e) { public void clusterStateProcessed(ClusterState oldState, ClusterState newState) { logger.log( request.quiet() ? Level.DEBUG : Level.INFO, - "restore of snapshot [{}] started for indices {}", + "started restore of snapshot [{}] for indices {}", snapshot, snapshotInfo.indices() ); From 6e3741b83ec860d3ef5ae4eafe81b39a040332bc Mon Sep 17 00:00:00 2001 From: Iraklis Psaroudakis Date: Tue, 12 Jul 2022 15:29:02 +0300 Subject: [PATCH 8/9] Add PatternSeenEventExpectations --- .../snapshots/RestoreSnapshotIT.java | 40 ++++++++----------- 1 file changed, 17 insertions(+), 23 deletions(-) diff --git a/server/src/internalClusterTest/java/org/elasticsearch/snapshots/RestoreSnapshotIT.java b/server/src/internalClusterTest/java/org/elasticsearch/snapshots/RestoreSnapshotIT.java index 74199bd252d15..8a6d32f2d69e8 100644 --- a/server/src/internalClusterTest/java/org/elasticsearch/snapshots/RestoreSnapshotIT.java +++ b/server/src/internalClusterTest/java/org/elasticsearch/snapshots/RestoreSnapshotIT.java @@ -179,29 +179,23 @@ public void testRestoreLogging() throws IllegalAccessException { mockLogAppender.start(); Loggers.addAppender(LogManager.getLogger(RestoreService.class), mockLogAppender); - mockLogAppender.addExpectation(new MockLogAppender.LoggingExpectation() { - String startMessageSnapshot; - Object startMessageIndicesList; - String completionMessageSnapshot; - - @Override - public void match(LogEvent event) { - final String message = event.getMessage().getFormattedMessage(); - if (message.startsWith("started restore of snapshot")) { - startMessageSnapshot = event.getMessage().getParameters()[0].toString(); - startMessageIndicesList = event.getMessage().getParameters()[1]; - } else if (message.startsWith("completed restore of snapshot")) { - completionMessageSnapshot = event.getMessage().getParameters()[0].toString(); - } - } - - @Override - public void assertMatched() { - assertThat(startMessageSnapshot, startsWith(snapshotName)); - assertEquals(Arrays.asList(indexName), startMessageIndicesList); - assertThat(completionMessageSnapshot, startsWith(snapshotName)); - } - }); + 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 From 7a8eb94faff81aebc0172c013517c2342cadb29c Mon Sep 17 00:00:00 2001 From: Iraklis Psaroudakis Date: Tue, 12 Jul 2022 15:44:26 +0300 Subject: [PATCH 9/9] Fix unused imports --- .../java/org/elasticsearch/snapshots/RestoreSnapshotIT.java | 2 -- 1 file changed, 2 deletions(-) diff --git a/server/src/internalClusterTest/java/org/elasticsearch/snapshots/RestoreSnapshotIT.java b/server/src/internalClusterTest/java/org/elasticsearch/snapshots/RestoreSnapshotIT.java index 8a6d32f2d69e8..23c43a16308bd 100644 --- a/server/src/internalClusterTest/java/org/elasticsearch/snapshots/RestoreSnapshotIT.java +++ b/server/src/internalClusterTest/java/org/elasticsearch/snapshots/RestoreSnapshotIT.java @@ -11,7 +11,6 @@ import org.apache.logging.log4j.Level; import org.apache.logging.log4j.LogManager; import org.apache.logging.log4j.Logger; -import org.apache.logging.log4j.core.LogEvent; import org.elasticsearch.Version; import org.elasticsearch.action.ActionFuture; import org.elasticsearch.action.admin.cluster.snapshots.restore.RestoreSnapshotResponse; @@ -64,7 +63,6 @@ import static org.hamcrest.Matchers.not; import static org.hamcrest.Matchers.notNullValue; import static org.hamcrest.Matchers.nullValue; -import static org.hamcrest.Matchers.startsWith; public class RestoreSnapshotIT extends AbstractSnapshotIntegTestCase {