hellodml commented on issue #18570:
URL:
https://github.com/apache/dolphinscheduler/issues/18570#issuecomment-5352934150
> We should use `ExceptionUtils.throwableOfType(...)` to judge if the
exception is `CommandDuplicateHandleException` in
`CommandEngine.bootstrapError`.
Thanks for the careful review — you are right, and my original framing of the
root cause was wrong. Here is a correction plus the evidence you asked for.
## 1. Correction: slot = -1 is NOT the blocker
I re-examined the logs from the 100-minute outage (2026-08-19 09:40–11:20,
container TZ Asia/Jakarta). Counting per hour:
| hour | `slot (-1` | `Do rebalance failed` | `CommandEngine:[128]` overload
|
|------|-----------:|----------------------:|-------------------------------:|
| 09 | 39 | 56 | 4325
|
| 10 | **0** | 120 | **10791**
|
| 11 | 20 | 92 | 7471
|
During hour 10 — the worst hour, zero commands consumed — `slot (-1` does not
appear **even once**. So slot invalidation is incidental noise, not the
cause.
The actual blocker is exactly the path you described:
```
INFO [MasterCommandLoopThread] MasterServerLoadProtection:[56] -
OverLoad: the workflow instance count: 25 exceeds the
maxConcurrentWorkflowInstances
WARN [MasterCommandLoopThread] CommandEngine:[128] -
The current server is overload, cannot consumes commands.
```
(3597 occurrences of the WARN in hour 10 alone)
Please disregard the "self-starvation via slot rebalance" theory in the issue
body. I also accept your objection to my suggested fix #2 — preserving a
stale
slot would indeed create overlapping assignments in a multi-master
deployment.
@zhang-arvin — this also means #18572 would not have fixed the incident, and
I
am sorry for sending you down that path with a wrong issue description. That
PR
keeps the slot when the master is BUSY, but during the worst hour of our
outage
`slot (-1` never appears in the logs at all, while
`CommandEngine:[128] "The current server is overload, cannot consumes
commands"`
appears 3597 times. Command consumption is gated by the overload check
*before*
the slot is ever used, so preserving the slot would not have let the master
resume. Thanks for the quick turnaround regardless.
## 2. The missing link: why the count never drops
Your model says the master recovers once the active workflow count falls
below
the threshold. That is correct in principle. In our incident **the count
never
moved**. Extracting every logged count value:
```
hour 09: 21 ×36, 22 ×8, 23 ×22, 24 ×30, 25 ×2665
hour 10: 25 ×7194 <- nothing but 25, for the whole hour
hour 11: 22 ×5, 24 ×1, 25 ×2236, 26 ×3, 29 ×7
```
Pinned at exactly 25 (limit was 20 at the time). 25 `WorkflowExecuteRunnable`
instances were registered and none of them ever completed.
What those wedged runnables look like in the metadata DB — of the 573
workflow
instances created during the outage window:
```
instances with any task ever dispatched (host IS NOT NULL) : 0
instances with tasks created but never dispatched : 20
instances with NO task instance rows at all : 553
```
So the runnables were stuck **before task creation**, not waiting on workers.
Recovery required a container restart; the overload state never cleared on
its own.
## 3. Evidence you requested
### Full exception chain (verbatim)
```
java.util.concurrent.CompletionException:
org.apache.dolphinscheduler.server.master.engine.exceptions.CommandDuplicateHandleException:
The command: 520266 has already been handled
at
java.util.concurrent.CompletableFuture.encodeThrowable(CompletableFuture.java:273)
at
java.util.concurrent.CompletableFuture.completeThrowable(CompletableFuture.java:280)
at
java.util.concurrent.CompletableFuture.uniApply(CompletableFuture.java:618)
at
java.util.concurrent.CompletableFuture$UniApply.tryFire(CompletableFuture.java:591)
at
java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:488)
at
java.util.concurrent.CompletableFuture$AsyncSupply.run(CompletableFuture.java:1609)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
Caused by:
org.apache.dolphinscheduler.server.master.engine.exceptions.CommandDuplicateHandleException:
The command: 520266 has already been handled
at
org.apache.dolphinscheduler.server.master.engine.workflow.execution.WorkflowExecutionFactory.deleteCommandOrThrow(WorkflowExecutionFactory.java:76)
at
org.apache.dolphinscheduler.server.master.engine.workflow.execution.WorkflowExecutionFactory.createWorkflowExecuteRunnable(WorkflowExecutionFactory.java:51)
at
org.apache.dolphinscheduler.server.master.engine.workflow.execution.WorkflowExecutionFactory$$FastClassBySpringCGLIB$$46c24446.invoke(<generated>)
at
org.apache.dolphinscheduler.server.master.engine.workflow.execution.WorkflowExecutionFactory$$EnhancerBySpringCGLIB$$7ee93ae2.createWorkflowExecuteRunnable(<generated>)
```
**This confirms your hypothesis exactly** — it arrives at `bootstrapError`
wrapped in `CompletionException`, so a direct `instanceof` check cannot see
it.
`ExceptionUtils.throwableOfType(...)` is the right fix.
### Repeated command IDs
```
2026-08-19 00:15 command 518447 workflow instance 515163
2026-08-19 02:50 command 519296 workflow instance 516012
2026-08-19 02:50 command 519297 workflow instance 516013
2026-08-19 05:40 command 520266 workflow instance 516982
2026-08-19 05:40 command 520267 workflow instance 516983
```
Millisecond timeline for command 520266:
```
05:40:01.071 INFO CommandEngine:[190] - Success bootstrap command { "id" :
520266, ... }
05:40:01.082 WARN CommandEngine:[204] - Failed bootstrap command { "id" :
520266, ... }
05:40:01.085 INFO CommandEngine:[211] - Set workflow instance 516982 state
to FAILURE
05:40:01.089 INFO CommandEngine:[214] - Move command 520266 to error
command table
05:40:01.131 INFO AbstractWorkflowLifecycleEventHandler:[47] - Begin fire
workflow ...
05:40:01.136 INFO TaskGroupCoordinator:[365] - Success insert
TaskGroupQueue: taskId=539177
05:40:01.139 INFO AbstractTaskStateAction:[272] - using taskGroup, success
acquire taskGroup slot
<-- 12 log lines total for this instance; nothing further ever
happens
```
Note lines 5–7 execute **after** the instance was set to FAILURE — the first
(successful) execution's event bus keeps running and even acquires a task
group
slot, while the task itself is never dispatched.
Downstream consequence in the same hour:
```
java.lang.UnsupportedOperationException: The WorkflowInstance: 516982 state
is FAILURE, no need to notify
```
### Master addresses
Single master, standalone Docker, no multi-master:
```
/nodes/master/172.18.0.2:5678
/nodes/master-coordinator
```
All workflow instances in the affected period carry `host = 172.18.0.2:5678`.
So this reproduces with **one** master — no slot contention between peers
involved.
## 4. Frequency, and why these instances are never reclaimed
Measured over 11 hours on a steady workload (~340 `Success bootstrap` per
hour):
| hour | Success bootstrap | Failed bootstrap |
|------|------------------:|-----------------:|
| 00 | 337 | 1 |
| 01 | 337 | 0 |
| 02 | 338 | 2 |
| 03 | 339 | 0 |
| 04 | 342 | 0 |
| 05 | 344 | 2 |
| 06 | 341 | 0 |
| 07 | 351 | 0 |
| 08 | 341 | 0 |
| 13 | 397 | 0 |
Roughly 0.2% of SCHEDULER commands, always in the same minute as a cron
batch.
The stranded task instances are **never reclaimed**. Our DataX tasks use
`timeout_notify_strategy = 0` (WARN only), so DS emits a "Task Timeout Warn"
alert at the timeout and then leaves the task in `state=0` indefinitely. We
have
observed one sitting at `state=0` for over 23 hours. A reliable fingerprint
for
finding them in the metadata DB:
```sql
SELECT * FROM t_ds_task_instance
WHERE state = 6 AND host IS NULL AND log_path IS NULL
AND TIMESTAMPDIFF(SECOND, start_time, end_time) = <task timeout in
seconds>;
```
## 5. A second, easier-to-reproduce trigger for the same class of bug
Running **individual tasks** (`command_type = 12`, EXECUTE_TASK) in quick
succession against the same already-finished workflow instance hits the
adjacent
registration guard:
```
java.lang.IllegalStateException: WorkflowExecuteRunnable(514408/<name>)
already registered at WorkflowEventBusFireWorker
at
com.google.common.base.Preconditions.checkState(Preconditions.java:821)
at
org.apache.dolphinscheduler.server.master.engine.WorkflowEventBusFireWorker.registerWorkflowEventBus(WorkflowEventBusFireWorker.java:66)
at
org.apache.dolphinscheduler.server.master.engine.WorkflowEventBusCoordinator.registerWorkflowEventBus(WorkflowEventBusCoordinator.java:50)
at
org.apache.dolphinscheduler.server.master.engine.command.CommandEngine.bootstrapWorkflowExecution(CommandEngine.java:183)
```
Steps:
1. take any finished workflow instance with several serial tasks
2. in the UI, run a single task from it; wait for it to finish
3. run the next task ~3 minutes later
4. repeat — the third or fourth throws the above, and its task stays
`state=0` forever
Both paths fail inside `CommandEngine.bootstrapWorkflowExecution` and both
leave
a task (and its task group slot) stranded. If the
`ExceptionUtils.throwableOfType`
fix also covers the `IllegalStateException: already registered` case, it may
resolve both.
Happy to run any additional diagnostics on this instance — it reproduces the
0.2% case several times a day.
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: [email protected]
For queries about this service, please contact Infrastructure at:
[email protected]
