Gerrit 2.11.3: "internal error"; "Error inserting change/patchset"

[w...@extrahop.com]

We have a Gerrit server that's been running since June, currently on version 2.11.3. We've been seeing this error on and off ever since, always on the same project (which is by far the largest project in our organization).

To reproduce:

1. A user attempts to upload multiple commits for review:

$ git review
You are about to submit multiple commits. This is expected if you are
submitting a commit that is dependent on one or more in-review
commits. Otherwise you should consider squashing your changes into one
commit before submitting.

The outstanding commits are:

<...>

Do you really want to submit the above commits?
Type 'yes' to confirm, other to cancel: yes
remote:
remote: Processing changes: updated: 7, refs: 11, done
*remote: error: internal error while processing changes*
*To ssh://<our-gerrit>:29418/<our-project>
<http://<our-gerrit>:29418/<our-project>&gt;&#39;*
* ! [remote rejected] HEAD -> refs/<...> (internal
error)*
*error: failed to push some refs to
'ssh://<our-gerrit>:29418/<our-project>
<http://<our-gerrit>:29418/<our-project>&gt;&#39;*

2. In the logs, a message like this shows up:

[2015-11-25 00:13:40,481] ERROR com.google.gerrit.server.git.ReceiveCommits : Can't insert change/patchset for <our-project> com.google.gerrit.server.git.InsertException: Error inserting change/patchset at com.google.gerrit.server.git.ReceiveCommits$1.apply(ReceiveCommits.java:269) at com.google.gerrit.server.git.ReceiveCommits$1.apply(ReceiveCommits.java:260) at com.google.common.util.concurrent.Futures$MappingCheckedFuture.mapException(Futures.java:1809) at com.google.common.util.concurrent.AbstractCheckedFuture.checkedGet(AbstractCheckedFuture.java:85) at com.google.gerrit.server.git.ReceiveCommits.insertChangesAndPatchSets(ReceiveCommits.java:803) at com.google.gerrit.server.git.ReceiveCommits.processCommands(ReceiveCommits.java:588) at com.google.gerrit.server.git.AsyncReceiveCommits$Worker.run(AsyncReceiveCommits.java:89) at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471) at com.google.gerrit.server.util.RequestScopePropagator$5.call(RequestScopePropagator.java:222) at com.google.gerrit.server.util.RequestScopePropagator$4.call(RequestScopePropagator.java:201) at com.google.gerrit.server.util.ThreadLocalRequestScopePropagator$1.call(ThreadLocalRequestScopePropagator.java:55) at com.google.gerrit.server.util.RequestScopePropagator$1.call(RequestScopePropagator.java:98) at com.google.gerrit.server.util.RequestScopePropagator$2.run(RequestScopePropagator.java:131) at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471) at java.util.concurrent.FutureTask.run(FutureTask.java:262) at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:178) at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:292) at com.google.gerrit.server.git.WorkQueue$Task.run(WorkQueue.java:379) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) at java.lang.Thread.run(Thread.java:745) Caused by: java.util.concurrent.ExecutionException: java.io.IOException: java.lang.InterruptedException at java.util.concurrent.FutureTask.report(FutureTask.java:122) at java.util.concurrent.FutureTask.get(FutureTask.java:188) at com.google.common.util.concurrent.ForwardingFuture.get(ForwardingFuture.java:63) at com.google.common.util.concurrent.AbstractCheckedFuture.checkedGet(AbstractCheckedFuture.java:78) ... 17 more Caused by: java.io.IOException: java.lang.InterruptedException at com.google.gerrit.lucene.LuceneChangeIndex.replace(LuceneChangeIndex.java:318) at com.google.gerrit.server.index.ChangeIndexer$IndexTask.call(ChangeIndexer.java:238) at com.google.gerrit.server.index.ChangeIndexer$IndexTask.call(ChangeIndexer.java:198) at java.util.concurrent.FutureTask.run(FutureTask.java:262) at com.google.common.util.concurrent.MoreExecutors$DirectExecutorService.execute(MoreExecutors.java:299) at java.util.concurrent.AbstractExecutorService.submit(AbstractExecutorService.java:132) at com.google.common.util.concurrent.AbstractListeningExecutorService.submit(AbstractListeningExecutorService.java:58) at com.google.gerrit.server.index.ChangeIndexer.submit(ChangeIndexer.java:195) at com.google.gerrit.server.index.ChangeIndexer.indexAsync(ChangeIndexer.java:123) at com.google.gerrit.server.git.ReceiveCommits$ReplaceRequest.insertPatchSet(ReceiveCommits.java:2222) at com.google.gerrit.server.git.ReceiveCommits$ReplaceRequest$1.call(ReceiveCommits.java:2059) at com.google.gerrit.server.git.ReceiveCommits$ReplaceRequest$1.call(ReceiveCommits.java:2052) at com.google.gerrit.server.util.RequestScopePropagator$1.call(RequestScopePropagator.java:96) at java.util.concurrent.FutureTask.run(FutureTask.java:262) at com.google.common.util.concurrent.MoreExecutors$DirectExecutorService.execute(MoreExecutors.java:299) at java.util.concurrent.AbstractExecutorService.submit(AbstractExecutorService.java:132) at com.google.common.util.concurrent.AbstractListeningExecutorService.submit(AbstractListeningExecutorService.java:58) at com.google.gerrit.server.git.ReceiveCommits$ReplaceRequest.insertPatchSet(ReceiveCommits.java:2051) at com.google.gerrit.server.git.ReceiveCommits.insertChangesAndPatchSets(ReceiveCommits.java:794) ... 16 more Caused by: java.lang.InterruptedException at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireSharedInterruptibly(AbstractQueuedSynchronizer.java:1301) at com.google.common.util.concurrent.AbstractFuture$Sync.get(AbstractFuture.java:285) at com.google.common.util.concurrent.AbstractFuture.get(AbstractFuture.java:116) at com.google.gerrit.lucene.LuceneChangeIndex.replace(LuceneChangeIndex.java:309) ... 34 more

