scheduler_snapshot_outbox_cleanup_test.go 28 KB

123456789101112131415161718192021222324252627282930313233343536373839404142434445464748495051525354555657585960616263646566676869707172737475767778798081828384858687888990919293949596979899100101102103104105106107108109110111112113114115116117118119120121122123124125126127128129130131132133134135136137138139140141142143144145146147148149150151152153154155156157158159160161162163164165166167168169170171172173174175176177178179180181182183184185186187188189190191192193194195196197198199200201202203204205206207208209210211212213214215216217218219220221222223224225226227228229230231232233234235236237238239240241242243244245246247248249250251252253254255256257258259260261262263264265266267268269270271272273274275276277278279280281282283284285286287288289290291292293294295296297298299300301302303304305306307308309310311312313314315316317318319320321322323324325326327328329330331332333334335336337338339340341342343344345346347348349350351352353354355356357358359360361362363364365366367368369370371372373374375376377378379380381382383384385386387388389390391392393394395396397398399400401402403404405406407408409410411412413414415416417418419420421422423424425426427428429430431432433434435436437438439440441442443444445446447448449450451452453454455456457458459460461462463464465466467468469470471472473474475476477478479480481482483484485486487488489490491492493494495496497498499500501502503504505506507508509510511512513514515516517518519520521522523524525526527528529530531532533534535536537538539540541542543544545546547548549550551552553554555556557558559560561562563564565566567568569570571572573574575576577578579580581582583584585586587588589590591592593594595596597598599600601602603604605606607608609610611612613614615616617618619620621622623624625626627628629630631632633634635636637638639640641642643644645646647648649650651652653654655656657658659660661662663664665666667668669670671672673674675676677678679680681682683684685686687688689690691692693694695696697698699700701702703704705706707708709710711712713714715716717718719720721722723724725726727728729730731732733734735736737738739740741742743744745746747748749750751752753754755756757758759760761762763764765766767768769770771772773774775776777778779780781782783784785786787788789790791792793794795796797798799800801802803804805806807808809810811812813814815816817818819820821822823824825826827828829830831832833834835836837838839840841842843844845846847848849850851852853854855856857858859860861862863864865866867868869870871872873874875876877878879880881882883884885886887888889890891892893894
  1. package service
  2. import (
  3. "context"
  4. "errors"
  5. "reflect"
  6. "sync"
  7. "testing"
  8. "time"
  9. "github.com/Wei-Shaw/sub2api/internal/config"
  10. )
  11. type outboxCleanupCache struct {
  12. watermark int64
  13. setWatermarks []int64
  14. updateErr error
  15. listBucketErr error
  16. listBuckets []SchedulerBucket
  17. listBucketCalls int
  18. }
  19. func (c *outboxCleanupCache) GetSnapshot(ctx context.Context, bucket SchedulerBucket) ([]*Account, bool, error) {
  20. return nil, false, nil
  21. }
  22. func (c *outboxCleanupCache) CaptureBucketWriteToken(ctx context.Context, bucket SchedulerBucket) (SchedulerBucketWriteToken, error) {
  23. return SchedulerBucketWriteToken{Bucket: bucket, Epoch: 1}, nil
  24. }
  25. func (c *outboxCleanupCache) SetSnapshot(ctx context.Context, bucket SchedulerBucket, token SchedulerBucketWriteToken, accounts []Account) error {
  26. return nil
  27. }
  28. func (c *outboxCleanupCache) RetireBucket(ctx context.Context, bucket SchedulerBucket) error {
  29. return nil
  30. }
  31. func (c *outboxCleanupCache) ReopenBucket(ctx context.Context, bucket SchedulerBucket) (SchedulerBucketWriteToken, error) {
  32. return SchedulerBucketWriteToken{Bucket: bucket, Epoch: 1}, nil
  33. }
  34. func (c *outboxCleanupCache) TryAcquireGroupLifecycleLease(context.Context, int64, time.Duration) (SchedulerGroupLifecycleLease, bool, error) {
  35. return SchedulerGroupLifecycleLease{}, false, nil
  36. }
  37. func (c *outboxCleanupCache) ReleaseGroupLifecycleLease(context.Context, SchedulerGroupLifecycleLease) error {
  38. return nil
  39. }
  40. func (c *outboxCleanupCache) GetAccount(ctx context.Context, accountID int64) (*Account, error) {
  41. return nil, nil
  42. }
  43. func (c *outboxCleanupCache) SetAccount(ctx context.Context, account *Account) error {
  44. return nil
  45. }
  46. func (c *outboxCleanupCache) DeleteAccount(ctx context.Context, accountID int64) error {
  47. return nil
  48. }
  49. func (c *outboxCleanupCache) UpdateLastUsed(ctx context.Context, updates map[int64]time.Time) error {
  50. return c.updateErr
  51. }
  52. func (c *outboxCleanupCache) TryLockBucket(ctx context.Context, bucket SchedulerBucket, ttl time.Duration) (bool, error) {
  53. return true, nil
  54. }
  55. func (c *outboxCleanupCache) UnlockBucket(ctx context.Context, bucket SchedulerBucket) error {
  56. return nil
  57. }
  58. func (c *outboxCleanupCache) ListBuckets(ctx context.Context) ([]SchedulerBucket, error) {
  59. c.listBucketCalls++
  60. return c.listBuckets, c.listBucketErr
  61. }
  62. func (c *outboxCleanupCache) GetOutboxWatermark(ctx context.Context) (int64, error) {
  63. return c.watermark, nil
  64. }
  65. func (c *outboxCleanupCache) SetOutboxWatermark(ctx context.Context, id int64) error {
  66. c.watermark = id
  67. c.setWatermarks = append(c.setWatermarks, id)
  68. return nil
  69. }
  70. type outboxCleanupDeleteCall struct {
  71. watermark int64
  72. limit int
  73. }
  74. type outboxCleanupRepo struct {
  75. events []SchedulerOutboxEvent
  76. rows []int64
  77. maxIDCalls int
  78. maxIDErr error
  79. lockAcquired bool
  80. lockAttempts int
  81. releaseCount int
  82. deleteCalls []outboxCleanupDeleteCall
  83. firstCreatedAfterID []int64
  84. }
  85. type outboxCleanupAccountRepo struct {
  86. AccountRepository
  87. }
  88. func (r *outboxCleanupAccountRepo) ListSchedulableUngroupedByPlatform(context.Context, string) ([]Account, error) {
  89. return nil, nil
  90. }
  91. type blockingOutboxCleanupCache struct {
  92. *outboxCleanupCache
  93. mu sync.Mutex
  94. calls int
  95. started chan struct{}
  96. release chan struct{}
  97. }
  98. func (c *blockingOutboxCleanupCache) ListBuckets(context.Context) ([]SchedulerBucket, error) {
  99. c.mu.Lock()
  100. c.calls++
  101. call := c.calls
  102. c.mu.Unlock()
  103. if call == 1 {
  104. close(c.started)
  105. <-c.release
  106. }
  107. return c.listBuckets, c.listBucketErr
  108. }
  109. func (c *blockingOutboxCleanupCache) listCalls() int {
  110. c.mu.Lock()
  111. defer c.mu.Unlock()
  112. return c.calls
  113. }
  114. func (r *outboxCleanupRepo) ListAfterAndReleaseDedup(ctx context.Context, afterID int64, limit int) ([]SchedulerOutboxEvent, error) {
  115. events := make([]SchedulerOutboxEvent, 0, len(r.events))
  116. for _, event := range r.events {
  117. if event.ID <= afterID {
  118. continue
  119. }
  120. events = append(events, event)
  121. if limit > 0 && len(events) >= limit {
  122. break
  123. }
  124. }
  125. return events, nil
  126. }
  127. func (r *outboxCleanupRepo) FirstCreatedAtAfter(ctx context.Context, afterID int64) (time.Time, bool, error) {
  128. r.firstCreatedAfterID = append(r.firstCreatedAfterID, afterID)
  129. for _, event := range r.events {
  130. if event.ID > afterID {
  131. return event.CreatedAt, true, nil
  132. }
  133. }
  134. return time.Time{}, false, nil
  135. }
  136. func (r *outboxCleanupRepo) MaxID(ctx context.Context) (int64, error) {
  137. r.maxIDCalls++
  138. if r.maxIDErr != nil {
  139. return 0, r.maxIDErr
  140. }
  141. var maxID int64
  142. for _, id := range r.rows {
  143. if id > maxID {
  144. maxID = id
  145. }
  146. }
  147. return maxID, nil
  148. }
  149. func (r *outboxCleanupRepo) DeleteConsumedUpTo(ctx context.Context, watermark int64, limit int) (int64, error) {
  150. r.deleteCalls = append(r.deleteCalls, outboxCleanupDeleteCall{
  151. watermark: watermark,
  152. limit: limit,
  153. })
  154. if watermark <= 0 || limit <= 0 {
  155. return 0, nil
  156. }
  157. deleted := int64(0)
  158. kept := make([]int64, 0, len(r.rows))
  159. for _, id := range r.rows {
  160. if id <= watermark && deleted < int64(limit) {
  161. deleted++
  162. continue
  163. }
  164. kept = append(kept, id)
  165. }
  166. r.rows = kept
  167. return deleted, nil
  168. }
  169. func (r *outboxCleanupRepo) TryAcquireCleanupLock(ctx context.Context) (SchedulerOutboxCleanupLease, bool, error) {
  170. r.lockAttempts++
  171. if !r.lockAcquired {
  172. return nil, false, nil
  173. }
  174. return outboxCleanupLease{release: func() {
  175. r.releaseCount++
  176. }}, true, nil
  177. }
  178. type outboxCleanupLease struct {
  179. release func()
  180. }
  181. func (l outboxCleanupLease) Release() {
  182. if l.release != nil {
  183. l.release()
  184. }
  185. }
  186. func TestSchedulerSnapshotServicePollOutboxCleansConsumedRowsAfterWatermark(t *testing.T) {
  187. cache := &outboxCleanupCache{}
  188. repo := &outboxCleanupRepo{
  189. events: []SchedulerOutboxEvent{
  190. {ID: 10000, EventType: SchedulerOutboxEventAccountLastUsed},
  191. },
  192. rows: int64Range(1, 10003),
  193. lockAcquired: true,
  194. }
  195. svc := NewSchedulerSnapshotService(cache, repo, nil, nil, nil)
  196. svc.pollOutbox()
  197. if cache.watermark != 10000 {
  198. t.Fatalf("expected watermark 10000, got %d", cache.watermark)
  199. }
  200. if !reflect.DeepEqual(cache.setWatermarks, []int64{10000}) {
  201. t.Fatalf("unexpected watermark writes: %#v", cache.setWatermarks)
  202. }
  203. if !reflect.DeepEqual(repo.rows, []int64{10001, 10002, 10003}) {
  204. t.Fatalf("expected rows above watermark to remain, got %#v", repo.rows)
  205. }
  206. if repo.lockAttempts != 1 || repo.releaseCount != 1 {
  207. t.Fatalf("expected one lock acquire/release, got acquire=%d release=%d", repo.lockAttempts, repo.releaseCount)
  208. }
  209. if len(repo.deleteCalls) != 3 {
  210. t.Fatalf("expected cleanup to loop until a short batch, got %d calls", len(repo.deleteCalls))
  211. }
  212. for _, call := range repo.deleteCalls {
  213. if call.watermark != 10000 || call.limit != schedulerOutboxCleanupBatch {
  214. t.Fatalf("unexpected cleanup call: %#v", call)
  215. }
  216. }
  217. }
  218. func TestSchedulerSnapshotServicePollOutboxSkipsCleanupWhenLockUnavailable(t *testing.T) {
  219. cache := &outboxCleanupCache{}
  220. repo := &outboxCleanupRepo{
  221. events: []SchedulerOutboxEvent{
  222. {ID: 3, EventType: SchedulerOutboxEventAccountLastUsed},
  223. },
  224. rows: []int64{1, 2, 3, 4},
  225. lockAcquired: false,
  226. }
  227. svc := NewSchedulerSnapshotService(cache, repo, nil, nil, nil)
  228. svc.pollOutbox()
  229. if cache.watermark != 3 {
  230. t.Fatalf("expected watermark 3, got %d", cache.watermark)
  231. }
  232. if !reflect.DeepEqual(repo.rows, []int64{1, 2, 3, 4}) {
  233. t.Fatalf("expected cleanup to skip all rows, got %#v", repo.rows)
  234. }
  235. if repo.lockAttempts != 1 {
  236. t.Fatalf("expected one lock attempt, got %d", repo.lockAttempts)
  237. }
  238. if len(repo.deleteCalls) != 0 {
  239. t.Fatalf("expected no delete calls, got %#v", repo.deleteCalls)
  240. }
  241. if repo.releaseCount != 0 {
  242. t.Fatalf("expected no release without lock, got %d", repo.releaseCount)
  243. }
  244. }
  245. func TestSchedulerSnapshotServicePollOutboxDoesNotCleanupOnHandleFailure(t *testing.T) {
  246. cache := &outboxCleanupCache{
  247. updateErr: errors.New("cache update failed"),
  248. }
  249. repo := &outboxCleanupRepo{
  250. events: []SchedulerOutboxEvent{
  251. {
  252. ID: 5,
  253. EventType: SchedulerOutboxEventAccountLastUsed,
  254. Payload: map[string]any{
  255. "last_used": map[string]any{"101": float64(123)},
  256. },
  257. },
  258. },
  259. rows: []int64{1, 2, 3, 4, 5, 6},
  260. lockAcquired: true,
  261. }
  262. svc := NewSchedulerSnapshotService(cache, repo, nil, nil, nil)
  263. svc.pollOutbox()
  264. if len(cache.setWatermarks) != 0 {
  265. t.Fatalf("expected no watermark write on handle failure, got %#v", cache.setWatermarks)
  266. }
  267. if repo.lockAttempts != 0 {
  268. t.Fatalf("expected cleanup lock not to be attempted, got %d", repo.lockAttempts)
  269. }
  270. if len(repo.deleteCalls) != 0 {
  271. t.Fatalf("expected no delete calls, got %#v", repo.deleteCalls)
  272. }
  273. if !reflect.DeepEqual(repo.rows, []int64{1, 2, 3, 4, 5, 6}) {
  274. t.Fatalf("expected rows unchanged, got %#v", repo.rows)
  275. }
  276. }
  277. func TestSchedulerSnapshotServicePollOutboxDoesNotUseConsumedEventForLag(t *testing.T) {
  278. cache := &outboxCleanupCache{}
  279. repo := &outboxCleanupRepo{
  280. events: []SchedulerOutboxEvent{
  281. {
  282. ID: 7,
  283. EventType: SchedulerOutboxEventAccountLastUsed,
  284. CreatedAt: time.Now().Add(-time.Hour),
  285. },
  286. },
  287. }
  288. cfg := &config.Config{
  289. Gateway: config.GatewayConfig{
  290. Scheduling: config.GatewaySchedulingConfig{
  291. OutboxLagWarnSeconds: 1,
  292. OutboxLagRebuildSeconds: 1,
  293. OutboxLagRebuildFailures: 1,
  294. },
  295. },
  296. }
  297. svc := NewSchedulerSnapshotService(cache, repo, nil, nil, cfg)
  298. svc.pollOutbox()
  299. if cache.watermark != 7 {
  300. t.Fatalf("expected watermark 7, got %d", cache.watermark)
  301. }
  302. if !reflect.DeepEqual(repo.firstCreatedAfterID, []int64{7}) {
  303. t.Fatalf("expected lag check after consumed watermark, got %#v", repo.firstCreatedAfterID)
  304. }
  305. if cache.listBucketCalls != 0 {
  306. t.Fatalf("expected consumed event not to trigger full rebuild, got %d attempts", cache.listBucketCalls)
  307. }
  308. if svc.lagFailures != 0 {
  309. t.Fatalf("expected lag failures to remain reset, got %d", svc.lagFailures)
  310. }
  311. }
  312. func TestSchedulerSnapshotServiceCheckOutboxLagLatchesPersistentDegradation(t *testing.T) {
  313. tests := []struct {
  314. name string
  315. createdAt time.Time
  316. rows []int64
  317. lagSeconds int
  318. backlogThreshold int
  319. }{
  320. {
  321. name: "lag",
  322. createdAt: time.Now().Add(-time.Hour),
  323. rows: []int64{1},
  324. lagSeconds: 1,
  325. },
  326. {
  327. name: "backlog",
  328. createdAt: time.Now(),
  329. rows: []int64{100},
  330. backlogThreshold: 50,
  331. },
  332. {
  333. name: "lag_and_backlog",
  334. createdAt: time.Now().Add(-time.Hour),
  335. rows: []int64{100},
  336. lagSeconds: 1,
  337. backlogThreshold: 50,
  338. },
  339. }
  340. for _, tt := range tests {
  341. t.Run(tt.name, func(t *testing.T) {
  342. cache := &outboxCleanupCache{listBuckets: []SchedulerBucket{{Platform: PlatformOpenAI, Mode: SchedulerModeSingle}}}
  343. repo := &outboxCleanupRepo{
  344. events: []SchedulerOutboxEvent{{ID: 1, CreatedAt: tt.createdAt}},
  345. rows: tt.rows,
  346. }
  347. cfg := &config.Config{
  348. Gateway: config.GatewayConfig{
  349. Scheduling: config.GatewaySchedulingConfig{
  350. OutboxLagRebuildSeconds: tt.lagSeconds,
  351. OutboxLagRebuildFailures: 1,
  352. OutboxBacklogRebuildRows: tt.backlogThreshold,
  353. },
  354. },
  355. }
  356. svc := NewSchedulerSnapshotService(cache, repo, &outboxCleanupAccountRepo{}, nil, cfg)
  357. for range 3 {
  358. svc.checkOutboxLag(context.Background(), 0)
  359. }
  360. if cache.listBucketCalls != 1 {
  361. t.Fatalf("expected one rebuild attempt during a persistent degraded episode, got %d", cache.listBucketCalls)
  362. }
  363. })
  364. }
  365. }
  366. func TestSchedulerSnapshotServiceCheckOutboxLagFailedRebuildRearmsAfterRecovery(t *testing.T) {
  367. cache := &outboxCleanupCache{listBucketErr: errors.New("list buckets failed")}
  368. repo := &outboxCleanupRepo{
  369. events: []SchedulerOutboxEvent{{ID: 1, CreatedAt: time.Now().Add(-time.Hour)}},
  370. rows: []int64{1},
  371. }
  372. cfg := &config.Config{
  373. Gateway: config.GatewayConfig{
  374. Scheduling: config.GatewaySchedulingConfig{
  375. OutboxLagRebuildSeconds: 1,
  376. OutboxLagRebuildFailures: 1,
  377. },
  378. },
  379. }
  380. svc := NewSchedulerSnapshotService(cache, repo, nil, nil, cfg)
  381. svc.checkOutboxLag(context.Background(), 0)
  382. svc.checkOutboxLag(context.Background(), 0)
  383. if cache.listBucketCalls != 1 {
  384. t.Fatalf("expected a failed rebuild to stay bounded within the episode, got %d attempts", cache.listBucketCalls)
  385. }
  386. svc.checkOutboxLag(context.Background(), 1)
  387. repo.events = append(repo.events, SchedulerOutboxEvent{ID: 2, CreatedAt: time.Now().Add(-time.Hour)})
  388. repo.rows = []int64{2}
  389. svc.checkOutboxLag(context.Background(), 1)
  390. if cache.listBucketCalls != 2 {
  391. t.Fatalf("expected recovery to rearm a failed rebuild for the next episode, got %d attempts", cache.listBucketCalls)
  392. }
  393. }
  394. func TestSchedulerSnapshotServiceCheckOutboxLagFailedRebuildRetriesAfterCooldownWithoutRecovery(t *testing.T) {
  395. cache := &outboxCleanupCache{
  396. listBucketErr: errors.New("list buckets failed"),
  397. listBuckets: []SchedulerBucket{{Platform: PlatformOpenAI, Mode: SchedulerModeSingle}},
  398. }
  399. repo := &outboxCleanupRepo{
  400. events: []SchedulerOutboxEvent{{ID: 1, CreatedAt: time.Now().Add(-time.Hour)}},
  401. rows: []int64{1},
  402. }
  403. cfg := &config.Config{
  404. Gateway: config.GatewayConfig{
  405. Scheduling: config.GatewaySchedulingConfig{
  406. OutboxLagRebuildSeconds: 1,
  407. OutboxLagRebuildFailures: 1,
  408. FullRebuildIntervalSeconds: 0,
  409. },
  410. },
  411. }
  412. svc := NewSchedulerSnapshotService(cache, repo, &outboxCleanupAccountRepo{}, nil, cfg)
  413. svc.checkOutboxLag(context.Background(), 0)
  414. for range 3 {
  415. svc.checkOutboxLag(context.Background(), 0)
  416. }
  417. if cache.listBucketCalls != 1 {
  418. t.Fatalf("expected failed rebuild polls to be rate limited, got %d attempts", cache.listBucketCalls)
  419. }
  420. svc.lagMu.Lock()
  421. if !svc.outboxRebuildRetryAt.After(time.Now()) {
  422. t.Fatal("expected failed rebuild to schedule a future retry")
  423. }
  424. svc.outboxRebuildRetryAt = time.Now().Add(-time.Second)
  425. svc.lagMu.Unlock()
  426. svc.checkOutboxLag(context.Background(), 0)
  427. if cache.listBucketCalls != 2 {
  428. t.Fatalf("expected persistent degradation to retry after cooldown, got %d attempts", cache.listBucketCalls)
  429. }
  430. for range 3 {
  431. svc.checkOutboxLag(context.Background(), 0)
  432. }
  433. if cache.listBucketCalls != 2 {
  434. t.Fatalf("expected repeated rebuild failures to stay rate limited, got %d attempts", cache.listBucketCalls)
  435. }
  436. svc.lagMu.Lock()
  437. svc.outboxRebuildRetryAt = time.Now().Add(-time.Second)
  438. svc.lagMu.Unlock()
  439. cache.listBucketErr = nil
  440. svc.checkOutboxLag(context.Background(), 0)
  441. if cache.listBucketCalls != 3 {
  442. t.Fatalf("expected degraded episode to retry after cooldown, got %d attempts", cache.listBucketCalls)
  443. }
  444. for range 3 {
  445. svc.checkOutboxLag(context.Background(), 0)
  446. }
  447. if cache.listBucketCalls != 3 {
  448. t.Fatalf("expected successful retry to latch the degraded episode, got %d attempts", cache.listBucketCalls)
  449. }
  450. }
  451. func TestSchedulerSnapshotServiceCheckOutboxLagBacklogRetryDoesNotBypassNewLagThreshold(t *testing.T) {
  452. cache := &outboxCleanupCache{listBucketErr: errors.New("list buckets failed")}
  453. repo := &outboxCleanupRepo{
  454. events: []SchedulerOutboxEvent{{ID: 1, CreatedAt: time.Now()}},
  455. rows: []int64{100},
  456. }
  457. cfg := &config.Config{
  458. Gateway: config.GatewayConfig{
  459. Scheduling: config.GatewaySchedulingConfig{
  460. OutboxLagRebuildSeconds: 1,
  461. OutboxLagRebuildFailures: 3,
  462. OutboxBacklogRebuildRows: 50,
  463. },
  464. },
  465. }
  466. svc := NewSchedulerSnapshotService(cache, repo, nil, nil, cfg)
  467. // Start with backlog-only degradation and leave its failed rebuild retry due.
  468. svc.checkOutboxLag(context.Background(), 0)
  469. if cache.listBucketCalls != 1 {
  470. t.Fatalf("expected the backlog degradation to attempt one rebuild, got %d", cache.listBucketCalls)
  471. }
  472. svc.lagMu.Lock()
  473. svc.outboxRebuildRetryAt = time.Now().Add(-time.Second)
  474. svc.lagMu.Unlock()
  475. // The backlog recovers while lag becomes newly degraded. The stale backlog
  476. // retry must not make the first lag observation bypass its failure threshold.
  477. repo.rows = []int64{1}
  478. repo.events[0].CreatedAt = time.Now().Add(-time.Hour)
  479. svc.checkOutboxLag(context.Background(), 0)
  480. if cache.listBucketCalls != 1 {
  481. t.Fatalf("expected the new lag episode to start at its own threshold, got %d rebuild attempts", cache.listBucketCalls)
  482. }
  483. svc.checkOutboxLag(context.Background(), 0)
  484. svc.checkOutboxLag(context.Background(), 0)
  485. if cache.listBucketCalls != 2 {
  486. t.Fatalf("expected lag rebuild only after three lag observations, got %d attempts", cache.listBucketCalls)
  487. }
  488. }
  489. func TestSchedulerSnapshotServiceCheckOutboxLagLagRetryDoesNotDelayOrEscalateNewBacklog(t *testing.T) {
  490. cache := &outboxCleanupCache{listBucketErr: errors.New("list buckets failed")}
  491. repo := &outboxCleanupRepo{
  492. events: []SchedulerOutboxEvent{{ID: 1, CreatedAt: time.Now().Add(-time.Hour)}},
  493. rows: []int64{1},
  494. }
  495. cfg := &config.Config{
  496. Gateway: config.GatewayConfig{
  497. Scheduling: config.GatewaySchedulingConfig{
  498. OutboxLagRebuildSeconds: 1,
  499. OutboxLagRebuildFailures: 1,
  500. OutboxBacklogRebuildRows: 50,
  501. },
  502. },
  503. }
  504. svc := NewSchedulerSnapshotService(cache, repo, nil, nil, cfg)
  505. // Start with lag-only degradation and a failed rebuild in cooldown.
  506. svc.checkOutboxLag(context.Background(), 0)
  507. if cache.listBucketCalls != 1 {
  508. t.Fatalf("expected the lag degradation to attempt one rebuild, got %d", cache.listBucketCalls)
  509. }
  510. // Lag recovers while backlog becomes newly degraded. It must start immediately
  511. // and its first failure must use the base retry generation, not lag's count.
  512. repo.events[0].CreatedAt = time.Now()
  513. repo.rows = []int64{100}
  514. svc.checkOutboxLag(context.Background(), 0)
  515. if cache.listBucketCalls != 2 {
  516. t.Fatalf("expected the new backlog degradation not to inherit lag cooldown, got %d rebuild attempts", cache.listBucketCalls)
  517. }
  518. svc.lagMu.Lock()
  519. failures := svc.outboxRebuildFailures
  520. svc.lagMu.Unlock()
  521. if failures != 1 {
  522. t.Fatalf("expected backlog retry failures to restart at one, got %d", failures)
  523. }
  524. }
  525. func TestSchedulerSnapshotServiceCheckOutboxLagBacklogRetrySurvivesUnknownBacklog(t *testing.T) {
  526. cache := &outboxCleanupCache{listBucketErr: errors.New("list buckets failed")}
  527. repo := &outboxCleanupRepo{
  528. events: []SchedulerOutboxEvent{{ID: 1, CreatedAt: time.Now()}},
  529. rows: []int64{100},
  530. }
  531. cfg := &config.Config{
  532. Gateway: config.GatewayConfig{
  533. Scheduling: config.GatewaySchedulingConfig{
  534. OutboxBacklogRebuildRows: 50,
  535. },
  536. },
  537. }
  538. svc := NewSchedulerSnapshotService(cache, repo, nil, nil, cfg)
  539. // A failed backlog rebuild starts a reason-scoped cooldown.
  540. svc.checkOutboxLag(context.Background(), 0)
  541. if cache.listBucketCalls != 1 {
  542. t.Fatalf("expected one initial backlog rebuild, got %d", cache.listBucketCalls)
  543. }
  544. svc.lagMu.Lock()
  545. retryAt := svc.outboxRebuildRetryAt
  546. svc.lagMu.Unlock()
  547. if !retryAt.After(time.Now()) {
  548. t.Fatalf("expected a future backlog retry, got %s", retryAt)
  549. }
  550. // A temporary MaxID failure makes backlog health unknown, not recovered.
  551. repo.maxIDErr = errors.New("max id unavailable")
  552. svc.checkOutboxLag(context.Background(), 0)
  553. svc.lagMu.Lock()
  554. retryReason := svc.outboxRebuildRetryReason
  555. failures := svc.outboxRebuildFailures
  556. retryAtAfterUnknown := svc.outboxRebuildRetryAt
  557. svc.lagMu.Unlock()
  558. if retryReason != "outbox_backlog" || failures != 1 || !retryAtAfterUnknown.Equal(retryAt) {
  559. t.Fatalf("expected unknown backlog to preserve retry state, got reason=%q failures=%d retry_at=%s", retryReason, failures, retryAtAfterUnknown)
  560. }
  561. // When MaxID recovers and backlog remains degraded, the original cooldown
  562. // still applies; only an expired cooldown may trigger the retry.
  563. repo.maxIDErr = nil
  564. svc.checkOutboxLag(context.Background(), 0)
  565. if cache.listBucketCalls != 1 {
  566. t.Fatalf("expected backlog recovery before cooldown to stay rate limited, got %d attempts", cache.listBucketCalls)
  567. }
  568. svc.lagMu.Lock()
  569. svc.outboxRebuildRetryAt = time.Now().Add(-time.Second)
  570. svc.lagMu.Unlock()
  571. svc.checkOutboxLag(context.Background(), 0)
  572. if cache.listBucketCalls != 2 {
  573. t.Fatalf("expected backlog retry after cooldown expiry, got %d attempts", cache.listBucketCalls)
  574. }
  575. }
  576. func TestSchedulerSnapshotServiceCheckOutboxLagPreemptsUnknownBacklogRetryAtThreshold(t *testing.T) {
  577. cache := &outboxCleanupCache{listBucketErr: errors.New("list buckets failed")}
  578. repo := &outboxCleanupRepo{
  579. events: []SchedulerOutboxEvent{{ID: 1, CreatedAt: time.Now()}},
  580. rows: []int64{100},
  581. }
  582. cfg := &config.Config{
  583. Gateway: config.GatewayConfig{
  584. Scheduling: config.GatewaySchedulingConfig{
  585. OutboxLagRebuildSeconds: 1,
  586. OutboxLagRebuildFailures: 3,
  587. OutboxBacklogRebuildRows: 50,
  588. },
  589. },
  590. }
  591. svc := NewSchedulerSnapshotService(cache, repo, nil, nil, cfg)
  592. // Backlog starts the first failed rebuild generation and remains unknown.
  593. svc.checkOutboxLag(context.Background(), 0)
  594. if cache.listBucketCalls != 1 {
  595. t.Fatalf("expected one initial backlog rebuild, got %d", cache.listBucketCalls)
  596. }
  597. repo.maxIDErr = errors.New("max id unavailable")
  598. repo.events[0].CreatedAt = time.Now().Add(-time.Hour)
  599. // A known lag degradation must keep accumulating independently of the active
  600. // backlog cooldown and preempt it only after reaching its own threshold.
  601. for observation := 1; observation <= 2; observation++ {
  602. svc.checkOutboxLag(context.Background(), 0)
  603. if cache.listBucketCalls != 1 {
  604. t.Fatalf("expected lag observation %d to stay below threshold, got %d rebuild attempts", observation, cache.listBucketCalls)
  605. }
  606. }
  607. svc.checkOutboxLag(context.Background(), 0)
  608. if cache.listBucketCalls != 2 {
  609. t.Fatalf("expected lag to preempt backlog cooldown at its threshold, got %d attempts", cache.listBucketCalls)
  610. }
  611. svc.lagMu.Lock()
  612. retryReason := svc.outboxRebuildRetryReason
  613. failures := svc.outboxRebuildFailures
  614. retryAt := svc.outboxRebuildRetryAt
  615. svc.lagMu.Unlock()
  616. if retryReason != "outbox_lag" || failures != 1 || !retryAt.After(time.Now()) {
  617. t.Fatalf("expected a fresh lag retry generation, got reason=%q failures=%d retry_at=%s", retryReason, failures, retryAt)
  618. }
  619. }
  620. func TestOutboxRebuildRetryDelayIsExponentiallyBounded(t *testing.T) {
  621. previous := time.Duration(0)
  622. for failures := 1; failures <= 20; failures++ {
  623. delay := outboxRebuildRetryDelay(failures)
  624. if delay < previous {
  625. t.Fatalf("expected retry delay to be monotonic, failure %d produced %s after %s", failures, delay, previous)
  626. }
  627. if delay > outboxRebuildRetryMaxDelay {
  628. t.Fatalf("expected retry delay to stay bounded, got %s", delay)
  629. }
  630. previous = delay
  631. }
  632. if previous != outboxRebuildRetryMaxDelay {
  633. t.Fatalf("expected repeated failures to reach max delay %s, got %s", outboxRebuildRetryMaxDelay, previous)
  634. }
  635. }
  636. func TestSchedulerSnapshotServicePollOutboxEmptyBatchClearsDegradedEpisode(t *testing.T) {
  637. cache := &outboxCleanupCache{listBuckets: []SchedulerBucket{{Platform: PlatformOpenAI, Mode: SchedulerModeSingle}}}
  638. repo := &outboxCleanupRepo{
  639. events: []SchedulerOutboxEvent{{ID: 1, CreatedAt: time.Now().Add(-time.Hour)}},
  640. rows: []int64{1},
  641. }
  642. cfg := &config.Config{
  643. Gateway: config.GatewayConfig{
  644. Scheduling: config.GatewaySchedulingConfig{
  645. OutboxLagRebuildSeconds: 1,
  646. OutboxLagRebuildFailures: 1,
  647. OutboxBacklogRebuildRows: 1,
  648. },
  649. },
  650. }
  651. svc := NewSchedulerSnapshotService(cache, repo, &outboxCleanupAccountRepo{}, nil, cfg)
  652. svc.checkOutboxLag(context.Background(), 0)
  653. cache.watermark = 1
  654. svc.pollOutbox()
  655. if !reflect.DeepEqual(repo.firstCreatedAfterID, []int64{0}) {
  656. t.Fatalf("expected empty poll to use the empty batch as recovery evidence, got watermarks %#v", repo.firstCreatedAfterID)
  657. }
  658. if repo.maxIDCalls != 1 {
  659. t.Fatalf("expected empty poll to skip a redundant backlog query, got %d health checks", repo.maxIDCalls)
  660. }
  661. repo.events = append(repo.events, SchedulerOutboxEvent{ID: 2, CreatedAt: time.Now().Add(-time.Hour)})
  662. repo.rows = []int64{2}
  663. svc.checkOutboxLag(context.Background(), 1)
  664. if cache.listBucketCalls != 2 {
  665. t.Fatalf("expected empty-poll recovery to rearm the next degraded episode, got %d attempts", cache.listBucketCalls)
  666. }
  667. }
  668. func TestSchedulerSnapshotServiceOutboxLagWarningIsTransitionLimited(t *testing.T) {
  669. svc := NewSchedulerSnapshotService(nil, nil, nil, nil, nil)
  670. if !svc.shouldLogOutboxLagWarning(true) {
  671. t.Fatal("expected the initial degraded transition to log")
  672. }
  673. if svc.shouldLogOutboxLagWarning(true) {
  674. t.Fatal("expected persistent degradation to suppress repeated warnings")
  675. }
  676. if svc.shouldLogOutboxLagWarning(true) {
  677. t.Fatal("expected persistent degradation to suppress repeated warnings")
  678. }
  679. if svc.shouldLogOutboxLagWarning(false) {
  680. t.Fatal("expected recovery not to emit a lag warning")
  681. }
  682. if !svc.shouldLogOutboxLagWarning(true) {
  683. t.Fatal("expected renewed degradation to log after recovery")
  684. }
  685. }
  686. func TestSchedulerSnapshotServiceCheckOutboxLagSamplesMaxIDErrors(t *testing.T) {
  687. svc := NewSchedulerSnapshotService(nil, nil, nil, nil, nil)
  688. now := time.Now()
  689. if !svc.shouldLogOutboxMaxIDError(now) {
  690. t.Fatal("expected the first MaxID error to log")
  691. }
  692. if svc.shouldLogOutboxMaxIDError(now.Add(outboxMaxIDErrorLogSampleInterval / 2)) {
  693. t.Fatal("expected MaxID errors inside the sample interval to be suppressed")
  694. }
  695. if !svc.shouldLogOutboxMaxIDError(now.Add(outboxMaxIDErrorLogSampleInterval)) {
  696. t.Fatal("expected MaxID error logging to rearm after the sample interval")
  697. }
  698. }
  699. func TestSchedulerSnapshotServicePollOutboxHealthyEmptyBatchSkipsLagHealthQueries(t *testing.T) {
  700. cache := &outboxCleanupCache{}
  701. repo := &outboxCleanupRepo{}
  702. cfg := &config.Config{
  703. Gateway: config.GatewayConfig{
  704. Scheduling: config.GatewaySchedulingConfig{
  705. OutboxLagRebuildSeconds: 1,
  706. OutboxLagRebuildFailures: 1,
  707. OutboxBacklogRebuildRows: 1,
  708. },
  709. },
  710. }
  711. svc := NewSchedulerSnapshotService(cache, repo, nil, nil, cfg)
  712. svc.pollOutbox()
  713. if len(repo.firstCreatedAfterID) != 0 {
  714. t.Fatalf("expected healthy empty poll to skip lag query, got watermarks %#v", repo.firstCreatedAfterID)
  715. }
  716. if repo.maxIDCalls != 0 {
  717. t.Fatalf("expected healthy empty poll to skip backlog query, got %d calls", repo.maxIDCalls)
  718. }
  719. }
  720. func TestSchedulerSnapshotServiceEmptyPollDoesNotReleaseRunningRebuild(t *testing.T) {
  721. baseCache := &outboxCleanupCache{
  722. watermark: 1,
  723. listBuckets: []SchedulerBucket{{Platform: PlatformOpenAI, Mode: SchedulerModeSingle}},
  724. }
  725. cache := &blockingOutboxCleanupCache{
  726. outboxCleanupCache: baseCache,
  727. started: make(chan struct{}),
  728. release: make(chan struct{}),
  729. }
  730. repo := &outboxCleanupRepo{
  731. events: []SchedulerOutboxEvent{{ID: 1, CreatedAt: time.Now().Add(-time.Hour)}},
  732. rows: []int64{1},
  733. }
  734. cfg := &config.Config{
  735. Gateway: config.GatewayConfig{
  736. Scheduling: config.GatewaySchedulingConfig{
  737. OutboxLagRebuildSeconds: 1,
  738. OutboxLagRebuildFailures: 1,
  739. },
  740. },
  741. }
  742. svc := NewSchedulerSnapshotService(cache, repo, &outboxCleanupAccountRepo{}, nil, cfg)
  743. firstDone := make(chan struct{})
  744. go func() {
  745. svc.checkOutboxLag(context.Background(), 0)
  746. close(firstDone)
  747. }()
  748. select {
  749. case <-cache.started:
  750. case <-time.After(time.Second):
  751. t.Fatal("first rebuild did not start")
  752. }
  753. // The empty batch proves recovery for episode/retry state, but it must not
  754. // release ownership of the still-running rebuild.
  755. svc.pollOutbox()
  756. secondDone := make(chan struct{})
  757. go func() {
  758. svc.checkOutboxLag(context.Background(), 0)
  759. close(secondDone)
  760. }()
  761. select {
  762. case <-secondDone:
  763. case <-time.After(200 * time.Millisecond):
  764. close(cache.release)
  765. <-firstDone
  766. <-secondDone
  767. t.Fatal("second lag check queued another rebuild while the first was running")
  768. }
  769. close(cache.release)
  770. <-firstDone
  771. if calls := cache.listCalls(); calls != 1 {
  772. t.Fatalf("expected one rebuild generation, got %d", calls)
  773. }
  774. }
  775. func TestSchedulerSnapshotServiceCleanupSkipsNonPositiveWatermark(t *testing.T) {
  776. repo := &outboxCleanupRepo{
  777. rows: []int64{1, 2, 3},
  778. lockAcquired: true,
  779. }
  780. svc := NewSchedulerSnapshotService(&outboxCleanupCache{}, repo, nil, nil, nil)
  781. svc.cleanupConsumedOutbox(0)
  782. if repo.lockAttempts != 0 {
  783. t.Fatalf("expected no lock attempt for non-positive watermark, got %d", repo.lockAttempts)
  784. }
  785. if len(repo.deleteCalls) != 0 {
  786. t.Fatalf("expected no delete calls, got %#v", repo.deleteCalls)
  787. }
  788. if !reflect.DeepEqual(repo.rows, []int64{1, 2, 3}) {
  789. t.Fatalf("expected rows unchanged, got %#v", repo.rows)
  790. }
  791. }
  792. func int64Range(start, end int64) []int64 {
  793. values := make([]int64, 0, end-start+1)
  794. for id := start; id <= end; id++ {
  795. values = append(values, id)
  796. }
  797. return values
  798. }