Description Thomas Dräbing 2022-04-12 02:41:52 EDT

For some select repositories in our Gerrit instance we regularly found this stacktrace for failed fetches:

java.lang.IllegalStateException: Timer already terminated:[callingThread=Thread[SSH git-upload-pack /project.git (user),1,main], deadline=0, terminated=true]
	at org.eclipse.jgit.util.io.InterruptTimer.begin(InterruptTimer.java:198)
	at org.eclipse.jgit.util.io.InterruptTimer.begin(InterruptTimer.java:97)
	at org.eclipse.jgit.util.io.TimeoutOutputStream.beginWrite(TimeoutOutputStream.java:127)
	at org.eclipse.jgit.util.io.TimeoutOutputStream.write(TimeoutOutputStream.java:91)
	at org.eclipse.jgit.transport.UploadPack.write(UploadPack.java:2403)
	at org.eclipse.jgit.transport.PacketLineOut.writePacket(PacketLineOut.java:157)
	at org.eclipse.jgit.transport.PacketLineOut.writePacket(PacketLineOut.java:133)
	at org.eclipse.jgit.transport.PacketLineOut.writeString(PacketLineOut.java:119)
	at org.eclipse.jgit.transport.UploadPack.writeError(UploadPack.java:2444)
	at org.eclipse.jgit.transport.UploadPack.upload(UploadPack.java:770)
	at com.google.gerrit.sshd.commands.Upload.runImpl(Upload.java:101)
	at com.google.gerrit.sshd.AbstractGitCommand.service(AbstractGitCommand.java:109)
	at com.google.gerrit.sshd.AbstractGitCommand.access-zsh(AbstractGitCommand.java:33)
	at com.google.gerrit.sshd.AbstractGitCommand.run(AbstractGitCommand.java:74)
	at com.google.gerrit.sshd.BaseCommand.run(BaseCommand.java:490)
	at com.google.gerrit.server.logging.LoggingContextAwareRunnable.run(LoggingContextAwareRunnable.java:113)
	at java.util.concurrent.Executors.call(Executors.java:511)
	at java.util.concurrent.FutureTask.run(FutureTask.java:266)
	at java.util.concurrent.ScheduledThreadPoolExecutor.access(ScheduledThreadPoolExecutor.java:180)
	at java.util.concurrent.ScheduledThreadPoolExecutor.run(ScheduledThreadPoolExecutor.java:293)
	at com.google.gerrit.server.git.WorkQueue.run(WorkQueue.java:612)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
	at java.util.concurrent.ThreadPoolExecutor.run(ThreadPoolExecutor.java:624)
	at java.lang.Thread.run(Thread.java:836)

By adding some trace statements we found, that the InterruptTimer was terminated by the finally block of `org.eclipse.jgit.transport.UploadPack.uploadWithExceptionPropagation(UploadPack.java:845)` and thus after the fetch was completed/failed:

org.eclipse.jgit.util.io.InterruptTimer.terminate(InterruptTimer.java:217),
 org.eclipse.jgit.util.io.InterruptTimer.terminate(InterruptTimer.java:111),
 org.eclipse.jgit.transport.UploadPack.uploadWithExceptionPropagation(UploadPack.java:845),
 org.eclipse.jgit.transport.UploadPack.upload(UploadPack.java:752),
 com.google.gerrit.sshd.commands.Upload.runImpl(Upload.java:101),
 com.google.gerrit.sshd.AbstractGitCommand.service(AbstractGitCommand.java:109),
 com.google.gerrit.sshd.AbstractGitCommand.access-zsh(AbstractGitCommand.java:33),
 com.google.gerrit.sshd.AbstractGitCommand.run(AbstractGitCommand.java:74),
 com.google.gerrit.sshd.BaseCommand.run(BaseCommand.java:490),
 com.google.gerrit.server.logging.LoggingContextAwareRunnable.run(LoggingContextAwareRunnable.java:113),
 java.util.concurrent.Executors.call(Executors.java:511),
 java.util.concurrent.FutureTask.run(FutureTask.java:266),
 java.util.concurrent.ScheduledThreadPoolExecutor.access(ScheduledThreadPoolExecutor.java:180),
 java.util.concurrent.ScheduledThreadPoolExecutor.run(ScheduledThreadPoolExecutor.java:293),
 com.google.gerrit.server.git.WorkQueue.run(WorkQueue.java:612),
 java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149),
 java.util.concurrent.ThreadPoolExecutor.run(ThreadPoolExecutor.java:624),
 java.lang.Thread.run(Thread.java:836)

However, according to the exception stacktrace, it tried to write an error to the client after the above mentioned finally block. This writeError() call ends up reusing the same InterruptTimer in `org.eclipse.jgit.transport.UploadPack.write(UploadPack.java:2403)`, which fails, since it is already terminated.

This should be reproducible by causing an artificial IOException or similar within uploadWithExceptionPropagation().

We will add some more tracing to figure out which error is causing this, since such errors are not logged to the server logs and due to this issue never reach the client.

Possible solutions might be:
- If there is an error don't terminate the InterruptTimer in the finally block, but let the error handling code do it.
- Don't use a TimeoutOutputStream for writing errors to the client, instead use just an OutputStream.