Files

T

Naeel fcc3449469 doc: progress log 2026-04-27 — poolmgr reuse fix + console cleanup

2026-04-27 15:16:36 +03:00

15 KiB

Raw Blame History

Postmortem: Fission poolmgr reuse bug — полное исследование и fix

Дата: 2026-04-27
Статус: РЕШЕНО
Image: naeel/fission-bundle:v1.22.0-multi-ns-10
Commit: 0cae275 executor: update gpm.podLister in AddNamespace to fix IsValid nil panic

Симптом

При последовательных invoke одной и той же poolmgr-функции executor каждый раз делал choosePod + specializePod вместо reuse уже существующего специализированного pod.

Наблюдаемые признаки:

phppp (PHP): 10/10 HTTP 200, но PHP_PODS_BEFORE=1 → PHP_PODS_AFTER=11
88 (Python): 3/10 HTTP 200, затем HTTP 000 (timeout), PY_PODS_BEFORE=1 → PY_PODS_AFTER=4
В executor logs на каждый invoke: choosing pod from pool, relabel pod, specializing pod, added function service
Через ~2 минуты idle reaper убирал накопившиеся pods: release idle function resources
Не было ни одной строчки: served from cache или аналогичного

Архитектура reuse path (как должно работать)

[router RoundTrip]
  │
  ├─ getServiceEntry(ctx)
  │    └─ getServiceEntryFromExecutor()  ─── POST /v2/getServiceForFunction
  │         │
  │         │ [executor api.go]
  │         ├─ GetFuncSvcFromCache(fn)   ─── poolcache.GetSvcValue(CacheKeyURG, rpp, concurrency)
  │         │    ├─ CACHE HIT  → activeRequests++ → return fsvc
  │         │    └─ CACHE MISS → getServiceForFunction → choosePod → specializePod → AddFunc → activeRequests=1
  │         │
  │         └─ IsValid(ctx, fsvc)        ─── podLister[ns].Get(pod.Name)
  │              ├─ pod ready + IP match → return true  → "served from cache"
  │              └─ nil panic / not found → return false → DeleteFuncSvcFromCache → choosePod
  │
  ├─ defer unTapService(ctx, fn, serviceURL)
  │    └─ POST /v2/unTapService
  │         │ [executor api.go → gpm.UnTapService]
  │         └─ fsCache.MarkAvailable(CacheKeyURGFromMeta(fnMeta), svcHost)
  │              └─ poolcache.markAvailable → activeRequests--
  │
  └─ [NEXT INVOKE]: GetFuncSvcFromCache видит activeRequests=0 → CACHE HIT → reuse

Условие reuse: activeRequests < requestsPerPod (default: requestsPerPod=1, т.е. нужно activeRequests=0).

Bug #1 (исправлен ранее, commit `775845b`)

Что было не так

UnTapService в pkg/executor/client/client.go передавал FnMetadata без поля Generation:

// ДО fix (client.go UnTapService):
FnMetadata: metav1.ObjectMeta{
    Name:            fnMeta.Name,
    Namespace:       fnMeta.Namespace,
    ResourceVersion: fnMeta.ResourceVersion,
    UID:             fnMeta.UID,
    // Generation отсутствовал!
},

Где ломалось

CacheKeyURGFromMeta в pkg/crd/key.go:

func CacheKeyURGFromMeta(metadata *metav1.ObjectMeta) CacheKeyURG {
    return CacheKeyURG{
        UID:             metadata.UID,
        ResourceVersion: metadata.ResourceVersion,
        Generation:      metadata.Generation,  // был 0 вместо реального
    }
}

Кэш записывался с ключом {UID, RV, Generation=1}.
MarkAvailable искал по ключу {UID, RV, Generation=0}.
cache[{UID, RV, Generation=0}] не существовал → activeRequests никогда не уменьшался.

Fix

Добавлен Generation: fnMeta.Generation в TapService и UnTapService в client.go.

