Siyao Meng created HDDS-16882:
---------------------------------
Summary: Recon swallows the RocksDB open failure of a fetched OM
DB snapshot, logs success and keeps using its deleted previous OM DB
Key: HDDS-16882
URL: https://issues.apache.org/jira/browse/HDDS-16882
Project: Apache Ozone
Issue Type: Bug
Reporter: Siyao Meng
Attachments: CR-18-recon-report-failed-open-of-fetched-om-db.patch,
TestBugCR18ReconOmDbOpenFailureReportedAsSuccess.java
h3. Mechanism
{{ReconOmMetadataManagerImpl.updateOmDB}} opens the new snapshot through
{{initializeNewRdbStore}}, which catches the {{IOException}} from
{{DBStoreBuilder.build}}, logs "Unable to initialize Recon OM DB snapshot
store." and returns normally. The store is not replaced, so Recon keeps its
previous OM DB handle, whose directory
{{OzoneManagerServiceProviderImpl.getOzoneManagerDBSnapshot}} deleted at the
start of the fetch. {{updateReconOmDBWithNewSnapshot}} then logs "Successfully
updated Recon OM DB with new snapshot.", increments {{snapshotDownloadSuccess}}
and returns true.
{{executeFullSnapshot}} continues as if the snapshot had been installed and
queues the task reinitialization. That creates a RocksDB checkpoint of the
previous DB, which fails because its directory is gone ({{NotFound: ... Failed
to createCheckpoint}}). Only this second failure marks the run as failed: the
snapshot task status becomes -1, health turns false and
{{GET_OM_DB_SNAPSHOT_FAILED}} is set, with "Failed to queue reinitialization
event for manual trigger (result: RETRY_LATER)" as the logged reason. The catch
dates from HDDS-1233; the same code is in 2.2.1.
h3. Trigger
Any full OM DB fetch whose result RocksDB cannot open, for example a snapshot
with a truncated or missing SST, or a disk that fills up while RocksDB opens
it. Only two cases were run: a snapshot whose largest SST is cut in half
({{Corruption: ... Failed to open}}) and a {{CURRENT}} file that names a
missing MANIFEST. On master a truncated SST can come from a retry after a
failed untar (HDDS-16880).
h3. Impact
* The log and the {{snapshotDownloadSuccess}} metric report a successful
update. The failure that is reported instead is the task reinitialization, and
its message blames the previous DB ("the on-disk OM DB may be incomplete or
corrupt").
* Recon keeps serving the previous OM DB handle. Reads still work from the open
files and writes are accepted, so the following delta updates are applied to
it, but a flush of that DB fails because its directory is gone (run with a
direct write and flush).
* Because the reinitialization failed, {{ReconTaskControllerImpl}} sets its
task failure flag, and {{consumeOMEvents}} stops passing delta events to the
Recon tasks until a reinitialization is queued (from code, not run). Each
following sync retries the reinitialization against the previous DB and fails
again. After at most six failed attempts it falls back to a full fetch, which
recovers (run: six sync cycles, about 30 seconds at the default 5 s
{{ozone.recon.om.snapshot.task.interval.delay}}). If the delta updates still
fail, for example with {{SequenceNumberNotFoundException}}, the next sync
fetches again right away (run).
* No effect on OM.
h3. Reproduction
Deterministic, unmodified source.
[^TestBugCR18ReconOmDbOpenFailureReportedAsSuccess.java]
({{hadoop-ozone/recon}}) runs Recon's own {{ReconOmMetadataManagerImpl}},
{{OzoneManagerServiceProviderImpl}} and {{ReconTaskControllerImpl}} against a
real OM RocksDB. Recon starts from a snapshot it fetched earlier; only the
download is replaced, and it returns a copy of an OM checkpoint whose largest
SST is cut in half. The tests assert the correct behaviour, so they fail while
the defect is present:
* {{updateReconOmDBWithNewSnapshot}} returns true, while Recon's store is still
the previous one, whose directory no longer exists.
* A full sync through {{syncDataFromOM}} (delta updates rejected with
{{SequenceNumberNotFoundException}}) queues the task reinitialization against
the previous DB.
With the patch both pass.
h3. Patch
[^CR-18-recon-report-failed-open-of-fetched-om-db.patch], against
a6b7bdb937109ba2893688b41a89470bc95c88cf. It also applies to master at
6818707698c.
{{initializeNewRdbStore}} no longer catches the exception. {{start}} keeps the
catch, so Recon still starts without an OM DB when its last known snapshot
cannot be opened, and then fetches a new one. {{updateOmDB}} now deletes the
snapshot directory that failed to open and rethrows, keeping the previous store
open, and {{updateReconOmDBWithNewSnapshot}} logs "Unable to refresh Recon OM
DB Snapshot." with the RocksDB error, counts {{snapshotDownloadFailures}} and
returns false. {{executeFullSnapshot}} then marks the run as failed without
queuing the reinitialization. This is how a failed download is already handled,
and as after a failed download no {{om.snapshot.db_<ts>}} is left on disk, so a
restart finds no OM DB snapshot and fetches a new one.
The deletion matters because the Recon tasks now keep consuming delta updates
after the failed open. If the open failure was transient (for example no file
descriptors or disk space left), a restart would otherwise open the left over
snapshot, the OM DB would be back behind the tasks, and the next delta updates
would reach the tasks a second time (from code, not run end to end).
Recovery is then also the same as after a failed download. If the delta updates
still fail, for example with {{SequenceNumberNotFoundException}}, the next sync
fetches again (run). If the full fetch came from failed task reinitializations,
the following syncs first retry the reinitialization up to six times, as today.
If the trigger was a transient delta failure, Recon goes on applying delta
updates to the previous handle, the Recon tasks keep receiving events, and
health shows {{GET_OM_DB_SNAPSHOT_FAILED}} until a full fetch succeeds. Today
the failing reinitialization forces that fetch within six cycles, about 30
seconds at the default interval. With the patch it happens at the next delta
failure, the first failed flush of the previous DB, or a restart, so on a
cluster with little OM write traffic there is no bound (run: no new fetch in
ten cycles). Until then the deleted files of the previous DB stay allocated.
That any failed full fetch leaves Recon on a DB whose directory is deleted is
not changed here.
Covered by {{testUpdateReconOmDBWithUnreadableSnapshot}} in the existing
{{TestOzoneManagerServiceProviderImpl}} and {{testUnreadableSnapshot}} in the
existing {{TestReconOmMetadataManagerImpl}} (which also checks that {{start}}
still skips an unreadable snapshot). Without the change they fail with
"expected: <false> but was: <true>" and "Expecting code to raise a throwable.".
Both also check that the snapshot directory that failed to open is deleted;
without the deletion they fail with "expected: <0> but was: <1>" and "Expecting
file: ... not to exist". With it, the Recon module unit tests pass (937 run;
the only failures are a Derby performance test,
{{TestUnhealthyContainersDerbyPerformance}}, that times out on the test machine
and fails the same way without the change), and checkstyle is clean.
Related: HDDS-16880 (a retry after a failed untar builds a snapshot with a
truncated SST), HDDS-9367 (open, RocksDB error handling in Recon in general),
HDDS-15995 (Recon SCM DB used after its directory was renamed).
Found by code review of the OM Ratis snapshot (checkpoint) install paths, as
part of the TLA+ verification effort under HDDS-15926, on commit
a6b7bdb937109ba2893688b41a89470bc95c88cf. Checked against HDDS issues and
apache/ozone pull requests for duplicates before filing. The attached patch is
a proposal for review. Generated with Specula (Claude Opus 5.5).
--
This message was sent by Atlassian Jira
(v8.20.10#820010)
---------------------------------------------------------------------
To unsubscribe, e-mail: [email protected]
For additional commands, e-mail: [email protected]
