Error 500 after pushing to new repos - docker

[holmesb]

Further to issue #7499, at the request of @sapk, I am opening a new issue to track this problem on docker. Get error 500 in webui after pushing to or initialising a repo. @sapk suspects this is related to gitea not being able to read some folders for various reason. But shelling into the container and writing files in the repos dir works fine. Example of error:

[Macaron] 2019-08-26 18:04:01: Completed GET /myorg/myrepo 500 Internal Server Error in 58.821377ms

I've tried SSH & HTTPS, OpenID & local login and private & non-private. Restarting container\pod doesn't help.

• Gitea version (or commit ref): v1.9.2
• Git version: 2.17.1
• Operating system: Whatever the docker image is.
• Database (use [x]):
  • PostgreSQL
  • MySQL
  • MSSQL
  • SQLite
• Can you reproduce the bug at https://try.gitea.io:
  • Yes (provide example URL)
  • No
  • Not relevant

Can be fixed on systemd-based systems by adding line to systemd config file: ReadWritePaths=/path/to/git/repos But this does not exist in docker container.

[lafriks]

Can you give error from gitea.log that is logged when this error happens

[holmesb]

Hi @lafriks. The error above ("[Macaron]...") is from the gitea.log AFAIK. I'm on Kubernetes, so whatever log file is output by the kubectl logs command is what I posted. I can post the surrounding lines if it helps, but don't think they were interesting. It happens at exactly the moment I try to browse to a repo, post-push\initialise.

[lafriks]

Real error is logged in gitea.log file /data/gitea/logs/ directory

[holmesb]

/data/gitea/log dir is empty in k8s. The surrounding lines when webui error occurs:

[Macaron] 2019-08-28 22:21:37: Started GET /myorg/myrepo for 10.197.8.9
[Macaron] 2019-08-28 22:21:38: Completed GET /myorg/myrepo 500 Internal Server Error in 61.893175ms
[Macaron] 2019-08-28 22:21:38: Started GET /img/favicon.png for 10.197.8.9
[Macaron] 2019-08-28 22:21:38: Started GET /manifest.json for 10.197.8.9
[Macaron] [Static] Serving /img/favicon.png
[Macaron] 2019-08-28 22:21:38: Completed GET /img/favicon.png 200 OK in 127.45µs
[Macaron] 2019-08-28 22:21:38: Completed GET /manifest.json 200 OK in 1.668535ms
[Macaron] 2019-08-28 22:21:40: Started GET /serviceworker.js for 10.197.8.9
[Macaron] 2019-08-28 22:21:40: Completed GET /serviceworker.js 200 OK in 2.08394ms

[typeless]

How do you set up your Gitea using Docker? Can you post your docker-compose or the startup script for your Gitea image?

[typeless]

By the way, the app.ini config file has a log section which can control the log level. Setting it to Trace level will provide more information.

[holmesb]

Logging is already LEVEL = trace. Setup using this helm chart. I am using docker image gitea/gitea:1.9.2, which was built from this Dockerfile. Should be easy to try to reproduce. Can you?

[typeless]

I set up my Gitea with systemd and have no idea about the helm chart.

For troubleshooting, the things that I would have a look are

1. The owners and file permissions of the repository files and directories.
2. The user/group of the Gitea process in the container.
3. The log in gitea.log at the moment when creating the repository.

[holmesb]

You don't need the helm chart just to run the docker image (to test without systemd). Same occurs just running gitea in a simple pod (not via Kubernetes stuff, ie no ingress\services, etc). Here are all processes and the associated user:

PID   USER     TIME  COMMAND
1      root      0:00 /bin/s6-svscan /etc/s6
14     root      0:00 s6-supervise openssh
15     root      0:00 s6-supervise gitea
16     root      0:00 /usr/sbin/sshd -D -e
17     git      12:57 /app/gitea/gitea web
52     root      0:00 bash
29     root      0:00 bash
138    root      0:00 bash

And here are the data perms:

bash-5.0# ls -al /data
total 4
drwxr-xr-x    1 root     root            48 Aug 26 17:58 .
drwxr-xr-x    1 root     root          4096 Aug 26 18:25 ..
drwxr-xr-x    1 git      git             64 Aug 26 18:25 git
drwxr-xr-x    1 git      git             14 Aug 25 21:38 gitea
drwx------    1 999      root           486 Aug 25 21:36 postgresql-db
drwx------    1 root     root           312 Aug 25 21:38 ssh

I haven't changed any perms. Everything under git & gitea are owned by git. Does that look right?

[typeless]

@holmesb I just tested it on my macOS using Sqlite, and it worked fine.
I used the docker-compose file as in the webpage: https://docs.gitea.io/en-us/install-with-docker/

version: "2"

networks:
  gitea:
    external: false

services:
  server:
    image: gitea/gitea:latest
    environment:
      - USER_UID=1000
      - USER_GID=1000
    restart: always
    networks:
      - gitea
    volumes:
      - ./gitea:/data
    ports:
      - "3000:3000"
      - "222:22"

I used the the above snippet verbatim, and saving it as docker-compose-yml.

[holmesb]

Ok found gitea.log. It's not in /data/log as I expected, it's: /app/gitea/log/gitea.log. Here's what's logged when the 500 error occurs in the webui (when clicking a repo):

2019/09/01 17:02:11 .../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/09/01 17:02:11 .../xorm/session_raw.go:87:queryRow() [I] [SQL] SELECT count(*) FROM "notification" WHERE (user_id = $1) AND (status = $2) []interface {}{1, 0x1}
2019/09/01 17:02:11 .../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 {}{"myorg"}
2019/09/01 17:02:11 .../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 {}{8, "sr"}
2019/09/01 17:02:11 .../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 {}{3, 1}
2019/09/01 17:02:11 ...xorm/session_find.go:199:noCacheFind() [I] [SQL] SELECT "id", "repo_id", "type", "config", "created_unix" FROM "repo_unit" WHERE (repo_id = $1) []interface {}{3}
2019/09/01 17:02:11 .../xorm/session_raw.go:87:queryRow() [I] [SQL] SELECT count(*) FROM "release" WHERE repo_id=$1 AND is_draft=$2 []interface {}{3, false}
2019/09/01 17:02:11 .../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, 3}
2019/09/01 17:02:11 .../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, 3}
2019/09/01 17:02:11 .../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, 3}
2019/09/01 17:02:11 ...ules/context/repo.go:664:func1() [E] GetCommitsCount: dial unix data/caches: connect: no such file or directory
2019/09/01 17:02:12 .../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/09/01 17:02:12 .../xorm/session_raw.go:87:queryRow() [I] [SQL] SELECT count(*) FROM "notification" WHERE (user_id = $1) AND (status = $2) []interface {}{1, 0x1}
2019/09/01 17:02:13 .../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/09/01 17:02:13 .../xorm/session_raw.go:87:queryRow() [I] [SQL] SELECT count(*) FROM "notification" WHERE (user_id = $1) AND (status = $2) []interface {}{1, 0x1}
2019/09/01 17:05:10 ...go-xorm/xorm/rows.go:50:newRows() [I] [SQL] SELECT "id", "repo_id", "interval", "enable_prune", "updated_unix", "next_update_unix" FROM "mirror" WHERE (next_update_unix<=$1) AND (next_update_unix!=0) []interface {}{1567357510}

So the real error is:
2019/09/01 17:02:11 ...ules/context/repo.go:664:func1() [E] GetCommitsCount: dial unix data/caches: connect: no such file or directory
But I created dir "/data/caches" and permissioned it to user: git, and this error still occurs. Any ideas? Perhaps some problem with the memcached container (memcached:1.5.6-alpine) that is also running in this pod?

[holmesb]

I've created a new issue to address the fact finding gitea logs in docker is not intuitive.

[typeless]

I can not think of any clue about the log. Can you have a clean install with the default configurations (do not create app.ini by hand, just let Gitea generate it)?

If that worked, then try to bisect the nuances between the A/B cases.

[holmesb]

Fixed. There was a mismatch between the tcp port memcached was listening on and app.ini setting:

[cache]
HOST     = 127.0.0.1:<PORT>

Thanks @typeless for establishing that it wasn't a problem with the Dockerfile.