search

helidon-io / helidon

Java libraries for writing microservices
https://helidon.io
Apache License 2.0
3.52k stars 565 forks source link

Intermittent test failures in webserver PlainTest #651

Closed tomas-langer closed 5 years ago

tomas-langer commented 5 years ago

We have an intermittent issue with webserver PlainTest - the test hangs and the build times out. I have seen it in: https://app.wercker.com/Helidon/helidon/runs/build/5ccf26a8ab79a30008ed02e7?step=5ccf26e13d81fb0007cc3d1f

and also locally (@Verdent on windows when the computer was under heavy load).

Environment Details

tomas-langer commented 5 years ago

Managed to replicate on local computer - under very heavy load. Hanging test: PlainTest.deferredGetWithLargePayloadCausesConnectionClose() Thread dump:

Full thread dump

"nioEventLoopGroup-3-8" #20 prio=10 os_prio=31 tid=0x00007fe15909c000 nid=0x5903 runnable [0x0000700008eff000]
   java.lang.Thread.State: RUNNABLE
    at sun.nio.ch.KQueueArrayWrapper.kevent0(Native Method)
    at sun.nio.ch.KQueueArrayWrapper.poll(KQueueArrayWrapper.java:198)
    at sun.nio.ch.KQueueSelectorImpl.doSelect(KQueueSelectorImpl.java:117)
    at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:86)
    - locked <0x00000007bfb87070> (a io.netty.channel.nio.SelectedSelectionKeySet)
    - locked <0x00000007bfb88178> (a java.util.Collections$UnmodifiableSet)
    - locked <0x00000007bfb88098> (a sun.nio.ch.KQueueSelectorImpl)
    at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:97)
    at io.netty.channel.nio.SelectedSelectionKeySetSelector.select(SelectedSelectionKeySetSelector.java:62)
    at io.netty.channel.nio.NioEventLoop.select(NioEventLoop.java:786)
    at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:434)
    at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:905)
    at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
    at java.lang.Thread.run(Thread.java:748)

"nioEventLoopGroup-3-7" #19 prio=10 os_prio=31 tid=0x00007fe159af7800 nid=0xa603 runnable [0x0000700008dfc000]
   java.lang.Thread.State: RUNNABLE
    at sun.nio.ch.KQueueArrayWrapper.kevent0(Native Method)
    at sun.nio.ch.KQueueArrayWrapper.poll(KQueueArrayWrapper.java:198)
    at sun.nio.ch.KQueueSelectorImpl.doSelect(KQueueSelectorImpl.java:117)
    at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:86)
    - locked <0x00000007bfb8a850> (a io.netty.channel.nio.SelectedSelectionKeySet)
    - locked <0x00000007bfb8b958> (a java.util.Collections$UnmodifiableSet)
    - locked <0x00000007bfb8b878> (a sun.nio.ch.KQueueSelectorImpl)
    at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:97)
    at io.netty.channel.nio.SelectedSelectionKeySetSelector.select(SelectedSelectionKeySetSelector.java:62)
    at io.netty.channel.nio.NioEventLoop.select(NioEventLoop.java:786)
    at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:434)
    at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:905)
    at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
    at java.lang.Thread.run(Thread.java:748)

"nioEventLoopGroup-3-6" #18 prio=10 os_prio=31 tid=0x00007fe159af7000 nid=0xa703 runnable [0x0000700008cf9000]
   java.lang.Thread.State: RUNNABLE
    at sun.nio.ch.KQueueArrayWrapper.kevent0(Native Method)
    at sun.nio.ch.KQueueArrayWrapper.poll(KQueueArrayWrapper.java:198)
    at sun.nio.ch.KQueueSelectorImpl.doSelect(KQueueSelectorImpl.java:117)
    at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:86)
    - locked <0x00000007bfb8e338> (a io.netty.channel.nio.SelectedSelectionKeySet)
    - locked <0x00000007bfb8f440> (a java.util.Collections$UnmodifiableSet)
    - locked <0x00000007bfb8f360> (a sun.nio.ch.KQueueSelectorImpl)
    at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:97)
    at io.netty.channel.nio.SelectedSelectionKeySetSelector.select(SelectedSelectionKeySetSelector.java:62)
    at io.netty.channel.nio.NioEventLoop.select(NioEventLoop.java:786)
    at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:434)
    at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:905)
    at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
    at java.lang.Thread.run(Thread.java:748)

