HBASE-29776: Log filtering in IncrementalBackupManager can lead to data loss

[hgromer]

There was a previous attempt at this change here. I want to make sure the dicussions there are carried over

[hgromer]

I know there was debate whether this was necessary or not here, and want to emphasize that this is a very important change. Without this change, we're subject to data loss anytime a new RS joins the cluster.

If we add just this code snippet back, our TestBackupOfflineRS tests will fail, showing this is in fact problematic. Importantly, adding a file to newestLog means it is not included in the backup. The roll time moves forward, and then the log cleaner deletes these logs without them ever being included in the backup.

There was some discussion about modifying this check due to hypothetical scenarios. I think it's a lot safer to simply remove this block which can cause data loss and provides no value. Simply removing this check keeps things safe. And I don't think the scenario here warrants potential data loss. Even if this scenario did play out, the only consequence is that we include a WAL that we don't technically need in a backup. This is a non-issue, given that our restore process handles this without any issues.

Finally, there was dicussion around trying to ensure "cross-table consistency" and data being out of sync which I disagree with as well. This backup is a point-in-time snapshot. In a distributed system, each RS is going to have it's own point in time. This is similarly true for snapshots, where one region's snapshot procedure can happen minutes prior to another one.

Regardless, I think preventing data loss scenarios and simplifying the code should be the priority here.

[DieterDePaepe]

I still argue to not delete this check, but to change it to if (newTimestamp != null && currentLogTS > newTimestamp) instead. I think the removal (as suggested in the PR) can lead to data loss. This adjusted version fixes the original data loss issue and does not break the newly added tests.

Two things have to occur on a region server during an incremental backup to cause data loss:

1. Two quick wall rolls. The backup's own roll creates a new WAL, C. Before the backup finishes listing oldWALs, the region server has to roll twice more: C → T, then T → U. Only then is T closed and eligible for archiving.
2. T is archived while C isn't. cleanOldLogs archives any closed WAL whose regions have all flushed past its edits. If C holds edits for a region that T doesn't touch, and that region hasn't flushed yet, T gets archived first.

Of these 2 conditions, I expect (2) to occur commonly. For (1): The window runs from the backup's roll to the end of the oldWALs listing, and that's normally a few seconds. Two rolls might fit in it when one of these holds:

• Heavy ingest. By default a WAL rolls when it reaches 0.5 × (2 × HDFS block size), which is about 128 MB. A region server ingesting around 50–100 MB/s rolls every 1–3 seconds. The hourly time-based roll (hbase.regionserver.logroll.period) is far too slow to matter.
• A slow listing. getLogFilesForNewBackup runs one listStatus per region server directory, then a recursive listing of oldWALs. BackupLogCleaner keeps every WAL that a backup root still needs, so with backups enabled oldWALs can hold tens or hundreds of thousands of files. A large cluster or a slow NameNode can stretch the window to tens of seconds.

A rare case, but one that can occur on any incremental backup on any region server. For a large cluster with daily backups, it is bound to happen eventually. The result is a WAL that never gets included in a backup, leading to data loss when restoring.

I agree that simpler is better, and I wished lots of the backup code was simpler, but in this case the complexity is worth it.

Example test case (breaks on the current PR, succeeds on the current PR + suggested adjustment):

