500 Internal server error on `/admin/emails`

[adyanth]

• Gitea version (or commit ref): 1.15.0+dev-517-g096634935 built with GNU Make 4.3, go1.16.5 : bindata, timetzdata, sqlite, sqlite_unlock_notify
• Git version: 2.30.2
• Operating system: Ubuntu 20.04, docker latest tag
• Database (use [x]):
  • PostgreSQL
  • MySQL
  • MSSQL
  • SQLite
• Can you reproduce the bug at https://try.gitea.io:
  • Yes (provide example URL)
  • No
• Log gist: With database debug logging enabled:

gitea_1   | 2021/06/30 13:25:05 Started GET /admin/emails for 10.10.10.10:0
gitea_1   | 2021/06/30 13:25:05 models/user.go:1370:getUserByID() [I] [SQL] SELECT "id", "lower_name", "name", "full_name", "email", "keep_email_private", "email_notifications_preference", "passwd", "passwd_hash_algo", "must_change_password", "login_type", "login_source", "login_name", "type", "location", "website", "rands", "salt", "language", "description", "created_unix", "updated_unix", "last_login_unix", "last_repo_visibility", "max_repo_creation", "is_active", "is_admin", "is_restricted", "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", "num_teams", "num_members", "visibility", "repo_admin_change_team_access", "diff_view_style", "theme", "keep_activity_private" FROM "user" WHERE "id"=$1 LIMIT 1 [2] - 3.396415ms
gitea_1   | 2021/06/30 13:25:05 ...s/issue_stopwatch.go:67:HasUserStopwatch() [I] [SQL] SELECT "id", "issue_id", "user_id", "created_unix" FROM "stopwatch" WHERE (user_id = $1) LIMIT 1 [2] - 1.344389ms
gitea_1   | 2021/06/30 13:25:05 .../web/admin/emails.go:79:Emails() [I] [SQL] SELECT count(*) FROM "email_address" INNER JOIN "user" ON "user".ID = email_address.uid WHERE user."type"=$1 [0] - 1.206426ms
gitea_1   | 2021/06/30 13:25:05 .../web/admin/emails.go:81:Emails() [E] SearchEmails: Count: pq: syntax error at or near "."
gitea_1   | 2021/06/30 13:25:05 ...dels/notification.go:716:GetNotificationCount() [I] [SQL] SELECT count(*) FROM "notification" WHERE (user_id = $1) AND (status = $2) [2 1] - 822.306µs
gitea_1   | 2021/06/30 13:25:05 models/avatar.go:135:SizedAvatarLink() [I] [SQL] BEGIN TRANSACTION [] - 1.221931ms
gitea_1   | 2021/06/30 13:25:05 models/avatar.go:99:func1() [I] [SQL] SELECT "hash", "email" FROM "email_hash" WHERE (email = $1 AND hash = $2) LIMIT 1 [adyanthh@gmail.com 56c1a30ce27236aaa99c65c60f73cde0] - 4.274246ms
gitea_1   | 2021/06/30 13:25:05 models/avatar.go:87:HashedAvatarLink() [I] [SQL] ROLLBACK [] - 275.952µs
gitea_1   | 2021/06/30 13:25:05 Completed GET /admin/emails 500 Internal Server Error in 60.734787ms

Description

I do not have an idea from when this started, since I rarely visit that URL. Today, when I did, I can see a 500 internal server error.

From the debug logging for SQL, I can see that the 1st line where user."type" seems to be wrong? and should have been "user"."type"?
This is the closest I can see in code:

gitea/models/user_mail.go

Line 319 in 1bfb0a2

var cond builder.Cond = builder.Eq{"user.`type`": UserTypeIndividual}

Screenshots

Sample of what I see, a generic 500 page.

[adyanth]

As a sanity check, I ran that SQL command (corrected) and it works:

gitea=# SELECT count(*) FROM "email_address" INNER JOIN "user" ON "user".ID = email_address.uid WHERE "user"."type"=0;
 count 
-------
     5
(1 row)

But the incorrect one printed in the logs does not:

gitea=# SELECT count(*) FROM "email_address" INNER JOIN "user" ON "user".ID = email_address.uid WHERE user."type"=0;
ERROR:  syntax error at or near "."
LINE 1: ..."user" ON "user".ID = email_address.uid WHERE user."type"=0;
                                                             ^

[6543]

Ah user need to be escaped

[6543]

Wana send a pull to fix Line 319?

user -> `user`

[adyanth]

Sure!

[6543]

@adyanth did create a test instance with postgress and i do not get a 500. would be good if you can test this change on your installation first. If it fixes it we can put it in :)

[zeripath]

@adyanth did create a test instance with postgress and i do not get a 500. would be good if you can test this change on your installation first. If it fixes it we can put it in :)

@6543 I suspect this could be schema specific.

[adyanth]

@6543 will create a test instance and check too.

What else can I enable to see why atleast mine is running into it?

[Alexsaphir]

Same issue on my side. I've set the sql query to be outputted to log and try the query directly on the database. I needed to escape user so that the query succeed.

I think it's this commit who introduce the issue : b9d611e#diff-88af2d242341edbdb69e8e6c0b47f3ee9329ce057bdc239f1fe484d93f46bda4L348

The function was rewritten.

