frequent error 500 when writing comment on code line in PR

[sbourdeauducq]

• Gitea version (or commit ref): 1.13.1
• Git version: 2.29.2
• Operating system: NixOS 20.09.2483.c5c6009fb43. Gitea run via systemd.
• Database (use [x]):
  • PostgreSQL
  • MySQL
  • MSSQL
  • SQLite
• Can you reproduce the bug at https://try.gitea.io:
  • Yes (provide example URL)
  • No, worked fine when I tried: https://try.gitea.io/jpraet-org/otherteam-repo/pulls/1/files#issuecomment-75119
• Log gist:
  Couldn't find anything pertinent in the log so far.

Description

Writing a comment on a source code line in a pull request often causes a weird "Error 500" screen (with multiple top bars, exactly as the screenshot shows). The comment is still posted.

Screenshots

[noerw]

Could you provide an excerpt from your gitea log file, when this happened?

[noerw]

@jpraet could this be a regression from #14002?

[jpraet]

@jpraet could this be a regression from #14002?

I doubt that, as that PR just restored the previous behavior. But difficult to say without the logs.

[zeripath]

Every 500 is accompanied by a log.Error - without providing logs we will not be able to debug this at all.

Not providing logs is frankly rude and is tantamount to spamming maintainers.

I've written multiple times about how to adjust logging configuration to help improve this, and it's in the header, but for completeness here is the link: https://docs.gitea.io/en-us/logging-configuration/#debugging-problems

You must give us logs. It is not fair to expect us to guess the cause of your problems.

[sbourdeauducq]

You must give us logs. It is not fair to expect us to guess the cause of your problems.

I was not expecting someone to guess; but since logs via journalctl turned out to be somewhat tricky (probably not a gitea issue but on NixOS it doesn't use the systemd logging levels for instance) and the symptom (screenshot) is quite peculiar, I posted it just in case it was a known problem.

Anyway, sorry for posting a low quality bug report; I got logs now and this seems to be similar to #13581 (but happening more often) and not related to the "weirdness" of the screenshot:

Jan 07 13:07:05 nixbld gitea[2612]: 2021/01/07 13:07:05 ...m.io/xorm/core/db.go:286:afterProcess() [I] [SQL] SELECT `id`, `user_id`, `repo_id`, `status`, `source`, `issue_id`, `commit_id`, `comment_id`, `updated_by`, `created_unix`, `upd>
Jan 07 13:07:05 nixbld gitea[2612]: 2021/01/07 13:07:05 ...m.io/xorm/core/db.go:286:afterProcess() [I] [SQL] SELECT count(*) FROM `notification` WHERE (user_id = ?) AND (status = ?) [1 1] - 68.797µs
Jan 07 13:07:05 nixbld gitea[2612]: 2021/01/07 13:07:05 ...user/notification.go:38:func1() [E] GetNotificationCount: database table is locked: notification
Jan 07 13:07:05 nixbld gitea[2612]: 2021/01/07 13:07:05 ...s/context/context.go:139:HTML() [D] Template: status/500
Jan 07 13:07:05 nixbld gitea[2612]: 2021/01/07 13:07:05 ...m.io/xorm/core/db.go:286:afterProcess() [I] [SQL] UPDATE `notification` SET `updated_unix` = ? WHERE `id`=? [1609996025 2091] - 19.885µs
Jan 07 13:07:05 nixbld gitea[2612]: 2021/01/07 13:07:05 ...m.io/xorm/core/db.go:286:afterProcess() [I] [SQL] SELECT `id`, `lower_name`, `name`, `full_name`, `email`, `keep_email_private`, `email_notifications_preference`, `passwd`, `pass>
Jan 07 13:07:05 nixbld gitea[2612]: 2021/01/07 13:07:05 ...m.io/xorm/core/db.go:286:afterProcess() [I] [SQL] SELECT count(*) FROM `notification` WHERE (user_id = ?) AND (status = ?) [1 1] - 20.3µs
Jan 07 13:07:05 nixbld gitea[2612]: 2021/01/07 13:07:05 ...user/notification.go:38:func1() [E] GetNotificationCount: database table is locked: notification
Jan 07 13:07:05 nixbld gitea[2612]: 2021/01/07 13:07:05 ...s/context/context.go:139:HTML() [D] Template: status/500

...

Jan 07 13:07:05 nixbld gitea[2612]: 2021/01/07 13:07:05 ...m.io/xorm/core/db.go:286:afterProcess() [I] [SQL] SELECT count(*) FROM `notification` WHERE (user_id = ?) AND (status = ?) [1 1] - 76.472µs
Jan 07 13:07:05 nixbld gitea[2612]: 2021/01/07 13:07:05 ...user/notification.go:38:func1() [E] GetNotificationCount: database table is locked: notification
Jan 07 13:07:05 nixbld gitea[2612]: 2021/01/07 13:07:05 ...s/context/context.go:139:HTML() [D] Template: status/500
...

Jan 07 13:07:05 nixbld gitea[2612]: [Macaron] 2021-01-07 13:07:05: Completed GET /M-Labs/thermostat/pulls/43/files 500 Internal Server Error in 46.118127ms

So, migrate to PostgreSQL?

[zeripath]

Oh crap your SQLITE db is locking somehow.

But it is weird - because if we have a genuine deadlock we should be seeing your process just get locked up completely - edit: it probably is.

Do you have a cluster of multiple gitea processes running at the same time? If so you have to use a real db not sqlite.

Are you building gitea yourself? What tags are you building gitea with?

[zeripath]

If it's a real deadlock we'll need more logs - we would need to get all of the logs from just before it was working to just as it stops. That is include at least a few SQL queries that definitely succeed and don't trim anything except confidential data out.

Deadlocks are a nightmare we literally need to know exactly what was the causative request for the failure.

The notification queries you've shown us will not be the cause - the issue will be earlier.

[sbourdeauducq]

But it is weird - because if we have a genuine deadlock we should be seeing your process just get locked up completely - edit: it probably is.

Wouldn't there be an error entry in the log about it? I don't see any [E] messages that would indicate this.

Do you have a cluster of multiple gitea processes running at the same time?

No, only one.

Are you building gitea yourself? What tags are you building gitea with?

No, I am using the Nix package. It is built with the pam sqlite tags.

https://github.com/NixOS/nixpkgs/blob/release-20.09/pkgs/applications/version-management/gitea/default.nix
https://github.com/NixOS/nixpkgs/blob/release-20.09/nixos/modules/services/misc/gitea.nix

If it's a real deadlock we'll need more logs - we would need to get all of the logs from just before it was working to just as it stops

There doesn't seem to be any stopping. The same process has been running for days, and comments still get posted and the rest of the site still operates, the only symptom seems to be the "error 500" screen.

[zeripath]

Ah. That's the problem!

You need the sqlite_unlock_notify tag in addition to pam and sqlite

[sbourdeauducq]

Thanks, will try :)

[sbourdeauducq]

Seems to do the trick :) Thanks again.