search

riverqueue / river

Fast and reliable background jobs in Go
https://riverqueue.com
Mozilla Public License 2.0
3.37k stars 89 forks source link

Intermittent test failure: `TestPeriodicJobEnqueuer/EnqueuesPeriodicJobs` #215

Closed brandur closed 6 months ago

brandur commented 7 months ago

Another intermittent failure. This time in the periodic job enqueuer.

Sample failure run:

https://github.com/riverqueue/river/actions/runs/7956225078/job/21716534964?pr=214

--- FAIL: TestPeriodicJobEnqueuer (0.00s)
    --- FAIL: TestPeriodicJobEnqueuer/EnqueuesPeriodicJobs (1.57s)
        logger.go:225: time=2024-02-19T07:53:42.969Z level=INFO msg="PeriodicJobEnqueuer: Run loop started"
        periodic_job_enqueuer_test.go:112: 
                Error Trace:    /home/runner/work/river/river/internal/maintenance/periodic_job_enqueuer_test.go:82
                                            /home/runner/work/river/river/internal/maintenance/periodic_job_enqueuer_test.go:112
                Error:          "[%!s(*dbsqlc.RiverJob=&{45 [1[23](https://github.com/riverqueue/river/actions/runs/7956225078/job/21716534964?pr=214#step:8:24) 125] 0 <nil> [] {482531000 63843926023 0x107e100} [] <nil> periodic_job_500ms 25 [123 125] 1 default available {482709000 63843926023 0x107e100} []}) %!s(*dbsqlc.RiverJob=&{46 [123 125] 0 <nil> [] {983499000 63843926023 0x107e100} [] <nil> periodic_job_500ms 25 [123 125] 1 default available {983650000 63843926023 0x107e100} []})]" should have 3 item(s), but has 2
                Test:           TestPeriodicJobEnqueuer/EnqueuesPeriodicJobs
                Messages:       Expected to find exactly 3 job(s) of kind: periodic_job_500ms, but found 2
        logger.go:225: time=20[24](https://github.com/riverqueue/river/actions/runs/7956225078/job/21716534964?pr=214#step:8:25)-02-19T07:53:44.472Z level=INFO msg="PeriodicJobEnqueuer: Run loop stopped"
FAIL
FAIL    github.com/riverqueue/river/internal/maintenance    1.761s
brandur commented 6 months ago

Sigh, I saw this again [1]:

--- FAIL: TestPeriodicJobEnqueuer (0.00s)
    --- FAIL: TestPeriodicJobEnqueuer/EnqueuesPeriodicJobs (1.60s)
        logger.go:225: time=2024-03-08T01:[21](https://github.com/riverqueue/river/actions/runs/8197155842/job/22418957742#step:8:22):25.764Z level=INFO msg="PeriodicJobEnqueuer: Run loop started"
        periodic_job_enqueuer_test.go:110: 
                Error Trace:    /home/runner/work/river/river/internal/maintenance/periodic_job_enqueuer_test.go:80
                                            /home/runner/work/river/river/internal/maintenance/periodic_job_enqueuer_test.go:110
                Error:          "[0xc00012e7e0 0xc00012eea0]" should have 3 item(s), but has 2
                Test:           TestPeriodicJobEnqueuer/EnqueuesPeriodicJobs
                Messages:       Expected to find exactly 3 job(s) of kind: periodic_job_500ms, but found 2
        logger.go:[22](https://github.com/riverqueue/river/actions/runs/8197155842/job/22418957742#step:8:23)5: time=20[24](https://github.com/riverqueue/river/actions/runs/8197155842/job/22418957742#step:8:25)-03-08T01:21:27.[26](https://github.com/riverqueue/river/actions/runs/8197155842/job/22418957742#step:8:27)6Z level=INFO msg="PeriodicJobEnqueuer: Run loop stopped"
FAIL

It does seem to happen less often now. This is the first time I've seen it since I pushed that fix last week.

[1] https://github.com/riverqueue/river/actions/runs/8197155842/job/22418957742

brandur commented 6 months ago

This one is now our most common intermittent error. Saw it ~3 times today.