Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Intermittent test failures in webserver PlainTest #651

Closed
tomas-langer opened this issue May 6, 2019 · 6 comments
Closed

Intermittent test failures in webserver PlainTest #651

tomas-langer opened this issue May 6, 2019 · 6 comments
Assignees
@spericas
Labels
bug Something isn't working build SE webserver
Projects
Backlog

Comments

@tomas-langer
Copy link
Member

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

  • Helidon Version: 1.0.4-SNAPSHOT
  • Helidon SE
  • On Wercker
@tomas-langer tomas-langer added bug Something isn't working SE build webserver labels May 6, 2019
@tomas-langer tomas-langer added this to Needs triage in Backlog via automation May 6, 2019
@tomas-langer
Copy link
Member Author

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
Copy link
Member

spericas commented May 6, 2019

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

@tomas-langer
Copy link
Member Author

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 spericas self-assigned this May 9, 2019
@spericas
Copy link
Member

spericas commented May 9, 2019

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

@m0mus m0mus moved this from Needs triage to High priority in Backlog May 9, 2019
@spericas
Copy link
Member

spericas commented May 9, 2019

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?

@barchetta barchetta moved this from High priority to In Progress in Backlog May 14, 2019
spericas added a commit to spericas/helidon that referenced this issue May 16, 2019
@spericas
Complete writing a response before checking unconsumed request payloa…
b79abaa 
…d that may trigger a connection reset. See helidon-io#651.

Signed-off-by: Santiago Pericas-Geertsen <Santiago.PericasGeertsen@oracle.com>
@spericas
Copy link
Member

PR #699

spericas added a commit that referenced this issue May 16, 2019
@spericas
Complete writing a response before checking unconsumed request payloa…
8d48020 
…d that may trigger a connection reset. See #651. (#699)

Signed-off-by: Santiago Pericas-Geertsen <Santiago.PericasGeertsen@oracle.com>
Backlog automation moved this from In Progress to Closed May 22, 2019
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@spericas spericas

Labels
bug Something isn't working build SE webserver
Projects
Backlog
  
Closed
Milestone
No milestone
Development

No branches or pull requests
2 participants
@spericas @tomas-langer