"nioEventLoopGroup-3-5" #17 prio=10 os_prio=31 tid=0x00007fe1590b6800 nid=0xa903 runnable [0x0000700008bf6000]
   java.lang.Thread.State: RUNNABLE
    at sun.nio.ch.KQueueArrayWrapper.kevent0(Native Method)
    at sun.nio.ch.KQueueArrayWrapper.poll(KQueueArrayWrapper.java:198)
    at sun.nio.ch.KQueueSelectorImpl.doSelect(KQueueSelectorImpl.java:117)
    at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:86)
    - locked <0x00000007bfb91b08> (a io.netty.channel.nio.SelectedSelectionKeySet)
    - locked <0x00000007bfb92c10> (a java.util.Collections$UnmodifiableSet)
    - locked <0x00000007bfb92b30> (a sun.nio.ch.KQueueSelectorImpl)
    at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:97)
    at io.netty.channel.nio.SelectedSelectionKeySetSelector.select(SelectedSelectionKeySetSelector.java:62)
    at io.netty.channel.nio.NioEventLoop.select(NioEventLoop.java:786)
    at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:434)
    at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:905)
    at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
    at java.lang.Thread.run(Thread.java:748)

"nioEventLoopGroup-3-4" #16 prio=10 os_prio=31 tid=0x00007fe1580b3800 nid=0x5503 runnable [0x0000700008af3000]
   java.lang.Thread.State: RUNNABLE
    at sun.nio.ch.KQueueArrayWrapper.kevent0(Native Method)
    at sun.nio.ch.KQueueArrayWrapper.poll(KQueueArrayWrapper.java:198)
    at sun.nio.ch.KQueueSelectorImpl.doSelect(KQueueSelectorImpl.java:117)
    at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:86)
    - locked <0x00000007bfba52f0> (a io.netty.channel.nio.SelectedSelectionKeySet)
    - locked <0x00000007bfba63f8> (a java.util.Collections$UnmodifiableSet)
    - locked <0x00000007bfba6318> (a sun.nio.ch.KQueueSelectorImpl)
    at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:97)
    at io.netty.channel.nio.SelectedSelectionKeySetSelector.select(SelectedSelectionKeySetSelector.java:62)
    at io.netty.channel.nio.NioEventLoop.select(NioEventLoop.java:786)
    at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:434)
    at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:905)
    at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
    at java.lang.Thread.run(Thread.java:748)

"nioEventLoopGroup-3-3" #15 prio=10 os_prio=31 tid=0x00007fe159927800 nid=0x4303 runnable [0x00007000089f0000]
   java.lang.Thread.State: RUNNABLE
    at sun.nio.ch.KQueueArrayWrapper.kevent0(Native Method)
    at sun.nio.ch.KQueueArrayWrapper.poll(KQueueArrayWrapper.java:198)
    at sun.nio.ch.KQueueSelectorImpl.doSelect(KQueueSelectorImpl.java:117)
    at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:86)
    - locked <0x00000007bfba8ac0> (a io.netty.channel.nio.SelectedSelectionKeySet)
    - locked <0x00000007bfba9bc8> (a java.util.Collections$UnmodifiableSet)
    - locked <0x00000007bfba9ae8> (a sun.nio.ch.KQueueSelectorImpl)
    at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:97)
    at io.netty.channel.nio.SelectedSelectionKeySetSelector.select(SelectedSelectionKeySetSelector.java:62)
    at io.netty.channel.nio.NioEventLoop.select(NioEventLoop.java:786)
    at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:434)
    at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:905)
    at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
    at java.lang.Thread.run(Thread.java:748)

