loustler commented on issue #11679:
URL: https://github.com/apache/seatunnel/issues/11679#issuecomment-5229110726
Thanks both. @SEZ9 asked for the logs, so I pulled the full job logs for
both legs and went through them properly. Two things came out of that: **I have
to correct two statements in my own issue description**, and the corrected
picture is a good deal sharper than what I originally reported — it points at a
specific method.
Everything below is from run `31100290272` on
`claude/dev-baseline-paimon-s3` @ `80fe7dc77` (`origin/dev` + a three-line
comment, added only so the `changes` filter would schedule
`paimon-connector-it`). Log excerpts are folded; open the one you want.
---
## First, two corrections to the issue description
Steps 3 and 4 of my "Observed sequence" describe @DanielLeens's trace of run
`31077218606` (the #11648 head), which I paraphrased when filing this without
re-deriving them from my own baseline run. On my baseline run neither holds:
| I wrote | Actually, on `dev` @ `80fe7dc77`, JDK 8 leg |
|---|---|
| "`SubPlan.handleCheckpointError()` moves the pipeline `RUNNING ->
CANCELING`. The pipeline is resubmitted and fails identically, repeatedly." |
There is **no** `CANCELING` transition anywhere, and no repeated resubmission.
`handleCheckpointError` logs `checkpoint have error, cancel the pipeline` — and
the pipeline never logs anything again. |
| "the coordinator's own periodic status dump keeps reporting
`pendingJobCount / … = 0` … every ~10s from this point onward, for the next ~2
hours" | The dump does **not** keep reporting. `CoordinatorService`'s 10-second
print stops permanently 6 seconds after the error. The last all-zero `Job info
detail` I quoted is from **13:11:05 — before the failure at 13:11:09**, so it
was never evidence of anything. |
Both were my error, not the reviewer's — his trace was accurate for the run
he was looking at. Sorry for putting them in the issue as if they were baseline
observations. The corrected sequence follows, and it is a stronger case, not a
weaker one.
---
## What actually happens
```
13:11:09 NoPrivilegeException: User paimon doesn't have privilege SELECT
on table seatunnel_namespace11.st_test
13:11:09,896 WARN SubPlan - Pipeline [(1/1)] checkpoint have error, cancel
the pipeline
13:11:09,916 INFO TaskExecutionService - task 1000300000000 error with
exception
13:11:09,918 INFO LoggingEventHandler -
ReaderCloseEvent(jobId=1137734595555360769)
<- the last mention of this job anywhere in the log
13:11:15,786 INFO CoordinatorService - Thread Pool Status
<- the last periodic print, ever
13:11:20,210 WARN SlowOperationDetector - Slow operation detected:
SubPlan.updatePipelineState(SubPlan.java:345)
SubPlan.handleCheckpointError(SubPlan.java:644)
JobMaster.handleCheckpointError(JobMaster.java:770)
CheckpointManager.handleCheckpointError(CheckpointManager.java:219)
... CheckpointErrorReportOperation.runInternal
... com.hazelcast...OperationThread.executeRun
13:12:02,527 INFO CoordinatorService - clean job log, jobId:
1137734545932550145
<- the last CoordinatorService line of any kind
13:10:45 → 15:22:22 Create/Release classloader for job 1137734545932550145
(the job that
already FINISHED), every 5 s, 3,120 cycles, for 2 h 11
m
15:22:25 ##[error]The operation was canceled.
15:22:25 Terminate orphan process: pid (14667) (java) / (15448) (sh) /
(15450) (java)
```
After 13:12:03 the window contains **one** line that is not classloader
churn, out of ~6,270. No ERROR or WARN of any kind after 13:11:21. The engine
does not crash, does not retry, does not report — it simply stops.
Note the last two lines: the runner has to kill an orphaned `sh` and two
`java` processes. That is the `seatunnel.sh` client the test was blocked on,
still alive after 2 hours.
<details>
<summary><b>Log — the failure and the cancel decision
(13:11:09)</b></summary>
The container's STDOUT and STDERR are relayed by separate consumers, so
don't read anything into the sub-second interleaving between the STDERR stack
and the STDOUT engine lines.
```
[1137734595555360769] 13:11:09,901 STDERR:
org.apache.seatunnel.common.utils.SeaTunnelException:
org.apache.paimon.privilege.NoPrivilegeException: User paimon doesn't
have privilege SELECT
on table seatunnel_namespace11.st_test
at
org.apache.paimon.privilege.PrivilegeCheckerImpl.assertCanSelect(PrivilegeCheckerImpl.java:44)
at
org.apache.paimon.privilege.PrivilegedFileStoreTable.newScan(PrivilegedFileStoreTable.java:202)
...
at
org.apache.seatunnel.engine.server.task.SourceSeaTunnelTask.init(SourceSeaTunnelTask.java:76)
at
org.apache.seatunnel.engine.server.TaskExecutionService$BlockingWorker.run(TaskExecutionService.java:1077)
[1137734595555360769] 13:11:09,896 WARN SubPlan - Job
paimon_to_paimon_with_s3_with_privilege.conf
(1137734595555360769), Pipeline: [(1/1)] checkpoint have error, cancel
the pipeline
[1137734595555360769] 13:11:09,916 INFO TaskExecutionService - task
1000300000000 error with exception
[] 13:11:09,918 INFO LoggingEventHandler - log event:
ReaderCloseEvent(createdTime=1786021869917,
jobId=1137734595555360769, eventType=LIFECYCLE_READER_CLOSE)
```
`checkpoint have error, cancel the pipeline` is the first line of
`SubPlan.handleCheckpointError()`. Nothing after it — no `turned from state ...
to CANCELING`, no `will end with state`, no `state process is stop` — is ever
logged for this pipeline.
</details>
<details>
<summary><b>Log — the Hazelcast operation thread stuck in
<code>SubPlan.updatePipelineState</code> (13:11:20)</b></summary>
```
[] 13:11:20,210 WARN
com.hazelcast.spi.impl.operationexecutor.slowoperationdetector.SlowOperationDetector
- [localhost]:5801 [seatunnel] [5.1] Slow operation detected: ...
org.apache.seatunnel.engine.server.dag.physical.SubPlan.updatePipelineState(SubPlan.java:345)
org.apache.seatunnel.engine.server.dag.physical.SubPlan.handleCheckpointError(SubPlan.java:644)
org.apache.seatunnel.engine.server.master.JobMaster.lambda$handleCheckpointError$9(JobMaster.java:773)
java.util.ArrayList.forEach(ArrayList.java:1259)
org.apache.seatunnel.engine.server.master.JobMaster.handleCheckpointError(JobMaster.java:770)
org.apache.seatunnel.engine.server.checkpoint.CheckpointManager.handleCheckpointError(CheckpointManager.java:219)
org.apache.seatunnel.engine.server.checkpoint.CheckpointCoordinator.handleCoordinatorError(CheckpointCoordinator.java:352)
org.apache.seatunnel.engine.server.checkpoint.CheckpointCoordinator.handleCoordinatorError(CheckpointCoordinator.java:338)
org.apache.seatunnel.engine.server.checkpoint.CheckpointCoordinator.reportCheckpointErrorFromTask(CheckpointCoordinator.java:519)
org.apache.seatunnel.engine.server.checkpoint.CheckpointManager.reportCheckpointErrorFromTask(CheckpointManager.java:227)
org.apache.seatunnel.engine.server.checkpoint.operation.CheckpointErrorReportOperation.runInternal(CheckpointErrorReportOperation.java:48)
org.apache.seatunnel.engine.server.task.operation.TracingOperation.run(TracingOperation.java:42)
com.hazelcast.spi.impl.operationservice.Operation.call(Operation.java:189)
com.hazelcast.spi.impl.operationservice.impl.OperationRunnerImpl.call(OperationRunnerImpl.java:273)
com.hazelcast.spi.impl.operationexecutor.impl.OperationThread.executeRun(OperationThread.java:123)
com.hazelcast.internal.util.executor.HazelcastManagedThread.run(HazelcastManagedThread.java:102)
```
One caveat I want to state rather than gloss: Hazelcast's
`SlowOperationDetector` logs a given stack **once** and then aggregates
repeats, so a single entry does not by itself prove the thread stayed there.
What corroborates it is independent — `CoordinatorService`'s 10-second periodic
print stops 5 seconds *before* this warning and never resumes.
</details>
<details>
<summary><b>Log — the coordinator's periodic print stops, and what runs for
the next two hours</b></summary>
`CoordinatorService` prints on a 10-second cadence. Within the
`PaimonWithS3IT` window it prints exactly four times and then stops:
```
13:10:45,790 CoordinatorService Thread Pool Status
13:10:55,789 CoordinatorService Thread Pool Status
13:10:55,816 Job info detail (all counts 0)
13:11:05,788 CoordinatorService Thread Pool Status
13:11:05,794 Job info detail (all counts 0) <- LAST, and this is
BEFORE the 13:11:09 failure
13:11:15,788 CoordinatorService Thread Pool Status <- LAST periodic print
of any kind
13:12:02,527 clean job log, jobId: 1137734545932550145 <- LAST
CoordinatorService line at all
```
From then until the runner kills the job at 15:22, the only thing the engine
emits is this, every 5 seconds:
```
13:xx:xx DefaultClassLoaderService - Create classloader for job
1137734545932550145
with jars
[file:/tmp/seatunnel/connectors/connector-fake-3.0.0-SNAPSHOT-2.12.15.jar]
13:xx:xx DefaultClassLoaderService - Create classloader for job
1137734545932550145
with jars
[file:/tmp/seatunnel/connectors/connector-paimon-3.0.0-SNAPSHOT-2.12.15.jar]
13:xx:xx DefaultClassLoaderService - Release classloader for job
1137734545932550145 ...
13:xx:xx DefaultClassLoaderService - Release classloader for job
1137734545932550145 ...
```
Totals in the window:
| job | Create | Release |
|---|---|---|
| `1137734545932550145` (job 1 — already `FINISHED`) | 3,120 | 3,120 |
| `1137734595555360769` (job 2 — the rejected one) | 2 | **1** |
Two things worth noting. The churn is on the job that **finished
successfully**, not the failed one. And job 2 creates two classloaders and
releases one — a leak consistent with its pipeline never completing teardown.
</details>
<details>
<summary><b>Log — job-level state transitions, job 1 vs job 2</b></summary>
```
Job fake_to_paimon_with_s3_with_privilege.conf (1137734545932550145)
CREATED -> PENDING
PENDING -> SCHEDULED
SCHEDULED -> RUNNING
RUNNING -> FINISHED <- complete
Job paimon_to_paimon_with_s3_with_privilege.conf (1137734595555360769)
CREATED -> PENDING
PENDING -> SCHEDULED
<- and that is all. Never RUNNING. Never
terminal.
```
Job 2 never reaches job-level `RUNNING`. Its *tasks* did deploy and run
(`DEPLOYING -> RUNNING` at task-group level, three task groups on slots 4/5/6)
— the privilege error arrives while the job itself is still `SCHEDULED`.
</details>
<details>
<summary><b>Control — the same test, the same commit, on the JDK 11 leg (job
<code>92614470554</code>)</b></summary>
Same commit, same config file, passing leg — `Tests run: 4, Failures: 0,
Errors: 0, Skipped: 0, Time elapsed: 118.481 s`.
| | JDK 8 leg (hung) | JDK 11 leg (passed) |
|---|---|---|
| `checkpoint have error, cancel the pipeline` | 1 | **8** |
| `Slow operation detected` | **1** | 0 |
| `SubPlan.updatePipelineState` in a stack | **1** | 0 |
| `CoordinatorService` periodic prints | 4, then stops | 14, continuous |
| `paimon_to_paimon_with_s3_with_privilege.conf` job states |
`CREATED→PENDING→SCHEDULED`, stop | `RUNNING→FAILING→FAILED` (×2) |
| classloader Create / Release | 3,122 / 3,121 | 42 / 42 |
This is the part I find most useful. The cancel path is not rare on the good
leg — it runs **eight** times and completes every time, driving the job to
`FAILING` and then `FAILED`. So `handleCheckpointError` is not broken in
general. The difference is *when* the error arrives: on the passing leg the job
had already reached `RUNNING`; on the hung leg it was still `SCHEDULED`.
</details>
<details>
<summary><b>Control — this was not a slow or overloaded runner</b></summary>
On the same hung JDK 8 leg, the sibling test class ran to completion
normally before `PaimonWithS3IT` started:
```
12:31:35 [INFO] Running org.apache.seatunnel.e2e.connector.paimon.PaimonIT
12:51:41 [INFO] Tests run: 26, Failures: 0, Errors: 0, Skipped: 0,
Time elapsed: 1,206.934 s - in ...PaimonIT
13:10:34 [INFO] Running
org.apache.seatunnel.e2e.connector.paimon.PaimonWithS3IT
15:22:25 ##[error]The operation was canceled.
```
</details>
---
## @SEZ9 — on your (a)/(b) split
Your (b) is the one the evidence lands on, and your (a) needs amending for
this run:
> (a) `SubPlan.handleCheckpointError` repeatedly resubmitting a pipeline
that fails deterministically
On my baseline run there is no repeated resubmission —
`handleCheckpointError` is entered **once** and does not come back out. So a
retry cap wouldn't help here; the pipeline never gets as far as retrying.
> (b) the job vanishing from coordinator counters without ever transitioning
to FAILED/CANCELED, so the client-side job-completion future never completes
This is exactly it, and the logs now name the frame. `handleCheckpointError`
(`SubPlan.java:644`) does:
```java
public void handleCheckpointError() {
log.warn(... "checkpoint have error, cancel the pipeline");
if (!getPipelineState().isEndState()) {
updatePipelineState(PipelineStatus.CANCELING); // SubPlan.java:345
}
}
```
and `updatePipelineState` is **`synchronized`** and performs Hazelcast
`IMap` operations (`updateStateTimestamps`, `runningJobStateIMap.get/set`)
inside `RetryUtils.retryWithException`, then calls `stateProcess()` — also
`synchronized`. All of this is running on a Hazelcast **operation thread**
(`CheckpointErrorReportOperation` → `TracingOperation` → `OperationRunnerImpl`
→ `OperationThread`).
The `turned from state ... to CANCELING` log line is emitted *after* the
retry block, and it never appears — so control never got past the IMap work. A
Hazelcast operation thread blocking on distributed map operations while holding
a monitor is a shape that can starve the very pool those operations need.
I want to flag the limit of that reasoning rather than overstate it:
`Constant.OPERATION_RETRY_TIME = 30` and `OPERATION_RETRY_SLEEP = 2000`, so the
retry loop is bounded at roughly 60 seconds — it cannot by itself account for a
two-hour stall, and no `log.error` from the surrounding `catch` ever appears.
So something downstream of, or concurrent with, that retry is where it actually
parks. I don't know the engine well enough to say which, and I'd rather hand
you a located frame than a guessed cause.
Agreed on your fix direction, and agreed that a client-side timeout should
not be the primary fix. One clarification so it isn't misread when it appears:
I'm opening a separate PR that bounds `executeJob` **in the E2E test harness**,
at @DanielLeens's request on #11648. That is CI blast-radius containment — a
recurrence costs seconds instead of a 180-minute runner slot — not a proposed
fix for this issue, and it touches no engine or client code.
## @SEZ9 — on the logs
Both full job logs are downloaded and I can pull any window you name:
- job `92614470569` — JDK 8, 31,752,702 bytes, hung
- job `92614470554` — JDK 11, 31,308,272 bytes, passed
What I still do **not** have is a thread dump of the blocked client, which
is what would settle whether the future is dropped or the terminal state is
never published. The hang is non-deterministic and I could not reproduce it
locally: SeaTunnel pins `testcontainer.version` at 1.17.6, whose docker-java
negotiates Docker API 1.32, and the daemon available to me requires 1.40+.
Bumping the pin works but perturbs container startup timing — precisely the
variable a timing race turns on — so I stopped rather than chase a reproduction
whose negative result would mean nothing.
One practical warning if you pull these yourself: `gh api .../logs`
**truncates inconsistently** (I got 27.8 MB, 18.9 MB and 29.7 MB for the same
job on three attempts), and it refuses the download entirely without
`--allow-escape-sequences`. Check the tail reaches the post-job `Cleaning up
orphan processes` block before concluding a line is absent — two of my earlier
readings of this incident were wrong for exactly that reason, and so were the
two corrections at the top of this comment.
## @abdessalems — yes, please, and here is where to start
> I can reproduce the problem and look into the client-side
`waitForJobComplete()` / terminal-state handling.
That is exactly the half I'm not taking — I said in the issue I'm not
submitting the engine fix, since the suspected area is Zeta's cancel/restore
and client status-polling logic and I don't know it well enough to change
safely. If you want it, it's yours.
Three things that should save you time:
1. **The server-side frame is located.** `SubPlan.updatePipelineState`
(`SubPlan.java:345`), reached from `handleCheckpointError` (`SubPlan.java:644`)
on a Hazelcast operation thread. If the pipeline never leaves `SCHEDULED`, no
terminal `JobResult` is ever published — so before digging into the client, it
is worth confirming whether the client is dropping a result or never being sent
one. The evidence above points at the latter.
2. **It is not deterministic, and the trigger looks like a race on job
state.** Same commit, two legs: on the passing leg the job reached `RUNNING`
before the privilege error and went `RUNNING → FAILING → FAILED`; on the hung
leg the error arrived while the job was still `SCHEDULED`. Don't read a single
green run as "not reproducing" — expect several attempts.
3. **If you reproduce it, grab a thread dump before anything is torn down**
— `jstack` on both the `seatunnel.sh` client and the engine process inside the
container. That single artifact is what none of us has.
Happy to help with reproduction, to test a candidate fix, and to pull any
window out of the two runs above on request.
--
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]
