Skip to content
Open
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
Original file line number Diff line number Diff line change
@@ -0,0 +1,9 @@
# See https://github.com/apache/solr/blob/main/dev-docs/changelog.adoc
title: /replication?command=details now reports a backup while it is still running, with file counts, instead of showing the previous backup's status until the new one completes

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

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

"repots backup details" maybe?

type: fixed # added, changed, fixed, deprecated, removed, dependency_update, security, other
authors:
- name: Idan Tepper
nick: idantepper
links:
- name: SOLR-18344
url: https://issues.apache.org/jira/browse/SOLR-18344
54 changes: 54 additions & 0 deletions solr/core/src/java/org/apache/solr/handler/SnapShooter.java
Original file line number Diff line number Diff line change
Expand Up @@ -66,6 +66,12 @@ public class SnapShooter {
private BackupRepository backupRepo = null;
private String commitName; // can be null

/**
* Receives in-progress status while the snapshot is being created, so that it can be reported
* before the snapshot completes. A no-op unless set by {@link #createSnapAsync}.
*/
private volatile Consumer<NamedList<?>> progressListener = nl -> {};

public SnapShooter(
BackupRepository backupRepo,
SolrCore core,
Expand Down Expand Up @@ -228,7 +234,42 @@ public static IndexCommit getAndSaveNamedIndexCommit(SolrCore solrCore, String c
+ solrCore.getName());
}

/**
* The status of a snapshot that has been requested but has not finished yet. A null {@link
* #snapshotName} is omitted rather than reported, matching how {@link CoreSnapshotResponse}
* reports the same snapshot once it has completed.
*/
private NamedList<Object> inProgressDetails(String startTime, String status) {
NamedList<Object> details = new SimpleOrderedMap<>();
details.add("startTime", startTime);
details.add("status", status);
if (snapshotName != null) {
details.add("snapshotName", snapshotName);
}
details.add("directoryName", directoryName);
return details;
}

/**
* The status of a snapshot whose files are being copied. Only reported once the index commit has
* been resolved, since until then there is no file list to count.
*
* @param fileCount the total number of files this snapshot will copy
* @param finishedFileCount how many of them have been copied so far
*/
private NamedList<Object> runningDetails(String startTime, int fileCount, int finishedFileCount) {
NamedList<Object> details = inProgressDetails(startTime, RUNNING_STATUS);
details.add("fileCount", fileCount);
details.add("finishedFileCount", finishedFileCount);
return details;
}

public void createSnapAsync(final int numberToKeep, Consumer<NamedList<?>> result) {
this.progressListener = result;
// Report before the thread starts, otherwise the previously reported status (possibly a
// "success" from an earlier snapshot) stays visible until the index commit has been resolved.

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

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

so is the idea that a success is just going to hangaround for forever, or until the next snapshot is begun? I guess that is how it works...

Copy link
Copy Markdown
Author

Choose a reason for hiding this comment

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

Yes, exactly that. snapShootDetails on ReplicationHandler is a plain volatile field that is never cleared -- getReplicationDetails publishes it under backup whenever it is non-null. It gets overwritten by the next backup, or by a snapshot deletion, and it is only back to null after a core reload or node restart, at which point the backup key is simply absent again.

That lifetime is pre-existing and this PR does not change it. What it changes is when the first overwrite lands: it used to be at the end of the next backup, so a stale success survived the entire run of the backup that was meant to replace it. Now it is replaced the moment the next backup is requested, which is the part that fixes the stale read.

You prompted me to go look at the docs, and my checklist claim was wrong: backup-restore.adoc -- "Backup Status" does document the shape of this response, it just only showed the completed success payload. I have pushed a ref-guide commit that adds the two in-progress statuses and states this retention behaviour explicitly, so a reader knows a success may describe an earlier backup rather than one just requested.

Drive-by in the same section, shout if you would rather it went separately: it said a failure reports snapShootException, which appears nowhere in the codebase -- the key is exception.

// The file list isn't known until then, so this status carries no file counts.
result.accept(inProgressDetails(Instant.now().toString(), WAITING_FOR_COMMIT_STATUS));
// TODO should use Solr's ExecutorUtil
new Thread(
() -> {
Expand Down Expand Up @@ -277,6 +318,7 @@ protected CoreSnapshotResponse createSnapshot(final IndexCommit indexCommit) thr
details.startTime = Instant.now().toString();

Collection<String> files = indexCommit.getFileNames();
progressListener.accept(runningDetails(details.startTime, files.size(), 0));
Directory dir =
solrCore
.getDirectoryFactory()
Expand All @@ -285,10 +327,13 @@ protected CoreSnapshotResponse createSnapshot(final IndexCommit indexCommit) thr
DirContext.DEFAULT,
solrCore.getSolrConfig().indexConfig.lockType);
try {
int finishedFileCount = 0;
for (String fileName : files) {
log.debug(
"Copying fileName={} from dir={} to snapshot={}", fileName, dir, snapshotDirPath);
backupRepo.copyFileFrom(dir, fileName, snapshotDirPath);
progressListener.accept(
runningDetails(details.startTime, files.size(), ++finishedFileCount));
}
} finally {
solrCore.getDirectoryFactory().release(dir);
Expand Down Expand Up @@ -376,6 +421,15 @@ protected void deleteNamedSnapshot(ReplicationHandler replicationHandler) {

public static final String DATE_FMT = "yyyyMMddHHmmssSSS";

/**
* Status reported after a snapshot has been requested but before its index commit -- and with it
* the list of files to copy -- has been resolved.
*/
public static final String WAITING_FOR_COMMIT_STATUS = "waiting for commit";

/** Status reported while a snapshot's files are being copied. */
public static final String RUNNING_STATUS = "running";

public static class CoreSnapshotResponse extends SolrJerseyResponse {
@Schema(description = "The time at which snapshot started at.")
@JsonProperty("startTime")
Expand Down
101 changes: 101 additions & 0 deletions solr/core/src/test/org/apache/solr/handler/TestSnapshotCoreBackup.java
Original file line number Diff line number Diff line change
Expand Up @@ -20,6 +20,9 @@
import java.nio.file.Files;
import java.nio.file.Path;
import java.util.Arrays;
import java.util.List;
import java.util.concurrent.CopyOnWriteArrayList;
import java.util.concurrent.TimeUnit;
import org.apache.lucene.index.CheckIndex;
import org.apache.lucene.index.DirectoryReader;
import org.apache.lucene.index.IndexCommit;
Expand All @@ -29,9 +32,12 @@
import org.apache.lucene.tests.util.TestUtil;
import org.apache.solr.SolrTestCaseJ4;
import org.apache.solr.common.params.CoreAdminParams;
import org.apache.solr.common.util.NamedList;
import org.apache.solr.common.util.TimeSource;
import org.apache.solr.core.CoreContainer;
import org.apache.solr.handler.admin.CoreAdminHandler;
import org.apache.solr.response.SolrQueryResponse;
import org.apache.solr.util.TimeOut;
import org.junit.After;
import org.junit.Before;

Expand Down Expand Up @@ -369,6 +375,101 @@ public void testBackupAfterSoftCommit() throws Exception {
admin.close();
}

/**
* Backups run asynchronously, so the status reported to /replication?command=details must
* describe a snapshot that is still running -- not stay silent (or keep describing the previously
* completed snapshot) until it finishes.
*
* <p>Rather than racing a live backup by polling "details", this collects every status the
* handler would have published and asserts on the whole sequence, which is deterministic.
*/
public void testBackupReportsProgressWhileRunning() throws Exception {

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

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

is this a pattern that we follow elsewhere in Solr for these types of things?

Copy link
Copy Markdown
Author

Choose a reason for hiding this comment

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

Yes -- Solr has a family of "record what the code published, then assert on the collected sequence" helpers rather than racing the thing under test. The three closest to this one:

  • TrackingBackupRepository (solr/test-framework/src/java/org/apache/solr/core/TrackingBackupRepository.java) is the nearest, and it is in this same feature area: it wraps the repository and records every copyIndexFileFrom / createOutput / createDirectory into a synchronized list so a test can assert on what a backup actually did. AbstractIncrementalBackupTest asserts on copiedFiles() / outputsCreated() / directoriesCreated(), as do LocalFSCloudIncrementalBackupTest and the S3/GCS/HDFS backup tests. Same seam as here -- the per-file copy inside a running backup -- and the same shape.
  • SoftAutoCommitTest.MockEventListener registers a SolrEventListener that offers each async commit / newSearcher event into a LinkedBlockingQueue, and the test asserts on the ordering of what arrived. That is the precedent for asserting on an asynchronous sequence rather than polling for a single state.
  • SnapshotBackupAPITest.TrackingSnapshotBackupAPI overrides doSnapShoot and records what the handler passed instead of running a live backup -- the same seam this test uses. The Consumer<NamedList<?>> overload of ReplicationHandler.doSnapShoot is what ReplicationHandler itself calls, so this is not a test-only backdoor.

The alternative would have been BackupStatusChecker, which polls command=details over HTTP (TestRestoreCore, TestReplicationHandlerBackup, TestStressThreadBackup). I did not use it because it is deliberately terminal-state-only -- it returns null for anything that is not success -- and its own javadoc says it is "NOT suitable/safe ... because the replication handler API provides no reliable way to check the results of a specific backup before the results of another backup may overwrite them internally". Polling it for an intermediate status would flake: on a test-sized index the copy loop can finish between two 50ms polls.

Worth recording that the new statuses do not disturb that helper either -- non-success statuses still return null, and neither the exception check nor the startsWith("Unable to delete") check can match waiting for commit / running.

Happy to add an HTTP-level assertion on top if you would prefer one, though it could only assert "not success yet" rather than a specific in-progress status.

Unrelated: the red check is TestGracefulJettyShutdown.testSingleShardInFlightRequestsDuringShutDown failing on a jetty HTTP/2 ClosedChannelException during shutdown -- nothing to do with this change; gradle check is green.

for (int i = 0; i < 50; i++) {
assertU(adoc("id", String.valueOf(i)));
}
assertU(commit());

final Path backupDir = createTempDir();
h.getCoreContainer().getAllowPaths().add(backupDir);

// this is what /replication?command=backup does, minus the http plumbing
final List<NamedList<?>> reports = new CopyOnWriteArrayList<>();
ReplicationHandler.doSnapShoot(
0, 0, backupDir.toString(), null, null, "progress_backup", h.getCore(), reports::add);

final TimeOut timeOut = new TimeOut(60, TimeUnit.SECONDS, TimeSource.NANO_TIME);
NamedList<?> last = null;
while (!timeOut.hasTimedOut()) {
if (!reports.isEmpty()) {
last = reports.get(reports.size() - 1);
assertNull("Backup failed: " + last, last.get("exception"));
if ("success".equals(last.get("status"))) {
break;
}
}
timeOut.sleep(20);
}
assertNotNull("No backup status was ever reported", last);
assertEquals(
"Backup did not succeed before the TimeOut elapsed: " + last,
"success",
last.get("status"));
// the backup is over, so no further reports can arrive and 'reports' is now stable
final int totalFileCount = ((Number) last.get("fileCount")).intValue();
assertTrue(
"Test needs a backup of more than one file, got " + totalFileCount, 1 < totalFileCount);

// the very first status is published before the index commit is resolved, so it names no files
final NamedList<?> waiting = reports.get(0);
assertEquals(
"backup should first report itself as waiting: " + waiting,
SnapShooter.WAITING_FOR_COMMIT_STATUS,
waiting.get("status"));
assertNull("no file list is known yet: " + waiting, waiting.get("fileCount"));
assertNull("no file list is known yet: " + waiting, waiting.get("finishedFileCount"));

final List<NamedList<?>> running = reports.subList(1, reports.size() - 1);
assertFalse("Backup was never reported as running", running.isEmpty());

int previousFinished = -1;
for (NamedList<?> report : running) {
assertEquals(
"not reported as running: " + report, SnapShooter.RUNNING_STATUS, report.get("status"));

final int finished = ((Number) report.get("finishedFileCount")).intValue();
assertTrue(
"finishedFileCount went backwards: " + previousFinished + " -> " + finished,
previousFinished <= finished);
previousFinished = finished;
}

// every in-progress status must identify the backup it is about
for (NamedList<?> report : reports.subList(0, reports.size() - 1)) {
assertNotNull("in-progress report has no startTime: " + report, report.get("startTime"));
assertEquals(
"in-progress report names the wrong snapshot: " + report,
"progress_backup",
report.get("snapshotName"));
assertEquals(
"in-progress report has the wrong directoryName: " + report,
"snapshot.progress_backup",
report.get("directoryName"));
}

// by the last report before completion, every file must be accounted for
final NamedList<?> lastRunning = running.get(running.size() - 1);
assertEquals(
"last running report disagrees with the completed backup: " + lastRunning,
totalFileCount,
((Number) lastRunning.get("fileCount")).intValue());
assertEquals(
"last running report did not finish every file: " + lastRunning,
totalFileCount,
((Number) lastRunning.get("finishedFileCount")).intValue());

simpleBackupCheck(backupDir.resolve("snapshot.progress_backup"), 50);
}

/**
* A simple sanity check that asserts the current weird behavior of
* DirectoryReader.openIfChanged() and demos how 'softCommit' can cause the IndexReader in use by
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -129,15 +129,43 @@ The name of the commit which was used while taking a snapshot using the CREATESN

=== Backup Status

The `backup` operation can be monitored to see if it has completed by sending the `details` command to the `/replication` handler, as in this example:
The `backup` operation can be monitored by sending the `details` command to the `/replication` handler, as in this example:

.Status API Example
[source,text]
----
http://localhost:8983/solr/gettingstarted/replication?command=details&wt=xml
----

.Output Snippet
The `backup` section of the response describes the most recent backup on the core, whether it is still running or has already finished.
While a backup is in progress, `status` is one of:

`waiting for commit`::
The backup has been requested, but its index commit -- and with it the list of files to copy -- has not been resolved yet.
No file counts are reported.

`running`::
The backup's files are being copied.
`fileCount` is the total number of files to copy, and `finishedFileCount` how many of them have been copied so far.

.Output Snippet: a running backup
[source,xml]
----
<lst name="backup">
<str name="startTime">2022-02-11T17:19:33.271461700Z</str>
<str name="status">running</str>
<str name="snapshotName">my_backup</str>
<str name="directoryName">snapshot.my_backup</str>
<int name="fileCount">10</int>
<int name="finishedFileCount">4</int>
</lst>
----

`snapshotName` is only reported for a named backup.

Once the backup completes, `status` becomes `success`:

.Output Snippet: a completed backup
[source,xml]
----
<lst name="backup">
Expand All @@ -151,7 +179,10 @@ http://localhost:8983/solr/gettingstarted/replication?command=details&wt=xml
</lst>
----

If it failed then a `snapShootException` will be sent in the response.
If it failed then an `exception` will be sent in the response.

The reported status is retained until the next backup is started on the core, or until the core is reloaded.
A `success` may therefore describe an earlier backup rather than one that was just requested; a newly requested backup replaces it with `waiting for commit` as soon as it is accepted.

=== Restore API

Expand Down
Loading