"nioEventLoopGroup-3-2" #14 prio=10 os_prio=31 tid=0x00007fe159844800 nid=0x4103 runnable [0x00007000088ed000]
   java.lang.Thread.State: RUNNABLE
    at sun.nio.ch.KQueueArrayWrapper.kevent0(Native Method)
    at sun.nio.ch.KQueueArrayWrapper.poll(KQueueArrayWrapper.java:198)
    at sun.nio.ch.KQueueSelectorImpl.doSelect(KQueueSelectorImpl.java:117)
    at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:86)
    - locked <0x00000007bfbbd050> (a io.netty.channel.nio.SelectedSelectionKeySet)
    - locked <0x00000007bfbbe158> (a java.util.Collections$UnmodifiableSet)
    - locked <0x00000007bfbbe078> (a sun.nio.ch.KQueueSelectorImpl)
    at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:97)
    at io.netty.channel.nio.SelectedSelectionKeySetSelector.select(SelectedSelectionKeySetSelector.java:62)
    at io.netty.channel.nio.NioEventLoop.select(NioEventLoop.java:786)
    at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:434)
    at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:905)
    at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
    at java.lang.Thread.run(Thread.java:748)

"nioEventLoopGroup-3-1" #13 prio=10 os_prio=31 tid=0x00007fe1580bb800 nid=0x4a07 runnable [0x00007000087ea000]
   java.lang.Thread.State: RUNNABLE
    at sun.nio.ch.KQueueArrayWrapper.kevent0(Native Method)
    at sun.nio.ch.KQueueArrayWrapper.poll(KQueueArrayWrapper.java:198)
    at sun.nio.ch.KQueueSelectorImpl.doSelect(KQueueSelectorImpl.java:117)
    at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:86)
    - locked <0x00000007bfbbecd0> (a io.netty.channel.nio.SelectedSelectionKeySet)
    - locked <0x00000007bfbbfda8> (a java.util.Collections$UnmodifiableSet)
    - locked <0x00000007bfbbec20> (a sun.nio.ch.KQueueSelectorImpl)
    at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:97)
    at io.netty.channel.nio.SelectedSelectionKeySetSelector.select(SelectedSelectionKeySetSelector.java:62)
    at io.netty.channel.nio.NioEventLoop.select(NioEventLoop.java:786)
    at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:434)
    at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:905)
    at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
    at java.lang.Thread.run(Thread.java:748)

"nioEventLoopGroup-2-1" #12 prio=10 os_prio=31 tid=0x00007fe15908c800 nid=0xc07 runnable [0x00007000086e7000]
   java.lang.Thread.State: RUNNABLE
    at sun.nio.ch.KQueueArrayWrapper.kevent0(Native Method)
    at sun.nio.ch.KQueueArrayWrapper.poll(KQueueArrayWrapper.java:198)
    at sun.nio.ch.KQueueSelectorImpl.doSelect(KQueueSelectorImpl.java:117)
    at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:86)
    - locked <0x00000007bfb181f8> (a io.netty.channel.nio.SelectedSelectionKeySet)
    - locked <0x00000007bfb18210> (a java.util.Collections$UnmodifiableSet)
    - locked <0x00000007bfb181a8> (a sun.nio.ch.KQueueSelectorImpl)
    at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:97)
    at io.netty.channel.nio.SelectedSelectionKeySetSelector.select(SelectedSelectionKeySetSelector.java:62)
    at io.netty.channel.nio.NioEventLoop.select(NioEventLoop.java:786)
    at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:434)
    at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:905)
    at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
    at java.lang.Thread.run(Thread.java:748)

