search

go-gitea / gitea

Git with a cup of tea! Painless self-hosted all-in-one software development service, including Git hosting, code review, team collaboration, package registry and CI/CD
https://gitea.com
MIT License
45.21k stars 5.5k forks source link

Gitea: Internal error retrieve protected branches information failed: EOF #8251

Closed randyesq closed 4 years ago

randyesq commented 5 years ago

Description

We are hitting the following error very frequently when pushing from our local git repository to Gitea. Gitea is running in its docker image in Kubernetes.

From the local system pushing the branch:

slice-sms01-nmn:~/mfisch/config-management # git push origin master
--
Username for 'https://api-gw-service-nmn.local': crayvcs
Password for 'https://vcs@api-gw-service-nmn.local':
Counting objects: 18, done.
Delta compression using up to 16 threads.
Compressing objects: 100% (14/14), done.
Writing objects: 100% (18/18), 2.10 KiB \| 2.10 MiB/s, done.
Total 18 (delta 3), reused 0 (delta 0)
remote: Gitea: Internal error
remote: retrieve protected branches information failed: EOF
To https://api-gw-service-nmn.local/vcs/config-management.git
! [remote rejected] master -> master (pre-receive hook declined)
error: failed to push some refs to 'https://api-gw-service-nmn.local/vcs/config-management.git'

The gitea server logs running in the pod show the following:

2019/09/14 20:53:52 [T] GetProtectedBranchBy: http://localhost:3000/api/internal/branch/1/vcs/cme-premium/1.0.0
2019/09/14 20:53:55 [T] GetProtectedBranchBy: http://localhost:3000/api/internal/branch/1/master
2019/09/20 02:44:36 [T] GetProtectedBranchBy: http://localhost:3000/api/internal/branch/1/mfisch
2019/09/20 02:44:36 [...io/gitea/cmd/hook.go:109 runHookPreReceive()] [F] retrieve protected branches information failed: EOF
2019/09/20 02:48:32 [T] GetProtectedBranchBy: http://localhost:3000/api/internal/branch/1/mfisch
2019/09/20 02:48:32 [...io/gitea/cmd/hook.go:109 runHookPreReceive()] [F] retrieve protected branches information failed: EOF

Here is our app.ini:

; This file lists the default values used by Gitea
; Copy required sections to your own app.ini (default is custom/conf/app.ini)
; and modify as needed.

; see https://docs.gitea.io/en-us/config-cheat-sheet/ for additional documentation.

; App name that shows in every page title
APP_NAME = VCS
; Change it if you run locally
RUN_USER = git
; Either "dev", "prod" or "test", default is "dev"
RUN_MODE = prod

[repository]
; Disable the ability to interact with repositories using the HTTP protocol
DISABLE_HTTP_GIT = false

[repository.upload]
; Whether repository file uploads are enabled. Defaults to `true`
ENABLED = true
; Path for uploads. Defaults to `data/tmp/uploads` (tmp gets deleted on gitea restart)
TEMP_PATH = data/tmp/uploads
; One or more allowed types, e.g. image/jpeg|image/png. Nothing means any file type
ALLOWED_TYPES =
; Max size of each file in megabytes. Defaults to 3MB
FILE_MAX_SIZE = 3
; Max number of files per upload. Defaults to 5
MAX_FILES = 5

[server]
; The protocol the server listens on. One of 'http', 'https', 'unix' or 'fcgi'.
PROTOCOL = http
DOMAIN = api-gw-service-nmn.local
; ROOT_URL = %(PROTOCOL)s://%(DOMAIN)s:%(HTTP_PORT)s/
ROOT_URL = https://%(DOMAIN)s/vcs/
; The address to listen on. Either a IPv4/IPv6 address or the path to a unix socket.
HTTP_ADDR = 0.0.0.0
HTTP_PORT = 3000
; Local (DMZ) URL for Gitea workers (such as SSH update) accessing web service.
; In most cases you do not need to change the default value.
; Alter it only if your SSH server node is not the same as HTTP node.
; Do not set this variable if PROTOCOL is set to 'unix'.
LOCAL_ROOT_URL = http://localhost:3000/
; Disable SSH feature when not available
DISABLE_SSH = true
; Whether to use the builtin SSH server or not.
START_SSH_SERVER = false
; Gitea will create a authorized_keys file by default when it is not using the internal ssh server
; If you intend to use the AuthorizedKeysCommand functionality then you should turn this off.
SSH_CREATE_AUTHORIZED_KEYS_FILE = false
; Disable CDN even in "prod" mode
OFFLINE_MODE = true
DISABLE_ROUTER_LOG = false
; Default path for App data
APP_DATA_PATH = data
; Application level GZIP support
ENABLE_GZIP = false
; Application profiling (memory and cpu)
; For "web" command it listens on localhost:6060
; For "serve" command it dumps to disk at PPROF_DATA_PATH as (cpuprofile|memprofile)_<username>_<temporary id>
ENABLE_PPROF = false
; PPROF_DATA_PATH, use an absolute path when you start gitea as service
PPROF_DATA_PATH = data/tmp/pprof
; Enables git-lfs support. true or false, default is false.
LFS_START_SERVER = false
; Where your lfs files reside, default is data/lfs.
LFS_CONTENT_PATH = data/lfs
; LFS authentication secret, change this yourself
LFS_JWT_SECRET =
; LFS authentication validity period (in time.Duration), pushes taking longer than this may fail.
LFS_HTTP_AUTH_EXPIRY = 20m

