ops_system_log_sink_backoff_test.go 7.1 KB

123456789101112131415161718192021222324252627282930313233343536373839404142434445464748495051525354555657585960616263646566676869707172737475767778798081828384858687888990919293949596979899100101102103104105106107108109110111112113114115116117118119120121122123124125126127128129130131132133134135136137138139140141142143144145146147148149150151152153154155156157158159160161162163164165166167168169170171172173174175176177178179180181182183184185186187188189190191192193194195196197198199200201202203204205206207208209210211212213214215216217218219220221222223224225
  1. package service
  2. import (
  3. "context"
  4. "errors"
  5. "sync/atomic"
  6. "testing"
  7. "time"
  8. "github.com/Wei-Shaw/sub2api/internal/pkg/logger"
  9. )
  10. func opsSystemLogBackoffEvent() *logger.LogEvent {
  11. return &logger.LogEvent{
  12. Time: time.Now().UTC(),
  13. Level: "warn",
  14. Component: "app",
  15. Message: "boom",
  16. Fields: map[string]any{},
  17. }
  18. }
  19. // pumpOpsSystemLogEvents 持续投递日志事件,模拟故障期间业务侧不断产生 WARN/ERROR。
  20. func pumpOpsSystemLogEvents(t *testing.T, sink *OpsSystemLogSink) {
  21. t.Helper()
  22. stop := make(chan struct{})
  23. done := make(chan struct{})
  24. go func() {
  25. defer close(done)
  26. for {
  27. select {
  28. case <-stop:
  29. return
  30. default:
  31. }
  32. sink.WriteLogEvent(opsSystemLogBackoffEvent())
  33. time.Sleep(2 * time.Millisecond)
  34. }
  35. }()
  36. t.Cleanup(func() {
  37. close(stop)
  38. <-done
  39. })
  40. }
  41. func waitForOpsSystemLogCondition(t *testing.T, timeout time.Duration, cond func() bool) bool {
  42. t.Helper()
  43. deadline := time.Now().Add(timeout)
  44. for time.Now().Before(deadline) {
  45. if cond() {
  46. return true
  47. }
  48. time.Sleep(5 * time.Millisecond)
  49. }
  50. return cond()
  51. }
  52. func TestOpsSystemLogSinkFlushBackoffFor(t *testing.T) {
  53. sink := &OpsSystemLogSink{flushBackoff: time.Second, flushBackoffMax: 8 * time.Second}
  54. cases := []struct {
  55. name string
  56. failures int
  57. want time.Duration
  58. }{
  59. {"first_failure", 1, time.Second},
  60. {"second_failure", 2, 2 * time.Second},
  61. {"third_failure", 3, 4 * time.Second},
  62. {"fourth_failure", 4, 8 * time.Second},
  63. {"capped", 9, 8 * time.Second},
  64. {"large_streak_does_not_overflow", 1000, 8 * time.Second},
  65. {"zero_streak_uses_base", 0, time.Second},
  66. {"negative_streak_uses_base", -1, time.Second},
  67. }
  68. for _, tc := range cases {
  69. t.Run(tc.name, func(t *testing.T) {
  70. if got := sink.flushBackoffFor(tc.failures); got != tc.want {
  71. t.Fatalf("flushBackoffFor(%d) = %s, want %s", tc.failures, got, tc.want)
  72. }
  73. })
  74. }
  75. }
  76. // 未显式配置时回落到默认值;max 小于 base 时以 base 为准,不产生比基准还短的退避。
  77. func TestOpsSystemLogSinkFlushBackoffForFallbacks(t *testing.T) {
  78. zero := &OpsSystemLogSink{}
  79. if got := zero.flushBackoffFor(1); got != defaultOpsSystemLogFlushBackoff {
  80. t.Fatalf("zero-value base = %s, want %s", got, defaultOpsSystemLogFlushBackoff)
  81. }
  82. if got := zero.flushBackoffFor(100); got != defaultOpsSystemLogFlushBackoffMax {
  83. t.Fatalf("zero-value cap = %s, want %s", got, defaultOpsSystemLogFlushBackoffMax)
  84. }
  85. inverted := &OpsSystemLogSink{flushBackoff: 5 * time.Second, flushBackoffMax: time.Second}
  86. if got := inverted.flushBackoffFor(3); got != 5*time.Second {
  87. t.Fatalf("inverted bounds = %s, want 5s", got)
  88. }
  89. }
  90. // issue #5265:写入失败后如果按 flushInterval 继续每秒重试,每一轮都会占用并取消
  91. // 一条池内连接(远程 PG 上 COPY 取消会让连接协议失步而被销毁),小连接池会被日志
  92. // 通道长期占满,业务侧最终报 Billing 503。失败后必须退避。
  93. func TestOpsSystemLogSinkSuppressesRetriesDuringBackoff(t *testing.T) {
  94. var calls int64
  95. repo := &opsRepoMock{
  96. BatchInsertSystemLogsFn: func(_ context.Context, _ []*OpsInsertSystemLogInput) (int64, error) {
  97. atomic.AddInt64(&calls, 1)
  98. return 0, errors.New("db unavailable")
  99. },
  100. }
  101. sink := NewOpsSystemLogSink(repo)
  102. sink.batchSize = 1
  103. sink.flushInterval = 5 * time.Millisecond
  104. sink.flushBackoff = 800 * time.Millisecond
  105. sink.flushBackoffMax = 800 * time.Millisecond
  106. sink.Start()
  107. defer sink.Stop()
  108. pumpOpsSystemLogEvents(t, sink)
  109. if !waitForOpsSystemLogCondition(t, 2*time.Second, func() bool { return atomic.LoadInt64(&calls) >= 1 }) {
  110. t.Fatalf("first flush never happened")
  111. }
  112. // 退避窗口内不得再打上游:修复前 5ms 的 flushInterval 会在这 300ms 里打出上百次。
  113. time.Sleep(300 * time.Millisecond)
  114. if got := atomic.LoadInt64(&calls); got != 1 {
  115. t.Fatalf("upstream calls during backoff = %d, want 1", got)
  116. }
  117. // 被抑制的批次记为 dropped,而不是 write_failed —— 没有尝试过就不算写失败。
  118. health := sink.Health()
  119. if health.DroppedCount == 0 {
  120. t.Fatalf("dropped_count should grow while flushing is suppressed")
  121. }
  122. if health.WriteFailed == 0 || health.LastError == "" {
  123. t.Fatalf("failed flush should still surface in health: %+v", health)
  124. }
  125. }
  126. // 退避到期后必须自动恢复,不能变成永久停写。
  127. func TestOpsSystemLogSinkResumesAfterBackoffWindow(t *testing.T) {
  128. var calls int64
  129. repo := &opsRepoMock{
  130. BatchInsertSystemLogsFn: func(_ context.Context, _ []*OpsInsertSystemLogInput) (int64, error) {
  131. atomic.AddInt64(&calls, 1)
  132. return 0, errors.New("db unavailable")
  133. },
  134. }
  135. sink := NewOpsSystemLogSink(repo)
  136. sink.batchSize = 1
  137. sink.flushInterval = 5 * time.Millisecond
  138. sink.flushBackoff = 150 * time.Millisecond
  139. sink.flushBackoffMax = 150 * time.Millisecond
  140. sink.Start()
  141. defer sink.Stop()
  142. pumpOpsSystemLogEvents(t, sink)
  143. if !waitForOpsSystemLogCondition(t, 3*time.Second, func() bool { return atomic.LoadInt64(&calls) >= 3 }) {
  144. t.Fatalf("sink did not resume flushing after backoff, calls=%d", atomic.LoadInt64(&calls))
  145. }
  146. }
  147. // 一次成功必须清空失败计数与抑制窗口,否则短暂抖动后写入速率无法恢复。
  148. func TestOpsSystemLogSinkSuccessClearsSuppression(t *testing.T) {
  149. var calls int64
  150. repo := &opsRepoMock{
  151. BatchInsertSystemLogsFn: func(_ context.Context, inputs []*OpsInsertSystemLogInput) (int64, error) {
  152. if atomic.AddInt64(&calls, 1) == 1 {
  153. return 0, errors.New("db unavailable")
  154. }
  155. return int64(len(inputs)), nil
  156. },
  157. }
  158. sink := NewOpsSystemLogSink(repo)
  159. sink.batchSize = 1
  160. sink.flushInterval = 5 * time.Millisecond
  161. sink.flushBackoff = 150 * time.Millisecond
  162. sink.flushBackoffMax = 150 * time.Millisecond
  163. sink.Start()
  164. defer sink.Stop()
  165. pumpOpsSystemLogEvents(t, sink)
  166. // 第 2 次调用(恢复后的首次成功)之后不应再有抑制:调用次数需要快速爬升。
  167. if !waitForOpsSystemLogCondition(t, 3*time.Second, func() bool { return atomic.LoadInt64(&calls) >= 2 }) {
  168. t.Fatalf("sink never retried after the first failure")
  169. }
  170. recovered := atomic.LoadInt64(&calls)
  171. time.Sleep(200 * time.Millisecond)
  172. if got := atomic.LoadInt64(&calls) - recovered; got < 3 {
  173. t.Fatalf("calls after recovery = %d in 200ms, want >=3 (suppression not cleared)", got)
  174. }
  175. if sink.Health().WrittenCount == 0 {
  176. t.Fatalf("written_count should grow after recovery")
  177. }
  178. }
  179. // 健康路径不受影响:一直成功就永远不进入退避。
  180. func TestOpsSystemLogSinkHealthyPathNeverSuppressed(t *testing.T) {
  181. var calls int64
  182. repo := &opsRepoMock{
  183. BatchInsertSystemLogsFn: func(_ context.Context, inputs []*OpsInsertSystemLogInput) (int64, error) {
  184. atomic.AddInt64(&calls, 1)
  185. return int64(len(inputs)), nil
  186. },
  187. }
  188. sink := NewOpsSystemLogSink(repo)
  189. sink.batchSize = 1
  190. sink.flushInterval = 5 * time.Millisecond
  191. sink.flushBackoff = time.Hour
  192. sink.flushBackoffMax = time.Hour
  193. sink.Start()
  194. defer sink.Stop()
  195. pumpOpsSystemLogEvents(t, sink)
  196. if !waitForOpsSystemLogCondition(t, 3*time.Second, func() bool { return atomic.LoadInt64(&calls) >= 10 }) {
  197. t.Fatalf("healthy sink should keep flushing, calls=%d", atomic.LoadInt64(&calls))
  198. }
  199. if got := sink.Health().DroppedCount; got != 0 {
  200. t.Fatalf("healthy sink dropped_count = %d, want 0", got)
  201. }
  202. }