[adyanth]

@6543 a fresh compose setup with a new DB resulted in a 500 after the 1st login and going to /admin/emails. Are you using the gitea:latest from docker?

Fresh repro:

gitea_1  | 2021/06/30 15:44:37 Started GET /admin/emails for 10.10.10.10:0
gitea_1  | 2021/06/30 15:44:37 models/user.go:1370:getUserByID() [I] [SQL] SELECT "id", "lower_name", "name", "full_name", "email", "keep_email_private", "email_notifications_preference", "passwd", "passwd_hash_algo", "must_change_password", "login_type", "login_source", "login_name", "type", "location", "website", "rands", "salt", "language", "description", "created_unix", "updated_unix", "last_login_unix", "last_repo_visibility", "max_repo_creation", "is_active", "is_admin", "is_restricted", "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", "num_teams", "num_members", "visibility", "repo_admin_change_team_access", "diff_view_style", "theme", "keep_activity_private" FROM "user" WHERE "id"=$1 LIMIT 1 [1] - 721.426µs
gitea_1  | 2021/06/30 15:44:37 ...s/issue_stopwatch.go:67:HasUserStopwatch() [I] [SQL] SELECT "id", "issue_id", "user_id", "created_unix" FROM "stopwatch" WHERE (user_id = $1) LIMIT 1 [1] - 613.259µs
gitea_1  | 2021/06/30 15:44:37 .../web/admin/emails.go:79:Emails() [I] [SQL] SELECT count(*) FROM "email_address" INNER JOIN "user" ON "user".ID = email_address.uid WHERE user."type"=$1 [0] - 268.689µs
gitea_1  | 2021/06/30 15:44:37 .../web/admin/emails.go:81:Emails() [E] SearchEmails: Count: pq: syntax error at or near "."
gitea_1  | 2021/06/30 15:44:37 ...dels/notification.go:716:GetNotificationCount() [I] [SQL] SELECT count(*) FROM "notification" WHERE (user_id = $1) AND (status = $2) [1 1] - 2.18059ms
gitea_1  | 2021/06/30 15:44:37 models/avatar.go:135:SizedAvatarLink() [I] [SQL] BEGIN TRANSACTION [] - 213.794µs
gitea_1  | 2021/06/30 15:44:37 models/avatar.go:99:func1() [I] [SQL] SELECT "hash", "email" FROM "email_hash" WHERE (email = $1 AND hash = $2) LIMIT 1 [adyanthh@gmail.com 56c1a30ce27236aaa99c65c60f73cde0] - 2.48431ms
gitea_1  | 2021/06/30 15:44:37 models/avatar.go:87:HashedAvatarLink() [I] [SQL] ROLLBACK [] - 127.941µs
gitea_1  | 2021/06/30 15:44:37 Completed GET /admin/emails 500 Internal Server Error in 14.211549ms

Will try the fix locally and update

[adyanth]

Here is after the change:

gitea_1  | 2021/06/30 15:57:36 Started GET /admin/emails for 10.10.10.10:0
gitea_1  | 2021/06/30 15:57:36 models/user.go:1370:getUserByID() [I] [SQL] SELECT "id", "lower_name", "name", "full_name", "email", "keep_email_private", "email_notifications_preference", "passwd", "passwd_hash_algo", "must_change_password", "login_type", "login_source", "login_name", "type", "location", "website", "rands", "salt", "language", "description", "created_unix", "updated_unix", "last_login_unix", "last_repo_visibility", "max_repo_creation", "is_active", "is_admin", "is_restricted", "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", "num_teams", "num_members", "visibility", "repo_admin_change_team_access", "diff_view_style", "theme", "keep_activity_private" FROM "user" WHERE "id"=$1 LIMIT 1 [1] - 1.182398ms
gitea_1  | 2021/06/30 15:57:36 ...s/issue_stopwatch.go:67:HasUserStopwatch() [I] [SQL] SELECT "id", "issue_id", "user_id", "created_unix" FROM "stopwatch" WHERE (user_id = $1) LIMIT 1 [1] - 976µs
gitea_1  | 2021/06/30 15:57:36 .../web/admin/emails.go:79:Emails() [I] [SQL] SELECT count(*) FROM "email_address" INNER JOIN "user" ON "user".ID = email_address.uid WHERE "user"."type"=$1 [0] - 1.176922ms
gitea_1  | 2021/06/30 15:57:36 models/user_mail.go:363:SearchEmails() [I] [SQL] SELECT email_address.*, "user".name, "user".full_name FROM "email_address" INNER JOIN "user" ON "user".ID = email_address.uid WHERE "user"."type"=$1 ORDER BY email_address.lower_email ASC, email_address.is_primary DESC, email_address.id ASC LIMIT 50 [0] - 1.217405ms
gitea_1  | 2021/06/30 15:57:36 ...dels/notification.go:716:GetNotificationCount() [I] [SQL] SELECT count(*) FROM "notification" WHERE (user_id = $1) AND (status = $2) [1 1] - 726.65µs
gitea_1  | 2021/06/30 15:57:36 Completed GET /admin/emails 200 OK in 9.095327ms

Fixes it. Will submit the PR.

[adyanth]

Checking the release/1.14, I dont see this changed function. Will submit the PR to main itself.