morningman commented on issue #67446: URL: https://github.com/apache/doris/issues/67446#issuecomment-5509994359
## Root cause found — this is not an Iceberg problem I still had the FE logs from the affected instance. The terminated pool **is** `ThreadPools.getWorkerPool()`, but nothing in Doris or Iceberg calls `shutdown()` on it. It is shut down by **its own JVM shutdown hook**, fired by an ordinary `stop_fe.sh --grace`, while the FE goes on serving queries for minutes afterwards. ### Timeline (local time, UTC+8; `output/fe/log/`) | Time | Event | |---|---| | 18:45:05 | FE starts (matches the "up for ~1 hour" in the report) | | 19:36:56 / 19:37:26 | BE announces shutdown, then heartbeat `alive=false` — `stop_be.sh --grace` ran first | | **19:37:27,560** | `fe.log` — `Received shutdown signal, starting graceful shutdown...` **← the Iceberg worker pool is shut down at this instant** | | 19:37:28 → 19:41:20 | `waiting 2 queries to finish before shutdown`, repeated for 233 s | | **19:39:48 / 19:40:41 / 19:41:04** | the three `RejectedExecutionException`s — all inside that window | | 19:41:32 | FE restarts | Two corroborating details: - The full stack goes through `Executors$DelegatedExecutorService.submit` → `Tasks$Builder.runParallel` → `SnapshotProducer.writeManifests(SnapshotProducer.java:685)`. `DelegatedExecutorService` is exactly the `Executors.unconfigurableExecutorService` wrapper that `MoreExecutors.getExitingExecutorService` returns, i.e. `ThreadPools.getWorkerPool()`. - `iceberg-worker-pool-*` threads last appear in the log at **19:25:01** (thread id 403). The next appearance is **19:41:53** — with thread id 267, i.e. already the *new* JVM. The pool never ran another task after the signal, which is why `completed tasks = 26` was byte-identical across all three failures. ### Mechanism 1. `ThreadPools.WORKER_POOL = newExitingWorkerPool(...)` → `MoreExecutors.getExitingExecutorService(...)` → `addDelayedShutdownHook(...)` → `Runtime.getRuntime().addShutdownHook(...)`, and the hook body's first instruction is `ExecutorService.shutdown()` (verified against the `iceberg-bundled-guava:1.10.1` bytecode). 2. The JVM runs all shutdown hooks **concurrently**. Doris's own hook (`fe/fe-core/src/main/java/org/apache/doris/DorisFE.java:183`) calls `gracefulShutdown()` first, which waits up to **300 s** for in-flight coordinators (`DorisFE.java:727-741`), and only *afterwards* calls `qeService.stop()` / `thriftServerStarter.stop()`. So while Guava's hook has already killed the pool, the MySQL port is still open and still executing statements. 3. `serverReady.set(false)` does not help: its only consumer is the HTTP health endpoint (`httpv2/rest/HealthAction.java:42`). And `MysqlServer.stop()` — even when it does run — only closes the accepting channel; established connections keep executing statements. The failing INSERTs all arrived on `mysql-nio-pool-13|532`, an already-open pooled JDBC connection. 4. `ThreadPools.WORKER_POOL` is `private static final`, so once terminated the JVM is poisoned for good. Hence "restarting the FE is the only recovery", and hence a brand-new catalog/database/table still fails. The drain hung for the full 233 s because the BE had been stopped **first**, so the two in-flight coordinators could never complete. With the documented stop order (`stop_be.sh --grace` then `stop_fe.sh --grace`) this window is reproducible every time. `bin/stop_fe.sh` also waits forever (`while true; ... sleep 2`) with no SIGKILL fallback, so the operator only sees `Waiting for fe process with PID ... to terminate` and has no indication that the FE is still accepting work it can no longer perform. ### Why the three hypotheses in the report all tested clean `drop catalog`, `drop database force` and the failed `CREATE TABLE` were all retried **after** the 19:41:32 restart — a new JVM with a fresh pool. They were never going to reproduce it. ### Deterministic reproduction ``` # with at least one query in flight: output/fe/bin/stop_fe.sh --grace # SIGTERM (note: the default without --grace is SIGKILL) # the FE does not exit yet. On an ALREADY-OPEN connection, during the drain window: insert into <iceberg table> select ... # -> RejectedExecutionException, every time ``` ### Notes for whoever picks this up The obvious fix — moving `qeService.stop()` / `thriftServerStarter.stop()` ahead of `gracefulShutdown()` — is **not** the right one: - Moving `thriftServerStarter.stop()` first breaks the drain itself. BE reports fragment status through `FrontendServiceImpl.reportExecStatus` (`FrontendServiceImpl.java:1086`) → `QeProcessorImpl`, which is precisely what empties the `coordinatorMap` that `gracefulShutdown()` polls. In-flight queries could then never complete, so the drain would burn its full 300 s budget *and* fail every query. It would also cut `finishTask`/`report`, `loadTxnBegin`/`loadTxnCommit`/`streamLoadPut`, `forward` (follower→master DDL) and FE↔FE session refresh — cluster-wide damage if the node is the Master. - Moving `qeService.stop()` first does not close the window at all, because `MysqlServer.stop()` only closes the listening socket and the offending statements came in over an existing connection. It would additionally hard-cut in-flight Arrow Flight SQL: `DorisFlightSqlService.stop()` → `FlightServer.close()` is `shutdown()` + 3 s + `shutdownNow()`. What actually closes the window is a **statement-level gate**: once shutdown starts, reject *new* statements at `ConnectProcessor.executeQuery` / `StmtExecutor.execute` with a clear "FE is shutting down" error. That covers existing connections, leaves in-flight work drainable, keeps thrift up so coordinators can actually finish, and stops new queries from repopulating `coordinatorMap` during the drain. An Iceberg-side mitigation is not available in 1.10.1: `SnapshotUpdate.scanManifestsWith()` only overrides `SnapshotProducer.workerPool()` (used at `SnapshotProducer.java:283` for manifest *scanning*), whereas the failing write path `SnapshotProducer.writeManifests` hardcodes `ThreadPools.getWorkerPool()` at `SnapshotProducer.java:684`. That is arguably an upstream gap worth reporting separately. ### Closing Closing this: the root cause is understood and it is not an Iceberg bug — it is the FE shutdown-hook ordering, which leaves up to a 300 s window where the FE accepts work it can no longer perform. No fix planned right now; happy for someone to reopen or file a focused issue against `DorisFE`'s shutdown sequence. -- 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] --------------------------------------------------------------------- To unsubscribe, e-mail: [email protected] For additional commands, e-mail: [email protected]
