Error 500 on comment creation via API, with sudo

[jlecour]

• Gitea version (or commit ref): 1.7.0
• Git version: 2.20.1
• Operating system: Deban 9.6
• 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:

Description

I've been using the API to import projects and issues from Redmine/Gitolite to Gitea (it will be open sourced soon).
For a few days I've been using a Gitea instance with a version < 1.7 and it seemed to work really well. I could create issues and comments on repositories, with or without the Sudo header.
It seems that after the 1.7 upgrade I can't use Sudo anymore.
My request fail if I add the HTTP header. I get the same error with the query string parameter.

Examples :

# this one works
curl -v -X POST "https://my-gitea/api/v1/repos/jlecour/tests-redmine-to-gitea/issues/1/comments" -H "accept: application/json" -H "Authorization: token XXX" -H "Content-Type: application/json" -d "{ \"body\": \"comment body\"}"

# this one doesn't work (error 500)
curl -v -X POST "https://my-gitea/api/v1/repos/jlecour/tests-redmine-to-gitea/issues/1/comments" -H "accept: application/json" -H "Authorization: token XXX" -H "Content-Type: application/json" -d "{ \"body\": \"comment body\"}" -H "Sudo: other_user"

Obviously other_user exists and is a collaborator on the repository with Write permission.

In the logs, I only get SQL logs with a failed transaction (ROLLBACK). I've executed each request manually against my database and I get no error, so I guess the faulty request is not logged.

I'm not sure if it's a bug or if I did something wrong.
Is there a way to have more information about the error ?

[jlecour]

I've tried this on try.gitea.org but I can't get to use sudo since I'm not an administrator.

[jlecour]

Another strange fact : I can create issues with Sudo (and the same user, on the same repository), but it fails for comments

[zeripath]

Oo that's interesting... Just tried this on master on my local machine.
I can get a 500 if I fail to log in correctly:

[Macaron] 2019-01-27 21:26:23: Started POST /api/v1/repos/administrator/private-with-collaborator/issues/1/comments for 127.0.0.1
[Macaron] PANIC: runtime error: invalid memory address or nil pointer dereference
/usr/lib/go-1.10/src/runtime/panic.go:502 (0x4388f8)
	gopanic: reflectcall(nil, unsafe.Pointer(d.fn), deferArgs(d), uint32(d.siz), uint32(d.siz))
/usr/lib/go-1.10/src/runtime/panic.go:63 (0x43796d)
	panicmem: panic(memoryError)
/usr/lib/go-1.10/src/runtime/signal_unix.go:388 (0x44e879)
	sigpanic: panicmem()
