| 123456789101112131415161718192021222324252627282930313233343536373839404142434445464748495051525354555657585960616263646566676869707172737475767778798081828384858687888990919293949596979899100101102103104105106107108109110111112113114115116117118119120121122123124125126127128129130131132133134135136137138139140141142143144145146147148149150151152153154155156157158159160161162163164165166167168169170171172173174175176177178179180181182183184185186187188189190191192193194195196197198199200201202203204205206207208209210211212213214215216217218219220221222223224225 |
- package service
- import (
- "context"
- "errors"
- "sync/atomic"
- "testing"
- "time"
- "github.com/Wei-Shaw/sub2api/internal/pkg/logger"
- )
- func opsSystemLogBackoffEvent() *logger.LogEvent {
- return &logger.LogEvent{
- Time: time.Now().UTC(),
- Level: "warn",
- Component: "app",
- Message: "boom",
- Fields: map[string]any{},
- }
- }
- // pumpOpsSystemLogEvents 持续投递日志事件,模拟故障期间业务侧不断产生 WARN/ERROR。
- func pumpOpsSystemLogEvents(t *testing.T, sink *OpsSystemLogSink) {
- t.Helper()
- stop := make(chan struct{})
- done := make(chan struct{})
- go func() {
- defer close(done)
- for {
- select {
- case <-stop:
- return
- default:
- }
- sink.WriteLogEvent(opsSystemLogBackoffEvent())
- time.Sleep(2 * time.Millisecond)
- }
- }()
- t.Cleanup(func() {
- close(stop)
- <-done
- })
- }
- func waitForOpsSystemLogCondition(t *testing.T, timeout time.Duration, cond func() bool) bool {
- t.Helper()
- deadline := time.Now().Add(timeout)
- for time.Now().Before(deadline) {
- if cond() {
- return true
- }
- time.Sleep(5 * time.Millisecond)
- }
- return cond()
- }
- func TestOpsSystemLogSinkFlushBackoffFor(t *testing.T) {
- sink := &OpsSystemLogSink{flushBackoff: time.Second, flushBackoffMax: 8 * time.Second}
- cases := []struct {
- name string
- failures int
- want time.Duration
- }{
- {"first_failure", 1, time.Second},
- {"second_failure", 2, 2 * time.Second},
- {"third_failure", 3, 4 * time.Second},
- {"fourth_failure", 4, 8 * time.Second},
- {"capped", 9, 8 * time.Second},
- {"large_streak_does_not_overflow", 1000, 8 * time.Second},
- {"zero_streak_uses_base", 0, time.Second},
- {"negative_streak_uses_base", -1, time.Second},
- }
- for _, tc := range cases {
- t.Run(tc.name, func(t *testing.T) {
- if got := sink.flushBackoffFor(tc.failures); got != tc.want {
- t.Fatalf("flushBackoffFor(%d) = %s, want %s", tc.failures, got, tc.want)
- }
- })
- }
- }
- // 未显式配置时回落到默认值;max 小于 base 时以 base 为准,不产生比基准还短的退避。
- func TestOpsSystemLogSinkFlushBackoffForFallbacks(t *testing.T) {
- zero := &OpsSystemLogSink{}
- if got := zero.flushBackoffFor(1); got != defaultOpsSystemLogFlushBackoff {
- t.Fatalf("zero-value base = %s, want %s", got, defaultOpsSystemLogFlushBackoff)
- }
- if got := zero.flushBackoffFor(100); got != defaultOpsSystemLogFlushBackoffMax {
- t.Fatalf("zero-value cap = %s, want %s", got, defaultOpsSystemLogFlushBackoffMax)
- }
- inverted := &OpsSystemLogSink{flushBackoff: 5 * time.Second, flushBackoffMax: time.Second}
- if got := inverted.flushBackoffFor(3); got != 5*time.Second {
- t.Fatalf("inverted bounds = %s, want 5s", got)
- }
- }
- // issue #5265:写入失败后如果按 flushInterval 继续每秒重试,每一轮都会占用并取消
- // 一条池内连接(远程 PG 上 COPY 取消会让连接协议失步而被销毁),小连接池会被日志
- // 通道长期占满,业务侧最终报 Billing 503。失败后必须退避。
- func TestOpsSystemLogSinkSuppressesRetriesDuringBackoff(t *testing.T) {
- var calls int64
- repo := &opsRepoMock{
- BatchInsertSystemLogsFn: func(_ context.Context, _ []*OpsInsertSystemLogInput) (int64, error) {
- atomic.AddInt64(&calls, 1)
- return 0, errors.New("db unavailable")
- },
- }
- sink := NewOpsSystemLogSink(repo)
- sink.batchSize = 1
- sink.flushInterval = 5 * time.Millisecond
- sink.flushBackoff = 800 * time.Millisecond
- sink.flushBackoffMax = 800 * time.Millisecond
- sink.Start()
- defer sink.Stop()
- pumpOpsSystemLogEvents(t, sink)
- if !waitForOpsSystemLogCondition(t, 2*time.Second, func() bool { return atomic.LoadInt64(&calls) >= 1 }) {
- t.Fatalf("first flush never happened")
- }
- // 退避窗口内不得再打上游:修复前 5ms 的 flushInterval 会在这 300ms 里打出上百次。
- time.Sleep(300 * time.Millisecond)
- if got := atomic.LoadInt64(&calls); got != 1 {
- t.Fatalf("upstream calls during backoff = %d, want 1", got)
- }
- // 被抑制的批次记为 dropped,而不是 write_failed —— 没有尝试过就不算写失败。
- health := sink.Health()
- if health.DroppedCount == 0 {
- t.Fatalf("dropped_count should grow while flushing is suppressed")
- }
- if health.WriteFailed == 0 || health.LastError == "" {
- t.Fatalf("failed flush should still surface in health: %+v", health)
- }
- }
- // 退避到期后必须自动恢复,不能变成永久停写。
- func TestOpsSystemLogSinkResumesAfterBackoffWindow(t *testing.T) {
- var calls int64
- repo := &opsRepoMock{
- BatchInsertSystemLogsFn: func(_ context.Context, _ []*OpsInsertSystemLogInput) (int64, error) {
- atomic.AddInt64(&calls, 1)
- return 0, errors.New("db unavailable")
- },
- }
- sink := NewOpsSystemLogSink(repo)
- sink.batchSize = 1
- sink.flushInterval = 5 * time.Millisecond
- sink.flushBackoff = 150 * time.Millisecond
- sink.flushBackoffMax = 150 * time.Millisecond
- sink.Start()
- defer sink.Stop()
- pumpOpsSystemLogEvents(t, sink)
- if !waitForOpsSystemLogCondition(t, 3*time.Second, func() bool { return atomic.LoadInt64(&calls) >= 3 }) {
- t.Fatalf("sink did not resume flushing after backoff, calls=%d", atomic.LoadInt64(&calls))
- }
- }
- // 一次成功必须清空失败计数与抑制窗口,否则短暂抖动后写入速率无法恢复。
- func TestOpsSystemLogSinkSuccessClearsSuppression(t *testing.T) {
- var calls int64
- repo := &opsRepoMock{
- BatchInsertSystemLogsFn: func(_ context.Context, inputs []*OpsInsertSystemLogInput) (int64, error) {
- if atomic.AddInt64(&calls, 1) == 1 {
- return 0, errors.New("db unavailable")
- }
- return int64(len(inputs)), nil
- },
- }
- sink := NewOpsSystemLogSink(repo)
- sink.batchSize = 1
- sink.flushInterval = 5 * time.Millisecond
- sink.flushBackoff = 150 * time.Millisecond
- sink.flushBackoffMax = 150 * time.Millisecond
- sink.Start()
- defer sink.Stop()
- pumpOpsSystemLogEvents(t, sink)
- // 第 2 次调用(恢复后的首次成功)之后不应再有抑制:调用次数需要快速爬升。
- if !waitForOpsSystemLogCondition(t, 3*time.Second, func() bool { return atomic.LoadInt64(&calls) >= 2 }) {
- t.Fatalf("sink never retried after the first failure")
- }
- recovered := atomic.LoadInt64(&calls)
- time.Sleep(200 * time.Millisecond)
- if got := atomic.LoadInt64(&calls) - recovered; got < 3 {
- t.Fatalf("calls after recovery = %d in 200ms, want >=3 (suppression not cleared)", got)
- }
- if sink.Health().WrittenCount == 0 {
- t.Fatalf("written_count should grow after recovery")
- }
- }
- // 健康路径不受影响:一直成功就永远不进入退避。
- func TestOpsSystemLogSinkHealthyPathNeverSuppressed(t *testing.T) {
- var calls int64
- repo := &opsRepoMock{
- BatchInsertSystemLogsFn: func(_ context.Context, inputs []*OpsInsertSystemLogInput) (int64, error) {
- atomic.AddInt64(&calls, 1)
- return int64(len(inputs)), nil
- },
- }
- sink := NewOpsSystemLogSink(repo)
- sink.batchSize = 1
- sink.flushInterval = 5 * time.Millisecond
- sink.flushBackoff = time.Hour
- sink.flushBackoffMax = time.Hour
- sink.Start()
- defer sink.Stop()
- pumpOpsSystemLogEvents(t, sink)
- if !waitForOpsSystemLogCondition(t, 3*time.Second, func() bool { return atomic.LoadInt64(&calls) >= 10 }) {
- t.Fatalf("healthy sink should keep flushing, calls=%d", atomic.LoadInt64(&calls))
- }
- if got := sink.Health().DroppedCount; got != 0 {
- t.Fatalf("healthy sink dropped_count = %d, want 0", got)
- }
- }
|