3. The changes don't show up in the project.

We see many instances of this since our server was deployed in late June:

$ gunzip --stdout error_log.2015-* | grep "Can't insert change/patchset"

[2015-06-23 02:11:48,268] ERROR com.google.gerrit.server.git.ReceiveCommits : Can't insert change/patchset for <our-project>

[2015-06-24 21:15:40,536] ERROR com.google.gerrit.server.git.ReceiveCommits : Can't insert change/patchset for <our-project>

[2015-07-02 18:13:27,858] ERROR com.google.gerrit.server.git.ReceiveCommits : Can't insert change/patchset for <our-project>

[2015-07-10 15:22:02,236] ERROR com.google.gerrit.server.git.ReceiveCommits : Can't insert change/patchset for <our-project>

[2015-07-21 21:11:38,155] ERROR com.google.gerrit.server.git.ReceiveCommits : Can't insert change/patchset for <our-project>

[2015-07-22 15:46:59,775] ERROR com.google.gerrit.server.git.ReceiveCommits : Can't insert change/patchset for <our-project>

[2015-07-24 17:23:48,614] ERROR com.google.gerrit.server.git.ReceiveCommits : Can't insert change/patchset for <our-project>

[2015-07-31 00:29:41,113] ERROR com.google.gerrit.server.git.ReceiveCommits : Can't insert change/patchset for <our-project>

[2015-07-31 21:31:06,313] ERROR com.google.gerrit.server.git.ReceiveCommits : Can't insert change/patchset for <our-project>

[2015-08-04 00:31:56,219] ERROR com.google.gerrit.server.git.ReceiveCommits : Can't insert change/patchset for <our-project>

[2015-08-05 01:30:15,932] ERROR com.google.gerrit.server.git.ReceiveCommits : Can't insert change/patchset for <our-project>

