500 Internal Server Error when creating new pull request

[ralphtheninja]

• Gitea version (or commit ref): 1.1.1 (using gitea:1.1.1 from docker hub)
• Git version: 2.8.3
• Operating system: Ubuntu as host system (but running official docker image)
• Database (use [x]):
  • PostgreSQL
  • MySQL
  • MSSQL
  • SQLite
• Can you reproduce the bug at https://try.gitea.io:
  • Yes (provide example URL)
  • No
  • Not relevant
• Log gist: (real org, repo and ips redacted)

[Macaron] 2017-05-09 11:54:12: Started POST /org/repo/compare/master...pr-test for 1.2.3.4    
[Macaron] 2017-05-09 11:54:13: Completed /org/repo/compare/master...pr-test 302 Found in 1.06402539s
[Macaron] 2017-05-09 11:54:13: Started GET /org/repo/pulls/24 for 1.2.3.4                     
[Macaron] 2017-05-09 11:54:13: Completed /org/repo/pulls/24 500 Internal Server Error in 77.113788ms
[Macaron] 2017-05-09 11:54:14: Started GET /lms for 3.4.5.6                                                       
[Macaron] 2017-05-09 11:54:14: Completed /lms 200 OK in 4.469068ms                                                      

Description

The 500 internal server error only shows up on some repositories. I have tried on both try.gitea.io and on our self hosted gitea and PRs work just fine on a brand new small repo (like two tiny text files). However on some repositories it seems we always get 500 back.

Unfortunately there's no other information than the 500 Internal Server Error message in the log. Can I enable more verbose logging somehow or are there other logs to dig from? This is trivial for me to reproduce in our environment so should be easy for me to get to the bottom if I get some assistance in digging :)

[plessbd]

possibly related to #1372

[bkcsoft]

Setting this should make the logs waaaay more verbose 🙂

[log]
LEVEL=Trace

[ralphtheninja]

As a side note I also get 500 back when closing an already existing pull request.

[ralphtheninja]

Some additional information. It seems I can reproduce this by just closing/re-opening a PR. When creating a new PR it always fails (for the repository in question). But when re-opening/closing it fails randomly, i.e. fails sometimes and succeeds sometimes.

The pattern I can see when I get 500 back seems to be related to the database, i.e. database table is locked: notification. Maybe this can give some more insight (user/notification.go:33)

See summary below:

Create a new PR

This always fails (for the repository in question):

2017/05/09 14:14:41 [D] Session ID: 2624f619d1bbc418                                                                                                                                                                                                                                                                                                                        
2017/05/09 14:14:41 [D] CSRF Token: XXXXX                                                                                                                                                                                                                                                                                                                                   
2017/05/09 14:14:41 [T] PullRequest[0].testPatch (patchPath): /data/git/repositories/ORG/REPO.git/pulls/26.patch                                                                                                                                                                                                                                                            
2017/05/09 14:14:42 [T] PushToBaseRepo[22]: pushing commits to base repo 'refs/pull/26/head'                                                                                                                                                                                                                                                                                
2017/05/09 14:14:42 [T] DeliverHooks [repo_id: 22]                                                                                                                                                                                                                                                                                                                          
2017/05/09 14:14:42 [T] Pull request created: 22/80                                                                                                                                                                                                                                                                                                                         
2017/05/09 14:14:43 [D] Session ID: 2624f619d1bbc418                                                                                                                                                                                                                                                                                                                        
2017/05/09 14:14:43 [D] CSRF Token: XXXXX                                                                                                                                                                                                                                                                                                                                   
2017/05/09 14:14:43 [...user/notification.go:33 GetNotificationCount()] [E] GetNotificationCount: database table is locked: notification                                                                                                                                                                                                                                    
2017/05/09 14:14:43 [D] Template: status/500                                                                                                                                                                                                                                                                                                                                
2017/05/09 14:14:43 [T] Hook delivered: 824eeec6-6502-45a1-9f25-d61ea999c875                                                                                                                                                                                                                                                                                                
2017/05/09 14:14:43 [...ea/models/webhook.go:643 DeliverHooks()] [E] GetWebhookByID: webhook does not exist [id: 2]                                                                                                                                                                                                                                                         

