blaze icon indicating copy to clipboard operation
blaze copied to clipboard
verified publisher icon http4s

Scary looking stacktrace found in test logs

Open bryce-anderson opened this issue 7 years ago • 6 comments

Nothing failed, so I suspect this is a racy shutdown:

16:14:21.837 [anInnocuousThread] ERROR org.http4s.blaze.util.Execution - Trampoline EC Exception caught
java.lang.IllegalStateException: Promise already completed.
	at scala.concurrent.Promise.complete(Promise.scala:49)
	at scala.concurrent.Promise.complete$(Promise.scala:48)
	at scala.concurrent.impl.Promise$DefaultPromise.complete(Promise.scala:183)
	at scala.concurrent.Promise.failure(Promise.scala:100)
	at scala.concurrent.Promise.failure$(Promise.scala:100)
	at scala.concurrent.impl.Promise$DefaultPromise.failure(Promise.scala:183)
	at scala.concurrent.impl.Promise.$anonfun$transformWith$1(Promise.scala:41)
	at scala.concurrent.impl.CallbackRunnable.run(Promise.scala:60)
	at org.http4s.blaze.util.Execution$ThreadLocalTrampoline.run(Execution.scala:108)
	at org.http4s.blaze.util.Execution$ThreadLocalTrampoline.execute(Execution.scala:94)
	at org.http4s.blaze.util.Execution$$anon$2.execute(Execution.scala:53)
	at scala.concurrent.impl.CallbackRunnable.executeWithValue(Promise.scala:68)
	at scala.concurrent.impl.Promise$DefaultPromise.$anonfun$tryComplete$1(Promise.scala:284)
	at scala.concurrent.impl.Promise$DefaultPromise.$anonfun$tryComplete$1$adapted(Promise.scala:284)
	at scala.concurrent.impl.Promise$DefaultPromise.tryComplete(Promise.scala:284)
	at scala.concurrent.impl.Promise$DefaultPromise.link(Promise.scala:337)
	at scala.concurrent.impl.Promise$DefaultPromise.linkRootOf(Promise.scala:322)
	at scala.concurrent.impl.Promise.$anonfun$transformWith$1(Promise.scala:39)
	at scala.concurrent.impl.CallbackRunnable.run(Promise.scala:60)
	at org.http4s.blaze.util.Execution$ThreadLocalTrampoline.run(Execution.scala:108)
	at org.http4s.blaze.util.Execution$ThreadLocalTrampoline.execute(Execution.scala:94)
	at org.http4s.blaze.util.Execution$$anon$2.execute(Execution.scala:53)
	at scala.concurrent.impl.CallbackRunnable.executeWithValue(Promise.scala:68)
	at scala.concurrent.impl.Promise$DefaultPromise.$anonfun$tryComplete$1(Promise.scala:284)
	at scala.concurrent.impl.Promise$DefaultPromise.$anonfun$tryComplete$1$adapted(Promise.scala:284)
	at scala.concurrent.impl.Promise$DefaultPromise.tryComplete(Promise.scala:284)
	at scala.concurrent.Promise.trySuccess(Promise.scala:90)
	at scala.concurrent.Promise.trySuccess$(Promise.scala:90)
	at scala.concurrent.impl.Promise$DefaultPromise.trySuccess(Promise.scala:183)
	at org.http4s.blaze.channel.nio2.ByteBufferHead$$anon$3.completed(ByteBufferHead.scala:114)
	at org.http4s.blaze.channel.nio2.ByteBufferHead$$anon$3.completed(ByteBufferHead.scala:100)
	at sun.nio.ch.Invoker.invokeUnchecked(Invoker.java:126)
	at sun.nio.ch.UnixAsynchronousSocketChannelImpl.finishRead(UnixAsynchronousSocketChannelImpl.java:430)
	at sun.nio.ch.UnixAsynchronousSocketChannelImpl.finish(UnixAsynchronousSocketChannelImpl.java:191)
	at sun.nio.ch.UnixAsynchronousSocketChannelImpl.onEvent(UnixAsynchronousSocketChannelImpl.java:213)
	at sun.nio.ch.KQueuePort$EventHandlerTask.run(KQueuePort.java:301)
	at sun.nio.ch.AsynchronousChannelGroupImpl$1.run(AsynchronousChannelGroupImpl.java:112)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
	at java.lang.Thread.run(Thread.java:748)
	at sun.misc.InnocuousThread.run(InnocuousThread.java:74)