[2015-08-05 18:16:01,981] ERROR com.google.gerrit.server.git.ReceiveCommits : Can't insert change/patchset for <our-project>

[2015-08-05 18:34:51,218] ERROR com.google.gerrit.server.git.ReceiveCommits : Can't insert change/patchset for <our-project>

[2015-08-14 19:10:31,230] ERROR com.google.gerrit.server.git.ReceiveCommits : Can't insert change/patchset for <our-project>

[2015-08-14 22:09:40,207] ERROR com.google.gerrit.server.git.ReceiveCommits : Can't insert change/patchset for <our-project>

[2015-08-14 22:13:18,093] ERROR com.google.gerrit.server.git.ReceiveCommits : Can't insert change/patchset for <our-project>

[2015-08-15 01:26:06,102] ERROR com.google.gerrit.server.git.ReceiveCommits : Can't insert change/patchset for <our-project>

[2015-08-15 01:31:05,463] ERROR com.google.gerrit.server.git.ReceiveCommits : Can't insert change/patchset for <our-project>

[2015-08-17 15:35:11,273] ERROR com.google.gerrit.server.git.ReceiveCommits : Can't insert change/patchset for <our-project>

[2015-08-17 17:40:30,602] ERROR com.google.gerrit.server.git.ReceiveCommits : Can't insert change/patchset for <our-project>

[2015-08-17 18:06:39,183] ERROR com.google.gerrit.server.git.ReceiveCommits : Can't insert change/patchset for <our-project>

[2015-08-17 22:12:13,026] ERROR com.google.gerrit.server.git.ReceiveCommits : Can't insert change/patchset for <our-project>

[2015-08-17 23:05:28,090] ERROR com.google.gerrit.server.git.ReceiveCommits : Can't insert change/patchset for <our-project>

[2015-08-17 23:14:10,158] ERROR com.google.gerrit.server.git.ReceiveCommits : Can't insert change/patchset for <our-project>

[2015-08-17 23:18:50,345] ERROR com.google.gerrit.server.git.ReceiveCommits : Can't insert change/patchset for <our-project>

[2015-09-01 21:36:35,756] ERROR com.google.gerrit.server.git.ReceiveCommits : Can't insert change/patchset for <our-project>

[2015-09-01 21:39:02,984] ERROR com.google.gerrit.server.git.ReceiveCommits : Can't insert change/patchset for <our-project>

[2015-09-01 22:01:37,314] ERROR com.google.gerrit.server.git.ReceiveCommits : Can't insert change/patchset for <our-project>

[2015-09-02 09:57:03,104] ERROR com.google.gerrit.server.git.ReceiveCommits : Can't insert change/patchset for <our-project>

[2015-09-15 17:37:53,682] ERROR com.google.gerrit.server.git.ReceiveCommits : Can't insert change/patchset for <our-project>

[2015-09-25 22:49:46,131] ERROR com.google.gerrit.server.git.ReceiveCommits : Can't insert change/patchset for <our-project>

[2015-10-02 01:32:50,953] ERROR com.google.gerrit.server.git.ReceiveCommits : Can't insert change/patchset for <our-project>

[2015-10-20 18:25:13,541] ERROR com.google.gerrit.server.git.ReceiveCommits : Can't insert change/patchset for <our-project>

[2015-10-26 23:44:21,305] ERROR com.google.gerrit.server.git.ReceiveCommits : Can't insert change/patchset for <our-project>

[2015-11-12 20:10:43,089] ERROR com.google.gerrit.server.git.ReceiveCommits : Can't insert change/patchset for <our-project>

[2015-11-13 19:29:45,722] ERROR com.google.gerrit.server.git.ReceiveCommits : Can't insert change/patchset for <our-project>

[2015-11-19 19:09:39,487] ERROR com.google.gerrit.server.git.ReceiveCommits : Can't insert change/patchset for <our-project>

