Git Hook execution failed with insufficient information in log

Hi folks,

Recently we encounter this issue when pushing to our Monorepo

> git push
remote: GitLab: 500 Internal Server Error
To gitlab.org.com:group/repo.git
 ! [remote rejected]           trunk -> trunk (pre-receive hook declined)

After investigation, we managed to distilled the issue down to this correlation ID

[root@gitaly-2003 gitaly]# grep '01FAFJGFBDC8JAVTYQNYHNZ72J' current | jq '.' > /tmp/fail.log
[root@gitaly-2003 gitaly]# cat /tmp/fail.log
{
  "correlation_id": "01FAFJGFBDC8JAVTYQNYHNZ72J",
  "duration_ms": 60292,
  "error": "500 Internal Server Error",
  "level": "error",
  "method": "POST",
  "msg": "Internal API error",
  "status": 500,
  "time": "2021-07-13T09:18:44.304Z",
  "url": "https://gitlab.org.com/api/v4/internal/allowed"
}
{
  "correlation_id": "01FAFJGFBDC8JAVTYQNYHNZ72J",
  "error": "GitLab: 500 Internal Server Error",
  "grpc.meta.auth_version": "v2",
  "grpc.meta.deadline_type": "none",
  "grpc.method": "PreReceiveHook",
  "grpc.request.fullMethod": "/gitaly.HookService/PreReceiveHook",
  "grpc.request.glProjectPath": "group/repo",
  "grpc.request.glRepository": "project-177",
  "grpc.request.repoPath": "@hashed/8c/d2/8cd2510271575d8430c05368315a87b9c4784c7389a47496080c1e615a2a00b6.git",
  "grpc.request.repoStorage": "gitaly-pool-001",
  "grpc.request.topLevelGroup": "@hashed",
  "grpc.service": "gitaly.HookService",
  "grpc.start_time": "2021-07-13T09:17:44.011Z",
  "level": "warning",
  "msg": "stopping transaction because pre-receive hook failed",
  "peer.address": "@",
  "pid": 3299,
  "span.kind": "server",
  "system": "grpc",
  "time": "2021-07-13T09:18:44.304Z"
}
{
  "correlation_id": "01FAFJGFBDC8JAVTYQNYHNZ72J",
  "grpc.code": "OK",
  "grpc.meta.auth_version": "v2",
  "grpc.meta.deadline_type": "none",
  "grpc.method": "PreReceiveHook",
  "grpc.request.fullMethod": "/gitaly.HookService/PreReceiveHook",
  "grpc.request.glProjectPath": "group/repo",
  "grpc.request.glRepository": "project-177",
  "grpc.request.repoPath": "@hashed/8c/d2/8cd2510271575d8430c05368315a87b9c4784c7389a47496080c1e615a2a00b6.git",
  "grpc.request.repoStorage": "gitaly-pool-001",
  "grpc.request.topLevelGroup": "@hashed",
  "grpc.service": "gitaly.HookService",
  "grpc.start_time": "2021-07-13T09:17:44.011Z",
  "grpc.time_ms": 60293.016,
  "level": "info",
  "msg": "finished streaming call with code OK",
  "peer.address": "@",
  "pid": 3299,
  "span.kind": "server",
  "system": "grpc",
  "time": "2021-07-13T09:18:44.304Z"
}
{
  "correlation_id": "01FAFJGFBDC8JAVTYQNYHNZ72J",
  "diskcache": "01137567-11c0-4a57-ab76-20c62efa68cb",
  "grpc.meta.auth_version": "v2",
  "grpc.meta.client_name": "gitlab-shell",
  "grpc.meta.deadline_type": "none",
  "grpc.method": "SSHReceivePack",
  "grpc.request.fullMethod": "/gitaly.SSHService/SSHReceivePack",
  "grpc.request.glProjectPath": "group/repo",
  "grpc.request.glRepository": "project-177",
  "grpc.request.repoPath": "@hashed/8c/d2/8cd2510271575d8430c05368315a87b9c4784c7389a47496080c1e615a2a00b6.git",
  "grpc.request.repoStorage": "gitaly-pool-001",
  "grpc.request.topLevelGroup": "@hashed",
  "grpc.service": "gitaly.SSHService",
  "grpc.start_time": "2021-07-13T09:17:32.441Z",
  "level": "info",
  "msg": "diskcache state change",
  "peer.address": "10.187.6.25:43350",
  "pid": 3299,
  "remote_ip": "10.197.29.109",
  "span.kind": "server",
  "system": "grpc",
  "time": "2021-07-13T09:18:44.329Z",
  "user_id": "user-289",
  "username": "user-1"
}
{
  "correlation_id": "01FAFJGFBDC8JAVTYQNYHNZ72J",
  "grpc.code": "OK",
  "grpc.meta.auth_version": "v2",
  "grpc.meta.client_name": "gitlab-shell",
  "grpc.meta.deadline_type": "none",
  "grpc.method": "SSHReceivePack",
  "grpc.request.fullMethod": "/gitaly.SSHService/SSHReceivePack",
  "grpc.request.glProjectPath": "group/repo",
  "grpc.request.glRepository": "project-177",
  "grpc.request.repoPath": "@hashed/8c/d2/8cd2510271575d8430c05368315a87b9c4784c7389a47496080c1e615a2a00b6.git",
  "grpc.request.repoStorage": "gitaly-pool-001",
  "grpc.request.topLevelGroup": "@hashed",
  "grpc.service": "gitaly.SSHService",
  "grpc.start_time": "2021-07-13T09:17:32.441Z",
  "grpc.time_ms": 71888.125,
  "level": "info",
  "msg": "finished streaming call with code OK",
  "peer.address": "10.187.6.25:43350",
  "pid": 3299,
  "remote_ip": "10.197.29.109",
  "span.kind": "server",
  "system": "grpc",
  "time": "2021-07-13T09:18:44.329Z",
  "user_id": "user-289",
  "username": "user-1"
}

It took us a bit to realize that the issue was not with our PreReceive hook like the git-push message said, but with Gitaly authorization call against Gitlab Rails (and Gitlab Rails error out with 500).

https://sourcegraph.com/gitlab.com/gitlab-org/gitaly@v13.10.4/-/blob/internal/gitaly/hook/prereceive.go?L129

I will be raising a separate issue to Gitlab project about the rails authentication issue, but could we please be more clear in logging and letting the user know that this was not caused by our Server Git Hook execution but by Gitlab Rails?