package logbuf import ( "bytes" "context" "encoding/json" "errors" "log/slog" "net/http" "net/http/httptest" "strings" "sync" "testing" "time" ) // ЩО САМЕ ТУТ ПЕРЕВІРЯЄТЬСЯ І ЧОМУ САМЕ ЦЕ // // Урок проєкту, дослівно: зелена перевірка доводить рівно те, що вона // перевіряє. Тест ізоляції RLS був правильний і зелений — і пропустив // зламаний вхід, бо перевіряв «чи не видно чужого» тоді, коли зламалось // «чи видно своє». // // Для кільця дзеркальна пастка виглядає так: тест «старі записи // витісняються» зелений і на кільці, яке викидає ВСЕ; тест «секрет // замаскований» зелений і на кільці, яке не пише нічого. Тому кожна // перевірка нижче має обидві половини — що зникло І що лишилось. // // Найважливіший тест у файлі — TestWrapKeepsStderr. Кільце має // ДОПОВНЮВАТИ вивід, а не заміняти його: stderr переживає падіння // процесу, кільце ні. Поломка «журнал є на сторінці, зник у docker // logs» виглядає як робоча система рівно доти, доки хтось не піде // шукати причину аварії — тобто виявиться в найгіршу мить. // collect — логер, який пише і в кільце, і в перевіряний буфер. func collect(t *testing.T, max int) (*slog.Logger, *Ring, *bytes.Buffer) { t.Helper() var out bytes.Buffer ring := New(max) h := slog.NewJSONHandler(&out, &slog.HandlerOptions{Level: slog.LevelDebug}) return slog.New(ring.Wrap(h)), ring, &out } // --------------------------------------------------------------------- // Витіснення // --------------------------------------------------------------------- func TestEvictsOldestOnOverflow(t *testing.T) { // Кільце рівно на MaxRecordBytes: беремо мінімум, який дозволяє New, // щоб переповнити його десятком коротких рядків, а не мільйоном. log, ring, _ := collect(t, MaxRecordBytes) // Один запис важить len(msg)+len(attrs)+recordOverhead. При // повідомленні на ~10 байтів це ~140, тобто в 8 КіБ їх влазить // близько шістдесяти. Пишемо помітно більше. const n = 400 for i := range n { log.Info("рядок", "i", i) } snap := ring.Snapshot("test") if len(snap.Records) == 0 { t.Fatal("кільце порожнє: витіснення викинуло все — це не витіснення, а стирання") } if snap.Dropped == 0 { t.Fatal("нічого не витіснено, хоча записів свідомо більше за стелю") } if snap.Bytes > snap.MaxBytes { t.Fatalf("стелю перевищено: %d > %d", snap.Bytes, snap.MaxBytes) } if int(snap.Dropped)+len(snap.Records) != n { t.Fatalf("записи загубились: витіснено %d + лишилось %d ≠ %d", snap.Dropped, len(snap.Records), n) } // ПЕРША ПОЛОВИНА: найсвіжіший рядок на місці. Без цієї перевірки // зеленим був би й буфер, який викидає найновіше замість найстарішого. if got := snap.Records[0].Attrs; got != "i=399" { t.Fatalf("зверху має бути найсвіжіший запис, а там %q", got) } // ДРУГА ПОЛОВИНА: найстаріший зник саме тому, що не влазить. last := snap.Records[len(snap.Records)-1] if last.Attrs == "i=0" { t.Fatal("найстаріший запис не витіснено, хоча стеля перевищена") } // Порядок усередині знімка — суворо від нового до старого. for i := 1; i < len(snap.Records); i++ { if snap.Records[i-1].Seq <= snap.Records[i].Seq { t.Fatalf("порядок порушено на %d: %d після %d", i, snap.Records[i].Seq, snap.Records[i-1].Seq) } } // Since має переїхати на найстаріший із тих, що лишились: інакше // сторінка казала б «журнал від старту процесу» там, де початок уже // витіснено. if !snap.Since.Equal(last.Time) { t.Fatalf("Since не переїхав: %v замість %v", snap.Since, last.Time) } } // Один довжелезний рядок не має виносити з кільця все інше — заради // цього й існує MaxRecordBytes. func TestHugeRecordDoesNotEmptyRing(t *testing.T) { log, ring, _ := collect(t, 64<<10) for i := range 20 { log.Info("звичайний", "i", i) } log.Error("велика помилка", "sql", strings.Repeat("x", 4<<20)) snap := ring.Snapshot("test") if len(snap.Records) < 10 { t.Fatalf("один довгий рядок вимів кільце: лишилось %d", len(snap.Records)) } top := snap.Records[0] if !strings.HasSuffix(top.Attrs, truncMark) { t.Fatalf("довгий запис не обрізано: %d байтів без позначки", len(top.Attrs)) } if len(top.Msg)+len(top.Attrs) > MaxRecordBytes { t.Fatalf("обрізано не до стелі: %d", len(top.Msg)+len(top.Attrs)) } // Обрізаний запис має лишатись корисним: повідомлення ціле, і з // нього видно, ЩО сталося. if top.Msg != "велика помилка" { t.Fatalf("повідомлення постраждало: %q", top.Msg) } } // --------------------------------------------------------------------- // Вивід у stderr не зникає // --------------------------------------------------------------------- func TestWrapKeepsStderr(t *testing.T) { log, ring, out := collect(t, DefaultMaxBytes) log.With("процес", "api").WithGroup("db").Info("привіт", "хост", "db:5432") // Нижній обробник відпрацював і віддав свій JSON — рівно те, що // забирає docker. var line map[string]any if err := json.Unmarshal(bytes.TrimSpace(out.Bytes()), &line); err != nil { t.Fatalf("stderr не отримав JSON: %v (%q)", err, out.String()) } if line["msg"] != "привіт" { t.Fatalf("stderr отримав не те: %v", line) } if line["процес"] != "api" { t.Fatalf("атрибути WithAttrs не доїхали до stderr: %v", line) } if g, ok := line["db"].(map[string]any); !ok || g["хост"] != "db:5432" { t.Fatalf("група не доїхала до stderr: %v", line) } // І та сама подія лежить у кільці — тобто це доповнення, а не заміна. snap := ring.Snapshot("api") if len(snap.Records) != 1 { t.Fatalf("у кільці %d записів замість одного", len(snap.Records)) } rec := snap.Records[0] if rec.Msg != "привіт" || rec.Level != "INFO" || rec.Source != "api" { t.Fatalf("запис зіпсовано: %+v", rec) } if rec.Attrs != `процес=api db.хост=db:5432` { t.Fatalf("атрибути зведено неправильно: %q", rec.Attrs) } } // Помилка нижнього обробника не має ані ковтатись, ані заважати кільцю. func TestWrapPropagatesHandlerError(t *testing.T) { ring := New(DefaultMaxBytes) want := errors.New("stderr зайнято") h := ring.Wrap(failingHandler{err: want}) var rec slog.Record rec = slog.NewRecord(time.Now(), slog.LevelWarn, "щось", 0) if err := h.Handle(context.Background(), rec); !errors.Is(err, want) { t.Fatalf("помилку нижнього обробника проковтнуто: %v", err) } if got := len(ring.Snapshot("x").Records); got != 1 { t.Fatalf("запис не потрапив у кільце попри збій stderr: %d", got) } } type failingHandler struct{ err error } func (h failingHandler) Enabled(context.Context, slog.Level) bool { return true } func (h failingHandler) Handle(context.Context, slog.Record) error { return h.err } func (h failingHandler) WithAttrs([]slog.Attr) slog.Handler { return h } func (h failingHandler) WithGroup(string) slog.Handler { return h } // Логери, породжені від одного, не мають затирати атрибути один одному. // Це класична пастка спільного хвоста слайса: помилка тиха й з'являється // лише тоді, коли з базового логера зробили двох дітей. func TestWithAttrsDoesNotShareTail(t *testing.T) { log, ring, _ := collect(t, DefaultMaxBytes) base := log.With("спільне", "так") base.With("гілка", "перша").Info("а") base.With("гілка", "друга").Info("б") snap := ring.Snapshot("test") if len(snap.Records) != 2 { t.Fatalf("записів %d", len(snap.Records)) } if snap.Records[0].Attrs != "спільне=так гілка=друга" { t.Fatalf("другий запис: %q", snap.Records[0].Attrs) } if snap.Records[1].Attrs != "спільне=так гілка=перша" { t.Fatalf("перший запис: %q", snap.Records[1].Attrs) } } // --------------------------------------------------------------------- // Маскування // --------------------------------------------------------------------- func TestMaskHidesSecretsKeepsContext(t *testing.T) { const pw = "s3cret-pass-word" const dsn = "postgres://netpulse:" + pw + "@db:5432/netpulse?sslmode=disable" const dek = "k1=0123456789abcdef0123456789abcdef0123456789abcdef0123456789abcdef" log, ring, out := collect(t, DefaultMaxBytes) ring.Mask(DSNSecrets(dsn)...) ring.Mask(KeySecrets(dek)...) log.Error("підключення до БД", "dsn", dsn, "err", "cannot parse `"+dsn+"`: invalid port") log.Error("дзеркало", "url", "https://netpulse:glpat-AbCdEf0123456789@forgejo.example/np.git") log.Error("ключі", "spec", dek) snap := ring.Snapshot("test") all := "" for _, rec := range snap.Records { all += rec.Msg + " " + rec.Attrs + "\n" } // ПЕРША ПОЛОВИНА: секретів немає. for _, bad := range []string{pw, "glpat-AbCdEf0123456789", "0123456789abcdef0123456789abcdef0123456789abcdef0123456789abcdef"} { if strings.Contains(all, bad) { t.Fatalf("секрет %q протік у кільце:\n%s", bad, all) } } // ДРУГА ПОЛОВИНА, і без неї тест зелений на кільці, яке взагалі // нічого не пише: контекст, заради якого журнал і читають, лишився. for _, want := range []string{"db:5432", "invalid port", "forgejo.example/np.git", "підключення до БД", "дзеркало"} { if !strings.Contains(all, want) { t.Fatalf("маскування знесло потрібне (%q):\n%s", want, all) } } // Маскування стосується КІЛЬЦЯ, а не stderr: у docker logs журнал // має лишитись таким, яким був. Інакше ця зміна тихо переписала б // поведінку, на яку ніхто не підписувався. if !strings.Contains(out.String(), pw) { t.Fatal("stderr теж почистили — це вже не доповнення, а зміна поведінки") } } func TestDSNSecrets(t *testing.T) { cases := []struct { in string want string }{ {"postgres://u:pa55word@db/netpulse", "pa55word"}, {"host=db user=netpulse password=pa55word dbname=netpulse", "pa55word"}, {"postgres://u@db/netpulse", ""}, {"", ""}, } for _, c := range cases { got := DSNSecrets(c.in) if c.want == "" { if len(got) != 0 { t.Fatalf("%q: вигадано секрет %v", c.in, got) } continue } if len(got) != 1 || got[0] != c.want { t.Fatalf("%q: %v замість [%q]", c.in, got, c.want) } } } // --------------------------------------------------------------------- // Одночасний запис і читання // --------------------------------------------------------------------- // Гонка тут не гіпотетична: у кільце пишуть усі такти обох процесів, а // читає його HTTP-обробник у чужій горутині — тобто одночасний доступ є // в найпершу ж секунду роботи. // // Прогін під -race доводить відсутність гонки; без нього (CGO_ENABLED=0, // збірка без компілятора C) цей тест усе одно ловить головне: зрив // інваріантів. Незамкнений доступ до слайса, що ріжеться з голови, // дає або паніку на індексі, або знімок із порожніми записами, або // розбіжність обліку байтів. func TestConcurrentWriteAndRead(t *testing.T) { ring := New(64 << 10) log := slog.New(ring.Wrap(slog.NewJSONHandler(discard{}, nil))) const writers, perWriter, readers = 8, 500, 4 var wg sync.WaitGroup stop := make(chan struct{}) for w := range writers { wg.Add(1) go func() { defer wg.Done() for i := range perWriter { log.Info("такт", "writer", w, "i", i) } }() } for range readers { wg.Add(1) go func() { defer wg.Done() for { select { case <-stop: return default: } snap := ring.Snapshot("test") var sum int for i, rec := range snap.Records { if rec.Seq == 0 || rec.Level == "" { t.Errorf("порожній запис у знімку на позиції %d", i) return } if i > 0 && snap.Records[i-1].Seq <= rec.Seq { t.Errorf("порядок порушено: %d після %d", rec.Seq, snap.Records[i-1].Seq) return } sum += rec.size() } // Облік байтів має збігатися з тим, що справді лежить у // кільці: розбіжність означала б, що витіснення й // додавання бачать різні стани. if sum != snap.Bytes { t.Errorf("облік байтів розійшовся: %d за записами, %d у лічильнику", sum, snap.Bytes) return } if snap.Bytes > snap.MaxBytes { t.Errorf("стелю перевищено під навантаженням: %d > %d", snap.Bytes, snap.MaxBytes) return } } }() } // Читачі спиняються після письменників, а не разом із ними: останній // знімок має застати кільце вже в спокої. done := make(chan struct{}) go func() { wg.Wait() close(done) }() go func() { time.Sleep(200 * time.Millisecond) close(stop) }() <-done snap := ring.Snapshot("test") if int(snap.Dropped)+len(snap.Records) != writers*perWriter { t.Fatalf("записи загубились: %d + %d ≠ %d", snap.Dropped, len(snap.Records), writers*perWriter) } } type discard struct{} func (discard) Write(p []byte) (int, error) { return len(p), nil } // --------------------------------------------------------------------- // Внутрішня ручка // --------------------------------------------------------------------- func TestInternalHandlerRequiresToken(t *testing.T) { ring := New(DefaultMaxBytes) slog.New(ring.Wrap(slog.NewJSONHandler(discard{}, nil))).Info("такт") const dek = "k1=0123456789abcdef0123456789abcdef0123456789abcdef0123456789abcdef" token := InternalToken(dek) if token == "" { t.Fatal("токен не виведено") } if InternalToken("") != "" { t.Fatal("порожній секрет має давати порожній токен — інакше це відчинені двері") } srv := httptest.NewServer(ring.HTTPHandler("collector", token)) defer srv.Close() // БЕЗ токена — відмова. res, err := http.Get(srv.URL + InternalPath) if err != nil { t.Fatal(err) } res.Body.Close() if res.StatusCode != http.StatusForbidden { t.Fatalf("без токена віддано %d", res.StatusCode) } // З ЧУЖИМ токеном — теж відмова. if _, err := Fetch(context.Background(), srv.URL, InternalToken("k1=beef"), time.Second); err == nil { t.Fatal("чужий токен прийнято") } // ЗІ СВОЇМ — знімок доїжджає цілим. snap, err := Fetch(context.Background(), srv.URL, token, 5*time.Second) if err != nil { t.Fatalf("свій токен відхилено: %v", err) } if snap.Source != "collector" || len(snap.Records) != 1 || snap.Records[0].Msg != "такт" { t.Fatalf("знімок доїхав зіпсованим: %+v", snap) } if snap.MaxBytes != DefaultMaxBytes { t.Fatalf("стеля не доїхала: %d", snap.MaxBytes) } } // Ручка без токена має бути зачиненою, а не відчиненою: інсталяція без // -dek існує, і мовчазне зняття перевірки на ній було б найгіршим із // можливих наслідків порожньої змінної. func TestInternalHandlerWithoutTokenIsClosed(t *testing.T) { ring := New(DefaultMaxBytes) srv := httptest.NewServer(ring.HTTPHandler("collector", "")) defer srv.Close() for _, auth := range []string{"", "Bearer ", "Bearer щось"} { req, _ := http.NewRequest(http.MethodGet, srv.URL+InternalPath, nil) if auth != "" { req.Header.Set("Authorization", auth) } res, err := http.DefaultClient.Do(req) if err != nil { t.Fatal(err) } res.Body.Close() if res.StatusCode != http.StatusForbidden { t.Fatalf("з %q віддано %d", auth, res.StatusCode) } } }