[2015-11-23 23:22:34,329] ERROR com.google.gerrit.server.git.ReceiveCommits : Can't insert change/patchset for <our-project>

[2015-11-24 17:49:57,001] ERROR com.google.gerrit.server.git.ReceiveCommits : Can't insert change/patchset for <our-project>

[2015-11-24 23:03:44,231] ERROR com.google.gerrit.server.git.ReceiveCommits : Can't insert change/patchset for <our-project>

Does anyone have any ideas where I might start troubleshooting? Let me know what other information I can provide that might help.

[Marco Miller]

Hi,

We also experienced the same error a bit more than a month ago using 2.11.3 back then.
Our case was not about multiple commits or changes but just one.
It happened only once to our "explicit" knowledge; we might have missed other /more "silent" occurrences.

Initial troubleshooting led to noticing that db.close (=> null 'conn') was called before db.rollback,
as per this trace you and I got (cf. ReceiveCommits).

We cannot explain why such premature closing can happen yet.
The aforementioned db reference is the "global" (request?) one, i.e.,
differs from the local 'db' object(s) found elsewhere in that class or around.

Let's keep each other (well, community) informed,
should either one of us make progress on this =)
-And thx for bringing this up then!
/Marco

[w...@extrahop.com]

I tried upping our database poolLimit from the default (8) to 16. It may have resolved another error we were seeing, but this one cropped up again.

[w...@extrahop.com]

This issue is still plaguing us. Does anybody have any suggestions?

[w...@extrahop.com]

I took another step yesterday:

receive.changeUpdateThreads

Number of threads to perform change creation or patch set updates concurrently. Each thread uses its own database connection from the database connection pool, and if all threads are busy then main receive thread will also perform a change creation or patch set update.

Defaults to 1, using only the main receive thread. This feature is for databases with very high latency that can benefit from concurrent operations when multiple changes are impacted at once.

I noticed the stack trace bubbling up through a lot of concurrency code, and so I upped this setting from the default 1 to 8, essentially throwing more threads at the problem. According to one user, this "fixed" the problem: they still get an error, but it's changed from "internal error" to "internal server error," and the error that I'm seeing in the server-side logs has changed, as well:

[2015-12-10 23:29:41,624] ERROR com.google.gerrit.server.git.ReceiveCommits : Can't insert change/patchset for <our-project>
com.google.gerrit.server.git.InsertException: Error inserting change/patchset
        at com.google.gerrit.server.git.ReceiveCommits$1.apply(ReceiveCommits.java:269)
        at com.google.gerrit.server.git.ReceiveCommits$1.apply(ReceiveCommits.java:260)
        at com.google.common.util.concurrent.Futures$MappingCheckedFuture.mapException(Futures.java:1809)
        at com.google.common.util.concurrent.AbstractCheckedFuture.checkedGet(AbstractCheckedFuture.java:81)
        at com.google.gerrit.server.git.ReceiveCommits.insertChangesAndPatchSets(ReceiveCommits.java:803)
        at com.google.gerrit.server.git.ReceiveCommits.processCommands(ReceiveCommits.java:588)
        at com.google.gerrit.server.git.AsyncReceiveCommits$Worker.run(AsyncReceiveCommits.java:89)
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
        at com.google.gerrit.server.util.RequestScopePropagator$5.call(RequestScopePropagator.java:222)
        at com.google.gerrit.server.util.RequestScopePropagator$4.call(RequestScopePropagator.java:201)
        at com.google.gerrit.server.util.ThreadLocalRequestScopePropagator$1.call(ThreadLocalRequestScopePropagator.java:55)
        at com.google.gerrit.server.util.RequestScopePropagator$1.call(RequestScopePropagator.java:98)
        at com.google.gerrit.server.util.RequestScopePropagator$2.run(RequestScopePropagator.java:131)
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
        at java.util.concurrent.FutureTask.run(FutureTask.java:262)
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:178)
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:292)
        at com.google.gerrit.server.git.WorkQueue$Task.run(WorkQueue.java:379)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
        at java.lang.Thread.run(Thread.java:745)
