From fcc3449469ccbd68197572d46c3cc5d3a8d2cf36 Mon Sep 17 00:00:00 2001 From: Naeel Date: Mon, 27 Apr 2026 15:16:36 +0300 Subject: [PATCH] =?UTF-8?q?doc:=20progress=20log=202026-04-27=20=E2=80=94?= =?UTF-8?q?=20poolmgr=20reuse=20fix=20+=20console=20cleanup?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit --- doc/CHAT_SUMMARY_2026-04-27.md | 86 +++++ ...POOLMGR_REUSE_BUG_POSTMORTEM_2026-04-27.md | 324 ++++++++++++++++ ...SONNET_HANDOFF_2026-04-27_POOLMGR_REUSE.md | 353 ++++++++++++++++++ doc/progress.md | 47 +++ token.txt | 10 + 5 files changed, 820 insertions(+) create mode 100644 doc/CHAT_SUMMARY_2026-04-27.md create mode 100644 doc/POOLMGR_REUSE_BUG_POSTMORTEM_2026-04-27.md create mode 100644 doc/SONNET_HANDOFF_2026-04-27_POOLMGR_REUSE.md create mode 100644 token.txt diff --git a/doc/CHAT_SUMMARY_2026-04-27.md b/doc/CHAT_SUMMARY_2026-04-27.md new file mode 100644 index 0000000..6c1a0f0 --- /dev/null +++ b/doc/CHAT_SUMMARY_2026-04-27.md @@ -0,0 +1,86 @@ +Состояние на 2026-04-27 + +Что уже исправлено + +- Починен вход по валидному JWT в test mode без ослабления поведения при FISSION_TEST_MODE=false. +- Добавлены тесты на auth. +- Починен статус инициализации namespace в UI: console получил права читать pod'ы control-plane. +- Убран баг с кешем ensured namespace: если namespace удалили вручную, EnsureUserNS теперь проверяет его существование и пересоздаёт. +- Live console раскатан по digest, не по tag. +- Правила обновлены: не откатывать без явной команды пользователя, после каждого исправления делать отдельный commit. + +Что важно помнить + +- Все shell-команды только через SSH: + ssh -i ~/.ssh/naeel_vm_id_ed25519 -o StrictHostKeyChecking=no -o ConnectTimeout=10 naeel@5.172.178.213 '...' +- Ничего не откатывать без явной команды пользователя. +- После каждого реального исправления нужен отдельный commit. +- Пользователь очень чувствителен к "нереальным" тестам. Предпочтение только live user-flow проверкам. + +Текущий live state + +- Репозиторий: /home/naeel/remote_dev/fission +- Live deployment console уже работает на digest: + naeel/fission-console@sha256:5f0846c53267bd275f173981afbc8181e7808c3cf98c3902acaa659d6183e8a9 +- Пользовательский namespace: + fission-ffd1f598c169b0ae +- Проблемная функция: + phppp + +Текущая активная проблема + +- В UI при invoke функции phppp показывается ошибка: + invoke "phppp" timeout after 20s: function specialization likely failed (for example, syntax error) +- Но это generic fallback из console/internal/api/handlers.go, а не доказанный root cause. + +Что уже установлено по phppp + +- Функция phppp, package phppp-pkg, environment console-php-env и httptrigger существуют в namespace fission-ffd1f598c169b0ae. +- Function spec: + - environment: console-php-env + - functionName: main.php::handler +- Environment runtime: + - image: ghcr.io/fission/php-env +- Package literal успешно извлечён. +- Реальный код main.php внутри package это тяжёлая PHP-функция примерно на 10 секунд. +- В коде используются bcadd и bcmul, то есть есть сильное подозрение на отсутствие расширения bcmath в PHP runtime. + +Критически важное наблюдение + +- Executor log уже показал, что specialization для phppp проходит успешно: + - choosing pod from pool + - calling fetcher to copy function + - specializing pod + - specialized pod + - added function service +- Значит проблема, скорее всего, не в specialization, а уже в runtime execution внутри PHP env или в неверном timeout/error mapping со стороны console. + +Что пошло не так в последней диагностике + +- Логи pod были сняты не с php pod, а с pod другой функции, где был nodejs runtime. +- Поэтому точная runtime ошибка phppp ещё не поймана. + +Следующий правильный шаг + +1. Найти именно pod, у которого labels/functionName=phppp или environment=console-php-env и namespace=fission-ffd1f598c169b0ae. +2. Снять logs именно с php container этого pod. +3. Проверить, есть ли в runtime расширение bcmath. +4. Если bcmath отсутствует, исправить корень проблемы, а не маскировать timeout. +5. После исправления сделать отдельный commit и live-проверку invoke. + +Файлы, которые уже были важны в этой истории + +- console/internal/api/auth.go +- console/internal/api/handlers.go +- console/internal/api/ns_status.go +- console/internal/cloud/tenant.go +- console/internal/fission/namespace.go +- console/deploy/console.yaml +- deploy/rbac/console-ns-manager.yaml +- .github/copilot-instructions.md + +Что не надо делать + +- Не откатывать image, manifests, deployment или код. +- Не считать сообщение про specialization доказательством syntax error. +- Не использовать synthetic тесты вместо live-проверки, если пользователь просит именно user-flow. \ No newline at end of file diff --git a/doc/POOLMGR_REUSE_BUG_POSTMORTEM_2026-04-27.md b/doc/POOLMGR_REUSE_BUG_POSTMORTEM_2026-04-27.md new file mode 100644 index 0000000..7b5a818 --- /dev/null +++ b/doc/POOLMGR_REUSE_BUG_POSTMORTEM_2026-04-27.md @@ -0,0 +1,324 @@ +# 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`: + +```go +// ДО 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`: + +```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:** + +```go +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`: + +```go +for ns, informerFactory := range gpmInformerFactory { + gpm.podLister[ns] = informerFactory.Core().V1().Pods().Lister() +} +``` + +**3. `gpmInformerFactory` строится из `DefaultNSResolver()`**, который читает env vars executor: + +```json +"FISSION_FUNCTION_NAMESPACE": "", +"FISSION_RESOURCE_NAMESPACES": "default" +``` + +Итог: `gpm.podLister = {"default": }` — **только namespace `default`**. + +**4. При создании нового user namespace** `fission-ffd1f598c169b0ae` вызывается `AddNamespace`: + +```go +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` + +```go +// 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 + +### Методология + +1. Удалить все накопленные specialized pods в user namespace (сброс состояния). +2. Запустить 10 последовательных invokes с паузой 2s. +3. Считать число php pods до и после. +4. Ожидаемый результат: `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` | Нет | + +--- + +## Ключевые инварианты для будущей поддержки + +1. **`gpm.podLister` и `poolPodC.podLister` — два разных объекта.** При добавлении нового namespace нужно обновлять оба. Сейчас это обеспечено патчем. + +2. **`CacheKeyURG` = `{UID + ResourceVersion + Generation}`.** Любой код, вызывающий `MarkAvailable` или `GetFuncSvc`, обязан передавать все три поля в `FnMetadata`. + +3. **`activeRequests` — единственный критерий reuse.** Если он не возвращается к 0 (из-за паники, незавершённого UnTap и т.д.), pod навсегда "застревает" как занятый, а `listAvailableValue` (idle reaper) не уберёт его пока `activeRequests > 0`. + +4. **poolmgr всегда ходит в executor** (`getServiceEntryFromExecutor`) для каждого invoke — кэш в router (`fmap`) для poolmgr не используется (см. `getServiceEntry`). Кэш живёт только на стороне executor в `connFunctionCache`. + +5. **`requestsPerPod` default = 1.** Значит: один pod может обслуживать только один одновременный запрос. Для reuse нужно завершить предыдущий UnTap до следующего GetFuncSvc. diff --git a/doc/SONNET_HANDOFF_2026-04-27_POOLMGR_REUSE.md b/doc/SONNET_HANDOFF_2026-04-27_POOLMGR_REUSE.md new file mode 100644 index 0000000..2777135 --- /dev/null +++ b/doc/SONNET_HANDOFF_2026-04-27_POOLMGR_REUSE.md @@ -0,0 +1,353 @@ +# Handoff: Fission poolmgr reuse still broken after partial fix + +## Goal + +Нужно разобраться, почему в live Fission при последовательных invoke одной и той же function с executor `poolmgr` executor каждый раз снова делает `choosePod + specializePod`, вместо reuse уже существующего specialized pod/function service. + +Ключевой симптом: + +- после завершения invoke resources не reuse-ятся для следующего вызова; +- executor продолжает создавать новый specialized pod почти на каждый invoke; +- для тяжелых функций это приводит к росту pod count и затем к timeout/504. + +## Environment + +- Local workspace: `/home/naeel/remote_dev/fission` +- Remote console repo: `/home/naeel/terra/fission` +- Remote Fission runtime repo: `/home/naeel/terra/fission-src` +- Live cluster access only via SSH: + +```bash +ssh -i ~/.ssh/naeel_vm_id_ed25519 -o StrictHostKeyChecking=no -o ConnectTimeout=10 naeel@5.172.178.213 '...' +``` + +- Fission namespace: `fission` +- Live user namespace under test: `fission-ffd1f598c169b0ae` + +## Functions under test + +Namespace: `fission-ffd1f598c169b0ae` + +- `phppp` + - env: `console-php-env` + - executor: `poolmgr` + - route: `/f598c169b0ae/phppp` +- `88` + - env: `console-python-env` + - executor: `poolmgr` + - route: `/f598c169b0ae/88` + +HTTP invoke path used for live validation: + +```bash +https://fission.kube5s.ru/fn/f598c169b0ae/phppp +https://fission.kube5s.ru/fn/f598c169b0ae/88 +``` + +Valid user token used for direct invoke is in: + +- `/home/naeel/remote_dev/terraform/TEST_STAND/POSTGRES/terraform.tfvars` +- remote mirror: `/home/naeel/terra/terraform/TEST_STAND/POSTGRES/terraform.tfvars` + +## What was already found earlier + +Изначально казалось, что проблема только в namespace quota saturation, потому что при многократных invoke возникали `504`, а quota по CPU/memory/pods реально упирались в потолок. + +Но затем был найден реальный runtime bug: + +- reuse key в executor uses `UID + ResourceVersion + Generation` +- `CacheKeyURGFromMeta(...)` in `pkg/crd/key.go` +- router/executor client path previously sent `FnMetadata` in `TapService`/`UnTapService` without `Generation` +- из-за этого `UnTapService -> MarkAvailable` не попадал в тот же cache key +- `activeRequests` не уменьшался у правильного cached function service +- следующий invoke видел cache miss и создавал новый specialized pod + +### Previous fix already made + +File changed in runtime repo: + +- `pkg/executor/client/client.go` + +Change: + +- added `Generation: fnMeta.Generation` in `TapService(...)` +- added `Generation: fnMeta.Generation` in `UnTapService(...)` + +Remote commit already made: + +- `775845b executor: preserve generation in untap metadata` + +## Important: this fix is already rolled out to live + +New bundle image built and deployed: + +- image: `naeel/fission-bundle:v1.22.0-multi-ns-9` +- digest: `sha256:5348bca2eacb78a030e639d7f4f7ac392369b6f702677ac47a69ea9f61f50a12` + +Live deployment state after rollout: + +- `router` image = `naeel/fission-bundle:v1.22.0-multi-ns-9` +- `executor` image = `naeel/fission-bundle:v1.22.0-multi-ns-9` + +So: the `Generation` fix is **already in live**, but reuse is **still broken**. + +## Current live reproduction + +### `phppp` + +Command pattern: + +```bash +USER_TOKEN=$(grep -m1 '^api_token' /home/naeel/terra/terraform/TEST_STAND/POSTGRES/terraform.tfvars | sed -E 's/^api_token = "(.*)"$/\1/') +curl -sk -o /tmp/phppp.out -w '%{http_code}' --max-time 40 \ + "https://fission.kube5s.ru/fn/f598c169b0ae/phppp" \ + -H "Authorization: Bearer $USER_TOKEN" +``` + +Observed result: + +- 10 of 10 invokes returned `200` +- BUT php specialized pod count grew from `1` to `11` + +Exact observed summary: + +- `PHP_PODS_BEFORE=1` +- invokes `1..10`: all `HTTP=200` +- `PHP_PODS_AFTER=11` + +This proves: + +- invoke itself works +- auth token is valid +- runtime is still specializing a new pod on each invoke instead of reusing + +### `88` + +Command pattern: + +```bash +USER_TOKEN=$(grep -m1 '^api_token' /home/naeel/terra/terraform/TEST_STAND/POSTGRES/terraform.tfvars | sed -E 's/^api_token = "(.*)"$/\1/') +curl -sk -o /tmp/88.out -w '%{http_code}' --max-time 40 \ + "https://fission.kube5s.ru/fn/f598c169b0ae/88" \ + -H "Authorization: Bearer $USER_TOKEN" +``` + +Observed result: + +- first 3 invokes returned `200` +- then invokes 4..10 returned `000` / timeout-like failure from curl +- python pod count grew from `1` to `4` + +Exact observed summary: + +- `PY_PODS_BEFORE=1` +- tries 1..3: `HTTP=200` +- tries 4..10: `HTTP=000` +- `PY_PODS_AFTER=4` + +This suggests: + +- same reuse bug path still exists for python too +- when function is heavier, pod growth quickly returns the original operational problem + +## Most important executor logs + +After rollout, executor logs still show for `phppp` on nearly every invoke: + +- `choosing pod from pool` +- `relabel pod` +- `specializing pod` +- `added function service` + +Example pattern repeated for each invoke: + +```text +choosing pod from pool +relabel pod +chose pod ... poolmgr-console-php-env-...-5dcc862z4hm +calling fetcher to copy function +specializing pod +specialized pod ... podIP=172.16.1.80 +added function service ... serviceHost=172.16.1.80:8888 + +choosing pod from pool +relabel pod +chose pod ... poolmgr-console-php-env-...-5dcc86k2zlk +calling fetcher to copy function +specializing pod +specialized pod ... podIP=172.16.3.209 +added function service ... serviceHost=172.16.3.209:8888 + +choosing pod from pool +relabel pod +chose pod ... poolmgr-console-php-env-...-5dcc86ftzfp +calling fetcher to copy function +specializing pod +specialized pod ... podIP=172.16.3.52 +added function service ... serviceHost=172.16.3.52:8888 +``` + +That is, executor behavior in live clearly remains: + +- no effective reuse of existing function service +- no steady-state one-pod serving repeated invokes + +Also later there is only idle cleanup like: + +```text +release idle function resources +function=phppp +address=172.16.2.155:8888 +``` + +That confirms pods are being reaped later, but not reused immediately for next request. + +## What is already ruled out + +### Not an auth issue + +- token from `terraform.tfvars` is valid +- direct `/fn/...` invoke works with bearer token + +### Not just quota + +- quota pressure was real earlier +- but now we have a cleaner reproduction where repeated invoke still creates new specialized pod even before total failure +- for `phppp`, 10 requests succeed but pod count still grows `1 -> 11` + +### Not only missing `Generation` anymore + +- `Generation` was indeed missing before +- that fix is already committed, built, deployed +- live logs prove reuse is still broken after that fix + +## Highest-value question now + +Where else in the path does executor fail to map the completion of request back to the existing cached function service? + +In other words: why does `UnTapService -> MarkAvailable` still not make the current function service reusable for the next invoke? + +## Narrow code path to inspect + +Please focus on the smallest path controlling release/reuse: + +- `pkg/router/functionHandler.go` + - request lifecycle + - `getServiceEntry` + - `unTapService` + - what metadata and service URL/address are sent back after request completes +- `pkg/executor/client/client.go` + - `TapService(...)` + - `UnTapService(...)` +- `pkg/executor/api.go` + - `/v2/getServiceForFunction` + - `/v2/unTapService` + - `/v2/tapServices` +- `pkg/executor/fscache/functionServiceCache.go` + - `GetFuncSvc` + - `AddFunc` + - `MarkAvailable` + - `TouchByAddress` +- `pkg/executor/fscache/poolcache.go` + - activeRequests accounting + - `markAvailable` +- `pkg/executor/executortype/poolmgr/gp.go` + - `getFuncSvc` + - `choosePod` + - `specializePod` +- `pkg/executor/executortype/poolmgr/gpm.go` + - `TapService` + - `UnTapService` + - idle reaper logic +- `pkg/crd/key.go` + - `CacheKeyURGFromMeta` + +## Strong suspicion + +There is still a mismatch in at least one of these dimensions: + +1. metadata key used by cache lookup / mark available +2. service address format used for matching existing function service +3. path by which router reports completion back to executor +4. activeRequests decrement path in pool cache +5. tap/untap batching behavior versus per-request lifecycle + +### Concrete symptoms that support this + +- every next invoke still enters `choosePod` +- `added function service` repeats with new pod IP every time +- there is no visible log evidence that the just-used address became available in time for the next invoke + +## Helpful concrete questions for investigation + +1. Does router send the same logical function identity on `getServiceForFunction` and `unTapService` after the `Generation` fix, or is there still some field mismatch? +2. Is `serviceURL`/address normalized differently between tap and untap, so the address cannot match the cached function service? +3. Does `MarkAvailable` expect `serviceHost` without scheme while router sends full URL or vice versa? +4. Is `activeRequests` decremented on the same object/key that `GetFuncSvc` checks on the next invoke? +5. Could `TouchByAddress` / `MarkAvailable` be operating on a stale or different cache entry than `AddFunc` created? +6. Is the router definitely calling untap on successful invoke for these direct `/fn/...` requests? +7. Is there any race where the next invoke starts before previous untap is processed, making this appear as no reuse even for sequential calls with ~4-5s spacing? +8. For `phppp`, since calls are sequential and each lasts ~4s, why is a new pod still chosen 5 seconds later if previous invoke already completed? + +## Useful live commands already used + +Check live deployment images: + +```bash +ssh -i ~/.ssh/naeel_vm_id_ed25519 -o StrictHostKeyChecking=no -o ConnectTimeout=10 naeel@5.172.178.213 \ + 'kubectl describe deploy router -n fission | sed -n "/Containers:/,/Conditions:/p"' + +ssh -i ~/.ssh/naeel_vm_id_ed25519 -o StrictHostKeyChecking=no -o ConnectTimeout=10 naeel@5.172.178.213 \ + 'kubectl describe deploy executor -n fission | sed -n "/Containers:/,/Conditions:/p"' +``` + +Check function and trigger: + +```bash +ssh -i ~/.ssh/naeel_vm_id_ed25519 -o StrictHostKeyChecking=no -o ConnectTimeout=10 naeel@5.172.178.213 \ + 'kubectl get function phppp -n fission-ffd1f598c169b0ae -o yaml | sed -n "1,220p"' + +ssh -i ~/.ssh/naeel_vm_id_ed25519 -o StrictHostKeyChecking=no -o ConnectTimeout=10 naeel@5.172.178.213 \ + 'kubectl get httptrigger phppp-route -n fission-ffd1f598c169b0ae -o yaml | sed -n "1,220p"' +``` + +Live smoke used to prove bug remains: + +```bash +ssh -i ~/.ssh/naeel_vm_id_ed25519 -o StrictHostKeyChecking=no -o ConnectTimeout=10 naeel@5.172.178.213 <<'SSH' +set -e +USER_TOKEN=$(grep -m1 '^api_token' /home/naeel/terra/terraform/TEST_STAND/POSTGRES/terraform.tfvars | sed -E 's/^api_token = "(.*)"$/\1/') +NS=fission-ffd1f598c169b0ae +BEFORE=$(kubectl get pods -n "$NS" --no-headers | grep 'poolmgr-console-php-env' | wc -l) +echo "PHP_PODS_BEFORE=$BEFORE" +for i in 1 2 3 4 5 6 7 8 9 10; do + code=$(curl -sk -o /tmp/phppp.out -w '%{http_code}' --max-time 40 "https://fission.kube5s.ru/fn/f598c169b0ae/phppp" -H "Authorization: Bearer $USER_TOKEN" || true) + body=$(tr '\n' ' ' /dev/null | head -c 200 || true) + echo "TRY=$i HTTP=$code BODY=$body" +done +AFTER=$(kubectl get pods -n "$NS" --no-headers | grep 'poolmgr-console-php-env' | wc -l) +echo "PHP_PODS_AFTER=$AFTER" +SSH +``` + +Executor logs: + +```bash +ssh -i ~/.ssh/naeel_vm_id_ed25519 -o StrictHostKeyChecking=no -o ConnectTimeout=10 naeel@5.172.178.213 \ + 'kubectl logs -n fission deploy/executor --since=15m | egrep "phppp| 88 |functionName=88|choosing pod from pool|specializing pod|added function service|marking function service|MarkAvailable|tapService|unTapService" | tail -n 240' +``` + +## What is wanted from Sonnet + +Не просто общая гипотеза, а конкретно: + +1. pinpoint the next exact root cause in code +2. explain why the already-deployed `Generation` fix was necessary but insufficient +3. propose the smallest correct patch +4. say exactly how to validate that patch in live + +Best outcome: + +- a minimal patch in one or a few files +- explanation of the failing cache/release path +- exact reason repeated invokes still go through `choosePod` after success of prior invoke diff --git a/doc/progress.md b/doc/progress.md index 785ecb4..35d8e6d 100644 --- a/doc/progress.md +++ b/doc/progress.md @@ -506,3 +506,50 @@ - Deployment обновлен и успешно прокатан. - Проверено в live HTML: отдается - ``. +--- + +## 2026-04-27 + +### Сессия: poolmgr reuse fix (Bug #1 + Bug #2) + console cleanup + +#### Bug #1 — Generation в TapService/UnTapService (`client.go`, commit `775845b`) +- Симптом: 10/10 HTTP 200, но pod count рос 1→11 (новый pod на каждый invoke). +- Root cause: `Generation` не передавался в `TapService`/`UnTapService`. `MarkAvailable` строил ключ `{UID, RV, Generation=0}` вместо `{UID, RV, Generation=1}` → `activeRequests` никогда не декрементировался → всегда cache miss. +- Fix: добавить `Generation: fnMeta.Generation` в оба вызова в `pkg/executor/client/client.go`. +- Image: `naeel/fission-bundle:v1.22.0-multi-ns-9`. + +#### Bug #2 — `gpm.podLister[ns]` nil для user namespace (`gpm.go`, commit `0cae275`) +- Симптом: после Bug #1 fix — reuse всё ещё не работал. +- Root cause: `AddNamespace` обновлял только `poolPodC.podLister[ns]`, но не `gpm.podLister[ns]`. `IsValid` вызывал `gpm.podLister[ns].Pods(...).Get(...)` → nil pointer panic → net/http рвал соединение → router retry → `activeRequests=1` (stuck) → cache miss → новый pod. +- Fix: добавить одну строку в `AddNamespace` в `pkg/executor/executortype/poolmgr/gpm.go`: + ```go + gpm.podLister[ns] = gpmInformer.Core().V1().Pods().Lister() + ``` +- Image: `naeel/fission-bundle:v1.22.0-multi-ns-10`. +- Live validation: `PHP_PODS_BEFORE=1 → PHP_PODS_AFTER=2, NEW_PODS_CREATED=1, REUSE_WORKING=YES_REUSE_FIXED`. +- Postmortem: `doc/POOLMGR_REUSE_BUG_POSTMORTEM_2026-04-27.md`. + +#### Console: убрана карточка тайм-триггеров (`console/ui/index.html`, commit `96a02b4`) +- Убрана карточка "Тайм-триггеры" из dashboard (счётчик `0`). +- Убраны JS-строки: `getJSON('/timetriggers')`, `setText('time-count', ...)`, `const [..., time]`. +- Образ: `naeel/fission-console:v1.1` (sha256:0713fee1...). +- Деплой: `kubectl set image deployment/fission-console console=naeel/fission-console:v1.1 -n fission`. +- **Важно**: container name в deployment = `console` (не `fission-console`!). + +#### TODO: тайм-триггеры (не реализовано, отложено) +Нужно реализовать: +1. Поле "Cron" в форме создания функции (или отдельная форма/таблица) +2. `POST /console/api/timetriggers` → handler `handleCreateTimeTrigger` +3. `DELETE /console/api/timetriggers/:name` → handler +4. `model.CreateTimeTriggerRequest {Name, FunctionName, Cron string}` +5. CRD builder: `fission.io/v1` kind `TimeTrigger`, spec: `{cron, functionref: {name, namespace}}` +6. Таблица тайм-триггеров в UI с колонками: имя, функция, расписание, удалить + +#### Текущее состояние live кластера +- Fission bundle: `naeel/fission-bundle:v1.22.0-multi-ns-10` (executor + router) +- Console: `naeel/fission-console:v1.1` +- User namespace: `fission-ffd1f598c169b0ae` +- Функции: `88` (Python), `88node` (Node.js), `phppp` (PHP), `rub` (Ruby) +- Маршруты: `/f598c169b0ae/{name}` +- SSH: `naeel@5.172.178.213`, key `~/.ssh/naeel_vm_id_ed25519` +- Token: `grep -m1 "^api_token" /home/naeel/terra/terraform/TEST_STAND/POSTGRES/terraform.tfvars | sed -E "s/^api_token = \"(.*)\"$/\1/"` \ No newline at end of file diff --git a/token.txt b/token.txt new file mode 100644 index 0000000..659d224 --- /dev/null +++ b/token.txt @@ -0,0 +1,10 @@ +api_token = "eyJhbGciOiJSUzI1NiIsInR5cCI6IkpXVCJ9.eyJpc3MiOiJhdXRoLWFwaSIsInN1YiI6IjAxOWNjMjY4LTZjNmEtNzgxZS04NjEzLTRiZWQ0ZWM3Y2QyMCIsImV4cCI6MTc4OTAxNTg2NywiaWF0IjoxNzczNDYzODY3LCJqdGkiOiJmYjRkMGFiNy1lYT> +# s3_uid = "332cdb0d-34bf-43bf-864d-4adcc3b556fc" +s3_uid = "332cdb0d-34bf-43bf-864d-4adcc3b556fb" +# realm = "k8s-5-sandbox-nubes-ru" +realm = "k8s-3-sandbox-nubes-ru" +#realm = "naeel-test-3" + + + +eyJhbGciOiJSUzI1NiIsInR5cCI6IkpXVCJ9.eyJpc3MiOiJhdXRoLWFwaSIsInN1YiI6IjAxOWNjMjY4LTZjNmEtNzgxZS04NjEzLTRiZWQ0ZWM3Y2QyMCIsImV4cCI6MTc4OTAxNTg2Nywia \ No newline at end of file