16:14:21.846 [anInnocuousThread] ERROR org.http4s.blaze.util.Execution - Trampoline EC Exception caught
java.lang.IllegalStateException: Promise already completed.
	at scala.concurrent.Promise.complete(Promise.scala:49)
	at scala.concurrent.Promise.complete$(Promise.scala:48)
	at scala.concurrent.impl.Promise$DefaultPromise.complete(Promise.scala:183)
	at scala.concurrent.Promise.failure(Promise.scala:100)
	at scala.concurrent.Promise.failure$(Promise.scala:100)
	at scala.concurrent.impl.Promise$DefaultPromise.failure(Promise.scala:183)
	at scala.concurrent.impl.Promise.$anonfun$transformWith$1(Promise.scala:41)
	at scala.concurrent.impl.CallbackRunnable.run(Promise.scala:60)
	at org.http4s.blaze.util.Execution$ThreadLocalTrampoline.run(Execution.scala:108)
	at org.http4s.blaze.util.Execution$ThreadLocalTrampoline.execute(Execution.scala:94)
	at org.http4s.blaze.util.Execution$$anon$2.execute(Execution.scala:53)
	at scala.concurrent.impl.CallbackRunnable.executeWithValue(Promise.scala:68)
	at scala.concurrent.impl.Promise$DefaultPromise.$anonfun$tryComplete$1(Promise.scala:284)
	at scala.concurrent.impl.Promise$DefaultPromise.$anonfun$tryComplete$1$adapted(Promise.scala:284)
	at scala.concurrent.impl.Promise$DefaultPromise.tryComplete(Promise.scala:284)
	at scala.concurrent.impl.Promise$DefaultPromise.link(Promise.scala:337)
	at scala.concurrent.impl.Promise$DefaultPromise.linkRootOf(Promise.scala:322)
	at scala.concurrent.impl.Promise.$anonfun$transformWith$1(Promise.scala:39)
	at scala.concurrent.impl.CallbackRunnable.run(Promise.scala:60)
	at org.http4s.blaze.util.Execution$ThreadLocalTrampoline.run(Execution.scala:108)
	at org.http4s.blaze.util.Execution$ThreadLocalTrampoline.execute(Execution.scala:94)
	at org.http4s.blaze.util.Execution$$anon$2.execute(Execution.scala:53)
	at scala.concurrent.impl.CallbackRunnable.executeWithValue(Promise.scala:68)
	at scala.concurrent.impl.Promise$DefaultPromise.$anonfun$tryComplete$1(Promise.scala:284)
	at scala.concurrent.impl.Promise$DefaultPromise.$anonfun$tryComplete$1$adapted(Promise.scala:284)
	at scala.concurrent.impl.Promise$DefaultPromise.tryComplete(Promise.scala:284)
	at scala.concurrent.Promise.trySuccess(Promise.scala:90)
	at scala.concurrent.Promise.trySuccess$(Promise.scala:90)
	at scala.concurrent.impl.Promise$DefaultPromise.trySuccess(Promise.scala:183)
	at org.http4s.blaze.channel.nio2.ByteBufferHead$$anon$3.completed(ByteBufferHead.scala:114)
	at org.http4s.blaze.channel.nio2.ByteBufferHead$$anon$3.completed(ByteBufferHead.scala:100)
	at sun.nio.ch.Invoker.invokeUnchecked(Invoker.java:126)
	at sun.nio.ch.Invoker$2.run(Invoker.java:218)
	at sun.nio.ch.AsynchronousChannelGroupImpl$1.run(AsynchronousChannelGroupImpl.java:112)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
	at java.lang.Thread.run(Thread.java:748)
	at sun.misc.InnocuousThread.run(InnocuousThread.java:74)