"Monitor Ctrl-Break" #5 daemon prio=5 os_prio=31 tid=0x00007fe159802000 nid=0x3503 runnable [0x0000700007fd2000]
   java.lang.Thread.State: RUNNABLE
    at java.net.SocketInputStream.socketRead0(Native Method)
    at java.net.SocketInputStream.socketRead(SocketInputStream.java:116)
    at java.net.SocketInputStream.read(SocketInputStream.java:171)
    at java.net.SocketInputStream.read(SocketInputStream.java:141)
    at sun.nio.cs.StreamDecoder.readBytes(StreamDecoder.java:284)
    at sun.nio.cs.StreamDecoder.implRead(StreamDecoder.java:326)
    at sun.nio.cs.StreamDecoder.read(StreamDecoder.java:178)
    - locked <0x00000007bfb17138> (a java.io.InputStreamReader)
    at java.io.InputStreamReader.read(InputStreamReader.java:184)
    at java.io.BufferedReader.fill(BufferedReader.java:161)
    at java.io.BufferedReader.readLine(BufferedReader.java:324)
    - locked <0x00000007bfb17138> (a java.io.InputStreamReader)
    at java.io.BufferedReader.readLine(BufferedReader.java:389)
    at com.intellij.rt.execution.application.AppMainV2$1.run(AppMainV2.java:64)

