Flaky test: `TestRepoCommitsStatusParallel`

[lunny]

Description

https://drone.gitea.io/go-gitea/gitea/64361/2/14

testlogger.go:77: 2022/12/12 08:53:27 ...pi/v1/repo/status.go:65:NewCommitStatus() [E] [6396ec07-46] CreateCommitStatus: NewCommitStatus[repo_id: 1, user_id: 2, sha: 65f1bf27bc3bf70f64657658635e66094edbcb4d]: insert CommitStatus[/tmp/tmp.nh2kDx6pG3/tests/integration/gitea-integration-mysql/gitea-repositories/user2/repo1.git, 65f1bf27bc3bf70f64657658635e66094edbcb4d]: Error 1062: Duplicate entry '4-1-65f1bf27bc3bf70f64657658635e66094edbcb4d' for key 'UQE_commit_status_repo_sha_index'
--- FAIL: TestRepoCommitsStatusParallel/ParallelCreateStatus_6 (0.38s)
        pull_status_test.go:104: 
            	Error Trace:	/drone/src/integration_test.go:336
            	            				/drone/src/integration_test.go:165
            	            				/drone/src/pull_status_test.go:104
            	            				/drone/src/repo_commits_test.go:141
            	Error:      	Not equal: 
            	            	expected: 201
            	            	actual  : 500
            	Test:       	TestRepoCommitsStatusParallel/ParallelCreateStatus_6
            	Messages:   	Request: POST /api/v1/repos/user2/repo1/statuses/65f1bf27bc3bf70f64657658635e66094edbcb4d?token=95f5e0e052db6781e31573a683234ad48417a1ea
        pull_status_test.go:104: Response: {"message":"","url":"http://localhost:3001/api/swagger"}

Gitea Version

6398ca7

Can you reproduce the bug on the Gitea demo site?

Yes

Log Gist

No response

Screenshots

No response

Git Version

No response

Operating System

No response

How are you running Gitea?

localhost

Database

Mysql

[kousu]

I just saw this this again in https://github.com/neuropoly/gitea/actions/runs/4922154631/jobs/8792661253, when testing against mysql. It's at 7abe958 (well, it's one ahead of that, but the only changes I made were in web_src/ so they should be irrelevant to the database tests)

