queue: Flaky test TestLevelQueue #7309

Closed
opened 2025-11-02 07:22:37 -06:00 by GiteaMirror · 0 comments
Owner

Originally created by @silverwind on GitHub (May 7, 2021).

Can reproduce this locally somewhat rarely. CI failure example:

$ while true; do go test -count=1 -run TestLevelQueue ./modules/queue; done
ok    code.gitea.io/gitea/modules/queue 0.457s
ok    code.gitea.io/gitea/modules/queue 0.452s
ok    code.gitea.io/gitea/modules/queue 0.445s
2021/05/07 19:46:40 ...les/queue/manager.go:134:Add() [T] Queue Manager registered: queue-1 (QID: 1)
2021/05/07 19:46:40 ...ue/queue_bytefifo.go:96:Run() [D] level:  Starting
2021/05/07 19:46:40 ...ue/queue_bytefifo.go:104:Run() [T] level:  Waiting til closed
2021/05/07 19:46:40 ...ue/queue_bytefifo.go:147:readToChan() [T] level : Task found: &queue.testData{TestString:"A", TestInt:1}
2021/05/07 19:46:40 .../queue/workerpool.go:251:commonRegisterWorkers() [T] WorkerPool: 1 (for queue-1) adding 1 workers with group id: 1
2021/05/07 19:46:40 .../queue/workerpool.go:93:zeroBoost() [W] WorkerPool: 1 (for queue-1) has zero workers - adding 5 temporary workers for 5m0s
2021/05/07 19:46:40 ...ue/queue_bytefifo.go:147:readToChan() [T] level : Task found: &queue.testData{TestString:"B", TestInt:2}
2021/05/07 19:46:40 .../queue/workerpool.go:420:doWork() [T] Handling: 1 data, [0xc00065edf8]
2021/05/07 19:46:40 .../queue/workerpool.go:420:doWork() [T] Handling: 1 data, [0xc00000ed98]
2021/05/07 19:46:40 ...ue/queue_bytefifo.go:156:Shutdown() [T] level:  Shutting down
2021/05/07 19:46:40 ...ue/queue_bytefifo.go:164:Shutdown() [D] level:  Shutdown
2021/05/07 19:46:40 ...ue/queue_bytefifo.go:106:Run() [T] level:  Waiting til done
2021/05/07 19:46:40 .../queue/workerpool.go:396:doWork() [T] Worker shutting down
2021/05/07 19:46:40 .../queue/workerpool.go:396:doWork() [T] Worker shutting down
2021/05/07 19:46:40 .../queue/workerpool.go:396:doWork() [T] Worker shutting down
2021/05/07 19:46:40 .../queue/workerpool.go:396:doWork() [T] Worker shutting down
2021/05/07 19:46:40 .../queue/workerpool.go:396:doWork() [T] Worker shutting down
2021/05/07 19:46:40 .../queue/workerpool.go:396:doWork() [T] Worker shutting down
2021/05/07 19:46:40 ...ue/queue_bytefifo.go:109:Run() [T] level:  Waiting til cleaned
2021/05/07 19:46:40 .../queue/workerpool.go:309:CleanUp() [T] WorkerPool: 1 CleanUp
2021/05/07 19:46:40 .../queue/workerpool.go:321:CleanUp() [T] WorkerPool: 1 CleanUp Done
2021/05/07 19:46:40 ...ue/queue_bytefifo.go:174:Terminate() [T] level:  Terminating
2021/05/07 19:46:40 ...ue/queue_bytefifo.go:156:Shutdown() [T] level:  Shutting down
2021/05/07 19:46:40 ...ue/queue_bytefifo.go:164:Shutdown() [D] level:  Shutdown
2021/05/07 19:46:40 ...ue/queue_bytefifo.go:186:Terminate() [D] level:  Closing with 2 tasks left in queue
2021/05/07 19:46:40 ...ue/queue_bytefifo.go:191:Terminate() [D] level:  Terminated
2021/05/07 19:46:41 ...les/queue/manager.go:134:Add() [T] Queue Manager registered: queue-2 (QID: 2)
2021/05/07 19:46:41 ...ue/queue_bytefifo.go:96:Run() [D] level:  Starting
2021/05/07 19:46:41 ...ue/queue_bytefifo.go:104:Run() [T] level:  Waiting til closed
2021/05/07 19:46:41 .../queue/workerpool.go:251:commonRegisterWorkers() [T] WorkerPool: 2 (for queue-2) adding 1 workers with group id: 1
2021/05/07 19:46:41 ...ue/queue_bytefifo.go:147:readToChan() [T] level : Task found: &queue.testData{TestString:"A", TestInt:1}
2021/05/07 19:46:41 ...ue/queue_bytefifo.go:147:readToChan() [T] level : Task found: &queue.testData{TestString:"B", TestInt:2}
2021/05/07 19:46:41 .../queue/workerpool.go:412:doWork() [T] Handling: 2 data, [0xc000d085d0 0xc000d08708]
2021/05/07 19:46:41 ...ue/queue_bytefifo.go:156:Shutdown() [T] level:  Shutting down
2021/05/07 19:46:41 ...ue/queue_bytefifo.go:164:Shutdown() [D] level:  Shutdown
2021/05/07 19:46:41 ...ue/queue_bytefifo.go:156:Shutdown() [T] level:  Shutting down
2021/05/07 19:46:41 ...ue/queue_bytefifo.go:164:Shutdown() [D] level:  Shutdown
2021/05/07 19:46:41 ...ue/queue_bytefifo.go:174:Terminate() [T] level:  Terminating
2021/05/07 19:46:41 ...ue/queue_bytefifo.go:156:Shutdown() [T] level:  Shutting down
2021/05/07 19:46:41 ...ue/queue_bytefifo.go:106:Run() [T] level:  Waiting til done
2021/05/07 19:46:41 ...ue/queue_bytefifo.go:164:Shutdown() [D] level:  Shutdown
2021/05/07 19:46:41 ...ue/queue_bytefifo.go:174:Terminate() [T] level:  Terminating
2021/05/07 19:46:41 ...ue/queue_bytefifo.go:156:Shutdown() [T] level:  Shutting down
2021/05/07 19:46:41 ...ue/queue_bytefifo.go:164:Shutdown() [D] level:  Shutdown
2021/05/07 19:46:41 ...ue/queue_bytefifo.go:186:Terminate() [D] level:  Closing with 0 tasks left in queue
2021/05/07 19:46:41 ...ue/queue_bytefifo.go:191:Terminate() [D] level:  Terminated
--- FAIL: TestLevelQueue (0.70s)
    queue_disk_test.go:21:
          Error Trace:  queue_disk_test.go:21
                              workerpool.go:421
                              workerpool.go:276
                              asm_amd64.s:1371
          Error:        Should be true
          Test:         TestLevelQueue
    queue_disk_test.go:21:
          Error Trace:  queue_disk_test.go:21
                              workerpool.go:421
                              workerpool.go:276
                              asm_amd64.s:1371
          Error:        Should be true
          Test:         TestLevelQueue
    queue_disk_test.go:73:
          Error Trace:  queue_disk_test.go:73
          Error:        Not equal:
                        expected: "A"
                        actual  : "B"

                        Diff:
                        --- Expected
                        +++ Actual
                        @@ -1 +1 @@
                        -A
                        +B
          Test:         TestLevelQueue
    queue_disk_test.go:74:
          Error Trace:  queue_disk_test.go:74
          Error:        Not equal:
                        expected: 1
                        actual  : 2
          Test:         TestLevelQueue
    queue_disk_test.go:77:
          Error Trace:  queue_disk_test.go:77
          Error:        Not equal:
                        expected: "B"
                        actual  : "A"

                        Diff:
                        --- Expected
                        +++ Actual
                        @@ -1 +1 @@
                        -B
                        +A
          Test:         TestLevelQueue
    queue_disk_test.go:78:
          Error Trace:  queue_disk_test.go:78
          Error:        Not equal:
                        expected: 2
                        actual  : 1
          Test:         TestLevelQueue