"main" #1 prio=5 os_prio=31 tid=0x00007fe159004000 nid=0x2803 runnable [0x0000700007632000]
   java.lang.Thread.State: RUNNABLE
    at java.net.SocketInputStream.socketRead0(Native Method)
    at java.net.SocketInputStream.socketRead(SocketInputStream.java:116)
    at java.net.SocketInputStream.read(SocketInputStream.java:171)
    at java.net.SocketInputStream.read(SocketInputStream.java:141)
    at sun.nio.cs.StreamDecoder.readBytes(StreamDecoder.java:284)
    at sun.nio.cs.StreamDecoder.implRead(StreamDecoder.java:326)
    at sun.nio.cs.StreamDecoder.read(StreamDecoder.java:178)
    - locked <0x00000007be6259e0> (a java.io.InputStreamReader)
    at java.io.InputStreamReader.read(InputStreamReader.java:184)
    at java.io.BufferedReader.fill(BufferedReader.java:161)
    at java.io.BufferedReader.readLine(BufferedReader.java:324)
    - locked <0x00000007be6259e0> (a java.io.InputStreamReader)
    at java.io.BufferedReader.readLine(BufferedReader.java:389)
    at io.helidon.webserver.utils.SocketHttpClient.receive(SocketHttpClient.java:173)
    at io.helidon.webserver.utils.SocketHttpClient.assertConnectionIsClosed(SocketHttpClient.java:138)
    at io.helidon.webserver.PlainTest.deferredGetWithLargePayloadCausesConnectionClose(PlainTest.java:241)
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:498)
    at org.junit.platform.commons.util.ReflectionUtils.invokeMethod(ReflectionUtils.java:436)
    at org.junit.jupiter.engine.execution.ExecutableInvoker.invoke(ExecutableInvoker.java:115)
    at org.junit.jupiter.engine.descriptor.TestMethodTestDescriptor.lambda$invokeTestMethod$6(TestMethodTestDescriptor.java:170)
    at org.junit.jupiter.engine.descriptor.TestMethodTestDescriptor$$Lambda$182/1054932644.execute(Unknown Source)
    at org.junit.jupiter.engine.execution.ThrowableCollector.execute(ThrowableCollector.java:40)
    at org.junit.jupiter.engine.descriptor.TestMethodTestDescriptor.invokeTestMethod(TestMethodTestDescriptor.java:166)
    at org.junit.jupiter.engine.descriptor.TestMethodTestDescriptor.execute(TestMethodTestDescriptor.java:113)
    at org.junit.jupiter.engine.descriptor.TestMethodTestDescriptor.execute(TestMethodTestDescriptor.java:58)
    at org.junit.platform.engine.support.hierarchical.HierarchicalTestExecutor$NodeExecutor.lambda$executeRecursively$3(HierarchicalTestExecutor.java:112)
    at org.junit.platform.engine.support.hierarchical.HierarchicalTestExecutor$NodeExecutor$$Lambda$117/1576861390.execute(Unknown Source)
    at org.junit.platform.engine.support.hierarchical.SingleTestExecutor.executeSafely(SingleTestExecutor.java:66)
    at org.junit.platform.engine.support.hierarchical.HierarchicalTestExecutor$NodeExecutor.executeRecursively(HierarchicalTestExecutor.java:108)
    at org.junit.platform.engine.support.hierarchical.HierarchicalTestExecutor$NodeExecutor.execute(HierarchicalTestExecutor.java:79)
    at org.junit.platform.engine.support.hierarchical.HierarchicalTestExecutor$NodeExecutor.lambda$executeRecursively$2(HierarchicalTestExecutor.java:120)
    at org.junit.platform.engine.support.hierarchical.HierarchicalTestExecutor$NodeExecutor$$Lambda$120/269468037.accept(Unknown Source)
    at java.util.stream.ForEachOps$ForEachOp$OfRef.accept(ForEachOps.java:184)
    at java.util.stream.ReferencePipeline$2$1.accept(ReferencePipeline.java:175)
    at java.util.Iterator.forEachRemaining(Iterator.java:116)
    at java.util.Spliterators$IteratorSpliterator.forEachRemaining(Spliterators.java:1801)
    at java.util.stream.AbstractPipeline.copyInto(AbstractPipeline.java:481)
    at java.util.stream.AbstractPipeline.wrapAndCopyInto(AbstractPipeline.java:471)
    at java.util.stream.ForEachOps$ForEachOp.evaluateSequential(ForEachOps.java:151)
    at java.util.stream.ForEachOps$ForEachOp$OfRef.evaluateSequential(ForEachOps.java:174)
    at java.util.stream.AbstractPipeline.evaluate(AbstractPipeline.java:234)
    at java.util.stream.ReferencePipeline.forEach(ReferencePipeline.java:418)
    at org.junit.platform.engine.support.hierarchical.HierarchicalTestExecutor$NodeExecutor.lambda$executeRecursively$3(HierarchicalTestExecutor.java:120)
    at org.junit.platform.engine.support.hierarchical.HierarchicalTestExecutor$NodeExecutor$$Lambda$117/1576861390.execute(Unknown Source)
    at org.junit.platform.engine.support.hierarchical.SingleTestExecutor.executeSafely(SingleTestExecutor.java:66)
    at org.junit.platform.engine.support.hierarchical.HierarchicalTestExecutor$NodeExecutor.executeRecursively(HierarchicalTestExecutor.java:108)
    at org.junit.platform.engine.support.hierarchical.HierarchicalTestExecutor$NodeExecutor.execute(HierarchicalTestExecutor.java:79)
    at org.junit.platform.engine.support.hierarchical.HierarchicalTestExecutor$NodeExecutor.lambda$executeRecursively$2(HierarchicalTestExecutor.java:120)
    at org.junit.platform.engine.support.hierarchical.HierarchicalTestExecutor$NodeExecutor$$Lambda$120/269468037.accept(Unknown Source)
    at java.util.stream.ForEachOps$ForEachOp$OfRef.accept(ForEachOps.java:184)
    at java.util.stream.ReferencePipeline$2$1.accept(ReferencePipeline.java:175)
    at java.util.Iterator.forEachRemaining(Iterator.java:116)
    at java.util.Spliterators$IteratorSpliterator.forEachRemaining(Spliterators.java:1801)
    at java.util.stream.AbstractPipeline.copyInto(AbstractPipeline.java:481)
    at java.util.stream.AbstractPipeline.wrapAndCopyInto(AbstractPipeline.java:471)
    at java.util.stream.ForEachOps$ForEachOp.evaluateSequential(ForEachOps.java:151)
    at java.util.stream.ForEachOps$ForEachOp$OfRef.evaluateSequential(ForEachOps.java:174)
    at java.util.stream.AbstractPipeline.evaluate(AbstractPipeline.java:234)
    at java.util.stream.ReferencePipeline.forEach(ReferencePipeline.java:418)
    at org.junit.platform.engine.support.hierarchical.HierarchicalTestExecutor$NodeExecutor.lambda$executeRecursively$3(HierarchicalTestExecutor.java:120)
    at org.junit.platform.engine.support.hierarchical.HierarchicalTestExecutor$NodeExecutor$$Lambda$117/1576861390.execute(Unknown Source)
    at org.junit.platform.engine.support.hierarchical.SingleTestExecutor.executeSafely(SingleTestExecutor.java:66)
    at org.junit.platform.engine.support.hierarchical.HierarchicalTestExecutor$NodeExecutor.executeRecursively(HierarchicalTestExecutor.java:108)
    at org.junit.platform.engine.support.hierarchical.HierarchicalTestExecutor$NodeExecutor.execute(HierarchicalTestExecutor.java:79)
    at org.junit.platform.engine.support.hierarchical.HierarchicalTestExecutor.execute(HierarchicalTestExecutor.java:55)
    at org.junit.platform.engine.support.hierarchical.HierarchicalTestEngine.execute(HierarchicalTestEngine.java:43)
    at org.junit.platform.launcher.core.DefaultLauncher.execute(DefaultLauncher.java:170)
    at org.junit.platform.launcher.core.DefaultLauncher.execute(DefaultLauncher.java:154)
    at org.junit.platform.launcher.core.DefaultLauncher.execute(DefaultLauncher.java:90)
    at com.intellij.junit5.JUnit5IdeaTestRunner.startRunnerWithArgs(JUnit5IdeaTestRunner.java:69)
    at com.intellij.rt.execution.junit.IdeaTestRunner$Repeater.startRunnerWithArgs(IdeaTestRunner.java:47)
    at com.intellij.rt.execution.junit.JUnitStarter.prepareStreamsAndStart(JUnitStarter.java:242)
    at com.intellij.rt.execution.junit.JUnitStarter.main(JUnitStarter.java:70)