=== TestRepoCommitsStatusParallel (tests/integration/repo_commits_test.go:137)
--- FAIL: TestRepoCommitsStatusParallel (2.68s)
    testlogger.go:84: 2023/05/09 04:27:26 ...les/storage/local.go:47:NewLocalStorage() [I] Creating new Local Storage at /home/runner/work/gitea/gitea/tests/gitea-lfs-meta
    testlogger.go:84: 2023/05/09 04:27:26 ...eb/routing/logger.go:98:func1() [I] [6459cbae] router: completed GET /user/login for test-mock:12345, 200 OK in 10.9ms @ auth/auth.go:141(auth.SignIn)
    testlogger.go:84: 2023/05/09 04:27:26 ...eb/routing/logger.go:98:func1() [I] [6459cbae-2] router: completed POST /user/login for test-mock:12345, 303 See Other in 35.1ms @ auth/auth.go:170(auth.SignInPost)
    testlogger.go:84: 2023/05/09 04:27:26 ...eb/routing/logger.go:98:func1() [I] [6459cbae-3] router: completed GET /user2/repo1/commits/branch/master for test-mock:12345, 200 OK in 92.9ms @ repo/commit.go:36(repo.RefCommits)
    testlogger.go:84: 2023/05/09 04:27:26 ...eb/routing/logger.go:98:func1() [I] [6459cbae-10] router: completed GET /user/login for test-mock:12345, 200 OK in 33.0ms @ auth/auth.go:141(auth.SignIn)
    testlogger.go:84: 2023/05/09 04:27:26 ...eb/routing/logger.go:98:func1() [I] [6459cbae-16] router: completed GET /user/login for test-mock:12345, 200 OK in 31.4ms @ auth/auth.go:141(auth.SignIn)
    testlogger.go:84: 2023/05/09 04:27:26 ...eb/routing/logger.go:98:func1() [I] [6459cbae-13] router: completed GET /user/login for test-mock:12345, 200 OK in 41.7ms @ auth/auth.go:141(auth.SignIn)
    testlogger.go:84: 2023/05/09 04:27:26 ...eb/routing/logger.go:98:func1() [I] [6459cbae-12] router: completed GET /user/login for test-mock:12345, 200 OK in 42.4ms @ auth/auth.go:141(auth.SignIn)
    testlogger.go:84: 2023/05/09 04:27:26 ...eb/routing/logger.go:98:func1() [I] [6459cbae-14] router: completed GET /user/login for test-mock:12345, 200 OK in 49.5ms @ auth/auth.go:141(auth.SignIn)
    testlogger.go:84: 2023/05/09 04:27:26 ...eb/routing/logger.go:98:func1() [I] [6459cbae-17] router: completed GET /user/login for test-mock:12345, 200 OK in 47.0ms @ auth/auth.go:141(auth.SignIn)
    testlogger.go:84: 2023/05/09 04:27:26 ...eb/routing/logger.go:98:func1() [I] [6459cbae-9] router: completed GET /user/login for test-mock:12345, 200 OK in 60.0ms @ auth/auth.go:141(auth.SignIn)
    testlogger.go:84: 2023/05/09 04:27:26 ...eb/routing/logger.go:98:func1() [I] [6459cbae-11] router: completed GET /user/login for test-mock:12345, 200 OK in 59.8ms @ auth/auth.go:141(auth.SignIn)
    testlogger.go:84: 2023/05/09 04:27:26 ...eb/routing/logger.go:98:func1() [I] [6459cbae-15] router: completed GET /user/login for test-mock:12345, 200 OK in 65.5ms @ auth/auth.go:141(auth.SignIn)
    testlogger.go:84: 2023/05/09 04:27:26 ...eb/routing/logger.go:98:func1() [I] [6459cbae-18] router: completed GET /user/login for test-mock:12345, 200 OK in 65.5ms @ auth/auth.go:141(auth.SignIn)
    testlogger.go:84: 2023/05/09 04:27:26 ...eb/routing/logger.go:98:func1() [I] [6459cbae-20] router: completed POST /user/login for test-mock:12345, 303 See Other in 21.2ms @ auth/auth.go:170(auth.SignInPost)
    testlogger.go:84: 2023/05/09 04:27:26 ...eb/routing/logger.go:98:func1() [I] [6459cbae-19] router: completed POST /user/login for test-mock:12345, 303 See Other in 52.6ms @ auth/auth.go:170(auth.SignInPost)
    testlogger.go:84: 2023/05/09 04:27:26 ...eb/routing/logger.go:98:func1() [I] [6459cbae-23] router: completed POST /user/login for test-mock:12345, 303 See Other in 41.6ms @ auth/auth.go:170(auth.SignInPost)
    testlogger.go:84: 2023/05/09 04:27:26 ...eb/routing/logger.go:98:func1() [I] [6459cbae-21] router: completed POST /user/login for test-mock:12345, 303 See Other in 58.3ms @ auth/auth.go:170(auth.SignInPost)
    testlogger.go:84: 2023/05/09 04:27:26 ...eb/routing/logger.go:98:func1() [I] [6459cbae-29] router: completed POST /user/login for test-mock:12345, 303 See Other in 48.4ms @ auth/auth.go:170(auth.SignInPost)
    testlogger.go:84: 2023/05/09 04:27:26 ...eb/routing/logger.go:98:func1() [I] [6459cbae-22] router: completed POST /user/login for test-mock:12345, 303 See Other in 87.7ms @ auth/auth.go:170(auth.SignInPost)
    testlogger.go:84: 2023/05/09 04:27:26 ...eb/routing/logger.go:98:func1() [I] [6459cbae-30] router: completed GET /user/settings/applications for test-mock:12345, 200 OK in 67.3ms @ setting/applications.go:23(setting.Applications)
    testlogger.go:84: 2023/05/09 04:27:26 ...eb/routing/logger.go:98:func1() [I] [6459cbae-25] router: completed POST /user/login for test-mock:12345, 303 See Other in 92.9ms @ auth/auth.go:170(auth.SignInPost)
    testlogger.go:84: 2023/05/09 04:27:26 ...eb/routing/logger.go:98:func1() [I] [6459cbae-24] router: completed POST /user/login for test-mock:12345, 303 See Other in 101.2ms @ auth/auth.go:170(auth.SignInPost)
    testlogger.go:84: 2023/05/09 04:27:26 ...eb/routing/logger.go:98:func1() [I] [6459cbae-27] router: completed POST /user/login for test-mock:12345, 303 See Other in 98.5ms @ auth/auth.go:170(auth.SignInPost)
    testlogger.go:84: 2023/05/09 04:27:26 ...eb/routing/logger.go:98:func1() [I] [6459cbae-26] router: completed POST /user/login for test-mock:12345, 303 See Other in 110.6ms @ auth/auth.go:170(auth.SignInPost)
    testlogger.go:84: 2023/05/09 04:27:26 ...eb/routing/logger.go:98:func1() [I] [6459cbae-28] router: completed GET /user/settings/applications for test-mock:12345, 200 OK in 129.8ms @ setting/applications.go:23(setting.Applications)
    testlogger.go:84: 2023/05/09 04:27:26 ...eb/routing/logger.go:98:func1() [I] [6459cbae-32] router: completed GET /user/settings/applications for test-mock:12345, 200 OK in 150.5ms @ setting/applications.go:23(setting.Applications)
    testlogger.go:84: 2023/05/09 04:27:26 ...eb/routing/logger.go:98:func1() [I] [6459cbae-31] router: completed GET /user/settings/applications for test-mock:12345, 200 OK in 184.1ms @ setting/applications.go:23(setting.Applications)
    testlogger.go:84: 2023/05/09 04:27:26 ...eb/routing/logger.go:98:func1() [I] [6459cbae-33] router: completed GET /user/settings/applications for test-mock:12345, 200 OK in 197.9ms @ setting/applications.go:23(setting.Applications)
    testlogger.go:84: 2023/05/09 04:27:26 ...eb/routing/logger.go:98:func1() [I] [6459cbae-34] router: completed GET /user/settings/applications for test-mock:12345, 200 OK in 199.4ms @ setting/applications.go:23(setting.Applications)
    testlogger.go:84: 2023/05/09 04:27:26 ...eb/routing/logger.go:98:func1() [I] [6459cbae-36] router: completed GET /user/settings/applications for test-mock:12345, 200 OK in 240.1ms @ setting/applications.go:23(setting.Applications)
    testlogger.go:84: 2023/05/09 04:27:26 ...eb/routing/logger.go:98:func1() [I] [6459cbae-37] router: completed GET /user/settings/applications for test-mock:12345, 200 OK in 242.1ms @ setting/applications.go:23(setting.Applications)
    testlogger.go:84: 2023/05/09 04:27:26 ...eb/routing/logger.go:98:func1() [I] [6459cbae-39] router: completed GET /user/settings/applications for test-mock:12345, 200 OK in 247.6ms @ setting/applications.go:23(setting.Applications)
    testlogger.go:84: 2023/05/09 04:27:26 ...eb/routing/logger.go:98:func1() [I] [6459cbae-38] router: completed GET /user/settings/applications for test-mock:12345, 200 OK in 279.1ms @ setting/applications.go:23(setting.Applications)
    testlogger.go:84: 2023/05/09 04:27:26 ...eb/routing/logger.go:98:func1() [I] [6459cbae-35] router: completed POST /user/settings/applications for test-mock:12345, 303 See Other in 395.5ms @ setting/applications.go:33(setting.ApplicationsPost)
    testlogger.go:84: 2023/05/09 04:27:27 ...eb/routing/logger.go:98:func1() [I] [6459cbae-42] router: completed POST /user/settings/applications for test-mock:12345, 303 See Other in 468.9ms @ setting/applications.go:33(setting.ApplicationsPost)
    testlogger.go:84: 2023/05/09 04:27:27 ...eb/routing/logger.go:98:func1() [I] [6459cbaf] router: completed GET /user/settings/applications for test-mock:12345, 200 OK in 52.8ms @ setting/applications.go:23(setting.Applications)
    testlogger.go:84: 2023/05/09 04:27:27 ...eb/routing/logger.go:98:func1() [I] [6459cbae-44] router: completed POST /user/settings/applications for test-mock:12345, 303 See Other in 473.4ms @ setting/applications.go:33(setting.ApplicationsPost)
    testlogger.go:84: 2023/05/09 04:27:27 ...eb/routing/logger.go:98:func1() [I] [6459cbae-40] router: completed POST /user/settings/applications for test-mock:12345, 303 See Other in 686.9ms @ setting/applications.go:33(setting.ApplicationsPost)
    testlogger.go:84: 2023/05/09 04:27:27 ...eb/routing/logger.go:98:func1() [I] [6459cbae-41] router: completed POST /user/settings/applications for test-mock:12345, 303 See Other in 639.1ms @ setting/applications.go:33(setting.ApplicationsPost)
    testlogger.go:84: 2023/05/09 04:27:27 ...eb/routing/logger.go:98:func1() [I] [6459cbae-45] router: completed POST /user/settings/applications for test-mock:12345, 303 See Other in 561.3ms @ setting/applications.go:33(setting.ApplicationsPost)
    testlogger.go:84: 2023/05/09 04:27:27 ...eb/routing/logger.go:98:func1() [I] [6459cbae-47] router: completed POST /user/settings/applications for test-mock:12345, 303 See Other in 529.8ms @ setting/applications.go:33(setting.ApplicationsPost)
    testlogger.go:84: 2023/05/09 04:27:27 ...eb/routing/logger.go:98:func1() [I] [6459cbae-43] router: completed POST /user/settings/applications for test-mock:12345, 303 See Other in 640.9ms @ setting/applications.go:33(setting.ApplicationsPost)
    testlogger.go:84: 2023/05/09 04:27:27 ...eb/routing/logger.go:98:func1() [I] [6459cbae-48] router: completed POST /user/settings/applications for test-mock:12345, 303 See Other in 531.3ms @ setting/applications.go:33(setting.ApplicationsPost)
    testlogger.go:84: 2023/05/09 04:27:27 ...eb/routing/logger.go:98:func1() [I] [6459cbaf-9] router: completed GET /user/settings/applications for test-mock:12345, 200 OK in 60.7ms @ setting/applications.go:23(setting.Applications)
    testlogger.go:84: 2023/05/09 04:27:27 ...eb/routing/logger.go:98:func1() [I] [6459cbae-46] router: completed POST /user/settings/applications for test-mock:12345, 303 See Other in 643.6ms @ setting/applications.go:33(setting.ApplicationsPost)
    testlogger.go:84: 2023/05/09 04:27:27 ...eb/routing/logger.go:98:func1() [I] [6459cbaf-8] router: completed GET /user/settings/applications for test-mock:12345, 200 OK in 103.3ms @ setting/applications.go:23(setting.Applications)
    testlogger.go:84: 2023/05/09 04:27:27 ...eb/routing/logger.go:98:func1() [I] [6459cbae-49] router: completed GET /user/settings/applications for test-mock:12345, 200 OK in 536.9ms @ setting/applications.go:23(setting.Applications)
    testlogger.go:84: 2023/05/09 04:27:27 ...eb/routing/logger.go:98:func1() [I] [6459cbaf-7] router: completed GET /user/settings/applications for test-mock:12345, 200 OK in 178.6ms @ setting/applications.go:23(setting.Applications)
    testlogger.go:84: 2023/05/09 04:27:27 ...eb/routing/logger.go:98:func1() [I] [6459cbaf-6] router: completed GET /user/settings/applications for test-mock:12345, 200 OK in 203.1ms @ setting/applications.go:23(setting.Applications)
    testlogger.go:84: 2023/05/09 04:27:27 ...eb/routing/logger.go:98:func1() [I] [6459cbaf-4] router: completed GET /user/settings/applications for test-mock:12345, 200 OK in 313.9ms @ setting/applications.go:23(setting.Applications)
    testlogger.go:84: 2023/05/09 04:27:27 ...eb/routing/logger.go:98:func1() [I] [6459cbaf-2] router: completed GET /user/settings/applications for test-mock:12345, 200 OK in 417.0ms @ setting/applications.go:23(setting.Applications)
    testlogger.go:84: 2023/05/09 04:27:27 ...eb/routing/logger.go:98:func1() [I] [6459cbaf-11] router: completed GET /user/settings/applications for test-mock:12345, 200 OK in 217.9ms @ setting/applications.go:23(setting.Applications)
    testlogger.go:84: 2023/05/09 04:27:28 ...eb/routing/logger.go:98:func1() [I] [6459cbaf-5] router: completed GET /user/settings/applications for test-mock:12345, 200 OK in 746.4ms @ setting/applications.go:23(setting.Applications)
    testlogger.go:84: 2023/05/09 04:27:28 ...eb/routing/logger.go:98:func1() [I] [6459cbaf-3] router: completed POST /api/v1/repos/user2/repo1/statuses/65f1bf27bc3bf70f64657658635e66094edbcb4d?token=f3eaa96f3ed2b66db84af0ec95fe65d29f52bf21 for test-mock:12345, 201 Created in 1050.7ms @ repo/status.go:20(repo.NewCommitStatus)
    testlogger.go:84: 2023/05/09 04:27:28 ...eb/routing/logger.go:98:func1() [I] [6459cbaf-10] router: completed POST /api/v1/repos/user2/repo1/statuses/65f1bf27bc3bf70f64657658635e66094edbcb4d?token=a287aa95db15ed6b1993de3aafdb3d25b83c9c48 for test-mock:12345, 201 Created in 832.7ms @ repo/status.go:20(repo.NewCommitStatus)
    testlogger.go:84: 2023/05/09 04:27:28 ...eb/routing/logger.go:98:func1() [I] [6459cbaf-14] router: completed POST /api/v1/repos/user2/repo1/statuses/65f1bf27bc3bf70f64657658635e66094edbcb4d?token=7aa54833f0a7eed7b777372c6fad8da7eca2769d for test-mock:12345, 201 Created in 764.1ms @ repo/status.go:20(repo.NewCommitStatus)
    testlogger.go:84: 2023/05/09 04:27:28 ...pi/v1/repo/status.go:65:NewCommitStatus() [E] [6459cbaf-13] CreateCommitStatus: NewCommitStatus[repo_id: 1, user_id: 2, sha: 65f1bf27bc3bf70f64657658635e66094edbcb4d]: insert CommitStatus[/tmp/tmp.frEdo8pdce/tests/integration/gitea-integration-mysql/gitea-repositories/user2/repo1.git, 65f1bf27bc3bf70f64657658635e66094edbcb4d]: Error 1062 (23000): Duplicate entry '6-1-65f1bf27bc3bf70f64657658635e66094edbcb4d' for key 'UQE_commit_status_repo_sha_index'
    --- FAIL: TestRepoCommitsStatusParallel/ParallelCreateStatus_9 (1.95s)
        pull_status_test.go:108: 
            	Error Trace:	/home/runner/work/gitea/gitea/tests/integration/integration_test.go:379
            	            				/home/runner/work/gitea/gitea/tests/integration/integration_test.go:173
            	            				/home/runner/work/gitea/gitea/tests/integration/pull_status_test.go:108
            	            				/home/runner/work/gitea/gitea/tests/integration/repo_commits_test.go:163
            	Error:      	Not equal: 
            	            	expected: 201
            	            	actual  : 500
            	Test:       	TestRepoCommitsStatusParallel/ParallelCreateStatus_9
            	Messages:   	Request: POST /api/v1/repos/user2/repo1/statuses/65f1bf27bc3bf70f64657658635e66094edbcb4d?token=8365bb6c656fc40b3b6e0ea894c40184d4090298
        pull_status_test.go:108: Response:  {"message":"","url":"http://localhost:3001/api/swagger"}
            
    testlogger.go:84: 2023/05/09 04:27:28 ...eb/routing/logger.go:98:func1() [I] [6459cbaf-13] router: completed POST /api/v1/repos/user2/repo1/statuses/65f1bf27bc3bf70f64657658635e66094edbcb4d?token=8365bb6c656fc40b3b6e0ea894c40184d4090298 for test-mock:12345, 500 Internal Server Error in 781.9ms @ repo/status.go:20(repo.NewCommitStatus)
    testlogger.go:84: 2023/05/09 04:27:28 ...eb/routing/logger.go:98:func1() [I] [6459cbaf-16] router: completed POST /api/v1/repos/user2/repo1/statuses/65f1bf27bc3bf70f64657658635e66094edbcb4d?token=ae774b5cf67d220bd4570495344f525708c2125f for test-mock:12345, 201 Created in 710.4ms @ repo/status.go:20(repo.NewCommitStatus)
    testlogger.go:84: 2023/05/09 04:27:28 ...eb/routing/logger.go:98:func1() [I] [6459cbaf-17] router: completed POST /api/v1/repos/user2/repo1/statuses/65f1bf27bc3bf70f64657658635e66094edbcb4d?token=567930a75e620207c31073f7d042274b68526165 for test-mock:12345, 201 Created in 685.7ms @ repo/status.go:20(repo.NewCommitStatus)
    testlogger.go:84: 2023/05/09 04:27:28 ...eb/routing/logger.go:98:func1() [I] [6459cbaf-12] router: completed POST /api/v1/repos/user2/repo1/statuses/65f1bf27bc3bf70f64657658635e66094edbcb4d?token=c5d35466f761720e70117abdbc664202f4796128 for test-mock:12345, 201 Created in 850.8ms @ repo/status.go:20(repo.NewCommitStatus)
    testlogger.go:84: 2023/05/09 04:27:28 ...eb/routing/logger.go:98:func1() [I] [6459cbaf-15] router: completed POST /api/v1/repos/user2/repo1/statuses/65f1bf27bc3bf70f64657658635e66094edbcb4d?token=e24dec445f8ffa6baf90cd13cbe9d1e8f79c8839 for test-mock:12345, 201 Created in 779.6ms @ repo/status.go:20(repo.NewCommitStatus)
    testlogger.go:84: 2023/05/09 04:27:28 ...eb/routing/logger.go:98:func1() [I] [6459cbaf-18] router: completed POST /api/v1/repos/user2/repo1/statuses/65f1bf27bc3bf70f64657658635e66094edbcb4d?token=7a718c00e2fb3071e26bf553f277bd839dfe6f06 for test-mock:12345, 201 Created in 613.5ms @ repo/status.go:20(repo.NewCommitStatus)
    testlogger.go:84: 2023/05/09 04:27:28 ...eb/routing/logger.go:98:func1() [I] [6459cbb0] router: completed POST /api/v1/repos/user2/repo1/statuses/65f1bf27bc3bf70f64657658635e66094edbcb4d?token=920aed1fe0eb8cec0adb869b92cfe672dfc5ab8f for test-mock:12345, 201 Created in 328.9ms @ repo/status.go:20(repo.NewCommitStatus)

