Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Generate status commit index parallelly failed #24532

Closed
lunny opened this issue May 5, 2023 · 4 comments
Closed

Generate status commit index parallelly failed #24532

lunny opened this issue May 5, 2023 · 4 comments
Labels
issue/duplicate The issue has already been reported.

Comments

@lunny
Copy link
Member

lunny commented May 5, 2023

Description

--- FAIL: TestRepoCommitsStatusParallel/ParallelCreateStatus_9 (0.34s)
        pull_status_test.go:108: 
            	Error Trace:	/home/runner/work/gitea/gitea/integration_test.go:378
            	            				/home/runner/work/gitea/gitea/integration_test.go:172
            	            				/home/runner/work/gitea/gitea/pull_status_test.go:108
            	            				/home/runner/work/gitea/gitea/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=2a0edf9d5edc67deebe4018e95ab67ae848df63a
        pull_status_test.go:108: Response:  {"message":"","url":"http://localhost:3004/api/swagger"}
            
    testlogger.go:77: 2023/05/05 01:43:37 ...pi/v1/repo/status.go:65:NewCommitStatus() [E] [64545f49-60] CreateCommitStatus: NewCommitStatus[repo_id: 1, user_id: 2, sha: 65f1bf27bc3bf70f64657658635e66094edbcb4d]: generate commit status index failed: Error 1213 (40001): Deadlock found when trying to get lock; try restarting transaction
    testlogger.go:77: 2023/05/05 01:43:37 ...eb/routing/logger.go:98:func1() [I] [64545f49-60] router: completed POST /api/v1/repos/user2/repo1/statuses/65f1bf27bc3bf70f64657658635e66094edbcb4d?token=2a0edf9d5edc67deebe4018e95ab67ae848df63a for test-mock:12345, 500 Internal Server Error in 150.5ms @ repo/status.go:20(repo.NewCommitStatus)
    testlogger.go:77: 2023/05/05 01:43:37 ...pi/v1/repo/status.go:65:NewCommitStatus() [E] [64545f49-63] CreateCommitStatus: NewCommitStatus[repo_id: 1, user_id: 2, sha: 65f1bf27bc3bf70f64657658635e66094edbcb4d]: insert CommitStatus[/tmp/tmp.YbUpxeoNIU/tests/integration/gitea-integration-mysql8/gitea-repositories/user2/repo1.git, 65f1bf27bc3bf70f64657658635e66094edbcb4d]: Error 1062 (23000): Duplicate entry '4-1-65f1bf27bc3bf70f64657658635e66094edbcb4d' for key 'commit_status.UQE_commit_status_repo_sha_index'
    --- FAIL: TestRepoCommitsStatusParallel/ParallelCreateStatus_6 (0.35s)
        pull_status_test.go:108: 
            	Error Trace:	/home/runner/work/gitea/gitea/integration_test.go:378
            	            				/home/runner/work/gitea/gitea/integration_test.go:172
            	            				/home/runner/work/gitea/gitea/pull_status_test.go:108
            	            				/home/runner/work/gitea/gitea/repo_commits_test.go:163
            	Error:      	Not equal: 
            	            	expected: 201
            	            	actual  : 500
            	Test:       	TestRepoCommitsStatusParallel/ParallelCreateStatus_6
            	Messages:   	Request: POST /api/v1/repos/user2/repo1/statuses/65f1bf27bc3bf70f64657658635e66094edbcb4d?token=1c47a6eaa29731897bfbbb6a961d4e3f5dbe0a33
        pull_status_test.go:108: Response:  {"message":"","url":"http://localhost:3004/api/swagger"}
            
    testlogger.go:77: 2023/05/05 01:43:37 ...eb/routing/logger.go:98:func1() [I] [64545f49-63] router: completed POST /api/v1/repos/user2/repo1/statuses/65f1bf27bc3bf70f64657658635e66094edbcb4d?token=1c47a6eaa29731897bfbbb6a961d4e3f5dbe0a33 for test-mock:12345, 500 Internal Server Error in 122.9ms @ repo/status.go:20(repo.NewCommitStatus)
    testlogger.go:77: 2023/05/05 01:43:37 ...eb/routing/logger.go:98:func1() [I] [64545f49-58] router: completed POST /api/v1/repos/user2/repo1/statuses/65f1bf27bc3bf70f64657658635e66094edbcb4d?token=5ea5a60c7aa8e936feb6ba8a72894d690fccaef7 for test-mock:12345, 201 Created in 170.3ms @ repo/status.go:20(repo.NewCommitStatus)
    testlogger.go:77: 2023/05/05 01:43:37 ...eb/routing/logger.go:98:func1() [I] [64545f49-61] router: completed POST /api/v1/repos/user2/repo1/statuses/65f1bf27bc3bf70f64657658635e66094edbcb4d?token=3ceb9530f5fb797d1c142fc27fba15542f16dd48 for test-mock:12345, 201 Created in 172.2ms @ repo/status.go:20(repo.NewCommitStatus)
    testlogger.go:77: 2023/05/05 01:43:37 ...eb/routing/logger.go:98:func1() [I] [64545f49-59] router: completed POST /api/v1/repos/user2/repo1/statuses/65f1bf27bc3bf70f64657658635e66094edbcb4d?token=2f22ce8d82f639ffdeec68d02de3ad4cefc58f92 for test-mock:12345, 201 Created in 176.6ms @ repo/status.go:20(repo.NewCommitStatus)
    testlogger.go:77: 2023/05/05 01:43:37 ...eb/routing/logger.go:98:func1() [I] [64545f49-65] router: completed POST /api/v1/repos/user2/repo1/statuses/65f1bf27bc3bf70f64657658635e66094edbcb4d?token=6a4162b40ebe2a15cfdc84b7197ead392a4f2d76 for test-mock:12345, 201 Created in 127.6ms @ repo/status.go:20(repo.NewCommitStatus)
    testlogger.go:77: 2023/05/05 01:43:37 ...eb/routing/logger.go:98:func1() [I] [64545f49-64] router: completed POST /api/v1/repos/user2/repo1/statuses/65f1bf27bc3bf70f64657658635e66094edbcb4d?token=23fee270b747039b6c4be3b917c624d6178737eb for test-mock:12345, 201 Created in 134.8ms @ repo/status.go:20(repo.NewCommitStatus)
    testlogger.go:77: 2023/05/05 01:43:37 ...eb/routing/logger.go:98:func1() [I] [64545f49-76] router: completed POST /api/v1/repos/user2/repo1/statuses/65f1bf27bc3bf70f64657658635e66094edbcb4d?token=39b5c0ed525fc96295b5d3efdcb387f8eb68517a for test-mock:12345, 201 Created in 84.5ms @ repo/status.go:20(repo.NewCommitStatus)
    testlogger.go:77: 2023/05/05 01:43:37 ...eb/routing/logger.go:98:func1() [I] [64545f49-74] router: completed POST /api/v1/repos/user2/repo1/statuses/65f1bf27bc3bf70f64657658635e66094edbcb4d?token=4098020a9564610d50e5d7bc2582c54288d1973f for test-mock:12345, 201 Created in 93.4ms @ repo/status.go:20(repo.NewCommitStatus)
    testlogger.go:77: 2023/05/05 01:43:37 ...eb/routing/logger.go:98:func1() [I] [64545f49-77] router: completed POST /api/v1/repos/user2/repo1/statuses/65f1bf27bc3bf70f64657658635e66094edbcb4d?token=de56d8271c1888bd0993eb997ba01a14110194ca for test-mock:12345, 201 Created in 88.0ms @ repo/status.go:20(repo.NewCommitStatus)