/home/andrew/go/src/code.gitea.io/gitea/routers/api/v1/api.go:88 (0x12a48a2)
	sudo.func1: if ctx.User.IsAdmin {
...

It's de-referencing null because ctx.User isn't actually set anymore.

Nasty. I don't understand how the tests didn't pick this up.

I've put in a PR to fix this.

[zeripath]

OK, I think I've spotted a different bug, because I wasn't actually properly logging in... So I was getting a null pointer - which is bad enough to require a patch in itself...

[zeripath]

I'm not able to completely replicate your issue on master. Let me check on 1.7.0

[jlecour]

Is there a special mode I can run my instance with to help you debug this ?

[zeripath]

Hmm... I can't replicate with a valid token. I can get a 500 if the token is invalid though and I've just put a PR in for that. Are you sure that your token is correct?

[zeripath]

Is there something special about that issue?

[zeripath]

I guess you aren't getting the above nil dereference error?

[jlecour]

As far as I can tell, my token is working.
I've been using it to create/delete repositories and issues (with Sudo), add collaborators to a repository…
I just can't post a comment with Sudo :/

[zeripath]

If you're getting a ROLLBACK then something is causing a conflict in the database - which is very odd.

[jlecour]

It's working perfectly with 1.6.3 but not with 1.7.0.

[zeripath]

I suspect its something to do with my fixing of deadlocks patches. There's a cascade of actions that come after the creation of an issue comment. I wonder if one of them isn't working within the session...

[jlecour]

It's also OK with 1.6.4.

[zeripath]

OK presumably the conflict is occurring in here: https://github.com/go-gitea/gitea/blob/master/models/issue_comment.go#L544

[zeripath]

Do you have watchers on your issue or have webhooks?

[jlecour]

No watchers on the comment.
Since it's an import job from another code hosting system, the issue is created and the comments are added right after that.

There is also no webhooks nor Git hooks.

[zeripath]

There's nothing trying to post at the same time is there? Maybe you're both trying to post at the same time although there really should be an error thrown back to you.

[zeripath]

Could you post your db log with the rollback in it? And what dB are you using?

[jlecour]

I don't think anything tries to post at the same time. It's a procedural script.

Here is the DB log :

2019/01/28 00:07:32 [I] [SQL] SELECT `id`, `owner_id`, `lower_name`, `name`, `description`, `website`, `default_branch`, `num_watches`, `num_stars`, `num_forks`, `num_issues`, `num_closed_issues`, `num_pulls`, `num_closed_pulls`, `num_milestones`, `num_closed_milestones`, `is_private`, `is_bare`, `is_mirror`, `is_fork`, `fork_id`, `size`, `is_fsck_enabled`, `topics`, `created_unix`, `updated_unix` FROM `repository` WHERE `id`=? LIMIT 1 []interface {}{90}
2019/01/28 00:07:32 [I] [SQL] SELECT `name` FROM `user` WHERE `id`=? LIMIT 1 []interface {}{11}
2019/01/28 00:07:32 [I] [SQL] SELECT * FROM `user` INNER JOIN issue_assignees ON assignee_id = `user`.id WHERE (issue_assignees.issue_id = ?) []interface {}{2559}
2019/01/28 00:07:33 [I] [SQL] SELECT `id`, `uid`, `name`, `sha1`, `created_unix`, `updated_unix` FROM `access_token` WHERE `sha1`=? LIMIT 1 []interface {}{"MYTOKEN"}
2019/01/28 00:07:33 [I] [SQL] UPDATE `access_token` SET `uid` = ?, `name` = ?, `sha1` = ?, `updated_unix` = ? WHERE `id`=? []interface {}{11, "remine-to-gitea", "MYTOKEN", 1548630453, 2}
2019/01/28 00:07:33 [I] [SQL] SELECT `id`, `lower_name`, `name`, `full_name`, `email`, `keep_email_private`, `passwd`, `must_change_password`, `login_type`, `login_source`, `login_name`, `type`, `location`, `website`, `rands`, `salt`, `language`, `created_unix`, `updated_unix`, `last_login_unix`, `last_repo_visibility`, `max_repo_creation`, `is_active`, `is_admin`, `allow_git_hook`, `allow_import_local`, `allow_create_organization`, `prohibit_login`, `avatar`, `avatar_email`, `use_custom_avatar`, `num_followers`, `num_following`, `num_stars`, `num_repos`, `description`, `num_teams`, `num_members`, `diff_view_style` FROM `user` WHERE `id`=? LIMIT 1 []interface {}{11}
2019/01/28 00:07:33 [I] [SQL] SELECT `id`, `lower_name`, `name`, `full_name`, `email`, `keep_email_private`, `passwd`, `must_change_password`, `login_type`, `login_source`, `login_name`, `type`, `location`, `website`, `rands`, `salt`, `language`, `created_unix`, `updated_unix`, `last_login_unix`, `last_repo_visibility`, `max_repo_creation`, `is_active`, `is_admin`, `allow_git_hook`, `allow_import_local`, `allow_create_organization`, `prohibit_login`, `avatar`, `avatar_email`, `use_custom_avatar`, `num_followers`, `num_following`, `num_stars`, `num_repos`, `description`, `num_teams`, `num_members`, `diff_view_style` FROM `user` WHERE `lower_name`=? LIMIT 1 []interface {}{"redmine_importer"}
2019/01/28 00:07:33 [I] [SQL] SELECT `id`, `lower_name`, `name`, `full_name`, `email`, `keep_email_private`, `passwd`, `must_change_password`, `login_type`, `login_source`, `login_name`, `type`, `location`, `website`, `rands`, `salt`, `language`, `created_unix`, `updated_unix`, `last_login_unix`, `last_repo_visibility`, `max_repo_creation`, `is_active`, `is_admin`, `allow_git_hook`, `allow_import_local`, `allow_create_organization`, `prohibit_login`, `avatar`, `avatar_email`, `use_custom_avatar`, `num_followers`, `num_following`, `num_stars`, `num_repos`, `description`, `num_teams`, `num_members`, `diff_view_style` FROM `user` WHERE `lower_name`=? LIMIT 1 []interface {}{"jlecour"}
2019/01/28 00:07:33 [I] [SQL] SELECT `id`, `owner_id`, `lower_name`, `name`, `description`, `website`, `default_branch`, `num_watches`, `num_stars`, `num_forks`, `num_issues`, `num_closed_issues`, `num_pulls`, `num_closed_pulls`, `num_milestones`, `num_closed_milestones`, `is_private`, `is_bare`, `is_mirror`, `is_fork`, `fork_id`, `size`, `is_fsck_enabled`, `topics`, `created_unix`, `updated_unix` FROM `repository` WHERE `owner_id`=? AND `lower_name`=? LIMIT 1 []interface {}{11, "tests-redmine-to-gitea"}
2019/01/28 00:07:33 [I] [SQL] SELECT `id`, `repo_id`, `type`, `config`, `created_unix` FROM `repo_unit` WHERE (repo_id = ?) []interface {}{90}
2019/01/28 00:07:33 [I] [SQL] SELECT `id`, `user_id`, `repo_id`, `mode` FROM `access` WHERE `user_id`=? AND `repo_id`=? LIMIT 1 []interface {}{20, 90}
2019/01/28 00:07:33 [I] [SQL] BEGIN TRANSACTION
2019/01/28 00:07:33 [I] [SQL] INSERT INTO `issue` (`repo_id`,`index`,`poster_id`,`name`,`content`,`milestone_id`,`priority`,`is_closed`,`is_pull`,`num_comments`,`ref`,`deadline_unix`,`created_unix`,`updated_unix`,`closed_unix`) VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?) []interface {}{90, 6, 20, "Page d'activité / historique", "MY ISSUE", 0, 0, false, false, 0, "", 0, 1548630453, 1548630453, 0}
2019/01/28 00:07:33 [I] [SQL] UPDATE `repository` SET num_issues = num_issues + 1 WHERE id = ? []interface {}{90}
2019/01/28 00:07:33 [I] [SQL] SELECT `id`, `user_id`, `repo_id`, `mode` FROM `access` WHERE (repo_id = ? AND mode >= ?) []interface {}{90, 2}
2019/01/28 00:07:33 [I] [SQL] SELECT `id`, `lower_name`, `name`, `full_name`, `email`, `keep_email_private`, `passwd`, `must_change_password`, `login_type`, `login_source`, `login_name`, `type`, `location`, `website`, `rands`, `salt`, `language`, `created_unix`, `updated_unix`, `last_login_unix`, `last_repo_visibility`, `max_repo_creation`, `is_active`, `is_admin`, `allow_git_hook`, `allow_import_local`, `allow_create_organization`, `prohibit_login`, `avatar`, `avatar_email`, `use_custom_avatar`, `num_followers`, `num_following`, `num_stars`, `num_repos`, `description`, `num_teams`, `num_members`, `diff_view_style` FROM `user` WHERE `id` IN (?) []interface {}{20}
2019/01/28 00:07:33 [I] [SQL] INSERT INTO `issue_user` (`uid`, `issue_id`, `is_read`, `is_mentioned`) VALUES (?, ?, ?, ?),(?, ?, ?, ?) []interface {}{20, 2560, false, false, 11, 2560, false, false}
2019/01/28 00:07:33 [I] [SQL] SELECT * FROM `label` LEFT JOIN issue_label ON issue_label.label_id = label.id WHERE (issue_label.issue_id = ?) ORDER BY `label`.`name` ASC []interface {}{2560}
2019/01/28 00:07:33 [I] [SQL] SELECT * FROM `user` INNER JOIN issue_assignees ON assignee_id = `user`.id WHERE (issue_assignees.issue_id = ?) []interface {}{2560}
2019/01/28 00:07:33 [I] [SQL] SELECT `id`, `uuid`, `issue_id`, `release_id`, `comment_id`, `name`, `download_count`, `size`, `created_unix` FROM `attachment` WHERE (issue_id = ? AND comment_id = 0) []interface {}{2560}
2019/01/28 00:07:33 [I] [SQL] SELECT `id`, `type`, `poster_id`, `issue_id`, `label_id`, `old_milestone_id`, `milestone_id`, `assignee_id`, `removed_assignee`, `old_title`, `new_title`, `dependent_issue_id`, `commit_id`, `line`, `tree_path`, `content`, `patch`, `created_unix`, `updated_unix`, `commit_sha`, `review_id`, `invalidated` FROM `comment` WHERE comment.issue_id=? ORDER BY `comment`.`created_unix` ASC, `comment`.`id` ASC []interface {}{2560}
2019/01/28 00:07:33 [I] [SQL] SELECT COALESCE(sum(`time`),0) FROM `tracked_time` WHERE issue_id=? []interface {}{2560}
2019/01/28 00:07:33 [I] [SQL] SELECT `id`, `type`, `issue_id`, `comment_id`, `user_id`, `created_unix` FROM `reaction` WHERE reaction.issue_id=? ORDER BY `reaction`.`issue_id` ASC, `reaction`.`comment_id` ASC, `reaction`.`created_unix` ASC, `reaction`.`id` ASC []interface {}{2560}
2019/01/28 00:07:33 [I] [SQL] COMMIT
2019/01/28 00:07:33 [I] [SQL] SELECT * FROM `watch` INNER JOIN `user` ON `user`.id = `watch`.user_id WHERE (`watch`.repo_id=?) AND (`user`.is_active=?) AND (`user`.prohibit_login=?) []interface {}{90, true, false}
2019/01/28 00:07:33 [I] [SQL] SELECT `id`, `repo_id`, `index`, `poster_id`, `name`, `content`, `milestone_id`, `priority`, `is_closed`, `is_pull`, `num_comments`, `ref`, `deadline_unix`, `created_unix`, `updated_unix`, `closed_unix` FROM `issue` WHERE `id`=? LIMIT 1 []interface {}{2560}
2019/01/28 00:07:33 [I] [SQL] INSERT INTO `action` (`user_id`,`op_type`,`act_user_id`,`repo_id`,`comment_id`,`is_deleted`,`ref_name`,`is_private`,`content`,`created_unix`) VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, ?) []interface {}{20, 6, 20, 90, 0, false, "", true, "6|Page d'activité / historique", 1548630453}
2019/01/28 00:07:33 [I] [SQL] SELECT `id`, `lower_name`, `name`, `full_name`, `email`, `keep_email_private`, `passwd`, `must_change_password`, `login_type`, `login_source`, `login_name`, `type`, `location`, `website`, `rands`, `salt`, `language`, `created_unix`, `updated_unix`, `last_login_unix`, `last_repo_visibility`, `max_repo_creation`, `is_active`, `is_admin`, `allow_git_hook`, `allow_import_local`, `allow_create_organization`, `prohibit_login`, `avatar`, `avatar_email`, `use_custom_avatar`, `num_followers`, `num_following`, `num_stars`, `num_repos`, `description`, `num_teams`, `num_members`, `diff_view_style` FROM `user` WHERE `id`=? LIMIT 1 []interface {}{11}
2019/01/28 00:07:33 [I] [SQL] SELECT `id`, `repo_id`, `type`, `config`, `created_unix` FROM `repo_unit` WHERE (repo_id = ?) []interface {}{90}
2019/01/28 00:07:33 [I] [SQL] INSERT INTO `action` (`user_id`,`op_type`,`act_user_id`,`repo_id`,`comment_id`,`is_deleted`,`ref_name`,`is_private`,`content`,`created_unix`) VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, ?) []interface {}{11, 6, 20, 90, 0, false, "", true, "6|Page d'activité / historique", 1548630453}
2019/01/28 00:07:33 [I] [SQL] SELECT * FROM `watch` INNER JOIN `user` ON `user`.id = `watch`.user_id WHERE (`watch`.repo_id=?) AND (`user`.is_active=?) AND (`user`.prohibit_login=?) []interface {}{90, true, false}
2019/01/28 00:07:33 [I] [SQL] SELECT DISTINCT `poster_id` FROM `comment` INNER JOIN `user` ON `user`.id = `comment`.poster_id WHERE (`comment`.issue_id = ?) AND (`comment`.type = ?) AND (`user`.is_active = ?) AND (`user`.prohibit_login = ?) []interface {}{2560, 0, true, false}
2019/01/28 00:07:33 [I] [SQL] SELECT `id`, `lower_name`, `name`, `full_name`, `email`, `keep_email_private`, `passwd`, `must_change_password`, `login_type`, `login_source`, `login_name`, `type`, `location`, `website`, `rands`, `salt`, `language`, `created_unix`, `updated_unix`, `last_login_unix`, `last_repo_visibility`, `max_repo_creation`, `is_active`, `is_admin`, `allow_git_hook`, `allow_import_local`, `allow_create_organization`, `prohibit_login`, `avatar`, `avatar_email`, `use_custom_avatar`, `num_followers`, `num_following`, `num_stars`, `num_repos`, `description`, `num_teams`, `num_members`, `diff_view_style` FROM `user` WHERE `id`=? LIMIT 1 []interface {}{20}
2019/01/28 00:07:33 [I] [SQL] SELECT * FROM `user` INNER JOIN issue_assignees ON assignee_id = `user`.id WHERE (issue_assignees.issue_id = ?) []interface {}{2560}
2019/01/28 00:07:33 [I] [SQL] SELECT `id`, `lower_name`, `name`, `full_name`, `email`, `keep_email_private`, `passwd`, `must_change_password`, `login_type`, `login_source`, `login_name`, `type`, `location`, `website`, `rands`, `salt`, `language`, `created_unix`, `updated_unix`, `last_login_unix`, `last_repo_visibility`, `max_repo_creation`, `is_active`, `is_admin`, `allow_git_hook`, `allow_import_local`, `allow_create_organization`, `prohibit_login`, `avatar`, `avatar_email`, `use_custom_avatar`, `num_followers`, `num_following`, `num_stars`, `num_repos`, `description`, `num_teams`, `num_members`, `diff_view_style` FROM `user` WHERE `id`=? LIMIT 1 []interface {}{11}
2019/01/28 00:07:33 [I] [SQL] SELECT `id`, `user_id`, `repo_id`, `mode` FROM `access` WHERE `user_id`=? AND `repo_id`=? LIMIT 1 []interface {}{20, 90}
2019/01/28 00:07:33 [I] [SQL] SELECT * FROM `label` LEFT JOIN issue_label ON issue_label.label_id = label.id WHERE (issue_label.issue_id = ?) ORDER BY `label`.`name` ASC []interface {}{2560}
2019/01/28 00:07:33 [I] [SQL] SELECT * FROM `user` INNER JOIN issue_assignees ON assignee_id = `user`.id WHERE (issue_assignees.issue_id = ?) []interface {}{2560}
2019/01/28 00:07:33 [I] [SQL] SELECT `id`, `repo_id`, `org_id`, `url`, `content_type`, `secret`, `events`, `is_ssl`, `is_active`, `hook_task_type`, `meta`, `last_status`, `created_unix`, `updated_unix` FROM `webhook` WHERE (is_active=?) AND `repo_id`=? []interface {}{true, 90}
2019/01/28 00:07:33 [I] [SQL] SELECT `id`, `repo_id`, `hook_id`, `uuid`, `type`, `url`, `payload_content`, `content_type`, `event_type`, `is_ssl`, `is_delivered`, `delivered`, `is_succeed`, `request_content`, `response_content` FROM `hook_task` WHERE (repo_id=? AND is_delivered=?) []interface {}{90, false}
2019/01/28 00:07:33 [I] [SQL] SELECT `id`, `repo_id`, `index`, `poster_id`, `name`, `content`, `milestone_id`, `priority`, `is_closed`, `is_pull`, `num_comments`, `ref`, `deadline_unix`, `created_unix`, `updated_unix`, `closed_unix` FROM `issue` WHERE `id`=? LIMIT 1 []interface {}{2560}
2019/01/28 00:07:33 [I] [SQL] SELECT * FROM `label` LEFT JOIN issue_label ON issue_label.label_id = label.id WHERE (issue_label.issue_id = ?) ORDER BY `label`.`name` ASC []interface {}{2560}
2019/01/28 00:07:33 [I] [SQL] SELECT `id`, `lower_name`, `name`, `full_name`, `email`, `keep_email_private`, `passwd`, `must_change_password`, `login_type`, `login_source`, `login_name`, `type`, `location`, `website`, `rands`, `salt`, `language`, `created_unix`, `updated_unix`, `last_login_unix`, `last_repo_visibility`, `max_repo_creation`, `is_active`, `is_admin`, `allow_git_hook`, `allow_import_local`, `allow_create_organization`, `prohibit_login`, `avatar`, `avatar_email`, `use_custom_avatar`, `num_followers`, `num_following`, `num_stars`, `num_repos`, `description`, `num_teams`, `num_members`, `diff_view_style` FROM `user` WHERE `id`=? LIMIT 1 []interface {}{20}
2019/01/28 00:07:33 [I] [SQL] BEGIN TRANSACTION
2019/01/28 00:07:33 [I] [SQL] SELECT * FROM `issue_watch` INNER JOIN `user` ON `user`.id = `issue_watch`.user_id WHERE (`issue_watch`.issue_id = ?) AND (`user`.is_active = ?) AND (`user`.prohibit_login = ?) []interface {}{2560, true, false}
2019/01/28 00:07:33 [I] [SQL] SELECT `id`, `owner_id`, `lower_name`, `name`, `description`, `website`, `default_branch`, `num_watches`, `num_stars`, `num_forks`, `num_issues`, `num_closed_issues`, `num_pulls`, `num_closed_pulls`, `num_milestones`, `num_closed_milestones`, `is_private`, `is_bare`, `is_mirror`, `is_fork`, `fork_id`, `size`, `is_fsck_enabled`, `topics`, `created_unix`, `updated_unix` FROM `repository` WHERE `id`=? LIMIT 1 []interface {}{90}
2019/01/28 00:07:33 [I] [SQL] SELECT * FROM `watch` INNER JOIN `user` ON `user`.id = `watch`.user_id WHERE (`watch`.repo_id=?) AND (`user`.is_active=?) AND (`user`.prohibit_login=?) []interface {}{90, true, false}
2019/01/28 00:07:33 [I] [SQL] SELECT `id`, `user_id`, `repo_id`, `status`, `source`, `issue_id`, `commit_id`, `updated_by`, `created_unix`, `updated_unix` FROM `notification` WHERE (issue_id = ?) []interface {}{2560}
2019/01/28 00:07:33 [I] [SQL] SELECT `id`, `lower_name`, `name`, `full_name`, `email`, `keep_email_private`, `passwd`, `must_change_password`, `login_type`, `login_source`, `login_name`, `type`, `location`, `website`, `rands`, `salt`, `language`, `created_unix`, `updated_unix`, `last_login_unix`, `last_repo_visibility`, `max_repo_creation`, `is_active`, `is_admin`, `allow_git_hook`, `allow_import_local`, `allow_create_organization`, `prohibit_login`, `avatar`, `avatar_email`, `use_custom_avatar`, `num_followers`, `num_following`, `num_stars`, `num_repos`, `description`, `num_teams`, `num_members`, `diff_view_style` FROM `user` WHERE `id`=? LIMIT 1 []interface {}{11}
2019/01/28 00:07:33 [I] [SQL] SELECT `name` FROM `user` WHERE `id`=? LIMIT 1 []interface {}{11}
2019/01/28 00:07:33 [I] [SQL] SELECT `id`, `repo_id`, `type`, `config`, `created_unix` FROM `repo_unit` WHERE (repo_id = ?) []interface {}{90}
2019/01/28 00:07:33 [I] [SQL] SELECT * FROM `user` INNER JOIN issue_assignees ON assignee_id = `user`.id WHERE (issue_assignees.issue_id = ?) []interface {}{2560}
2019/01/28 00:07:33 [I] [SQL] INSERT INTO `notification` (`user_id`,`repo_id`,`status`,`source`,`issue_id`,`commit_id`,`updated_by`,`created_unix`,`updated_unix`) VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?) []interface {}{11, 90, 1, 1, 2560, "", 20, 1548630453, 1548630453}
2019/01/28 00:07:33 [I] [SQL] COMMIT
2019/01/28 00:07:33 [I] [SQL] SELECT `id`, `uid`, `name`, `sha1`, `created_unix`, `updated_unix` FROM `access_token` WHERE `sha1`=? LIMIT 1 []interface {}{"MYTOKEN"}
2019/01/28 00:07:33 [I] [SQL] UPDATE `access_token` SET `uid` = ?, `name` = ?, `sha1` = ?, `updated_unix` = ? WHERE `id`=? []interface {}{11, "remine-to-gitea", "MYTOKEN", 1548630453, 2}
2019/01/28 00:07:33 [I] [SQL] SELECT `id`, `lower_name`, `name`, `full_name`, `email`, `keep_email_private`, `passwd`, `must_change_password`, `login_type`, `login_source`, `login_name`, `type`, `location`, `website`, `rands`, `salt`, `language`, `created_unix`, `updated_unix`, `last_login_unix`, `last_repo_visibility`, `max_repo_creation`, `is_active`, `is_admin`, `allow_git_hook`, `allow_import_local`, `allow_create_organization`, `prohibit_login`, `avatar`, `avatar_email`, `use_custom_avatar`, `num_followers`, `num_following`, `num_stars`, `num_repos`, `description`, `num_teams`, `num_members`, `diff_view_style` FROM `user` WHERE `id`=? LIMIT 1 []interface {}{11}
2019/01/28 00:07:33 [I] [SQL] SELECT `id`, `lower_name`, `name`, `full_name`, `email`, `keep_email_private`, `passwd`, `must_change_password`, `login_type`, `login_source`, `login_name`, `type`, `location`, `website`, `rands`, `salt`, `language`, `created_unix`, `updated_unix`, `last_login_unix`, `last_repo_visibility`, `max_repo_creation`, `is_active`, `is_admin`, `allow_git_hook`, `allow_import_local`, `allow_create_organization`, `prohibit_login`, `avatar`, `avatar_email`, `use_custom_avatar`, `num_followers`, `num_following`, `num_stars`, `num_repos`, `description`, `num_teams`, `num_members`, `diff_view_style` FROM `user` WHERE `lower_name`=? LIMIT 1 []interface {}{"redmine_importer"}
2019/01/28 00:07:33 [I] [SQL] SELECT `id`, `lower_name`, `name`, `full_name`, `email`, `keep_email_private`, `passwd`, `must_change_password`, `login_type`, `login_source`, `login_name`, `type`, `location`, `website`, `rands`, `salt`, `language`, `created_unix`, `updated_unix`, `last_login_unix`, `last_repo_visibility`, `max_repo_creation`, `is_active`, `is_admin`, `allow_git_hook`, `allow_import_local`, `allow_create_organization`, `prohibit_login`, `avatar`, `avatar_email`, `use_custom_avatar`, `num_followers`, `num_following`, `num_stars`, `num_repos`, `description`, `num_teams`, `num_members`, `diff_view_style` FROM `user` WHERE `lower_name`=? LIMIT 1 []interface {}{"jlecour"}
2019/01/28 00:07:33 [I] [SQL] SELECT `id`, `owner_id`, `lower_name`, `name`, `description`, `website`, `default_branch`, `num_watches`, `num_stars`, `num_forks`, `num_issues`, `num_closed_issues`, `num_pulls`, `num_closed_pulls`, `num_milestones`, `num_closed_milestones`, `is_private`, `is_bare`, `is_mirror`, `is_fork`, `fork_id`, `size`, `is_fsck_enabled`, `topics`, `created_unix`, `updated_unix` FROM `repository` WHERE `owner_id`=? AND `lower_name`=? LIMIT 1 []interface {}{11, "tests-redmine-to-gitea"}
2019/01/28 00:07:33 [I] [SQL] SELECT `id`, `repo_id`, `type`, `config`, `created_unix` FROM `repo_unit` WHERE (repo_id = ?) []interface {}{90}
2019/01/28 00:07:33 [I] [SQL] SELECT `id`, `user_id`, `repo_id`, `mode` FROM `access` WHERE `user_id`=? AND `repo_id`=? LIMIT 1 []interface {}{20, 90}
2019/01/28 00:07:33 [I] [SQL] SELECT `id`, `repo_id`, `index`, `poster_id`, `name`, `content`, `milestone_id`, `priority`, `is_closed`, `is_pull`, `num_comments`, `ref`, `deadline_unix`, `created_unix`, `updated_unix`, `closed_unix` FROM `issue` WHERE `repo_id`=? AND `index`=? LIMIT 1 []interface {}{90, 6}
2019/01/28 00:07:33 [I] [SQL] BEGIN TRANSACTION
2019/01/28 00:07:33 [I] [SQL] INSERT INTO `comment` (`type`,`poster_id`,`issue_id`,`label_id`,`old_milestone_id`,`milestone_id`,`assignee_id`,`removed_assignee`,`old_title`,`new_title`,`dependent_issue_id`,`commit_id`,`line`,`tree_path`,`content`,`patch`,`created_unix`,`updated_unix`,`commit_sha`,`review_id`,`invalidated`) VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?) []interface {}{0, 20, 2560, 0, 0, 0, 0, false, "", "", 0, 0, 0, "", "MY COMMENT", "", 1548630453, 1548630453, "", 0, false}
2019/01/28 00:07:33 [I] [SQL] UPDATE `issue` SET num_comments=num_comments+1 WHERE id=? []interface {}{2560}
2019/01/28 00:07:33 [I] [SQL] UPDATE `issue` SET `updated_unix` = ? WHERE `id`=? []interface {}{1548630453, 2560}
2019/01/28 00:07:33 [I] [SQL] SELECT * FROM `watch` INNER JOIN `user` ON `user`.id = `watch`.user_id WHERE (`watch`.repo_id=?) AND (`user`.is_active=?) AND (`user`.prohibit_login=?) []interface {}{90, true, false}
2019/01/28 00:07:33 [I] [SQL] INSERT INTO `action` (`user_id`,`op_type`,`act_user_id`,`repo_id`,`comment_id`,`is_deleted`,`ref_name`,`is_private`,`content`,`created_unix`) VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, ?) []interface {}{20, 10, 20, 90, 3592, false, "", true, "6|MY COMMENT", 1548630453}
2019/01/28 00:07:33 [I] [SQL] SELECT `id`, `lower_name`, `name`, `full_name`, `email`, `keep_email_private`, `passwd`, `must_change_password`, `login_type`, `login_source`, `login_name`, `type`, `location`, `website`, `rands`, `salt`, `language`, `created_unix`, `updated_unix`, `last_login_unix`, `last_repo_visibility`, `max_repo_creation`, `is_active`, `is_admin`, `allow_git_hook`, `allow_import_local`, `allow_create_organization`, `prohibit_login`, `avatar`, `avatar_email`, `use_custom_avatar`, `num_followers`, `num_following`, `num_stars`, `num_repos`, `description`, `num_teams`, `num_members`, `diff_view_style` FROM `user` WHERE `id`=? LIMIT 1 []interface {}{11}
2019/01/28 00:07:33 [I] [SQL] SELECT `id`, `repo_id`, `type`, `config`, `created_unix` FROM `repo_unit` WHERE (repo_id = ?) []interface {}{90}
2019/01/28 00:07:33 [I] [SQL] INSERT INTO `action` (`user_id`,`op_type`,`act_user_id`,`repo_id`,`comment_id`,`is_deleted`,`ref_name`,`is_private`,`content`,`created_unix`) VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, ?) []interface {}{11, 10, 20, 90, 3592, false, "", true, "6|MY COMMENT", 1548630453}
2019/01/28 00:07:33 [I] [SQL] SELECT * FROM `watch` INNER JOIN `user` ON `user`.id = `watch`.user_id WHERE (`watch`.repo_id=?) AND (`user`.is_active=?) AND (`user`.prohibit_login=?) []interface {}{90, true, false}
2019/01/28 00:07:33 [I] [SQL] SELECT DISTINCT `poster_id` FROM `comment` INNER JOIN `user` ON `user`.id = `comment`.poster_id WHERE (`comment`.issue_id = ?) AND (`comment`.type = ?) AND (`user`.is_active = ?) AND (`user`.prohibit_login = ?) []interface {}{2560, 0, true, false}
2019/01/28 00:07:33 [I] [SQL] SELECT `id`, `lower_name`, `name`, `full_name`, `email`, `keep_email_private`, `passwd`, `must_change_password`, `login_type`, `login_source`, `login_name`, `type`, `location`, `website`, `rands`, `salt`, `language`, `created_unix`, `updated_unix`, `last_login_unix`, `last_repo_visibility`, `max_repo_creation`, `is_active`, `is_admin`, `allow_git_hook`, `allow_import_local`, `allow_create_organization`, `prohibit_login`, `avatar`, `avatar_email`, `use_custom_avatar`, `num_followers`, `num_following`, `num_stars`, `num_repos`, `description`, `num_teams`, `num_members`, `diff_view_style` FROM `user` WHERE `id`=? LIMIT 1 []interface {}{20}
2019/01/28 00:07:33 [I] [SQL] SELECT * FROM `user` INNER JOIN issue_assignees ON assignee_id = `user`.id WHERE (issue_assignees.issue_id = ?) []interface {}{2560}
2019/01/28 00:07:33 [I] [SQL] SELECT `id`, `lower_name`, `name`, `full_name`, `email`, `keep_email_private`, `passwd`, `must_change_password`, `login_type`, `login_source`, `login_name`, `type`, `location`, `website`, `rands`, `salt`, `language`, `created_unix`, `updated_unix`, `last_login_unix`, `last_repo_visibility`, `max_repo_creation`, `is_active`, `is_admin`, `allow_git_hook`, `allow_import_local`, `allow_create_organization`, `prohibit_login`, `avatar`, `avatar_email`, `use_custom_avatar`, `num_followers`, `num_following`, `num_stars`, `num_repos`, `description`, `num_teams`, `num_members`, `diff_view_style` FROM `user` WHERE `id`=? LIMIT 1 []interface {}{11}
2019/01/28 00:07:33 [I] [SQL] ROLL BACK