16:14:21.848 [anInnocuousThread] ERROR org.http4s.blaze.util.Execution - Trampoline EC Exception caught
java.lang.IllegalStateException: Promise already completed.
	at scala.concurrent.Promise.complete(Promise.scala:49)
	at scala.concurrent.Promise.complete$(Promise.scala:48)
	at scala.concurrent.impl.Promise$DefaultPromise.complete(Promise.scala:183)
	at scala.concurrent.Promise.failure(Promise.scala:100)
	at scala.concurrent.Promise.failure$(Promise.scala:100)
	at scala.concurrent.impl.Promise$DefaultPromise.failure(Promise.scala:183)
	at scala.concurrent.impl.Promise.$anonfun$transformWith$1(Promise.scala:41)
	at scala.concurrent.impl.CallbackRunnable.run(Promise.scala:60)
	at org.http4s.blaze.util.Execution$ThreadLocalTrampoline.run(Execution.scala:108)
	at org.http4s.blaze.util.Execution$ThreadLocalTrampoline.execute(Execution.scala:94)
	at org.http4s.blaze.util.Execution$$anon$2.execute(Execution.scala:53)
	at scala.concurrent.impl.CallbackRunnable.executeWithValue(Promise.scala:68)
	at scala.concurrent.impl.Promise$DefaultPromise.$anonfun$tryComplete$1(Promise.scala:284)
	at scala.concurrent.impl.Promise$DefaultPromise.$anonfun$tryComplete$1$adapted(Promise.scala:284)
	at scala.concurrent.impl.Promise$DefaultPromise.tryComplete(Promise.scala:284)
	at scala.concurrent.impl.Promise$DefaultPromise.link(Promise.scala:337)
	at scala.concurrent.impl.Promise$DefaultPromise.linkRootOf(Promise.scala:322)
	at scala.concurrent.impl.Promise.$anonfun$transformWith$1(Promise.scala:39)
	at scala.concurrent.impl.CallbackRunnable.run(Promise.scala:60)
	at org.http4s.blaze.util.Execution$ThreadLocalTrampoline.run(Execution.scala:108)
	at org.http4s.blaze.util.Execution$ThreadLocalTrampoline.execute(Execution.scala:94)
	at org.http4s.blaze.util.Execution$$anon$2.execute(Execution.scala:53)
	at scala.concurrent.impl.CallbackRunnable.executeWithValue(Promise.scala:68)
	at scala.concurrent.impl.Promise$DefaultPromise.$anonfun$tryComplete$1(Promise.scala:284)
	at scala.concurrent.impl.Promise$DefaultPromise.$anonfun$tryComplete$1$adapted(Promise.scala:284)
	at scala.concurrent.impl.Promise$DefaultPromise.tryComplete(Promise.scala:284)
	at scala.concurrent.Promise.trySuccess(Promise.scala:90)
	at scala.concurrent.Promise.trySuccess$(Promise.scala:90)
	at scala.concurrent.impl.Promise$DefaultPromise.trySuccess(Promise.scala:183)
	at org.http4s.blaze.channel.nio2.ByteBufferHead$$anon$3.completed(ByteBufferHead.scala:114)
	at org.http4s.blaze.channel.nio2.ByteBufferHead$$anon$3.completed(ByteBufferHead.scala:100)
	at sun.nio.ch.Invoker.invokeUnchecked(Invoker.java:126)
	at sun.nio.ch.UnixAsynchronousSocketChannelImpl.finishRead(UnixAsynchronousSocketChannelImpl.java:430)
	at sun.nio.ch.UnixAsynchronousSocketChannelImpl.finish(UnixAsynchronousSocketChannelImpl.java:191)
	at sun.nio.ch.UnixAsynchronousSocketChannelImpl.onEvent(UnixAsynchronousSocketChannelImpl.java:213)
	at sun.nio.ch.KQueuePort$EventHandlerTask.run(KQueuePort.java:301)
	at sun.nio.ch.AsynchronousChannelGroupImpl$1.run(AsynchronousChannelGroupImpl.java:112)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
	at java.lang.Thread.run(Thread.java:748)
	at sun.misc.InnocuousThread.run(InnocuousThread.java:74)

bryce-anderson avatar Feb 17 '18 16:02 bryce-anderson

It's only reproducible when running the tests test-only *ServerSpec in the blaze-http package, and it seems to pop every time. This consists of two different tests, Http1ServerSpec and Http2ServerSpec, both of which when run independently don't seem to have an issue.

bryce-anderson avatar Feb 17 '18 16:02 bryce-anderson

A particularly interesting thing about that trace is that it seems that the ThreadLocalTrampoline has become re-entrant somehow.

bryce-anderson avatar Feb 17 '18 17:02 bryce-anderson

It looks like the exception is happening on the client side of things: moving the server to NIO1 still shows the stack trace originating in nio2.

bryce-anderson avatar Feb 18 '18 15:02 bryce-anderson

And since it's happening in those two tests, the HTTP/1 test uses the async-client, so it must be happening in the HTTP/2 client.

bryce-anderson avatar Feb 18 '18 15:02 bryce-anderson

I've been able to change the ExecutionContext to directec in PriorKnowledgeHandshaker and get it to register in the stacktrace. There are a lot of flatMap operations in there so it seems consistent with where there may be an issue.

bryce-anderson avatar Feb 18 '18 15:02 bryce-anderson

I'm stumped on this. I haven't found anything in the handshaker callpath that would try to force-set a promise again, and all the ones that use the tryComplete methods seem to be successfully setting the promise. I'm going to shelf this for now since it doesn't seem to be a real issue.

bryce-anderson avatar Feb 18 '18 19:02 bryce-anderson