// paste me in TestIncrementalBackupManager 

  /**
   * WALs can be archived out of order. This test sets up the WAL directories as an incremental
   * backup would find them if, after its log roll, a newer WAL got archived while an older one was
   * still in the WALs directory. The older WAL must still end up in a backup.
   */
  @Test
  public void testOutOfOrderArchivedWALDoesNotSkipOlderWAL() throws Exception {
    List<TableName> tables = List.of(table1);
    HRegionServer rs = TEST_UTIL.getMiniHBaseCluster().getRegionServer(0);
    ServerName serverName = rs.getServerName();
    Path walRootDir = CommonFSUtils.getWALRootDir(conf1);
    FileSystem fs = walRootDir.getFileSystem(conf1);

    try (Connection conn = ConnectionFactory.createConnection(conf1);
      BackupAdminImpl backupAdmin = new BackupAdminImpl(conn)) {
      String fullBackupId =
        backupAdmin.backupTables(createBackupRequest(BackupType.FULL, tables, BACKUP_ROOT_DIR));
      assertTrue(checkSucceeded(fullBackupId));

      // Both test WALs are newer than any WAL that exists at this point, so they are newer than the
      // WAL reported by the log roll of the next incremental backup.
      long olderWALTs = EnvironmentEdgeManager.currentTime() + 1;
      long newerWALTs = olderWALTs + 1;
      Path walDir =
        new Path(walRootDir, AbstractFSWALProvider.getWALDirectoryName(serverName.toString()));
      Path olderWAL =
        new Path(walDir, serverName.toString() + BackupUtils.LOGNAME_SEPARATOR + olderWALTs);
      Path archiveDir = new Path(walRootDir,
        AbstractFSWALProvider.getWALArchiveDirectoryName(conf1, serverName.toString()));
      Path newerArchivedWAL =
        new Path(archiveDir, "wal" + BackupUtils.LOGNAME_SEPARATOR + newerWALTs);
      fs.create(olderWAL).close();
      fs.mkdirs(archiveDir);
      fs.create(newerArchivedWAL).close();

      try {
        List<String> firstBackupFiles;
        try (IncrementalBackupManager manager = new IncrementalBackupManager(conn, conf1)) {
          BackupInfo backupInfo = manager.createBackupInfo("backup_incr_1",
            BackupType.INCREMENTAL, tables, BACKUP_ROOT_DIR, -1, -1, false, false);
          Map<String, Long> boundaries = manager.getIncrBackupLogFileMap();
          manager.writeRegionServerLogTimestamp(backupInfo.getTables(), boundaries);
          firstBackupFiles = backupInfo.getIncrBackupFileList();
        }

        // Roll once more, so the log roll of the next backup reports a WAL that is newer than both
        // test WALs.
        TEST_UTIL.waitFor(30_000, () -> EnvironmentEdgeManager.currentTime() > newerWALTs);
        rs.getWalRoller().requestRollAll();
        rs.getWalRoller().waitUntilWalRollFinished();

        List<String> secondBackupFiles;
        try (IncrementalBackupManager manager = new IncrementalBackupManager(conn, conf1)) {
          BackupInfo backupInfo = manager.createBackupInfo("backup_incr_2",
            BackupType.INCREMENTAL, tables, BACKUP_ROOT_DIR, -1, -1, false, false);
          manager.getIncrBackupLogFileMap();
          secondBackupFiles = backupInfo.getIncrBackupFileList();
        }

        assertTrue(
          firstBackupFiles.contains(olderWAL.toString())
            || secondBackupFiles.contains(olderWAL.toString()),
          "WAL " + olderWAL + " was not included in any backup. First backup: " + firstBackupFiles
            + ", second backup: " + secondBackupFiles);
      } finally {
        fs.delete(olderWAL, false);
        fs.delete(newerArchivedWAL, false);
      }
    }
  }

[hgromer]

Hmm, okay I think I see your point, I didn't realize that WAL archival was random. This comment makes sense. In that case, I think your proposed change makes sense, while still preventing the data loss scenario that I'm trying to address

[rmdmattingly]

The new WAL-directory scan is invoked after backupInfo.setState(BackupState.COMPLETE) — past the point the surrounding comment describes as the checkpoint after which "even if entering cancel process, will let the backup finished". Any IOException from the scan (fs.listStatus(oldLogDir) throws FileNotFoundException when oldWALs has not been created yet, e.g. a freshly initialized WAL root) or an unchecked parse failure now propagates out of handleNonContinuousBackup before updateBackupMetadata() runs, leaving a completed snapshot with no persisted timestamp map.

Fix: Either move the scan before the COMPLETE checkpoint, or wrap it so a scan failure logs a warning and falls back to the log-roll-derived newTimestamps instead of failing the backup after the snapshot has been taken. Also guard against a non-existent oldLogDir with an fs.exists check.

[hgromer]

yeah, good idea. I've wrapped it in a try/catch

[hgromer]

I've moved when this happens, and will actually let this throw now, because it's early enough a failure won't mess up the state. Falling back to existing newTimestamps exposes the data loss bugs, so I think a loud failure is warranted

[hgromer]

I believe the yetus failures are unrelated

[charlesconnell]

I feel good about this since it's been battle-tested inside Hubspot

[DieterDePaepe]

I think this change introduces a new possible data loss scenario, where a region server comes online after the log roll and before the WAL listing (ie: while the performBackupSnapshots is running the MR copy jobs, which can significant for full backups).

This test demonstrates the issue:

public class TestBackupOfflineRS extends TestBackupBase {
...
  /** Full backup client that runs {@link #afterSnapshotHook} once the table snapshots exist. */
  public static class FullTableBackupClientWithHook extends FullTableBackupClient {
    @Override
    protected void snapshotCopy(BackupInfo backupInfo) throws IOException {
      afterSnapshotHook.run();
      super.snapshotCopy(backupInfo);
    }
  }

