Приём отвечает 200 до свёртки, свёртку ведёт фоновый воркер

- Очередью служит сама таблица: доставка ждёт свёртки в статусе `pending`,
  канал несёт только бит «есть работа». Переполнять нечего, падение процесса
  очередь не теряет, а подбор `pending` при старте — обычный проход воркера, а
  не отдельный код. Классификация исхода общая с пересборкой журнала.
- Исход разбора начал отражать доставку, а не обстоятельства: отмена и
  занятость базы статус не меняют (иначе конкуренция за базу выводила бы
  доставку из очереди навсегда), паника свёртки больше не валит процесс, а
  учёт доставки идёт через транзакцию с повторами.
- Длинный бюджет ответа выдан маршруту приёма, а не всему серверу:
  `write_timeout` в Go покрывает и чтение тела, и общий подъём снял бы защиту с
  остальных маршрутов.
This commit is contained in:
av
2026-08-02 11:01:42 +03:00
parent ebd59af056
commit 63bffe2865
46 changed files with 3561 additions and 296 deletions
+11 -5
View File
@@ -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("")
}
+15 -8
View File
@@ -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",
+98 -22
View File
@@ -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
}
+133
View File
@@ -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
}