pushes failing "unable to finish processing" in git-receive-pack

[euph...@gmail.com]

We're on Gerrit 3.3.5, and we started seeing a strange problem with some pushes failing, beginning a few days ago.  I've expunged identifying information in the output below so as to not antagonize our security group; those aren't the real user, repo, branch, etc. names.  When one of the offending commits is pushed, it will sit there in "Processing changes" for four minutes, then it hits the Gerrit server's four minute receive.timeout and stops.  The client and the Gerrit server are sitting in the same server room, perhaps a few feet apart from one another, on a 10gbit network.  Latency and bandwidth should not be an issue.  This is only a 6.45kb push, so I sincerely doubt if it's struggling to move the entire commit across the wire in those four minutes (it's not like it's trying to move a gigabyte-sized commit across the WAN, or something like that).  What's really strange is that while this is running, I can log into the same client system, create another commit for the same repo and branch, and push it in without any difficulties.  If we try again to push the commit that failed, it will hit the four minute timeout and fail again.  Re-try all you want, that commit won't push.  But I can create all the test commits I like and push them in for the same repo and branch.  If I take the diff of this commit, log into a different client, clone the repo, apply the patch, create a new commit, and try the push again, this push will fail there as well.

I'm starting to wonder if there's something about the content of the commit that's causing git-receive-pack to fail.  Is there some way to get some more detail on what's going wrong in git-receive-pack on the server side?  "unable to finish processing" isn't really giving me enough of a hint as to what's going wrong.  If there's something about the error message that I'm missing, please tell me.

thanks,

--Andrew

someuser@somehost:~/somerepo$ git push origin HEAD:refs/for/release/somebranch

Counting objects: 15, done.

Delta compression using up to 8 threads.

Compressing objects: 100% (15/15), done.

Writing objects: 100% (15/15), 6.45 KiB | 6.45 MiB/s, done.

Total 15 (delta 14), reused 0 (delta 0)

remote: Resolving deltas: 100% (14/14)

remote: Processing changes: done    

remote: error: internal error

To ssh://gerrit.somedomain.com:29418/somerepo

 ! [remote rejected]   HEAD -> refs/for/release/somebranch (internal error)

error: failed to push some refs to 'ssh://some...@gerrit.somedomain.com:29418/somerepo'

If I then go pull up the corresponding error messages from error_log, I see this:

[2021-08-20T21:34:33.669-07:00] [SSH git-receive-pack /somerepo (someuser)] WARN  com.google.gerrit.server.git.MultiProgressMonitor : MultiProgressMonitor worker killed after 240134ms: (timeout 134ms, cancelled)

[2021-08-20T21:34:33.671-07:00] [SSH git-receive-pack /somerepo (someuser)] WARN  com.google.gerrit.server.git.MultiProgressMonitor : unable to finish processing

java.util.concurrent.CancellationException

        at java.base/java.util.concurrent.FutureTask.report(FutureTask.java:121)

        at java.base/java.util.concurrent.FutureTask.get(FutureTask.java:205)

        at com.google.gerrit.server.git.WorkQueue$Task.get(WorkQueue.java:583)

        at com.google.gerrit.server.git.MultiProgressMonitor.waitFor(MultiProgressMonitor.java:244)

        at com.google.gerrit.server.git.receive.AsyncReceiveCommits.preReceive(AsyncReceiveCommits.java:381)

        at com.google.gerrit.server.git.receive.AsyncReceiveCommits.lambda$asHook$0(AsyncReceiveCommits.java:332)

        at org.eclipse.jgit.transport.ReceivePack.service(ReceivePack.java:2206)

        at org.eclipse.jgit.transport.ReceivePack.receive(ReceivePack.java:2120)

        at com.google.gerrit.sshd.commands.Receive.runImpl(Receive.java:98)

        at com.google.gerrit.sshd.AbstractGitCommand.service(AbstractGitCommand.java:108)

        at com.google.gerrit.sshd.AbstractGitCommand$1.run(AbstractGitCommand.java:73)

        at com.google.gerrit.sshd.BaseCommand$TaskThunk.run(BaseCommand.java:488)

        at com.google.gerrit.server.logging.LoggingContextAwareRunnable.run(LoggingContextAwareRunnable.java:103)

        at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)

        at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)

        at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304)

        at com.google.gerrit.server.git.WorkQueue$Task.run(WorkQueue.java:612)

        at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)

        at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)

        at java.base/java.lang.Thread.run(Thread.java:834)