Re-opening a closed PR

Sometimes fails, sometimes not. Seems it works/fails every other time I re-open a PR.

When re-opening fails:

2017/05/09 14:07:44 [D] Session ID: 2624f619d1bbc418                                                                                                                                                                                                                                                                                                                        
2017/05/09 14:07:44 [D] CSRF Token: XXXXX                                                                                                                                                                                                                                                                                                                                   
2017/05/09 14:07:44 [.../runtime/asm_amd64.s:2086 goexit()] [E] AddToTaskQueue.UpdateCols[72].(add to queue): database table is locked                                                                                                                                                                                                                                      
2017/05/09 14:07:44 [T] TestPullRequests[72]: processing test task                                                                                                                                                                                                                                                                                                          
2017/05/09 14:07:44 [...gitea/models/pull.go:1092 TestPullRequests()] [E] PullRequest[72].getMergeCommit: GetRepositoryByID: repository does not exist [id: 22, uid: 0, name: ]                                                                                                                                                                                             
2017/05/09 14:07:44 [.../runtime/asm_amd64.s:2086 goexit()] [E] testPatch[72]: GetRepositoryByID: repository does not exist [id: 22, uid: 0, name: ]                                                                                                                                                                                                                        
2017/05/09 14:07:44 [T] Issue [79] status changed to closed: false                                                                                                                                                                                                                                                                                                          
2017/05/09 14:07:44 [T] DeliverHooks [repo_id: 22]                                                                                                                                                                                                                                                                                                                          
2017/05/09 14:07:45 [D] Session ID: 2624f619d1bbc418                                                                                                                                                                                                                                                                                                                        
2017/05/09 14:07:45 [D] CSRF Token: XXXXX                                                                                                                                                                                                                                                                                                                                   
2017/05/09 14:07:45 [...user/notification.go:33 GetNotificationCount()] [E] GetNotificationCount: database table is locked: notification                                                                                                                                                                                                                                    
2017/05/09 14:07:45 [D] Template: status/500                                                                                                                                                                                                                                                                                                                                
2017/05/09 14:07:46 [T] Hook delivered: 119de1a1-0b46-42ec-aa5c-12c041ec7e34                                                                                                                                                                                                                                                                                                
2017/05/09 14:07:46 [...ea/models/webhook.go:643 DeliverHooks()] [E] GetWebhookByID: webhook does not exist [id: 2]                                                                                                                                                                                                                                                         

When re-opening succeeds:

2017/05/09 14:10:21 [D] Session ID: 2624f619d1bbc418                                                                                                                                                                                                                                                                                                                        
2017/05/09 14:10:21 [D] CSRF Token: XXXXX                                                                                                                                                                                                                                                                                                                                   
2017/05/09 14:10:21 [.../runtime/asm_amd64.s:2086 goexit()] [E] AddToTaskQueue.UpdateCols[72].(add to queue): database table is locked                                                                                                                                                                                                                                      
2017/05/09 14:10:21 [T] TestPullRequests[72]: processing test task                                                                                                                                                                                                                                                                                                          
2017/05/09 14:10:21 [...gitea/models/pull.go:1092 TestPullRequests()] [E] PullRequest[72].getMergeCommit: GetRepositoryByID: repository does not exist [id: 22, uid: 0, name: ]                                                                                                                                                                                             
2017/05/09 14:10:21 [.../runtime/asm_amd64.s:2086 goexit()] [E] testPatch[72]: GetRepositoryByID: repository does not exist [id: 22, uid: 0, name: ]                                                                                                                                                                                                                        
2017/05/09 14:10:21 [T] DeliverHooks [repo_id: 22]                                                                                                                                                                                                                                                                                                                          
2017/05/09 14:10:21 [T] Issue [79] status changed to closed: false                                                                                                                                                                                                                                                                                                          
2017/05/09 14:10:21 [D] Session ID: 2624f619d1bbc418                                                                                                                                                                                                                                                                                                                        
2017/05/09 14:10:21 [D] CSRF Token: XXXXX                                                                                                                                                                                                                                                                                                                                   
2017/05/09 14:10:21 [D] Template: repo/issue/view                                                                                                                                                                                                                                                                                                                           
2017/05/09 14:10:22 [T] Hook delivered: e70e6e2c-d3f9-483e-b531-0c6296ef9c4a                                                                                                                                                                                                                                                                                                
2017/05/09 14:10:22 [...ea/models/webhook.go:643 DeliverHooks()] [E] GetWebhookByID: webhook does not exist [id: 2]                                                                                                                                                                                                                                                         

