From f96649b14ebd5886051e8ff24b63bce735d68f7d Mon Sep 17 00:00:00 2001 From: Repinoid Date: Wed, 7 Oct 2026 08:27:10 +0300 Subject: [PATCH] =?UTF-8?q?doc:=20P1.2=20=D1=81=D0=B4=D0=B5=D0=BB=D0=B0?= =?UTF-8?q?=D0=BD=20=E2=80=94=20=D1=80=D0=B5=D0=B7=D1=83=D0=BB=D1=8C=D1=82?= =?UTF-8?q?=D0=B0=D1=82=D1=8B,=20=D0=BD=D0=B0=D0=B9=D0=B4=D0=B5=D0=BD?= =?UTF-8?q?=D0=BD=D1=8B=D0=B9=20=D0=B4=D0=B5=D1=84=D0=B5=D0=BA=D1=82=20(?= =?UTF-8?q?=D1=83=D1=82=D0=B5=D1=87=D0=BA=D0=B0=20per-queue=20=D0=B1=D0=BB?= =?UTF-8?q?=D0=BE=D0=BA=D0=B8=D1=80=D0=BE=D0=B2=D0=BA=D0=B8)=20=D0=B8=20?= =?UTF-8?q?=D0=BF=D1=80=D0=BE=D0=B3=D0=BE=D0=BD=D1=8B=20=D1=82=D0=B5=D1=81?= =?UTF-8?q?=D1=82=D0=BE=D0=B2?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit --- HISTORY/2026-10-07-session-log.md | 111 ++++++++++++++++++ ...p1.1-per-queue-lock-analysis-2026-10-06.md | 9 ++ .../p1.2-message-index-design-2026-10-07.md | 57 +++++++++ 3 files changed, 177 insertions(+) create mode 100644 HISTORY/2026-10-07-session-log.md diff --git a/HISTORY/2026-10-07-session-log.md b/HISTORY/2026-10-07-session-log.md new file mode 100644 index 0000000..b5e764f --- /dev/null +++ b/HISTORY/2026-10-07-session-log.md @@ -0,0 +1,111 @@ +# История правок shared-sqs — 2026-10-07 (P1.2 + фикс утечки блокировки) + +> Запись по требованию «документировать всё, включая собственные ошибки». +> Предыдущие записи: `doc/thinking/*-2026-10-0[56].md`, `HISTORY/2026-08-1*-session-log.md`. + +## 1. Задача + +Пользователь: «доделать ПОЛНОСТЬЮ и протестировать SQS». Незакрытым по плану +`plan-for-flash-2026-10-05.md` оставался единственный пункт — **P1.2 +(индексация сообщений)**, отложенный 2026-10-06 с обоснованием. + +## 2. Что сделано + +### 2.1. Дизайн (коммит `b58e958`) + +`doc/thinking/p1.2-message-index-design-2026-10-07.md`. + +Ключевое решение: **tombstone + индексы + амортизированная компакция**. +Удаление не сдвигает срез (O(1)), поэтому индексы `receipt→index` и `uuid→index` +остаются валидными. Физическая чистка — `Compact`/`CompactIfNeeded` в `processQueueTick`. +Redis-схема не меняется (сообщения и так лежат в per-message HASH). + +### 2.2. Код (коммит `22e9bc8`) + +- `models.Queue`: `deadIdx`, `receiptIdx`, `uuidIdx`, `liveCount`, `deadCount` (все `json:"-"`) + + примитивы: `AppendMessage`, `RemoveIndex`, `Compact`, `CompactIfNeeded`, `Reset`, + `EnsureIndexes`/`RebuildIndexes`, `IndexOfReceipt`, `IndexOfUUID`, `MarkInFlight`, + `ClearInFlight`, `InFlightIndexes`, `IsDead`, `LiveCount`. +- `DeleteMessage` / `ChangeMessageVisibility(±Batch)` — поиск по индексу вместо скана среза; + удаление без сдвига остатка. +- `DeleteMessageBatch` — tombstone вместо полной пересборки среза. +- `processQueueTick` — visibility/DLQ по индексу in-flight (O(in-flight)), retention — через + tombstone, в конце — `CompactIfNeeded`. +- send-пути — `AppendMessage`/`LiveCount`; admin/metrics/persistence — учёт живых сообщений; + `LoadAllQueues` — `RebuildIndexes` после загрузки. + +### 2.3. Тесты (коммиты `e05af04`, `5b3fb51`) + +- `app/models/message_index_test.go` — 6 тестов примитивов (tombstone, компакция, индексы, Reset, порог). +- `app/gosqs/delete_middle_test.go` — удаление СЕРЕДИНЫ очереди через API: остальные не теряются, + удалённое не возвращается. +- `app/gosqs/tenant_flow_test.go` — существующие тесты переведены на `LiveCount()`; добавлен + `TestReceiveEmptyQueue_DoesNotLeakLock`. + +## 3. НАЙДЕННЫЙ ДЕФЕКТ (моя регрессия) — утечка per-queue блокировки + +### 3.1. Проявление + +Стресс (2000 сообщений × циклы): `ReadTimeout`, всплеск 1.9 с на `delete_batch`, +дальше — зависание сервиса (health при этом отвечает). + +### 3.2. Диагностика (факты, не догадки) + +- Снят стек горутин по `SIGQUIT`: десятки горутин в `sync.RWMutex.RLock` + (`models.go:101 Queue.RLockMu`), включая `metrics.updateGauges` (ждала 15 минут) + и HTTP-хендлеры `GetQueueAttributesV1`. +- Аудит всех `GetLocked`/`GetRLocked`: дефект ровно один. +- `receive_message.go`: + ```go + queue := models.SyncQueues.GetLocked(key) // Lock взят + if queue == nil || queue.LiveCount() == 0 { + return nil, false // ← возврат БЕЗ Unlock + } + defer queue.UnlockMu() + ``` + +### 3.3. Причина и почему проявилось именно сейчас + +Возврат до `defer` оставлял `queue.mu` захваченным навсегда (в Go мьютекс не +освобождается при выходе из функции). Прежнее условие `len(queue.Messages) == 0` +срабатывало только на полностью пустой очереди; после перехода на tombstone +появился новый случай `LiveCount()==0` при `len(Messages)>0` (все сообщения удалены, +компакция ещё не прошла) — типовой для последовательных циклов «залить → выгрести». + +### 3.4. Фикс + +`defer queue.UnlockMu()` — до любой проверки/возврата. Регрессионный тест +`TestReceiveEmptyQueue_DoesNotLeakLock` проверен на дефекте (падает за 2 с) +и на фиксе (зелёный). + +## 4. Результаты проверок (после фикса) + +| Проверка | Результат | +|---|---| +| `go build ./...`, `go vet ./...` | OK | +| `go test -race ./app/...` | зелёные | +| `tests/api_test.sh` (aws CLI, локальный сервис) | PASS=22 FAIL=0 | +| `tests/sdk_test.py` (boto3 1.43.108) | PASS=15 FAIL=0 | +| `tests/fifo_dlq_probe.py` | fifo_order / fifo_dedup / dlq = PASS | +| Стресс 3×2000 (send-batch → receive → delete-batch) | send ≈0.6 с, drain ≈1.2 с на цикл, `left=0/0`, вызовов >0.5 с нет | + +## 5. Инфраструктурные заметки (для повторного прогона) + +- Локальный сервис: `SHARED_SQS_SEED_DEMO=true /tmp/shared-sqs --admin-token=... --port=4100` + (memory-only без `REDIS_ADDR`; креды демо-тенанта печатаются в лог при старте). +- `boto3` в системе НЕ установлен (PEP 668) и `python3.12-venv` отсутствует → + wheels скачаны через `pip download` и распакованы в `/tmp/sqlibs_unpacked`, + запуск с `PYTHONPATH=/tmp/sqlibs_unpacked`. +- Лимит очередей тенанта — 10: падавшие скрипты оставляют очереди, перед прогоном + чистить (`aws sqs delete-queue`). +- `ENDPOINT` (api_test.sh) и `ENDPOINT_URL` (python-тесты) — разные имена переменных. + +## 6. Уроки + +1. Стресс-проверка обязательна: api/sdk/fifo проходили и с дефектом, он проявлялся + только на циклах полного опустошения очереди. +2. `SIGQUIT` — быстрый и точный способ найти зависание (кто держит мьютекс), дешевле догадок. +3. При замене условия на новый критерий (`len` → `LiveCount`) надо перечитывать + весь блок, включая порядок `defer` — старый код содержал латентную утечку лока, + которую новый критерий сделал массовой. +4. Не запускать сервис с `| head` — SIGPIPE убивает процесс на середине теста. diff --git a/doc/thinking/p1.1-per-queue-lock-analysis-2026-10-06.md b/doc/thinking/p1.1-per-queue-lock-analysis-2026-10-06.md index d57f36e..e7b0574 100644 --- a/doc/thinking/p1.1-per-queue-lock-analysis-2026-10-06.md +++ b/doc/thinking/p1.1-per-queue-lock-analysis-2026-10-06.md @@ -77,3 +77,12 @@ O(1): удаление из середины среза сдвигает все затрагивает сериализацию и все пути — крупная рискованная правка с маргинальной выгодой на текущих объёмах. Отложено до появления реальной нагрузки/лимитов. +## P1.2 — СДЕЛАНО (2026-10-07) + +Возврат к пункту по прямому указанию. Решение — tombstone + receipt/uuid-индексы ++ амортизированная компакция (удаление НЕ сдвигает срез → индексы стабильны, +O(1)-удаление без смены контейнера и без изменения Redis-схемы). +Дизайн и результаты: `p1.2-message-index-design-2026-10-07.md`. +По ходу найден и исправлен дефект утечки per-queue блокировки в receive +(возврат до `defer UnlockMu`) — см. там же, раздел 6. + diff --git a/doc/thinking/p1.2-message-index-design-2026-10-07.md b/doc/thinking/p1.2-message-index-design-2026-10-07.md index cb4640d..69ac1d1 100644 --- a/doc/thinking/p1.2-message-index-design-2026-10-07.md +++ b/doc/thinking/p1.2-message-index-design-2026-10-07.md @@ -95,3 +95,60 @@ get_queue_attributes}.go`, `app/admin/admin.go`, `app/metrics/gauge_updater.go`, 2. visibility-перерасчёт в тике идёт по числу in-flight, не по размеру очереди. 3. Все существующие тесты зелёные; добавлены тесты на tombstone/компакцию. 4. Redis-схема не изменилась; рестарт не «воскрешает» удалённые сообщения. + +## 6. РЕАЛИЗОВАНО (2026-10-07) — и найденный по ходу дефект + +Коммиты: `22e9bc8` (код), `e05af04` (тесты примитивов), `5b3fb51` (фикс ниже). + +### 6.1. Найденный дефект (МОЯ РЕГРЕССИЯ) — утечка per-queue блокировки + +При переводе `receiveMessagesUnderLock` на `LiveCount()` я сохранил исходный +порядок строк: + +```go +queue := models.SyncQueues.GetLocked(key) // взяли Lock +if queue == nil || queue.LiveCount() == 0 { + return nil, false // ← возврат БЕЗ Unlock +} +defer queue.UnlockMu() +``` + +Возврат на «пустой» очереди оставлял `queue.mu` захваченным НАВСЕГДА: любой +последующий `Lock`/`RLock` этой очереди ждал вечно (в Go мьютекс не +освобождается при выходе из функции). + +Почему стало заметно именно сейчас: раньше условие было `len(queue.Messages) == 0` +и срабатывало только на полностью пустой очереди; после перехода на tombstone +добавился новый случай — «все сообщения удалены, но срез ещё не компактирован» +(`LiveCount()==0` при `len(Messages)>0`), который в стресс-сценарии возникает +на каждом цикле. + +Диагностика (без гаданий): +- симптом: `ReadTimeout` при нагрузке 2000 сообщений, единичные всплески ~1.9 с на `delete_batch`; +- снят стек горутин по `SIGQUIT` → десятки горутин в `sync.RWMutex.RLock` на `Queue.RLockMu` + (`models.go:101`), включая `metrics.updateGauges`; HTTP-хендлеры `GetQueueAttributesV1` — там же. +- аудит всех `GetLocked`/`GetRLocked` показал: дефект ровно один — в `receive_message.go`. + +Фикс (`5b3fb51`): `defer queue.UnlockMu()` — ДО любой проверки/возврата. +Регрессионный тест `TestReceiveEmptyQueue_DoesNotLeakLock` (на дефекте падает +за 2 с, на фиксе — зелёный). + +### 6.2. Результаты проверок + +| Проверка | Результат | +|---|---| +| `go build ./...`, `go vet ./...` | OK | +| `go test -race ./app/...` | зелёные (admin, models, gosqs) | +| `tests/api_test.sh` (aws CLI, локальный сервис) | **PASS=22 FAIL=0** | +| `tests/sdk_test.py` (boto3) | **PASS=15 FAIL=0** | +| `tests/fifo_dlq_probe.py` | **fifo_order/fifo_dedup/dlq = PASS** | +| Стресс 3×2000 сообщений (send-batch → receive → delete-batch) | send ≈0.6 с, drain ≈1.2 с на цикл; `left=0/0`; ни одного вызова >0.5 с | + +Стресс подтверждает и отсутствие «протечки» tombstone: после каждого цикла +очередь возвращается к 0 живых (`CompactIfNeeded` в тике работает). + +### 6.3. Замечание + +В первом прогоне api/sdk/fifo уже проходили (22/22, 15/15, PASS×3) — то есть +дефект проявлялся не на каждом сценарии, а на последовательных циклах полного +опустошения очереди. Поэтому стресс-проверка была обязательной.