[2021-08-20T21:34:33.672-07:00] [SSH git-receive-pack /somerepo (someuser)] ERROR com.google.gerrit.server.git.receive.AsyncReceiveCommits : error while processing push

java.util.concurrent.CancellationException

        at java.base/java.util.concurrent.FutureTask.report(FutureTask.java:121)

        at java.base/java.util.concurrent.FutureTask.get(FutureTask.java:205)

        at com.google.gerrit.server.git.WorkQueue$Task.get(WorkQueue.java:583)

        at com.google.gerrit.server.git.MultiProgressMonitor.waitFor(MultiProgressMonitor.java:244)

        at com.google.gerrit.server.git.receive.AsyncReceiveCommits.preReceive(AsyncReceiveCommits.java:381)

        at com.google.gerrit.server.git.receive.AsyncReceiveCommits.lambda$asHook$0(AsyncReceiveCommits.java:332)

        at org.eclipse.jgit.transport.ReceivePack.service(ReceivePack.java:2206)

        at org.eclipse.jgit.transport.ReceivePack.receive(ReceivePack.java:2120)

        at com.google.gerrit.sshd.commands.Receive.runImpl(Receive.java:98)

        at com.google.gerrit.sshd.AbstractGitCommand.service(AbstractGitCommand.java:108)

        at com.google.gerrit.sshd.AbstractGitCommand$1.run(AbstractGitCommand.java:73)

        at com.google.gerrit.sshd.BaseCommand$TaskThunk.run(BaseCommand.java:488)

        at com.google.gerrit.server.logging.LoggingContextAwareRunnable.run(LoggingContextAwareRunnable.java:103)

        at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)

        at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)

        at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304)

        at com.google.gerrit.server.git.WorkQueue$Task.run(WorkQueue.java:612)

        at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)

        at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)

        at java.base/java.lang.Thread.run(Thread.java:834)

[Matthias Sohn]

On Sat, Aug 21, 2021 at 7:25 AM euph...@gmail.com <euph...@gmail.com> wrote:

We're on Gerrit 3.3.5, and we started seeing a strange problem with some pushes failing, beginning a few days ago.  I've expunged identifying information in the output below so as to not antagonize our security group; those aren't the real user, repo, branch, etc. names.  When one of the offending commits is pushed, it will sit there in "Processing changes" for four minutes, then it hits the Gerrit server's four minute receive.timeout and stops.  The client and the Gerrit server are sitting in the same server room, perhaps a few feet apart from one another, on a 10gbit network.  Latency and bandwidth should not be an issue.  This is only a 6.45kb push, so I sincerely doubt if it's struggling to move the entire commit across the wire in those four minutes (it's not like it's trying to move a gigabyte-sized commit across the WAN, or something like that).  What's really strange is that while this is running, I can log into the same client system, create another commit for the same repo and branch, and push it in without any difficulties.  If we try again to push the commit that failed, it will hit the four minute timeout and fail again.  Re-try all you want, that commit won't push.  But I can create all the test commits I like and push them in for the same repo and branch.  If I take the diff of this commit, log into a different client, clone the repo, apply the patch, create a new commit, and try the push again, this push will fail there as well.

I'm starting to wonder if there's something about the content of the commit that's causing git-receive-pack to fail.  Is there some way to get some more detail on what's going wrong in git-receive-pack on the server side?  "unable to finish processing" isn't really giving me enough of a hint as to what's going wrong.  If there's something about the error message that I'm missing, please tell me.

• Create a couple of thread dumps while the push is hanging. They should reveal where it's hanging.
• Try to trace that push [1] and check the trace output in the error_log.
• If you are using the uploadvalidator [2] or hooks [3] plugin, disable or remove it in order to check if it's the cause