=== TestRepoCommitsStatusMultiple (/home/runner/work/gitea/gitea/tests/integration/repo_commits_test.go:172)

Gitea Version

8f17237

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?

CI with mysql8 database

Database

None

@lunny lunny added the type/bug label May 5, 2023
@wxiaoguang
Copy link
Contributor

------------------------
LATEST DETECTED DEADLOCK
------------------------
2023-05-07 22:05:41 0x700006f61000
*** (1) TRANSACTION:
TRANSACTION 2389106, ACTIVE 0 sec inserting
mysql tables in use 1, locked 1
LOCK WAIT 3 lock struct(s), heap size 1136, 2 row lock(s), undo log entries 1
MySQL thread id 11428, OS thread handle 123145430302720, query id 241439 localhost 127.0.0.1 root update
INSERT INTO `commit_status_index` (repo_id, sha, max_index) VALUES (1, '65f1bf27bc3bf70f64657658635e66094edbcb4d', 0)

*** (1) HOLDS THE LOCK(S):
RECORD LOCKS space id 24750 page no 5 n bits 72 index UQE_commit_status_index_repo_sha of table `gitea_test`.`commit_status_index` trx id 2389106 lock_mode X
Record lock, heap no 1 PHYSICAL RECORD: n_fields 1; compact format; info bits 0
 0: len 8; hex 73757072656d756d; asc supremum;;


