INFO logging of snapshot restore and completion #88257

kingherc · 2022-07-04T15:36:04Z

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

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

docs/reference/snapshot-restore/apis/restore-snapshot-api.asciidoc

kingherc · 2022-07-04T15:44:21Z

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

@@ -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());


@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.

kingherc · 2022-07-04T15:52:33Z

Hi. Adding @DaveCTurner as reviewer (since he created the issue) and @original-brownbear as another reviewer (since you have experience with snapshot restores AFAIK). I manually tested this in this way:

Executed org.elasticsearch.snapshots.RestoreSnapshotIT#testParallelRestoreOperations (for regular snapshot restore use case) and saw that it emits the INFO log messages
Executed org.elasticsearch.xpack.ccr.AutoFollowIT#testAutoFollow (for CCR use case) and saw it does not emit the INFO log messages
Executed org.elasticsearch.xpack.searchablesnapshots.SearchableSnapshotsIntegTests#testCreateAndRestoreSearchableSnapshot (for searchable snapshot use case) and saw it does not emit the INFO log messages

Feel free to tell me:

if only one of you is needed as reviewer
whether we would like to add some sort of logging testing (if it exists for this part of the code, similar to logging tests that I saw in CoordinatorTests.java).

elasticmachine · 2022-07-04T15:54:18Z

Pinging @elastic/es-distributed (Team:Distributed)

elasticsearchmachine · 2022-07-04T15:55:07Z

Hi @kingherc, I've created a changelog YAML for you.

kingherc · 2022-07-05T09:49:35Z

OK, I understand I should have added you as reviewers after the CI passes -- will keep that in mind.

After conversing a bit, I also understand that in order to fix the CI bwc failures, I should (a) not expose the silent parameter in XContent, and (b) add ifs around the serialization parts. I'll try that 🤞 .

DaveCTurner · 2022-07-05T09:58:36Z

++ yes we shouldn't see this parameter in anything user-facing (particularly this means neither in docs nor XContent¹) and the wire-format change needs version guards. When receiving a transport message from an older node I suggest just treating the missing silent parameter as true.

NB XContent is not always user-facing, it's also used for writing the cluster metadata to disk (e.g. for cluster coordination and snapshots) but in this case neither of those cases apply. ↩

kingherc · 2022-07-05T13:52:55Z

Hi @original-brownbear and @DaveCTurner , CI passed. Feel free to review.

...in/java/org/elasticsearch/action/admin/cluster/snapshots/restore/RestoreSnapshotRequest.java

DaveCTurner

Looks good, I left a couple of small suggestions.

I'd like to have a test which asserts that we do actually report the log message we're adding at the right level. I think you can add a test case in RestoreSnapshotIT for that.

...in/java/org/elasticsearch/action/admin/cluster/snapshots/restore/RestoreSnapshotRequest.java

.../org/elasticsearch/action/admin/cluster/snapshots/restore/RestoreSnapshotRequestBuilder.java

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

kingherc · 2022-07-07T10:49:23Z

@DaveCTurner incorporated your feedback. Feel free to review. @original-brownbear feel free to also review if you'd like. Thanks!

kingherc · 2022-07-12T11:13:20Z

Gentle reminder for review @original-brownbear , @DaveCTurner

DaveCTurner

Sorry for the delay here @kingherc, this all looks good although I've one question about the test you added.

DaveCTurner · 2022-07-12T11:49:00Z

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

+            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));
+                }
+            });


I think it'd be clearer to write this as two regular SeenEventExpectation expectations with the actual message we expect (maybe with some * wildcards) instead of doing this. But maybe I've missed some subtlety about why we're doing it this way.

Done this way I think the fields would need to be volatile right?

DaveCTurner

LGTM

