Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

INFO logging of snapshot restore and completion #88257

Merged
merged 12 commits into from
Jul 12, 2022
Original file line number Diff line number Diff line change
Expand Up @@ -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`.
kingherc marked this conversation as resolved.
Show resolved Hide resolved

[[restore-snapshot-api-include-global-state]]
`include_global_state`::
+
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -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()
)
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -48,6 +48,7 @@ public class RestoreSnapshotRequest extends MasterNodeRequest<RestoreSnapshotReq
private boolean includeGlobalState = false;
private boolean partial = false;
private boolean includeAliases = true;
private boolean silent = false;
private Settings indexSettings = Settings.EMPTY;
private String[] ignoreIndexSettings = Strings.EMPTY_ARRAY;

Expand Down Expand Up @@ -83,6 +84,7 @@ public RestoreSnapshotRequest(StreamInput in) throws IOException {
includeGlobalState = in.readBoolean();
partial = in.readBoolean();
includeAliases = in.readBoolean();
silent = in.readBoolean();
indexSettings = readSettingsFromStream(in);
ignoreIndexSettings = in.readStringArray();
snapshotUuid = in.readOptionalString();
Expand All @@ -102,6 +104,7 @@ public void writeTo(StreamOutput out) throws IOException {
out.writeBoolean(includeGlobalState);
out.writeBoolean(partial);
out.writeBoolean(includeAliases);
out.writeBoolean(silent);
writeSettingsToStream(indexSettings, out);
out.writeStringArray(ignoreIndexSettings);
out.writeOptionalString(snapshotUuid);
Expand Down Expand Up @@ -383,6 +386,26 @@ public boolean includeAliases() {
return includeAliases;
}

/**
* If set to true the logging should be at a lower level
kingherc marked this conversation as resolved.
Show resolved Hide resolved
*
* @param silent true if logging should be at a lower level
kingherc marked this conversation as resolved.
Show resolved Hide resolved
* @return this request
*/
public RestoreSnapshotRequest silent(boolean silent) {
this.silent = silent;
return this;
}

/**
* Returns a boolean for whether logging should be at a lower or higher level
*
* @return true if logging should be at a lower level
kingherc marked this conversation as resolved.
Show resolved Hide resolved
*/
public boolean silent() {
return silent;
}

/**
* Sets settings that should be added/changed in all restored indices
*/
Expand Down Expand Up @@ -505,6 +528,8 @@ public RestoreSnapshotRequest source(Map<String, Object> 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());
Expand Down Expand Up @@ -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) {
Expand Down Expand Up @@ -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)
Expand All @@ -626,6 +653,7 @@ public int hashCode() {
includeGlobalState,
partial,
includeAliases,
silent,
indexSettings,
snapshotUuid,
skipOperatorOnlyState
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -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) {
kingherc marked this conversation as resolved.
Show resolved Hide resolved
request.silent(silent);
return this;
}

/**
* Sets index settings that should be added or replaced during restore
*
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -104,19 +104,35 @@ 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 silent,
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 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<String> indices, Map<ShardId, ShardRestoreStatus> shards) {
public Entry(
String uuid,
Snapshot snapshot,
State state,
boolean silent,
List<String> indices,
Map<ShardId, ShardRestoreStatus> 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();
Expand Down Expand Up @@ -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<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,
silent,
indices,
in.readImmutableMap(ShardId::new, ShardRestoreStatus::readShardRestoreStatus)
)
);
}
this.entries = Collections.unmodifiableMap(entriesBuilder);
Expand All @@ -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);
});
Expand All @@ -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()) {
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -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);
Expand Down Expand Up @@ -737,6 +736,7 @@ public static RestoreInProgress updateRestoreStateWithDeletedIndices(RestoreInPr
entry.uuid(),
entry.snapshot(),
overallState(RestoreInProgress.State.STARTED, shards),
entry.silent(),
entry.indices(),
shards
)
Expand Down Expand Up @@ -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.silent(), entry.indices(), shards)
);
} else {
builder.add(entry);
}
Expand Down Expand Up @@ -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());
Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@fcofdez suggested to me this is a nice place to log the completion of a snapshot restore. This meant passing the silent property from the RestoreSnapshotRequest to RestoreInProgress.Entry so that we can read the silent parameter here.

changed = true;
} else {
restoreInProgressBuilder.add(entry);
Expand Down Expand Up @@ -1373,6 +1376,7 @@ && isSystemIndex(snapshotIndexMetadata) == false) {
restoreUUID,
snapshot,
overallState(RestoreInProgress.State.INIT, shards),
request.silent(),
List.copyOf(indicesToRestore.keySet()),
Map.copyOf(shards)
)
Expand Down Expand Up @@ -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));
}
}
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -64,6 +64,7 @@ private RestoreSnapshotRequest randomState(RestoreSnapshotRequest instance) {
}
instance.partial(randomBoolean());
instance.includeAliases(randomBoolean());
instance.silent(randomBoolean());

if (randomBoolean()) {
Map<String, Object> indexSettings = new HashMap<>();
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -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()
);
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -414,6 +414,7 @@ private ClusterState createRecoveryStateAndInitializeAllocations(
restoreUUID,
snapshot,
RestoreInProgress.State.INIT,
false,
new ArrayList<>(snapshotIndices),
restoreShards.build()
);
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -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()))
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -148,6 +148,7 @@ public void testCanAllocatePrimaryExistingInRestoreInProgress() {
recoverySource.restoreUUID(),
snapshot,
restoreState,
false,
singletonList("test"),
shards.build()
);
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -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()
)
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -451,6 +451,7 @@ private ClusterState addUnassignedShards(final ClusterState currentState, String
recoverySource.restoreUUID(),
recoverySource.snapshot(),
RestoreInProgress.State.INIT,
false,
Collections.singletonList(indexName),
shards.build()
)
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -158,7 +158,8 @@ public void testThatRepositoryRecoversEmptyIndexBasedOnLeaderSettings() throws I
.renamePattern("^(.*)$")
.renameReplacement(followerIndex)
.masterNodeTimeout(TimeValue.MAX_VALUE)
.indexSettings(settingsBuilder);
.indexSettings(settingsBuilder)
.silent(true);

PlainActionFuture<RestoreInfo> future = PlainActionFuture.newFuture();
restoreService.restoreSnapshot(restoreRequest, waitForRestore(clusterService, future));
Expand Down Expand Up @@ -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<RestoreInfo> future = PlainActionFuture.newFuture();
restoreService.restoreSnapshot(restoreRequest, waitForRestore(clusterService, future));
Expand Down Expand Up @@ -298,7 +300,8 @@ public void testRateLimitingIsEmployed() throws Exception {
.renamePattern("^(.*)$")
.renameReplacement(followerIndex)
.masterNodeTimeout(TimeValue.MAX_VALUE)
.indexSettings(settingsBuilder);
.indexSettings(settingsBuilder)
.silent(true);

PlainActionFuture<RestoreInfo> future = PlainActionFuture.newFuture();
restoreService.restoreSnapshot(restoreRequest, waitForRestore(clusterService, future));
Expand Down Expand Up @@ -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);
Expand Down Expand Up @@ -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<MockTransportService> transportServices = new ArrayList<>();
CountDownLatch latch = new CountDownLatch(1);
Expand Down Expand Up @@ -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);
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -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 {
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -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,
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -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);
Expand Down