Siyao Meng created HDDS-17395:
---------------------------------
Summary: Restarted BackgroundService can stop for good or run
batches from its old executor after a forced shutdown
Key: HDDS-17395
URL: https://issues.apache.org/jira/browse/HDDS-17395
Project: Apache Ozone
Issue Type: Bug
Reporter: Siyao Meng
h3. Mechanism
{{BackgroundService.PeriodicalTask.run}} waits for the previous batch with
{{future.join()}} on the instance field {{future}}, then calls {{getTasks()}}
and submits every task with {{CompletableFuture.runAsync(..., exec)}}, folding
each task's future into {{future}}. {{join()}} ignores interrupts. The submit
reads the field {{exec}}, not the executor the run was scheduled on.
{{shutdown()}} calls {{exec.shutdown()}}, waits 60 seconds in
{{awaitTermination}}, and calls {{shutdownNow()}} when that wait runs out or
the calling thread is interrupted. {{start()}} creates a new executor when the
old one is shut down, but keeps {{future}}. Three things follow:
* {{shutdownNow()}} removes the queued {{runAsync}} wrappers from the executor
without running them, so their futures never complete, and neither does
{{future}}. The first run of the restarted service waits on it forever.
* A run that was waiting in {{join()}} during the restart is not stopped by
{{shutdownNow()}}. When the slow task ends, it calls {{getTasks()}} and submits
into {{exec}}, which is now the new executor, while the new executor's own run
does the same.
* Since HDDS-14645, {{shutdown()}} calls {{exec.shutdown()}} outside the
monitor that the submit loop holds, so it can land between {{getTasks()}} and
the submit. {{runAsync}} then throws {{RejectedExecutionException}}, which ends
the run with no log line; the polled task is lost and the rest of the batch is
abandoned.
h3. Trigger
{{BlockDeletingService.updateAndRestart}} and
{{DirectoryDeletingService.updateAndRestart}} are the only callers that restart
a service instance in place. They run when {{ozone admin reconfig}} changes
{{hdds.datanode.block.deleting.service.interval}}
({{ozone.block.deleting.service.interval}} in 2.1 and 2.2),
{{ozone.block.deleting.service.timeout}} or
{{ozone.block.deleting.service.workers}} on a datanode, or
{{ozone.directory.deleting.service.interval}} or
{{ozone.thread.number.dir.deletion}} on an OM. The restart reaches
{{shutdownNow()}} when the tasks still running or queued at that moment do not
finish within 60 seconds. The interrupt path of {{shutdown()}} exists in the
code, but nothing in Ozone interrupts the reconfiguration thread. After a plain
{{exec.shutdown()}} the queued tasks still run, so a task is dropped only if it
has not started when the 60 seconds run out.
For {{BlockDeletingService}}, a batch has one task per container with pending
deletes, up to {{hdds.datanode.block.deleting.limit.per.interval}} (20000
blocks by default) in total, so on a datanode with a deletion backlog it often
has more tasks than the 10 default workers. {{BlockDeletingTask}} does not
check for interrupts. Tasks are dropped when such a batch is still running 60
seconds after the reconfiguration started, which is also when an operator is
likely to retune deletion. This is argued from the code, not measured on a
datanode. {{DirectoryDeletingService}} runs one worker since HDDS-16164, but
its own {{shutdown()}} first shuts its deletion pool down, after which queued
tasks return quickly, so it reaches {{shutdownNow()}} only when a task outlives
that as well (argued from the code).
h3. Impact
All of the following were run on unmodified source against
{{BackgroundService}} through its public methods, with a test subclass that
restarts in the same order as {{updateAndRestart}}. No production service was
run.
* *Restarted service never runs again.* Pool size 1, first batch of two tasks,
one running and one queued. After a restart whose {{shutdown()}} was
interrupted, and after one whose 60 second wait really ran out, the restarted
service called {{getTasks()}} zero times in 3 seconds at a 50 ms interval, with
its only worker parked in {{CompletableFuture.join}} from
{{PeriodicalTask.run}}. Nothing reassigns {{future}}, so this lasts until the
process restarts, and by code reading every later {{shutdown()}} waits the full
60 seconds for the parked thread. For {{BlockDeletingService}} this means block
deletion on that datanode stops while the service still counts as started.
[^TestBugMC1RestartAfterForcedShutdown.java]
* *Two batches at once.* Pool size 2, one task holding a worker through the
restart and the next run waiting for it. After the task ended, both the old
executor's run and the new executor's run fetched a batch, and the two batches
ran at the same time on the new executor, against the class contract of one
batch per interval. In {{BlockDeletingService}} the duplicate batch is absorbed
({{getTasks()}} only reads, and each task re-reads the container under its
write lock), so this is a latent defect today (argued from the code).
[^TestBugMC2StaleLoopOverlapsRestartedBatch.java]
* *Single worker deadlock.* Pool size 1 and two restarts that both reach
{{shutdownNow()}}: the run that survived the second restart submitted its task
into the third executor, behind that executor's next run, which then waited in
{{join()}} for a task that could only run on its own thread. {{getTasks()}} was
not called again. The test orders the steps with latches, so it shows that the
interleaving exists, not how often it occurs.
[^TestBugMC3SingleWorkerSelfDeadlock.java]
* *Batch dropped without a log line.* A {{shutdown()}} that landed after
{{getTasks()}} had returned four tasks: one task was polled and neither ran nor
was handed back, three were abandoned, and only the start and shutdown INFO
lines were logged. The services restarted in place rebuild their batch from
durable state on the next run, and the services whose {{getTasks()}} reserves
state ({{KeyLifecycleService}}, {{DiskBalancerService}}) are only stopped
together with their owner and then discarded, so no wrong result follows today
(argued from the code). [^TestBugMC4ShutdownDuringSubmit.java]
h3. Reproduction
The four attached JUnit classes belong in
{{hadoop-hdds/framework/src/test/java/org/apache/hadoop/util/}} (Maven command
in each class comment) and pass on unmodified source while the bug is present.
They only use {{start()}}, {{shutdown()}}, {{setInterval()}} and
{{getExecutorService()}}. Except for one case of the first class, the forced
shutdown is reached by interrupting the restarting thread, which takes the same
{{shutdownNow()}} path as a 60 second wait that runs out, without waiting for
it.
h3. Patch
[^MC-1-complete-dropped-tasks-and-stop-stale-background-service-loops.patch],
against 9c3e5477ffb9f41da639051aaa5e9d7bd8b53fe4. It also applies to master at
c521a16af75.
All changes are in {{BackgroundService}}:
* {{start()}} schedules a new {{PeriodicalTask}}, which keeps the executor it
was scheduled on. A run whose executor has been shut down returns after
{{join()}} without calling {{getTasks()}}, and the submit loop stops when its
executor is shut down. So no run of an old executor reaches the new one.
* Each submitted task registers its future in a set kept per executor and
removes it when it starts. After {{shutdownNow()}}, {{shutdown()}} completes
the futures still in the set, which belong to the tasks that were dropped and
will never run. A task that had started is still waited for, so the restarted
service does not run its first batch next to a task of the old executor that is
still running.
* {{shutdown()}} calls {{exec.shutdown()}} under the monitor, so it cannot land
halfway through the submit loop. {{awaitTermination}} stays outside the
monitor, as HDDS-15429 requires. {{exec.shutdown()}} does not wait for workers,
and the submit loop already takes the executor's lock while holding the
monitor, so this adds no new lock order. A batch fetched before the shutdown
and not submitted is logged at INFO with its size.
A service that is never restarted and whose shutdown finishes in time behaves
as before. Resetting {{future}} in {{start()}} was not chosen: the new batch
would then run next to tasks of the old executor that are still running, and a
run of the old executor parked on a dropped task would stay parked.
Covered by three new cases in the existing {{TestBackgroundService}}:
{{testRestartAfterForcedShutdownSkipsDroppedTasks}},
{{testLoopOfReplacedExecutorDoesNotFetchTasks}} and
{{testShutdownWhileFetchingTasksDropsWholeBatch}}. Without the change they fail
with a {{TimeoutException}} (the restarted run parked in {{join()}}),
"Expecting AtomicInteger(2) to have value: 1" and "expected: 4 but was: 3".
With it they pass, the existing suites of the {{BackgroundService}} subclasses
in {{hadoop-hdds/container-service}} and {{hadoop-ozone/ozone-manager}} pass,
checkstyle is clean, and the four attached classes no longer show the bug.
Found by TLA+ model checking and code review of the BackgroundService restart
and shutdown paths and the reconfiguration callback handling under HDDS-15926,
on commit 9c3e5477ffb9f41da639051aaa5e9d7bd8b53fe4. Checked against HDDS issues
and apache/ozone pull requests for duplicates before filing. Related but not
duplicates: HDDS-15429 (monitor deadlock in {{updateAndRestart}}, whose fix
stopped calling {{shutdown()}} under the monitor), HDDS-14645 (moved
{{exec.shutdown()}} and {{awaitTermination}} out of the monitor), HDDS-14020
(open, the same lock shared by shutdown and the submit loop), HDDS-13773 (open,
timeout and interrupt for background tasks), HDDS-14236 (fixed delay scheduling
of {{PeriodicalTask}}, in progress, its PR closed), HDDS-16949 (an exception
from {{getTasks()}} cancelled the periodic task) and HDDS-17296 (a replaced
{{DirectoryDeletingService}} is restarted by its reconfiguration callback). The
attached patch is a proposal for review. Generated with Specula (Claude Opus
5.5).
--
This message was sent by Atlassian Jira
(v10.3.26#10030026)
---------------------------------------------------------------------
To unsubscribe, e-mail: [email protected]
For additional commands, e-mail: [email protected]