"Finalizer" #3 daemon prio=8 os_prio=31 tid=0x00007fe15903d000 nid=0x4f03 in Object.wait() [0x0000700007d49000]
   java.lang.Thread.State: WAITING (on object monitor)
    at java.lang.Object.wait(Native Method)
    - waiting on <0x00000007bfb17640> (a java.lang.ref.ReferenceQueue$Lock)
    at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:143)
    - locked <0x00000007bfb17640> (a java.lang.ref.ReferenceQueue$Lock)
    at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:164)
    at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:209)

"Reference Handler" #2 daemon prio=10 os_prio=31 tid=0x00007fe159002800 nid=0x5003 in Object.wait() [0x0000700007c46000]
   java.lang.Thread.State: WAITING (on object monitor)
    at java.lang.Object.wait(Native Method)
    - waiting on <0x00000007bfb17870> (a java.lang.ref.Reference$Lock)
    at java.lang.Object.wait(Object.java:502)
    at java.lang.ref.Reference.tryHandlePending(Reference.java:191)
    - locked <0x00000007bfb17870> (a java.lang.ref.Reference$Lock)
    at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:153)

"Attach Listener" #10 daemon prio=9 os_prio=31 tid=0x00007fe15904c000 nid=0x3e03 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Service Thread" #9 daemon prio=9 os_prio=31 tid=0x00007fe159058000 nid=0x3b03 runnable [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"C1 CompilerThread2" #8 daemon prio=9 os_prio=31 tid=0x00007fe15882e800 nid=0x4703 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"C2 CompilerThread1" #7 daemon prio=9 os_prio=31 tid=0x00007fe159827000 nid=0x3903 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"C2 CompilerThread0" #6 daemon prio=9 os_prio=31 tid=0x00007fe159057000 nid=0x3703 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Signal Dispatcher" #4 daemon prio=9 os_prio=31 tid=0x00007fe159023000 nid=0x480b runnable [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"VM Thread" os_prio=31 tid=0x00007fe158805800 nid=0x5203 runnable 