*** (1) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 24750 page no 5 n bits 72 index UQE_commit_status_index_repo_sha of table `gitea_test`.`commit_status_index` trx id 2389106 lock_mode X insert intention waiting
Record lock, heap no 1 PHYSICAL RECORD: n_fields 1; compact format; info bits 0
 0: len 8; hex 73757072656d756d; asc supremum;;


*** (2) TRANSACTION:
TRANSACTION 2389110, ACTIVE 0 sec inserting
mysql tables in use 1, locked 1
LOCK WAIT 3 lock struct(s), heap size 1136, 2 row lock(s), undo log entries 1
MySQL thread id 11437, OS thread handle 123145430605824, query id 241482 localhost 127.0.0.1 root update
INSERT INTO `commit_status_index` (repo_id, sha, max_index) VALUES (1, '65f1bf27bc3bf70f64657658635e66094edbcb4d', 0)

*** (2) HOLDS THE LOCK(S):
RECORD LOCKS space id 24750 page no 5 n bits 72 index UQE_commit_status_index_repo_sha of table `gitea_test`.`commit_status_index` trx id 2389110 lock_mode X
Record lock, heap no 1 PHYSICAL RECORD: n_fields 1; compact format; info bits 0
 0: len 8; hex 73757072656d756d; asc supremum;;


*** (2) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 24750 page no 5 n bits 72 index UQE_commit_status_index_repo_sha of table `gitea_test`.`commit_status_index` trx id 2389110 lock_mode X insert intention waiting
Record lock, heap no 1 PHYSICAL RECORD: n_fields 1; compact format; info bits 0
 0: len 8; hex 73757072656d756d; asc supremum;;

*** WE ROLL BACK TRANSACTION (2)

@wxiaoguang
Copy link
Contributor

wxiaoguang commented May 7, 2023

Try this:

diff --git a/models/git/commit_status.go b/models/git/commit_status.go
index 82cbb2363..f6e9ce1da 100644
--- a/models/git/commit_status.go
+++ b/models/git/commit_status.go
@@ -82,7 +82,23 @@ func GetNextCommitStatusIndex(ctx context.Context, repoID int64, sha string) (in
        }
        if affected == 0 {
                // this slow path is only for the first time of creating a resource index
-               _, errIns := e.Exec("INSERT INTO `commit_status_index` (repo_id, sha, max_index) VALUES (?, ?, 0)", repoID, sha)
+               var errIns error
+               for i := 0; i < 5; i++ {
+                       // in case mysql deadlock occurs, retry for a few times
+                       // Error 1213 (40001): Deadlock found when trying to get lock; try restarting transaction
+                       // To reproduce:
+                       // * txn1: truncate commit_status_index; begin; update commit_status_index set max_index=max_index+1 where sha='xxx' and repo_id=1;
+                       // * txn2: begin; update commit_status_index set max_index=max_index+1 where sha='xxx' and repo_id=1;
+                       // * txn1: insert into `commit_status_index` (repo_id, sha, max_index) values (1, 'xxx', 0);
+                       // * txn2: insert into `commit_status_index` (repo_id, sha, max_index) values (1, 'xxx', 0); -- then deadlock
+                       // * then txn1 can commit, txn2 can retry and commit
+                       _, errIns = e.Exec("INSERT INTO `commit_status_index` (repo_id, sha, max_index) VALUES (?, ?, 0)", repoID, sha)
+                       if errIns != nil && strings.Contains(errIns.Error(), "Deadlock") {
+                               continue
+                       } else {
+                               break
+                       }
+               }
                res, err = e.Exec("UPDATE `commit_status_index` SET max_index=max_index+1 WHERE repo_id=? AND sha=?", repoID, sha)
                if err != nil {
                        return 0, err

@lunny
Copy link
Member Author

lunny commented May 7, 2023

Could you help to send the commit to #24567 ?

@wxiaoguang
Copy link
Contributor

No, I have no writer permission.

@lunny lunny closed this as completed May 9, 2023
@lunny lunny added issue/duplicate The issue has already been reported. and removed type/bug labels May 9, 2023
@github-actions github-actions bot locked as resolved and limited conversation to collaborators Jun 24, 2023
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
issue/duplicate The issue has already been reported.
Projects
None yet
Development

No branches or pull requests

2 participants