Full logs: logs_1035.zip, in case you don't have permissions to see or they get erased in the future.

[kousu]

By the way I think #24532 is a duplicate of this?

[silverwind]

Another failure: https://github.com/go-gitea/gitea/actions/runs/4984577376/jobs/8923100485?pr=24740

We should consider skipping the test on CI.

[silverwind]

#24741 for the CI skip.

[silverwind]

I think it may not yet be fully resolved for MSSQL:

https://github.com/go-gitea/gitea/actions/runs/5211731616/jobs/9404404909?pr=25134

--- FAIL: TestRepoCommitsStatusParallel (5.01s)
    --- FAIL: TestRepoCommitsStatusParallel/ParallelCreateStatus_4 (3.99s)
        pull_status_test.go:108: 
            	Error Trace:	/home/runner/work/gitea/gitea/tests/integration/integration_test.go:379
            	            				/home/runner/work/gitea/gitea/tests/integration/integration_test.go:173
            	            				/home/runner/work/gitea/gitea/tests/integration/pull_status_test.go:108
            	            				/home/runner/work/gitea/gitea/tests/integration/repo_commits_test.go:163
            	Error:      	Not equal: 
            	            	expected: 201
            	            	actual  : 500
            	Test:       	TestRepoCommitsStatusParallel/ParallelCreateStatus_4
            	Messages:   	Request: POST /api/v1/repos/user2/repo1/statuses/65f1bf27bc3bf70f64657658635e66094edbcb4d?token=bacb177a1cef232e59aa67b27b1143285e7a65fb
        pull_status_test.go:108: Response:  {"message":"","url":"http://localhost:3003/api/swagger"}