[database]
; Either "mysql", "postgres", "mssql" or "sqlite3", it's your choice
DB_TYPE = postgres
HOST = vcs-database
NAME = gitea
USER = <redacted>
; Use PASSWD = `your password` for quoting if you use special characters in the password.
PASSWD = `<redacted>`
; For Postgres, either "disable" (default), "require", or "verify-full"
; For MySQL, either "false" (default), "true", or "skip-verify"
SSL_MODE = disable
; Show the database generated SQL
LOG_SQL = true

[admin]
; Disallow regular (non-admin) users from creating organizations.
DISABLE_REGULAR_ORG_CREATION = false

[security]
; Whether the installer is disabled
INSTALL_LOCK = true
; !!CHANGE THIS TO KEEP YOUR USER DATA SAFE!!
SECRET_KEY = <redacted>

[service]
; Whether a new user needs to confirm their email when registering.
REGISTER_EMAIL_CONFIRM = false
; Disallow registration, only allow admins to create accounts.
DISABLE_REGISTRATION = true
; Each new user will get the value of this setting copied into their profile
DEFAULT_KEEP_EMAIL_PRIVATE = true
; Default value for AllowCreateOrganization
; Every new user will have rights set to create organizations depending on this setting
DEFAULT_ALLOW_CREATE_ORGANIZATION = true
; Default value for EnableDependencies
; Repositories will use dependencies by default depending on this setting
DEFAULT_ENABLE_DEPENDENCIES = true
; Enable heatmap on users profiles.
ENABLE_USER_HEATMAP = false
; Show Registration button
SHOW_REGISTRATION_BUTTON = false

[mailer]
ENABLED = false

[cache]
; Either "memory", "redis", or "memcache", default is "memory"
ADAPTER = memory

[session]
; Either "memory", "file", or "redis", default is "memory"
PROVIDER = memory

[picture]
; This value will always be true in offline mode.
DISABLE_GRAVATAR = true

[log]
; Either "console", "file", "conn", "smtp" or "database", default is "console"
; Use comma to separate multiple modes, e.g. "console, file"
MODE = console
; Either "Trace", "Debug", "Info", "Warn", "Error", "Critical", default is "Trace"
LEVEL = Trace
REDIRECT_MACARON_LOG = false

; For "console" mode only
[log.console]
LEVEL = Trace

[other]
; Show template execution time in the footer
SHOW_FOOTER_TEMPLATE_LOAD_TIME = false

The only thing that can be done to unwedge this is to restart the pod running the gitea server. It appears as though the problem only happens when gitea is first deployed. After restarting the pod, we never see this issue again.

Possibly important is that we do not setup SSH at all, only https. The push failures occurs after cloning the repository using https, and pushing back using https.

randyesq commented 5 years ago

Note that our LOCAL_ROOT_URL is hard-coded to http://localhost:3000/ as was suggested in #3226, #1685, #2270, and #7630. The restart seems to be working for others with different problems that have a similar error signature (#2851).

randyesq commented 5 years ago

I also have run the admin Maintenance Operations task titled "Resynchronize pre-receive, update and post-receive hooks of all repositories." and this did not fix anything.

techknowlogick commented 5 years ago

This may have been fixed in a more recent version of Gitea (we just released 1.9.3). The newer versions also have patched some security vulns that are in 1.7.

1.9 also has improved logging to assist with debugging.

randyesq commented 5 years ago

@techknowlogick is there something in the diff between 1.7 -> 1.9 that would suggest this would be fixed? From most of the issues that I referred to, it didn't seem like it was understood why this was even happening in the first place.

techknowlogick commented 5 years ago

Potentially there could be something that has been added as there has been hundreds of PRs since 1.7. It could be a timeout issue with the DB, and we've updated upstream dependencies, it could be an uncaught error that is now handled, it could be many things. We've also significantly refactored working with the underlying git repos which may be a factor. Please see the entire list of changes here: https://github.com/go-gitea/gitea/blob/master/CHANGELOG.md