* upstream/master: (38 commits) Simplify map copying (elastic#88432) Make DiffableUtils.diff implementation agnostic (elastic#88403) Ingest: Start separating Metadata from IngestSourceAndMetadata (elastic#88401) Move runtime fields base scripts out of scripting fields api package. (elastic#88488) Enable TRACE Logging for test and increase timeout (elastic#88477) Mute ReactiveStorageIT#testScaleDuringSplitOrClone (elastic#88480) Track the count of failed invocations since last successful policy snapshot (elastic#88398) Avoid noisy exceptions on data nodes when aborting snapshots (elastic#88476) Fix ReactiveStorageDeciderServiceTests testNodeSizeForDataBelowLowWatermark (elastic#88452) INFO logging of snapshot restore and completion (elastic#88257) unmute test (elastic#88454) Updatable API keys - noop check (elastic#88346) Corrected an incomplete sentence. (elastic#86542) Use consistent shard map type in IndexService (elastic#88465) Stop registering TestGeoShapeFieldMapperPlugin in ESIntegTestCase (elastic#88460) TSDB: RollupShardIndexer logging improvements (elastic#88416) Audit API key ID when create or grant API keys (elastic#88456) Bound random negative size test in SearchSourceBuilderTests#testNegativeSizeErrors (elastic#88457) Updatable API keys - logging audit trail event (elastic#88276) Polish reworked LoggedExec task (elastic#88424) ... # Conflicts: # x-pack/plugin/rollup/src/main/java/org/elasticsearch/xpack/rollup/v2/RollupShardIndexer.java

INFO logging of snapshot restore and completion

866d810

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

elasticsearchmachine added the v8.4.0 label Jul 4, 2022

kingherc commented Jul 4, 2022

View reviewed changes

kingherc marked this pull request as ready for review July 4, 2022 15:45

kingherc requested review from original-brownbear and DaveCTurner July 4, 2022 15:45

kingherc self-assigned this Jul 4, 2022

kingherc added the Team:Distributed (Obsolete) Meta label for distributed team (obsolete). Replaced by Distributed Indexing/Coordination. label Jul 4, 2022

kingherc added >enhancement :Distributed Coordination/Snapshot/Restore Anything directly related to the `_snapshot/*` APIs Supportability Improve our (devs, SREs, support eng, users) ability to troubleshoot/self-service product better. labels Jul 4, 2022

Update docs/changelog/88257.yaml

77f27be

kingherc added 4 commits July 5, 2022 13:02

Do not expose in XContext and fix backwards compat

2836e5d

Also the same for RestoreInProgress.Entry

13eb54a

Fix a test

2144beb

Merge branch 'master' into feature/log-snapshot-restore

b871d37

kingherc commented Jul 5, 2022

View reviewed changes

...in/java/org/elasticsearch/action/admin/cluster/snapshots/restore/RestoreSnapshotRequest.java Outdated Show resolved Hide resolved

DaveCTurner reviewed Jul 5, 2022

View reviewed changes

kingherc added 2 commits July 6, 2022 17:57

Incorporate reviewer feedback

dccb199

Add test for ensuring log of snapshot restore

5bf00fb

kingherc requested a review from DaveCTurner July 7, 2022 10:48

Merge branch 'master' into feature/log-snapshot-restore

8619690

DaveCTurner reviewed Jul 12, 2022

View reviewed changes

kingherc added 2 commits July 12, 2022 15:29

Add PatternSeenEventExpectations

6e3741b

Merge branch 'master' into feature/log-snapshot-restore

44079ac

DaveCTurner approved these changes Jul 12, 2022

View reviewed changes

Fix unused imports

7a8eb94

kingherc merged commit 1e07915 into elastic:master Jul 12, 2022

kingherc deleted the feature/log-snapshot-restore branch July 12, 2022 13:52

DaveCTurner mentioned this pull request Aug 14, 2024

Restore snapshot logs include too many indices #111872

Open

3 tasks

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

INFO logging of snapshot restore and completion #88257

INFO logging of snapshot restore and completion #88257

kingherc commented Jul 4, 2022

kingherc Jul 4, 2022

kingherc commented Jul 4, 2022

elasticmachine commented Jul 4, 2022

elasticsearchmachine commented Jul 4, 2022

kingherc commented Jul 5, 2022

DaveCTurner commented Jul 5, 2022 •

edited

Loading

kingherc commented Jul 5, 2022

DaveCTurner left a comment

kingherc commented Jul 7, 2022

kingherc commented Jul 12, 2022

DaveCTurner left a comment

DaveCTurner Jul 12, 2022

DaveCTurner left a comment

INFO logging of snapshot restore and completion #88257

INFO logging of snapshot restore and completion #88257

Conversation

kingherc commented Jul 4, 2022

kingherc Jul 4, 2022

Choose a reason for hiding this comment

kingherc commented Jul 4, 2022

elasticmachine commented Jul 4, 2022

elasticsearchmachine commented Jul 4, 2022

kingherc commented Jul 5, 2022

DaveCTurner commented Jul 5, 2022 • edited Loading

Footnotes

kingherc commented Jul 5, 2022

DaveCTurner left a comment

Choose a reason for hiding this comment

kingherc commented Jul 7, 2022

kingherc commented Jul 12, 2022

DaveCTurner left a comment

Choose a reason for hiding this comment

DaveCTurner Jul 12, 2022

Choose a reason for hiding this comment

DaveCTurner left a comment

Choose a reason for hiding this comment

DaveCTurner commented Jul 5, 2022 •

edited

Loading