FAIL
FAIL  code.gitea.io/gitea/modules/queue 0.781s
FAIL
ok    code.gitea.io/gitea/modules/queue 0.444s
ok    code.gitea.io/gitea/modules/queue 0.485s
ok    code.gitea.io/gitea/modules/queue 0.450s
ok    code.gitea.io/gitea/modules/queue 0.449s
ok    code.gitea.io/gitea/modules/queue 0.448s
ok    code.gitea.io/gitea/modules/queue 0.445s
ok    code.gitea.io/gitea/modules/queue 0.445s
ok    code.gitea.io/gitea/modules/queue 0.442s
ok    code.gitea.io/gitea/modules/queue 0.449s
Originally created by @silverwind on GitHub (May 7, 2021). Can reproduce this locally somewhat rarely. [CI failure example](https://drone.gitea.io/go-gitea/gitea/39472/2/12): ```bash $ while true; do go test -count=1 -run TestLevelQueue ./modules/queue; done ok code.gitea.io/gitea/modules/queue 0.457s ok code.gitea.io/gitea/modules/queue 0.452s ok code.gitea.io/gitea/modules/queue 0.445s 2021/05/07 19:46:40 ...les/queue/manager.go:134:Add() [T] Queue Manager registered: queue-1 (QID: 1) 2021/05/07 19:46:40 ...ue/queue_bytefifo.go:96:Run() [D] level: Starting 2021/05/07 19:46:40 ...ue/queue_bytefifo.go:104:Run() [T] level: Waiting til closed 2021/05/07 19:46:40 ...ue/queue_bytefifo.go:147:readToChan() [T] level : Task found: &queue.testData{TestString:"A", TestInt:1} 2021/05/07 19:46:40 .../queue/workerpool.go:251:commonRegisterWorkers() [T] WorkerPool: 1 (for queue-1) adding 1 workers with group id: 1 2021/05/07 19:46:40 .../queue/workerpool.go:93:zeroBoost() [W] WorkerPool: 1 (for queue-1) has zero workers - adding 5 temporary workers for 5m0s 2021/05/07 19:46:40 ...ue/queue_bytefifo.go:147:readToChan() [T] level : Task found: &queue.testData{TestString:"B", TestInt:2} 2021/05/07 19:46:40 .../queue/workerpool.go:420:doWork() [T] Handling: 1 data, [0xc00065edf8] 2021/05/07 19:46:40 .../queue/workerpool.go:420:doWork() [T] Handling: 1 data, [0xc00000ed98] 2021/05/07 19:46:40 ...ue/queue_bytefifo.go:156:Shutdown() [T] level: Shutting down 2021/05/07 19:46:40 ...ue/queue_bytefifo.go:164:Shutdown() [D] level: Shutdown 2021/05/07 19:46:40 ...ue/queue_bytefifo.go:106:Run() [T] level: Waiting til done 2021/05/07 19:46:40 .../queue/workerpool.go:396:doWork() [T] Worker shutting down 2021/05/07 19:46:40 .../queue/workerpool.go:396:doWork() [T] Worker shutting down 2021/05/07 19:46:40 .../queue/workerpool.go:396:doWork() [T] Worker shutting down 2021/05/07 19:46:40 .../queue/workerpool.go:396:doWork() [T] Worker shutting down 2021/05/07 19:46:40 .../queue/workerpool.go:396:doWork() [T] Worker shutting down 2021/05/07 19:46:40 .../queue/workerpool.go:396:doWork() [T] Worker shutting down 2021/05/07 19:46:40 ...ue/queue_bytefifo.go:109:Run() [T] level: Waiting til cleaned 2021/05/07 19:46:40 .../queue/workerpool.go:309:CleanUp() [T] WorkerPool: 1 CleanUp 2021/05/07 19:46:40 .../queue/workerpool.go:321:CleanUp() [T] WorkerPool: 1 CleanUp Done 2021/05/07 19:46:40 ...ue/queue_bytefifo.go:174:Terminate() [T] level: Terminating 2021/05/07 19:46:40 ...ue/queue_bytefifo.go:156:Shutdown() [T] level: Shutting down 2021/05/07 19:46:40 ...ue/queue_bytefifo.go:164:Shutdown() [D] level: Shutdown 2021/05/07 19:46:40 ...ue/queue_bytefifo.go:186:Terminate() [D] level: Closing with 2 tasks left in queue 2021/05/07 19:46:40 ...ue/queue_bytefifo.go:191:Terminate() [D] level: Terminated 2021/05/07 19:46:41 ...les/queue/manager.go:134:Add() [T] Queue Manager registered: queue-2 (QID: 2) 2021/05/07 19:46:41 ...ue/queue_bytefifo.go:96:Run() [D] level: Starting 2021/05/07 19:46:41 ...ue/queue_bytefifo.go:104:Run() [T] level: Waiting til closed 2021/05/07 19:46:41 .../queue/workerpool.go:251:commonRegisterWorkers() [T] WorkerPool: 2 (for queue-2) adding 1 workers with group id: 1 2021/05/07 19:46:41 ...ue/queue_bytefifo.go:147:readToChan() [T] level : Task found: &queue.testData{TestString:"A", TestInt:1} 2021/05/07 19:46:41 ...ue/queue_bytefifo.go:147:readToChan() [T] level : Task found: &queue.testData{TestString:"B", TestInt:2} 2021/05/07 19:46:41 .../queue/workerpool.go:412:doWork() [T] Handling: 2 data, [0xc000d085d0 0xc000d08708] 2021/05/07 19:46:41 ...ue/queue_bytefifo.go:156:Shutdown() [T] level: Shutting down 2021/05/07 19:46:41 ...ue/queue_bytefifo.go:164:Shutdown() [D] level: Shutdown 2021/05/07 19:46:41 ...ue/queue_bytefifo.go:156:Shutdown() [T] level: Shutting down 2021/05/07 19:46:41 ...ue/queue_bytefifo.go:164:Shutdown() [D] level: Shutdown 2021/05/07 19:46:41 ...ue/queue_bytefifo.go:174:Terminate() [T] level: Terminating 2021/05/07 19:46:41 ...ue/queue_bytefifo.go:156:Shutdown() [T] level: Shutting down 2021/05/07 19:46:41 ...ue/queue_bytefifo.go:106:Run() [T] level: Waiting til done 2021/05/07 19:46:41 ...ue/queue_bytefifo.go:164:Shutdown() [D] level: Shutdown 2021/05/07 19:46:41 ...ue/queue_bytefifo.go:174:Terminate() [T] level: Terminating 2021/05/07 19:46:41 ...ue/queue_bytefifo.go:156:Shutdown() [T] level: Shutting down 2021/05/07 19:46:41 ...ue/queue_bytefifo.go:164:Shutdown() [D] level: Shutdown 2021/05/07 19:46:41 ...ue/queue_bytefifo.go:186:Terminate() [D] level: Closing with 0 tasks left in queue 2021/05/07 19:46:41 ...ue/queue_bytefifo.go:191:Terminate() [D] level: Terminated --- FAIL: TestLevelQueue (0.70s) queue_disk_test.go:21: Error Trace: queue_disk_test.go:21 workerpool.go:421 workerpool.go:276 asm_amd64.s:1371 Error: Should be true Test: TestLevelQueue queue_disk_test.go:21: Error Trace: queue_disk_test.go:21 workerpool.go:421 workerpool.go:276 asm_amd64.s:1371 Error: Should be true Test: TestLevelQueue queue_disk_test.go:73: Error Trace: queue_disk_test.go:73 Error: Not equal: expected: "A" actual : "B" Diff: --- Expected +++ Actual @@ -1 +1 @@ -A +B Test: TestLevelQueue queue_disk_test.go:74: Error Trace: queue_disk_test.go:74 Error: Not equal: expected: 1 actual : 2 Test: TestLevelQueue queue_disk_test.go:77: Error Trace: queue_disk_test.go:77 Error: Not equal: expected: "B" actual : "A" Diff: --- Expected +++ Actual @@ -1 +1 @@ -B +A Test: TestLevelQueue queue_disk_test.go:78: Error Trace: queue_disk_test.go:78 Error: Not equal: expected: 2 actual : 1 Test: TestLevelQueue FAIL FAIL code.gitea.io/gitea/modules/queue 0.781s FAIL ok code.gitea.io/gitea/modules/queue 0.444s ok code.gitea.io/gitea/modules/queue 0.485s ok code.gitea.io/gitea/modules/queue 0.450s ok code.gitea.io/gitea/modules/queue 0.449s ok code.gitea.io/gitea/modules/queue 0.448s ok code.gitea.io/gitea/modules/queue 0.445s ok code.gitea.io/gitea/modules/queue 0.445s ok code.gitea.io/gitea/modules/queue 0.442s ok code.gitea.io/gitea/modules/queue 0.449s ```
GiteaMirror added the type/testing label 2025-11-02 07:22:37 -06:00
Sign in to join this conversation.
1 Participants
Notifications
Due Date
No due date set.
Dependencies

No dependencies set.

Reference: github-starred/gitea#7309