  /**
   * Tests that edits written during a full backup, after its log roll and table snapshot, to an RS
   * that started after that log roll, are included in the next incremental backup.
   */
  @Test
  public void testRSStartedDuringFullBackup() throws Exception {
    SingleProcessHBaseCluster cluster = TEST_UTIL.getMiniHBaseCluster();
    List<TableName> tables = Lists.newArrayList(table1);

    afterSnapshotHook = () -> {
      try {
        HRegionServer newRS = cluster.startRegionServerAndWait(10000).getRegionServer();
        try (Admin admin = TEST_UTIL.getConnection().getAdmin()) {
          RegionInfo region = admin.getRegions(table1).get(0);
          admin.move(region.getEncodedNameAsBytes(), newRS.getServerName());
          TEST_UTIL.waitUntilAllRegionsAssigned(table1);
        }
        try (Connection conn = ConnectionFactory.createConnection(conf1)) {
          insertIntoTable(conn, table1, famName, 8, 50).close();
        }
      } catch (Exception e) {
        throw new RuntimeException(e);
      }
    };
    conf1.set(TableBackupClient.BACKUP_CLIENT_IMPL_CLASS,
      FullTableBackupClientWithHook.class.getName());
    String fullBackupId;
    try {
      fullBackupId = fullTableBackup(tables);
    } finally {
      conf1.unset(TableBackupClient.BACKUP_CLIENT_IMPL_CLASS);
    }
    assertTrue(checkSucceeded(fullBackupId), "Full backup should succeed");

    String incrBackupId = incrementalTableBackup(tables);
    assertTrue(checkSucceeded(incrBackupId), "Incremental backup should succeed");

    TableName restoredTable = TableName.valueOf("table1_rs_started_during_full_backup");
    try (Connection conn = ConnectionFactory.createConnection(conf1);
      BackupAdminImpl backupAdmin = new BackupAdminImpl(conn)) {
      backupAdmin.restore(BackupUtils.createRestoreRequest(BACKUP_ROOT_DIR, incrBackupId, false,
        new TableName[] { table1 }, new TableName[] { restoredTable }, true));
    }
    assertEquals(TEST_UTIL.countRows(table1), TEST_UTIL.countRows(restoredTable),
      "Restored table should contain all rows, including those written to the new RS");
  }

This test succeeded on the original version.

[hgromer]

I've moved adjustTimestampsForOfflineHosts prior to the snapshotting of the table.

[DieterDePaepe]

These tests fail on my computer, and I traced it down to my hostname containing a capital. Apparently, the backup code is mixing lower and original-cased hostnames.

• Lowercased: the server-name host,port,startcode, and WAL folder/file names.
• Original case: ServerName.getHostname() and getAddress().toString(), which end up in the roll results.

So on a host with uppercase letters in its name, roll-result keys and WAL-path keys don't match.

The simplest option is to lowercase the hostname wherever the backup code builds a host:port key: in logRollV2, in LogRollBackupSubprocedure, and in the two BackupUtils parsers, so all of them agree with the WAL file names. Already stored rslogts and trslm rows would need to be read case-insensitively, or migrated once.

My workaround (which can be adjusted to trigger the issue too):

  conf1.set("hbase.unsafe.regionserver.hostname", "localhost");
  conf1.set("hbase.master.hostname", "localhost");

Fine for me to log this as a separate issue instead of fixing here. Let me know if you'd prefer I log a new ticket for this.

[hgromer]

Do you mind drafting up a new issue here? It'd be nice to try to keep the scope of this PR, which is already quite large, to what it is now.

[DieterDePaepe]

The offline host gets re-introduced upon later incremental backups.

In the IncrementalBackupManager, this is the check:

  Long earliestTimestampToIncludeInBackup = previousTimestampMins.get(host);
  boolean isInactive = earliestTimestampToIncludeInBackup != null
    && earliestTimestampToIncludeInBackup >= latestLogRoll;

So a host counts as inactive only if two things are true:

1. The previous backup stored a boundary for it.
2. That boundary has caught up with its last roll result.

Any host that the previous backup did not store is treated as active, whatever its roll result says.

Replace the remaining code by this snippet as demonstration (this will make the test fail):

      timestamps = sysTable.readLogTimestampMap(BACKUP_ROOT_DIR);
      rsTimestamps = timestamps.get(table1);
      assertFalse(rsTimestamps.containsKey(offlineHost),
        "Offline RS should not have a boundary after all its WALs have been backed up");