Почему fix был необходим, но недостаточен

После fix MarkAvailable стал находить правильный ключ и декрементировал activeRequests до 0.
Следующий GetFuncSvcFromCache успешно находил запись (0 < 1) → инкрементировал до 1 → возвращал fsvc.
Дальше вызывался IsValid(ctx, fsvc) — и здесь находился второй баг.

Bug #2 (исправлен в v1.22.0-multi-ns-10, commit `0cae275`) — ROOT CAUSE

Точная цепочка отказа

1. IsValid в gpm.go строка 289:

func (gpm *GenericPoolManager) IsValid(ctx context.Context, fsvc *fscache.FuncSvc) bool {
    for _, obj := range fsvc.KubernetesObjects {
        if strings.ToLower(obj.Kind) == "pod" {
            pod, err := gpm.podLister[obj.Namespace].Pods(obj.Namespace).Get(obj.Name)
            //                     ^^^^^^^^^^^^^^^^
            //                     NIL для user namespace!

2. gpm.podLister инициализируется только один раз при старте в MakeGenericPoolManager:

for ns, informerFactory := range gpmInformerFactory {
    gpm.podLister[ns] = informerFactory.Core().V1().Pods().Lister()
}

3. gpmInformerFactory строится из DefaultNSResolver(), который читает env vars executor:

"FISSION_FUNCTION_NAMESPACE": "",
"FISSION_RESOURCE_NAMESPACES": "default"

Итог: gpm.podLister = {"default": <lister>} — только namespace default.

4. При создании нового user namespace fission-ffd1f598c169b0ae вызывается AddNamespace:

func (gpm *GenericPoolManager) AddNamespace(ctx context.Context, ns string, ...) error {
    // ... создаёт gpmInformer для нового NS ...
    
    gpm.poolPodC.AddNamespaceInformers(ctx, ns, finformer, gpmInformer)
    //   ↑ регистрирует poolPodC.podLister[ns] — ОК
    
    // НО gpm.podLister[ns] НЕ обновлялся ← БАГ
    
    gpmInformer.Start(ctx.Done())
}

AddNamespaceInformers регистрировал podLister только в poolPodC (для PoolPodController), но не в gpm (для IsValid).

5. Результат: gpm.podLister["fission-ffd1f598c169b0ae"] = nil.

6. nil.Pods(ns).Get(name) → nil pointer dereference panic.

7. net/http перехватывает panic в handler goroutine → разрывает соединение.

8. Router's retryablehttp видит connection error → retry.

9. На retry: GetFuncSvcFromCache видит activeRequests=1 (был инкрементирован на шаге cache hit, до panic, и не был декрементирован), 1 >= requestsPerPod=1 → cache miss → choosePod → новый pod.

Почему каждый invoke создавал ровно 1 новый pod

Invoke N	Что происходит	Состояние после
1	Cache miss (первый invoke) → pod₁ specialized, `activeRequests=1`. UnTap → `activeRequests=0`	pod₁ ready, AR=0
2	Cache HIT (AR=0→1), IsValid → nil panic, retry: AR=1≥1 → miss → pod₂ specialized	pod₁ stuck AR=1, pod₂ AR=1→0
3	Cache hit pod₂ (AR=0→1), IsValid → nil panic; retry: AR=1≥1 → miss → pod₃ specialized	pod₁ stuck AR=1, pod₂ stuck AR=1, pod₃ AR=1→0
…	То же	+1 pod каждый invoke
10		10 stuck pods + 1 "live" pod

Итого после 10 invokes: 11 pods (PHP_PODS_BEFORE=1 → PHP_PODS_AFTER=11). Совпадает с наблюдением.

Каждые ~2 минуты idle reaper убирал stuck pods (у которых activeRequests=1 но запросов нет — баг idle reaper в отдельной логике списания).

Fix

Файл: pkg/executor/executortype/poolmgr/gpm.go
Функция: AddNamespace
Изменение: добавлена одна строка — обновление gpm.podLister[ns] после AddNamespaceInformers

// Register the new informers with PoolPodController.
if err := gpm.poolPodC.AddNamespaceInformers(ctx, ns, finformer, gpmInformer); err != nil {
    return fmt.Errorf("AddNamespace %s: register informers: %w", ns, err)
}

// Also update gpm.podLister so IsValid can resolve pods in this namespace.
// Without this line gpm.podLister[ns] is nil for dynamically-added user namespaces,
// causing a nil-pointer panic in IsValid, which leaves activeRequests permanently stuck at 1.
gpm.podLister[ns] = gpmInformer.Core().V1().Pods().Lister()   // ← PATCH

// Start the factories — they will begin syncing immediately.
finformer.Start(ctx.Done())
gpmInformer.Start(ctx.Done())

Почему именно здесь, а не в `AddNamespaceInformers`

AddNamespaceInformers — метод PoolPodController, который знает только о своём podLister.
gpm.podLister — поле GenericPoolManager, логически отдельное от poolPodC.
Обновлять оба необходимо, чтобы IsValid (метод GenericPoolManager) работал корректно.
gpmInformer уже создан и передан в AddNamespaceInformers — повторное использование того же объекта безопасно.

Live validation

Методология

Удалить все накопленные specialized pods в user namespace (сброс состояния).
Запустить 10 последовательных invokes с паузой 2s.
Считать число php pods до и после.
Ожидаемый результат: NEW_PODS_CREATED=1 (первый cold start) и REUSE_WORKING=YES.

Результат после patch (v1.22.0-multi-ns-10)

=== CLEAN BASELINE: PHP_PODS_BEFORE=1 ===
--- 10 sequential phppp invokes (2s apart) ---
  invoke 1: HTTP=200
  invoke 2: HTTP=200
  invoke 3: HTTP=200
  invoke 4: HTTP=200
  invoke 5: HTTP=200
  invoke 6: HTTP=200
  invoke 7: HTTP=200
  invoke 8: HTTP=200
  invoke 9: HTTP=200
  invoke 10: HTTP=200

PHP_PODS_BEFORE=1
PHP_PODS_AFTER=2
NEW_PODS_CREATED=1
REUSE_WORKING=YES_REUSE_FIXED

Интерпретация:

NEW_PODS_CREATED=1 — ровно 1 pod создан для cold start первого invoke.
invokes 2–10 полностью reuse тот же pod (activeRequests корректно 0→1→0 на каждый цикл).
REUSE_WORKING=YES_REUSE_FIXED — условие delta ≤ 1 выполнено.

До patch (v1.22.0-multi-ns-9):

PHP_PODS_BEFORE=1 → PHP_PODS_AFTER=11
NEW_PODS_CREATED=10
REUSE_WORKING=NO

Build и deploy summary

Шаг	Команда / артефакт
Patch	`gpm.go`: добавлена строка `gpm.podLister[ns] = gpmInformer.Core().V1().Pods().Lister()`
Compile check	`go build ./pkg/executor/...` — ошибок нет
Commit	`0cae275 executor: update gpm.podLister in AddNamespace to fix IsValid nil panic`
Binary build	`CGO_ENABLED=0 GOOS=linux GOARCH=amd64 go build -o _build/linux_amd64/fission-bundle ./cmd/fission-bundle/`
Docker build	`naeel/fission-bundle:v1.22.0-multi-ns-10`
Docker push	`sha256:f3a054408e7ffe6e89ae2059614ece6250c0658154902b3b772236ccee89dafa`
Rollout executor	`kubectl set image deployment/executor executor=naeel/fission-bundle:v1.22.0-multi-ns-10 -n fission`
Rollout router	`kubectl set image deployment/router router=naeel/fission-bundle:v1.22.0-multi-ns-10 -n fission`
Rollout status	`deployment "executor" successfully rolled out` / `deployment "router" successfully rolled out`

История двух bugов в timeline

[Сессия 1]
  Симптом: quota saturation + 504
  Причина: quota limits слишком низкие + reuse не работает (оба бага)
  Действие: поднята quota

[Сессия 2]
  Симптом: phppp 10/10 200, но pods 1→11
  Найден Bug #1: Generation отсутствует в TapService/UnTapService
  Fix: добавлен Generation в client.go
  Commit: 775845b
  Image: v1.22.0-multi-ns-9
  Результат: MarkAvailable теперь находит ключ, НО IsValid паникует → reuse всё ещё сломан

[Сессия 3 (текущая)]
  Симптом: phppp 10/10 200, pods 1→11 (то же)
  Найден Bug #2: gpm.podLister не обновляется в AddNamespace
  Fix: добавлена одна строка в gpm.AddNamespace
  Commit: 0cae275
  Image: v1.22.0-multi-ns-10
  Результат: phppp 10/10 200, pods 1→2 (1 cold start + 9 reuse) ✓

Файлы затронутые в этом исследовании

Файл	Роль	Изменён
`pkg/crd/key.go`	Определение `CacheKeyURG`, `CacheKeyURGFromMeta`	Нет
`pkg/executor/client/client.go`	Router→executor HTTP client, `TapService`/`UnTapService`	Да (Bug #1, `775845b`)
`pkg/executor/api.go`	HTTP endpoints `/v2/getServiceForFunction`, `/v2/unTapService`, `/v2/tapServices`	Нет
`pkg/executor/executor.go`	`serveCreateFuncServices` goroutine, `createServiceForFunction`	Нет
`pkg/executor/fscache/functionServiceCache.go`	`GetFuncSvc`, `AddFunc`, `MarkAvailable` (delegating to PoolCache)	Нет
`pkg/executor/fscache/poolcache.go`	`activeRequests` accounting, `getValue`, `markAvailable`	Нет
`pkg/executor/executortype/poolmgr/gp.go`	`getFuncSvc`, `choosePod`, `specializePod`, `AddFunc`	Нет
`pkg/executor/executortype/poolmgr/gpm.go`	`IsValid`, `UnTapService`, `AddNamespace`	Да (Bug #2, `0cae275`)
`pkg/executor/executortype/poolmgr/poolpodcontroller.go`	`AddNamespaceInformers`, `podLister` для PoolPodController	Нет
`pkg/router/functionHandler.go`	`RoundTrip`, `unTapService`, `getServiceEntry`	Нет
`pkg/utils/namespace.go`	`DefaultNSResolver`, `NamespaceResolver`	Нет
`pkg/utils/informer.go`	`GetInformerFactoryByExecutor`	Нет

Ключевые инварианты для будущей поддержки

gpm.podLister и poolPodC.podLister — два разных объекта. При добавлении нового namespace нужно обновлять оба. Сейчас это обеспечено патчем.
CacheKeyURG = {UID + ResourceVersion + Generation}. Любой код, вызывающий MarkAvailable или GetFuncSvc, обязан передавать все три поля в FnMetadata.
activeRequests — единственный критерий reuse. Если он не возвращается к 0 (из-за паники, незавершённого UnTap и т.д.), pod навсегда "застревает" как занятый, а listAvailableValue (idle reaper) не уберёт его пока activeRequests > 0.
poolmgr всегда ходит в executor (getServiceEntryFromExecutor) для каждого invoke — кэш в router (fmap) для poolmgr не используется (см. getServiceEntry). Кэш живёт только на стороне executor в connFunctionCache.
requestsPerPod default = 1. Значит: один pod может обслуживать только один одновременный запрос. Для reuse нужно завершить предыдущий UnTap до следующего GetFuncSvc.

15 KiB Raw Blame History Unescape Escape