backup fails with "Gitlab::Git::CommandError: 4:Deadline Exceeded"
https://gitlab.zendesk.com/agent/tickets/95969
As requested in gitlab-ce#43985 I'm opening this issue regarding backup failure with this "Deadline Exceeded" error. We have a customer who has been unable to get a backup on his system for weeks now due to this issue. He is understandably worried. Is there anything more we need to get to be able to investigate this issue?
** Execute gitlab:backup:repo:create
rake aborted!
Gitlab::Git::CommandError: 4:Deadline Exceeded
/opt/gitlab/embedded/service/gitlab-rails/lib/gitlab/git/repository.rb:1401:in `rescue in gitaly_migrate'
/opt/gitlab/embedded/service/gitlab-rails/lib/gitlab/git/repository.rb:1394:in `gitaly_migrate'
/opt/gitlab/embedded/service/gitlab-rails/lib/gitlab/git/repository.rb:1560:in `uncached_has_local_branches?'
/opt/gitlab/embedded/service/gitlab-rails/lib/gitlab/git/repository.rb:240:in `block in has_local_branches?'
...
Caused by:
GRPC::DeadlineExceeded: 4:Deadline Exceeded
/opt/gitlab/embedded/lib/ruby/gems/2.3.0/gems/grpc-1.10.0-x86_64-linux/src/ruby/lib/grpc/generic/active_call.rb:31:in `check_status'
/opt/gitlab/embedded/lib/ruby/gems/2.3.0/gems/grpc-1.10.0-x86_64-linux/src/ruby/lib/grpc/generic/active_call.rb:180:in `attach_status_results_and_complete_call'
/opt/gitlab/embedded/lib/ruby/gems/2.3.0/gems/grpc-1.10.0-x86_64-linux/src/ruby/lib/grpc/generic/active_call.rb:372:in `request_response'
/opt/gitlab/embedded/lib/ruby/gems/2.3.0/gems/grpc-1.10.0-x86_64-linux/src/ruby/lib/grpc/generic/client_stub.rb:178:in `block in request_response'
/opt/gitlab/embedded/lib/ruby/gems/2.3.0/gems/grpc-1.10.0-x86_64-linux/src/ruby/lib/grpc/generic/interceptors.rb:170:in `intercept!'
/opt/gitlab/embedded/lib/ruby/gems/2.3.0/gems/grpc-1.10.0-x86_64-linux/src/ruby/lib/grpc/generic/client_stub.rb:177:in `request_response'
/opt/gitlab/embedded/lib/ruby/gems/2.3.0/gems/grpc-1.10.0-x86_64-linux/src/ruby/lib/grpc/generic/service.rb:170:in `block (3 levels) in rpc_stub_class'
/opt/gitlab/embedded/service/gitlab-rails/lib/gitlab/gitaly_client.rb:134:in `call'
/opt/gitlab/embedded/service/gitlab-rails/lib/gitlab/gitaly_client/repository_service.rb:79:in `has_local_branches?'
In his gitaly logs he sees this (with real group and project names anonymized):
2018-05-09_01:38:47.99469 time="2018-05-09T01:38:47Z" level=info msg="finished unary call" grpc.code=OK grpc.meta.call_site=repository_exists grpc.meta.client_name=gitlab-web grpc.method=RepositoryExists grpc.request.glRepository=project-87 grpc.request.repoPath=groupname/projectname.git grpc.request.repoStorage=default grpc.request.topLevelGroup=groupname grpc.service=gitaly.RepositoryService grpc.time_ms=0 peer.address=@ span.kind=server system=grpc2018-05-09_01:38:47.99871 time="2018-05-09T01:38:47Z" level=info msg=spawn args="[/opt/gitlab/embedded/bin/git --git-dir /var/opt/gitlab/git-data/repositories/groupname/projectname.git for-each-ref --count=1 refs/heads]" grpc.meta.call_site=has_local_branches grpc.meta.client_name=gitlab-web grpc.method=HasLocalBranches grpc.request.glRepository=project-87 grpc.request.repoPath=groupname/projectname.git grpc.request.repoStorage=default grpc.request.topLevelGroup=groupname grpc.service=gitaly.RepositoryService path=/opt/gitlab/embedded/bin/git peer.address=@ pid=32503 span.kind=server system=grpc
2018-05-09_01:38:58.44768 time="2018-05-09T01:38:58Z" level=info msg="spawn complete" args="[/opt/gitlab/embedded/bin/git --git-dir /var/opt/gitlab/git-data/repositories/groupname/projectname.git for-each-ref --count=1 refs/heads]" command.exitCode=-1 command.inblock=8 command.maxrss=22836 command.oublock=0 command.real_time_ms=10449.380272 command.system_time_ms=2.068 command.user_time_ms=1.034 grpc.meta.call_site=has_local_branches grpc.meta.client_name=gitlab-web grpc.method=HasLocalBranches grpc.request.glRepository=project-87 grpc.request.repoPath=groupname/projectname.git grpc.request.repoStorage=default grpc.request.topLevelGroup=groupname grpc.service=gitaly.RepositoryService path=/opt/gitlab/embedded/bin/git peer.address=@ pid=32503 span.kind=server system=grpc
2018-05-09_01:38:58.44772 time="2018-05-09T01:38:58Z" level=info msg="finished unary call" error="rpc error: code = Canceled desc = rpc error: code = Internal desc = HasLocalBranches: cmd wait: signal: terminated" grpc.code=Canceled grpc.meta.call_site=has_local_branches grpc.meta.client_name=gitlab-web grpc.method=HasLocalBranches grpc.request.glRepository=project-87 grpc.request.repoPath=groupname/projectname.git grpc.request.repoStorage=default grpc.request.topLevelGroup=groupname grpc.service=gitaly.RepositoryService grpc.time_ms=10449 peer.address=@ span.kind=server system=grpc
2018-05-09_01:38:58.44774 time="2018-05-09T01:38:58Z" level=info msg="grpc: Server.processUnaryRPC failed to write status: connection error: desc = "transport is closing"" system=system