From 63bffe2865a670cb0ce24924ff0f406fb860c763 Mon Sep 17 00:00:00 2001 From: Anton Vakhrushev Date: Sun, 2 Aug 2026 11:01:42 +0300 Subject: [PATCH] =?UTF-8?q?=D0=9F=D1=80=D0=B8=D1=91=D0=BC=20=D0=BE=D1=82?= =?UTF-8?q?=D0=B2=D0=B5=D1=87=D0=B0=D0=B5=D1=82=20200=20=D0=B4=D0=BE=20?= =?UTF-8?q?=D1=81=D0=B2=D1=91=D1=80=D1=82=D0=BA=D0=B8,=20=D1=81=D0=B2?= =?UTF-8?q?=D1=91=D1=80=D1=82=D0=BA=D1=83=20=D0=B2=D0=B5=D0=B4=D1=91=D1=82?= =?UTF-8?q?=20=D1=84=D0=BE=D0=BD=D0=BE=D0=B2=D1=8B=D0=B9=20=D0=B2=D0=BE?= =?UTF-8?q?=D1=80=D0=BA=D0=B5=D1=80?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit - Очередью служит сама таблица: доставка ждёт свёртки в статусе `pending`, канал несёт только бит «есть работа». Переполнять нечего, падение процесса очередь не теряет, а подбор `pending` при старте — обычный проход воркера, а не отдельный код. Классификация исхода общая с пересборкой журнала. - Исход разбора начал отражать доставку, а не обстоятельства: отмена и занятость базы статус не меняют (иначе конкуренция за базу выводила бы доставку из очереди навсегда), паника свёртки больше не валит процесс, а учёт доставки идёт через транзакцию с повторами. - Длинный бюджет ответа выдан маршруту приёма, а не всему серверу: `write_timeout` в Go покрывает и чтение тела, и общий подъём снял бы защиту с остальных маршрутов. --- CLAUDE.md | 2 + Taskfile.yml | 9 + cmd/healthlog/reindex_report.go | 16 +- cmd/healthlog/reindex_test.go | 23 +- cmd/healthlog/serve.go | 120 ++++- cmd/healthlog/serve_test.go | 133 ++++++ config.docker.toml | 2 +- config.example.toml | 7 +- docs/architecture.md | 81 +++- docs/backlog/README.md | 2 +- .../cena-sliyaniya-na-shirokoj-dostavke.md | 12 +- docs/backlog/otvet-i-svyortka.md | 92 ---- docs/backlog/poryadok-zhurnala-na-priyome.md | 74 +++ docs/backlog/stats-nablyudaemost.md | 8 + docs/database.md | 9 +- docs/plan.md | 4 +- internal/fold/busy_test.go | 97 ++++ internal/fold/fold.go | 47 +- internal/fold/fold_test.go | 62 +++ internal/httpapi/httpapi.go | 22 +- internal/httpapi/httpapi_test.go | 30 +- internal/httpapi/ingest.go | 28 ++ internal/ingest/ingest.go | 114 +++-- internal/ingest/ingest_test.go | 145 ++++-- internal/replay/classify_test.go | 67 +++ internal/replay/player.go | 110 +++++ internal/replay/replay.go | 61 +-- internal/replay/worker.go | 232 ++++++++++ internal/replay/worker_test.go | 373 +++++++++++++++ internal/store/delivery.go | 81 +++- internal/store/errors.go | 34 +- .../migrations/00006_delivery_pending.sql | 20 + internal/store/pending_test.go | 153 +++++++ internal/store/tx.go | 5 +- .../.openspec.yaml | 2 + .../2026-08-02-otvet-i-svyortka/design.md | 431 ++++++++++++++++++ .../2026-08-02-otvet-i-svyortka/proposal.md | 86 ++++ .../specs/ingest/spec.md | 294 ++++++++++++ .../specs/parsing/spec.md | 17 + .../specs/reindex/spec.md | 115 +++++ .../specs/storage/spec.md | 94 ++++ .../2026-08-02-otvet-i-svyortka/tasks.md | 180 ++++++++ openspec/specs/ingest/spec.md | 304 ++++++++++++ openspec/specs/parsing/spec.md | 5 + openspec/specs/reindex/spec.md | 14 +- openspec/specs/storage/spec.md | 40 +- 46 files changed, 3561 insertions(+), 296 deletions(-) create mode 100644 cmd/healthlog/serve_test.go delete mode 100644 docs/backlog/otvet-i-svyortka.md create mode 100644 docs/backlog/poryadok-zhurnala-na-priyome.md create mode 100644 internal/fold/busy_test.go create mode 100644 internal/replay/classify_test.go create mode 100644 internal/replay/player.go create mode 100644 internal/replay/worker.go create mode 100644 internal/replay/worker_test.go create mode 100644 internal/store/migrations/00006_delivery_pending.sql create mode 100644 internal/store/pending_test.go create mode 100644 openspec/changes/archive/2026-08-02-otvet-i-svyortka/.openspec.yaml create mode 100644 openspec/changes/archive/2026-08-02-otvet-i-svyortka/design.md create mode 100644 openspec/changes/archive/2026-08-02-otvet-i-svyortka/proposal.md create mode 100644 openspec/changes/archive/2026-08-02-otvet-i-svyortka/specs/ingest/spec.md create mode 100644 openspec/changes/archive/2026-08-02-otvet-i-svyortka/specs/parsing/spec.md create mode 100644 openspec/changes/archive/2026-08-02-otvet-i-svyortka/specs/reindex/spec.md create mode 100644 openspec/changes/archive/2026-08-02-otvet-i-svyortka/specs/storage/spec.md create mode 100644 openspec/changes/archive/2026-08-02-otvet-i-svyortka/tasks.md create mode 100644 openspec/specs/ingest/spec.md diff --git a/CLAUDE.md b/CLAUDE.md index aeb8308..1cf1f6b 100644 --- a/CLAUDE.md +++ b/CLAUDE.md @@ -78,6 +78,8 @@ Module path — `git.vakhrushev.me/av/healthlog`. - `task verify:archive` — сходимость на живом архиве: весь `./data/raw` через разбор, повтор обязан дать то же состояние. В гейт не входит намеренно — минута прогона и данные, которых нет ни на какой другой машине +- `task verify:busy` — свёртка под удерживаемой блокировкой базы: занятость + обязана оставить доставку в очереди. В гейт не входит: 25 секунд на прогон - `task tidy` — `go mod tidy` - `task setup` — установка golangci-lint diff --git a/Taskfile.yml b/Taskfile.yml index 7567bd5..080b3d4 100644 --- a/Taskfile.yml +++ b/Taskfile.yml @@ -41,6 +41,15 @@ tasks: # платить за проверку, которая возможна только на этой машине. - go test ./internal/replay -run TestReplay -healthlog.archive={{.ARCHIVE | default (printf "%s/data/raw" .ROOT_DIR)}} -v -count=1 + verify:busy: + desc: 'Свёртка под удерживаемой блокировкой базы: занятость обязана оставить доставку в очереди (около 25 секунд)' + cmds: + # Не входит в `task test` и `task gate` намеренно: busy_timeout — пять + # секунд, повторов транзакции пять, и гейт гоняет тесты трижды. Проверяет + # при этом центральное решение задачи «разнести ответ и свёртку»: + # занятость базы — обстоятельство, а не свойство доставки. + - go test ./internal/fold -run TestBusy -healthlog.busy -v -count=1 + lint: desc: Запуск golangci-lint cmds: diff --git a/cmd/healthlog/reindex_report.go b/cmd/healthlog/reindex_report.go index 054ef5e..f309859 100644 --- a/cmd/healthlog/reindex_report.go +++ b/cmd/healthlog/reindex_report.go @@ -25,8 +25,9 @@ func writeReport(w io.Writer, r report) { r.replay.Bodies, r.replay.SkippedFiles, r.replay.Duplicates) p(" учёт: подобрано тел без записи %d, не удалось подобрать %d, записей без тела %d", r.replay.Adopted, r.replay.AdoptFailed, r.replay.Orphans) - p(" свёрнуто: %d; отказов: слой не выведен %d, содержимое %d, прочее %d", - r.replay.Folded, r.replay.FailedLayer, r.replay.FailedMalformed, r.replay.FailedOther) + p(" свёрнуто: %d; отказов: слой не выведен %d, содержимое %d, прочее %d, отложено %d", + r.replay.Folded, r.replay.FailedLayer, r.replay.FailedMalformed, r.replay.FailedOther, + r.replay.Deferred) p(" слияние: частично разобрано %d, несравнимых наборов %d", r.replay.Partial, r.replay.Incomparable) @@ -48,7 +49,12 @@ func writeReport(w io.Writer, r report) { // журнале, и предупреждать о нём значило бы отправлять человека искать // дефект там, где его нет. А вот «содержимое не разбирается» штатным не // является: тело один раз уже прошло проверку формы на приёме. - badFailures := r.replay.FailedOther > 0 || r.replay.FailedMalformed > 0 || r.replay.AdoptFailed > 0 + // + // Отложенные доставки (занятая база, отмена) сюда входят: пересборка идёт в + // свежий файл при единственном писателе, и такая доставка в собранной + // витрине просто отсутствует — вместе с теми, кто наследовал от неё слой. + badFailures := r.replay.FailedOther > 0 || r.replay.FailedMalformed > 0 || + r.replay.AdoptFailed > 0 || r.replay.Deferred > 0 if r.sourceMissing { p(" объектов: %d", r.replay.Buckets) @@ -111,8 +117,8 @@ func writeReport(w io.Writer, r report) { p("") } if badFailures { - p("отказы, которых быть не должно (%d прочих, %d по содержимому, %d при подборе) —", - r.replay.FailedOther, r.replay.FailedMalformed, r.replay.AdoptFailed) + p("отказы, которых быть не должно (%d прочих, %d по содержимому, %d при подборе, %d отложено) —", + r.replay.FailedOther, r.replay.FailedMalformed, r.replay.AdoptFailed, r.replay.Deferred) p("разберитесь по логу, прежде чем подменять базу.") p("") } diff --git a/cmd/healthlog/reindex_test.go b/cmd/healthlog/reindex_test.go index d53f366..72b7f46 100644 --- a/cmd/healthlog/reindex_test.go +++ b/cmd/healthlog/reindex_test.go @@ -86,8 +86,9 @@ func TestОтчётНеРаскрываетДанныхОЗдоровье(t *tes var buf bytes.Buffer writeReport(&buf, report{ replay: replay.Report{ - Bodies: 116, Folded: 116, Buckets: 2049, - Fingerprint: "aaaa", Partial: 53, + Bodies: 116, + Outcome: replay.Outcome{Folded: 116, Partial: 53}, + Buckets: 2049, Fingerprint: "aaaa", }, target: "/data/healthlog.db.rebuild", dbPath: "/data/healthlog.db", @@ -128,7 +129,9 @@ func TestПриездДоставокЗаПрогонОтменяетПодме var buf bytes.Buffer writeReport(&buf, report{ replay: replay.Report{ - Bodies: 116, Folded: 116, Buckets: 2049, Fingerprint: "aaaa", + Bodies: 116, + Outcome: replay.Outcome{Folded: 116}, + Buckets: 2049, Fingerprint: "aaaa", }, target: "/data/healthlog.db.rebuild", dbPath: "/data/healthlog.db", @@ -154,7 +157,7 @@ func TestПустойЖурналНеПечатаетПроцедуруПодм var buf bytes.Buffer writeReport(&buf, report{ - replay: replay.Report{Bodies: 0, Folded: 0, Fingerprint: "same"}, + replay: replay.Report{Bodies: 0, Fingerprint: "same"}, target: "/data/healthlog.db.rebuild", dbPath: "/data/healthlog.db", // Отпечатки совпадают: обе витрины пусты. @@ -176,7 +179,7 @@ func TestОтменённыйПрогонНеПечатаетПроцедуру var buf bytes.Buffer writeReport(&buf, report{ - replay: replay.Report{Bodies: 10, Folded: 3, Canceled: true}, + replay: replay.Report{Bodies: 10, Outcome: replay.Outcome{Folded: 3}, Canceled: true}, target: "/data/healthlog.db.rebuild", dbPath: "/data/healthlog.db", sourcePrint: "bbbb", @@ -217,7 +220,9 @@ func TestНепрочитаннаяЧастьЖурналаВидна(t *testing var buf bytes.Buffer writeReport(&buf, report{ replay: replay.Report{ - Bodies: 100, Folded: 100, Buckets: 2049, Fingerprint: "aaaa", + Bodies: 100, + Outcome: replay.Outcome{Folded: 100}, + Buckets: 2049, Fingerprint: "aaaa", // Симлинк на каталог суток уносит из прогона целый месяц одной // строкой счётчика. SkippedFiles: 1, @@ -245,7 +250,8 @@ func TestНеразобранноеСодержимоеПредупреждае var buf bytes.Buffer writeReport(&buf, report{ replay: replay.Report{ - Bodies: 100, Folded: 99, FailedMalformed: 1, + Bodies: 100, + Outcome: replay.Outcome{Folded: 99, FailedMalformed: 1}, Buckets: 2049, Fingerprint: "aaaa", }, target: "/data/healthlog.db.rebuild", dbPath: "/data/healthlog.db", @@ -264,7 +270,8 @@ func TestНевыведенныйСлойНеПоднимаетТревоги(t var buf bytes.Buffer writeReport(&buf, report{ replay: replay.Report{ - Bodies: 100, Folded: 98, FailedLayer: 2, + Bodies: 100, + Outcome: replay.Outcome{Folded: 98, FailedLayer: 2}, Buckets: 2049, Fingerprint: "aaaa", }, target: "/data/healthlog.db.rebuild", dbPath: "/data/healthlog.db", diff --git a/cmd/healthlog/serve.go b/cmd/healthlog/serve.go index b27cc59..a6a89e4 100644 --- a/cmd/healthlog/serve.go +++ b/cmd/healthlog/serve.go @@ -5,6 +5,8 @@ import ( "errors" "flag" "fmt" + "log/slog" + "net" "net/http" "os/signal" "syscall" @@ -16,11 +18,13 @@ import ( "git.vakhrushev.me/av/healthlog/internal/httpapi" "git.vakhrushev.me/av/healthlog/internal/ingest" "git.vakhrushev.me/av/healthlog/internal/logging" + "git.vakhrushev.me/av/healthlog/internal/replay" "git.vakhrushev.me/av/healthlog/internal/store" ) -// shutdownTimeout — сколько ждём завершения активных запросов при остановке. -// Приём может быть в середине записи многомегабайтного тела в архив. +// shutdownTimeout — общий бюджет остановки: сперва дожидаемся активных +// запросов, затем выхода воркера свёртки. Совпадает со `stop_grace_period` +// контейнера — за его пределом процесс всё равно убивают. const shutdownTimeout = 30 * time.Second func runServe(args []string) error { @@ -34,16 +38,40 @@ func runServe(args []string) error { if err != nil { return err } - log := logging.New(cfg.Log.Level, cfg.Log.Format) + ctx, stop := signal.NotifyContext(context.Background(), syscall.SIGINT, syscall.SIGTERM) + defer stop() + + return serve(ctx, cfg, logging.New(cfg.Log.Level, cfg.Log.Format), nil) +} + +// serve поднимает сервис и ведёт его до отмены контекста. +// +// Контекст параметром, а не подпиской на сигнал внутри: иначе весь жизненный +// цикл — порядок остановки, ожидание воркера, судьба несвёрнутой доставки — +// проверялся бы только посылкой сигнала самому себе, то есть не проверялся бы. +// +// ready, если задан, зовётся с ФАКТИЧЕСКИМ адресом прослушивания: при `:0` в +// конфиге узнать порт больше неоткуда. +func serve(ctx context.Context, cfg *config.Config, log *slog.Logger, ready func(addr string)) error { st, err := store.Open(cfg.Storage.DBPath) if err != nil { return err } - defer func() { _ = st.Close() }() + // Закрытие базы — не `defer`: при исчерпании бюджета остановки воркер может + // ещё сворачивать доставку, и закрытая из-под него база дала бы ERROR по + // доставке, с которой всё в порядке. Кто закрывает, решает ветка остановки. + closed := false + closeStore := func() { + if !closed { + closed = true + _ = st.Close() + } + } arch, err := archive.New(cfg.Storage.ArchiveDir) if err != nil { + closeStore() return err } @@ -51,16 +79,23 @@ func runServe(args []string) error { log.Warn("write auth disabled", "reason", "auth.write_tokens пуст") } - handler := httpapi.New(httpapi.Options{ - Ingest: ingest.New(arch, st, fold.New(arch, st, int64(cfg.Ingest.MaxBodyMB)<<20, log), log), - Log: log, - WriteTokens: cfg.Auth.WriteTokens, - MaxBodyMB: cfg.Ingest.MaxBodyMB, - }) + // Воркер и приём делят одну свёртку: приём её только будит, сворачивает + // воркер — и в порядке журнала, чего синхронная свёртка внутри обработчика + // не давала при конкурентных доставках. + worker := replay.NewWorker(st, fold.New(arch, st, int64(cfg.Ingest.MaxBodyMB)<<20, log), log) srv := &http.Server{ - Addr: cfg.Server.Addr, - Handler: handler, + Handler: httpapi.New(httpapi.Options{ + Ingest: ingest.New(arch, st, worker.Notify, log), + Log: log, + WriteTokens: cfg.Auth.WriteTokens, + MaxBodyMB: cfg.Ingest.MaxBodyMB, + // Бюджет ответа маршрута приёма: `WriteTimeout` сервера ставится ДО + // вызова обработчика и потому покрывает чтение тела, обрывая + // медленную загрузку молча. Длинный бюджет нужен одному маршруту, + // поэтому и выдаётся ему, а не всему серверу. + IngestWriteBudget: cfg.Server.ReadTimeout.D() + cfg.Server.WriteTimeout.D(), + }), // ReadTimeout щедрый (большой пакет по мобильной сети), но заголовки // обязаны приехать быстро — иначе полуоткрытое соединение держит слот. ReadHeaderTimeout: 10 * time.Second, @@ -68,33 +103,74 @@ func runServe(args []string) error { WriteTimeout: cfg.Server.WriteTimeout.D(), } - ctx, stop := signal.NotifyContext(context.Background(), syscall.SIGINT, syscall.SIGTERM) - defer stop() + ln, err := net.Listen("tcp", cfg.Server.Addr) + if err != nil { + closeStore() + return fmt.Errorf("listen %q: %w", cfg.Server.Addr, err) + } + + workerCtx, stopWorker := context.WithCancel(context.Background()) + defer stopWorker() + workerDone := make(chan struct{}) + go func() { + defer close(workerDone) + // Первый проход воркера и есть подбор неразобранного при старте: + // отдельного кода для него нет намеренно. + worker.Run(workerCtx) + }() errCh := make(chan error, 1) go func() { log.Info("server started", - "addr", cfg.Server.Addr, + "addr", ln.Addr().String(), "db_path", cfg.Storage.DBPath, "archive_dir", arch.Root(), "max_body_mb", cfg.Ingest.MaxBodyMB) - if err := srv.ListenAndServe(); err != nil && !errors.Is(err, http.ErrServerClosed) { - errCh <- fmt.Errorf("listen: %w", err) + if err := srv.Serve(ln); err != nil && !errors.Is(err, http.ErrServerClosed) { + errCh <- fmt.Errorf("serve: %w", err) } }() + if ready != nil { + ready(ln.Addr().String()) + } + var serveErr error select { - case err := <-errCh: - return err + case serveErr = <-errCh: + // Отказ приёма не отменяет остановки воркера: закрыть базу, не дождавшись + // его, значит выдернуть её из-под идущей свёртки и получить ERROR по + // доставке, с которой всё в порядке. Ошибка не логируется здесь — она + // возвращается наверх, и логирует её один раз вызывающий. case <-ctx.Done(): + log.Info("server stopping") } - log.Info("server stopping") shutdownCtx, cancel := context.WithTimeout(context.Background(), shutdownTimeout) defer cancel() + + // Приём прекращается РАНЬШЕ воркера: обратный порядок оставил бы доставки, + // принятые после его остановки, никого не разбудившими. if err := srv.Shutdown(shutdownCtx); err != nil { - return fmt.Errorf("shutdown: %w", err) + switch { + case errors.Is(err, context.DeadlineExceeded): + // Исчерпание бюджета Shutdown возвращает штатно, и отказом это не + // является: приём мог дочитывать многомегабайтное тело. + log.Warn("shutdown budget exceeded", "stage", "http") + case serveErr == nil: + serveErr = fmt.Errorf("shutdown: %w", err) + } } - return nil + + stopWorker() + select { + case <-workerDone: + closeStore() + case <-shutdownCtx.Done(): + // Воркер не вышел в бюджет. База не закрывается: её транзакцию свернёт + // выход процесса, и доставка останется `pending` — то есть будет + // подобрана следующим стартом. + log.Warn("shutdown budget exceeded", "stage", "fold-worker") + } + return serveErr } diff --git a/cmd/healthlog/serve_test.go b/cmd/healthlog/serve_test.go new file mode 100644 index 0000000..e97fbdd --- /dev/null +++ b/cmd/healthlog/serve_test.go @@ -0,0 +1,133 @@ +package main + +import ( + "context" + "log/slog" + "net/http" + "path/filepath" + "strings" + "testing" + "time" + + "git.vakhrushev.me/av/healthlog/internal/config" + "git.vakhrushev.me/av/healthlog/internal/store" +) + +// Приём и свёртка разнесены, но связаны: обработчик отвечает `200`, ничего не +// сворачивая, а фоновый воркер доводит доставку до витрины. Проверяется целиком, +// потому что связь между ними — сигнал, и оборвать его можно, не сломав ни один +// модульный тест. +func TestServeПринимаетИСворачиваетФоном(t *testing.T) { + dir := t.TempDir() + cfg := serveConfig(dir) + + ctx, cancel := context.WithCancel(context.Background()) + defer cancel() + + addrCh := make(chan string, 1) + done := make(chan error, 1) + go func() { + done <- serve(ctx, cfg, slog.New(slog.DiscardHandler), func(addr string) { addrCh <- addr }) + }() + + var addr string + select { + case addr = <-addrCh: + case err := <-done: + t.Fatalf("сервис не поднялся: %v", err) + } + + body := strings.NewReader(`{"data":{"metrics":[{"name":"heart_rate","units":"count/min","data":[` + + `{"date":"2026-07-31 12:00:00 +0300","Min":60,"Avg":62,"Max":65}]}]}}`) + req, err := http.NewRequestWithContext(ctx, http.MethodPost, "http://"+addr+"/api/v1/ingest", body) + if err != nil { + t.Fatalf("запрос: %v", err) + } + req.Header.Set("automation-aggregation", "Minutes") + + res, err := http.DefaultClient.Do(req) + if err != nil { + t.Fatalf("приём: %v", err) + } + _ = res.Body.Close() + if res.StatusCode != http.StatusOK { + t.Fatalf("статус приёма %d, ожидался 200", res.StatusCode) + } + + // Сигнал дошёл до воркера, и он довёл доставку до витрины. Опрос, а не сон: + // снаружи процесса другого шва нет, а сон превратил бы проверку в лотерею. + waitFolded(t, cfg.Storage.DBPath) + + // Остановка: приём прекращается раньше воркера, воркер выходит сам. + cancel() + select { + case err := <-done: + if err != nil { + t.Fatalf("остановка вернула ошибку: %v", err) + } + case <-time.After(shutdownTimeout + 10*time.Second): + t.Fatal("сервис не остановился в бюджет") + } + + // Инвариант остановки: доставка либо свёрнута целиком, либо числится + // `pending`; состояния «разобрана, а объектов половина» не существует. + st, err := store.Open(cfg.Storage.DBPath) + if err != nil { + t.Fatalf("база: %v", err) + } + defer func() { _ = st.Close() }() + + d, err := st.LastDelivery(context.Background()) + if err != nil { + t.Fatalf("LastDelivery: %v", err) + } + buckets, err := st.CountBuckets(context.Background()) + if err != nil { + t.Fatalf("CountBuckets: %v", err) + } + switch d.ParseStatus { + case store.ParseDone, store.ParsePartial: + if buckets == 0 { + t.Error("доставка числится разобранной, а объектов нет") + } + case store.ParsePending: + if buckets != 0 { + t.Error("доставка числится неразобранной, а объекты записаны") + } + default: + t.Errorf("parse_status = %q", d.ParseStatus) + } +} + +// waitFolded ждёт, пока фоновый воркер разберёт принятую доставку. +func waitFolded(t *testing.T, dbPath string) { + t.Helper() + + deadline := time.Now().Add(15 * time.Second) + for time.Now().Before(deadline) { + st, err := store.OpenForRead(dbPath) + if err == nil { + d, err := st.LastDelivery(context.Background()) + _ = st.Close() + if err == nil && d.ParseStatus != store.ParsePending { + if d.ParseStatus != store.ParseDone { + t.Fatalf("parse_status = %q, ожидался %q", d.ParseStatus, store.ParseDone) + } + return + } + } + time.Sleep(10 * time.Millisecond) + } + t.Fatal("воркер не свернул доставку: сигнал от приёма не дошёл") +} + +func serveConfig(dir string) *config.Config { + cfg := &config.Config{} + cfg.Server.Addr = "127.0.0.1:0" + cfg.Server.ReadTimeout = config.Duration(30 * time.Second) + cfg.Server.WriteTimeout = config.Duration(30 * time.Second) + cfg.Storage.DBPath = filepath.Join(dir, "healthlog.db") + cfg.Storage.ArchiveDir = filepath.Join(dir, "raw") + cfg.Ingest.MaxBodyMB = 1 + return cfg +} diff --git a/config.docker.toml b/config.docker.toml index e188f6d..25763a3 100644 --- a/config.docker.toml +++ b/config.docker.toml @@ -9,7 +9,7 @@ [server] addr = ":8080" read_timeout = "5m" # экспорт истории — десятки мегабайт, бывает медленно -write_timeout = "30s" +write_timeout = "30s" # прочих маршрутов; приём держит свой бюджет, см. config.example.toml [auth] write_tokens = [] # ПУСТО = проверка выключена, см. предупреждение выше diff --git a/config.example.toml b/config.example.toml index 229f2dc..c931eaa 100644 --- a/config.example.toml +++ b/config.example.toml @@ -7,7 +7,12 @@ [server] addr = ":8080" # адрес прослушивания; ":8080" — все интерфейсы (нужно, чтобы телефон достучался по локальной сети) read_timeout = "5m" # на всё чтение запроса вместе с телом; Go-duration. Щедро: экспорт истории — десятки мегабайт по мобильной сети -write_timeout = "30s" # на отправку ответа; Go-duration +# ВНИМАНИЕ: write_timeout в Go покрывает НЕ только отправку ответа. Он ставится +# до вызова обработчика и потому включает чтение тела: значение меньше +# read_timeout молча обрывает медленную загрузку. Маршрут приёма поэтому держит +# собственный бюджет (read_timeout + write_timeout), а это значение остаётся +# защитой от застрявшей записи ответа на остальных маршрутах. +write_timeout = "30s" # на отправку ответа прочих маршрутов; Go-duration [auth] # Токены проверяются как `Authorization: Bearer <токен>`. diff --git a/docs/architecture.md b/docs/architecture.md index 78f2ba3..6ae2000 100644 --- a/docs/architecture.md +++ b/docs/architecture.md @@ -223,9 +223,24 @@ HRV); у накопительных — только `date`. Поэтому то ``` запрос → токен → лимит тела, gzip → проверка формы JSON → запись тела в архив → строка в delivery → 200 - → разбор → запись в витрину + ↓ + фоновый воркер: разбор → запись в витрину ``` +**Ответ отдаётся до свёртки, и это контракт, а не деталь реализации.** `200` +означает «тело сохранено и учтено»; разобрано ли оно, говорит +`delivery.parse_status`, и говорит позже. Причина измерена: свёртка 16 тысяч +точек занимает 11 секунд, а `WriteTimeout` в Go ставится в `readRequest` — то +есть до вызова обработчика — и потому является общим бюджетом на чтение тела, +запись архива, учёт и свёртку. Исчерпав его, сервер считает, что отдал `200`, +клиент получает обрыв, а `accessLog` пишет `status_code=200`: единственный канал +наблюдаемости врёт. Бьёт это по широким проходам — ровно по тем, ради которых +заведён инвариант «дыры закрываются сами». + +Отсюда же второй бюджет: длинный дедлайн ответа выставляет **сам обработчик +приёма**, а не конфиг сервера. `write_timeout` глобален, и поднять его значило бы +снять защиту от застрявшей записи со всех маршрутов ради одного. + Код ответа определяется **доставкой**, не разбором: - **400** — тело не разбирается как JSON ожидаемой верхнеуровневой формы. @@ -236,6 +251,70 @@ HRV); у накопительных — только `date`. Поэтому то безопасности, исход разбора виден в логе, в `delivery.parse_status` и в `/stats`, а доразобрать их можно командой `reindex`. +#### Очередь свёртки — таблица, а не структура в памяти + +Доставка ждёт свёртки в собственном статусе `pending`; канал между приёмом и +воркером несёт один бит «есть работа». Это **transactional outbox**, он же «база +как очередь заданий»: состояние задания пишется той же базой, что и факт +события, а фоновый процесс выбирает необработанные строки. + +Три следствия, ради которых так и сделано: + +- **переполнять нечего** — доставка `pending` всегда, пока не свёрнута, поэтому + «очередь переполнена» невыразимо; +- **падение процесса очереди не теряет** — транзакция свёртки откатывается, + статус остаётся `pending`; +- **подбор `pending` при старте не является отдельным кодом** — это обычный + проход воркера, а не особый режим. + +Отвергнут **канал идентификаторов в памяти**: он вводит второе, недолговечное +представление того же факта, и эти два расходятся при каждом падении; политика +переполнения всё равно требует подбора из базы, то есть того же кода — только в +двух экземплярах. Отвергнут и **опрос по таймеру вместо сигнала**: полпериода +задержки на каждую доставку без пользы. Тик при этом взят **в дополнение** к +сигналу: доставка, оставшаяся в очереди по обстоятельствам, иначе ждала бы +следующей доставки, а ночью телефон молчит часами. + +Воркер один, и порядок у него тот же, что у пересборки — `(received_at, id)`: +слой доставки без плотных метрик наследуется от предшествующей доставки той же +автоматизации, то есть является функцией префикса журнала. Обещается достижимое: +в этом порядке сворачивается всё, что **видно воркеру** на момент выборки; +абсолютного порядка при конкурентных приёмах нет и быть не может без сериализации +самого приёма. + +Классификацию исхода свёртки воркер и пересборка делят (`internal/replay`): +второй классификатор разошёлся бы с первым молча, а по одному из его счётчиков +(`partial`) принимается решение о судьбе тела в архиве. + +**Исход разбора отражает доставку, а не обстоятельства.** Отмена и занятость +базы статус не меняют — доставка остаётся `pending` и будет свёрнута снова; +непонятое содержимое, невыводимый слой, нечитаемое тело, исчерпанный дедлайн и +паника свёртки дают `failed`. Различение появилось не из аккуратности: `failed` +из очереди выбывает навсегда и возвращается только пересборкой, а конкуренция за +базу между приёмом и свёрткой стала штатной — без него занятость стирала бы +доставку с полки молча. По той же причине учёт доставки идёт через транзакцию с +повторами: одиночная вставка пересиживала бы только `busy_timeout`, после чего +приём ответил бы `500` по доставке, тело которой уже на диске. + +**Паника свёртки перехватывается там же, где пишется исход разбора.** Пока +свёртка шла внутри обработчика, панику ловил транспорт и стоила она одного +ответа; из фоновой горутины она валит процесс, а перезапуск берёт ту же доставку +первой — дефект одной доставки становится циклом перезапуска, при котором приём +не работает вовсе. + +**Предел порядка назван вслух.** Метка приёма фиксируется раньше, чем строка +учёта становится видимой, поэтому две одновременные доставки могут закоммитить +строки в обратном порядке. Доставка без плотных метрик, свёрнутая раньше своей +предшественницы, слоя не выведет и уйдёт в `failed`: её точки доедут только +пересборкой. Окно узкое, и изменение его сужает, а не открывает, — но закрытие +предела требует удерживать порядок на самом приёме, и это отдельный вопрос +(беклог, блокеры). + +Остановка формулируется **инвариантом**: приём прекращается раньше воркера, и +после остановки не существует доставки, которая числится разобранной, а записана +наполовину. Обещать «текущая доставка досворачивается» нельзя — бюджет остановки +(30 с) меньше бюджета свёртки (2 мин). + #### Частичный разбор Разбор покрывает секцию `metrics`; `workouts`, `stateOfMind`, `symptoms`, `ecg` diff --git a/docs/backlog/README.md b/docs/backlog/README.md index 742c405..99f393e 100644 --- a/docs/backlog/README.md +++ b/docs/backlog/README.md @@ -18,6 +18,7 @@ либо берётся, либо отвергается с названной причиной. ## блокеры +- [Порядок журнала при конкурентных приёмах](poryadok-zhurnala-na-priyome.md) — доставка, свёрнутая раньше своей предшественницы, уходит в failed навсегда — живое состояние расходится с reindex ## высокий - [Тренировки и секции с собственными id](trenirovki-i-zapisi.md) — Тренировки с геотреком и состояние разума приходят, но не разбираются — без них не закрыть ни трекер, ни агента-медика @@ -25,7 +26,6 @@ - [Read API: точки, выбор слоя, свёртка по сетке](read-api-tochki.md) — Данные видны только через sqlite на хосте — ни один из трёх потребителей ничего прочитать не может - [OpenAPI-спека и Swagger UI](openapi-swagger.md) — Потребителей три и один из них агент — контракт должен читаться машиной, а не пересказываться в чате - [MCP-сервер поверх Read API](mcp-server.md) — Агент-медик — первый заказчик проекта, а подключить его сейчас нечем -- [Разнести ответ приёма и свёртку доставки](otvet-i-svyortka.md) — синхронная свёртка не помещается в write_timeout: широкие проходы получают обрыв вместо 200 ## средний - [Словарь категориальных значений → коды HealthKit](slovar-kategorialnyh-znachenij.md) — Фазы сна и типы тренировок приходят строками русской локали — с экспортом Apple их не сверить diff --git a/docs/backlog/cena-sliyaniya-na-shirokoj-dostavke.md b/docs/backlog/cena-sliyaniya-na-shirokoj-dostavke.md index 57a2c63..572f351 100644 --- a/docs/backlog/cena-sliyaniya-na-shirokoj-dostavke.md +++ b/docs/backlog/cena-sliyaniya-na-shirokoj-dostavke.md @@ -52,7 +52,11 @@ Form одной точки 2.2 мкс ## Связано -- [otvet-i-svyortka](otvet-i-svyortka.md) — воркер убирает влияние на ответ - приёму, но не на блокировку записи; задачи независимы. -- [reindex-iz-arhiva](reindex-iz-arhiva.md) — подбирает доставки, ушедшие в - `failed` по этой причине. +- Разнесение ответа приёма и свёртки **сделано** (архив change + `2026-08-02-otvet-i-svyortka`): воркер убрал влияние на время ответа, но не на + блокировку записи — длинная транзакция слияния держит её по-прежнему. Заодно + оттуда взято главное смягчение: занятость базы больше не выводит доставку из + очереди, она остаётся `pending` и пересворачивается. Оракул окна — + `task verify:busy`. +- Пересборка (`healthlog reindex`) подбирает доставки, ушедшие в `failed` по + другим причинам. diff --git a/docs/backlog/otvet-i-svyortka.md b/docs/backlog/otvet-i-svyortka.md deleted file mode 100644 index 3a8eed1..0000000 --- a/docs/backlog/otvet-i-svyortka.md +++ /dev/null @@ -1,92 +0,0 @@ -# Разнести ответ приёма и свёртку доставки - -**Приоритет:** высокий - -Была блокером, вынутым ревью кода задачи `razbor-metrik-v-obekty` (профиль -`deep`, находка №4 триажа, severity major). **Решение принято** — ниже задача. - -## Что не так сегодня - -Свёртка выполняется **синхронно внутри обработчика запроса**, поэтому время -ответа равно времени свёртки. - -`WriteTimeout` в Go ставится в `readRequest` — **до** чтения тела и до вызова -обработчика (`net/http/server.go:993-997`, прочитано в исходниках). Значит -30 секунд по умолчанию это бюджет на всё сразу: дочитать до 64 МиБ по -мобильной сети, сделать `fsync` архива, вставить доставку и свернуть. - -Воспроизведено минимальной программой: сервер с `WriteTimeout=200ms`, -обработчик спит 500 мс. - -``` -handler: WriteHeader(200), body Write err= -client: elapsed=501ms err=EOF -``` - -Сервер считает, что отдал `200` — ошибки записи не видно, ответ ушёл в буфер и -сбрасывается позже. Клиент получил обрыв. Код обработчика этого не видит, а -`accessLog` честно запишет `status_code=200`: единственный сегодняшний канал -наблюдаемости в этом сценарии врёт. - -Стоимость свёртки измерена **до** перехода на одну транзакцию на доставку: - -| тело | объектов | свёртка | -|---|---|---| -| 80 КиБ | 1001 | 815 мс | -| 323 КиБ | 4001 | 3.07 с | -| 1302 КиБ | 16001 | 11.07 с | - -Одна транзакция на доставку убрала около 0.7 мс на объект (прогон живого -архива ускорился с 64 до 52 секунд), но порядок величины остался: широкая -доставка по-прежнему измеряется секундами. - -Бьёт это по **широким проходам** — `Today`, `Previous 7 Days`, ручной -экспорт, — то есть ровно по тем, ради которых заведён инвариант «дыры -закрываются сами». - -## Что решено - -Вариант (а): **отвечать `200` сразу после архивации и учёта; свёртка — -воркером в порядке журнала, с подбором `pending` при старте.** - -Почему он, а не альтернативы: - -- Поднять `write_timeout` до согласованного с `foldTimeout` — дёшево, но - худший случай (64 МиБ) всё равно минуты, и молчание `accessLog` остаётся. - Это лечит симптом. -- Оставить как есть — широкие проходы продолжают рваться. - -Вариант (а) решает причину и попутно снимает две смежные дыры: параллельные -доставки одной автоматизации перестают гонять наследование слоя (сейчас вторая -может не найти слоя первой и уйти в `failed`), и доставка, застрявшая в -`pending` из-за сбоя записи, наконец кем-то подбирается. - -## Что делать - -1. Воркер свёртки: одна горутина, очередь идентификаторов доставок, обработка - **строго в порядке журнала** (`received_at`, `id`) — от этого зависит - наследование слоя и воспроизводимость. -2. Приём отвечает `200` после архивации и вставки доставки; свёртку ставит в - очередь. Очередь переполнена — доставка остаётся `pending`, это не отказ. -3. Подбор `pending` при старте, тем же путём. Это половина `reindex`, поэтому - код должен быть общим с ним, а не соседним. -4. Остановка сервиса дожидается текущей доставки: свёртка — одна транзакция, - рвать её нечем, но очередь надо дренировать осознанно. -5. Метка «доставка ждала свёртки дольше N» — в наблюдаемость, чтобы отставание - воркера было видно до того, как оно станет отставанием на сутки. -6. Тесты: порядок журнала соблюдается при конкурентных доставках; `pending` - подбирается при старте; отмена контекста не оставляет половинчатого - состояния; `task verify:archive` даёт то же состояние. - -## Что стоит без решения - -Ничего: свёртка работает, просто рискует не уложиться в таймаут на самых -широких доставках. Данные при этом не теряются — тело ложится в архив **до** -свёртки. - -## Связано - -- [reindex-iz-arhiva](reindex-iz-arhiva.md) — подбор `pending` это её половина; - делать одним кодом. -- [stats-nablyudaemost](stats-nablyudaemost.md) — метка «ответ не уложился в - таймаут» и отставание воркера должны попасть туда. diff --git a/docs/backlog/poryadok-zhurnala-na-priyome.md b/docs/backlog/poryadok-zhurnala-na-priyome.md new file mode 100644 index 0000000..ed79061 --- /dev/null +++ b/docs/backlog/poryadok-zhurnala-na-priyome.md @@ -0,0 +1,74 @@ +# Порядок журнала при конкурентных приёмах + +**Приоритет:** блокеры + +Вынут ревью кода задачи «Разнести ответ приёма и свёртку доставки» (профиль +`deep`, враждебный проход, находка с построенным путём и прогоном). + +## Что решить + +Метка `received_at` доставки фиксируется в момент выпуска ULID — **до** записи +тела в архив и до вставки строки учёта. Порядок, в котором строки становятся +видимыми воркеру, порядку меток не подчиняется: между выпуском идентификатора и +коммитом строки проходит запись тела (измерено 184 мс на 62 МиБ) плюс ожидание +занятой базы (до пяти секунд, а с повторами транзакции дольше). + +Путь построен и прогнан: + +1. Широкая доставка **A** автоматизации X получает `received_at = T1` и уходит + писать тело. +2. Узкая доставка **B** той же автоматизации (`T2 > T1`, только `sleep_analysis`, + плотных метрик нет) успевает закоммитить строку первой и будит воркер. +3. Воркер видит только B, сворачивает её, наследовать слой не от кого → + `ErrLayerUnknown` → `failed`. +4. `failed` фоновая свёртка не подбирает никогда. Точки B в витрину не попадут. + +Измерено на фикстурах: живой приём даёт `B=failed` и ноль часов +`sleep_analysis/minute`; журнальный порядок — `B=parsed` и два часа. То есть +живое состояние расходится с тем, что даст `healthlog reindex`, и расхождение +молчит: уровень лога у этого исхода `WARN`, такой же, как у штатного «у этой +автоматизации плотных метрик не бывает». + +**Это не регресс** — прежде свёртка шла в порядке завершения обработчиков, то +есть было хуже. Изменение окно сузило и назвало предел в спеке приёма; вопрос в +том, закрывать ли его совсем. + +## Варианты и цена + +**а. Резервировать строку учёта в начале `Accept`** (до записи тела), дописывая +`raw_path`/`bytes`/`sha256` после. Тогда видимость строки монотонна вместе с +`received_at`. Цена: ломается инвариант «тело на диск раньше строки учёта», +заведённый ровно затем, чтобы не было учтённой доставки без данных; появляется +новое состояние «строка есть, тела ещё нет», которое обязаны понимать пересборка +и ретеншен. + +**б. Откладывать свёртку доставки, пока она не «устоялась»** — не сворачивать +моложе N секунд. Цена: задержка N на каждую доставку и произвольное N: окно +занятости базы измерено до пяти секунд и зависит от нагрузки, так что N честно +не выбрать. + +**в. `ErrLayerUnknown` в живом пути не выводит доставку из очереди** — +ограниченное число повторов, потом `failed`. Цена: колонка счётчика попыток +(миграция) и политика «сколько попыток достаточно»; зато лечит и прочие случаи +«предшественница ещё не доехала». Требует правки спеки хранения («отказ разбора +⇒ `failed`»). + +**г. Ничего не делать**, оставив предел названным в спеке. Цена: редкая, +молчаливая потеря точек у автоматизаций без плотных метрик; лечится +`healthlog reindex` с остановкой сервиса и ручной подменой базы, но узнать о +необходимости неоткуда — счётчика `failed` в рантайме нет. + +## Что заблокировано + +Ничего: задача про разнесение ответа и свёртки доведена до конца в объявленных +границах, предел записан в спеке приёма. Заблокировано только **закрытие** +предела. + +Смежно: пока предел жив, полезно уметь сверять живую витрину с пересборкой — +`reindex` уже печатает оба отпечатка, но по расписанию их никто не сравнивает. + +## Рекомендация + +**(в)**, но не раньше `/stats`: сперва должно стать видно, сколько доставок +числится `failed` и как давно, — иначе повторы будут лечить болезнь, которую +никто не наблюдает. До тех пор — (г) с уже записанным пределом. diff --git a/docs/backlog/stats-nablyudaemost.md b/docs/backlog/stats-nablyudaemost.md index 0c78ca4..3a8861c 100644 --- a/docs/backlog/stats-nablyudaemost.md +++ b/docs/backlog/stats-nablyudaemost.md @@ -14,5 +14,13 @@ Готово, когда по одному запросу видно, какая из автоматизаций замолчала и когда. +Отдельной строкой — **отставание фоновой свёртки**: длина очереди +(`parse_status = 'pending'`) и возраст самой старой неразобранной доставки. +Сегодня об этом говорят только две метки в логе (`WARN` «доставка ждала свёртки +дольше пяти минут» и `INFO` о размере задолженности при старте), а `/healthz` +статичен и здорового сервиса от сервиса с сотней несвёрнутых тел не отличает. +Пришло из задачи «Разнести ответ приёма и свёртку доставки»: там числа +намеренно не заводились, чтобы не предрешать форму счётчиков этой задачи. + Активное уведомление — отдельная задача, здесь только факт. diff --git a/docs/database.md b/docs/database.md index 7bf6828..a123b66 100644 --- a/docs/database.md +++ b/docs/database.md @@ -56,7 +56,14 @@ SQLite (`modernc.org/sqlite`, чистый Go), миграции — goose, фа | `derived_layer` | слой, выведенный для этой доставки. Нужен не отчётности, а самому выводу: доставка без плотных метрик наследует последний надёжно выведенный слой той же автоматизации, и без хранения этой памяти первая такая доставка после перезапуска осталась бы без слоя | Индексы: `delivery_received_at` (порядок журнала), `delivery_sha256` (учёт -повторов), `delivery_automation_layer` (поиск последнего слоя автоматизации). +повторов), `delivery_automation_layer` (поиск последнего слоя автоматизации), +`delivery_pending` (очередь свёртки). + +`delivery_pending` **частичный** — только строки со статусом `pending`. Таблица +и есть очередь фоновой свёртки: воркер выбирает неразобранные доставки в +порядке журнала чаще, чем раз в минуту. В установившемся режиме в индексе +ноль-одна строка, тогда как полный индекс по `parse_status` хранил бы всю +историю ради выборки из одной. ## `bucket` — часовой объект точек diff --git a/docs/plan.md b/docs/plan.md index b4ca303..471c8ec 100644 --- a/docs/plan.md +++ b/docs/plan.md @@ -12,8 +12,8 @@ ## Ближайшая цель Метрики разбираются и ложатся в часовые объекты: тела перестали быть -недифференцированной кучей. Блокеры, накопившиеся из ревью, разобраны — их в -беклоге ноль. +недифференцированной кучей. Приём отвечает `200`, не дожидаясь свёртки: её ведёт +фоновый воркер, для которого очередью служит сама таблица доставок. **`reindex` сделан**: журнал проигрывается в свежую витрину, отпечатки сравниваются, повторный прогон ничего не меняет. Доставки, числящиеся `pending` diff --git a/internal/fold/busy_test.go b/internal/fold/busy_test.go new file mode 100644 index 0000000..54be352 --- /dev/null +++ b/internal/fold/busy_test.go @@ -0,0 +1,97 @@ +package fold_test + +import ( + "bytes" + "context" + "database/sql" + "errors" + "flag" + "log/slog" + "path/filepath" + "strings" + "testing" + + _ "modernc.org/sqlite" // тот же чистый Go-драйвер, что и у хранилища + + "git.vakhrushev.me/av/healthlog/internal/archive" + "git.vakhrushev.me/av/healthlog/internal/fold" + "git.vakhrushev.me/av/healthlog/internal/store" +) + +// Прогон под удерживаемой блокировкой намеренно не входит в `task test` и +// `task gate`: `busy_timeout` — пять секунд, повторов транзакции пять, то есть +// один этот тест стоит около двадцати пяти секунд, а гейт гоняет тесты трижды +// (обычно, на флаки и под детектором гонок). +// +// Проверяет он при этом центральное решение задачи «разнести ответ и свёртку»: +// занятость базы — обстоятельство, а не свойство доставки, и доставка обязана +// остаться в очереди. Ошибка здесь означает молчаливую потерю: `failed` фоновая +// свёртка не подбирает никогда, а вернуть доставку может только пересборка с +// остановкой сервиса и ручной подменой базы. +var runBusy = flag.Bool("healthlog.busy", false, + "прогнать свёртку под удерживаемой блокировкой базы (около 25 секунд)") + +func TestBusyЗанятаяБазаОставляетДоставкуВОчереди(t *testing.T) { + if !*runBusy { + t.Skip("прогон под блокировкой выключен: задайте -healthlog.busy") + } + + dir := t.TempDir() + dbPath := filepath.Join(dir, "healthlog.db") + + arch, err := archive.New(filepath.Join(dir, "raw")) + if err != nil { + t.Fatalf("архив: %v", err) + } + st, err := store.Open(dbPath) + if err != nil { + t.Fatalf("база: %v", err) + } + defer func() { _ = st.Close() }() + + var logs bytes.Buffer + f := fold.New(arch, st, 0, slog.New(slog.NewJSONHandler(&logs, nil))) + deliver(t, arch, st, "d1", "Minutes", "auto-1", fixture(t, "minute.json")) + + // Второе соединение держит запись, как её держит свёртка широкой доставки: + // измерено 11 секунд на 16 тысячах объектов, то есть окно реальное. + holder, err := sql.Open("sqlite", "file:"+dbPath+"?_pragma=busy_timeout(100)&_txlock=immediate") + if err != nil { + t.Fatalf("второе соединение: %v", err) + } + defer func() { _ = holder.Close() }() + + tx, err := holder.BeginTx(context.Background(), nil) + if err != nil { + t.Fatalf("удержание записи: %v", err) + } + if _, err := tx.Exec(`UPDATE delivery SET points = points WHERE id = 'd1'`); err != nil { + t.Fatalf("удержание записи: %v", err) + } + defer func() { _ = tx.Rollback() }() + + _, err = f.Fold(context.Background(), "d1") + if !errors.Is(err, store.ErrBusy) { + t.Fatalf("ошибка свёртки = %v, ожидалась %v", err, store.ErrBusy) + } + + status, err := st.DeliveryStatus(context.Background(), "d1") + if err != nil { + t.Fatalf("DeliveryStatus: %v", err) + } + if status != store.ParsePending { + t.Errorf("parse_status = %q, ожидался %q: занятость базы вывела доставку из очереди", + status, store.ParsePending) + } + + // Статуса мало: пока база занята, запись `failed` тоже не проходит, и + // `pending` получился бы и без правила. Различает их лог — свёртка обязана + // сказать «отложено», а не «отказ». + out := logs.String() + if !strings.Contains(out, "delivery fold deferred") { + t.Errorf("нет записи об отложенной свёртке:\n%s", out) + } + if strings.Contains(out, "delivery fold failed") { + t.Errorf("занятость базы записана отказом доставки:\n%s", out) + } +} diff --git a/internal/fold/fold.go b/internal/fold/fold.go index 0ed88f9..1925126 100644 --- a/internal/fold/fold.go +++ b/internal/fold/fold.go @@ -90,13 +90,33 @@ type Stats struct { UncoveredDropped int } +// ErrPanicked — свёртка паниковала. Доставка получает `failed`: тело в архиве, и +// пересборка вернёт её, когда дефект будет исправлен. +var ErrPanicked = errors.New("свёртка паниковала") + // Fold разбирает тело доставки и раскладывает точки по часовым объектам. // // Это единственный логирующий чекпоинт свёртки: транспорт и приём исход // разбора не логируют. Значения точек и имена устройств в лог не попадают — // данные о здоровье чувствительнее токенов. -func (s *Service) Fold(ctx context.Context, deliveryID string) (Stats, error) { - var stats Stats +// +// Паника перехватывается ЗДЕСЬ, у той же границы, что пишет исход разбора. +// Пока свёртка шла внутри HTTP-обработчика, панику ловил middleware.Recoverer и +// она стоила одного ответа; из фоновой горутины она валит процесс целиком, а +// `restart: unless-stopped` поднимает его снова — и первый же проход берёт ту +// же доставку, то есть дефект превращается в цикл перезапуска, при котором +// приём не работает вовсе. Перехват у этой границы, а не у вызывающего, +// оставляет писателя `parse_status` единственным. +func (s *Service) Fold(ctx context.Context, deliveryID string) (stats Stats, err error) { + defer func() { + r := recover() + if r == nil { + return + } + stats = Stats{} + err = fmt.Errorf("%w: %v", ErrPanicked, r) //nolint:errorlint // причину раскрываем текстом, sentinel — для ветвления + s.fail(ctx, deliveryID, err, nil) + }() d, err := s.store.DeliveryForParse(ctx, deliveryID) if err != nil { @@ -282,9 +302,28 @@ func (s *Service) finish(ctx context.Context, deliveryID string, out store.Parse return nil } -// fail отмечает доставку неразобранной. Тело остаётся в архиве, и её подберёт -// пересборка — приём при этом не затрагивается: сохранили значит приняли. +// fail записывает исход неудачной свёртки. +// +// Исход отражает ДОСТАВКУ, а не обстоятельства. Отмена снаружи и занятость базы +// работой доставки не являются: они означают «не сделано», а не «не выходит». +// Статус в этих случаях не трогается вовсе — доставка остаётся `pending` и +// подбирается следующим проходом. Иначе конкуренция за базу (после разнесения +// ответа и свёртки она штатная) выводила бы доставку из очереди навсегда: +// `failed` возвращает только пересборка, то есть ручная операция с остановкой +// сервиса. +// +// Всё прочее — непонятое содержимое, невыводимый слой, нечитаемое или слишком +// большое тело, исчерпанный дедлайн — свойства самой доставки, и повторять их +// бесполезно: статус `failed`, тело ждёт пересборки. Приём при этом не +// затрагивается: сохранили значит приняли. func (s *Service) fail(ctx context.Context, deliveryID string, cause error, uncovered []string) { + if store.Transient(cause) { + // WARN, а не ERROR: пройдёт само, разбирать нечего. Строка нужна, чтобы + // повтор не выглядел беспричинным. + s.log.WarnContext(ctx, "delivery fold deferred", "error", cause, "delivery_id", deliveryID) + return + } + level := slog.LevelError switch { case errors.Is(cause, hae.ErrLayerUnknown): diff --git a/internal/fold/fold_test.go b/internal/fold/fold_test.go index 8a4f0ba..14bfe16 100644 --- a/internal/fold/fold_test.go +++ b/internal/fold/fold_test.go @@ -324,3 +324,65 @@ func TestFoldПересвёрткаОчищаетСписок(t *testing.T) { t.Errorf("статус %q, ожидался %q", d.ParseStatus, store.ParseDone) } } + +// Отмена снаружи не превращается в свойство доставки: работа не сделана, но +// доставка остаётся в очереди и будет свёрнута снова. Иначе остановка сервиса в +// неудачный момент выводила бы доставку из очереди навсегда — `failed` фоновая +// свёртка не подбирает никогда, и вернуть её могла бы только пересборка с +// остановкой сервиса и ручной подменой базы. +func TestFoldОтменаОставляетДоставкуВОчереди(t *testing.T) { + t.Parallel() + + f, arch, st := newFold(t) + deliver(t, arch, st, "d1", "Minutes", "auto-1", fixture(t, "minute.json")) + + ctx, cancel := context.WithCancel(context.Background()) + cancel() + + if _, err := f.Fold(ctx, "d1"); err == nil { + t.Fatal("свёртка на отменённом контексте прошла успешно") + } + + status, err := st.DeliveryStatus(context.Background(), "d1") + if err != nil { + t.Fatalf("DeliveryStatus: %v", err) + } + if status != store.ParsePending { + t.Errorf("parse_status = %q, ожидался %q", status, store.ParsePending) + } + + n, err := st.CountBuckets(context.Background()) + if err != nil { + t.Fatalf("CountBuckets: %v", err) + } + if n != 0 { + t.Errorf("объектов %d: прерванная свёртка оставила половину", n) + } +} + +// Непонятое содержимое, наоборот, свойство самой доставки: повторять её +// бесполезно, и она выводится из очереди. +func TestFoldНепонятоеСодержимоеВыводитИзОчереди(t *testing.T) { + t.Parallel() + + f, arch, st := newFold(t) + ctx := context.Background() + + // Метрика есть, но слой определить нечем: плотных метрик нет, заголовок + // ничего не означает, наследовать не от чего. + body := []byte(`{"data":{"metrics":[{"name":"m","units":"u","data":[` + + `{"date":"2026-07-31 12:00:00 +0300","qty":1}]}]}}`) + deliver(t, arch, st, "d1", "Default", "auto-1", body) + + if _, err := f.Fold(ctx, "d1"); err == nil { + t.Fatal("свёртка непонятого содержимого прошла успешно") + } + + status, err := st.DeliveryStatus(ctx, "d1") + if err != nil { + t.Fatalf("DeliveryStatus: %v", err) + } + if status != store.ParseFailed { + t.Errorf("parse_status = %q, ожидался %q", status, store.ParseFailed) + } +} diff --git a/internal/httpapi/httpapi.go b/internal/httpapi/httpapi.go index c91848a..3b64210 100644 --- a/internal/httpapi/httpapi.go +++ b/internal/httpapi/httpapi.go @@ -23,22 +23,28 @@ type Options struct { Log *slog.Logger WriteTokens []string MaxBodyMB int + // IngestWriteBudget — сколько отводится маршруту приёма на чтение тела + // вместе с отправкой ответа. Ноль означает «полагаться на WriteTimeout + // сервера», и полагаться на него нельзя, см. handleIngest. + IngestWriteBudget time.Duration } type api struct { - ingest *ingest.Service - log *slog.Logger - writeTokens []string - maxBody int64 + ingest *ingest.Service + log *slog.Logger + writeTokens []string + maxBody int64 + ingestBudget time.Duration } // New собирает HTTP-роутер. func New(o Options) http.Handler { a := &api{ - ingest: o.Ingest, - log: o.Log, - writeTokens: o.WriteTokens, - maxBody: int64(o.MaxBodyMB) << 20, + ingest: o.Ingest, + log: o.Log, + writeTokens: o.WriteTokens, + maxBody: int64(o.MaxBodyMB) << 20, + ingestBudget: o.IngestWriteBudget, } r := chi.NewRouter() diff --git a/internal/httpapi/httpapi_test.go b/internal/httpapi/httpapi_test.go index 8df16fc..71afc62 100644 --- a/internal/httpapi/httpapi_test.go +++ b/internal/httpapi/httpapi_test.go @@ -3,6 +3,7 @@ package httpapi_test import ( "bytes" "compress/gzip" + "context" "encoding/json" "log/slog" "net/http" @@ -10,9 +11,9 @@ import ( "path/filepath" "strings" "testing" + "time" "git.vakhrushev.me/av/healthlog/internal/archive" - "git.vakhrushev.me/av/healthlog/internal/fold" "git.vakhrushev.me/av/healthlog/internal/httpapi" "git.vakhrushev.me/av/healthlog/internal/ingest" "git.vakhrushev.me/av/healthlog/internal/store" @@ -259,6 +260,28 @@ func TestHealthz(t *testing.T) { } } +// Транспорт, не умеющий дедлайнов, приём не роняет: цена отказа здесь наивысшая +// в проекте — доставка, не попавшая в архив, не попадает и в журнал. +func TestПриёмРаботаетНаТранспортеБезДедлайнов(t *testing.T) { + h, st := newAPI(t, nil) + + req := httptest.NewRequest(http.MethodPost, "/api/v1/ingest", + strings.NewReader(`{"data":{"metrics":[]}}`)) + rec := httptest.NewRecorder() + h.ServeHTTP(rec, req) + + if rec.Code != http.StatusOK { + t.Fatalf("статус = %d, ожидался 200", rec.Code) + } + n, err := st.CountDeliveries(context.Background()) + if err != nil { + t.Fatalf("CountDeliveries: %v", err) + } + if n != 1 { + t.Errorf("доставок в учёте %d, ожидалась 1", n) + } +} + func newAPI(t *testing.T, writeTokens []string) (http.Handler, *store.Store) { t.Helper() dir := t.TempDir() @@ -276,10 +299,13 @@ func newAPI(t *testing.T, writeTokens []string) (http.Handler, *store.Store) { log := slog.New(slog.DiscardHandler) h := httpapi.New(httpapi.Options{ - Ingest: ingest.New(arch, st, fold.New(arch, st, 0, log), log), + Ingest: ingest.New(arch, st, nil, log), Log: log, WriteTokens: writeTokens, MaxBodyMB: 1, + // Бюджет задаётся всегда: httptest.ResponseRecorder дедлайнов не умеет, + // и это ровно тот транспорт, на котором приём обязан продолжать работать. + IngestWriteBudget: time.Minute, }) return h, st } diff --git a/internal/httpapi/ingest.go b/internal/httpapi/ingest.go index 53bd133..de7a3cd 100644 --- a/internal/httpapi/ingest.go +++ b/internal/httpapi/ingest.go @@ -6,6 +6,7 @@ import ( "io" "net/http" "strings" + "time" "git.vakhrushev.me/av/healthlog/internal/ingest" ) @@ -22,6 +23,8 @@ type ingestResponse struct { // Код ответа отражает ДОСТАВКУ, а не разбор: 200 означает «тело сохранено в // архив», и этого достаточно, потому что разобрать сохранённое можно всегда. func (a *api) handleIngest(w http.ResponseWriter, r *http.Request) { + a.extendWriteDeadline(w, r) + body, err := readBody(w, r, a.maxBody) if err != nil { writeReadError(w, err) @@ -46,6 +49,31 @@ func (a *api) handleIngest(w http.ResponseWriter, r *http.Request) { }) } +// extendWriteDeadline даёт маршруту приёма собственный бюджет ответа. +// +// `WriteTimeout` сервера ставится в `readRequest`, то есть ДО вызова +// обработчика, и потому покрывает не только запись ответа, но и чтение тела: +// при `read_timeout` в пять минут и `write_timeout` в тридцать секунд загрузка +// длиннее тридцати секунд обрывается, а `read_timeout` при этом обещает пять +// минут. Обрывается молча — обработчик ошибки записи не видит, а `accessLog` +// пишет `status_code=200`. +// +// Лечится это здесь, а не подъёмом общего таймаута: длинный бюджет нужен +// одному маршруту, и подъём снял бы защиту от застрявшей записи со всех +// остальных. +// +// Транспорт, не умеющий дедлайнов, отказом приёма не является: приём — +// единственное место, где поток вообще существует, и терять доставку из-за +// неподдержанной оптимизации нельзя. +func (a *api) extendWriteDeadline(w http.ResponseWriter, r *http.Request) { + if a.ingestBudget <= 0 { + return + } + if err := http.NewResponseController(w).SetWriteDeadline(time.Now().Add(a.ingestBudget)); err != nil { + a.log.DebugContext(r.Context(), "write deadline not set", "error", err) + } +} + // metaFromHeaders достаёт то, что автоматизация Health Auto Export // рассказывает о себе своими заголовками. Именованные поля — те, по которым // ходят запросы; полный набор кладётся рядом, потому что документация HAE diff --git a/internal/ingest/ingest.go b/internal/ingest/ingest.go index cf4fa63..d1fc1a6 100644 --- a/internal/ingest/ingest.go +++ b/internal/ingest/ingest.go @@ -14,7 +14,6 @@ import ( "time" "git.vakhrushev.me/av/healthlog/internal/archive" - "git.vakhrushev.me/av/healthlog/internal/fold" "git.vakhrushev.me/av/healthlog/internal/ident" "git.vakhrushev.me/av/healthlog/internal/store" ) @@ -48,33 +47,56 @@ type Result struct { RawPath string } -// foldTimeout — сколько отводится свёртке принятой доставки. +// recordTimeout — сколько отводится записи учёта доставки. // -// Свёртка идёт на контексте, отвязанном от запроса, поэтому собственный -// дедлайн обязателен: без него зависшая запись держала бы горутину до конца -// жизни процесса. -const foldTimeout = 2 * time.Minute +// Учёт ведётся на контексте, переживающем обрыв соединения (см. Accept), +// поэтому собственный дедлайн обязателен: без него отказ базы держал бы +// обработчик неограниченно. +const recordTimeout = 10 * time.Second -// Service принимает пакеты: сохраняет тело в архив, учитывает доставку и -// запускает её свёртку. +// Notify — «есть работа»: сигнал тому, кто сворачивает принятое. +// +// Функцией, а не интерфейсом: сигнал ничего не несёт и ничего не возвращает, +// а приёму незачем знать, кто именно свернёт доставку. +type Notify func() + +// Service принимает пакеты: сохраняет тело в архив, учитывает доставку и будит +// свёртку. +// +// Сворачивать сам он не умеет намеренно. Свёртка широкой доставки идёт +// секундами, а `WriteTimeout` в Go ставится до вызова обработчика — то есть +// синхронная свёртка тратила бы бюджет ответа и обрывала бы соединение молча, +// с записью `status_code=200` в журнале доступа. type Service struct { - arch *archive.Archive - store *store.Store - fold *fold.Service - log *slog.Logger + arch *archive.Archive + store *store.Store + notify Notify + log *slog.Logger } // New собирает use-case приёма. -func New(arch *archive.Archive, st *store.Store, f *fold.Service, log *slog.Logger) *Service { - return &Service{arch: arch, store: st, fold: f, log: log.With("capability", "ingest")} +// +// Нулевой notify означает «о свёртке заботится вызывающий» и приводится к +// пустой функции здесь же, один раз: проверка на nil в месте вызова рано или +// поздно окажется забытой, а паника там наступила бы ПОСЛЕ того, как тело уже +// записано и доставка учтена, — то есть отправитель получил бы отказ по +// сохранённой доставке. +func New(arch *archive.Archive, st *store.Store, notify Notify, log *slog.Logger) *Service { + if notify == nil { + notify = func() {} + } + return &Service{arch: arch, store: st, notify: notify, log: log.With("capability", "ingest")} } -// Accept принимает тело пакета: проверяет форму, кладёт в сырой архив и -// заводит запись о доставке. +// Accept принимает тело пакета: проверяет форму, кладёт в сырой архив, заводит +// запись о доставке и будит свёртку. // // Порядок важен: сначала тело оказывается на диске, и только потом появляется // учётная запись. Обратный порядок дал бы учтённую доставку без данных. // +// Возврат означает «сохранено и учтено», а не «разобрано»: доставка уезжает в +// очередь свёртки статусом `pending`, и её исход появится позже. +// // Это единственный логирующий чекпоинт приёма — транспорт исход не логирует. func (s *Service) Accept(ctx context.Context, body []byte, meta Meta) (Result, error) { if err := checkEnvelope(body); err != nil { @@ -94,9 +116,14 @@ func (s *Service) Accept(ctx context.Context, body []byte, meta Meta) (Result, e // к часам. Источник обязан быть один: у тела, лежащего в архиве без учётной // записи, метку восстанавливают из ULID, и два разных источника разошлись бы // на границе секунды — а от порядка журнала зависит наследование слоя. + // Ошибка здесь означает, что наш же генератор выдал неразбираемый + // идентификатор. Второго источника времени тут быть не может — он разошёлся + // бы с меткой, которую пересборка восстанавливает из ULID; поэтому отказ, а + // не подмена. Тело на диск ещё не легло, так что доставка не теряется. receivedAt, err := ident.TimeOf(res.DeliveryID) if err != nil { - receivedAt = store.Now() + s.log.ErrorContext(ctx, "delivery failed", "error", err, "delivery_id", res.DeliveryID) + return Result{}, fmt.Errorf("метка приёма из идентификатора: %w", err) } rawPath, err := s.arch.Write(res.DeliveryID, receivedAt, body) @@ -106,7 +133,15 @@ func (s *Service) Accept(ctx context.Context, body []byte, meta Meta) (Result, e } res.RawPath = rawPath - err = s.store.CreateDelivery(ctx, store.Delivery{ + // Учёт ведётся на контексте, ПЕРЕЖИВАЮЩЕМ обрыв соединения. Тело к этому + // моменту уже на диске (arch.Write контекста не берёт), и отказ вставки + // из-за ушедшего клиента оставил бы тело сиротой: доставки в журнале нет, + // а вернуть её может только пересборка с ручной подменой базы. Проверка + // формы выше остаётся отменяемой — там отмена уместна. + recordCtx, cancel := context.WithTimeout(context.WithoutCancel(ctx), recordTimeout) + defer cancel() + + err = s.store.CreateDelivery(recordCtx, store.Delivery{ ID: res.DeliveryID, ReceivedAt: receivedAt, Headers: encodeHeaders(meta.Headers), @@ -121,8 +156,8 @@ func (s *Service) Accept(ctx context.Context, body []byte, meta Meta) (Result, e ParseStatus: store.ParsePending, }) if err != nil { - // Тело уже на диске — данные не потеряны, но учёта нет. Разбор архива - // на следующем шаге проекта такую доставку подберёт. + // Тело уже на диске — данные не потеряны, но учёта нет. Такое тело + // подберёт пересборка (`healthlog reindex`), заведя запись заново. s.log.ErrorContext(ctx, "delivery failed", "error", err, "delivery_id", res.DeliveryID, "raw_path", rawPath) return Result{}, fmt.Errorf("record delivery: %w", err) } @@ -131,24 +166,37 @@ func (s *Service) Accept(ctx context.Context, body []byte, meta Meta) (Result, e "delivery_id", res.DeliveryID, "bytes", res.Bytes, "raw_path", rawPath, - "automation_name", meta.AutomationName, - "aggregation", meta.Aggregation, - "period", meta.Period) + "automation_name", clip(meta.AutomationName), + "aggregation", clip(meta.Aggregation), + "period", clip(meta.Period)) - // Свёртка идёт после того, как доставка учтена, и на контексте, ОТВЯЗАННОМ - // от запроса: обрыв соединения клиентом или прокси на середине оставил бы - // часть объектов записанной, а доставку — со статусом, по которому её - // никто не подберёт. Исход свёртки на код ответа не влияет — сохранили - // значит приняли. - foldCtx, cancel := context.WithTimeout(context.WithoutCancel(ctx), foldTimeout) - defer cancel() - // Ошибку не возвращаем: она уже записана в лог и в parse_status свёрткой, - // а доставка принята. - _, _ = s.fold.Fold(foldCtx, res.DeliveryID) + // Сигнал идёт последним — после того, как строка учёта закоммичена: иначе + // воркер мог бы проснуться раньше, чем увидит доставку, и потратить проход + // впустую. Потеря сигнала отказом не является: доставка числится `pending`, + // и её подберёт следующий сигнал, тик воркера или старт сервиса. + s.notify() return res, nil } +// maxAttrLen — сколько байт значения заголовка попадает в лог. +// +// Заголовки контролирует отправитель целиком, а `MaxHeaderBytes` у Go — мегабайт +// на запрос: без границы одна доставка выдавливает из ротации логов всю недавнюю +// историю, включая записи, по которым эту же доставку потом разыскивают. Та же +// граница по той же причине стоит на именах метрик и секций. +const maxAttrLen = 128 + +// clip обрезает значение, пришедшее от отправителя, до пригодного для лога. +func clip(s string) string { + if len(s) <= maxAttrLen { + return s + } + // Обрезка названа в самом значении: молча укороченное имя автоматизации + // выглядит как другое имя. + return s[:maxAttrLen] + "…(обрезано)" +} + // encodeHeaders сериализует заголовки для хранения. Ключи json.Marshal // сортирует сам, поэтому запись стабильна и её удобно сравнивать между // доставками. Сбой сериализации не должен ронять приём: заголовки — diff --git a/internal/ingest/ingest_test.go b/internal/ingest/ingest_test.go index 9a3d7d4..c078efe 100644 --- a/internal/ingest/ingest_test.go +++ b/internal/ingest/ingest_test.go @@ -12,7 +12,6 @@ import ( "testing" "git.vakhrushev.me/av/healthlog/internal/archive" - "git.vakhrushev.me/av/healthlog/internal/fold" "git.vakhrushev.me/av/healthlog/internal/ingest" "git.vakhrushev.me/av/healthlog/internal/store" ) @@ -123,32 +122,9 @@ func TestAcceptRejectsMalformed(t *testing.T) { } } -// Разбор не влияет на исход приёма: сохранили — значит приняли. Непонятое -// содержимое даёт принятую доставку с parse_status=failed, а не отказ. -func TestAcceptНепонятоеСодержимоеПринимается(t *testing.T) { - svc, _, st := newService(t) - ctx := context.Background() - - // Метрика есть, но слой определить нечем: плотных метрик нет, заголовок - // ничего не означает, наследовать не от чего. - body := []byte(`{"data":{"metrics":[{"name":"m","units":"u","data":[` + - `{"date":"2026-07-31 12:00:00 +0300","qty":1}]}]}}`) - - if _, err := svc.Accept(ctx, body, ingest.Meta{Aggregation: "Default"}); err != nil { - t.Fatalf("Accept отверг доставку из-за разбора: %v", err) - } - - d, err := st.LastDelivery(ctx) - if err != nil { - t.Fatalf("LastDelivery: %v", err) - } - if d.ParseStatus != store.ParseFailed { - t.Errorf("parse_status = %q, ожидался %q", d.ParseStatus, store.ParseFailed) - } -} - -// Разобранная доставка отмечается разобранной, и точки доезжают до объектов. -func TestAcceptРазобраннаяДоставкаОтмечена(t *testing.T) { +// Ответ отдаётся ДО свёртки: принятая доставка ждёт разбора в очереди, а не +// приезжает разобранной. Это смена контракта, и она проверяется явно. +func TestAcceptОставляетДоставкуВОчереди(t *testing.T) { svc, _, st := newService(t) ctx := context.Background() @@ -165,32 +141,106 @@ func TestAcceptРазобраннаяДоставкаОтмечена(t *testing if err != nil { t.Fatalf("LastDelivery: %v", err) } - if d.ParseStatus != store.ParseDone { - t.Fatalf("parse_status = %q, ожидался %q", d.ParseStatus, store.ParseDone) - } - if d.Points == 0 { - t.Error("точек 0: разбор не дошёл до учёта") + if d.ParseStatus != store.ParsePending { + t.Errorf("parse_status = %q, ожидался %q", d.ParseStatus, store.ParsePending) } n, err := st.CountBuckets(ctx) if err != nil { t.Fatalf("CountBuckets: %v", err) } - if n == 0 { - t.Error("объектов 0: точки не доехали до хранилища") + if n != 0 { + t.Errorf("объектов %d: свёртка произошла внутри приёма", n) } } -// Свёртка идёт на контексте, отвязанном от запроса (context.WithoutCancel в -// Accept), чтобы обрыв соединения не оставил часть объектов записанной. -// Автотестом это не покрыто: отмену надо подать РОВНО между учётом доставки и -// свёрткой, а такого шва снаружи нет, и заводить его ради теста дороже, чем -// проверять глазами. Атомарность самой записи проверена в store -// (TestMergePointsОтменаНеОставляетПоловины). - -func newService(t *testing.T) (*ingest.Service, *archive.Archive, *store.Store) { - t.Helper() +// Сигнал уходит после того, как доставка учтена: воркер, разбуженный раньше, +// потратил бы проход впустую. +func TestAcceptБудитСвёрткуПослеУчёта(t *testing.T) { dir := t.TempDir() + st, arch := newDeps(t, dir) + + var seen int64 + notify := func() { + n, err := st.CountDeliveries(context.Background()) + if err != nil { + t.Errorf("CountDeliveries: %v", err) + } + seen = n + } + svc := ingest.New(arch, st, notify, slog.New(slog.DiscardHandler)) + + if _, err := svc.Accept(context.Background(), []byte(`{"data":{"metrics":[]}}`), ingest.Meta{}); err != nil { + t.Fatalf("Accept: %v", err) + } + if seen != 1 { + t.Errorf("на момент сигнала доставок в учёте %d, ожидалась 1", seen) + } +} + +// Нулевой сигнал — законный вход (свёрткой заведует вызывающий), и приём от +// него не падает. Паника здесь наступила бы ПОСЛЕ записи тела и учёта, то есть +// отправитель получил бы отказ по сохранённой доставке. +func TestAcceptБезСигналаНеПадает(t *testing.T) { + dir := t.TempDir() + st, arch := newDeps(t, dir) + svc := ingest.New(arch, st, nil, slog.New(slog.DiscardHandler)) + + if _, err := svc.Accept(context.Background(), []byte(`{"data":{"metrics":[]}}`), ingest.Meta{}); err != nil { + t.Fatalf("Accept: %v", err) + } +} + +// Обрыв соединения после записи тела не должен оставлять тело без учёта: +// доставка, не попавшая в журнал, восстанавливается только пересборкой с +// ручной подменой базы. +func TestAcceptУчитываетДоставкуПослеОбрываСоединения(t *testing.T) { + svc, _, st := newService(t) + + ctx, cancel := context.WithCancel(context.Background()) + cancel() + + res, err := svc.Accept(ctx, []byte(`{"data":{"metrics":[]}}`), ingest.Meta{}) + if err != nil { + t.Fatalf("Accept на отменённом контексте: %v", err) + } + + status, err := st.DeliveryStatus(context.Background(), res.DeliveryID) + if err != nil { + t.Fatalf("DeliveryStatus: %v", err) + } + if status != store.ParsePending { + t.Errorf("parse_status = %q, ожидался %q", status, store.ParsePending) + } +} + +// Учёта нет, а тело есть: приём кладёт тело на диск раньше строки в базе, и +// отказ на вставке оставляет тело в архиве. Такое тело подберёт пересборка. +func TestAcceptПриОтказеУчётаОставляетТелоВАрхиве(t *testing.T) { + dir := t.TempDir() + st, arch := newDeps(t, dir) + svc := ingest.New(arch, st, nil, slog.New(slog.DiscardHandler)) + + // База закрыта — учесть доставку нечем. + if err := st.Close(); err != nil { + t.Fatalf("закрытие базы: %v", err) + } + + if _, err := svc.Accept(context.Background(), []byte(`{"data":{"metrics":[]}}`), ingest.Meta{}); err == nil { + t.Fatal("приём не заметил, что доставка не учтена") + } + + entries, err := filepath.Glob(filepath.Join(arch.Root(), "*", "*", "*", "*.json.gz")) + if err != nil { + t.Fatalf("обход архива: %v", err) + } + if len(entries) != 1 { + t.Errorf("тел в архиве %d, ожидалось 1: тело потеряно вместе с учётом", len(entries)) + } +} + +func newDeps(t *testing.T, dir string) (*store.Store, *archive.Archive) { + t.Helper() st, err := store.Open(filepath.Join(dir, "healthlog.db")) if err != nil { @@ -202,7 +252,12 @@ func newService(t *testing.T) (*ingest.Service, *archive.Archive, *store.Store) if err != nil { t.Fatalf("archive.New: %v", err) } + return st, arch +} - log := slog.New(slog.DiscardHandler) - return ingest.New(arch, st, fold.New(arch, st, 0, log), log), arch, st +func newService(t *testing.T) (*ingest.Service, *archive.Archive, *store.Store) { + t.Helper() + + st, arch := newDeps(t, t.TempDir()) + return ingest.New(arch, st, nil, slog.New(slog.DiscardHandler)), arch, st } diff --git a/internal/replay/classify_test.go b/internal/replay/classify_test.go new file mode 100644 index 0000000..1753847 --- /dev/null +++ b/internal/replay/classify_test.go @@ -0,0 +1,67 @@ +package replay + +import ( + "context" + "errors" + "fmt" + "testing" + + "git.vakhrushev.me/av/healthlog/internal/fold" + "git.vakhrushev.me/av/healthlog/internal/hae" + "git.vakhrushev.me/av/healthlog/internal/store" +) + +// Классификация исхода — та половина, которую пересборка и фоновый воркер +// обязаны делить. Проверяется перебором классов, без базы и без архива: второй +// классификатор разошёлся бы с первым молча, а по счётчику `partial` +// принимается решение о судьбе тела в архиве. +func TestClassifyРазводитИсходыПоКлассам(t *testing.T) { + t.Parallel() + + cases := []struct { + name string + err error + want Outcome + }{ + {"успех", nil, Outcome{Folded: 1}}, + {"слой не выведен", hae.ErrLayerUnknown, Outcome{FailedLayer: 1}}, + {"слой не выведен, обёрнут", fmt.Errorf("свёртка: %w", hae.ErrLayerUnknown), Outcome{FailedLayer: 1}}, + {"содержимое не разбирается", hae.ErrMalformed, Outcome{FailedMalformed: 1}}, + {"база занята", store.ErrBusy, Outcome{Deferred: 1}}, + {"база занята, обёрнута", fmt.Errorf("слияние: %w", store.ErrBusy), Outcome{Deferred: 1}}, + {"работу прекратили снаружи", context.Canceled, Outcome{Deferred: 1}}, + // Дедлайн — свойство доставки, а не обстоятельств: она не уложится в + // бюджет и в следующий раз, а повтор безнадёжного останавливает очередь. + {"свёртка не уложилась в бюджет", context.DeadlineExceeded, Outcome{FailedOther: 1}}, + {"прочее", errors.New("диск отвалился"), Outcome{FailedOther: 1}}, + // Паника — дефект нашего кода, а не обстоятельство: доставка выводится + // из очереди, тело ждёт пересборки. + {"свёртка паниковала", fold.ErrPanicked, Outcome{FailedOther: 1}}, + } + + for _, c := range cases { + t.Run(c.name, func(t *testing.T) { + t.Parallel() + + if got := classify(c.err); got != c.want { + t.Errorf("Classify(%v) = %+v, ожидалось %+v", c.err, got, c.want) + } + }) + } +} + +// Накопление — сложение по классам: у пересборки и у воркера один набор имён +// для одних исходов. +func TestOutcomeAddСкладываетПоКлассам(t *testing.T) { + t.Parallel() + + var total Outcome + total.Add(Outcome{Folded: 1, Partial: 1}) + total.Add(Outcome{Folded: 1, Incomparable: 2}) + total.Add(Outcome{Deferred: 1}) + + want := Outcome{Folded: 2, Deferred: 1, Partial: 1, Incomparable: 2} + if total != want { + t.Errorf("сумма %+v, ожидалась %+v", total, want) + } +} diff --git a/internal/replay/player.go b/internal/replay/player.go new file mode 100644 index 0000000..9c51315 --- /dev/null +++ b/internal/replay/player.go @@ -0,0 +1,110 @@ +package replay + +import ( + "context" + "errors" + + "git.vakhrushev.me/av/healthlog/internal/fold" + "git.vakhrushev.me/av/healthlog/internal/hae" + "git.vakhrushev.me/av/healthlog/internal/store" +) + +// Outcome — исход свёртки: одной доставки или их последовательности. +// +// Классы разведены потому, что читаются по-разному. FailedLayer — штатный исход +// (слой не выводится, таких тел в журнале заведомо есть), FailedMalformed — +// содержимое не разбирается, Deferred — работа не сделана по обстоятельствам, +// и доставка осталась в очереди. Только FailedOther означает, что что-то не так +// с самой свёрткой. Один общий счётчик отправлял бы человека искать дефект там, +// где его нет. +type Outcome struct { + Folded int + FailedLayer int + FailedMalformed int + // Deferred — доставка осталась `pending`: отмена или занятость базы. Не + // отказ доставки, а несделанная работа; её подберёт следующий проход. + Deferred int + FailedOther int + // Partial — доставок, в теле которых остались непокрытые разбором секции. + // Не отклонение, а половина потока; названо потому, что именно эти тела + // ретеншену трогать нельзя. + Partial int + // Incomparable — столкновений с несравнимыми наборами полей. На живом потоке + // их не было ни разу, и на этом стоит отказ от объединения полей. + Incomparable int +} + +// Add накапливает исход одной доставки в общий. +func (o *Outcome) Add(other Outcome) { + o.Folded += other.Folded + o.FailedLayer += other.FailedLayer + o.FailedMalformed += other.FailedMalformed + o.Deferred += other.Deferred + o.FailedOther += other.FailedOther + o.Partial += other.Partial + o.Incomparable += other.Incomparable +} + +// classify раскладывает ошибку свёртки по классам исхода. +// +// Чистая функция, и это не украшение: она и есть та половина, которую задача +// требовала не дублировать между пересборкой и фоновым воркером, — а +// проверяется она перебором классов, без базы и без архива. +// +// Неэкспортируемая намеренно: её результат содержит поля `Partial` и +// `Incomparable`, которые дописывает только Play, — вторая публичная дверь +// молча занижала бы именно тот счётчик, по которому принимается решение о +// судьбе тела в архиве. +func classify(err error) Outcome { + var out Outcome + switch { + case err == nil: + out.Folded++ + case store.Transient(err): + // Статус доставки свёртка в этих случаях не трогает: она осталась + // `pending` и будет свёрнута снова. Правило одно на обоих — то, по + // которому свёртка решает не писать исход. + out.Deferred++ + case errors.Is(err, hae.ErrLayerUnknown): + out.FailedLayer++ + case errors.Is(err, hae.ErrMalformed): + out.FailedMalformed++ + default: + out.FailedOther++ + } + return out +} + +// Player сворачивает доставку по идентификатору и классифицирует исход. +// +// Общий и для пересборки журнала, и для фонового воркера приёма — второй +// классификатор разошёлся бы с первым молча, а по одному из его счётчиков +// (`Partial`) принимается решение о судьбе тела в архиве. +type Player struct { + Fold *fold.Service +} + +// Play сворачивает одну доставку и возвращает её исход. +// +// Классифицируется ТОЛЬКО ошибка свёртки: на контекст Play не смотрит, и это +// существенно. У двух вызывающих отменённый контекст означает противоположное — +// у пересборки в свёртку уходит тот же отменяемый контекст («нас остановили»), +// у воркера отвязанный от остановки, с собственным дедлайном («доставка не +// уложилась в бюджет»). Решение «работу прекратили снаружи» принимает цикл, +// каждый по своему контексту. +func (p Player) Play(ctx context.Context, deliveryID string) (Outcome, error) { + st, err := p.Fold.Fold(ctx, deliveryID) + out := classify(err) + + if err == nil { + // Счётчики читаются только у успешной свёртки: при ошибке поля Stats + // заполнены частично (Uncovered у отказавшего разбора всегда пуст, хотя + // в базу список записан) — и Partial молча занижался бы. А по нему + // принимается решение о ретеншене тел. + if len(st.Uncovered) > 0 { + out.Partial++ + } + out.Incomparable += st.Incomparable + } + return out, err +} diff --git a/internal/replay/replay.go b/internal/replay/replay.go index 0b4ba3a..dc0d28a 100644 --- a/internal/replay/replay.go +++ b/internal/replay/replay.go @@ -24,7 +24,6 @@ import ( "git.vakhrushev.me/av/healthlog/internal/archive" "git.vakhrushev.me/av/healthlog/internal/fold" - "git.vakhrushev.me/av/healthlog/internal/hae" "git.vakhrushev.me/av/healthlog/internal/ident" "git.vakhrushev.me/av/healthlog/internal/store" ) @@ -70,24 +69,11 @@ type Report struct { // Orphans — строк учёта, у которых тела в архиве нет. Станет штатным, когда // появится ретеншен архива. Orphans int - // Folded — сколько доставок свернулось. - Folded int - // Отказы разведены по классам, потому что читаются они по-разному. - // FailedLayer — слой не выводится: штатный исход, таких доставок в журнале - // заведомо есть. FailedMalformed — содержимое не разбирается. FailedOther — - // всё прочее (тело не читается, отказ базы); только оно означает, что с - // пересборкой что-то не так. Один общий счётчик отправлял бы человека - // искать дефект там, где его нет. - FailedLayer int - FailedMalformed int - FailedOther int - // Partial — доставок, в теле которых остались непокрытые разбором секции. - // Не отклонение, а половина потока; названо потому, что именно эти тела - // ретеншену трогать нельзя. - Partial int - // Incomparable — столкновений с несравнимыми наборами полей. На живом потоке - // их не было ни разу, и на этом стоит отказ от объединения полей. - Incomparable int + + // Outcome — счётчики свёртки, те же самые, что считает фоновый воркер + // приёма. Встроены, а не продублированы именами: два набора имён для одних + // исходов разошлись бы при первой же правке классификации. + Outcome Buckets int64 Fingerprint string @@ -148,6 +134,7 @@ func Run(ctx context.Context, o Options) (Report, error) { } } + player := Player{Fold: o.Fold} for i, d := range journal { if ctx.Err() != nil { rep.Canceled = true @@ -156,36 +143,17 @@ func Run(ctx context.Context, o Options) (Report, error) { if err := o.Target.CreateDelivery(ctx, d); err != nil { return stopOr(rep, err) } - st, err := o.Fold.Fold(ctx, d.ID) - switch { - case err == nil: - rep.Folded++ - case ctx.Err() != nil: - // Отмена, застигшая свёртку, — не отказ доставки: считать её отказом - // значило бы обвинить разбор в том, чего он не делал, и отправить - // человека искать дефект по логу. + out, _ := player.Play(ctx, d.ID) + // Отмена, застигшая свёртку, — не отказ доставки: считать её отказом + // значило бы обвинить разбор в том, чего он не делал, и отправить + // человека искать дефект по логу. Решение принимает цикл по СВОЕМУ + // контексту — тому же, на котором шла свёртка; классификатор о нём не + // знает намеренно, у воркера тот же признак означает другое. + if ctx.Err() != nil { rep.Canceled = true return rep, nil - case errors.Is(err, hae.ErrLayerUnknown): - // Штатный исход, уже записанный свёрткой в лог и в parse_status: - // журнал заведомо содержит тела без плотных метрик. Останов на - // первом лишил бы пересборки все остальные. - rep.FailedLayer++ - case errors.Is(err, hae.ErrMalformed): - rep.FailedMalformed++ - default: - rep.FailedOther++ - } - if err == nil { - // Счётчики читаются только у успешной свёртки: при ошибке поля Stats - // заполнены частично (Uncovered у отказавшего разбора всегда пуст, - // хотя в базу список записан) — и Partial молча занижался бы. А по - // нему принимается решение о ретеншене тел. - if len(st.Uncovered) > 0 { - rep.Partial++ - } - rep.Incomparable += st.Incomparable } + rep.Add(out) if o.Progress != nil { o.Progress(i+1, len(journal)) } @@ -218,6 +186,7 @@ func Run(ctx context.Context, o Options) (Report, error) { "folded", rep.Folded, "failed_layer", rep.FailedLayer, "failed_malformed", rep.FailedMalformed, + "deferred", rep.Deferred, "failed_other", rep.FailedOther, "partial", rep.Partial, "incomparable", rep.Incomparable, diff --git a/internal/replay/worker.go b/internal/replay/worker.go new file mode 100644 index 0000000..5c4c751 --- /dev/null +++ b/internal/replay/worker.go @@ -0,0 +1,232 @@ +package replay + +import ( + "context" + "log/slog" + "time" + + "git.vakhrushev.me/av/healthlog/internal/fold" + "git.vakhrushev.me/av/healthlog/internal/store" +) + +// batchSize — сколько неразобранных доставок берётся одним запросом. +// +// Не ради страниц, а ради памяти: задолженность после миграции, переводящей +// строки в `pending`, равна всему архиву, и материализовать её целиком незачем — +// проход всё равно идёт по одной. +const batchSize = 256 + +// foldTimeout — сколько отводится свёртке одной доставки. +// +// Свёртка идёт на контексте, отвязанном от остановки, поэтому собственный +// дедлайн обязателен: без него зависшая запись держала бы единственного воркера +// до конца жизни процесса, и очередь перестала бы двигаться вовсе. +const foldTimeout = 2 * time.Minute + +// tickInterval — как часто воркер просыпается сам, без сигнала. +// +// Сигнал приносит приём, и для свежей доставки его достаточно. Тик закрывает +// два случая, которых сигнал не закрывает: доставка, оставшаяся в очереди из-за +// занятости базы, иначе ждала бы СЛЕДУЮЩЕЙ доставки (а ночью телефон молчит +// часами), и метка отставания иначе не вычислялась бы вовсе — «работа есть, +// прогресса нет» было бы неотличимо от здорового пустого потока. +const tickInterval = time.Minute + +// lagThreshold — с какого ожидания доставка считается задержанной. +// +// Период быстрого прохода синхронизации: если доставка ждала дольше, чем +// интервал между доставками, очередь растёт, а не рассасывается. +const lagThreshold = 5 * time.Minute + +// Worker — фоновая свёртка принятых доставок. +// +// Очередь — сама таблица: доставка ждёт свёртки в статусе `pending`, а канал +// несёт только бит «есть работа». Отсюда три свойства, ради которых так и +// сделано: переполнять нечего, падение процесса очереди не теряет, а подбор +// неразобранного при старте не является отдельным кодом — это обычный проход. +type Worker struct { + store *store.Store + player Player + log *slog.Logger + + // wake — сигнал «есть работа», ёмкость 1 и неблокирующая отправка. Та же + // форма, что у os/signal.Notify: сигнал ничего не несёт, и потерять лишний + // не только можно, но и нужно. + wake chan struct{} + + // startupDone — первый проход завершён. + // + // До него метка отставания молчит: задолженность, накопленная ДО старта, + // ждала не воркера, а его появления, и сотня одинаковых WARN при первом же + // запуске обесценила бы уровень. + startupDone bool +} + +// NewWorker собирает воркер над рабочей базой. +func NewWorker(st *store.Store, f *fold.Service, log *slog.Logger) *Worker { + return &Worker{ + store: st, + player: Player{Fold: f}, + log: log.With("capability", "fold-worker"), + wake: make(chan struct{}, 1), + } +} + +// Notify будит воркер. Вызывается приёмом после того, как доставка учтена. +// +// Потеря сигнала отказом не является: доставка от этого не перестаёт числиться +// `pending`, и её подберёт следующий сигнал, тик или старт. +func (w *Worker) Notify() { + select { + case w.wake <- struct{}{}: + default: + } +} + +// Run ведёт воркер до отмены контекста. +// +// Отмена проверяется МЕЖДУ доставками: свёртка идёт на отвязанном контексте и +// рваться не должна. Обещания «текущая доставка непременно досворачивается» тут +// нет — бюджет остановки меньше бюджета свёртки; гарантируется другое: после +// выхода не существует доставки, которая числится разобранной, а записана +// наполовину. +// +// Первый проход делается сразу, без ожидания сигнала: он и есть подбор +// неразобранного при старте. +func (w *Worker) Run(ctx context.Context) { + if n, err := w.store.CountPendingDeliveries(ctx); err != nil { + if ctx.Err() == nil { + w.log.ErrorContext(ctx, "pending backlog not counted", "error", err) + } + } else if n > 0 { + // Размер задолженности — ответ на вопрос «что сервис будет делать + // первые минуты после рестарта». Одной строкой и один раз. + w.log.InfoContext(ctx, "pending backlog at start", "deliveries", n) + } + + ticker := time.NewTicker(tickInterval) + defer ticker.Stop() + + for { + if _, err := w.Pass(ctx); err != nil && ctx.Err() == nil { + // Отказ прохода не убивает цикл: воркер, умерший от временного + // отказа базы, остановил бы свёртку до конца жизни процесса, пока + // приём продолжал бы отвечать 200. + // + // Отмена сюда не попадает: штатная остановка не отказ, а ERROR о + // ней обесценил бы уровень, по которому вмешиваются. + w.log.ErrorContext(ctx, "fold pass failed", "error", err) + } + + select { + case <-ctx.Done(): + return + case <-w.wake: + case <-ticker.C: + } + } +} + +// Pass делает один проход по очереди и возвращает его исход. +// +// Синхронный шов: тесты зовут его напрямую и не ждут по часам. Без него +// проверки «все свёрнуты», «проход конечен», «метка не сработала на первом +// проходе» писались бы опросом базы с таймаутом. +// +// Курсор строго возрастает, и это нужно не ради страниц, а ради завершимости: +// доставка, у которой не удалось записать даже исход разбора, остаётся +// `pending`, и проход без курсора выбирал бы её бесконечно. +func (w *Worker) Pass(ctx context.Context) (Outcome, error) { + var total Outcome + var cursor store.PendingDelivery + var lag lagged + + for { + if ctx.Err() != nil { + return total, nil + } + + batch, err := w.store.PendingDeliveries(ctx, cursor, batchSize) + if err != nil { + return total, err + } + if len(batch) == 0 { + // Флаг снимается ТОЛЬКО здесь — у прохода, дошедшего до пустой + // выборки. Взведённый на любом выходе (отказ базы, отмена), он + // включал бы метку задержки после прохода, который ничего не + // свернул, и следующий проход выдал бы WARN на всю задолженность — + // ровно тот шквал, против которого метка и подавляется при старте. + // + // Порядок двух строк существен: на задолженности ПЕРВОГО прохода + // метка молчит — та ждала не воркера, а его появления. + w.warnLag(ctx, lag) + w.startupDone = true + return total, nil + } + + for _, d := range batch { + if ctx.Err() != nil { + return total, nil + } + lag.add(d) + total.Add(w.foldOne(ctx, d.ID)) + cursor = d + } + } +} + +// lagged копит отставание прохода: сколько доставок ждали свёртки и дольше всех +// ждала какая. +// +// Считается на ВЫБОРКЕ, а не по факту успешной свёртки: иначе застрявшая +// доставка молчала бы ровно в том состоянии, ради которого метка и заведена. +type lagged struct { + count int + worst time.Duration + worstID string +} + +func (l *lagged) add(d store.PendingDelivery) { + waited := store.Now().Sub(d.ReceivedAt) + if waited < lagThreshold { + return + } + l.count++ + if waited > l.worst { + l.worst = waited + l.worstID = d.ID + } +} + +// foldOne сворачивает доставку на контексте, ОТВЯЗАННОМ от остановки. +// +// Отмена снаружи не должна превращаться в свойство доставки: свёртка пишет +// исход на переживающем отмену контексте, и оборванная на середине пометила бы +// доставку так, что воркер её больше не подберёт. Собственный дедлайн при этом +// остаётся и означает именно отказ доставки. +func (w *Worker) foldOne(ctx context.Context, deliveryID string) Outcome { + foldCtx, cancel := context.WithTimeout(context.WithoutCancel(ctx), foldTimeout) + defer cancel() + + // Ошибку не возвращаем: она уже записана свёрткой в лог и в parse_status, + // а отказ одной доставки прохода не прекращает. Паника тоже: её + // перехватывает сама свёртка — там же, где живёт единственный писатель + // исхода разбора. + out, _ := w.player.Play(foldCtx, deliveryID) + return out +} + +// warnLag называет отставание одной строкой на проход. +// +// Одной, а не по строке на доставку: задолженность в сотню тел давала бы сотню +// одинаковых WARN каждую минуту, и уровень, по которому вмешиваются, перестал +// бы что-либо значить. +func (w *Worker) warnLag(ctx context.Context, l lagged) { + if !w.startupDone || l.count == 0 { + return + } + w.log.WarnContext(ctx, "deliveries waited for fold", + "deliveries", l.count, + "worst_delivery_id", l.worstID, + "worst_waited_sec", int64(l.worst.Seconds())) +} diff --git a/internal/replay/worker_test.go b/internal/replay/worker_test.go new file mode 100644 index 0000000..3c13489 --- /dev/null +++ b/internal/replay/worker_test.go @@ -0,0 +1,373 @@ +package replay_test + +import ( + "context" + "encoding/json" + "log/slog" + "os" + "path/filepath" + "strings" + "sync" + "testing" + "time" + + "git.vakhrushev.me/av/healthlog/internal/archive" + "git.vakhrushev.me/av/healthlog/internal/fold" + "git.vakhrushev.me/av/healthlog/internal/ident" + "git.vakhrushev.me/av/healthlog/internal/replay" + "git.vakhrushev.me/av/healthlog/internal/store" +) + +// newWorker собирает воркер над свежей базой и архивом, отдавая заодно то, чем +// проверяют его следы в логе. +func newWorker(t *testing.T, dir string) (*replay.Worker, *store.Store, *archive.Archive, *logSink) { + t.Helper() + + arch := openArchive(t, filepath.Join(dir, "raw")) + st := openStore(t, filepath.Join(dir, "live.db")) + sink := newLogSink() + log := slog.New(slog.NewJSONHandler(sink, &slog.HandlerOptions{Level: slog.LevelDebug})) + w := replay.NewWorker(st, fold.New(arch, st, 0, log), log) + return w, st, arch, sink +} + +// logSink собирает записи лога, чтобы проверять их без гонок и без ожиданий по +// часам: тест синхронизируется появлением строки, а не сном. +type logSink struct { + mu sync.Mutex + lines []string + watch map[string]*watcher +} + +// watcher ждёт n-го появления строки. +type watcher struct { + left int + ch chan struct{} +} + +func newLogSink() *logSink { return &logSink{watch: map[string]*watcher{}} } + +func (s *logSink) Write(p []byte) (int, error) { + s.mu.Lock() + defer s.mu.Unlock() + + line := string(p) + s.lines = append(s.lines, line) + if w, ok := s.watch[msgOf(line)]; ok { + w.left-- + if w.left == 0 { + close(w.ch) + delete(s.watch, msgOf(line)) + } + } + return len(p), nil +} + +// expect регистрирует ожидание n-го появления строки до того, как она может +// появиться: синхронизация идёт событием, а не сном. +func (s *logSink) expect(msg string, n int) <-chan struct{} { + s.mu.Lock() + defer s.mu.Unlock() + + w := &watcher{left: n, ch: make(chan struct{})} + s.watch[msg] = w + return w.ch +} + +func msgOf(line string) string { + var rec struct { + Msg string `json:"msg"` + } + if err := json.Unmarshal([]byte(line), &rec); err != nil { + return "" + } + return rec.Msg +} + +// count считает записи с данным msg. +func (s *logSink) count(msg string) int { + s.mu.Lock() + defer s.mu.Unlock() + + n := 0 + for _, line := range s.lines { + if msgOf(line) == msg { + n++ + } + } + return n +} + +func (s *logSink) dump() string { + s.mu.Lock() + defer s.mu.Unlock() + return strings.Join(s.lines, "") +} + +// Подбор неразобранного — обычный проход воркера, а не отдельный режим: после +// миграции 00005 неразобранными числятся все доставки архива, и подобрать их +// сегодня может только пересборка с ручной подменой базы. +func TestПроходПодбираетЗадолженность(t *testing.T) { + t.Parallel() + + dir := t.TempDir() + w, st, arch, _ := newWorker(t, dir) + ctx := context.Background() + + items := journal(t, "minute.json", "hour.json", "raw.json") + for _, it := range items { + writeBody(t, arch, st, it, fixture(t, it.fixture)) + } + + out, err := w.Pass(ctx) + if err != nil { + t.Fatalf("проход: %v", err) + } + if out.Folded != len(items) { + t.Fatalf("свёрнуто %d из %d: %+v", out.Folded, len(items), out) + } + + n, err := st.CountPendingDeliveries(ctx) + if err != nil { + t.Fatalf("CountPendingDeliveries: %v", err) + } + if n != 0 { + t.Errorf("неразобранными остались %d доставок", n) + } + + buckets, err := st.CountBuckets(ctx) + if err != nil { + t.Fatalf("CountBuckets: %v", err) + } + if buckets == 0 { + t.Error("объектов 0: точки не доехали до хранилища") + } +} + +// Порядок задаётся ЖУРНАЛОМ, а не порядком, в котором доставки попали в учёт. +// Проверяется наблюдаемым следствием: доставка без плотных метрик наследует +// слой предшествующей ей по `(received_at, id)`. +// +// Учёт заполняется в обратном хронологии порядке — так выглядит гонка двух +// конкурентных приёмов, где поздняя доставка закоммитила строку первой. +func TestПроходИдётВПорядкеЖурналаАНеВставки(t *testing.T) { + t.Parallel() + + dir := t.TempDir() + w, st, arch, _ := newWorker(t, dir) + ctx := context.Background() + + base := time.Date(2026, 8, 1, 12, 0, 0, 0, time.UTC) + minute := item{id: ident.NewID(), at: base.Add(1 * time.Second), automationID: "a", aggregation: "Default", fixture: "minute.json"} + sleep := item{id: ident.NewID(), at: base.Add(2 * time.Second), automationID: "a", aggregation: "Default", fixture: "sparse_sleep.json"} + + // Сначала учитывается ПОЗДНЯЯ доставка. + writeBody(t, arch, st, sleep, fixture(t, sleep.fixture)) + writeBody(t, arch, st, minute, fixture(t, minute.fixture)) + + out, err := w.Pass(ctx) + if err != nil { + t.Fatalf("проход: %v", err) + } + if out.FailedLayer != 0 { + t.Fatalf("слой не вывелся у %d доставок: проход пошёл в порядке вставки", out.FailedLayer) + } + + // Предшественник — минутная доставка, значит эпизоды сна легли в minute. + hours, err := st.BucketHours(ctx, "sleep_analysis", "minute") + if err != nil { + t.Fatalf("часы объектов: %v", err) + } + if len(hours) == 0 { + t.Error("эпизоды сна не унаследовали слой предшествующей доставки") + } +} + +// Проход конечен и продвигается мимо доставки, которую свернуть не удалось: +// курсор двигается вперёд независимо от исхода свёртки. Без этого доставка, у +// которой не удалось записать даже исход разбора, выбиралась бы бесконечно. +func TestПроходПродвигаетсяМимоНесворачиваемойДоставки(t *testing.T) { + t.Parallel() + + dir := t.TempDir() + w, st, arch, _ := newWorker(t, dir) + ctx := context.Background() + + items := journal(t, "minute.json", "hour.json") + for _, it := range items { + writeBody(t, arch, st, it, fixture(t, it.fixture)) + } + // У первой доставки тела больше нет — свернуть её нечем. + if err := os.Remove(filepath.Join(arch.Root(), "2026", "08", "01", items[0].id+".json.gz")); err != nil { + t.Fatalf("удаление тела: %v", err) + } + + done := make(chan replay.Outcome, 1) + go func() { + out, err := w.Pass(ctx) + if err != nil { + t.Errorf("проход: %v", err) + } + done <- out + }() + + var out replay.Outcome + select { + case out = <-done: + case <-time.After(30 * time.Second): + t.Fatal("проход не завершился: курсор не двигается") + } + if out.Folded != 1 || out.FailedOther != 1 { + t.Fatalf("исход прохода %+v: ожидались одна свёрнутая и одна отказавшая", out) + } + + // Отказавшая доставка выбыла из очереди — иначе следующий проход брал бы её + // снова и снова. + n, err := st.CountPendingDeliveries(ctx) + if err != nil { + t.Fatalf("CountPendingDeliveries: %v", err) + } + if n != 0 { + t.Errorf("неразобранными числятся %d доставок, ожидалось 0", n) + } +} + +// Метка задержки молчит на задолженности первого прохода и говорит после него: +// доставки, накопленные до старта, ждали не воркера, а его появления. +func TestМеткаЗадержкиВключаетсяПослеПервогоПрохода(t *testing.T) { + t.Parallel() + + dir := t.TempDir() + w, st, arch, sink := newWorker(t, dir) + ctx := context.Background() + + old := item{ + id: ident.NewID(), at: store.Now().Add(-time.Hour), + automationID: "a", aggregation: "Minutes", fixture: "minute.json", + } + writeBody(t, arch, st, old, fixture(t, old.fixture)) + + if _, err := w.Pass(ctx); err != nil { + t.Fatalf("первый проход: %v", err) + } + if n := sink.count("deliveries waited for fold"); n != 0 { + t.Errorf("на задолженности первого прохода %d предупреждений о задержке:\n%s", n, sink.dump()) + } + + late := item{ + id: ident.NewID(), at: store.Now().Add(-time.Hour), + automationID: "a", aggregation: "Minutes", fixture: "hour.json", + } + writeBody(t, arch, st, late, fixture(t, late.fixture)) + + if _, err := w.Pass(ctx); err != nil { + t.Fatalf("второй проход: %v", err) + } + if n := sink.count("deliveries waited for fold"); n != 1 { + t.Errorf("предупреждений о задержке %d, ожидалось 1:\n%s", n, sink.dump()) + } +} + +// Отмена контекста завершает цикл — без ожиданий по часам: синхронизация идёт +// возвратом Run, а не сном. +func TestRunЗавершаетсяПоОтмене(t *testing.T) { + t.Parallel() + + dir := t.TempDir() + w, _, _, sink := newWorker(t, dir) + + ctx, cancel := context.WithCancel(context.Background()) + cancel() + + done := make(chan struct{}) + go func() { + defer close(done) + w.Run(ctx) + }() + select { + case <-done: + case <-time.After(10 * time.Second): + t.Fatalf("Run не вышел по отмене:\n%s", sink.dump()) + } +} + +// Задолженность при старте называется одной строкой: это ответ на вопрос «что +// сервис будет делать первые минуты после рестарта». +func TestRunНазываетЗадолженностьПриСтарте(t *testing.T) { + t.Parallel() + + dir := t.TempDir() + w, st, arch, sink := newWorker(t, dir) + + items := journal(t, "minute.json", "hour.json") + for _, it := range items { + writeBody(t, arch, st, it, fixture(t, it.fixture)) + } + + // Ожидание регистрируется ДО запуска: тест синхронизируется появлением + // строки, а не сном. + said := sink.expect("pending backlog at start", 1) + + ctx, cancel := context.WithCancel(context.Background()) + defer cancel() + done := make(chan struct{}) + go func() { + defer close(done) + w.Run(ctx) + }() + + select { + case <-said: + case <-time.After(30 * time.Second): + t.Fatalf("строки о задолженности нет:\n%s", sink.dump()) + } + cancel() + <-done +} + +// Notify не блокирует и не копит: сигнал ничего не несёт, и лишний теряется +// намеренно. +func TestNotifyНеБлокирует(t *testing.T) { + t.Parallel() + + w, _, _, _ := newWorker(t, t.TempDir()) + for range 100 { + w.Notify() + } +} + +// Отказ прохода не убивает цикл: воркер, умерший от временного отказа базы, +// остановил бы свёртку до конца жизни процесса, пока приём продолжал бы +// отвечать 200. +func TestRunПереживаетОтказПрохода(t *testing.T) { + t.Parallel() + + dir := t.TempDir() + w, st, _, sink := newWorker(t, dir) + + // База закрыта — выборка неразобранных отказывает на каждом проходе. + if err := st.Close(); err != nil { + t.Fatalf("закрытие базы: %v", err) + } + + // Второй отказ доказывает, что цикл пережил первый. Разбудить второй проход + // без ожидания по часам может только сигнал: тик идёт раз в минуту. + twice := sink.expect("fold pass failed", 2) + w.Notify() + + ctx, cancel := context.WithCancel(context.Background()) + defer cancel() + done := make(chan struct{}) + go func() { + defer close(done) + w.Run(ctx) + }() + + select { + case <-twice: + case <-time.After(30 * time.Second): + t.Fatalf("цикл не пережил отказ прохода:\n%s", sink.dump()) + } + cancel() + <-done +} diff --git a/internal/store/delivery.go b/internal/store/delivery.go index c4425ad..4ae12b9 100644 --- a/internal/store/delivery.go +++ b/internal/store/delivery.go @@ -54,6 +54,13 @@ type Delivery struct { } // CreateDelivery записывает факт приёма пакета. +// +// Через ту же транзакцию с повторами, что и слияние точек, и это не симметрия +// ради симметрии. Свёртка держит запись всю доставку целиком — измерено 11 +// секунд на 16 тысячах объектов, — а с фоновым воркером конкуренция за базу +// стала штатной. Одиночный `Exec` пересиживал бы только `busy_timeout`, после +// чего приём ответил бы `500` по доставке, тело которой уже на диске: доставка +// исчезла бы из журнала, а телефон её не перешлёт. func (s *Store) CreateDelivery(ctx context.Context, d Delivery) error { const q = ` INSERT INTO delivery (id, received_at, automation_name, automation_id, @@ -66,10 +73,13 @@ func (s *Store) CreateDelivery(ctx context.Context, d Delivery) error { headers = "{}" } - _, err := s.db.ExecContext(ctx, q, - d.ID, FormatTime(d.ReceivedAt), d.AutomationName, d.AutomationID, - d.Aggregation, d.Period, d.SessionID, d.Bytes, d.SHA256, - d.RawPath, d.ParseStatus, d.Points, headers) + err := s.inTx(ctx, func(tx *sql.Tx) error { + _, err := tx.ExecContext(ctx, q, + d.ID, FormatTime(d.ReceivedAt), d.AutomationName, d.AutomationID, + d.Aggregation, d.Period, d.SessionID, d.Bytes, d.SHA256, + d.RawPath, d.ParseStatus, d.Points, headers) + return err //nolint:wrapcheck // обёртка одна, на выходе + }) if err != nil { return fmt.Errorf("insert delivery: %w", err) } @@ -148,6 +158,69 @@ func (s *Store) ListDeliveries(ctx context.Context) ([]Delivery, error) { return out, nil } +// PendingDelivery — доставка, ожидающая свёртки. Она же курсор обхода: место в +// журнале задаётся парой `(received_at, id)`, и вызывающему достаточно передать +// обратно последнюю полученную строку. +// +// Метка приёма отдаётся не для порядка (его держит SQL), а для метки отставания: +// «доставка ждала свёртки дольше N» считается от неё. +type PendingDelivery struct { + ID string + ReceivedAt time.Time +} + +// PendingDeliveries возвращает неразобранные доставки в порядке журнала, +// строго после курсора. Нулевой курсор означает «с начала». +// +// Курсор нужен не ради страниц, а ради завершимости обхода: доставка, у которой +// не удалось записать даже исход разбора, остаётся `pending`, и выборка без +// курсора выдавала бы её бесконечно. +func (s *Store) PendingDeliveries(ctx context.Context, after PendingDelivery, limit int) ([]PendingDelivery, error) { + // Сравнение кортежем, а не через OR: развёрнутая форма даёт SCAN по + // индексу вместо SEARCH (проверено EXPLAIN QUERY PLAN). Тот же приём уже + // применён в LastDerivedLayer. + const q = ` + SELECT id, received_at FROM delivery + WHERE parse_status = ? AND (received_at, id) > (?, ?) + ORDER BY received_at, id LIMIT ?` + + rows, err := s.db.QueryContext(ctx, q, ParsePending, FormatTime(after.ReceivedAt), after.ID, limit) + if err != nil { + return nil, fmt.Errorf("select pending deliveries: %w", err) + } + defer func() { _ = rows.Close() }() + + var out []PendingDelivery + for rows.Next() { + var d PendingDelivery + var receivedAt string + if err := rows.Scan(&d.ID, &receivedAt); err != nil { + return nil, fmt.Errorf("scan pending delivery: %w", err) + } + d.ReceivedAt, err = ParseTime(receivedAt) + if err != nil { + return nil, err + } + out = append(out, d) + } + if err := rows.Err(); err != nil { + return nil, fmt.Errorf("select pending deliveries: %w", err) + } + return out, nil +} + +// CountPendingDeliveries возвращает размер задолженности — сколько доставок +// ждут свёртки. Нужен ровно одной строке лога при старте: сколько сервис должен +// разобрать, прежде чем витрина станет полной. +func (s *Store) CountPendingDeliveries(ctx context.Context) (int64, error) { + var n int64 + if err := s.db.GetContext(ctx, &n, + `SELECT count(*) FROM delivery WHERE parse_status = ?`, ParsePending); err != nil { + return 0, fmt.Errorf("count pending deliveries: %w", err) + } + return n, nil +} + // DeliveryStatus возвращает статус разбора доставки. func (s *Store) DeliveryStatus(ctx context.Context, id string) (string, error) { var status string diff --git a/internal/store/errors.go b/internal/store/errors.go index b81a88f..1a0844a 100644 --- a/internal/store/errors.go +++ b/internal/store/errors.go @@ -1,8 +1,40 @@ package store -import "errors" +import ( + "context" + "errors" +) // ErrNotFound — записи нет. Граничную ошибку драйвера (sql.ErrNoRows) // транслируем в доменную здесь же, у источника, чтобы выше по коду не торчал // database/sql. var ErrNotFound = errors.New("запись не найдена") + +// ErrBusy — база занята, и повторы транзакции этого не пересидели. +// +// Доменная ошибка, а не код драйвера: на неё ветвится свёртка. Отказ по +// занятости не является свойством доставки — работа просто не сделана, и +// доставка обязана остаться в очереди. Без этого различения конкуренция за +// базу выводила бы доставку из очереди навсегда. +var ErrBusy = errors.New("база занята") + +// Transient отвечает, вызван ли отказ ОБСТОЯТЕЛЬСТВАМИ, а не данными. +// +// Ровно два случая: работу прекратили снаружи и база оказалась занята дольше, +// чем длятся повторы транзакции. Оба означают «не сделано», а не «не выходит», +// поэтому работа обязана остаться к повторению. +// +// Определение живёт здесь, в одном месте, и его читают двое: тот, кто пишет +// исход разбора доставки, и тот, кто классифицирует этот исход в счётчики. Две +// копии правила разошлись бы, и доставка одновременно осталась бы в очереди и +// числилась отказавшей. +// +// Дедлайн самой операции сюда НЕ входит: не уложившаяся в бюджет работа не +// уложится в него и в следующий раз, а бесконечный повтор заведомо +// безнадёжного — это очередь, которая не движется. +func Transient(err error) bool { + if errors.Is(err, context.DeadlineExceeded) { + return false + } + return errors.Is(err, context.Canceled) || errors.Is(err, ErrBusy) +} diff --git a/internal/store/migrations/00006_delivery_pending.sql b/internal/store/migrations/00006_delivery_pending.sql new file mode 100644 index 0000000..da70fea --- /dev/null +++ b/internal/store/migrations/00006_delivery_pending.sql @@ -0,0 +1,20 @@ +-- +goose Up +-- Очередью свёртки служит сама таблица: доставка ждёт разбора в статусе +-- `pending`, а фоновый воркер выбирает такие строки в порядке журнала. Запрос +-- идёт чаще, чем раз в минуту, а `delivery` растёт примерно на 300 строк в +-- сутки — без индекса это скан всей таблицы с сортировкой на каждый проход. +-- +-- Индекс ЧАСТИЧНЫЙ, и это не украшение: в установившемся режиме неразобранных +-- доставок ноль или одна, поэтому индекс держит ноль-одну строку. Полный +-- индекс по `parse_status` хранил бы всю историю (сто тысяч строк в год) ради +-- выборки из одной. SQLite применяет частичный индекс, когда условие запроса +-- следует из условия индекса — наш случай. +-- +-- Порядок колонок = порядок журнала, тот же, в котором проигрывает пересборка. +-- Второй ключ обязателен: `received_at` хранится с секундной точностью, и +-- доставки одной секунды без него шли бы в неопределённом порядке. +CREATE INDEX delivery_pending ON delivery (received_at, id) + WHERE parse_status = 'pending'; + +-- +goose Down +DROP INDEX delivery_pending; diff --git a/internal/store/pending_test.go b/internal/store/pending_test.go new file mode 100644 index 0000000..e610527 --- /dev/null +++ b/internal/store/pending_test.go @@ -0,0 +1,153 @@ +package store_test + +import ( + "context" + "errors" + "fmt" + "testing" + "time" + + "git.vakhrushev.me/av/healthlog/internal/store" +) + +// Очередь свёртки — сама таблица, и порядок её обхода это порядок журнала: +// `(received_at, id)`, тот же, в котором проигрывает пересборка. +func TestPendingDeliveriesИдётВПорядкеЖурнала(t *testing.T) { + t.Parallel() + + st := open(t) + ctx := context.Background() + at := ts(t, "2026-08-01T12:00:00Z") + + // Учёт заполняется в порядке, обратном хронологии, и доставки одной секунды + // различаются только идентификатором. + seedPending(t, st, "d3", at.Add(time.Second)) + seedPending(t, st, "d2", at) + seedPending(t, st, "d1", at) + + got, err := st.PendingDeliveries(ctx, store.PendingDelivery{}, 10) + if err != nil { + t.Fatalf("PendingDeliveries: %v", err) + } + want := []string{"d1", "d2", "d3"} + if len(got) != len(want) { + t.Fatalf("выбрано %d доставок, ожидалось %d", len(got), len(want)) + } + for i, id := range want { + if got[i].ID != id { + t.Errorf("на месте %d доставка %q, ожидалась %q", i, got[i].ID, id) + } + } +} + +// Курсор строго возрастает, и обход им конечен: без этого доставка, у которой +// не удалось записать даже исход разбора, выбиралась бы бесконечно. +func TestPendingDeliveriesКурсорСтрогоВозрастает(t *testing.T) { + t.Parallel() + + st := open(t) + ctx := context.Background() + at := ts(t, "2026-08-01T12:00:00Z") + + seedPending(t, st, "d1", at) + seedPending(t, st, "d2", at) + + first, err := st.PendingDeliveries(ctx, store.PendingDelivery{}, 1) + if err != nil { + t.Fatalf("PendingDeliveries: %v", err) + } + if len(first) != 1 || first[0].ID != "d1" { + t.Fatalf("первая порция %+v", first) + } + + second, err := st.PendingDeliveries(ctx, first[0], 1) + if err != nil { + t.Fatalf("PendingDeliveries: %v", err) + } + if len(second) != 1 || second[0].ID != "d2" { + t.Fatalf("вторая порция %+v", second) + } + + // Доставка, оставшаяся `pending`, за курсором больше не выбирается — именно + // на этом стоит завершимость прохода воркера. + third, err := st.PendingDeliveries(ctx, second[0], 1) + if err != nil { + t.Fatalf("PendingDeliveries: %v", err) + } + if len(third) != 0 { + t.Errorf("за последней доставкой выбрано %d строк", len(third)) + } +} + +// В очередь попадают только неразобранные: свёрнутая доставка из неё выбывает, +// иначе воркер сворачивал бы весь журнал на каждом проходе. +func TestPendingDeliveriesБерётТолькоНеразобранные(t *testing.T) { + t.Parallel() + + st := open(t) + ctx := context.Background() + at := ts(t, "2026-08-01T12:00:00Z") + + seedPending(t, st, "d1", at) + seedPending(t, st, "d2", at.Add(time.Second)) + if err := st.FinishParse(ctx, "d1", store.ParseOutcome{Status: store.ParseDone}); err != nil { + t.Fatalf("FinishParse: %v", err) + } + + n, err := st.CountPendingDeliveries(ctx) + if err != nil { + t.Fatalf("CountPendingDeliveries: %v", err) + } + if n != 1 { + t.Errorf("задолженность %d, ожидалась 1", n) + } + + got, err := st.PendingDeliveries(ctx, store.PendingDelivery{}, 10) + if err != nil { + t.Fatalf("PendingDeliveries: %v", err) + } + if len(got) != 1 || got[0].ID != "d2" { + t.Errorf("в очереди %+v, ожидалась только d2", got) + } +} + +// Правило «отказ обстоятельств, а не данных» живёт в одном месте: его читают и +// тот, кто пишет исход разбора, и тот, кто классифицирует этот исход. +func TestTransientРазличаетОбстоятельстваИДанные(t *testing.T) { + t.Parallel() + + cases := map[string]struct { + err error + want bool + }{ + "работу прекратили снаружи": {context.Canceled, true}, + "база занята": {store.ErrBusy, true}, + "база занята, обёрнута": {fmt.Errorf("слияние: %w", store.ErrBusy), true}, + "не уложились в бюджет": {context.DeadlineExceeded, false}, + "записи нет": {store.ErrNotFound, false}, + "прочее": {errors.New("диск отвалился"), false}, + "ошибки нет": {nil, false}, + } + + for name, c := range cases { + t.Run(name, func(t *testing.T) { + t.Parallel() + + if got := store.Transient(c.err); got != c.want { + t.Errorf("Transient(%v) = %v, ожидалось %v", c.err, got, c.want) + } + }) + } +} + +func seedPending(t *testing.T, st *store.Store, id string, at time.Time) { + t.Helper() + + err := st.CreateDelivery(context.Background(), store.Delivery{ + ID: id, ReceivedAt: at, RawPath: id + ".json.gz", + SHA256: "-", ParseStatus: store.ParsePending, + }) + if err != nil { + t.Fatalf("запись доставки %q: %v", id, err) + } +} diff --git a/internal/store/tx.go b/internal/store/tx.go index fcb833b..bbb04e8 100644 --- a/internal/store/tx.go +++ b/internal/store/tx.go @@ -51,7 +51,10 @@ func (s *Store) inTx(ctx context.Context, fn func(*sql.Tx) error) error { lastErr = err } - return fmt.Errorf("транзакция не прошла за %d попыток: %w", txRetries, lastErr) + // Занятость называется доменной ошибкой здесь, у источника: выше по коду + // не должно торчать ни `sqlite.Error`, ни его коды, а ветвиться на этот + // исход нужно — доставка при нём остаётся в очереди. + return fmt.Errorf("%w: транзакция не прошла за %d попыток: %v", ErrBusy, txRetries, lastErr) //nolint:errorlint // раскрываем sentinel, причину — намеренно нет } func runTx(ctx context.Context, db *sql.DB, fn func(*sql.Tx) error) error { diff --git a/openspec/changes/archive/2026-08-02-otvet-i-svyortka/.openspec.yaml b/openspec/changes/archive/2026-08-02-otvet-i-svyortka/.openspec.yaml new file mode 100644 index 0000000..d658936 --- /dev/null +++ b/openspec/changes/archive/2026-08-02-otvet-i-svyortka/.openspec.yaml @@ -0,0 +1,2 @@ +schema: spec-driven +created: 2026-08-02 diff --git a/openspec/changes/archive/2026-08-02-otvet-i-svyortka/design.md b/openspec/changes/archive/2026-08-02-otvet-i-svyortka/design.md new file mode 100644 index 0000000..acb7592 --- /dev/null +++ b/openspec/changes/archive/2026-08-02-otvet-i-svyortka/design.md @@ -0,0 +1,431 @@ +## Context + +Приём и свёртка сегодня — одна операция. `ingest.Accept` пишет тело в архив, +вставляет строку `delivery` и **тут же** зовёт `fold.Fold` на контексте, +отвязанном от запроса, но синхронно; обработчик отвечает только после этого. +Стоимость свёртки измерена: 1001 объект — 815 мс, 4001 — 3.07 с, 16001 — +11.07 с. Переход на одну транзакцию на доставку снял около 0.7 мс на объект +(прогон живого архива ускорился с 64 до 52 секунд), но порядок величины +остался. + +Что уже есть и на что опираемся: + +- `fold.Fold(ctx, deliveryID)` — свёртка **одной** доставки по идентификатору, + тело читается из архива. Идемпотентна: победитель координаты — функция + множества кандидатов, а не порядка. +- `internal/replay` — проигрывание журнала целиком: состав из архива, порядок + `(received_at, id)`, классификация исходов, отчёт. Появился задачей + `reindex-iz-arhiva`. +- `store.ParsePending` — «этим разбором тело ещё не смотрели». Статус + консервативный: ретеншен его не трогает никогда. Миграция `00005` перевела в + него все доставки, и подобрать их сегодня может только `healthlog reindex`. +- `store.LastDerivedLayer(automationID, before, beforeID)` — наследование слоя + строго от **предшествующей** доставки: слой обязан быть функцией префикса + журнала. +- `store.inTx` — пять попыток с нарастающей паузой при занятости базы, + `_txlock=immediate`, одна транзакция на доставку. + +Ограничения окружения: один процесс, SQLite, файлы; «без очередей и внешних +зависимостей» — принцип архитектуры. Телефон шлёт молча каждые пять минут и +доставку не переприсылает. `stop_grace_period` контейнера — 30 секунд. + +## Goals / Non-Goals + +**Goals:** + +- Время ответа на приём перестаёт зависеть от ширины доставки. +- Свёртка идёт в порядке журнала и при конкурентных доставках тоже. +- Несвёрнутое переживает падение и рестарт процесса, а не только штатную + остановку. +- Подбор `pending` и пересборка — один код, а не два похожих. +- Отставание воркера видно **до** того, как станет отставанием на сутки, — в + том числе когда воркер не двигается вовсе. + +**Non-Goals:** + +- **Параллельная свёртка.** Слой — функция префикса журнала, запись объекта — + read-modify-write. Воркер один, и это требование, а не упрощение. +- **Дедупликация доставок, ретеншен архива, `/stats`.** Свои задачи беклога. +- **Гарантия «доставка свёрнута к моменту ответа».** Она снимается сознательно + — в этом вся задача; взамен даётся «доставка сохранена и учтена к моменту + ответа», а несвёрнутое видно в `parse_status`. +- **Абсолютный порядок журнала при конкурентных приёмах.** Достижимого предела + — «все видимые воркеру неразобранные доставки сворачиваются в порядке + `(received_at, id)`» — достаточно; см. риски. +- **Возврат `failed` в очередь.** Доставка, отказавшая по собственному + содержимому, остаётся `failed` и возвращается только пересборкой. Это + названная граница, см. решение 4б. + +## Decisions + +### 1. Очередью служит таблица `delivery`, а не список идентификаторов в памяти + +Формулировка задачи говорила «очередь идентификаторов доставок» и отдельно +оговаривала поведение при переполнении. Реализуется это **очередью в базе**: +доставка ждёт свёртки в собственном статусе `pending`, а канал между приёмом и +воркером несёт не идентификаторы, а один бит «есть работа» (буфер 1, +неблокирующая отправка). + +Prior art здесь однозначен и стар — это **transactional outbox** и его частный +случай «база как очередь заданий» +([AWS Prescriptive Guidance](https://docs.aws.amazon.com/prescriptive-guidance/latest/cloud-design-patterns/transactional-outbox.html), +[Three Dots Labs, durable execution на Go и SQLite](https://threedots.tech/post/sqlite-durable-execution/)). +Суть шаблона ровно наша: состояние задания пишется в ту же базу той же +транзакцией, что и факт события, а фоновый процесс выбирает необработанные +строки. Всё, что живёт только в памяти, теряется при падении — а у нас падение +означает молчаливую потерю свёртки для доставки, которую телефон не перешлёт. + +Что это даёт сверх памяти, по пунктам исходной задачи: + +- **Переполнения нет.** «Очередь переполнена — доставка остаётся `pending`, это + не отказ» выполняется по построению: доставка `pending` всегда, пока не + свёрнута. Сигнал теряться может и должен — он ничего не несёт. +- **Подбор `pending` при старте — не отдельный код.** Это обычный проход + воркера: старт просто будит его первым сигналом. Второй путь подбора не + появляется, потому что путь один. +- **Падение и `SIGKILL` не теряют очередь.** Транзакция свёртки откатывается, + статус остаётся `pending`, следующий старт подберёт. + +Форма сигнала — канал ёмкостью 1 с неблокирующей отправкой — не изобретение: +это форма `os/signal.Notify` («Package signal will not block sending to c… a +buffer of size 1 is sufficient») и `time.Ticker` («will drop ticks to make up +for slow receivers»), и она же названа в стайлгайде Uber (*Channel Size is One +or None*). `sync.Cond` здесь непригоден механически: `Wait()` не кладётся в +`select` с `ctx.Done()`. + +Отвергнуто: **канал идентификаторов в памяти** (буферизованный, с политикой +переполнения). Причина — он вводит второе, недолговечное представление того же +факта: доставка одновременно «в очереди» и «pending в базе», и эти два +представления расходятся при каждом падении. Плюс политика переполнения +(«оставить pending») всё равно требует подбора из базы, то есть кода из +варианта выше — только теперь его два. + +Отвергнуто: **опрос базы по таймеру ВМЕСТО сигнала**. Он добавляет задержку в +полпериода на каждую доставку без всякой пользы: сигнал — одна строка. Но тик +**в дополнение** к сигналу берётся, и по другой причине — см. решение 5. + +### 2. Порядок — тот же `(received_at, id)`, курсором внутри прохода + +Порядок журнала определён capability пересборки (`openspec/specs/reindex/`), и +здесь он не переопределяется, а используется: воркер обрабатывает доставки в +том же порядке и по той же причине. Повторять обоснование в двух спеках нельзя — +правило поехало бы в одной и осталось в другой. + +Проход воркера выбирает неразобранные доставки запросом +`WHERE parse_status = 'pending' AND (received_at, id) > (?, ?) +ORDER BY received_at, id LIMIT n`, курсор внутри прохода строго возрастает. + +Форма сравнения — **row-value**, а не развёрнутая через `OR`, и это проверено +планом запроса на воспроизведённой схеме: + +``` +(received_at,id) > (?,?) → SEARCH … COVERING INDEX delivery_pending +received_at > ? OR (received_at = ? AND id > ?) → SCAN … COVERING INDEX delivery_pending +``` + +Прецедент в проекте уже есть — `store.LastDerivedLayer`. Нулевой курсор — +`(time.Time{}, "")`, то есть `0001-01-01T00:00:00Z`: один текст запроса без +ветки «первая страница». + +Строго возрастающий курсор нужен не ради страниц, а ради **завершимости**: +доставка, у которой не удалось записать даже исход разбора, остаётся `pending` — +и проход без курсора выбирал бы её вечно. С курсором проход конечен всегда. + +Доставка, приехавшая во время прохода с меньшим `received_at`, курсором +пропускается — и подбирается следующим проходом, который её же сигнал и +запустит. + +Отвергнуто: множество «уже пробованных в этом проходе» вместо курсора. +Эквивалентно по эффекту, но растёт по памяти вместе с задолженностью — а +задолженность после миграции `00005` это весь архив. + +### 3. Общий с пересборкой код — классификатор исхода одной доставки + +`replay.Run` сегодня несёт в себе цикл, который для каждой доставки зовёт +`fold.Fold` и разбирает исход по классам: `ErrLayerUnknown` — штатный отказ +(слой не выведен), `ErrMalformed` — непонятое содержимое, прочее — настоящая +поломка; счётчики частичного разбора и несравнимых наборов читаются **только** +у успешной свёртки, иначе `Partial` молча занижается, а по нему принимается +решение о судьбе тела. + +Это и есть та половина, которую задача требует не дублировать. Она выносится в +`replay.Player.Play(ctx, deliveryID) (Outcome, error)` — исход **одной** +доставки значением, — и её зовут оба: `replay.Run` в своём цикле и воркер в +своём. Накопление — `(*Outcome).Add(other)`; `replay.Report` встраивает +`Outcome`, чтобы у пересборки не появилось второго набора имён для тех же +исходов. + +**`Player` не смотрит на контекст.** Он классифицирует только ошибку, которую +вернула свёртка; решение «нас остановили» принимает цикл, каждый по своему +контексту. Иначе один и тот же `ctx.Err() != nil` означал бы у двух вызывающих +противоположное: у пересборки в свёртку уходит тот же отменяемый контекст +(«нас остановили»), у воркера — отвязанный от остановки, с собственным дедлайном +(«доставка не уложилась в две минуты»). Воркер, унаследовавший чужую ветку, +принял бы свой дедлайн за остановку и бросил проход молча. + +Возврат значением, а не накопление по указателю: так устроены `fold.Fold`, +`store.MergePoints` и `replay.Run`, аккумулирующего out-параметра в проекте нет +ни одного. Плюс правило «счётчики только у успеха» становится утверждением о +результате одного вызова, а не вычитанием двух состояний — а именно на этом +правиле уже один раз занижался `Partial`. + +Целиком общим цикл быть не может, и это названная граница: у пересборки состав +берётся из **архива** (тело без учётной записи — тоже событие) и пишется в +пустую базу, у воркера состав берётся из **учёта** (`pending`) и пишется в +рабочую. Общее у них — порядок, точка входа в свёртку и классификация исхода; +именно они и разошлись бы молча. + +Отвергнуто: **звать `replay.Run` из воркера**. Он требует пустой базы +назначения и проигрывает весь журнал с нуля — под живым приёмом это не +операция подбора, а пересборка. + +Отвергнуто: **воркер в `internal/ingest`**. Тогда порядок журнала знали бы два +пакета, и правку правила пришлось бы вносить в оба. `internal/replay` уже +объявлен местом, где живут «состав, порядок, отчёт»; фоновое проигрывание +хвоста — тот же предмет, только непрерывный. + +### 4. Остановка формулируется инвариантом, а не обещанием досчитать + +Свёртка идёт на контексте `context.WithoutCancel` от контекста воркера плюс +собственный дедлайн — ровно так, как сегодня это делает `ingest.Accept`. +Механизм не новый, он переезжает. Отмена контекста воркера проверяется +**между** доставками. + +Обещать «текущая доставка досворачивается» нельзя: `foldTimeout` — две минуты, а +весь бюджет остановки — тридцать секунд, и `srv.Shutdown` тратит его первым. +Обещание, которое система не всегда исполняет, — это флакующий приёмочный тест и +неверное представление у следующего читателя. Поэтому требование формулируется +**инвариантом**: после остановки не существует доставки, которая числится +разобранной, а записана частично; несвёрнутое остаётся `pending`. + +Порядок остановки: `srv.Shutdown` (перестаём принимать) → отмена контекста +воркера → ожидание его выхода в остатке того же бюджета. Обратный порядок +оставил бы доставки, принятые после остановки воркера, никого не разбудившими. + +Механизм ожидания — `done chan struct{}`, закрываемый воркером в `defer`, и +`select` с бюджетом: `sync.WaitGroup.Wait()` бюджета не принимает. + +Два следствия, которые надо назвать вслух, иначе они дадут ложные `ERROR`: + +- **`Shutdown` возвращает `context.DeadlineExceeded` штатно** — так + задокументировано в stdlib. Сегодня `runServe` возвращает любую его ошибку + наверх, а `main` печатает `fatal startup` и выходит с кодом 1. После того как + бюджет ответа приёма вырос (решение 7), исчерпание бюджета остановки во время + загрузки станет обычным делом, и штатная остановка докладывалась бы как + провал старта. Контекстная ошибка `Shutdown` — `WARN`, а не отказ команды. +- **База не закрывается, пока воркер не вышел.** `defer st.Close()` при не + уложившемся в бюджет воркере закрыл бы базу под живой транзакцией свёртки, и + в лог ушли бы `ERROR` по доставке, с которой всё в порядке. Не уложились — + оставляем закрытие процессу, а факт называем `WARN`. + +### 4б. Отмена и занятость базы оставляют доставку в очереди, всё прочее — нет + +Сегодня `fold.fail` пишет `parse_status = failed` на **любой** ошибке. Пока +свёртка шла синхронно, это было терпимо. С воркером — нет: `failed` из очереди +выбывает навсегда, а вернуть его может только `healthlog reindex`, то есть +операция с остановкой сервиса и ручной подменой базы. Занятость базы после пяти +попыток `inTx` (порядка 200 мс на широкой доставке) стирала бы доставку с полки +молча — притом что сама эта задача делает конкуренцию за базу штатной. + +Правило: **исход разбора отражает доставку, а не обстоятельства.** + +- Отказ окружения — отмена контекста и занятость базы — статус **не меняет**: + доставка остаётся `pending` и подбирается следующим проходом или тиком. +- Всё остальное (`ErrMalformed`, `ErrLayerUnknown`, нечитаемое тело, тело сверх + предела, исчерпанный дедлайн свёртки) — `failed`, как и сейчас: это свойства + самой доставки, и повторять их бесполезно. + +Занятость распознаётся сентинелом `store.ErrBusy` — `inTx` уже отличает +`SQLITE_BUSY`/`SQLITE_BUSY_SNAPSHOT` по коду, осталось назвать исход доменной +ошибкой у источника, как того требуют конвенции. + +Отвергнуто: **счётчик попыток с переводом в `failed` после N**. Он нужен +очередям заданий общего назначения, где задание может быть ядовитым. У нас +ядовитость уже отсечена по классу: содержимое даёт `failed` с первого раза, а в +`pending` остаются только те два случая, которые проходят сами. Колонка и +политика «сколько попыток достаточно» были бы изобретением без наблюдения. + +### 5. Проход будит не только сигнал: тик — страховка и площадка для метки + +К сигналу добавляется тик (порядка минуты) в том же `select`. Он не альтернатива +сигналу (см. решение 1), он закрывает два случая, которые сигнал закрыть не +может: + +- **Доставка, оставшаяся `pending` по решению 4б**, ждала бы следующей доставки, + чтобы её кто-то разбудил. Ночью телефон молчит часами. +- **Отставание невидимо ровно тогда, когда оно опасно.** Если метка задержки + вычисляется внутри прохода, а прохода нет, «работа есть, прогресса нет» + неотличимо от здорового пустого потока. + +Наблюдаемость — две метки, и обе берутся из строк, которые проход и так +выбрал: + +- `WARN` «доставка ждала свёртки дольше пяти минут» с `delivery_id` и + величиной ожидания. Порог — период быстрого прохода синхронизации: если + доставка ждала дольше, чем интервал между доставками, очередь растёт, а не + рассасывается. Считается от `received_at` до **начала** свёртки. +- `INFO` один раз при старте: сколько доставок числится неразобранными. Это + размер задолженности и ответ на вопрос «что сервис будет делать первые минуты + после рестарта». + +**Первый проход задержку не считает.** После миграции `00005` неразобранными +числятся все доставки архива, и метка сработала бы сотней строк подряд, ничего +не сообщив: они ждали не воркера, а его появления. Задолженность при старте +называется одним `INFO`, метка включается после первого прохода. + +**Отказ прохода воркер переживает.** Отказ `SELECT` (занятая база, отказ диска) +— это `ERROR` и выход из прохода, а не из цикла: воркер, умерший от временного +отказа базы, остановил бы свёртку до конца жизни процесса, а приём продолжал бы +отвечать `200`. + +Числа — текущая длина `pending`, возраст самой старой неразобранной доставки — +это `/stats`, и они уезжают строкой в задачу `stats-nablyudaemost`. Здесь их +нет намеренно: отдельного механизма счётчиков в проекте пока не существует. + +### 6. Частичный индекс по неразобранным доставкам + +Запрос прохода спрашивается чаще, чем раз в минуту, а `delivery` растёт на +~300 строк в сутки (100 тысяч в год). Без индекса это скан таблицы с сортировкой +на каждый проход. + +Индекс — **частичный**: `(received_at, id) WHERE parse_status = 'pending'`. В +установившемся режиме в нём ноль–одна строка, потому что свёрнутая доставка из +него выпадает; полный индекс по `parse_status` хранил бы все сто тысяч ради +выборки из одной. План запроса проверен (см. решение 2): индекс покрывающий, и +счёт задолженности по нему тоже не сканирует таблицу. + +### 7. Длинный бюджет ответа даётся маршруту приёма, а не всему серверу + +`WriteTimeout` у Go ставится в `readRequest`, до вызова обработчика, и потому +покрывает **и чтение тела**: при `read_timeout = 5m` и `write_timeout = 30s` +загрузка дольше 30 секунд обрывается, а `read_timeout` при этом обещает пять +минут. Премисса проверена по исходнику (`net/http/server.go`, постановка +write-дедлайна `defer`-ом внутри `readRequest`), симптом описан +[здесь](https://adam-p.ca/blog/2022/01/golang-http-server-timeouts/) и +[здесь](https://blog.cloudflare.com/exposing-go-on-the-internet/). Для 64 МиБ по +мобильной сети это не теоретический случай, и после выноса свёртки это +**единственный** оставшийся источник того же молчаливого обрыва. + +Лечится это не подъёмом глобального умолчания, а дедлайном на том маршруте, +которому длинный бюджет нужен: обработчик приёма перед чтением тела ставит +`http.NewResponseController(w).SetWriteDeadline(now + read_timeout + +write_timeout)`. Тогда `/healthz` и будущий Read API сохраняют тридцатисекундную +защиту от застрявшей записи, конфиг не меняется вовсе, и не появляется пары +таймаутов, из которых один молча отменяет другой. + +Механика проверена: `middleware.WrapResponseWriter` из chi реализует +`Unwrap() http.ResponseWriter`, поэтому `ResponseController` до соединения +добирается. Транспорт, не поддерживающий дедлайнов, отвечает +`http.ErrNotSupported` — это `DEBUG` и продолжение работы, а не отказ приёма. + +Отвергнуто: **поднять умолчание `write_timeout` до `read_timeout`**. Три +возражения. Оно снимает защиту от застрявшей записи со **всех** маршрутов, ради +одного. Оно кладёт требование о глобальном параметре сервера в capability +приёма, где читатель Read API его не найдёт. И оно порождает вопрос +«сравниваются умолчания или эффективные значения», на который два реализатора +ответят по-разному. + +Отвергнуто: **не трогать вовсе**. Так и было бы, будь это вместо выноса +свёртки; вместе с ним это доведение до конца — иначе `read_timeout` остаётся +обещанием, которого сервер не исполняет. + +### 8. У цикла воркера есть синхронный шов, и тесты идут через него + +`Worker.Pass(ctx) (Outcome, error)` — один проход, синхронный, без каналов; +`Run(ctx)` — тонкий `select` поверх него. Тесты зовут `Pass` напрямую и ничего +не ждут по часам; на `Run` остаётся один тест — «отмена завершает цикл», и он +синхронизируется возвратом `Run`, а не сном. + +Без такого шва проверки «все свёрнуты», «проход конечен», «метка не сработала +на первом проходе» пишутся опросом базы с таймаутом, то есть сном в разной +форме, и мигают на загруженной машине. Гейт при этом перестаёт быть +детерминированным, а на нём стоит весь конвейер ревью. + +Остальные швы — те, что есть: + +- Порядок при конкурентных доставках проверяется наблюдаемым следствием + порядка — **наследованием слоя**: доставка без плотных метрик обязана + получить слой предшествующей ей по `(received_at, id)`. +- Отмена не оставляет половинчатого состояния — доставка остаётся `pending`, а + не `parsed` с половиной объектов. +- `task verify:archive` остаётся оракулом сходимости: пересборка проигрывает + журнал сама и воркера не касается. + +### 9. Учёт доставки переживает обрыв соединения + +`Accept` всё равно переписывается, и заодно чинится сузившийся до одного шага +риск: `store.CreateDelivery` идёт на контексте запроса, а тот отменяется при +обрыве связи клиентом. Тело к этому моменту уже в архиве (`arch.Write` +контекста не берёт), и отказ на вставке оставляет тело сиротой — восстановимо +только пересборкой с подменой базы. Раньше вероятность обрыва размазывалась по +следующей за вставкой свёртке; теперь вставка — последний шаг перед `200`. + +Поэтому учёт ведётся на `context.WithoutCancel` с коротким собственным +дедлайном — тем же приёмом и по той же причине, по какой это делает +`fold.finish`: отмена снаружи не должна превращаться в свойство доставки. +Проверка формы тела остаётся на исходном контексте — там отменяемость уместна. + +## Risks / Trade-offs + +- **Абсолютный порядок при конкурентных приёмах недостижим** → две доставки, + принимаемые одновременно, могут закоммитить строки в порядке, обратном их + `received_at`; если воркер успел свернуть позднюю до того, как ранняя стала + видимой, наследование слоя разойдётся с тем, что даст пересборка. Смягчение: + окно сузилось (воркер один и берёт минимум из видимых, а не сворачивает в + порядке завершения обработчиков), исход остаётся детерминированно чинимым + (`healthlog reindex`), и сам эффект касается только доставок **без плотных + метрик**. Абсолютную гарантию дало бы удержание порядка на приёме, то есть + сериализация приёма — цена, которую задача платить не собиралась. +- **Ответ `200` больше не означает «разобрано»** → это объявленная смена + контракта, и в `docs/architecture.md` она фиксируется как контракт, а не как + деталь реализации воркера. Клиент HAE о разборе и не спрашивал; владелец + видит исход в `parse_status` и в логе. Читатель, делающий `POST` → чтение, + получает гонку — сегодня такой читатель один, тесты, и они переписаны на + синхронный `Pass`. +- **`failed` из очереди не возвращается** → доставка, отказавшая по + содержимому, ждёт пересборки. Это осознанная граница: обратное означало бы + бесконечный повтор заведомо безнадёжного. Названа в спеке. +- **Задолженность после рестарта разбирается не мгновенно** → 116 тел живого + архива это порядка минуты работы воркера; всё это время витрина неполна. + Названо `INFO`-строкой при старте. `/healthz` этого не отражает — он статичен; + отражать будет `/stats`, задача `stats-nablyudaemost`. +- **Второй процесс на той же базе даёт двух воркеров** → «одна горутина» — + свойство процесса, а не файла базы. Порчи витрины ждать не приходится + (`_txlock=immediate` и повтор транзакции сериализуют слияние), но наследование + слоя перестаёт быть функцией префикса. Механизма против этого не вводим: + запуск второго `serve` на той же базе не входит ни в один сценарий проекта, а + блокировка файла — отдельная задача с собственной ценой. Названо, чтобы не + было открытием. +- **Свёртка теперь конкурирует с приёмом за базу** → она и раньше шла на + отвязанном контексте, то есть параллельно следующему запросу; новое здесь + только то, что параллельность стала штатной. `busy_timeout`, + `_txlock=immediate` и повтор транзакции уже есть, а исчерпание повторов теперь + не стирает доставку с полки (решение 4б). Наблюдение за этим — задача + `cena-sliyaniya-na-shirokoj-dostavke`. +- **Тик даёт проход раз в минуту при пустой очереди** → это один запрос по + покрывающему частичному индексу, в котором ноль строк. Цена измеримо нулевая, + а без него состояние «работа есть, прогресса нет» невидимо. + +## Migration Plan + +Миграция схемы одна — `00006`, частичный индекс по неразобранным доставкам. +Данных она не трогает; `Down` снимает индекс. + +Порядок выкладки обычный: `task build` → `task restart`. Первый старт нового +бинаря напечатает `INFO` с размером задолженности и разберёт её проходами +воркера — то есть заодно подберёт доставки, которые числятся `pending` после +миграции `00005`. + +Откат — предыдущий бинарь: он свернёт всё синхронно, как раньше; +неразобранное к тому моменту останется `pending` до следующего `reindex`. Индекс +старому бинарю не мешает. + +## Open Questions + +- Метка задержки считается от `received_at`, который хранится с секундной + точностью; для порога в пять минут этого достаточно, но если порог когда-то + опустится до секунд, точности не хватит. +- Каждая будущая миграция, переводящая строки в `pending` (спека хранения этого + прямо требует от задач, покрывающих новую секцию), теперь автоматически + запускает пересвёртку под живым приёмом. Для `00005` это желаемое поведение; + для миграции размером в годовой архив вопрос о темпе встанет заново. diff --git a/openspec/changes/archive/2026-08-02-otvet-i-svyortka/proposal.md b/openspec/changes/archive/2026-08-02-otvet-i-svyortka/proposal.md new file mode 100644 index 0000000..293bd00 --- /dev/null +++ b/openspec/changes/archive/2026-08-02-otvet-i-svyortka/proposal.md @@ -0,0 +1,86 @@ +## Why + +Свёртка выполняется **внутри обработчика запроса**, поэтому время ответа равно +времени свёртки: 16 тысяч точек — 11 секунд. `WriteTimeout` в Go ставится в +`readRequest`, то есть до вызова обработчика, и его 30 секунд — общий бюджет на +всё: дочитать тело по мобильной сети, записать архив, вставить строку, свернуть. +Когда бюджет выходит, сервер считает, что отдал `200` (ошибки записи +обработчику не видно, ответ ушёл в буфер), клиент получает обрыв, а `accessLog` +пишет `status_code=200` — единственный канал наблюдаемости в этом сценарии врёт. + +Бьёт это по **широким проходам** (`Today`, `Previous 7 Days`, ручной экспорт) — +ровно по тем, ради которых заведён инвариант «дыры закрываются сами». + +## What Changes + +- Приём отвечает `200` **после архивации тела и вставки строки `delivery`**. + Свёртка из обработчика уходит: время ответа перестаёт зависеть от ширины + доставки. +- Свёртку ведёт **фоновый воркер** — одна горутина, обработка в порядке журнала + (`received_at`, `id`) среди доставок, видимых ему на момент выборки. +- **Очередью служит сама таблица**, а не список идентификаторов в памяти: + доставка ждёт свёртки в статусе `pending`, канал несёт только сигнал «есть + работа». Отсюда три следствия: переполнять нечего (доставка и так `pending`, + это не отказ), падение процесса очередь не теряет, а «подбор `pending` при + старте» перестаёт быть отдельным кодом — это обычный проход воркера. +- Классификация исхода свёртки (`folded` / слой не выведен / содержимое не + разобрано / прочее / частичный разбор) становится **общей с пересборкой**: + один проигрыватель в `internal/replay`, а не второй рядом. +- **Исход свёртки начинает отражать доставку, а не обстоятельства.** Сегодня + `failed` пишется на любой ошибке, включая занятость базы; с воркером это + означало бы, что доставка выбывает из очереди навсегда — а конкуренция за базу + как раз становится штатной. Отмена и занятость статус больше не меняют, + доставка остаётся `pending`; всё прочее по-прежнему `failed` и возвращается + только пересборкой. +- Остановка сервиса формулируется **инвариантом**, а не обещанием досчитать: + приём прекращается раньше воркера, и после остановки нет доставки, которая + числится разобранной, а записана наполовину. Свёртка идёт на контексте, + отвязанном от остановки. +- Наблюдаемость воркера: `WARN`, когда доставка ждала свёртки дольше периода + быстрого прохода, и одна строка `INFO` о размере задолженности при старте. + Метка считается на выборке прохода, а сам проход будит не только сигнал, но и + тик — иначе «работа есть, прогресса нет» неотличимо от пустого потока. + Счётчики в `/stats` — задача `stats-nablyudaemost`, здесь только метки в логе. +- Убирается второй, оставшийся источник молчаливого обрыва: общий `write_timeout` + (30 с) меньше `read_timeout` (5 мин), а он покрывает и чтение тела — то есть + медленная загрузка 64 МиБ обрывается независимо от свёртки. Длинный бюджет + даётся **маршруту приёма** собственным дедлайном ответа; общий таймаут и + конфиг не меняются, и прочие маршруты защиту не теряют. +- Миграция: частичный индекс по неразобранным доставкам — воркер спрашивает их + чаще, чем раз в минуту, а таблица растёт на ~300 строк в сутки. + +## Capabilities + +### New Capabilities + +- `ingest`: приём доставки как самостоятельное поведение — что делает ответ + `200` заслуженным, когда он отдаётся, кто и в каком порядке сворачивает + принятое, что происходит с несвёрнутым при остановке и рестарте. + +### Modified Capabilities + +- `parsing`: требование «Разбор не влияет на код ответа приёма» уточняется — + разбор идёт **после** ответа, поэтому исход становится виден не в ответе и не + сразу, а асинхронно, в `parse_status` и в логе. +- `storage`: требование «Учёт частично разобранной доставки» уточняется — отказ + обстоятельств (отмена, занятость базы) статуса не меняет вовсе, а прежняя + формулировка «ошибка ⇒ `failed`» этого не допускала. +- `reindex`: требование «Отчёт, оракул и исход команды» получает четвёртый класс + отказа — «работа отложена по обстоятельствам»: классы у пересборки и у фоновой + свёртки общие. + +## Impact + +- `internal/ingest` — теряет зависимость от `internal/fold`: `Accept` кладёт + тело, учитывает доставку и будит воркер. +- `internal/replay` — общий проигрыватель (свернуть доставку, классифицировать + исход) и фоновый воркер поверх него. +- `internal/store` — выборка неразобранных доставок в порядке журнала с + курсором, сентинел занятости базы; миграция `00006` с частичным индексом. +- `internal/fold` — отмена и занятость базы больше не переводят доставку в + `failed`. +- `cmd/healthlog/serve.go` — жизненный цикл воркера и согласованная остановка. +- `internal/httpapi` — сборка `ingest.Service` без свёртки; собственный дедлайн + ответа на маршруте приёма. `config.example.toml` — комментарий к + `write_timeout`. +- `docs/architecture.md`, `docs/database.md` — путь приёма и новый индекс. diff --git a/openspec/changes/archive/2026-08-02-otvet-i-svyortka/specs/ingest/spec.md b/openspec/changes/archive/2026-08-02-otvet-i-svyortka/specs/ingest/spec.md new file mode 100644 index 0000000..d50f9da --- /dev/null +++ b/openspec/changes/archive/2026-08-02-otvet-i-svyortka/specs/ingest/spec.md @@ -0,0 +1,294 @@ +## ADDED Requirements + +### Requirement: Ответ приёма отражает сохранность, а не разбор + +Приём SHALL отвечать `200` после того, как тело записано в сырой архив и +доставка учтена строкой `delivery`, и MUST NOT ждать свёртки. Время ответа +зависеть от ширины доставки MUST NOT. + +Порядок обязателен именно такой: тело на диск, затем строка учёта. Обратный дал +бы учтённую доставку без данных. Отказ на любом из двух шагов — отказ приёма, и +о нём отправителю говорится ошибкой: `400` для неразбираемой верхнеуровневой +формы, `413` для тела сверх предела, `500` для отказа записи. + +Учёт доставки SHALL вестись на контексте, не отменяемом обрывом соединения: +тело к этому моменту уже на диске, и отказ вставки из-за ушедшего клиента +оставил бы тело без записи в журнале. Проверка формы тела при этом остаётся +отменяемой — там отмена уместна. + +Причина разнесения измерена: свёртка 16 тысяч точек занимает 11 секунд, а +`WriteTimeout` в Go ставится до вызова обработчика и потому является общим +бюджетом на чтение тела, запись архива, учёт и свёртку. Исчерпав его, сервер +считает, что отдал `200`, клиент получает обрыв, а запись `accessLog` называет +статус `200` — то есть единственный канал наблюдаемости врёт. + +#### Scenario: Ответ отдан до свёртки + +- **WHEN** тело принято, записано в архив и учтено +- **THEN** ответ `200` отдан +- **AND** доставка в этот момент числится неразобранной + +#### Scenario: Ширина доставки не удлиняет ответ + +- **WHEN** приезжает доставка, свёртка которой занимает секунды +- **THEN** время ответа не включает время свёртки + +#### Scenario: Обрыв соединения не оставляет тело без учёта + +- **WHEN** соединение обрывается после того, как тело записано в архив +- **THEN** строка учёта доставки всё равно записывается + +### Requirement: Несвёрнутая доставка числится неразобранной + +Учтённая, но ещё не свёрнутая доставка SHALL числиться в статусе `pending`, и +этот статус SHALL быть единственным признаком того, что свёртка ещё должна +произойти. Отдельного, живущего только в памяти представления той же очереди +система иметь MUST NOT. + +Отсюда следуют три свойства, и они и есть смысл требования: + +- переполнять нечего — доставка ждёт свёртки в базе, а не в буфере, и «очередь + переполнена» невыразимо; +- падение процесса очереди не теряет — несвёрнутое остаётся `pending`; +- подбор `pending` не является отдельной операцией — он совпадает с обычной + работой свёртки. + +#### Scenario: Принятая доставка ждёт свёртки в базе + +- **WHEN** доставка учтена, но ещё не свёрнута +- **THEN** её `parse_status` равен `pending` + +#### Scenario: Оборванный процесс не теряет несвёрнутое + +- **WHEN** процесс прекращается до того, как свёртка доставки завершилась +- **THEN** доставка остаётся `pending` +- **AND** следующий старт сворачивает её + +### Requirement: Исход свёртки отражает доставку, а не обстоятельства + +Свёртка SHALL оставлять доставку в очереди — то есть **не менять** её статус, — +когда работа не сделана по причине, к самой доставке не относящейся: отмена +контекста и занятость базы после исчерпания повторов транзакции. + +Все прочие отказы разбора и записи точек (непонятое содержимое, невыводимый +слой, нечитаемое или слишком большое тело, исчерпанный дедлайн свёртки, паника +самой свёртки) SHALL давать `failed`: это свойства доставки, и повторять их +бесполезно. + +Отказы, случившиеся **до** чтения тела, и отказ самой записи исхода статуса не +меняют по другой причине — записать его нечем. Доставка остаётся `pending`, и +это честно: этим разбором её не досмотрели. + +Паника свёртки SHALL перехватываться на той же границе, что пишет исход разбора, +и превращаться в `failed`. Иначе она валит процесс целиком — фоновая горутина +ничем не обёрнута, — а перезапуск берёт ту же доставку первой, то есть дефект +одной доставки становится циклом перезапуска, при котором приём не работает +вовсе. До разнесения ответа и свёртки ту же панику ловил транспорт, и стоила она +одного ответа. + +Доставка в статусе `failed` в очередь свёртки возвращаться MUST NOT — её +подбирает только пересборка журнала. Это названная граница: обратное означало бы +бесконечный повтор заведомо безнадёжного. + +Без такого различения занятость базы — а свёртка теперь конкурирует с приёмом за +неё штатно — стирала бы доставку с полки молча, и вернуть её могла бы только +ручная операция с остановкой сервиса. + +#### Scenario: Занятая база не выводит доставку из очереди + +- **WHEN** свёртка не прошла из-за занятости базы +- **THEN** доставка остаётся `pending` +- **AND** следующий проход пробует её снова + +#### Scenario: Непонятое содержимое выводит доставку из очереди + +- **WHEN** свёртка не прошла из-за содержимого тела +- **THEN** доставка получает статус `failed` +- **AND** следующий проход её не выбирает + +### Requirement: Свёртку ведёт один фоновый воркер в порядке журнала + +Свёртку принятых доставок SHALL вести одна горутина, обрабатывающая доставки в +порядке журнала — `(received_at, id)`, как он определён capability пересборки. +Распараллеливать свёртку MUST NOT. + +Достижимая гарантия называется точно: в порядке `(received_at, id)` +сворачиваются все доставки, **видимые воркеру** на момент выборки. Доставка, +ставшая видимой позже курсора прохода, подбирается следующим проходом; +абсолютного порядка при конкурентных приёмах система не обещает. + +Последствие этого предела называется вслух: доставка без плотных метрик, +свёрнутая раньше своей предшественницы, слоя не выведет и получит `failed` — то +есть её точки в витрину не попадут до пересборки. Живое состояние в этом случае +расходится с тем, что даёт `healthlog reindex`. Окно узкое (обе доставки должны +приниматься одновременно, и только у автоматизации без плотных метрик), и +изменение его сужает, а не открывает: прежде свёртка шла в порядке завершения +обработчиков. Устранение предела — отдельный вопрос, оно требует удерживать +порядок на самом приёме. + +Воркер SHALL продвигаться по неразобранным доставкам строго возрастающим +курсором в пределах одного прохода. Курсор обязателен для завершимости: +доставка, у которой не удалось записать даже исход разбора, остаётся `pending`, +и проход без курсора выбирал бы её бесконечно. + +Приём SHALL будить воркер после того, как доставка учтена. Потеря сигнала +отказом быть MUST NOT: доставка от этого не перестаёт числиться `pending`. +Помимо сигнала воркер SHALL просыпаться периодически — иначе доставка, +оставшаяся `pending` по причине выше, ждала бы следующей доставки, а ночью +телефон молчит часами. + +Отказ отдельного прохода воркер SHALL переживать: отказ выборки пишется `ERROR` +и прекращает проход, но не цикл. Отмена работы снаружи отказом при этом +считаться MUST NOT — штатная остановка не должна писать `ERROR`. Воркер, умерший +от временного отказа базы, остановил бы свёртку до конца жизни процесса, пока +приём продолжал бы отвечать `200`. + +#### Scenario: Видимые доставки сворачиваются в порядке журнала + +- **GIVEN** несколько доставок числятся `pending` до начала прохода +- **WHEN** воркер делает проход +- **THEN** он сворачивает их в порядке `(received_at, id)` +- **AND** доставка без плотных метрик наследует слой предшествующей ей по этому + порядку доставки той же автоматизации, а не соседа по времени вставки + +#### Scenario: Доставка, не записавшая исход, не зацикливает проход + +- **WHEN** свёртка доставки не смогла записать исход разбора и оставила её + `pending` +- **THEN** проход воркера завершается, а не выбирает её повторно + +#### Scenario: Доставка без входящего потока всё равно подбирается + +- **GIVEN** доставка осталась `pending`, и новых доставок не приезжает +- **WHEN** наступает очередное периодическое пробуждение +- **THEN** воркер пробует свернуть её снова + +### Requirement: Подбор неразобранного при старте — та же операция + +При старте система SHALL сворачивать доставки, числящиеся неразобранными, тем +же путём, каким сворачивает вновь принятые: отдельного кода подбора +существовать MUST NOT. + +Порядок журнала при подборе SHALL соблюдаться так же, как при обычной работе — +подбор это тот же проход воркера, а не особый режим. + +Классификация исхода свёртки (свёрнуто; слой не выведен; содержимое не +разобрано; прочий отказ; частичный разбор; несравнимые наборы полей) SHALL быть +общей с пересборкой журнала: второй классификатор разошёлся бы с первым молча. +Классифицироваться SHALL только ошибка свёртки; решение «работу прекратили +снаружи» MUST NOT приниматься классификатором — у пересборки и у воркера +контекст свёртки означает разное, и общая ветка отмены дала бы одному из них +противоположный смысл. + +Счётчики частичного разбора и несравнимых наборов SHALL читаться только у +успешной свёртки — у отказавшей они заполнены частично, и `partial` занижался бы, +а по нему принимается решение о судьбе тела. + +#### Scenario: Доставки, оставшиеся неразобранными, подбираются при старте + +- **GIVEN** в учёте есть доставки со статусом `pending` +- **WHEN** сервис стартует +- **THEN** они сворачиваются в порядке `(received_at, id)` + +#### Scenario: Размер задолженности назван при старте + +- **WHEN** сервис стартует и неразобранные доставки есть +- **THEN** их число попадает в лог одной записью уровня `INFO` + +### Requirement: Остановка не оставляет доставку в неопределённом состоянии + +Остановка сервиса SHALL сперва прекращать приём, затем останавливать воркер. +Обратный порядок оставил бы доставки, принятые после остановки воркера, никого +не разбудившими. + +Инвариант остановки: после неё не существует доставки, которая числится +разобранной, а записана частично; всё несвёрнутое остаётся `pending`. Обещать, +что текущая доставка непременно досворачивается, система MUST NOT — бюджет +остановки меньше бюджета свёртки, и такое обещание исполнялось бы не всегда. + +Свёртка SHALL идти на контексте, не отменяемом остановкой, а отмена SHALL +проверяться **между** доставками. Причина названа: свёртка помечает доставку +`failed` на ошибке, а `failed` воркер не подбирает — то есть отмена снаружи +превратилась бы в свойство доставки. + +Исчерпание бюджета остановки отказом сервиса считаться MUST NOT: и штатное +завершение воркера, и его прерывание оставляют состояние определённым. Факт +SHALL называться предупреждением, а не ошибкой старта. + +#### Scenario: Остановка не оставляет половины + +- **WHEN** сервис останавливается во время свёртки доставки +- **THEN** доставка либо свёрнута целиком, либо числится `pending` +- **AND** частично записанных объектов от неё не остаётся + +#### Scenario: Приём прекращается раньше воркера + +- **WHEN** сервис останавливается +- **THEN** приём перестаёт принимать раньше, чем останавливается воркер + +#### Scenario: Не уложились в бюджет остановки + +- **WHEN** воркер не успевает выйти в отведённый бюджет +- **THEN** факт попадает в лог предупреждением +- **AND** команда не сообщает об ошибке + +### Requirement: Отставание воркера видно в логе + +Система SHALL писать `WARN`, когда доставка ждала свёртки дольше периода +быстрого прохода синхронизации (пять минут): дольше этого срока очередь растёт, +а не рассасывается. Ожидание считается от `received_at` до начала свёртки. + +Записей SHALL быть **одна на проход**, а не одна на доставку: задолженность в +сотню тел давала бы сотню одинаковых предупреждений каждую минуту, и уровень, по +которому вмешиваются, перестал бы что-либо значить. Строка называет число +задержанных и худшее ожидание с идентификатором доставки. + +Метка SHALL вычисляться на выборке прохода, а не только по факту успешной +свёртки: состояние «работа есть, прогресса нет» обязано быть отличимо от +здорового пустого потока, иначе наблюдаемость молчит ровно там, где нужна. + +Задолженность, накопленную **до** старта, метка задержки помечать MUST NOT: она +названа отдельной записью `INFO` о размере задолженности, а сотня одинаковых +`WARN` при первом же старте обесценила бы уровень. Метка включается после того, +как первый проход воркера завершился. + +Записи воркера значений точек и имён устройств содержать MUST NOT — как и любые +записи свёртки. + +#### Scenario: Отставший воркер называет задержку + +- **GIVEN** первый проход воркера завершён +- **WHEN** доставки дожидаются свёртки дольше пяти минут +- **THEN** в лог идёт одна запись `WARN` на проход с числом задержанных и + худшим ожиданием + +#### Scenario: Задолженность при старте не даёт шквала предупреждений + +- **GIVEN** неразобранными числятся доставки, накопленные до старта +- **WHEN** воркер сворачивает их первым проходом +- **THEN** записей `WARN` о задержке по ним нет + +### Requirement: Длинный бюджет ответа принадлежит маршруту приёма + +Обработчик приёма SHALL выставлять собственный дедлайн записи ответа перед +чтением тела, и этот дедлайн SHALL покрывать чтение тела вместе с отправкой +ответа. Полагаться на общий `write_timeout` сервера система MUST NOT: он +ставится до вызова обработчика и потому обрывает загрузку, идущую дольше него, — +делая `read_timeout` обещанием, которого сервер не исполняет. + +Общий `write_timeout` сервера при этом расширяться MUST NOT: длинный бюджет +нужен одному маршруту, а остальные теряли бы защиту от застрявшей записи ответа. + +Транспорт, не поддерживающий установки дедлайна, отказом приёма считаться MUST +NOT: факт уходит в `DEBUG`, приём продолжается. + +#### Scenario: Медленная загрузка тела не обрывается + +- **WHEN** тело приезжает дольше, чем общий `write_timeout` сервера, но + укладывается в `read_timeout` +- **THEN** ответ доходит до отправителя + +#### Scenario: Прочие маршруты бюджета не наследуют + +- **WHEN** запрос идёт не на приём +- **THEN** его бюджет записи ответа остаётся общим `write_timeout` diff --git a/openspec/changes/archive/2026-08-02-otvet-i-svyortka/specs/parsing/spec.md b/openspec/changes/archive/2026-08-02-otvet-i-svyortka/specs/parsing/spec.md new file mode 100644 index 0000000..0ba9750 --- /dev/null +++ b/openspec/changes/archive/2026-08-02-otvet-i-svyortka/specs/parsing/spec.md @@ -0,0 +1,17 @@ +## MODIFIED Requirements + +### Requirement: Разбор не влияет на код ответа приёма + +Система MUST сохранять правило «сохранили — значит приняли»: исход разбора не +меняет код ответа на доставку. + +Разбор идёт **после** ответа, поэтому исход виден не в ответе и не в момент +ответа, а асинхронно — в `delivery.parse_status` и в записи лога. Когда именно +отдаётся ответ и кто сворачивает принятое, определяет capability `ingest`; +здесь нормируется только то, что от разбора код ответа не зависит. + +#### Scenario: Содержимое не разобралось + +- **WHEN** тело сохранено в архив, но разбор его содержимого не удался +- **THEN** ответ на приём остаётся `200` +- **AND** исход виден в `delivery.parse_status` и в записи лога diff --git a/openspec/changes/archive/2026-08-02-otvet-i-svyortka/specs/reindex/spec.md b/openspec/changes/archive/2026-08-02-otvet-i-svyortka/specs/reindex/spec.md new file mode 100644 index 0000000..0f5e711 --- /dev/null +++ b/openspec/changes/archive/2026-08-02-otvet-i-svyortka/specs/reindex/spec.md @@ -0,0 +1,115 @@ +## MODIFIED Requirements + +### Requirement: Отчёт, оракул и исход команды + +Система SHALL завершать пересборку отчётом, который несёт счётчики +(проиграно, свёрнуто, отказов по классам, тел без учётной записи, строк без +тела, пропущенных файлов, повторов, объектов **до и после**) и **два +отпечатка** — рабочей витрины и пересобранной, — с прямым ответом, совпали они +или нет. + +Отказы SHALL считаться **по классам**: слой не выводится, содержимое не +разбирается, работа отложена по обстоятельствам, всё прочее. Невыведенный слой +есть в каждом журнале и штатен; общий счётчик отправлял бы человека искать +дефект там, где его нет. Отдельно называть человеку следует только нештатные +отказы. + +Отложенная доставка (занятость базы, отмена работы снаружи) SHALL считаться +нештатной **для пересборки**, хотя для фоновой свёртки она штатна: пересборка +идёт в свежий файл при единственном писателе, и такая доставка в собранной +витрине просто отсутствует — вместе с теми, кто наследовал от неё слой. Классы +при этом общие с фоновой свёрткой: второй классификатор разошёлся бы с первым +молча. + +Число объектов «было и стало» SHALL печататься рядом с отпечатками: отпечатки +отвечают «да/нет», а решение о подмене необратимо, и по «да/нет» нельзя +судить о **направлении** расхождения. Именно пара чисел — 1737 против 1742 — +поймала прошлый дефект наследования слоя. + +Отпечаток здесь оракул, а не украшение: число объектов к правилу разрешения +столкновений нечувствительно — на координате всегда ровно одна точка, и правило +выбирает, какая, а не сколько. «Объектов столько же» совпало бы и при заведомо +сломанном правиле. + +Отпечаток рабочей витрины SHALL сниматься **до** начала проигрывания, а число +доставок в рабочей базе — до и после. Ненулевая разница SHALL называться в +отчёте, и при ней процедура подмены печататься MUST NOT: доставки, приехавшие за +время прогона, есть в рабочей базе и в архиве, но не в собранном файле, и +подмена стёрла бы их учёт вместе с заголовками, которых в архиве нет. + +Величины, которые не снимались, отчёт печатать MUST NOT. При отмене отпечаток +пересобранной витрины и число доставок после прогона не измеряются вовсе — +печатать их сравнение значило бы выдать неизмеренное за измеренное, причём в +единственном оракуле задачи. Ожидаемые классы расхождения (новые доставки за время прогона, +непереносимый признак запечатанного часа, исправленный разбор) SHALL называться +отдельно от самого факта расхождения. + +**Исход команды.** Расхождение отпечатков отказом быть MUST NOT: после +исправления разбора оно ожидаемо и есть сам смысл пересборки. Отказ отдельной +доставки отказом команды тоже MUST NOT быть: доставка, слой которой не +выводится, — штатный исход. + +Отказом команды SHALL быть: пустой журнал, отсутствие хотя бы одной свёрнутой +доставки, отмена и любая ошибка окружения. Пустая витрина совпадает по +отпечатку с пустой витриной, поэтому прогон по пустому журналу выглядит +идеальной сходимостью — а все умолчания подыгрывают такому запуску: конфига +может не быть вовсе, и тогда пути указывают в рабочий каталог процесса. Человек, +выполнивший напечатанную процедуру, заменил бы витрину пустой. + +Отчёт значений точек, имён метрик, имён устройств и содержимого тел содержать +MUST NOT: отпечаток берёт содержимое хешем. Ограничение относится к отчёту в +стандартном выводе; лог свёртки живёт по правилам спеки хранения, где координаты +столкновения (метрика, слой, час) разрешены явно. + +Отчёт идёт в стандартный вывод человеческим текстом. Прогресс длинного прогона +SHALL идти в поток ошибок, а не смешиваться с отчётом: прогон на полном архиве +молчит минутами, и зависший неотличим от идущего. + +#### Scenario: Отчёт сравнивает отпечатки + +- **WHEN** пересборка завершилась +- **THEN** отчёт содержит отпечаток рабочей витрины и отпечаток пересобранной +- **AND** прямо называет, совпали они или нет +- **AND** называет, изменилось ли число доставок в рабочей базе за время прогона + +#### Scenario: Расхождение отпечатков не является отказом + +- **WHEN** отпечаток пересобранной витрины отличается от рабочей, и при этом + хотя бы одна доставка свёрнута +- **THEN** команда завершается успешно, а расхождение названо в отчёте + +#### Scenario: Пустой журнал — отказ, а не идеальная сходимость + +- **WHEN** в архиве не нашлось ни одного тела +- **THEN** команда завершается ненулевым кодом +- **AND** процедуры подмены не печатает + +#### Scenario: Ни одна доставка не свернулась + +- **WHEN** журнал непуст, но свернуть не удалось ни одной доставки +- **THEN** команда завершается ненулевым кодом +- **AND** процедуры подмены не печатает + +#### Scenario: Приезд доставок за время прогона отменяет подмену + +- **WHEN** число доставок в рабочей базе за время прогона изменилось +- **THEN** отчёт называет разницу +- **AND** процедуры подмены не печатает + +#### Scenario: Отчёт после отмены не сравнивает неизмеренного + +- **WHEN** прогон отменён +- **THEN** отчёт не содержит ни ответа о совпадении отпечатков, ни разницы + числа доставок + +#### Scenario: Рабочей базы нет вовсе + +- **WHEN** файла рабочей базы не существует +- **THEN** пересборка идёт по одним подобранным телам +- **AND** отчёт называет, что сверять не с чем и что заголовки доставок не + восстанавливаются + +#### Scenario: Отчёт не раскрывает данных о здоровье + +- **WHEN** отчёт напечатан +- **THEN** он не содержит ни значений точек, ни имён метрик, ни имён устройств diff --git a/openspec/changes/archive/2026-08-02-otvet-i-svyortka/specs/storage/spec.md b/openspec/changes/archive/2026-08-02-otvet-i-svyortka/specs/storage/spec.md new file mode 100644 index 0000000..2a45b7e --- /dev/null +++ b/openspec/changes/archive/2026-08-02-otvet-i-svyortka/specs/storage/spec.md @@ -0,0 +1,94 @@ +## MODIFIED Requirements + +### Requirement: Учёт частично разобранной доставки + +Система SHALL отличать доставку, разобранную целиком, от доставки, в теле +которой остались непокрытые разбором секции. Доставка с непустым списком +непокрытых ключей MUST получать статус `partial`, а не `parsed`. + +Статусы разбора: + +``` +pending этим разбором ещё не смотрели — или смотрели, но работа не сделана + по обстоятельствам (см. ниже) +parsed разобрано всё, что в теле было +partial разобрано покрытое; в теле остались непокрытые секции +failed разобрать не удалось, точек нет +``` + +Источник истины — список непокрытых ключей; статус производен от него и от +факта отказа, в порядке `failed` → `partial` → `parsed`. Приоритет назван явно, +чтобы читатели (ретеншен, статистика) спрашивали статус, а не сравнивали список +со строкой. + +**Отказ обстоятельств статуса не меняет вовсе.** Отмена работы снаружи и +занятость базы дольше повторов транзакции означают «не сделано», а не «не +выходит»: доставка остаётся `pending` и будет свёрнута снова. Правило появилось +не из аккуратности — фоновая свёртка `failed` не подбирает никогда, и без этого +различения занятость базы (а с фоновой свёрткой конкуренция за неё штатная) +выводила бы доставку из очереди навсегда. Различение живёт **в одном месте**: +тот, кто пишет исход, и тот, кто классифицирует его в счётчики, спрашивают один +предикат. + +Дедлайн самой свёртки к обстоятельствам MUST NOT относиться: доставка, не +уложившаяся в бюджет, не уложится в него и в следующий раз, а бесконечный повтор +заведомо безнадёжного — это очередь, которая не движется. + +Отказы, случившиеся **до** чтения тела (учётной записи нет, соседний запрос не +прошёл), и отказ самой записи исхода статуса не меняют по другой причине — +записать его нечем. Доставка остаётся `pending`, что честно: этим разбором её не +досмотрели. + +Список непокрытых ключей SHALL сохраняться рядом с доставкой — именами ключей, +без содержимого секций. Он же ответ на вопрос «что останется потерянным, если +тело удалить»: для `stateOfMind` доставки HAE единственный источник, в экспорте +Apple его нет (находка 46). Поэтому список MUST сохраняться и при отказе +разбора, если разбор успел его собрать: `failed` с непустым списком — законное +состояние. + +Запись списка MUST замещать прежнее значение целиком, включая замещение пустым: +иначе доставка, все секции которой стали покрытыми, осталась бы `partial` +навсегда. + +Список — снимок покрытия **на момент свёртки**. Задача, которая начинает +разбирать секцию, тем же изменением SHALL переводить `partial`-строки с этим +ключом в `pending`; ретеншену позволено смотреть на `partial` только при +соблюдении этого правила. + +Статусы, поставленные разбором, который частичного исхода не различал, доверия +не заслуживают: под `parsed` у них лежат и полностью разобранные доставки, и +доставки без метрик вовсе. Такие строки MUST переводиться в `pending` — «этим +разбором ещё не смотрели». Число точек у них до пересвёртки остаётся прежним: оно +производно от объектов витрины, которые никуда не делись. + +#### Scenario: Доставка с непокрытой секцией отмечается частичной + +- **WHEN** разбор доставки вернул непустой список непокрытых ключей +- **THEN** `parse_status` доставки равен `partial` +- **AND** список непокрытых ключей сохранён вместе с доставкой +- **AND** точки покрытой секции сохранены как обычно + +#### Scenario: Доставка без непокрытых секций остаётся `parsed` + +- **WHEN** разбор доставки не дал непокрытых ключей +- **THEN** `parse_status` равен `parsed` +- **AND** сохранённый список непокрытых ключей пуст + +#### Scenario: Отказ разбора сильнее частичности + +- **WHEN** разбор доставки завершился ошибкой в самом разборе или в записи + точек +- **THEN** `parse_status` равен `failed` +- **AND** список непокрытых ключей сохранён, если разбор успел его собрать + +#### Scenario: Занятая база доставку из очереди не выводит + +- **WHEN** разбор не состоялся из-за занятости базы или отмены работы снаружи +- **THEN** `parse_status` остаётся `pending` + +#### Scenario: Пересвёртка после того, как секция стала покрытой + +- **WHEN** доставка со статусом `partial` сворачивается повторно разбором, + который эту секцию покрывает +- **THEN** `parse_status` становится `parsed` +- **AND** сохранённый список непокрытых ключей пуст diff --git a/openspec/changes/archive/2026-08-02-otvet-i-svyortka/tasks.md b/openspec/changes/archive/2026-08-02-otvet-i-svyortka/tasks.md new file mode 100644 index 0000000..baafdf1 --- /dev/null +++ b/openspec/changes/archive/2026-08-02-otvet-i-svyortka/tasks.md @@ -0,0 +1,180 @@ +## 1. Опоры в хранилище + +- [x] 1.1 Миграция `00006`: частичный индекс + `delivery (received_at, id) WHERE parse_status = 'pending'`. Комментарий + объясняет, почему частичный, а не по `parse_status`: в установившемся + режиме в нём ноль–одна строка, полный хранил бы всю таблицу ради выборки + из одной. +- [x] 1.2 `store.PendingDeliveries(ctx, after, limit)` — неразобранные доставки + в порядке `(received_at, id)`, строго после курсора; отдаёт идентификатор + и `received_at`. Сравнение курсора — **row-value** `(received_at, id) > + (?, ?)`: развёрнутая форма через `OR` даёт `SCAN` вместо `SEARCH` + (проверено `EXPLAIN QUERY PLAN`). Нулевой курсор — нулевое время и пустой + идентификатор, без ветки «первая страница». +- [x] 1.3 `store.CountPendingDeliveries(ctx)` — размер задолженности для + строки `INFO` при старте. +- [x] 1.4 `store.ErrBusy` — доменный сентинел занятости базы; `inTx` оборачивает + им исчерпание повторов, чтобы вызывающий не разбирал коды драйвера. +- [x] 1.5 Обновить `docs/database.md`: новый индекс в перечне индексов + `delivery`. + +## 2. Исход свёртки отражает доставку, а не обстоятельства + +- [x] 2.1 `fold.fail`: отмена контекста и `store.ErrBusy` статус **не меняют** — + доставка остаётся `pending`; всё прочее по-прежнему `failed`. Уровень лога + по адресату: занятость и отмена — `WARN` (пройдёт само), остальное как + сейчас. +- [x] 2.2 Тест: свёртка на занятой базе оставляет доставку `pending`; свёртка + непонятого содержимого оставляет `failed`. + +## 3. Общий проигрыватель — `internal/replay` + +- [x] 3.1 `replay.Player.Play(ctx, deliveryID) (Outcome, error)` — свернуть одну + доставку и вернуть её исход **значением**: ровно один классовый счётчик + равен единице, плюс `partial`/`incomparable` у успешной свёртки. + Классифицируется **только ошибка**; на контекст `Player` не смотрит — + решение «нас остановили» принимает цикл. +- [x] 3.2 `replay.Outcome` + `(*Outcome).Add(other)`; `replay.Report` встраивает + `Outcome`, чтобы имена исходов не раздвоились. Существующие вызывающие + (`cmd/healthlog/reindex*.go`, тесты) читают поля по-прежнему. +- [x] 3.3 `replay.Run` переводится на `Player`, свою ветку отмены оставляет + себе. Поведение и отчёт не меняются — проверяется существующими тестами + пакета. +- [x] 3.4 Табличный тест классификатора: ошибка → ожидаемый `Outcome`. + +## 4. Воркер свёртки + +- [x] 4.1 `replay.Worker` с синхронным швом: `Pass(ctx) (Outcome, error)` — один + проход, без каналов; `Run(ctx)` — тонкий `select` поверх него по сигналу, + тику и отмене; `Notify()` — неблокирующая отправка в канал ёмкостью 1; + `done` закрывается в `defer` внутри `Run`. +- [x] 4.2 `Pass`: выбирать `pending` порциями по курсору, сворачивать через + `Player`, курсор строго возрастает; отмена проверяется **между** + доставками; проход конечен даже когда доставка осталась `pending`. +- [x] 4.3 Свёртка внутри прохода идёт на `context.WithoutCancel` от контекста + прохода плюс собственный дедлайн (`foldTimeout`, переезжает из + `internal/ingest`). +- [x] 4.4 Отказ выборки — `ERROR` и выход из `Pass`, но не из `Run`: воркер + переживает временный отказ базы. +- [x] 4.5 Наблюдаемость: `INFO` с размером задолженности перед первым проходом; + `WARN` «доставка ждала свёртки дольше пяти минут» — считается на выборке + прохода, включается после того, как первый проход завершился. Ни значений + точек, ни имён устройств. + +## 5. Приём без свёртки + +- [x] 5.1 `ingest.Service` теряет зависимость от `fold`: `Accept` пишет тело, + учитывает доставку, логирует принятие и будит воркер. `foldTimeout` и + вызов свёртки уходят. +- [x] 5.2 Учёт доставки — на `context.WithoutCancel` с коротким дедлайном: + обрыв соединения после записи тела не должен оставлять тело без строки в + журнале. Проверка формы тела остаётся на исходном контексте. +- [x] 5.3 Сигнал воркеру — параметр конструктора функцией; `nil` приводится к + пустой функции **один раз в конструкторе**, как это уже делают `fold.New` + и `replay.Run` со своими нулевыми значениями. Проверок на `nil` в местах + вызова быть не должно. +- [x] 5.4 `internal/httpapi` собирается без `fold`; транспорт по-прежнему не + логирует исход и переводит только ошибки приёма. + +## 6. Жизненный цикл в `serve.go` + +- [x] 6.1 Собрать воркер, запустить `Run` в горутине, передать его `Notify` в + `ingest`, разбудить при старте — этим и делается подбор `pending`. +- [x] 6.2 Остановка: `srv.Shutdown` → отмена контекста воркера → ожидание + `done` в остатке того же бюджета `shutdownTimeout` (30 с, как + `stop_grace_period`). +- [x] 6.3 Контекстная ошибка `Shutdown` — `WARN`, а не отказ команды: stdlib + возвращает `DeadlineExceeded` штатно, а `main` печатает на любой ошибке + `fatal startup` и выходит с кодом 1. +- [x] 6.4 База не закрывается, пока воркер не вышел: `Close` под живой + транзакцией свёртки дал бы `ERROR` по доставке, с которой всё в порядке. + Не уложились — оставляем закрытие процессу и называем это `WARN`. + +## 7. Бюджет ответа маршрута приёма + +- [x] 7.1 `handleIngest` перед чтением тела ставит дедлайн записи ответа через + `http.NewResponseController(w).SetWriteDeadline` на `read_timeout + + write_timeout`. `http.ErrNotSupported` — `DEBUG` и продолжение, а не + отказ приёма. +- [x] 7.2 Общий `write_timeout` и его умолчание не меняются; комментарий в + `config.example.toml` объясняет, что он покрывает и чтение тела и потому + приём держит собственный бюджет. + +## 8. Проверки + +Приёмочные критерии — рубрика ревью дизайна, перенесена сюда целиком. + +- [x] 8.1 **Завершимость прохода.** Доставка, оставшаяся `pending`, не + выбирается проходом повторно; `Pass` возвращает управление. +- [x] 8.2 **Атомарность единицы работы.** Прерванная свёртка оставляет доставку + `pending` и не оставляет частично записанных объектов. +- [x] 8.3 **Идемпотентность повтора.** Двойная свёртка той же доставки даёт тот + же отпечаток витрины. +- [x] 8.4 **Сигнал не теряет работу.** Доставка, чей сигнал потерян, всё равно + подбирается — тиком или следующим проходом. +- [x] 8.5 **Тотальный порядок.** Доставки с одинаковым `received_at` + сворачиваются в порядке `id` при любом размере порции; порядок проверяется + наблюдаемым следствием — наследованием слоя. +- [x] 8.6 **Остановка.** Приём прекращается раньше воркера; после остановки нет + доставки, числящейся разобранной и записанной наполовину; исчерпание + бюджета не даёт ненулевого кода возврата. +- [x] 8.7 **Транзиентный отказ ≠ отказ доставки.** Занятость базы оставляет + `pending`, содержимое даёт `failed` (задача 2.2). +- [x] 8.8 **Отставание наблюдаемо и при отсутствии прогресса.** Метка не + срабатывает на задолженности первого прохода и срабатывает после него; + считается на выборке, а не по факту свёртки. +- [x] 8.9 **Одна классификация на оба входа.** Табличный тест `Player` (задача + 3.4) плюс зелёные существующие тесты `replay`. +- [x] 8.10 **Тестируемость без сна.** Ни один тест воркера не ждёт по часам: + проверки идут через `Pass`, тест на `Run` — один, «отмена завершает цикл». +- [x] 8.11 **Приём не платит за воркер.** После `Accept` доставка числится + `pending`, обработчик не ждёт; приём с неработающим воркером отвечает + `200`. +- [x] 8.12 **Данные о здоровье не в логе.** Записи воркера несут только + идентификатор доставки, счётчики и длительности. +- [x] 8.13 `task gate` зелёный; `task verify:archive` даёт то же состояние. + +## 9. Документация + +- [x] 9.1 `docs/architecture.md`, раздел «Приём»: ответ отдаётся после архивации + и учёта — это **контракт**, а не деталь реализации; очередь — таблица, а + не память; порядок журнала и остановка; классификация «отказ доставки» + против «отказ обстоятельств»; бюджет ответа маршрута приёма; отвергнутые + варианты с причинами. +- [x] 9.2 Строка в задачу беклога `stats-nablyudaemost`: длина `pending`, + возраст самой старой неразобранной доставки и то, что `/healthz` их не + отражает. + +## 10. Правки по ревью кода (профиль `deep`) + +- [x] 10.1 `store.CreateDelivery` — через `inTx` с повторами: одиночная вставка + пересиживала только `busy_timeout`, и приём отвечал `500` по доставке, + тело которой уже на диске (измерено: окно занятости 6.55 с при широкой + свёртке против пяти секунд ожидания). +- [x] 10.2 Паника свёртки перехватывается в `fold.Fold` — у той же границы, что + пишет исход разбора: в фоновой горутине она валила процесс, а + `restart: unless-stopped` превращал дефект одной доставки в цикл + перезапуска. Писатель `parse_status` остался единственным. +- [x] 10.3 Флаг «первый проход завершён» снимается только у прохода, дошедшего + до пустой выборки: взведённый на отказе базы, он включал метку задержки + после прохода, который ничего не свернул. +- [x] 10.4 Метка отставания — одна запись на проход (число задержанных и худшее + ожидание), а не запись на доставку: задолженность в сотню тел давала бы + сотню одинаковых `WARN` каждую минуту. +- [x] 10.5 Отмена не пишется `ERROR`-ом в цикле воркера; ветка отказа `Serve` в + `serve.go` останавливает воркер прежде, чем закрыть базу. +- [x] 10.6 Значения заголовков обрезаются перед логом: `automation-name` длиной + 600 КБ выдавливал из ротации всю недавнюю историю (измерено). +- [x] 10.7 Запасной `store.Now()` для метки приёма убран: он заводил второй + источник времени вопреки соседнему комментарию и был недостижим. +- [x] 10.8 `classify` неэкспортируема: вторая публичная дверь возвращала + `Outcome` без `Partial`, то есть молча занижала счётчик, по которому + решается судьба тела. +- [x] 10.9 Оракул правила «занятость — обстоятельство»: `task verify:busy` — + свёртка под удерживаемой блокировкой. В гейт не входит (25 секунд), но + мутацию «убрать ветку `Transient`» убивает. +- [x] 10.10 Дельты `storage` и `reindex`: «отказ ⇒ `failed`» сужено до отказов + разбора, добавлен класс «отложено». +- [x] 10.11 Остаточный предел порядка при конкурентных приёмах назван в спеке и + в `docs/architecture.md`, вынут блокером + (`docs/backlog/poryadok-zhurnala-na-priyome.md`). diff --git a/openspec/specs/ingest/spec.md b/openspec/specs/ingest/spec.md new file mode 100644 index 0000000..a2147ea --- /dev/null +++ b/openspec/specs/ingest/spec.md @@ -0,0 +1,304 @@ +# ingest Specification + +## Purpose + +Приём доставки от Health Auto Export как самостоятельное поведение: что делает +ответ `200` заслуженным, когда он отдаётся, кто и в каком порядке сворачивает +принятое, что происходит с несвёрнутым при остановке и рестарте. Цена ошибки +здесь наивысшая в проекте — доставка, не попавшая в архив и в журнал, не +восстанавливается: телефон её не перешлёт. + +## Requirements + +### Requirement: Ответ приёма отражает сохранность, а не разбор + +Приём SHALL отвечать `200` после того, как тело записано в сырой архив и +доставка учтена строкой `delivery`, и MUST NOT ждать свёртки. Время ответа +зависеть от ширины доставки MUST NOT. + +Порядок обязателен именно такой: тело на диск, затем строка учёта. Обратный дал +бы учтённую доставку без данных. Отказ на любом из двух шагов — отказ приёма, и +о нём отправителю говорится ошибкой: `400` для неразбираемой верхнеуровневой +формы, `413` для тела сверх предела, `500` для отказа записи. + +Учёт доставки SHALL вестись на контексте, не отменяемом обрывом соединения: +тело к этому моменту уже на диске, и отказ вставки из-за ушедшего клиента +оставил бы тело без записи в журнале. Проверка формы тела при этом остаётся +отменяемой — там отмена уместна. + +Причина разнесения измерена: свёртка 16 тысяч точек занимает 11 секунд, а +`WriteTimeout` в Go ставится до вызова обработчика и потому является общим +бюджетом на чтение тела, запись архива, учёт и свёртку. Исчерпав его, сервер +считает, что отдал `200`, клиент получает обрыв, а запись `accessLog` называет +статус `200` — то есть единственный канал наблюдаемости врёт. + +#### Scenario: Ответ отдан до свёртки + +- **WHEN** тело принято, записано в архив и учтено +- **THEN** ответ `200` отдан +- **AND** доставка в этот момент числится неразобранной + +#### Scenario: Ширина доставки не удлиняет ответ + +- **WHEN** приезжает доставка, свёртка которой занимает секунды +- **THEN** время ответа не включает время свёртки + +#### Scenario: Обрыв соединения не оставляет тело без учёта + +- **WHEN** соединение обрывается после того, как тело записано в архив +- **THEN** строка учёта доставки всё равно записывается + +### Requirement: Несвёрнутая доставка числится неразобранной + +Учтённая, но ещё не свёрнутая доставка SHALL числиться в статусе `pending`, и +этот статус SHALL быть единственным признаком того, что свёртка ещё должна +произойти. Отдельного, живущего только в памяти представления той же очереди +система иметь MUST NOT. + +Отсюда следуют три свойства, и они и есть смысл требования: + +- переполнять нечего — доставка ждёт свёртки в базе, а не в буфере, и «очередь + переполнена» невыразимо; +- падение процесса очереди не теряет — несвёрнутое остаётся `pending`; +- подбор `pending` не является отдельной операцией — он совпадает с обычной + работой свёртки. + +#### Scenario: Принятая доставка ждёт свёртки в базе + +- **WHEN** доставка учтена, но ещё не свёрнута +- **THEN** её `parse_status` равен `pending` + +#### Scenario: Оборванный процесс не теряет несвёрнутое + +- **WHEN** процесс прекращается до того, как свёртка доставки завершилась +- **THEN** доставка остаётся `pending` +- **AND** следующий старт сворачивает её + +### Requirement: Исход свёртки отражает доставку, а не обстоятельства + +Свёртка SHALL оставлять доставку в очереди — то есть **не менять** её статус, — +когда работа не сделана по причине, к самой доставке не относящейся: отмена +контекста и занятость базы после исчерпания повторов транзакции. + +Все прочие отказы разбора и записи точек (непонятое содержимое, невыводимый +слой, нечитаемое или слишком большое тело, исчерпанный дедлайн свёртки, паника +самой свёртки) SHALL давать `failed`: это свойства доставки, и повторять их +бесполезно. + +Отказы, случившиеся **до** чтения тела, и отказ самой записи исхода статуса не +меняют по другой причине — записать его нечем. Доставка остаётся `pending`, и +это честно: этим разбором её не досмотрели. + +Паника свёртки SHALL перехватываться на той же границе, что пишет исход разбора, +и превращаться в `failed`. Иначе она валит процесс целиком — фоновая горутина +ничем не обёрнута, — а перезапуск берёт ту же доставку первой, то есть дефект +одной доставки становится циклом перезапуска, при котором приём не работает +вовсе. До разнесения ответа и свёртки ту же панику ловил транспорт, и стоила она +одного ответа. + +Доставка в статусе `failed` в очередь свёртки возвращаться MUST NOT — её +подбирает только пересборка журнала. Это названная граница: обратное означало бы +бесконечный повтор заведомо безнадёжного. + +Без такого различения занятость базы — а свёртка теперь конкурирует с приёмом за +неё штатно — стирала бы доставку с полки молча, и вернуть её могла бы только +ручная операция с остановкой сервиса. + +#### Scenario: Занятая база не выводит доставку из очереди + +- **WHEN** свёртка не прошла из-за занятости базы +- **THEN** доставка остаётся `pending` +- **AND** следующий проход пробует её снова + +#### Scenario: Непонятое содержимое выводит доставку из очереди + +- **WHEN** свёртка не прошла из-за содержимого тела +- **THEN** доставка получает статус `failed` +- **AND** следующий проход её не выбирает + +### Requirement: Свёртку ведёт один фоновый воркер в порядке журнала + +Свёртку принятых доставок SHALL вести одна горутина, обрабатывающая доставки в +порядке журнала — `(received_at, id)`, как он определён capability пересборки. +Распараллеливать свёртку MUST NOT. + +Достижимая гарантия называется точно: в порядке `(received_at, id)` +сворачиваются все доставки, **видимые воркеру** на момент выборки. Доставка, +ставшая видимой позже курсора прохода, подбирается следующим проходом; +абсолютного порядка при конкурентных приёмах система не обещает. + +Последствие этого предела называется вслух: доставка без плотных метрик, +свёрнутая раньше своей предшественницы, слоя не выведет и получит `failed` — то +есть её точки в витрину не попадут до пересборки. Живое состояние в этом случае +расходится с тем, что даёт `healthlog reindex`. Окно узкое (обе доставки должны +приниматься одновременно, и только у автоматизации без плотных метрик), и +изменение его сужает, а не открывает: прежде свёртка шла в порядке завершения +обработчиков. Устранение предела — отдельный вопрос, оно требует удерживать +порядок на самом приёме. + +Воркер SHALL продвигаться по неразобранным доставкам строго возрастающим +курсором в пределах одного прохода. Курсор обязателен для завершимости: +доставка, у которой не удалось записать даже исход разбора, остаётся `pending`, +и проход без курсора выбирал бы её бесконечно. + +Приём SHALL будить воркер после того, как доставка учтена. Потеря сигнала +отказом быть MUST NOT: доставка от этого не перестаёт числиться `pending`. +Помимо сигнала воркер SHALL просыпаться периодически — иначе доставка, +оставшаяся `pending` по причине выше, ждала бы следующей доставки, а ночью +телефон молчит часами. + +Отказ отдельного прохода воркер SHALL переживать: отказ выборки пишется `ERROR` +и прекращает проход, но не цикл. Отмена работы снаружи отказом при этом +считаться MUST NOT — штатная остановка не должна писать `ERROR`. Воркер, умерший +от временного отказа базы, остановил бы свёртку до конца жизни процесса, пока +приём продолжал бы отвечать `200`. + +#### Scenario: Видимые доставки сворачиваются в порядке журнала + +- **GIVEN** несколько доставок числятся `pending` до начала прохода +- **WHEN** воркер делает проход +- **THEN** он сворачивает их в порядке `(received_at, id)` +- **AND** доставка без плотных метрик наследует слой предшествующей ей по этому + порядку доставки той же автоматизации, а не соседа по времени вставки + +#### Scenario: Доставка, не записавшая исход, не зацикливает проход + +- **WHEN** свёртка доставки не смогла записать исход разбора и оставила её + `pending` +- **THEN** проход воркера завершается, а не выбирает её повторно + +#### Scenario: Доставка без входящего потока всё равно подбирается + +- **GIVEN** доставка осталась `pending`, и новых доставок не приезжает +- **WHEN** наступает очередное периодическое пробуждение +- **THEN** воркер пробует свернуть её снова + +### Requirement: Подбор неразобранного при старте — та же операция + +При старте система SHALL сворачивать доставки, числящиеся неразобранными, тем +же путём, каким сворачивает вновь принятые: отдельного кода подбора +существовать MUST NOT. + +Порядок журнала при подборе SHALL соблюдаться так же, как при обычной работе — +подбор это тот же проход воркера, а не особый режим. + +Классификация исхода свёртки (свёрнуто; слой не выведен; содержимое не +разобрано; прочий отказ; частичный разбор; несравнимые наборы полей) SHALL быть +общей с пересборкой журнала: второй классификатор разошёлся бы с первым молча. +Классифицироваться SHALL только ошибка свёртки; решение «работу прекратили +снаружи» MUST NOT приниматься классификатором — у пересборки и у воркера +контекст свёртки означает разное, и общая ветка отмены дала бы одному из них +противоположный смысл. + +Счётчики частичного разбора и несравнимых наборов SHALL читаться только у +успешной свёртки — у отказавшей они заполнены частично, и `partial` занижался бы, +а по нему принимается решение о судьбе тела. + +#### Scenario: Доставки, оставшиеся неразобранными, подбираются при старте + +- **GIVEN** в учёте есть доставки со статусом `pending` +- **WHEN** сервис стартует +- **THEN** они сворачиваются в порядке `(received_at, id)` + +#### Scenario: Размер задолженности назван при старте + +- **WHEN** сервис стартует и неразобранные доставки есть +- **THEN** их число попадает в лог одной записью уровня `INFO` + +### Requirement: Остановка не оставляет доставку в неопределённом состоянии + +Остановка сервиса SHALL сперва прекращать приём, затем останавливать воркер. +Обратный порядок оставил бы доставки, принятые после остановки воркера, никого +не разбудившими. + +Инвариант остановки: после неё не существует доставки, которая числится +разобранной, а записана частично; всё несвёрнутое остаётся `pending`. Обещать, +что текущая доставка непременно досворачивается, система MUST NOT — бюджет +остановки меньше бюджета свёртки, и такое обещание исполнялось бы не всегда. + +Свёртка SHALL идти на контексте, не отменяемом остановкой, а отмена SHALL +проверяться **между** доставками. Причина названа: свёртка помечает доставку +`failed` на ошибке, а `failed` воркер не подбирает — то есть отмена снаружи +превратилась бы в свойство доставки. + +Исчерпание бюджета остановки отказом сервиса считаться MUST NOT: и штатное +завершение воркера, и его прерывание оставляют состояние определённым. Факт +SHALL называться предупреждением, а не ошибкой старта. + +#### Scenario: Остановка не оставляет половины + +- **WHEN** сервис останавливается во время свёртки доставки +- **THEN** доставка либо свёрнута целиком, либо числится `pending` +- **AND** частично записанных объектов от неё не остаётся + +#### Scenario: Приём прекращается раньше воркера + +- **WHEN** сервис останавливается +- **THEN** приём перестаёт принимать раньше, чем останавливается воркер + +#### Scenario: Не уложились в бюджет остановки + +- **WHEN** воркер не успевает выйти в отведённый бюджет +- **THEN** факт попадает в лог предупреждением +- **AND** команда не сообщает об ошибке + +### Requirement: Отставание воркера видно в логе + +Система SHALL писать `WARN`, когда доставка ждала свёртки дольше периода +быстрого прохода синхронизации (пять минут): дольше этого срока очередь растёт, +а не рассасывается. Ожидание считается от `received_at` до начала свёртки. + +Записей SHALL быть **одна на проход**, а не одна на доставку: задолженность в +сотню тел давала бы сотню одинаковых предупреждений каждую минуту, и уровень, по +которому вмешиваются, перестал бы что-либо значить. Строка называет число +задержанных и худшее ожидание с идентификатором доставки. + +Метка SHALL вычисляться на выборке прохода, а не только по факту успешной +свёртки: состояние «работа есть, прогресса нет» обязано быть отличимо от +здорового пустого потока, иначе наблюдаемость молчит ровно там, где нужна. + +Задолженность, накопленную **до** старта, метка задержки помечать MUST NOT: она +названа отдельной записью `INFO` о размере задолженности, а сотня одинаковых +`WARN` при первом же старте обесценила бы уровень. Метка включается после того, +как первый проход воркера завершился. + +Записи воркера значений точек и имён устройств содержать MUST NOT — как и любые +записи свёртки. + +#### Scenario: Отставший воркер называет задержку + +- **GIVEN** первый проход воркера завершён +- **WHEN** доставки дожидаются свёртки дольше пяти минут +- **THEN** в лог идёт одна запись `WARN` на проход с числом задержанных и + худшим ожиданием + +#### Scenario: Задолженность при старте не даёт шквала предупреждений + +- **GIVEN** неразобранными числятся доставки, накопленные до старта +- **WHEN** воркер сворачивает их первым проходом +- **THEN** записей `WARN` о задержке по ним нет + +### Requirement: Длинный бюджет ответа принадлежит маршруту приёма + +Обработчик приёма SHALL выставлять собственный дедлайн записи ответа перед +чтением тела, и этот дедлайн SHALL покрывать чтение тела вместе с отправкой +ответа. Полагаться на общий `write_timeout` сервера система MUST NOT: он +ставится до вызова обработчика и потому обрывает загрузку, идущую дольше него, — +делая `read_timeout` обещанием, которого сервер не исполняет. + +Общий `write_timeout` сервера при этом расширяться MUST NOT: длинный бюджет +нужен одному маршруту, а остальные теряли бы защиту от застрявшей записи ответа. + +Транспорт, не поддерживающий установки дедлайна, отказом приёма считаться MUST +NOT: факт уходит в `DEBUG`, приём продолжается. + +#### Scenario: Медленная загрузка тела не обрывается + +- **WHEN** тело приезжает дольше, чем общий `write_timeout` сервера, но + укладывается в `read_timeout` +- **THEN** ответ доходит до отправителя + +#### Scenario: Прочие маршруты бюджета не наследуют + +- **WHEN** запрос идёт не на приём +- **THEN** его бюджет записи ответа остаётся общим `write_timeout` diff --git a/openspec/specs/parsing/spec.md b/openspec/specs/parsing/spec.md index 6f536ba..aacf42f 100644 --- a/openspec/specs/parsing/spec.md +++ b/openspec/specs/parsing/spec.md @@ -252,6 +252,11 @@ Export шлёт под одним именем, чтобы одно имя оз Система MUST сохранять правило «сохранили — значит приняли»: исход разбора не меняет код ответа на доставку. +Разбор идёт **после** ответа, поэтому исход виден не в ответе и не в момент +ответа, а асинхронно — в `delivery.parse_status` и в записи лога. Когда именно +отдаётся ответ и кто сворачивает принятое, определяет capability `ingest`; +здесь нормируется только то, что от разбора код ответа не зависит. + #### Scenario: Содержимое не разобралось - **WHEN** тело сохранено в архив, но разбор его содержимого не удался diff --git a/openspec/specs/reindex/spec.md b/openspec/specs/reindex/spec.md index 8f5e05d..97d8fec 100644 --- a/openspec/specs/reindex/spec.md +++ b/openspec/specs/reindex/spec.md @@ -310,9 +310,17 @@ или нет. Отказы SHALL считаться **по классам**: слой не выводится, содержимое не -разбирается, всё прочее. Невыведенный слой есть в каждом журнале и штатен; -общий счётчик отправлял бы человека искать дефект там, где его нет. Отдельно -называть человеку следует только нештатные отказы. +разбирается, работа отложена по обстоятельствам, всё прочее. Невыведенный слой +есть в каждом журнале и штатен; общий счётчик отправлял бы человека искать +дефект там, где его нет. Отдельно называть человеку следует только нештатные +отказы. + +Отложенная доставка (занятость базы, отмена работы снаружи) SHALL считаться +нештатной **для пересборки**, хотя для фоновой свёртки она штатна: пересборка +идёт в свежий файл при единственном писателе, и такая доставка в собранной +витрине просто отсутствует — вместе с теми, кто наследовал от неё слой. Классы +при этом общие с фоновой свёрткой: второй классификатор разошёлся бы с первым +молча. Число объектов «было и стало» SHALL печататься рядом с отпечатками: отпечатки отвечают «да/нет», а решение о подмене необратимо, и по «да/нет» нельзя diff --git a/openspec/specs/storage/spec.md b/openspec/specs/storage/spec.md index f29695a..1e59a9d 100644 --- a/openspec/specs/storage/spec.md +++ b/openspec/specs/storage/spec.md @@ -343,7 +343,8 @@ HTML-экранирования: `&`, `<` и `>` внутри точки обя Статусы разбора: ``` -pending этим разбором ещё не смотрели +pending этим разбором ещё не смотрели — или смотрели, но работа не сделана + по обстоятельствам (см. ниже) parsed разобрано всё, что в теле было partial разобрано покрытое; в теле остались непокрытые секции failed разобрать не удалось, точек нет @@ -354,6 +355,24 @@ failed разобрать не удалось, точек нет чтобы читатели (ретеншен, статистика) спрашивали статус, а не сравнивали список со строкой. +**Отказ обстоятельств статуса не меняет вовсе.** Отмена работы снаружи и +занятость базы дольше повторов транзакции означают «не сделано», а не «не +выходит»: доставка остаётся `pending` и будет свёрнута снова. Правило появилось +не из аккуратности — фоновая свёртка `failed` не подбирает никогда, и без этого +различения занятость базы (а с фоновой свёрткой конкуренция за неё штатная) +выводила бы доставку из очереди навсегда. Различение живёт **в одном месте**: +тот, кто пишет исход, и тот, кто классифицирует его в счётчики, спрашивают один +предикат. + +Дедлайн самой свёртки к обстоятельствам MUST NOT относиться: доставка, не +уложившаяся в бюджет, не уложится в него и в следующий раз, а бесконечный повтор +заведомо безнадёжного — это очередь, которая не движется. + +Отказы, случившиеся **до** чтения тела (учётной записи нет, соседний запрос не +прошёл), и отказ самой записи исхода статуса не меняют по другой причине — +записать его нечем. Доставка остаётся `pending`, что честно: этим разбором её не +досмотрели. + Список непокрытых ключей SHALL сохраняться рядом с доставкой — именами ключей, без содержимого секций. Он же ответ на вопрос «что останется потерянным, если тело удалить»: для `stateOfMind` доставки HAE единственный источник, в экспорте @@ -391,21 +410,20 @@ Apple его нет (находка 46). Поэтому список MUST сох #### Scenario: Отказ разбора сильнее частичности -- **WHEN** разбор доставки завершился ошибкой +- **WHEN** разбор доставки завершился ошибкой в самом разборе или в записи + точек - **THEN** `parse_status` равен `failed` - **AND** список непокрытых ключей сохранён, если разбор успел его собрать +#### Scenario: Занятая база доставку из очереди не выводит + +- **WHEN** разбор не состоялся из-за занятости базы или отмены работы снаружи +- **THEN** `parse_status` остаётся `pending` + #### Scenario: Пересвёртка после того, как секция стала покрытой - **WHEN** доставка со статусом `partial` сворачивается повторно разбором, - который эту секцию уже покрывает -- **THEN** её статус становится `parsed` + который эту секцию покрывает +- **THEN** `parse_status` становится `parsed` - **AND** сохранённый список непокрытых ключей пуст -#### Scenario: Строки прежнего разбора переводятся в неразобранные - -- **WHEN** база содержит доставки со статусом `parsed`, свёрнутые до появления - частичного статуса -- **THEN** после миграции их статус равен `pending` -- **AND** тела остаются в архиве, а повторная свёртка даёт то же состояние -