Caused by: java.lang.InterruptedException
        at java.util.concurrent.FutureTask.awaitDone(FutureTask.java:400)
        at java.util.concurrent.FutureTask.get(FutureTask.java:187)
        at com.google.common.util.concurrent.ForwardingFuture.get(ForwardingFuture.java:63)
        at com.google.common.util.concurrent.AbstractCheckedFuture.checkedGet(AbstractCheckedFuture.java:78)
        ... 17 more
[2015-12-10 23:29:41,625] WARN  com.google.gerrit.server.git.AsyncReceiveCommits : Error in ReceiveCommits while processing changes for project <our-project>
java.util.concurrent.ExecutionException: (timeout 82ms, cancelled)
        at com.google.gerrit.server.git.MultiProgressMonitor.waitFor(MultiProgressMonitor.java:255)
        at com.google.gerrit.server.git.AsyncReceiveCommits.onPreReceive(AsyncReceiveCommits.java:162)
        at org.eclipse.jgit.transport.ReceivePack.service(ReceivePack.java:208)
        at org.eclipse.jgit.transport.ReceivePack.receive(ReceivePack.java:161)
        at com.google.gerrit.sshd.commands.Receive.runImpl(Receive.java:115)
        at com.google.gerrit.sshd.AbstractGitCommand.service(AbstractGitCommand.java:101)
        at com.google.gerrit.sshd.AbstractGitCommand.access$000(AbstractGitCommand.java:32)
        at com.google.gerrit.sshd.AbstractGitCommand$1.run(AbstractGitCommand.java:70)
        at com.google.gerrit.sshd.BaseCommand$TaskThunk.run(BaseCommand.java:445)
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
        at java.util.concurrent.FutureTask.run(FutureTask.java:262)
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:178)
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:292)
        at com.google.gerrit.server.git.WorkQueue$Task.run(WorkQueue.java:379)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
        at java.lang.Thread.run(Thread.java:745)
Caused by: java.util.concurrent.CancellationException
        at java.util.concurrent.FutureTask.report(FutureTask.java:121)
        at java.util.concurrent.FutureTask.get(FutureTask.java:202)
        at com.google.gerrit.server.git.WorkQueue$Task.get(WorkQueue.java:352)
        at com.google.gerrit.server.git.MultiProgressMonitor.waitFor(MultiProgressMonitor.java:251) 

        ... 16 more 

Lots of these cropping up, each with a slightly different timeout:

$ grep "java.util.concurrent.ExecutionException: (timeout" error_log.2015-12-10 
java.util.concurrent.ExecutionException: (timeout 53ms, cancelled)
java.util.concurrent.ExecutionException: (timeout 65ms, cancelled)
java.util.concurrent.ExecutionException: (timeout 69ms, cancelled)
java.util.concurrent.ExecutionException: (timeout 70ms, cancelled)
java.util.concurrent.ExecutionException: (timeout 73ms, cancelled)
java.util.concurrent.ExecutionException: (timeout 69ms, cancelled)
java.util.concurrent.ExecutionException: (timeout 82ms, cancelled)

On Wednesday, November 25, 2015 at 9:20:34 AM UTC-8, w...@extrahop.com wrote:

[w...@extrahop.com]

The issue may finally be resolved:

receive.timeout

Overall timeout on the time taken to process the change data in received packs. Only includes the time processing Gerrit changes and updating references, not the time to index the pack. Values can be specified using standard time unit abbreviations ('ms', 'sec', 'min', etc.).

Default is 2 minutes. If no unit is specified, milliseconds is assumed.

I checked with the user, and it was taking approximately two minutes before it errored out on his end. Increased this timeout to 5 minutes, and the error hasn't been back for several days.

...but really? >2 minutes to submit a batch of changes? Oh well; that's a separate problem.