search

spacemeshos / go-spacemesh

Go Implementation of the Spacemesh protocol full node. 💾⏰💪
https://spacemesh.io
MIT License
752 stars 212 forks source link

Flaky TestHare/with_proposals_subsets #6262

Open fasmat opened 2 months ago

fasmat commented 2 months ago

Description

Test keeps failing in unrelated changes, not just this sub test but others as well.

Affected code

TestHare/with_proposals_subsets and other subtests seems to be unstable. Example CI run: https://github.com/spacemeshos/go-spacemesh/actions/runs/10401090343/job/28802907577

=== FAIL: hare4 TestHare/with_proposals_subsets (11.10s)
2024-08-15T10:32:58.459+0200    INFO    hare4/hare.go:280   registered signing key  {"id": "892c51"}
2024-08-15T10:32:58.459+0200    INFO    hare4/hare.go:300   started {"enabled": false, "enabled layer": 0, "disabled layer": 4294967295, "committee": 50, "leaders": 5, "iterations limit": 4, "preround delay": "25s", "round duration": "12s", "log stats": true, "p2p protocol": "/h/4.0", "enabled": 8, "disabled": 4294967295}
2024-08-15T10:32:58.476+0200    INFO    hare4/hare.go:280   registered signing key  {"id": "bcc78c"}
2024-08-15T10:32:58.476+0200    INFO    hare4/hare.go:300   started {"enabled": false, "enabled layer": 0, "disabled layer": 4294967295, "committee": 50, "leaders": 5, "iterations limit": 4, "preround delay": "25s", "round duration": "12s", "log stats": true, "p2p protocol": "/h/4.0", "enabled": 8, "disabled": 4294967295}
2024-08-15T10:32:58.489+0200    INFO    hare4/hare.go:280   registered signing key  {"id": "5fd47e"}
2024-08-15T10:32:58.489+0200    INFO    hare4/hare.go:300   started {"enabled": false, "enabled layer": 0, "disabled layer": 4294967295, "committee": 50, "leaders": 5, "iterations limit": 4, "preround delay": "25s", "round duration": "12s", "log stats": true, "p2p protocol": "/h/4.0", "enabled": 8, "disabled": 4294967295}
2024-08-15T10:32:58.603+0200    INFO    hare4/hare.go:280   registered signing key  {"id": "906360"}
2024-08-15T10:32:58.603+0200    INFO    hare4/hare.go:300   started {"enabled": false, "enabled layer": 0, "disabled layer": 4294967295, "committee": 50, "leaders": 5, "iterations limit": 4, "preround delay": "25s", "round duration": "12s", "log stats": true, "p2p protocol": "/h/4.0", "enabled": 8, "disabled": 4294967295}
2024-08-15T10:32:58.616+0200    INFO    hare4/hare.go:280   registered signing key  {"id": "01a1ac"}
2024-08-15T10:32:58.616+0200    INFO    hare4/hare.go:300   started {"enabled": false, "enabled layer": 0, "disabled layer": 4294967295, "committee": 50, "leaders": 5, "iterations limit": 4, "preround delay": "25s", "round duration": "12s", "log stats": true, "p2p protocol": "/h/4.0", "enabled": 8, "disabled": 4294967295}
2024-08-15T10:32:58.620+0200    DEBUG   hare4/hare.go:309   notified    {"layer": 8}
2024-08-15T10:32:58.620+0200    DEBUG   hare4/hare.go:309   notified    {"layer": 8}
2024-08-15T10:32:58.620+0200    DEBUG   hare4/hare.go:309   notified    {"layer": 8}
2024-08-15T10:32:58.620+0200    DEBUG   hare4/hare.go:599   registered layer    {"lid": 8}
2024-08-15T10:32:58.622+0200    DEBUG   hare4/hare.go:599   registered layer    {"lid": 8}
2024-08-15T10:32:58.622+0200    DEBUG   hare4/hare.go:599   registered layer    {"lid": 8}
2024-08-15T10:32:58.627+0200    DEBUG   hare4/hare.go:642   active in preround. waiting for preround delay  {"lid": 8}
...
2024-08-15T10:32:59.314+0200    DEBUG   hare4/hare.go:611   terminated  {"lid": 8}
2024-08-15T10:32:59.314+0200    DEBUG   hare4/hare.go:739   round output    {"lid": 8, "iter": 2, "round": "hardlock", "terminated": false}
2024-08-15T10:32:59.314+0200    DEBUG   hare4/hare.go:739   round output    {"lid": 8, "iter": 2, "round": "hardlock", "terminated": true}
2024-08-15T10:32:59.315+0200    INFO    hare4/hare.go:689   stats   {"lid": 8, "iter": 1, "threshold": 26, "preround": [], "propose": [{"ref": "af1349b9f5", "grade": 2, "proposals": []}, {"ref": "060e8385f6", "grade": 2, "proposals": ["01ff123875"]}, {"ref": "060e8385f6", "grade": 2, "proposals": ["01ff123875"]}, {"ref": "060e8385f6", "grade": 2, "proposals": ["01ff123875"]}], "commit": [{"grade": 4, "tallies": [{"total": 40, "valid": 40, "id": "060e8385f6ea14cdf1eaadf13468192595cbe325482e283f820f5266eca66706"}, {"total": 10, "valid": 10, "id": "af1349b9f5f9a1a6a0404dea36dcc9499bcb25c9adc112b7cc9a93cae41f3262"}]}, {"grade": 5, "tallies": [{"total": 40, "valid": 40, "id": "060e8385f6ea14cdf1eaadf13468192595cbe325482e283f820f5266eca66706"}, {"total": 10, "valid": 10, "id": "af1349b9f5f9a1a6a0404dea36dcc9499bcb25c9adc112b7cc9a93cae41f3262"}]}], "notify": [{"grade": 5, "tallies": [{"total": 40, "valid": 40, "id": "060e8385f6ea14cdf1eaadf13468192595cbe325482e283f820f5266eca66706"}]}]}
2024-08-15T10:32:59.314+0200    DEBUG   hare4/hare.go:611   terminated  {"lid": 8}
2024-08-15T10:32:59.315+0200    DEBUG   hare4/hare.go:739   round output    {"lid": 8, "iter": 2, "round": "hardlock", "terminated": true}
2024-08-15T10:32:59.315+0200    INFO    hare4/hare.go:689   stats   {"lid": 8, "iter": 1, "threshold": 26, "preround": [], "propose": [{"ref": "af1349b9f5", "grade": 2, "proposals": []}, {"ref": "060e8385f6", "grade": 2, "proposals": ["01ff123875"]}, {"ref": "060e8385f6", "grade": 2, "proposals": ["01ff123875"]}, {"ref": "060e8385f6", "grade": 2, "proposals": ["01ff123875"]}], "commit": [{"grade": 4, "tallies": [{"total": 40, "valid": 40, "id": "060e8385f6ea14cdf1eaadf13468192595cbe325482e283f820f5266eca66706"}, {"total": 10, "valid": 10, "id": "af1349b9f5f9a1a6a0404dea36dcc9499bcb25c9adc112b7cc9a93cae41f3262"}]}, {"grade": 5, "tallies": [{"total": 10, "valid": 10, "id": "af1349b9f5f9a1a6a0404dea36dcc9499bcb25c9adc112b7cc9a93cae41f3262"}, {"total": 40, "valid": 40, "id": "060e8385f6ea14cdf1eaadf13468192595cbe325482e283f820f5266eca66706"}]}], "notify": [{"grade": 5, "tallies": [{"total": 40, "valid": 40, "id": "060e8385f6ea14cdf1eaadf13468192595cbe325482e283f820f5266eca66706"}]}]}
2024-08-15T10:32:59.315+0200    INFO    hare4/hare.go:689   stats   {"lid": 8, "iter": 1, "threshold": 26, "preround": [], "propose": [{"ref": "af1349b9f5", "grade": 2, "proposals": []}, {"ref": "060e8385f6", "grade": 2, "proposals": ["01ff123875"]}, {"ref": "060e8385f6", "grade": 2, "proposals": ["01ff123875"]}, {"ref": "060e8385f6", "grade": 2, "proposals": ["01ff123875"]}], "commit": [{"grade": 4, "tallies": [{"total": 40, "valid": 40, "id": "060e8385f6ea14cdf1eaadf13468192595cbe325482e283f820f5266eca66706"}, {"total": 10, "valid": 10, "id": "af1349b9f5f9a1a6a0404dea36dcc9499bcb25c9adc112b7cc9a93cae41f3262"}]}, {"grade": 5, "tallies": [{"total": 40, "valid": 40, "id": "060e8385f6ea14cdf1eaadf13468192595cbe325482e283f820f5266eca66706"}, {"total": 10, "valid": 10, "id": "af1349b9f5f9a1a6a0404dea36dcc9499bcb25c9adc112b7cc9a93cae41f3262"}]}], "notify": [{"grade": 5, "tallies": [{"total": 40, "valid": 40, "id": "060e8385f6ea14cdf1eaadf13468192595cbe325482e283f820f5266eca66706"}]}]}
2024-08-15T10:32:59.315+0200    DEBUG   hare4/hare.go:611   terminated  {"lid": 8}
2024-08-15T10:32:59.315+0200    DEBUG   hare4/hare.go:611   terminated  {"lid": 8}
    hare_test.go:652: eligibility can't be sent, waited: 10s, stacktraces:
        goroutine 868 [running]:
        runtime/pprof.writeGoroutineStacks({0x101a4c108, 0xc00049ae00})
            /Users/m1/actions-runner/_work/_tool/go/1.22.6/arm64/src/runtime/pprof/pprof.go:743 +0x74
        runtime/pprof.writeGoroutine({0x101a4c108, 0xc00049ae00}, 0x2)
            /Users/m1/actions-runner/_work/_tool/go/1.22.6/arm64/src/runtime/pprof/pprof.go:732 +0x44
        runtime/pprof.(*Profile).WriteTo(0x10239dba0, {0x101a4c108, 0xc00049ae00}, 0x2)
            /Users/m1/actions-runner/_work/_tool/go/1.22.6/arm64/src/runtime/pprof/pprof.go:369 +0x138
        github.com/spacemeshos/go-spacemesh/hare4.sendWithTimeout[...]({0x101a6db48?, 0xc0001e8000}, {0xc0007a6020, 0x1, 0x1}, 0xc00045d620, 0x2540be400, {0x1012bca08, 0x19})
            /Users/m1/actions-runner/_work/go-spacemesh/go-spacemesh/hare4/hare_test.go:651 +0x130
        github.com/spacemeshos/go-spacemesh/hare4.(*testTracer).OnActive(0xc00059ac00, {0xc0007a6020, 0x1, 0x1})
            /Users/m1/actions-runner/_work/go-spacemesh/go-spacemesh/hare4/hare_test.go:679 +0xa8
        github.com/spacemeshos/go-spacemesh/hare4.(*Hare).run(0xc0001d2300, 0xc000a82300)
            /Users/m1/actions-runner/_work/go-spacemesh/go-spacemesh/hare4/hare.go:669 +0x81c
        github.com/spacemeshos/go-spacemesh/hare4.(*Hare).onLayer.func1()
            /Users/m1/actions-runner/_work/go-spacemesh/go-spacemesh/hare4/hare.go:601 +0x4c
        golang.org/x/sync/errgroup.(*Group).Go.func1()
            /Users/m1/go/pkg/mod/golang.org/x/sync@v0.8.0/errgroup/errgroup.go:78 +0x80
        created by golang.org/x/sync/errgroup.(*Group).Go in goroutine 812
            /Users/m1/go/pkg/mod/golang.org/x/sync@v0.8.0/errgroup/errgroup.go:75 +0x110

        goroutine 1 [chan receive]:
        testing.(*T).Run(0xc00014e1a0, {0x1012a7bc6, 0x8}, 0x101a43148)
            /Users/m1/actions-runner/_work/_tool/go/1.22.6/arm64/src/testing/testing.go:1750 +0x604
        testing.runTests.func1(0xc00014e1a0)
            /Users/m1/actions-runner/_work/_tool/go/1.22.6/arm64/src/testing/testing.go:2161 +0x84
        testing.tRunner(0xc00014e1a0, 0xc00063fab8)
            /Users/m1/actions-runner/_work/_tool/go/1.22.6/arm64/src/testing/testing.go:1689 +0x184
        testing.runTests(0xc000122000, {0x1023aa440, 0x10, 0x10}, {0xc00063fbe8?, 0x100293164?, 0x1023c99c0?})
            /Users/m1/actions-runner/_work/_tool/go/1.22.6/arm64/src/testing/testing.go:[215](https://github.com/spacemeshos/go-spacemesh/actions/runs/10401090343/job/28802907577#step:14:216)9 +0x6e4
        testing.(*M).Run(0xc0005a4000)
            /Users/m1/actions-runner/_work/_tool/go/1.22.6/arm64/src/testing/testing.go:2027 +0xb78
        github.com/spacemeshos/go-spacemesh/hare4.TestMain(0xc0005a4000)
            /Users/m1/actions-runner/_work/go-spacemesh/go-spacemesh/hare4/hare_test.go:50 +0x34
        main.main()
            _testmain.go:81 +0x298

        goroutine 35 [select]:
        github.com/ipfs/go-log/writer.(*MirrorWriter).logRoutine(0xc00019c330)
            /Users/m1/go/pkg/mod/github.com/ipfs/go-log@v1.0.5/writer/writer.go:71 +0x114
        created by github.com/ipfs/go-log/writer.NewMirrorWriter in goroutine 1
            /Users/m1/go/pkg/mod/github.com/ipfs/go-log@v1.0.5/writer/writer.go:36 +0x168

        goroutine 36 [select]:
        go.opencensus.io/stats/view.(*worker).start(0xc00022ea00)
            /Users/m1/go/pkg/mod/go.opencensus.io@v0.24.0/stats/view/worker.go:292 +0x128
        created by go.opencensus.io/stats/view.init.0 in goroutine 1
            /Users/m1/go/pkg/mod/go.opencensus.io@v0.24.0/stats/view/worker.go:34 +0xf4

        goroutine 94 [chan receive]:
        testing.(*T).Run(0xc00014e340, {0x1012b86f0, 0x16}, 0x101a43370)
            /Users/m1/actions-runner/_work/_tool/go/1.22.6/arm64/src/testing/testing.go:1750 +0x604
        github.com/spacemeshos/go-spacemesh/hare4.TestHare(0xc00014e340)
            /Users/m1/actions-runner/_work/go-spacemesh/go-spacemesh/hare4/hare_test.go:755 +0x94
        testing.tRunner(0xc00014e340, 0x101a43148)
            /Users/m1/actions-runner/_work/_tool/go/1.22.6/arm64/src/testing/testing.go:1689 +0x184
        created by testing.(*T).Run in goroutine 1
            /Users/m1/actions-runner/_work/_tool/go/1.22.6/arm64/src/testing/testing.go:1742 +0x5e8

        goroutine 705 [select]:
        github.com/spacemeshos/go-spacemesh/hare4.waitForChan[...]({0x101a6db48?, 0xc0001e8000}, 0xc0003ec200, 0x2540be400, {0x1012ab1d4, 0xb})
            /Users/m1/actions-runner/_work/go-spacemesh/go-spacemesh/hare4/hare_test.go:637 +0xa0
        github.com/spacemeshos/go-spacemesh/hare4.(*testTracer).waitStopped(...)
            /Users/m1/actions-runner/_work/go-spacemesh/go-spacemesh/hare4/hare_test.go:658
        github.com/spacemeshos/go-spacemesh/hare4.(*lockstepCluster).waitStopped(...)
            /Users/m1/actions-runner/_work/go-spacemesh/go-spacemesh/hare4/hare_test.go:593
        github.com/spacemeshos/go-spacemesh/hare4.testHare(0xc00014e680, 0x5, 0x0, 0x0, {0xc000375ec0, 0x1, 0x1})
            /Users/m1/actions-runner/_work/go-spacemesh/go-spacemesh/hare4/hare_test.go:727 +0x5d0
        github.com/spacemeshos/go-spacemesh/hare4.TestHare.func4(0xc00014e680)
            /Users/m1/actions-runner/_work/go-spacemesh/go-spacemesh/hare4/hare_test.go:755 +0x88
        testing.tRunner(0xc00014e680, 0x101a43370)
            /Users/m1/actions-runner/_work/_tool/go/1.22.6/arm64/src/testing/testing.go:1689 +0x184
        created by testing.(*T).Run in goroutine 94
            /Users/m1/actions-runner/_work/_tool/go/1.22.6/arm64/src/testing/testing.go:1742 +0x5e8

        goroutine 149 [runnable]:
        github.com/spacemeshos/go-spacemesh/hare4.(*lockstepCluster).drainInteractiveMessages.func2()
            /Users/m1/actions-runner/_work/go-spacemesh/go-spacemesh/hare4/hare_test.go:605 +0xf0
        created by github.com/spacemeshos/go-spacemesh/hare4.(*lockstepCluster).drainInteractiveMessages in goroutine 95
            /Users/m1/actions-runner/_work/go-spacemesh/go-spacemesh/hare4/hare_test.go:603 +0x104

        goroutine 225 [runnable]:
        github.com/spacemeshos/go-spacemesh/hare4.(*lockstepCluster).drainInteractiveMessages.func2()
            /Users/m1/actions-runner/_work/go-spacemesh/go-spacemesh/hare4/hare_test.go:605 +0xf0
        created by github.com/spacemeshos/go-spacemesh/hare4.(*lockstepCluster).drainInteractiveMessages in goroutine 181
            /Users/m1/actions-runner/_work/go-spacemesh/go-spacemesh/hare4/hare_test.go:603 +0x104

        goroutine 242 [runnable]:
        github.com/spacemeshos/go-spacemesh/hare4.(*lockstepCluster).drainInteractiveMessages.func2()
            /Users/m1/actions-runner/_work/go-spacemesh/go-spacemesh/hare4/hare_test.go:605 +0xf0
        created by github.com/spacemeshos/go-spacemesh/hare4.(*lockstepCluster).drainInteractiveMessages in goroutine 181
            /Users/m1/actions-runner/_work/go-spacemesh/go-spacemesh/hare4/hare_test.go:603 +0x104

        goroutine 288 [chan receive]:
        github.com/go-llsqlite/crawshaw.(*Conn).SetInterrupt.func1()
            /Users/m1/go/pkg/mod/github.com/go-llsqlite/crawshaw@v0.5.3/sqlite.go:314 +0xc8
        created by github.com/go-llsqlite/crawshaw.(*Conn).SetInterrupt in goroutine 921
            /Users/m1/go/pkg/mod/github.com/go-llsqlite/crawshaw@v0.5.3/sqlite.go:309 +0x308

        goroutine 415 [runnable]:
        github.com/spacemeshos/go-spacemesh/hare4.(*lockstepCluster).drainInteractiveMessages.func2()
            /Users/m1/actions-runner/_work/go-spacemesh/go-spacemesh/hare4/hare_test.go:605 +0xf0
        created by github.com/spacemeshos/go-spacemesh/hare4.(*lockstepCluster).drainInteractiveMessages in goroutine 290
            /Users/m1/actions-runner/_work/go-spacemesh/go-spacemesh/hare4/hare_test.go:603 +0x104

        goroutine 416 [runnable]:
        github.com/spacemeshos/go-spacemesh/hare4.(*lockstepCluster).drainInteractiveMessages.func2()
            /Users/m1/actions-runner/_work/go-spacemesh/go-spacemesh/hare4/hare_test.go:605 +0xf0
        created by github.com/spacemeshos/go-spacemesh/hare4.(*lockstepCluster).drainInteractiveMessages in goroutine 290
            /Users/m1/actions-runner/_work/go-spacemesh/go-spacemesh/hare4/hare_test.go:603 +0x104

        goroutine 417 [runnable]:
        github.com/spacemeshos/go-spacemesh/hare4.(*lockstepCluster).drainInteractiveMessages.func2()
            /Users/m1/actions-runner/_work/go-spacemesh/go-spacemesh/hare4/hare_test.go:605 +0xf0
        created by github.com/spacemeshos/go-spacemesh/hare4.(*lockstepCluster).drainInteractiveMessages in goroutine 290
            /Users/m1/actions-runner/_work/go-spacemesh/go-spacemesh/hare4/hare_test.go:603 +0x104

        goroutine 418 [runnable]:
        github.com/spacemeshos/go-spacemesh/hare4.(*lockstepCluster).drainInteractiveMessages.func2()
            /Users/m1/actions-runner/_work/go-spacemesh/go-spacemesh/hare4/hare_test.go:605 +0xf0
        created by github.com/spacemeshos/go-spacemesh/hare4.(*lockstepCluster).drainInteractiveMessages in goroutine 290
            /Users/m1/actions-runner/_work/go-spacemesh/go-spacemesh/hare4/hare_test.go:603 +0x104

        goroutine 419 [runnable]:
        github.com/spacemeshos/go-spacemesh/hare4.(*lockstepCluster).drainInteractiveMessages.func2()
            /Users/m1/actions-runner/_work/go-spacemesh/go-spacemesh/hare4/hare_test.go:605 +0xf0
        created by github.com/spacemeshos/go-spacemesh/hare4.(*lockstepCluster).drainInteractiveMessages in goroutine 290
            /Users/m1/actions-runner/_work/go-spacemesh/go-spacemesh/hare4/hare_test.go:603 +0x104

        goroutine 289 [chan receive]:
        github.com/go-llsqlite/crawshaw.(*Conn).SetInterrupt.func1()
            /Users/m1/go/pkg/mod/github.com/go-llsqlite/crawshaw@v0.5.3/sqlite.go:314 +0xc8
        created by github.com/go-llsqlite/crawshaw.(*Conn).SetInterrupt in goroutine 921
            /Users/m1/go/pkg/mod/github.com/go-llsqlite/crawshaw@v0.5.3/sqlite.go:309 +0x308

        goroutine 655 [select]:
        github.com/spacemeshos/go-spacemesh/hare4.(*Hare).Start.func1()
            /Users/m1/actions-runner/_work/go-spacemesh/go-spacemesh/hare4/hare.go:307 +0x160
        golang.org/x/sync/errgroup.(*Group).Go.func1()
            /Users/m1/go/pkg/mod/golang.org/x/sync@v0.8.0/errgroup/errgroup.go:78 +0x80
        created by golang.org/x/sync/errgroup.(*Group).Go in goroutine 705
            /Users/m1/go/pkg/mod/golang.org/x/sync@v0.8.0/errgroup/errgroup.go:75 +0x110

        goroutine 774 [select]:
        github.com/spacemeshos/go-spacemesh/hare4.(*Hare).Start.func1()
            /Users/m1/actions-runner/_work/go-spacemesh/go-spacemesh/hare4/hare.go:307 +0x160
        golang.org/x/sync/errgroup.(*Group).Go.func1()
            /Users/m1/go/pkg/mod/golang.org/x/sync@v0.8.0/errgroup/errgroup.go:78 +0x80
        created by golang.org/x/sync/errgroup.(*Group).Go in goroutine 705
            /Users/m1/go/pkg/mod/golang.org/x/sync@v0.8.0/errgroup/errgroup.go:75 +0x110

        goroutine 1122 [chan receive]:
        github.com/go-llsqlite/crawshaw.(*Conn).SetInterrupt.func1()
            /Users/m1/go/pkg/mod/github.com/go-llsqlite/crawshaw@v0.5.3/sqlite.go:314 +0xc8
        created by github.com/go-llsqlite/crawshaw.(*Conn).SetInterrupt in goroutine 921
            /Users/m1/go/pkg/mod/github.com/go-llsqlite/crawshaw@v0.5.3/sqlite.go:309 +0x308

        goroutine 797 [select]:
        github.com/spacemeshos/go-spacemesh/hare4.(*Hare).Start.func1()
            /Users/m1/actions-runner/_work/go-spacemesh/go-spacemesh/hare4/hare.go:307 +0x160
        golang.org/x/sync/errgroup.(*Group).Go.func1()
            /Users/m1/go/pkg/mod/golang.org/x/sync@v0.8.0/errgroup/errgroup.go:78 +0x80
        created by golang.org/x/sync/errgroup.(*Group).Go in goroutine 705
            /Users/m1/go/pkg/mod/golang.org/x/sync@v0.8.0/errgroup/errgroup.go:75 +0x110

        goroutine 284 [chan receive]:
        github.com/go-llsqlite/crawshaw.(*Conn).SetInterrupt.func1()
            /Users/m1/go/pkg/mod/github.com/go-llsqlite/crawshaw@v0.5.3/sqlite.go:314 +0xc8
        created by github.com/go-llsqlite/crawshaw.(*Conn).SetInterrupt in goroutine 930
            /Users/m1/go/pkg/mod/github.com/go-llsqlite/crawshaw@v0.5.3/sqlite.go:309 +0x308

        goroutine 287 [chan receive]:
        github.com/go-llsqlite/crawshaw.(*Conn).SetInterrupt.func1()
            /Users/m1/go/pkg/mod/github.com/go-llsqlite/crawshaw@v0.5.3/sqlite.go:314 +0xc8
        created by github.com/go-llsqlite/crawshaw.(*Conn).SetInterrupt in goroutine 921
            /Users/m1/go/pkg/mod/github.com/go-llsqlite/crawshaw@v0.5.3/sqlite.go:309 +0x308

        goroutine 812 [select]:
        github.com/spacemeshos/go-spacemesh/hare4.(*Hare).Start.func1()
            /Users/m1/actions-runner/_work/go-spacemesh/go-spacemesh/hare4/hare.go:307 +0x160
        golang.org/x/sync/errgroup.(*Group).Go.func1()
            /Users/m1/go/pkg/mod/golang.org/x/sync@v0.8.0/errgroup/errgroup.go:78 +0x80
        created by golang.org/x/sync/errgroup.(*Group).Go in goroutine 705
            /Users/m1/go/pkg/mod/golang.org/x/sync@v0.8.0/errgroup/errgroup.go:75 +0x110

        goroutine 835 [select]:
        github.com/spacemeshos/go-spacemesh/hare4.(*Hare).Start.func1()
            /Users/m1/actions-runner/_work/go-spacemesh/go-spacemesh/hare4/hare.go:307 +0x160
        golang.org/x/sync/errgroup.(*Group).Go.func1()
            /Users/m1/go/pkg/mod/golang.org/x/sync@v0.8.0/errgroup/errgroup.go:78 +0x80
        created by golang.org/x/sync/errgroup.(*Group).Go in goroutine 705
            /Users/m1/go/pkg/mod/golang.org/x/sync@v0.8.0/errgroup/errgroup.go:75 +0x110

        goroutine 836 [select]:
        github.com/spacemeshos/go-spacemesh/hare4.(*lockstepCluster).drainInteractiveMessages.func2()
            /Users/m1/actions-runner/_work/go-spacemesh/go-spacemesh/hare4/hare_test.go:605 +0xf0
        created by github.com/spacemeshos/go-spacemesh/hare4.(*lockstepCluster).drainInteractiveMessages in goroutine 705
            /Users/m1/actions-runner/_work/go-spacemesh/go-spacemesh/hare4/hare_test.go:603 +0x104

        goroutine 837 [select]:
        github.com/spacemeshos/go-spacemesh/hare4.(*lockstepCluster).drainInteractiveMessages.func2()
            /Users/m1/actions-runner/_work/go-spacemesh/go-spacemesh/hare4/hare_test.go:605 +0xf0
        created by github.com/spacemeshos/go-spacemesh/hare4.(*lockstepCluster).drainInteractiveMessages in goroutine 705
            /Users/m1/actions-runner/_work/go-spacemesh/go-spacemesh/hare4/hare_test.go:603 +0x104

        goroutine 838 [select]:
        github.com/spacemeshos/go-spacemesh/hare4.(*lockstepCluster).drainInteractiveMessages.func2()
            /Users/m1/actions-runner/_work/go-spacemesh/go-spacemesh/hare4/hare_test.go:605 +0xf0
        created by github.com/spacemeshos/go-spacemesh/hare4.(*lockstepCluster).drainInteractiveMessages in goroutine 705
            /Users/m1/actions-runner/_work/go-spacemesh/go-spacemesh/hare4/hare_test.go:603 +0x104

        goroutine 839 [select]:
        github.com/spacemeshos/go-spacemesh/hare4.(*lockstepCluster).drainInteractiveMessages.func2()
            /Users/m1/actions-runner/_work/go-spacemesh/go-spacemesh/hare4/hare_test.go:605 +0xf0
        created by github.com/spacemeshos/go-spacemesh/hare4.(*lockstepCluster).drainInteractiveMessages in goroutine 705
            /Users/m1/actions-runner/_work/go-spacemesh/go-spacemesh/hare4/hare_test.go:603 +0x104

        goroutine 840 [select]:
        github.com/spacemeshos/go-spacemesh/hare4.(*lockstepCluster).drainInteractiveMessages.func2()
            /Users/m1/actions-runner/_work/go-spacemesh/go-spacemesh/hare4/hare_test.go:605 +0xf0
        created by github.com/spacemeshos/go-spacemesh/hare4.(*lockstepCluster).drainInteractiveMessages in goroutine 705
            /Users/m1/actions-runner/_work/go-spacemesh/go-spacemesh/hare4/hare_test.go:603 +0x104
    hare_test.go:641: didn't stop, waited: 10s, stacktraces:
        goroutine 705 [running]:
        runtime/pprof.writeGoroutineStacks({0x101a4c108, 0xc0000c2c80})
            /Users/m1/actions-runner/_work/_tool/go/1.22.6/arm64/src/runtime/pprof/pprof.go:743 +0x74
        runtime/pprof.writeGoroutine({0x101a4c108, 0xc0000c2c80}, 0x2)
            /Users/m1/actions-runner/_work/_tool/go/1.22.6/arm64/src/runtime/pprof/pprof.go:732 +0x44
        runtime/pprof.(*Profile).WriteTo(0x10239dba0, {0x101a4c108, 0xc0000c2c80}, 0x2)
            /Users/m1/actions-runner/_work/_tool/go/1.22.6/arm64/src/runtime/pprof/pprof.go:369 +0x138
        github.com/spacemeshos/go-spacemesh/hare4.waitForChan[...]({0x101a6db48?, 0xc0001e8000}, 0xc0003ec200, 0x2540be400, {0x1012ab1d4, 0xb})
            /Users/m1/actions-runner/_work/go-spacemesh/go-spacemesh/hare4/hare_test.go:640 +0x114
        github.com/spacemeshos/go-spacemesh/hare4.(*testTracer).waitStopped(...)
            /Users/m1/actions-runner/_work/go-spacemesh/go-spacemesh/hare4/hare_test.go:658
        github.com/spacemeshos/go-spacemesh/hare4.(*lockstepCluster).waitStopped(...)
            /Users/m1/actions-runner/_work/go-spacemesh/go-spacemesh/hare4/hare_test.go:593
        github.com/spacemeshos/go-spacemesh/hare4.testHare(0xc00014e680, 0x5, 0x0, 0x0, {0xc000375ec0, 0x1, 0x1})
            /Users/m1/actions-runner/_work/go-spacemesh/go-spacemesh/hare4/hare_test.go:727 +0x5d0
        github.com/spacemeshos/go-spacemesh/hare4.TestHare.func4(0xc00014e680)
            /Users/m1/actions-runner/_work/go-spacemesh/go-spacemesh/hare4/hare_test.go:755 +0x88
        testing.tRunner(0xc00014e680, 0x101a43370)
            /Users/m1/actions-runner/_work/_tool/go/1.22.6/arm64/src/testing/testing.go:1689 +0x184
        created by testing.(*T).Run in goroutine 94
            /Users/m1/actions-runner/_work/_tool/go/1.22.6/arm64/src/testing/testing.go:1742 +0x5e8

        goroutine 1 [chan receive]:
        testing.(*T).Run(0xc00014e1a0, {0x1012a7bc6, 0x8}, 0x101a43148)
            /Users/m1/actions-runner/_work/_tool/go/1.22.6/arm64/src/testing/testing.go:1750 +0x604
        testing.runTests.func1(0xc00014e1a0)
            /Users/m1/actions-runner/_work/_tool/go/1.22.6/arm64/src/testing/testing.go:[216](https://github.com/spacemeshos/go-spacemesh/actions/runs/10401090343/job/28802907577#step:14:217)1 +0x84
        testing.tRunner(0xc00014e1a0, 0xc00063fab8)
            /Users/m1/actions-runner/_work/_tool/go/1.22.6/arm64/src/testing/testing.go:1689 +0x184
        testing.runTests(0xc000122000, {0x1023aa440, 0x10, 0x10}, {0xc00063fbe8?, 0x100293164?, 0x1023c99c0?})
            /Users/m1/actions-runner/_work/_tool/go/1.22.6/arm64/src/testing/testing.go:2159 +0x6e4
        testing.(*M).Run(0xc0005a4000)
            /Users/m1/actions-runner/_work/_tool/go/1.22.6/arm64/src/testing/testing.go:2027 +0xb78
        github.com/spacemeshos/go-spacemesh/hare4.TestMain(0xc0005a4000)
            /Users/m1/actions-runner/_work/go-spacemesh/go-spacemesh/hare4/hare_test.go:50 +0x34
        main.main()
            _testmain.go:81 +0x298

        goroutine 35 [select]:
        github.com/ipfs/go-log/writer.(*MirrorWriter).logRoutine(0xc00019c330)
            /Users/m1/go/pkg/mod/github.com/ipfs/go-log@v1.0.5/writer/writer.go:71 +0x114
        created by github.com/ipfs/go-log/writer.NewMirrorWriter in goroutine 1
            /Users/m1/go/pkg/mod/github.com/ipfs/go-log@v1.0.5/writer/writer.go:36 +0x168

        goroutine 36 [select]:
        go.opencensus.io/stats/view.(*worker).start(0xc00022ea00)
            /Users/m1/go/pkg/mod/go.opencensus.io@v0.24.0/stats/view/worker.go:292 +0x128
        created by go.opencensus.io/stats/view.init.0 in goroutine 1
            /Users/m1/go/pkg/mod/go.opencensus.io@v0.24.0/stats/view/worker.go:34 +0xf4

        goroutine 94 [chan receive]:
        testing.(*T).Run(0xc00014e340, {0x1012b86f0, 0x16}, 0x101a43370)
            /Users/m1/actions-runner/_work/_tool/go/1.22.6/arm64/src/testing/testing.go:1750 +0x604
        github.com/spacemeshos/go-spacemesh/hare4.TestHare(0xc00014e340)
            /Users/m1/actions-runner/_work/go-spacemesh/go-spacemesh/hare4/hare_test.go:755 +0x94
        testing.tRunner(0xc00014e340, 0x101a43148)
            /Users/m1/actions-runner/_work/_tool/go/1.22.6/arm64/src/testing/testing.go:1689 +0x184
        created by testing.(*T).Run in goroutine 1
            /Users/m1/actions-runner/_work/_tool/go/1.22.6/arm64/src/testing/testing.go:1742 +0x5e8

        goroutine 149 [runnable]:
        github.com/spacemeshos/go-spacemesh/hare4.(*lockstepCluster).drainInteractiveMessages.func2()
            /Users/m1/actions-runner/_work/go-spacemesh/go-spacemesh/hare4/hare_test.go:605 +0xf0
        created by github.com/spacemeshos/go-spacemesh/hare4.(*lockstepCluster).drainInteractiveMessages in goroutine 95
            /Users/m1/actions-runner/_work/go-spacemesh/go-spacemesh/hare4/hare_test.go:603 +0x104

        goroutine [225](https://github.com/spacemeshos/go-spacemesh/actions/runs/10401090343/job/28802907577#step:14:226) [runnable]:
        github.com/spacemeshos/go-spacemesh/hare4.(*lockstepCluster).drainInteractiveMessages.func2()
            /Users/m1/actions-runner/_work/go-spacemesh/go-spacemesh/hare4/hare_test.go:605 +0xf0
        created by github.com/spacemeshos/go-spacemesh/hare4.(*lockstepCluster).drainInteractiveMessages in goroutine 181
            /Users/m1/actions-runner/_work/go-spacemesh/go-spacemesh/hare4/hare_test.go:603 +0x104

        goroutine 242 [runnable]:
        github.com/spacemeshos/go-spacemesh/hare4.(*lockstepCluster).drainInteractiveMessages.func2()
            /Users/m1/actions-runner/_work/go-spacemesh/go-spacemesh/hare4/hare_test.go:605 +0xf0
        created by github.com/spacemeshos/go-spacemesh/hare4.(*lockstepCluster).drainInteractiveMessages in goroutine 181
            /Users/m1/actions-runner/_work/go-spacemesh/go-spacemesh/hare4/hare_test.go:603 +0x104

        goroutine 288 [chan receive]:
        github.com/go-llsqlite/crawshaw.(*Conn).SetInterrupt.func1()
            /Users/m1/go/pkg/mod/github.com/go-llsqlite/crawshaw@v0.5.3/sqlite.go:314 +0xc8
        created by github.com/go-llsqlite/crawshaw.(*Conn).SetInterrupt in goroutine 921
            /Users/m1/go/pkg/mod/github.com/go-llsqlite/crawshaw@v0.5.3/sqlite.go:309 +0x308

        goroutine 415 [runnable]:
        github.com/spacemeshos/go-spacemesh/hare4.(*lockstepCluster).drainInteractiveMessages.func2()
            /Users/m1/actions-runner/_work/go-spacemesh/go-spacemesh/hare4/hare_test.go:605 +0xf0
        created by github.com/spacemeshos/go-spacemesh/hare4.(*lockstepCluster).drainInteractiveMessages in goroutine 290
            /Users/m1/actions-runner/_work/go-spacemesh/go-spacemesh/hare4/hare_test.go:603 +0x104

        goroutine 416 [runnable]:
        github.com/spacemeshos/go-spacemesh/hare4.(*lockstepCluster).drainInteractiveMessages.func2()
            /Users/m1/actions-runner/_work/go-spacemesh/go-spacemesh/hare4/hare_test.go:605 +0xf0
        created by github.com/spacemeshos/go-spacemesh/hare4.(*lockstepCluster).drainInteractiveMessages in goroutine 290
            /Users/m1/actions-runner/_work/go-spacemesh/go-spacemesh/hare4/hare_test.go:603 +0x104

        goroutine 417 [runnable]:
        github.com/spacemeshos/go-spacemesh/hare4.(*lockstepCluster).drainInteractiveMessages.func2()
            /Users/m1/actions-runner/_work/go-spacemesh/go-spacemesh/hare4/hare_test.go:605 +0xf0
        created by github.com/spacemeshos/go-spacemesh/hare4.(*lockstepCluster).drainInteractiveMessages in goroutine 290
            /Users/m1/actions-runner/_work/go-spacemesh/go-spacemesh/hare4/hare_test.go:603 +0x104

        goroutine 418 [runnable]:
        github.com/spacemeshos/go-spacemesh/hare4.(*lockstepCluster).drainInteractiveMessages.func2()
            /Users/m1/actions-runner/_work/go-spacemesh/go-spacemesh/hare4/hare_test.go:605 +0xf0
        created by github.com/spacemeshos/go-spacemesh/hare4.(*lockstepCluster).drainInteractiveMessages in goroutine 290
            /Users/m1/actions-runner/_work/go-spacemesh/go-spacemesh/hare4/hare_test.go:603 +0x104

        goroutine 419 [runnable]:
        github.com/spacemeshos/go-spacemesh/hare4.(*lockstepCluster).drainInteractiveMessages.func2()
            /Users/m1/actions-runner/_work/go-spacemesh/go-spacemesh/hare4/hare_test.go:605 +0xf0
        created by github.com/spacemeshos/go-spacemesh/hare4.(*lockstepCluster).drainInteractiveMessages in goroutine 290
            /Users/m1/actions-runner/_work/go-spacemesh/go-spacemesh/hare4/hare_test.go:603 +0x104

        goroutine 289 [chan receive]:
        github.com/go-llsqlite/crawshaw.(*Conn).SetInterrupt.func1()
            /Users/m1/go/pkg/mod/github.com/go-llsqlite/crawshaw@v0.5.3/sqlite.go:314 +0xc8
        created by github.com/go-llsqlite/crawshaw.(*Conn).SetInterrupt in goroutine 921
            /Users/m1/go/pkg/mod/github.com/go-llsqlite/crawshaw@v0.5.3/sqlite.go:309 +0x308

        goroutine 655 [select]:
        github.com/spacemeshos/go-spacemesh/hare4.(*Hare).Start.func1()
            /Users/m1/actions-runner/_work/go-spacemesh/go-spacemesh/hare4/hare.go:307 +0x160
        golang.org/x/sync/errgroup.(*Group).Go.func1()
            /Users/m1/go/pkg/mod/golang.org/x/sync@v0.8.0/errgroup/errgroup.go:78 +0x80
        created by golang.org/x/sync/errgroup.(*Group).Go in goroutine 705
            /Users/m1/go/pkg/mod/golang.org/x/sync@v0.8.0/errgroup/errgroup.go:75 +0x110

        goroutine 774 [select]:
        github.com/spacemeshos/go-spacemesh/hare4.(*Hare).Start.func1()
            /Users/m1/actions-runner/_work/go-spacemesh/go-spacemesh/hare4/hare.go:307 +0x160
        golang.org/x/sync/errgroup.(*Group).Go.func1()
            /Users/m1/go/pkg/mod/golang.org/x/sync@v0.8.0/errgroup/errgroup.go:78 +0x80
        created by golang.org/x/sync/errgroup.(*Group).Go in goroutine 705
            /Users/m1/go/pkg/mod/golang.org/x/sync@v0.8.0/errgroup/errgroup.go:75 +0x110

        goroutine 1122 [chan receive]:
        github.com/go-llsqlite/crawshaw.(*Conn).SetInterrupt.func1()
            /Users/m1/go/pkg/mod/github.com/go-llsqlite/crawshaw@v0.5.3/sqlite.go:314 +0xc8
        created by github.com/go-llsqlite/crawshaw.(*Conn).SetInterrupt in goroutine 921
            /Users/m1/go/pkg/mod/github.com/go-llsqlite/crawshaw@v0.5.3/sqlite.go:309 +0x308

        goroutine 797 [select]:
        github.com/spacemeshos/go-spacemesh/hare4.(*Hare).Start.func1()
            /Users/m1/actions-runner/_work/go-spacemesh/go-spacemesh/hare4/hare.go:307 +0x160
        golang.org/x/sync/errgroup.(*Group).Go.func1()
            /Users/m1/go/pkg/mod/golang.org/x/sync@v0.8.0/errgroup/errgroup.go:78 +0x80
        created by golang.org/x/sync/errgroup.(*Group).Go in goroutine 705
            /Users/m1/go/pkg/mod/golang.org/x/sync@v0.8.0/errgroup/errgroup.go:75 +0x110

        goroutine 284 [chan receive]:
        github.com/go-llsqlite/crawshaw.(*Conn).SetInterrupt.func1()
            /Users/m1/go/pkg/mod/github.com/go-llsqlite/crawshaw@v0.5.3/sqlite.go:314 +0xc8
        created by github.com/go-llsqlite/crawshaw.(*Conn).SetInterrupt in goroutine 930
            /Users/m1/go/pkg/mod/github.com/go-llsqlite/crawshaw@v0.5.3/sqlite.go:309 +0x308

        goroutine 287 [chan receive]:
        github.com/go-llsqlite/crawshaw.(*Conn).SetInterrupt.func1()
            /Users/m1/go/pkg/mod/github.com/go-llsqlite/crawshaw@v0.5.3/sqlite.go:314 +0xc8
        created by github.com/go-llsqlite/crawshaw.(*Conn).SetInterrupt in goroutine 921
            /Users/m1/go/pkg/mod/github.com/go-llsqlite/crawshaw@v0.5.3/sqlite.go:309 +0x308

        goroutine 812 [select]:
        github.com/spacemeshos/go-spacemesh/hare4.(*Hare).Start.func1()
            /Users/m1/actions-runner/_work/go-spacemesh/go-spacemesh/hare4/hare.go:307 +0x160
        golang.org/x/sync/errgroup.(*Group).Go.func1()
            /Users/m1/go/pkg/mod/golang.org/x/sync@v0.8.0/errgroup/errgroup.go:78 +0x80
        created by golang.org/x/sync/errgroup.(*Group).Go in goroutine 705
            /Users/m1/go/pkg/mod/golang.org/x/sync@v0.8.0/errgroup/errgroup.go:75 +0x110

        goroutine 835 [select]:
        github.com/spacemeshos/go-spacemesh/hare4.(*Hare).Start.func1()
            /Users/m1/actions-runner/_work/go-spacemesh/go-spacemesh/hare4/hare.go:307 +0x160
        golang.org/x/sync/errgroup.(*Group).Go.func1()
            /Users/m1/go/pkg/mod/golang.org/x/sync@v0.8.0/errgroup/errgroup.go:78 +0x80
        created by golang.org/x/sync/errgroup.(*Group).Go in goroutine 705
            /Users/m1/go/pkg/mod/golang.org/x/sync@v0.8.0/errgroup/errgroup.go:75 +0x110

        goroutine 836 [select]:
        github.com/spacemeshos/go-spacemesh/hare4.(*lockstepCluster).drainInteractiveMessages.func2()
            /Users/m1/actions-runner/_work/go-spacemesh/go-spacemesh/hare4/hare_test.go:605 +0xf0
        created by github.com/spacemeshos/go-spacemesh/hare4.(*lockstepCluster).drainInteractiveMessages in goroutine 705
            /Users/m1/actions-runner/_work/go-spacemesh/go-spacemesh/hare4/hare_test.go:603 +0x104

        goroutine 837 [select]:
        github.com/spacemeshos/go-spacemesh/hare4.(*lockstepCluster).drainInteractiveMessages.func2()
            /Users/m1/actions-runner/_work/go-spacemesh/go-spacemesh/hare4/hare_test.go:605 +0xf0
        created by github.com/spacemeshos/go-spacemesh/hare4.(*lockstepCluster).drainInteractiveMessages in goroutine 705
            /Users/m1/actions-runner/_work/go-spacemesh/go-spacemesh/hare4/hare_test.go:603 +0x104

        goroutine 838 [select]:
        github.com/spacemeshos/go-spacemesh/hare4.(*lockstepCluster).drainInteractiveMessages.func2()
            /Users/m1/actions-runner/_work/go-spacemesh/go-spacemesh/hare4/hare_test.go:605 +0xf0
        created by github.com/spacemeshos/go-spacemesh/hare4.(*lockstepCluster).drainInteractiveMessages in goroutine 705
            /Users/m1/actions-runner/_work/go-spacemesh/go-spacemesh/hare4/hare_test.go:603 +0x104

        goroutine 839 [select]:
        github.com/spacemeshos/go-spacemesh/hare4.(*lockstepCluster).drainInteractiveMessages.func2()
            /Users/m1/actions-runner/_work/go-spacemesh/go-spacemesh/hare4/hare_test.go:605 +0xf0
        created by github.com/spacemeshos/go-spacemesh/hare4.(*lockstepCluster).drainInteractiveMessages in goroutine 705
            /Users/m1/actions-runner/_work/go-spacemesh/go-spacemesh/hare4/hare_test.go:603 +0x104

        goroutine 840 [select]:
        github.com/spacemeshos/go-spacemesh/hare4.(*lockstepCluster).drainInteractiveMessages.func2()
            /Users/m1/actions-runner/_work/go-spacemesh/go-spacemesh/hare4/hare_test.go:605 +0xf0
        created by github.com/spacemeshos/go-spacemesh/hare4.(*lockstepCluster).drainInteractiveMessages in goroutine 705
            /Users/m1/actions-runner/_work/go-spacemesh/go-spacemesh/hare4/hare_test.go:603 +0x104
2024-08-15T10:33:09.416+0200    INFO    hare4/hare.go:877   stopped
2024-08-15T10:33:09.532+0200    INFO    hare4/hare.go:877   stopped
2024-08-15T10:33:09.533+0200    INFO    hare4/hare.go:877   stopped
2024-08-15T10:33:09.533+0200    INFO    hare4/hare.go:877   stopped
2024-08-15T10:33:09.534+0200    INFO    hare4/hare.go:877   stopped

=== FAIL: hare4 TestHare (18.95s)
fasmat commented 2 months ago

Same test in hare3 package: https://github.com/spacemeshos/go-spacemesh/actions/runs/10401170661/job/28803157041

fasmat commented 2 months ago

Different sub-test but looks like same issue: https://github.com/spacemeshos/go-spacemesh/actions/runs/10581561061

fasmat commented 1 month ago

Another subtest (TestHare/with_inactive), looks to be the same issue: https://github.com/spacemeshos/go-spacemesh/actions/runs/10849922157/job/30110182018