      // The offline RS keeps its entry in the last-log-roll table, which is never pruned. Later
      // incrementals must neither restore its boundary nor back up its WALs a second time.
      Long staleLogRoll =
        sysTable.readRegionServerLastLogRollResult(BACKUP_ROOT_DIR).get(offlineHost);

      String incrBackupId3 = incrementalTableBackup(tables);
      assertTrue(checkSucceeded(incrBackupId3), "Third incremental backup should succeed");
      Long boundaryAfterIncr3 = sysTable.readLogTimestampMap(BACKUP_ROOT_DIR).get(table1)
        .get(offlineHost);

      String incrBackupId4 = incrementalTableBackup(tables);
      assertTrue(checkSucceeded(incrBackupId4), "Fourth incremental backup should succeed");
      List<String> reincludedWals = walsOfHost(sysTable.readBackupInfo(incrBackupId4), offlineHost);

      assertAll(
        () -> assertNull(boundaryAfterIncr3,
          "Third incremental restored the pruned boundary of the offline RS (last log roll = "
            + staleLogRoll + ")"),
        () -> assertTrue(reincludedWals.isEmpty(),
          "Fourth incremental backed up WALs of the offline RS again: " + reincludedWals
            + ", first backed up in " + incrBackupId + ": " + offlineHostWals));
    }
  }

  private static List<String> walsOfHost(BackupInfo backupInfo, String host) {
    List<String> wals = backupInfo.getIncrBackupFileList();
    if (wals == null) {
      return List.of();
    }
    return wals.stream()
      .filter(wal -> host.equals(BackupUtils.parseHostNameFromLogFile(new Path(wal)))).toList();
  }

A consequence is that old WALs can be backed up again, which can corrupt data when doing a recovery.