I recommend updating and to see if this still happens, especially since there are several CVEs in the version you are currently using: https://cve.mitre.org/cgi-bin/cvekey.cgi?keyword=gitea Once you've updated the logging in v1.9.3 is really improved and can give a ton of details about what could be happening.

randyesq commented 5 years ago

Okay, we'll get on with upgrading this on our side and see if anything else comes up.

devurandom commented 5 years ago

I also have run the admin Maintenance Operations task titled "Resynchronize pre-receive, update and post-receive hooks of all repositories." and this did not fix anything.

In my case it worked. I also pressed the ".ssh/authorized_keys" button, so maybe that had some effect, too.

zeripath commented 5 years ago

yeah that would need changing too if you changed the path of the gitea binary.

To be clear Gitea has to write its real full path to:

These all have to be updated if you change the path of the Gitea binary.

If you are moving from Gogs you may have to remove any reference to Gogs within the gitea-repositories/*.git/hooks/*.d directories.

It really is simpler not to change the name of the binary.

randyesq commented 5 years ago

We encountered this issue in a K8S pod using v1.9.3 today.

zeripath commented 5 years ago

@randyesq in order to diagnose I need to see what the message underlying that was and what your main Gitea logs show.

The problem here as originally stated cannot happen on 1.9 because those internal endpoints do not exist. I deleted them - (and now constantly regret doing so instead of coming up with an error saying you need to update although I remain uncertain how that helpful that would be as it could only be on the server.)

If your Gitea serv is requesting those end points e.g. /api/internal/branch/1/mfisch then you have got an old version of Gitea running somewhere and you need to do hunt it down.

Otherwise it's a different problem.

randyesq commented 5 years ago

Here is the version of gitea that we are using:

ncn-w001:~/k8s # kubectl exec -it gitea-vcs-5df75f48f7-h8rx7 -n services bash
Defaulting container name to vcs.
Use 'kubectl describe pod/gitea-vcs-5df75f48f7-h8rx7 -n services' to see all of the containers in this pod.
bash-5.0# gitea --version
Gitea version 1.9.3 built with GNU Make 4.2.1, go1.12.9 : bindata, sqlite, sqlite_unlock_notify

Unfortunately, I don't have the server logs because they have rolled over since, but the output from the git client that was trying to force push the branch was:

    Total 12 (delta 2), reused 0 (delta 0)
    remote: Gitea: EOF
    To https://api-gw-service-nmn.local/vcs/cray/config-management.git
     ! [remote rejected] cray/cme-premium/1.1.0 -> cray/cme-premium/1.1.0 (pre-receive hook declined)
    error: failed to push some refs to 'https://api-gw-service-nmn.local/vcs/cray/config-management.git'
zeripath commented 5 years ago

Without those logs we can't tell you anything.

All you can say is that there was a pre-receive decline - that could be because you were force pushing to a protected branch and that was disallowed although the EOF implies that's not.

It could be a bug in /api/internal/hook/pre-receive or it could be that you've got an old Gitea hanging around that's trying to get to the old endpoints.

This last is the most likely so double check there aren't some seriously old Giteas hanging around and:

Ensure that your .SSH/authorized_keys always refers to the correct version of Gitea if there are multiple versions available, and ensure that your hooks are all doing similarly.

If it happens again grab the logs. If you're getting requests to /api/internal/branch then there's an old Gitea around. If not you've found a bug and we need the logs.

randyesq commented 5 years ago

Ensure that your .SSH/authorized_keys always refers to the correct version of Gitea if there are multiple versions available, and ensure that your hooks are all doing similarly.

How do I ensure this?

zeripath commented 5 years ago

The 2 admin tasks described above rewrite both of these things - however I can imagine a deployment style that would make those not work. It's your deployment - you tell me.

All I can say is to run those tasks, make sure there's not a rogue old version of Gitea in your container(s) or an old container still knocking around, and check those files.

If your Gitea serv is requesting /api/internal/branch that Gitea is not version 1.9 and it's out of date.

Further don't put multiple versions of Gitea in your containers. If you're using a script to wrap Gitea you should run Gitea with exec -a the_name_of_the_script as we use the $0 passed to Gitea as its path when writing hooks and authorized_keys.

randyesq commented 5 years ago

Okay thanks, we only have one version of gitea, whatever is in the gitea/1.9.3 docker image from Docker hub, so I don't think it is a version issue.

lunny commented 5 years ago

It seems you have a subpath of your domain setting, maybe it's related. https://api-gw-service-nmn.local/vcs/cray/config-management.git.

randyesq commented 5 years ago

Okay, I had this happen today. I am running v1.9.3 and logged in to the web UI, created an org, created a repo (initialized it with the checkbox), and attempted to create a file in the UI. Here is the server log:

[Macaron] 2019-11-07 20:19:31: Started POST /foo/bar/_new/master/ for 10.47.0.0
2019/11/07 20:19:31 .../xorm/session_get.go:99:nocacheGet() [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", "description", "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", "num_teams", "num_members", "visibility", "diff_view_style", "theme" FROM "user" WHERE "id"=$1 LIMIT 1 []interface {}{1}
2019/11/07 20:19:31 ...s/context/context.go:328:func1() [D] Session ID: 84335f472022f1f8
2019/11/07 20:19:31 ...s/context/context.go:329:func1() [D] CSRF Token: 44JwSeHDqnv5UnglbneRrWs288M6MTU3MzE1Nzg2ODg4NjkxNjc0NA==
2019/11/07 20:19:31 .../xorm/session_raw.go:87:queryRow() [I] [SQL] SELECT count(*) FROM "notification" WHERE (user_id = $1) AND (status = $2) []interface {}{1, 0x1}
2019/11/07 20:19:31 .../xorm/session_get.go:99:nocacheGet() [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", "description", "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", "num_teams", "num_members", "visibility", "diff_view_style", "theme" FROM "user" WHERE "lower_name"=$1 LIMIT 1 []interface {}{"foo"}
2019/11/07 20:19:31 .../xorm/session_get.go:99:nocacheGet() [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_empty", "is_archived", "is_mirror", "is_fork", "fork_id", "size", "is_fsck_enabled", "close_issues_via_commit_in_any_branch", "topics", "avatar", "created_unix", "updated_unix" FROM "repository" WHERE "owner_id"=$1 AND "lower_name"=$2 LIMIT 1 []interface {}{2, "bar"}
2019/11/07 20:19:31 .../xorm/session_get.go:99:nocacheGet() [I] [SQL] SELECT "id", "repo_id", "user_id", "mode" FROM "collaboration" WHERE "repo_id"=$1 AND "user_id"=$2 LIMIT 1 []interface {}{2, 1}
2019/11/07 20:19:31 ...xorm/session_find.go:199:noCacheFind() [I] [SQL] SELECT "id", "repo_id", "type", "config", "created_unix" FROM "repo_unit" WHERE (repo_id = $1) []interface {}{2}
2019/11/07 20:19:31 ...s/repo_permission.go:154:func1() [T] Permission Loaded for 824687817488:crayvcs in 824687817696:foo/bar:
    Permissions: AccessMode: 824687818880:owner, 5 Units, 0 UnitsMode(s): [
    Units[0]: ID: 824687817824 RepoID: 824687818160 Type: 824687818912:UnitTypeCode Config: {}
    Units[1]: ID: 824687818256 RepoID: 824687818352 Type: 824687818944:UnitTypeIssues Config: {"EnableTimetracker":true,"AllowOnlyContributorsToTrackTime":true,"EnableDependencies":true}
    Units[2]: ID: 824687818608 RepoID: 824687818640 Type: 824687818976:UnitTypePullRequests Config: {"IgnoreWhitespaceConflicts":false,"AllowMerge":true,"AllowRebase":true,"AllowRebaseMerge":true,"AllowSquash":true}
    Units[3]: ID: 824687818704 RepoID: 824687818736 Type: 824687819008:UnitTypeReleases Config: {}
    Units[4]: ID: 824687818800 RepoID: 824687818832 Type: 824687819040:UnitTypeWiki Config: {} ]
2019/11/07 20:19:31 .../xorm/session_raw.go:87:queryRow() [I] [SQL] SELECT count(*) FROM "release" WHERE repo_id=$1 AND is_draft=$2 []interface {}{2, false}
2019/11/07 20:19:31 .../xorm/session_get.go:99:nocacheGet() [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_empty", "is_archived", "is_mirror", "is_fork", "fork_id", "size", "is_fsck_enabled", "close_issues_via_commit_in_any_branch", "topics", "avatar", "created_unix", "updated_unix" FROM "repository" WHERE (owner_id=$1 AND fork_id=$2) LIMIT 1 []interface {}{1, 2}
2019/11/07 20:19:31 .../xorm/session_get.go:99:nocacheGet() [I] [SQL] SELECT "id", "user_id", "repo_id" FROM "watch" WHERE "user_id"=$1 AND "repo_id"=$2 LIMIT 1 []interface {}{1, 2}
2019/11/07 20:19:31 .../xorm/session_get.go:99:nocacheGet() [I] [SQL] SELECT "id", "uid", "repo_id" FROM "star" WHERE "uid"=$1 AND "repo_id"=$2 LIMIT 1 []interface {}{1, 2}
2019/11/07 20:19:31 .../xorm/session_get.go:99:nocacheGet() [I] [SQL] SELECT "id", "repo_id", "branch_name", "can_push", "enable_whitelist", "whitelist_user_i_ds", "whitelist_team_i_ds", "enable_merge_whitelist", "merge_whitelist_user_i_ds", "merge_whitelist_team_i_ds", "approvals_whitelist_user_i_ds", "approvals_whitelist_team_i_ds", "required_approvals", "created_unix", "updated_unix" FROM "protected_branch" WHERE "repo_id"=$1 AND "branch_name"=$2 LIMIT 1 []interface {}{2, "master"}
2019/11/07 20:19:31 .../xorm/session_get.go:99:nocacheGet() [I] [SQL] SELECT "id", "repo_id", "branch_name", "can_push", "enable_whitelist", "whitelist_user_i_ds", "whitelist_team_i_ds", "enable_merge_whitelist", "merge_whitelist_user_i_ds", "merge_whitelist_team_i_ds", "approvals_whitelist_user_i_ds", "approvals_whitelist_team_i_ds", "required_approvals", "created_unix", "updated_unix" FROM "protected_branch" WHERE "repo_id"=$1 AND "branch_name"=$2 LIMIT 1 []interface {}{2, "master"}
[Macaron] 2019-11-07 20:19:31: Started GET / for 127.0.0.1
2019/11/07 20:19:31 ...s/context/context.go:328:func1() [D] Session ID: 9592bbb188ca9a45
2019/11/07 20:19:31 ...s/context/context.go:329:func1() [D] CSRF Token: 21NVKuOMVuEkabb1tuJWO-fXj4M6MTU3MzE1Nzk3MTU2Mjg1ODU1Mg==
2019/11/07 20:19:31 ...s/context/context.go:137:HTML() [D] Template: home
[Macaron] 2019-11-07 20:19:31: Completed GET / 200 OK in 3.384469ms
[Macaron] 2019-11-07 20:19:31: Started GET /api/internal/hook/pre-receive/foo/bar?old=84ae4ffb4f9f503ce796d345a676c800b675aacc&new=db46e075b33bac76664db835e728b2b34384e424&ref=refs%2Fheads%2Fmaster&userID=1&gitObjectDirectory=%2Fdata%2Fgit%2Fgitea-repositories%2Ffoo%2Fbar.git%2F.%2Fobjects%2Fincoming-PfjpLI&gitAlternativeObjectDirectories=%2Fdata%2Fgit%2Fgitea-repositories%2Ffoo%2Fbar.git%2F.%2Fobjects&gitQuarantinePath=%2Fdata%2Fgit%2Fgitea-repositories%2Ffoo%2Fbar.git%2F.%2Fobjects%2Fincoming-PfjpLI&prID=0 for 127.0.0.1
2019/11/07 20:19:31 modules/auth/auth.go:97:CheckOAuthAccessToken() [T] ParseOAuth2Token: signature is invalid
2019/11/07 20:19:31 ...s/context/context.go:328:func1() [D] Session ID: 92c404aa8441d573
2019/11/07 20:19:31 ...s/context/context.go:329:func1() [D] CSRF Token: NMoCu5jvTAQNl_nD2qHisrnfQ9I6MTU3MzE1Nzk3MTc5MDgxMzM4MQ==
[Macaron] 2019-11-07 20:19:31: Completed GET /api/internal/hook/pre-receive/foo/bar?old=84ae4ffb4f9f503ce796d345a676c800b675aacc&new=db46e075b33bac76664db835e728b2b34384e424&ref=refs%2Fheads%2Fmaster&userID=1&gitObjectDirectory=%2Fdata%2Fgit%2Fgitea-repositories%2Ffoo%2Fbar.git%2F.%2Fobjects%2Fincoming-PfjpLI&gitAlternativeObjectDirectories=%2Fdata%2Fgit%2Fgitea-repositories%2Ffoo%2Fbar.git%2F.%2Fobjects&gitQuarantinePath=%2Fdata%2Fgit%2Fgitea-repositories%2Ffoo%2Fbar.git%2F.%2Fobjects%2Fincoming-PfjpLI&prID=0 403 Forbidden in 911.132µs
2019/11/07 20:19:31 ...s/context/context.go:137:HTML() [D] Template: repo/editor/edit
[Macaron] 2019-11-07 20:19:31: Completed POST /foo/bar/_new/master/ 302 Found in 469.152703ms
2019/11/07 20:19:31 ...c/net/http/server.go:3012:logf() [I] http: superfluous response.WriteHeader call from gopkg.in/macaron%2ev1.(*responseWriter).WriteHeader (response_writer.go:59)
[Macaron] 2019-11-07 20:19:31: Started GET /vendor/plugins/simplemde/simplemde.min.css for 10.47.0.0
[Macaron] [Static] Serving /vendor/plugins/simplemde/simplemde.min.css
[Macaron] 2019-11-07 20:19:31: Completed GET /vendor/plugins/simplemde/simplemde.min.css 200 OK in 734.459µs
[Macaron] 2019-11-07 20:19:31: Started GET /vendor/plugins/highlight/github.css for 10.47.0.0
[Macaron] [Static] Serving /vendor/plugins/highlight/github.css
[Macaron] 2019-11-07 20:19:31: Completed GET /vendor/plugins/highlight/github.css 200 OK in 326.641µs
[Macaron] 2019-11-07 20:19:32: Started GET /vendor/plugins/codemirror/mode/yaml/yaml.js for 10.47.0.0
[Macaron] [Static] Serving /vendor/plugins/codemirror/mode/yaml/yaml.js
[Macaron] 2019-11-07 20:19:32: Completed GET /vendor/plugins/codemirror/mode/yaml/yaml.js 200 OK in 358.95µs
[Macaron] 2019-11-07 20:19:32: Started GET /foo/bar/_new/master/site.yml for 10.47.0.0
2019/11/07 20:19:32 .../xorm/session_get.go:99:nocacheGet() [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", "description", "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", "num_teams", "num_members", "visibility", "diff_view_style", "theme" FROM "user" WHERE "id"=$1 LIMIT 1 []interface {}{1}
2019/11/07 20:19:32 ...s/context/context.go:328:func1() [D] Session ID: 84335f472022f1f8
2019/11/07 20:19:32 ...s/context/context.go:329:func1() [D] CSRF Token: 44JwSeHDqnv5UnglbneRrWs288M6MTU3MzE1Nzg2ODg4NjkxNjc0NA==
2019/11/07 20:19:32 .../xorm/session_raw.go:87:queryRow() [I] [SQL] SELECT count(*) FROM "notification" WHERE (user_id = $1) AND (status = $2) []interface {}{1, 0x1}
2019/11/07 20:19:32 .../xorm/session_get.go:99:nocacheGet() [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", "description", "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", "num_teams", "num_members", "visibility", "diff_view_style", "theme" FROM "user" WHERE "lower_name"=$1 LIMIT 1 []interface {}{"foo"}
2019/11/07 20:19:32 .../xorm/session_get.go:99:nocacheGet() [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_empty", "is_archived", "is_mirror", "is_fork", "fork_id", "size", "is_fsck_enabled", "close_issues_via_commit_in_any_branch", "topics", "avatar", "created_unix", "updated_unix" FROM "repository" WHERE "owner_id"=$1 AND "lower_name"=$2 LIMIT 1 []interface {}{2, "bar"}
2019/11/07 20:19:32 .../xorm/session_get.go:99:nocacheGet() [I] [SQL] SELECT "id", "repo_id", "user_id", "mode" FROM "collaboration" WHERE "repo_id"=$1 AND "user_id"=$2 LIMIT 1 []interface {}{2, 1}
2019/11/07 20:19:32 ...xorm/session_find.go:199:noCacheFind() [I] [SQL] SELECT "id", "repo_id", "type", "config", "created_unix" FROM "repo_unit" WHERE (repo_id = $1) []interface {}{2}
2019/11/07 20:19:32 ...s/repo_permission.go:154:func1() [T] Permission Loaded for 824707920288:crayvcs in 824707920368:foo/bar:
    Permissions: AccessMode: 824707921584:owner, 5 Units, 0 UnitsMode(s): [
    Units[0]: ID: 824707920560 RepoID: 824707920608 Type: 824707921616:UnitTypeCode Config: {}
    Units[1]: ID: 824707920992 RepoID: 824707921040 Type: 824707921648:UnitTypeIssues Config: {"EnableTimetracker":true,"AllowOnlyContributorsToTrackTime":true,"EnableDependencies":true}
    Units[2]: ID: 824707921136 RepoID: 824707921184 Type: 824707921680:UnitTypePullRequests Config: {"IgnoreWhitespaceConflicts":false,"AllowMerge":true,"AllowRebase":true,"AllowRebaseMerge":true,"AllowSquash":true}
    Units[3]: ID: 824707921344 RepoID: 824707921376 Type: 824707921712:UnitTypeReleases Config: {}
    Units[4]: ID: 824707921440 RepoID: 824707921504 Type: 824707921744:UnitTypeWiki Config: {} ]
2019/11/07 20:19:32 .../xorm/session_raw.go:87:queryRow() [I] [SQL] SELECT count(*) FROM "release" WHERE repo_id=$1 AND is_draft=$2 []interface {}{2, false}
2019/11/07 20:19:32 .../xorm/session_get.go:99:nocacheGet() [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_empty", "is_archived", "is_mirror", "is_fork", "fork_id", "size", "is_fsck_enabled", "close_issues_via_commit_in_any_branch", "topics", "avatar", "created_unix", "updated_unix" FROM "repository" WHERE (owner_id=$1 AND fork_id=$2) LIMIT 1 []interface {}{1, 2}
2019/11/07 20:19:32 .../xorm/session_get.go:99:nocacheGet() [I] [SQL] SELECT "id", "user_id", "repo_id" FROM "watch" WHERE "user_id"=$1 AND "repo_id"=$2 LIMIT 1 []interface {}{1, 2}
2019/11/07 20:19:32 .../xorm/session_get.go:99:nocacheGet() [I] [SQL] SELECT "id", "uid", "repo_id" FROM "star" WHERE "uid"=$1 AND "repo_id"=$2 LIMIT 1 []interface {}{1, 2}
2019/11/07 20:19:32 .../xorm/session_get.go:99:nocacheGet() [I] [SQL] SELECT "id", "repo_id", "branch_name", "can_push", "enable_whitelist", "whitelist_user_i_ds", "whitelist_team_i_ds", "enable_merge_whitelist", "merge_whitelist_user_i_ds", "merge_whitelist_team_i_ds", "approvals_whitelist_user_i_ds", "approvals_whitelist_team_i_ds", "required_approvals", "created_unix", "updated_unix" FROM "protected_branch" WHERE "repo_id"=$1 AND "branch_name"=$2 LIMIT 1 []interface {}{2, "master"}
2019/11/07 20:19:32 ...s/context/context.go:137:HTML() [D] Template: repo/editor/edit
[Macaron] 2019-11-07 20:19:32: Completed GET /foo/bar/_new/master/site.yml 200 OK in 43.711104ms
[Macaron] 2019-11-07 20:19:32: Started GET /serviceworker.js for 10.47.0.0
2019/11/07 20:19:32 .../xorm/session_get.go:99:nocacheGet() [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", "description", "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", "num_teams", "num_members", "visibility", "diff_view_style", "theme" FROM "user" WHERE "id"=$1 LIMIT 1 []interface {}{1}
2019/11/07 20:19:32 ...s/context/context.go:328:func1() [D] Session ID: 84335f472022f1f8
2019/11/07 20:19:32 ...s/context/context.go:329:func1() [D] CSRF Token: 44JwSeHDqnv5UnglbneRrWs288M6MTU3MzE1Nzg2ODg4NjkxNjc0NA==
2019/11/07 20:19:32 .../xorm/session_raw.go:87:queryRow() [I] [SQL] SELECT count(*) FROM "notification" WHERE (user_id = $1) AND (status = $2) []interface {}{1, 0x1}
[Macaron] 2019-11-07 20:19:32: Completed GET /serviceworker.js 200 OK in 7.783204ms

Looks like 

[Macaron] 2019-11-07 20:19:31: Started GET /api/internal/hook/pre-receive/foo/bar?old=84ae4ffb4f9f503ce796d345a676c800b675aacc&new=db46e075b33bac76664db835e728b2b34384e424&ref=refs%2Fheads%2Fmaster&userID=1&gitObjectDirectory=%2Fdata%2Fgit%2Fgitea-repositories%2Ffoo%2Fbar.git%2F.%2Fobjects%2Fincoming-PfjpLI&gitAlternativeObjectDirectories=%2Fdata%2Fgit%2Fgitea-repositories%2Ffoo%2Fbar.git%2F.%2Fobjects&gitQuarantinePath=%2Fdata%2Fgit%2Fgitea-repositories%2Ffoo%2Fbar.git%2F.%2Fobjects%2Fincoming-PfjpLI&prID=0 for 127.0.0.1
2019/11/07 20:19:31 modules/auth/auth.go:97:CheckOAuthAccessToken() [T] ParseOAuth2Token: signature is invalid

is the problem area.

Note, the user is created by the gitea admin CLI when gitea is brought up.

zeripath commented 5 years ago

Ok a status forbidden in hook pre-receive code is preceded by a warning.

So the forbidden is happening at:

https://github.com/go-gitea/gitea/blob/4a08d574cf496268b5ceae4fc605e103c870d204/routers/private/internal.go#L17-L24

Meaning that the internal token being passed to the server from the running command is incorrect.

You have different internal tokens - they all have to be the same.

randyesq commented 5 years ago

So this action was run from the UI from a logged in user. Are you saying that something that is being done with my configuration of gitea itself is wrong, or something in the UI is wrong?

zeripath commented 5 years ago

OK, I think it's time I stepped back down to what goes on when you do any git alterations in Gitea.

Now if you go and take a look at one of your gitea-repositories you'll see that the hooks are something like:

❯ cat ~/gitea-repositories/administrator/nonempty.git/hooks/pre-receive.d/gitea                           [20:50:54]
#!/usr/bin/env bash
"/home/zeripath/go/src/code.gitea.io/gitea/gitea" hook --config='/home/zeripath/go/src/code.gitea.io/gitea/custom/conf/app.ini' pre-receive

Note the absolute path to the gitea application that run it, and a config file reference.

The config file reference is important because gitea will not be unlikely to find its config otherwise, in particular it needs the INTERNAL_TOKEN from that app.ini because, well that's the authorization token that gitea hook uses to talk to the server and it needs find the local address for the Gitea server to speak to (That's specifically LOCAL_ROOT_URL, but ROOT_URL, or whatever goes to make that if that's not set.)

Now as I state above, there is no place for a user to get Forbidden in hooks without some more logging except at:

https://github.com/go-gitea/gitea/blob/4a08d574cf496268b5ceae4fc605e103c870d204/routers/private/internal.go#L17-L24

So, when that push is happening the config that the hook files is finding is not correct - either because INTERNAL_TOKEN is not set or the server that hook speaks to over LOCAL_ROOT_URL has a different INTERNAL_TOKEN.

randyesq commented 5 years ago

Is there a way I can modify the pre-receive.d/gitea bash script to print out the values of the INTERNAL_TOKEN that are in play?

zeripath commented 5 years ago

A grep of the config file as a hook would do it as far as I can see.

randyesq commented 5 years ago

Where would the output of that hook script end up for me to review?

zeripath commented 5 years ago

Stdout from most git hooks is sent directly to the client. Certainly these would do so.

The issue is ensuring that you're getting exactly the same config file as the hook - you could grep/sed it out of the Gitea hook file.

However if you can do all that, I'm not certain just checking hook files and container confs would not work.

If you don't want it to go to the client - one trick is to do a wget to get it into a server log.

randyesq commented 5 years ago

Okay, well the instance for the server logs that I found was running in a VM that I have up that has the same configuration as our regular setup, here is the content of the hook and shows that the app.ini and gitea executable are where I expect them to be:

bash-5.0# cat /data/git/gitea-repositories/foo/bar.git/hooks/pre-receive.d/gitea
#!/usr/bin/env bash
"/app/gitea/gitea" hook --config='/data/gitea/conf/app.ini' pre-receive
bash-5.0# ls -l /app/gitea/gitea
-rwxr-xr-x    1 git      git       62985080 Sep  7 18:02 /app/gitea/gitea
bash-5.0# ls -l /data/gitea/conf/app.ini
-rwxr-xr-x    1 git      git           5793 Nov  7 20:30 /data/gitea/conf/app.ini

My app.ini does not include an INTERNAL_TOKEN when Gitea first starts up, but it looks like Gitea is creating one properly

bash-5.0# grep INTERNAL_TOKEN /data/gitea/conf/app.ini
INTERNAL_TOKEN = eyJhbGciOiJIUzI1NiIsInR5cCI6IkpXVCJ9.eyJuYmYiOjE1NzMxNTg2MDB9.dhqm5QaQFItK3--HV69oW8D3j_8UKkLoN0hn4tqg0pM

LOCAL_ROOT_URL and ROOT_URL are defined as such in the server section of app.ini:

[server]
PROTOCOL                        = http
DOMAIN                          = git-service.local
ROOT_URL                        = https://%(DOMAIN)s/vcs/
HTTP_ADDR                       = 0.0.0.0
HTTP_PORT                       = 3000
LOCAL_ROOT_URL                  = http://localhost:3000/
DISABLE_SSH                     = true
START_SSH_SERVER                = false
SSH_CREATE_AUTHORIZED_KEYS_FILE = false
OFFLINE_MODE                    = true
DISABLE_ROUTER_LOG              = false
APP_DATA_PATH                   = data

Anything you see here look incorrect?

zeripath commented 5 years ago

I don't know your configuration but I suspect app.ini having internal token empty is incorrect. Do you ever have more than one Gitea running at a time?

Is it possible that the instance that is running the hook is not the same instance as the Gitea that is the server?

Stop recreating the internal token every time. Put it in the app.ini.

randyesq commented 5 years ago

We don't have more than one instance running at a time, so that is not possible.

I'll see about adding an internal token when we bring up gitea the first time. My question would be, however, is the internal token changing while gitea is up and running?

randyesq commented 5 years ago

Is there a specific format for the internal token that needs to be used?

zeripath commented 5 years ago

Not sure but I could imagine that if the server was restarted for whatever reason the internal token would change.

I think you just need to copy a created internal token from the app.ini of a running server and add that to your template.

stale[bot] commented 4 years ago

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs during the next 2 weeks. Thank you for your contributions.

randyesq commented 4 years ago

We have made the change to have the INTERNAL_TOKEN set when the instance is first brought up. Haven't seen any issues since then. Thanks for your help on this one @zeripath .