Recurring freezes on BSD

[phryk]

Gitea Version

1.15.8

Git Version

2.34.1

Operating System

FreeBSD

How are you running Gitea?

Installed from custom package repository built py local poudriere.
Same problem occured with versions from official FreeBSD pkg repo.

Gitea is running within a jail and has an nginx running on the same jail in front of it as transparent proxy.

Database

PostgreSQL

Can you reproduce the bug on the Gitea demo site?

No

Log Gist

I'm not sure what that even means. Do you want a paste?

Description

I've been experiencing recurring freezes where only killall -9 gitea helps for about a year now.
This happens from within a couple hours to a couple weeks after the service is started.

I cannot reproduce this issue wilfully, but if I wait long enough it always shows up.

I have previously tried setting the log level to Debug, but haven't seen anything that
would tell me what the actual issue is. As this happened last summer, I don't have
those particular logs anymore, but have re-escalated my log level to Debug to be able
to attach a log when this bug next hits.

My latest attempt in figuring out what's going on was to enable gitea's metrics and have
them graphed in Grafana, but every single metric just shows a straight line up to the point
when gitea freezes, which is when data stops coming in.

In the meantime till I can attach a log: Any hunches on what might trigger this behavior?
Any other data I can supply to help triage this issue?

Best wishes,

phryk

Screenshots

No response

[lunny]

How did you compile Gitea yourself?
And could you catch the CPU, disk, memory usage when Gitea recurring freezes?

[phryk]

It's built by poudriere, which is a bulk package builder for FreeBSD that
uses FreeBSDs ports system to do the actual building.
You can find out more about it here: https://github.com/freebsd/poudriere/wiki

Actual disk usage I sadly don't have data for, but here are graphs for the other metrics as well as gitea and nginx (the green one is the gitea, or rather the transparent proxy for it)

[phryk]

I should probably also mention that no other services seem to be affected by this, so it looks like it's not hogging any system resources (or rather not any used by anything else) when it freezes – it just stops doing stuff.

[zeripath]

This sounds like a deadlock happening somewhere but postgres isn't usually a DB that suffers from them. (SQLite is usually the way we detect these.) Apart from DB deadlocks I'm not sure there's any other obvious thing that would cause a deadlock.

One problem in 1.15.7- was that git cat-file --batch won't fail fast if the git repo is broken but #17992 should prevent that - Is this definitely still happening on 1.15.8?

If so, a few thoughts:

• Do you have pprof enabled? (be careful with this as on 1.15 pprof will write files to PPROF_DATA_PATH every time people ssh to your server.) It may be helpful to poll the cpuprofile to see if we can catch the problem as it happens.
• Have you been able to rule out a network port exhaustion problem? Or open files problem?
• In the router logs have you seen any common requests that aren't complete?
• I worry that what we're seeing might be a bug in go on FreeBSD - but I just don't know how to prove that.

[phryk]

• Other services using PostgreSQL (with other databases) are unaffected, not sure if that means a DB deadlock can be excluded.
• Yes, definitely happening on 1.15.8
• Well, now I have pprof enabled, will report back when the bug hits again
• I'm not quite sure what you mean with router logs and how I would tell a request didn't complete
  • grep -i error gitea.log shows nothing of interest, the only legitimate errors are from gitea being unable
    to update a mirror whose source repo got DMCA'd…

[zeripath]

The logs appear somewhat confusing:

2022/01/04 23:11:01 ...s/context/context.go:185:HTML() [D] Template: repo/commits
2022/01/04 23:11:01 models/repo.go:504:ComposeMetas() [I] [SQL] SELECT team.lower_name FROM "team_repo" INNER JOIN "team" ON team.id = team_repo.team_id WHERE (team_repo.repo_id = $1) ORDER BY team.lower_name [1] - 268.794µs
2022/01/04 23:11:02 ...s/context/context.go:755:1() [D] Session ID: <crawler>
2022/01/04 23:11:02 ...s/context/context.go:756:1() [D] CSRF Token: <crawler>
2022/01/04 23:11:02 ...rm.io/xorm/engine.go:1139:Get() [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 "lower_name"=$1 LIMIT 1 [owner] - 463.192µs
2022/01/04 23:11:02 ...rm.io/xorm/engine.go:1139:Get() [I] [SQL] SELECT "id", "owner_id", "owner_name", "lower_name", "name", "description", "website", "original_service_type", "original_url", "default_branch", "num_watches", "num_stars", "num_forks", "num_issues", "num_closed_issues", "num_pulls", "num_closed_pulls", "num_milestones", "num_closed_milestones", "num_projects", "num_closed_projects", "is_private", "is_empty", "is_archived", "is_mirror", "status", "is_fork", "fork_id", "is_template", "template_id", "size", "is_fsck_enabled", "close_issues_via_commit_in_any_branch", "topics", "trust_model", "avatar", "created_unix", "updated_unix" FROM "repository" WHERE "owner_id"=$1 AND "lower_name"=$2 LIMIT 1 [2 repo] - 413.763µs
2022/01/04 23:11:02 models/repo_unit.go:210:getUnitsByRepoID() [I] [SQL] SELECT "id", "repo_id", "type", "config", "created_unix" FROM "repo_unit" WHERE (repo_id = $1) [1] - 183.034µs
2022/01/04 23:11:02 ...s/repo_pushmirror.go:97:GetPushMirrorsByRepoID() [I] [SQL] SELECT "id", "repo_id", "remote_name", "interval", "created_unix", "last_update", "last_error" FROM "push_mirror" WHERE (repo_id=$1) [1] - 162.754µs
2022/01/04 23:11:02 ...ules/context/repo.go:470:RepoAssignment() [I] [SQL] SELECT count(*) FROM "release" WHERE repo_id=$1 AND is_draft=$2 [1 false] - 194.067µs
2022/01/04 23:11:02 ...ules/context/repo.go:477:RepoAssignment() [I] [SQL] SELECT count(*) FROM "release" WHERE repo_id=$1 AND is_draft=$2 AND is_tag=$3 [1 false false] - 196.112µs
2022/01/04 23:11:02 ...dules/git/command.go:120:RunInDirTimeoutEnvFullPipelineFunc() [D] /var/db/gitea/gitea-repositories/owner/repo.git: /usr/local/bin/git -c credential.helper= -c protocol.version=2 rev-parse
2022/01/04 23:11:02 ...dules/git/command.go:120:RunInDirTimeoutEnvFullPipelineFunc() [D] /var/db/gitea/gitea-repositories/owner/repo.git: /usr/local/bin/git -c credential.helper= -c protocol.version=2 show-ref --tags
2022/01/04 23:11:02 ...dules/git/command.go:120:RunInDirTimeoutEnvFullPipelineFunc() [D] /var/db/gitea/gitea-repositories/owner/repo.git: /usr/local/bin/git -c credential.helper= -c protocol.version=2 cat-file --batch
2022/01/04 23:11:02 ...dules/git/command.go:120:RunInDirTimeoutEnvFullPipelineFunc() [D] /var/db/gitea/gitea-repositories/owner/repo.git: /usr/local/bin/git -c credential.helper= -c protocol.version=2 cat-file --batch-check

This implies that the problem has occurred somewhere in:

gitea/modules/context/repo.go

Lines 551 to 558 in b25a571

	tags, err := ctx.Repo.GitRepo.GetTags()
	if err != nil {
	ctx.ServerError("GetTags", err)
	return
	}
	ctx.Data["Tags"] = tags
	brs, _, err := ctx.Repo.GitRepo.GetBranches(0, 0)

But the problem is that there isn't really any place for a deadlock to occur in there.

My thoughts for progressing this further are to apply the following:

diff --git a/modules/git/command.go b/modules/git/command.go
index d83c42fdc..273bea632 100644
--- a/modules/git/command.go
+++ b/modules/git/command.go
@@ -120,6 +120,8 @@ func (c *Command) RunInDirTimeoutEnvFullPipelineFunc(env []string, timeout time.
 		log.Debug("%s: %v", dir, c)
 	}
 
+	defer log.Debug("Done %s: %v", dir, c)
+
 	ctx, cancel := context.WithTimeout(c.parentContext, timeout)
 	defer cancel()
 
diff --git a/modules/git/repo_branch_nogogit.go b/modules/git/repo_branch_nogogit.go
index 666ca81c1..b9a7a483f 100644
--- a/modules/git/repo_branch_nogogit.go
+++ b/modules/git/repo_branch_nogogit.go
@@ -68,6 +68,9 @@ func (repo *Repository) GetBranches(skip, limit int) ([]string, int, error) {
 
 // callShowRef return refs, if limit = 0 it will not limit
 func callShowRef(repoPath, prefix, arg string, skip, limit int) (branchNames []string, countAll int, err error) {
+	log.Debug("callShowRef %s %s %s %d %d", repoPath, prefix, arg, skip, limit)
+	defer log.Debug("done: callShowRef %s %s %s %d %d", repoPath, prefix, arg, skip, limit)
+
 	stdoutReader, stdoutWriter := io.Pipe()
 	defer func() {
 		_ = stdoutReader.Close()
diff --git a/modules/process/manager.go b/modules/process/manager.go
index e42e38a0f..7ea6a73e6 100644
--- a/modules/process/manager.go
+++ b/modules/process/manager.go
@@ -14,6 +14,8 @@ import (
 	"sort"
 	"sync"
 	"time"
+
+	"code.gitea.io/gitea/modules/log"
 )
 
 // TODO: This packages still uses a singleton for the Manager.
@@ -56,6 +58,7 @@ func GetManager() *Manager {
 
 // Add a process to the ProcessManager and returns its PID.
 func (pm *Manager) Add(description string, cancel context.CancelFunc) int64 {
+	log.Debug("Add(%s)", description)
 	pm.mutex.Lock()
 	pid := pm.counter + 1
 	pm.processes[pid] = &Process{
@@ -67,6 +70,7 @@ func (pm *Manager) Add(description string, cancel context.CancelFunc) int64 {
 	pm.counter = pid
 	pm.mutex.Unlock()
 
+	log.Debug("Done Add(%s) PID: %d", description, pid)
 	return pid
 }
 

That would help us to see if there is deadlock somewhere.

One final random thought is maybe the problem is in log/file.go - I guess it's worth another review.

[zeripath]

Have you seen any further freezes?

[phryk]

Yes and no. The bug seems to have triggered again, but this time the process actually managed to die.
Logs are on their way to you.

[zeripath]

OK so somewhat relievingly the problem is not in process.GetManager().Add() and that the error has occurred in the same place suggests that logging is not to blame.

The problem lies somewhere in:

gitea/modules/git/command.go

Lines 123 to 155 in 6cb5069

	ctx, cancel := context.WithTimeout(c.parentContext, timeout)
	defer cancel()
	cmd := exec.CommandContext(ctx, c.name, c.args...)
	if env == nil {
	cmd.Env = os.Environ()
	} else {
	cmd.Env = env
	}
	cmd.Env = append(
	cmd.Env,
	fmt.Sprintf("LC_ALL=%s", DefaultLocale),
	// avoid prompting for credentials interactively, supported since git v2.3
	"GIT_TERMINAL_PROMPT=0",
	)
	// TODO: verify if this is still needed in golang 1.15
	if goVersionLessThan115 {
	cmd.Env = append(cmd.Env, "GODEBUG=asyncpreemptoff=1")
	}
	cmd.Dir = dir
	cmd.Stdout = stdout
	cmd.Stderr = stderr
	cmd.Stdin = stdin
	if err := cmd.Start(); err != nil {
	return err
	}
	desc := c.desc
	if desc == "" {
	desc = fmt.Sprintf("%s %s %s [repo_path: %s]", GitExecutable, c.name, strings.Join(c.args, " "), dir)
	}

The only places left therefore are:

1. line 123: ctx, cancel := context.WithTimeout(c.parentContext, timeout) is this deadlocking somehow?
2. line 126: cmd := exec.CommandContext(ctx, c.name, c.args...) this requires stating the filesystem. Is the filesystem locking for some reason?
3. line 148: if err := cmd.Start(); err != nil { this involves starting the process itself so maybe there is some issue with bsd process creation here.

None of these are looking greatly soluble, I guess adding some logging to this section of code would be the only thing to do to move things closer to working out what the possible reason is.

---

diff --git a/modules/git/command.go b/modules/git/command.go
index d83c42fdc..71c398aae 100644
--- a/modules/git/command.go
+++ b/modules/git/command.go
@@ -120,9 +120,13 @@ func (c *Command) RunInDirTimeoutEnvFullPipelineFunc(env []string, timeout time.
 		log.Debug("%s: %v", dir, c)
 	}
 
+	defer log.Debug("Done %s: %v", dir, c)
+
 	ctx, cancel := context.WithTimeout(c.parentContext, timeout)
 	defer cancel()
 
+	log.Debug("%s: %v created context", dir, c)
+
 	cmd := exec.CommandContext(ctx, c.name, c.args...)
 	if env == nil {
 		cmd.Env = os.Environ()
@@ -130,6 +134,8 @@ func (c *Command) RunInDirTimeoutEnvFullPipelineFunc(env []string, timeout time.
 		cmd.Env = env
 	}
 
+	log.Debug("%s: %v created CommandContext", dir, c)
+
 	cmd.Env = append(
 		cmd.Env,
 		fmt.Sprintf("LC_ALL=%s", DefaultLocale),
@@ -149,6 +155,8 @@ func (c *Command) RunInDirTimeoutEnvFullPipelineFunc(env []string, timeout time.
 		return err
 	}
 
+	log.Debug("%s: %v started", dir, c)
+
 	desc := c.desc
 	if desc == "" {
 		desc = fmt.Sprintf("%s %s %s [repo_path: %s]", GitExecutable, c.name, strings.Join(c.args, " "), dir)
diff --git a/modules/git/repo_branch_nogogit.go b/modules/git/repo_branch_nogogit.go
index 666ca81c1..b9a7a483f 100644
--- a/modules/git/repo_branch_nogogit.go
+++ b/modules/git/repo_branch_nogogit.go
@@ -68,6 +68,9 @@ func (repo *Repository) GetBranches(skip, limit int) ([]string, int, error) {
 
 // callShowRef return refs, if limit = 0 it will not limit
 func callShowRef(repoPath, prefix, arg string, skip, limit int) (branchNames []string, countAll int, err error) {
+	log.Debug("callShowRef %s %s %s %d %d", repoPath, prefix, arg, skip, limit)
+	defer log.Debug("done: callShowRef %s %s %s %d %d", repoPath, prefix, arg, skip, limit)
+
 	stdoutReader, stdoutWriter := io.Pipe()
 	defer func() {
 		_ = stdoutReader.Close()
diff --git a/modules/process/manager.go b/modules/process/manager.go
index e42e38a0f..7ea6a73e6 100644
--- a/modules/process/manager.go
+++ b/modules/process/manager.go
@@ -14,6 +14,8 @@ import (
 	"sort"
 	"sync"
 	"time"
+
+	"code.gitea.io/gitea/modules/log"
 )
 
 // TODO: This packages still uses a singleton for the Manager.
@@ -56,6 +58,7 @@ func GetManager() *Manager {
 
 // Add a process to the ProcessManager and returns its PID.
 func (pm *Manager) Add(description string, cancel context.CancelFunc) int64 {
+	log.Debug("Add(%s)", description)
 	pm.mutex.Lock()
 	pid := pm.counter + 1
 	pm.processes[pid] = &Process{
@@ -67,6 +70,7 @@ func (pm *Manager) Add(description string, cancel context.CancelFunc) int64 {
 	pm.counter = pid
 	pm.mutex.Unlock()
 
+	log.Debug("Done Add(%s) PID: %d", description, pid)
 	return pid
 }
 

(remember github likes to pretend the final empty line doesn't exist so if you copy this add a terminal empty line.)

[phryk]

Patched, deployed and will get back next time the bug strikes. Thanks for the assistance. :)

[thearchivalone]

@phryk thanks for posting this bug report. I'm having the same issue running Gitea in Bastille running postgres in the same container. I'm currently updating to the latest release but did notice that the hang happens the same way as you and have to fully restart the server when I need to update a setting or two (still getting Gitea moved over and configured properly from a Linux server).

Definitely seeing this issue with 1.15.10 on my end.

The easiest way to get it to trigger for me was to just spam service gitea restart until it freezes at Waiting for PIDS message. Sending this to the port maintainer.

[zeripath]

@bedwardly-down as I said above this isn't looking like a Gitea bug per se. The three points of possible deadlock are all deep in go std library code and likely at system calls.

My greatest suspicion is unfortunately falling at the context.WithTimeout call. If it's there then that's a serious problem and working around it will not be easy (although we could simply drop the WithTimeout assuming WithCancel is unaffected.)

[thearchivalone]

@zeripath thanks for responding. I'm waiting on the FreeBSD port maintainer to get back to me on it but go apps having this kind of issue is not uncommon on FreeBSD, according to other maintainers I've been interacting with in the IRC and official Discord channels. I ran a test yesterday that kind of goes along with your assumptions too.

I'm primarily involved with the Nodejs ecosystem right now, so I use the PM2 process manager and Nodemon pretty regularly. Running Gitea through PM2 and having that strapped to FreeBSD's init system showed that the port was attempting to start and stop at the exact same time in various places causing it to deadlock. I had a similar occurrence with Caddy and a few other go apps on my old Gentoo server (it uses a modified version of FreeBSD's init system with most of the core functionality being exactly the same between the two). Running Gitea and Caddy outside of init but instead directly seemed to work fine in several of my tests.