[1] https://gerrit-documentation.storage.googleapis.com/Documentation/3.3.6/user-request-tracing.html

[2] https://gerrit.googlesource.com/plugins/uploadvalidator/+/refs/heads/stable-3.3

[3] https://gerrit.googlesource.com/plugins/hooks/+/refs/heads/master

-Matthias

 

--
--
To unsubscribe, email repo-discuss...@googlegroups.com
More info at http://groups.google.com/group/repo-discuss?hl=en

---
You received this message because you are subscribed to the Google Groups "Repo and Gerrit Discussion" group.
To unsubscribe from this group and stop receiving emails from it, send an email to repo-discuss...@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/repo-discuss/a099d1f7-2ca8-49ca-8d6e-764ac03c879bn%40googlegroups.com.

[euph...@gmail.com]

On Saturday, August 21, 2021 at 1:53:06 AM UTC-7 Matthias Sohn wrote:

On Sat, Aug 21, 2021 at 7:25 AM euph...@gmail.com <euph...@gmail.com> wrote:

We're on Gerrit 3.3.5, and we started seeing a strange problem with some pushes failing, beginning a few days ago.  I've expunged identifying information in the output below so as to not antagonize our security group; those aren't the real user, repo, branch, etc. names.  When one of the offending commits is pushed, it will sit there in "Processing changes" for four minutes, then it hits the Gerrit server's four minute receive.timeout and stops.  The client and the Gerrit server are sitting in the same server room, perhaps a few feet apart from one another, on a 10gbit network.  Latency and bandwidth should not be an issue.  This is only a 6.45kb push, so I sincerely doubt if it's struggling to move the entire commit across the wire in those four minutes (it's not like it's trying to move a gigabyte-sized commit across the WAN, or something like that).  What's really strange is that while this is running, I can log into the same client system, create another commit for the same repo and branch, and push it in without any difficulties.  If we try again to push the commit that failed, it will hit the four minute timeout and fail again.  Re-try all you want, that commit won't push.  But I can create all the test commits I like and push them in for the same repo and branch.  If I take the diff of this commit, log into a different client, clone the repo, apply the patch, create a new commit, and try the push again, this push will fail there as well.

I'm starting to wonder if there's something about the content of the commit that's causing git-receive-pack to fail.  Is there some way to get some more detail on what's going wrong in git-receive-pack on the server side?  "unable to finish processing" isn't really giving me enough of a hint as to what's going wrong.  If there's something about the error message that I'm missing, please tell me.

• Create a couple of thread dumps while the push is hanging. They should reveal where it's hanging.
• Try to trace that push [1] and check the trace output in the error_log.

I hadn't seen that trace option before.  As soon as I added a "-o trace" to my push, the culprit was immediately made clear.  We're getting stuck in the its-jira plugin, which makes sense because we're having some problems with our Jira server at the moment.  We just hadn't realized these push failures were related.  We're probably seeing inconsistent behavior between different pushes because of the different Jira issue IDs in the different commit messages.  I know we're rebuilding our Jira indexes at the moment, so the pushes have probably been failing for the commits with Jira issue IDs in their commit messages that correspond to Jira issues that weren't indexed at the time its-jira tried to query our Jira server.  If I turn off the Jira integration for the repo I'm trying to push to and retry one of the failed pushes, the push succeeds immediately.  So we've got a root cause, a real solution (let the Jira reindex finish), and a workaround if we absolutely need it (turn off the Jira integration temporarily if one of these pushes is time-critical).

• If you are using the uploadvalidator [2] or hooks [3] plugin, disable or remove it in order to check if it's the cause

Good point!  I tried disabling these first (before I tried your suggestion to trace the push), but that made no difference (no surprise, given the results of the trace).  I should probably take the time to review the installed plugins and disable the ones we're not using.  We only have hooks installed because it's part of core, and uploadvalidator because it's included in the .rpm from GerritForge, but that doesn't mean they should be left enabled to potentially cause problems.

Thank you very much for your help.

--Andrew