diff --git a/changelog/unreleased/SOLR-18344-report-in-progress-backup-status.yml b/changelog/unreleased/SOLR-18344-report-in-progress-backup-status.yml new file mode 100644 index 00000000000..9641510d40e --- /dev/null +++ b/changelog/unreleased/SOLR-18344-report-in-progress-backup-status.yml @@ -0,0 +1,10 @@ +# See https://github.com/apache/solr/blob/main/dev-docs/changelog.adoc +title: /replication?command=details now reports backup details while the backup is + still running, including file counts, instead of the previous backup's status +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 diff --git a/solr/core/src/java/org/apache/solr/handler/SnapShooter.java b/solr/core/src/java/org/apache/solr/handler/SnapShooter.java index b971543a70a..81b2e9bc397 100644 --- a/solr/core/src/java/org/apache/solr/handler/SnapShooter.java +++ b/solr/core/src/java/org/apache/solr/handler/SnapShooter.java @@ -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> progressListener = nl -> {}; + public SnapShooter( BackupRepository backupRepo, SolrCore core, @@ -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 inProgressDetails(String startTime, String status) { + NamedList 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 runningDetails(String startTime, int fileCount, int finishedFileCount) { + NamedList details = inProgressDetails(startTime, RUNNING_STATUS); + details.add("fileCount", fileCount); + details.add("finishedFileCount", finishedFileCount); + return details; + } + public void createSnapAsync(final int numberToKeep, Consumer> 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. + // 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( () -> { @@ -277,6 +318,7 @@ protected CoreSnapshotResponse createSnapshot(final IndexCommit indexCommit) thr details.startTime = Instant.now().toString(); Collection files = indexCommit.getFileNames(); + progressListener.accept(runningDetails(details.startTime, files.size(), 0)); Directory dir = solrCore .getDirectoryFactory() @@ -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); @@ -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") diff --git a/solr/core/src/test/org/apache/solr/handler/TestSnapshotCoreBackup.java b/solr/core/src/test/org/apache/solr/handler/TestSnapshotCoreBackup.java index 126d39f0f83..0862d1ebb73 100644 --- a/solr/core/src/test/org/apache/solr/handler/TestSnapshotCoreBackup.java +++ b/solr/core/src/test/org/apache/solr/handler/TestSnapshotCoreBackup.java @@ -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; @@ -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; @@ -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. + * + *

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 { + 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> 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> 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 diff --git a/solr/solr-ref-guide/modules/deployment-guide/pages/backup-restore.adoc b/solr/solr-ref-guide/modules/deployment-guide/pages/backup-restore.adoc index 7e9cdd35bf2..e243e15a7b3 100644 --- a/solr/solr-ref-guide/modules/deployment-guide/pages/backup-restore.adoc +++ b/solr/solr-ref-guide/modules/deployment-guide/pages/backup-restore.adoc @@ -129,7 +129,7 @@ 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] @@ -137,7 +137,35 @@ The `backup` operation can be monitored to see if it has completed by sending th 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] +---- + + 2022-02-11T17:19:33.271461700Z + running + my_backup + snapshot.my_backup + 10 + 4 + +---- + +`snapshotName` is only reported for a named backup. + +Once the backup completes, `status` becomes `success`: + +.Output Snippet: a completed backup [source,xml] ---- @@ -151,7 +179,10 @@ http://localhost:8983/solr/gettingstarted/replication?command=details&wt=xml ---- -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