FastAPI Timeout 偵錯筆記：MongoDB + LDAP + Istio

症狀

FastAPI 偶發 timeout（10 秒）
Kibana 看到 Next.js router 記錄 downstream connection close（Istio response flag: DC）
Local 測試：FastAPI router 內部時間很快（0.x 秒），但 Next.js 記錄 4~7 秒以上
Local 快、Staging 才會 timeout → 代表問題不在查詢邏輯本身，而在 handler 之外的層（dependency injection、連線建立、event loop blocking）
無法在 local / dev 重現，只在 staging 偶發出現

`DC` flag 的意思

Istio Envoy response flag DC = Downstream Connection termination，是 Next.js 主動切斷連線，不是 FastAPI 或 Istio timeout。

Next.js App Router route handler 預設 timeout 10 秒，等不到 response 就切斷。

Envoy Access Log 關鍵欄位

kubectl logs <your-pod> -c istio-proxy | grep "/api/your-endpoint"

欄位	說明
`response_flags`	`DC` = downstream 切斷
`duration`	Envoy 看到的總時間
`upstream_response_time`	FastAPI 實際回應時間（這個短代表 FastAPI 沒問題）

實測：FastAPI middleware 量到 204ms，upstream_response_time 也應該接近 204ms。若 duration 遠大於 upstream_response_time，時間消失在 Envoy 或 Next.js 層。

# 找是否有 retry（同一 endpoint 多筆非 200 log）
kubectl logs <your-pod> -c istio-proxy | grep "/api/your-endpoint" | grep -v "200"

需要確認的事項（優先順序）

1. LDAP Connection 是否每次重建

# 壞：每次查詢都重建 TCP + bind，慢 100~500ms
def get_user(self, user_id):
    conn = Connection(Server("ldap://..."), auto_bind=True)  # 每次都建
    conn.search(...)

# 好：singleton reuse 同一條連線
class LDAPService:
    def __init__(self):
        self.conn = Connection(Server("ldap://..."), auto_bind=True)  # 只建一次

    def get_user(self, user_id):
        self.conn.search(...)  # reuse

確認方式： 看 LDAPService.__init__ 裡怎麼建 Connection。

2. LDAP 實際花多久

t0 = time.perf_counter()
result = ldap_conn.search(...)
logger.warning(f"LDAP search took {(time.perf_counter()-t0)*1000:.0f}ms")

正常範圍：5~50ms。超過 200ms 就要查原因（跨 AZ、server 負載、查詢結果太大）。

3. LDAP cache miss 時是否 block event loop

場景： async def endpoint + pymongo 或 LDAP 同步 call = block event loop。

Cache 過期瞬間，所有同時進來的 request 全部卡住等 LDAP。

# async def + 同步 LDAP = 問題
async def get_files(user = Depends(get_current_user)):
    user = ldap_service.get_user(...)  # 同步，block event loop

短期解法： 用 run_in_executor

user = await asyncio.get_event_loop().run_in_executor(
    None, lambda: ldap_service.get_user(user_id)
)

4. Thundering herd：cache 過期時多個 request 同時打 LDAP

Cache 過期瞬間，多個 request 同時 cache miss，各自打 LDAP，疊加 block。

解法：加 lock

import threading

class LDAPService:
    def __init__(self):
        self._cache = {}
        self._lock = threading.Lock()

    def get_user(self, user_id: str):
        if user_id in self._cache:
            return self._cache[user_id]

        with self._lock:
            if user_id in self._cache:  # double-check
                return self._cache[user_id]

            result = ldap_conn.search(...)
            self._cache[user_id] = result
            return result

5. endpoint 是 `async def` 還是 `def`

# async def + pymongo = block event loop
async def get_files():
    docs = list(collection.find(...))  # 同步，block

# def = FastAPI 自動丟 thread pool，沒問題
def get_files():
    docs = list(collection.find(...))  # OK

6. MongoDB `file_ids` 欄位有沒有索引

db.your_collection.getIndexes()

沒有的話：

db.your_collection.create_index("file_ids")

加 log 的位置

Handler 內部計時不含 Depends() 執行時間，dependency injection 是在 handler 跑之前就執行完的：

request 進來
    ↓
Depends(get_current_user) 執行  ← handler 計時之外
    ↓
handler 第一行  ← 才開始計時

因此要三層都加，才能找到真正的卡點：

# 1. middleware 量整個 request（含 dependency injection）
@app.middleware("http")
async def timing_middleware(request: Request, call_next):
    t0 = time.perf_counter()
    response = await call_next(request)
    logger.info(f"[middleware] {request.url.path} {(time.perf_counter()-t0)*1000:.0f}ms")
    return response

# 2. dependency 量 LDAP（最可疑的地方）
def get_current_user(service = Depends(get_ldap_service)):
    t0 = time.perf_counter()
    user = service.get_user(...)
    logger.info(f"[dependency] {(time.perf_counter()-t0)*1000:.0f}ms")
    return user

# 3. handler 量 MongoDB
@app.get("/files")
def get_files(user = Depends(get_current_user)):
    t0 = time.perf_counter()
    docs = list(collection.find(...))
    logger.info(f"[handler] {(time.perf_counter()-t0)*1000:.0f}ms")
    return docs

對比三個數字判斷卡在哪：

[dependency] 6500ms  ← LDAP 在 dependency 裡卡住
[handler]    8ms
[middleware] 6510ms

→ 接下來確認：LDAP connection 是否重建、是否 block event loop

[dependency] 5ms
[handler]    6500ms  ← MongoDB 查詢本身慢
[middleware] 6510ms

→ 接下來確認：有沒有索引、explain() 看 stage

[dependency] 5ms
[handler]    8ms
[middleware] 6500ms  ← 時間在 middleware 和 handler 之間消失

→ FastAPI 內部沒問題，往 Istio / 網路層查

pymongo CommandListener（監聽所有 MongoDB 操作）

from pymongo import monitoring

class CommandLogger(monitoring.CommandListener):
    def started(self, event):
        self._start = time.perf_counter()

    def succeeded(self, event):
        ms = (time.perf_counter() - self._start) * 1000
        if ms > 500:
            logger.warning(f"slow mongo: {event.command_name} took {ms:.0f}ms")

    def failed(self, event):
        logger.error(f"mongo failed: {event.command_name}")

client = MongoClient(MONGO_URI, event_listeners=[CommandLogger()])

注意：CommandListener 只量 MongoDB 執行時間，不含 event loop 排隊時間。