Possible fix, use the same defintion as FullBackupTableClient (but didn't verify this):

  Map<String, Long> rollsBefore = readRegionServerLastLogRollResult();
  BackupUtils.logRoll(conn, backupInfo.getBackupRootDir(), conf);
  Map<String, Long> rollsAfter = readRegionServerLastLogRollResult();
  // active: rollsAfter.get(h) != null && !rollsAfter.get(h).equals(rollsBefore.get(h))

[hgromer]

Hmm, yeah good callout, will do

[DieterDePaepe]

These tests don't demonstrate the actual data loss scenario from the ticket, just the changed bookkeeping.

[hgromer]

I've updated the tests to actually run backups + restores and assert that data wasn't lost. These new tests fail without the current change set

[DieterDePaepe]

I still argue to not delete this check, but to change it to if (newTimestamp != null && currentLogTS > newTimestamp) instead. I think the removal (as suggested in the PR) can lead to data loss. This adjusted version fixes the original data loss issue and does not break the newly added tests.

Two things have to occur on a region server during an incremental backup to cause data loss:

1. Two quick wall rolls. The backup's own roll creates a new WAL, C. Before the backup finishes listing oldWALs, the region server has to roll twice more: C → T, then T → U. Only then is T closed and eligible for archiving.
2. T is archived while C isn't. cleanOldLogs archives any closed WAL whose regions have all flushed past its edits. If C holds edits for a region that T doesn't touch, and that region hasn't flushed yet, T gets archived first.

Of these 2 conditions, I expect (2) to occur commonly. For (1): The window runs from the backup's roll to the end of the oldWALs listing, and that's normally a few seconds. Two rolls might fit in it when one of these holds:

• Heavy ingest. By default a WAL rolls when it reaches 0.5 × (2 × HDFS block size), which is about 128 MB. A region server ingesting around 50–100 MB/s rolls every 1–3 seconds. The hourly time-based roll (hbase.regionserver.logroll.period) is far too slow to matter.
• A slow listing. getLogFilesForNewBackup runs one listStatus per region server directory, then a recursive listing of oldWALs. BackupLogCleaner keeps every WAL that a backup root still needs, so with backups enabled oldWALs can hold tens or hundreds of thousands of files. A large cluster or a slow NameNode can stretch the window to tens of seconds.

A rare case, but one that can occur on any incremental backup on any region server. For a large cluster with daily backups, it is bound to happen eventually. The result is a WAL that never gets included in a backup, leading to data loss when restoring.

I agree that simpler is better, and I wished lots of the backup code was simpler, but in this case the complexity is worth it.

Example test case (breaks on the current PR, succeeds on the current PR + suggested adjustment):

// paste me in TestIncrementalBackupManager 

  /**
   * WALs can be archived out of order. This test sets up the WAL directories as an incremental
   * backup would find them if, after its log roll, a newer WAL got archived while an older one was
   * still in the WALs directory. The older WAL must still end up in a backup.
   */
  @Test
  public void testOutOfOrderArchivedWALDoesNotSkipOlderWAL() throws Exception {
    List<TableName> tables = List.of(table1);
    HRegionServer rs = TEST_UTIL.getMiniHBaseCluster().getRegionServer(0);
    ServerName serverName = rs.getServerName();
    Path walRootDir = CommonFSUtils.getWALRootDir(conf1);
    FileSystem fs = walRootDir.getFileSystem(conf1);

    try (Connection conn = ConnectionFactory.createConnection(conf1);
      BackupAdminImpl backupAdmin = new BackupAdminImpl(conn)) {
      String fullBackupId =
        backupAdmin.backupTables(createBackupRequest(BackupType.FULL, tables, BACKUP_ROOT_DIR));
      assertTrue(checkSucceeded(fullBackupId));

      // Both test WALs are newer than any WAL that exists at this point, so they are newer than the
      // WAL reported by the log roll of the next incremental backup.
      long olderWALTs = EnvironmentEdgeManager.currentTime() + 1;
      long newerWALTs = olderWALTs + 1;
      Path walDir =
        new Path(walRootDir, AbstractFSWALProvider.getWALDirectoryName(serverName.toString()));
      Path olderWAL =
        new Path(walDir, serverName.toString() + BackupUtils.LOGNAME_SEPARATOR + olderWALTs);
      Path archiveDir = new Path(walRootDir,
        AbstractFSWALProvider.getWALArchiveDirectoryName(conf1, serverName.toString()));
      Path newerArchivedWAL =
        new Path(archiveDir, "wal" + BackupUtils.LOGNAME_SEPARATOR + newerWALTs);
      fs.create(olderWAL).close();
      fs.mkdirs(archiveDir);
      fs.create(newerArchivedWAL).close();

      try {
        List<String> firstBackupFiles;
        try (IncrementalBackupManager manager = new IncrementalBackupManager(conn, conf1)) {
          BackupInfo backupInfo = manager.createBackupInfo("backup_incr_1",
            BackupType.INCREMENTAL, tables, BACKUP_ROOT_DIR, -1, -1, false, false);
          Map<String, Long> boundaries = manager.getIncrBackupLogFileMap();
          manager.writeRegionServerLogTimestamp(backupInfo.getTables(), boundaries);
          firstBackupFiles = backupInfo.getIncrBackupFileList();
        }

        // Roll once more, so the log roll of the next backup reports a WAL that is newer than both
        // test WALs.
        TEST_UTIL.waitFor(30_000, () -> EnvironmentEdgeManager.currentTime() > newerWALTs);
        rs.getWalRoller().requestRollAll();
        rs.getWalRoller().waitUntilWalRollFinished();

        List<String> secondBackupFiles;
        try (IncrementalBackupManager manager = new IncrementalBackupManager(conn, conf1)) {
          BackupInfo backupInfo = manager.createBackupInfo("backup_incr_2",
            BackupType.INCREMENTAL, tables, BACKUP_ROOT_DIR, -1, -1, false, false);
          manager.getIncrBackupLogFileMap();
          secondBackupFiles = backupInfo.getIncrBackupFileList();
        }

        assertTrue(
          firstBackupFiles.contains(olderWAL.toString())
            || secondBackupFiles.contains(olderWAL.toString()),
          "WAL " + olderWAL + " was not included in any backup. First backup: " + firstBackupFiles
            + ", second backup: " + secondBackupFiles);
      } finally {
        fs.delete(olderWAL, false);
        fs.delete(newerArchivedWAL, false);
      }
    }
  }

[hgromer]

@DieterDePaepe I believe I've addressed all your comments, thanks for being so thorough, let me know what you think

[hgromer]

If a server crashes as we're doing log rolls + backups, its WALs will sit in the /WALs directory until that split is finished. We need to have a concept of WALs that were "held back", which are set as LogFileSelection#pending.

We will keep the boundary at before the oldest held back WAL, ensuring that the log cleaner doesn't delete it. These WALs will be backed up in the next incremental.

[hgromer]

Sadly, I can't think of a much better way to accomplish consistency here. The HMaster may be initializing when we query for live RS, and unfortunately that means we may get a partial list of RS back.

This sanity check is a little brittle, but I believe that it's robust enough to do what we need. Given that we just rolled WAL files, if we don't see any of those hosts in the live RS list we got back from the HMaster, we can likely assume the HMaster didn't return a comprehensive list, and we should abort.