echobeijingecho commented on issue #66401:
URL: https://github.com/apache/doris/issues/66401#issuecomment-5173209822
Thanks for the fast and thorough triage @Doris-Breakwater. Point-by-point
response with the requested evidence (all hostnames/tables redacted):
**1. Concession: the `ThriftHMSCachedClient` claim (our point 4) is
withdrawn.** Re-checked at commit 35854e7: `getClient()` does wrap construction
— `return ugiDoAs(() -> new ThriftHMSClient(hiveConf));`. Our original reading
missed `getClient()` itself. This is also consistent with observation: that
pool has no idle expiry, and we never saw it create connections in steady state.
**2. Requested: redacted catalog DDLs (client-pool settings are all
defaults).**
```sql
CREATE CATALOG `paimon_prod` PROPERTIES (
"warehouse" = "hdfs://<nameservice>/paimon/warehouse",
"type" = "paimon",
"paimon.catalog.type" = "hms",
"ipc.client.fallback-to-simple-auth-allowed" = "true",
"hive.metastore.uris" =
"thrift://hms-1:9083,thrift://hms-2:9083,thrift://hms-3:9083",
"hive.metastore.sasl.enabled" = "false",
"hive.metastore.client.socket.timeout" = "1800s",
"hadoop.username" = "hive",
"hadoop.security.authentication" = "simple",
"fs.defaultFS" = "hdfs://<nameservice>",
-- plus dfs.nameservices / HA namenode entries
);
-- a second paimon catalog `paimon` shares the SAME warehouse and HMS uris
(plus 2 extra uris), also hadoop.username=hive
CREATE CATALOG `hive` PROPERTIES (
"type" = "hms",
"ipc.client.fallback-to-simple-auth-allowed" = "true",
"hive.metastore.uris" =
"thrift://hms-1:9083,thrift://hms-2:9083,thrift://hms-3:9083",
"hive.metastore.type" = "hms",
"hadoop.username" = "hive"
);
```
No `client-pool-cache.*`, no `paimon.table.cache.*` overrides anywhere.
fe.conf: `external_cache_expire_time_seconds_after_access = 300`,
`external_cache_refresh_time_minutes = 1`.
**3. Requested: one complete timestamped window (round 1, fe.log, FE runs as
root).**
```
17:06:51,217 (ForkJoinPool.commonPool-worker-869)
HiveMetaStoreClient.close():831 Closed a connection ... current connections: 12
17:06:51,217 (ForkJoinPool.commonPool-worker-869)
HiveMetaStoreClient.close():831 Closed a connection ... current connections: 11
17:07:18,426 (NotCheckpointRowCountRefreshExecutor-40)
HiveMetaStoreClient.<init>():358 Loading Doris HiveMetaStoreClient
17:07:18,428 (NotCheckpointRowCountRefreshExecutor-40)
HiveMetaStoreClient.open():659 Trying to connect ... thrift://hms-2:9083
17:07:18,428 (NotCheckpointRowCountRefreshExecutor-40)
HiveMetaStoreClient.open():735 Opened a connection ... current connections: 12
17:07:18,446 (NotCheckpointRowCountRefreshExecutor-40)
RetryingMetaStoreClient.<init>():97 ... ugi=root (auth:SIMPLE)
17:07:18,447 (NotCheckpointRowCountRefreshExecutor-40)
HiveMetaStoreClient.<init>():358 Loading Doris HiveMetaStoreClient
17:07:18,447 (NotCheckpointRowCountRefreshExecutor-40)
HiveMetaStoreClient.open():659 Trying to connect ... thrift://hms-3:9083
17:07:18,448 (NotCheckpointRowCountRefreshExecutor-40)
RetryingMetaStoreClient.<init>():97 ... ugi=root (auth:SIMPLE)
17:09:52,140 first failed query (audit): Failed to get Paimon table:...$null
... Permission denied: user=root, access=EXECUTE, inode="/paimon"
17:12:49 last failed query of round 1
17:17:49 (ForkJoinPool.commonPool-worker-878) Closed a connection x2
<- exactly last-access + 300s
```
HMS-side (metastore audit) for the same window: the poisoned connection
served `ugi=root ip=<FE-ip> get_database: paimon`, then `get_all_tables:
db=paimon`, then several `get_multi_table : db=paimon tbls=<t1>,<t2>,...`
batches between 17:09:52 and 17:10:01 on hms-2; and at **17:17:49** hms-3
logged `ugi=root ... Done cleaning up thread local RawStore` — matching the
FE-side close to the second. Round 2 was identical in shape: eviction 18:27:28
→ creation 18:27:37 (`NotCheckpointRowCountRefreshExecutor-11`, ugi=root, again
2 clients to 2 different uris) → 28 failed queries 18:35:52–19:06:02 → closes
at 19:11:11 (last access + ~300s).
**4. Observations that may help close the causality gap:**
- Deterministic split across the whole day: query threads
(`mysql-nio-pool-*`) created 24+ connections, 100% `ugi=hive`; the row-count
executor created connections exactly twice, 100% `ugi=root`, and both rounds
started ≤30s after a pool eviction.
- Each root round creates **exactly two clients back-to-back (~2ms apart) to
two different metastore URIs**. Given your note that `CachedClientPool`'s
constructor eagerly forces the first connection via `run(client -> null)`, this
looks like a fresh pool being instantiated on the row-count thread (eager first
client + immediate borrow) — i.e. pool/catalog (re)instantiation reached on
that thread outside any authenticator, rather than a plain borrow of an
existing pool.
- We agree eviction is expireAfterAccess, not a fixed cycle — both rounds
match last-access+300s to the second, and round 2 survived 43.6 min under
continuous borrow traffic.
- Agreed that `user_name` in the pool key is defense-in-depth only.
**5. Instrumentation offer.** We can reproduce-hunt in staging with
shortened expirations and add a stack trace +
`UserGroupInformation.getCurrentUser()` log at HMS client creation to pin the
exact escaping call site. If you have a preferred hook point (e.g. shaded
`HiveMetaStoreClient.<init>` vs `RetryingMetaStoreClientFactory`), let us know
and we'll run it and report back.
--
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]