When closing a PR

When closing fails:

2017/05/09 14:06:01 [D] Session ID: 2624f619d1bbc418                                                                                                                                                                                                                                                                                                                        
2017/05/09 14:06:01 [D] CSRF Token: XXXXX                                                                                                                                                                                                                                                                                                                                   
2017/05/09 14:06:01 [T] Issue [79] status changed to closed: true                                                                                                                                                                                                                                                                                                           
2017/05/09 14:06:01 [T] DeliverHooks [repo_id: 22]                                                                                                                                                                                                                                                                                                                          
2017/05/09 14:06:01 [D] Session ID: 2624f619d1bbc418                                                                                                                                                                                                                                                                                                                        
2017/05/09 14:06:01 [D] CSRF Token: XXXXX                                                                                                                                                                                                                                                                                                                                   
2017/05/09 14:06:01 [...user/notification.go:33 GetNotificationCount()] [E] GetNotificationCount: database table is locked: notification                                                                                                                                                                                                                                    
2017/05/09 14:06:01 [D] Template: status/500                                                                                                                                                                                                                                                                                                                                
2017/05/09 14:06:02 [T] Hook delivered: f6db92b9-e7ff-4334-b6c5-a3ea05f5130a                                                                                                                                                                                                                                                                                                
2017/05/09 14:06:02 [...ea/models/webhook.go:643 DeliverHooks()] [E] GetWebhookByID: webhook does not exist [id: 2]                                                                                                                                                                                                                                                         

When closing succeeds:

2017/05/09 14:11:32 [D] Session ID: 2624f619d1bbc418                                                                                                                                                                                                                                                                                                                        
2017/05/09 14:11:32 [D] CSRF Token: XXXXX                                                                                                                                                                                                                                                                                                                                   
2017/05/09 14:11:32 [T] Issue [79] status changed to closed: true                                                                                                                                                                                                                                                                                                           
2017/05/09 14:11:32 [T] DeliverHooks [repo_id: 22]                                                                                                                                                                                                                                                                                                                          
2017/05/09 14:11:32 [D] Session ID: 2624f619d1bbc418                                                                                                                                                                                                                                                                                                                        
2017/05/09 14:11:32 [D] CSRF Token: XXXXX                                                                                                                                                                                                                                                                                                                                   
2017/05/09 14:11:32 [D] Template: repo/issue/view                                                                                                                                                                                                                                                                                                                           
2017/05/09 14:11:33 [T] Hook delivered: 6e5841e5-9554-4435-976e-b24ac6dd90c3                                                                                                                                                                                                                                                                                                
2017/05/09 14:11:33 [...ea/models/webhook.go:643 DeliverHooks()] [E] GetWebhookByID: webhook does not exist [id: 2] 

[ralphtheninja]

Some more information. If after I have received a 500 and refresh the page, it always works. So seems to me that we sometimes abort with 500 before returning the pr-page. This makes sense too since creating/closing/re-opening is something more than just doing a simple http GET on the page.

[bkcsoft]

Duplicate of #1434