"GC task thread#0 (ParallelGC)" os_prio=31 tid=0x00007fe15800e800 nid=0x2007 runnable 

"GC task thread#1 (ParallelGC)" os_prio=31 tid=0x00007fe15800f800 nid=0x1d03 runnable 

"GC task thread#2 (ParallelGC)" os_prio=31 tid=0x00007fe158010000 nid=0x2a03 runnable 

"GC task thread#3 (ParallelGC)" os_prio=31 tid=0x00007fe158010800 nid=0x2b03 runnable 

"VM Periodic Task Thread" os_prio=31 tid=0x00007fe159809000 nid=0x3d03 waiting on condition 
JNI global references: 799
spericas commented 5 years ago

@tomas-langer Did you purposely introduce load in your system to reproduce this? If so, how?

tomas-langer commented 5 years ago

Yes I did. I used a small program that does stuff in a loop. It needs to print something to stdout, as otherwise java optimizes it and it stops loading. My program:

public class LoadIt {

    public static void main(String[] args) {
        LongAdder la = new LongAdder();
        Thread[] threads = new Thread[32];
        for (int i = 0; i < threads.length; i++) {
            threads[i] = new Thread(new Loader(la));
        }

        for (Thread thread : threads) {
            thread.start();
        }

        Thread printer = new Thread(() -> {
            while (true) {
                System.out.println("now: " + la.longValue());
                try {
                    Thread.sleep(1000);
                } catch (InterruptedException ignored) {
                    System.out.println("Printing thread interrupted");
                }
            }
        });

        printer.start();
    }

    private static class Loader implements Runnable {
        private final LongAdder la;

        Loader(LongAdder la) {
            this.la = la;
        }

        @Override
        public void run() {
            try {
                byte[] theBytes = new byte[1000000];
                Random random = new Random();
                while (true) {
                    random.nextBytes(theBytes);
                    MessageDigest instance = MessageDigest.getInstance("SHA-256");
                    instance.update(theBytes);
                    String hash = Base64.getEncoder().encodeToString(instance.digest());
                    la.add(hash.length());
                }
            } catch (NoSuchAlgorithmException ignored) {
                System.err.println("Algorithm SHA-256 not found");
            }
        }
    }
}
spericas commented 5 years ago

I'll try to reproduce it. I started by creating a binary for loadit using GraalVM for MacOS. Seems useful to have around.

loadit.zip

spericas commented 5 years ago

I have not been able to reproduce the problem so far, it always passes for me even after multiple runs on my Mac (High Sierra 10.13.6).

As @tomas-langer pointed out, the client is just waiting for data. Interestingly, the thread on which the handler runs (from ForkJoinPool) is not in the thread dump, it should look like this:

"ForkJoinPool.commonPool-worker-1" #16 daemon prio=10 os_prio=31 tid=0x00007fadd4437800 nid=0x5503 runnable [0x000070000d2ca000]

This suggests that the handler terminated normally and passed the response headers and payload to Netty.

The client seems to be stuck in readLine(). This can happen if (1) no data was sent or (2) an incomplete line was sent perhaps. SocketHttpClient.receive() logs an entry for every line received in FINEST level:

LOGGER.finest("Received: " + t);

Anyone seen this in the output? Maybe @Verdent?

spericas commented 5 years ago

PR #699