[zeripath]

Hmm I wonder I don't think this is necessary: https://github.com/go-gitea/gitea/blob/master/models/issue_comment.go#L533

Does commenting it out make your problem go away?

That's necessary

[zeripath]

No. It shouldn't be that.

It could be this

gitea/models/repo_watch.go

Line 90 in 6311e4c

act.loadRepo()

That loads the repository outside of the transaction.

[jlecour]

Are you asking me to download the source code, comment the If block, recompile and try again?

If so, I need instructions because I’ve never compiled a Go project yet.

[zeripath]

You probably have only just started noticing it because I might have missed it in my deadlock fixing set which probably moved the notifyWatchers bit into the transaction.

[zeripath]

If you want it fixed today, yes. I'm afraid it's almost midnight here and I'm going to bed. My day job is very different from coding so I won't be able to hack until the evening.

The act.loadRepo() function is defined here:

gitea/models/action.go

Line 117 in 7d65ddf

func (a *Action) loadRepo() {

Go isn't that hard - it's yet another imperative language with a garbage collector. If it helps, up until my first patch in August I had never written a line of it. There's some instructions on Gitea.io. See if you can recruit some help on discord too.

Otherwise I can fix it tomorrow. Hopefully I've identified the right bug so it should be quick to sort.

PS it's no longer a comment out the block btw, the act.loadrepo code needs to be pulled within the transaction by passing the session e in and using that. If no session is available then you can pass in x and it will work.

[zeripath]

https://docs.gitea.io/en-us/install-from-source/ is the basic build instructions.

[jlecour]

@zeripath Hey, I'm sorry if I was a bit blunt.

I did not expect anything, and certainly not to have it fixed and delivered for free the same day.
I'm very thankful for your quick response to my issue. You took from your limited personal time to help me and that's very appreciated.

I'm not sure that I'll be able to setup a test instance of gitea to try the proposed fix without impacting my production instance. I can stay on 1.6.4 until this is properly investigated and fixed. I will report if I can do more on my side.

Thanks again.

[zeripath]

OK, so looking at this again. The act.loadRepo() should be fine - we create it with that set.

What is interesting though is that your xorm.log appears to effectively call notifyWatchers twice.

[zeripath]

AHA! It's this https://github.com/go-gitea/gitea/blob/release/v1.7/models/issue_comment.go#L635 - which is not in master.

[zeripath]

So #5110 probably silently fixed this issue.

@lunny, do you think it would be reasonable to backport #5110 to v1.7.0 to fix this issue.

@jlecour could you try on latest to see if you can replicate your issue?

[jlecour]

@zeripath Good news !

Which commit/tag/branch should I try to compile and run ?

[adelowo]

@jlecour Master branch

[jlecour]

OK, compiling Gitea was really easy !

I've verified that master doesn't have the bug I've found anymore.

Thanks you @zeripath you've been amazing !

If by any chance you are at FOSDEM in Brussels next weekend, I'd be happy to thank your personally.

[zeripath]

No worries. Afraid I won't be at fosdem unfortunately, never been.

I'll have another think about this bug - I suspect that others were likely to be hit by it - it's likely to be in the mail creation scripts but I can't seem to replicate it. Tell me what dB are you using? I guess you've got email switched on too?

[jlecour]

I've been using MySQL and yes I have mail notifications enabled.

[zeripath]

This is probably actually the bug in #5891 - well when it's backported.