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

io.helidon.webserver.MaxPayloadSizeTest fails intermittently on Windows #6932

Closed
romain-grecourt opened this issue May 31, 2023 · 4 comments
Closed

io.helidon.webserver.MaxPayloadSizeTest fails intermittently on Windows #6932

romain-grecourt opened this issue May 31, 2023 · 4 comments
Assignees
@spericas
Labels
3.x Issues for 3.x version branch intermittent P3 testing webclient webserver

Comments

@romain-grecourt
Copy link
Contributor

romain-grecourt commented May 31, 2023 •
edited
Loading

io.helidon.webserver.MaxPayloadSizeTest fails on Windows with java.io.IOException: An established connection was aborted by the software in your host machine.

This is intermittent, however it fails half of the time in my local Windows VM. This was reported by @tvallin while working on #6717.

See the full stack trace:

[ERROR] io.helidon.webserver.MaxPayloadSizeTest.testContentLengthExceededWithPayload  Time elapsed: 0.496 s  <<< ERROR!
java.util.concurrent.CompletionException: java.io.IOException: An established connection was aborted by the software in your host machine
        at io.helidon.common.reactive.Awaitable.await(Awaitable.java:71)
        at io.helidon.webserver.MaxPayloadSizeTest.testContentLengthExceededWithPayload(MaxPayloadSizeTest.java:143)
        at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77)
        at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.base/java.lang.reflect.Method.invoke(Method.java:568)
        at org.junit.platform.commons.util.ReflectionUtils.invokeMethod(ReflectionUtils.java:688)
        at org.junit.jupiter.engine.execution.MethodInvocation.proceed(MethodInvocation.java:60)
        at org.junit.jupiter.engine.execution.InvocationInterceptorChain$ValidatingInvocation.proceed(InvocationInterceptorChain.java:131)
        at org.junit.jupiter.engine.extension.TimeoutExtension.intercept(TimeoutExtension.java:149)
        at org.junit.jupiter.engine.extension.TimeoutExtension.interceptTestableMethod(TimeoutExtension.java:140)
        at org.junit.jupiter.engine.extension.TimeoutExtension.interceptTestMethod(TimeoutExtension.java:84)
        at org.junit.jupiter.engine.execution.ExecutableInvoker$ReflectiveInterceptorCall.lambda$ofVoidMethod$0(ExecutableInvoker.java:115)
        at org.junit.jupiter.engine.execution.ExecutableInvoker.lambda$invoke$0(ExecutableInvoker.java:105)
        at org.junit.jupiter.engine.execution.InvocationInterceptorChain$InterceptedInvocation.proceed(InvocationInterceptorChain.java:106)
        at org.junit.jupiter.engine.execution.InvocationInterceptorChain.proceed(InvocationInterceptorChain.java:64)
        at org.junit.jupiter.engine.execution.InvocationInterceptorChain.chainAndInvoke(InvocationInterceptorChain.java:45)
        at org.junit.jupiter.engine.execution.InvocationInterceptorChain.invoke(InvocationInterceptorChain.java:37)
        at org.junit.jupiter.engine.execution.ExecutableInvoker.invoke(ExecutableInvoker.java:104)
        at org.junit.jupiter.engine.execution.ExecutableInvoker.invoke(ExecutableInvoker.java:98)
        at org.junit.jupiter.engine.descriptor.TestMethodTestDescriptor.lambda$invokeTestMethod$6(TestMethodTestDescriptor.java:210)
        at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
        at org.junit.jupiter.engine.descriptor.TestMethodTestDescriptor.invokeTestMethod(TestMethodTestDescriptor.java:206)
        at org.junit.jupiter.engine.descriptor.TestMethodTestDescriptor.execute(TestMethodTestDescriptor.java:131)
        at org.junit.jupiter.engine.descriptor.TestMethodTestDescriptor.execute(TestMethodTestDescriptor.java:65)
        at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$5(NodeTestTask.java:139)
        at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
        at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$7(NodeTestTask.java:129)
        at org.junit.platform.engine.support.hierarchical.Node.around(Node.java:137)
        at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$8(NodeTestTask.java:127)
        at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
        at org.junit.platform.engine.support.hierarchical.NodeTestTask.executeRecursively(NodeTestTask.java:126)
        at org.junit.platform.engine.support.hierarchical.NodeTestTask.execute(NodeTestTask.java:84)
        at java.base/java.util.ArrayList.forEach(ArrayList.java:1511)
        at org.junit.platform.engine.support.hierarchical.SameThreadHierarchicalTestExecutorService.invokeAll(SameThreadHierarchicalTestExecutorService.java:38)
        at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$5(NodeTestTask.java:143)
        at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
        at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$7(NodeTestTask.java:129)
        at org.junit.platform.engine.support.hierarchical.Node.around(Node.java:137)
        at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$8(NodeTestTask.java:127)
        at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
        at org.junit.platform.engine.support.hierarchical.NodeTestTask.executeRecursively(NodeTestTask.java:126)
        at org.junit.platform.engine.support.hierarchical.NodeTestTask.execute(NodeTestTask.java:84)
        at java.base/java.util.ArrayList.forEach(ArrayList.java:1511)
        at org.junit.platform.engine.support.hierarchical.SameThreadHierarchicalTestExecutorService.invokeAll(SameThreadHierarchicalTestExecutorService.java:38)
        at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$5(NodeTestTask.java:143)
        at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
        at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$7(NodeTestTask.java:129)
        at org.junit.platform.engine.support.hierarchical.Node.around(Node.java:137)
        at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$8(NodeTestTask.java:127)
        at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
        at org.junit.platform.engine.support.hierarchical.NodeTestTask.executeRecursively(NodeTestTask.java:126)
        at org.junit.platform.engine.support.hierarchical.NodeTestTask.execute(NodeTestTask.java:84)
        at org.junit.platform.engine.support.hierarchical.SameThreadHierarchicalTestExecutorService.submit(SameThreadHierarchicalTestExecutorService.java:32)
        at org.junit.platform.engine.support.hierarchical.HierarchicalTestExecutor.execute(HierarchicalTestExecutor.java:57)
        at org.junit.platform.engine.support.hierarchical.HierarchicalTestEngine.execute(HierarchicalTestEngine.java:51)
        at org.junit.platform.launcher.core.EngineExecutionOrchestrator.execute(EngineExecutionOrchestrator.java:108)
        at org.junit.platform.launcher.core.EngineExecutionOrchestrator.execute(EngineExecutionOrchestrator.java:88)
        at org.junit.platform.launcher.core.EngineExecutionOrchestrator.lambda$execute$0(EngineExecutionOrchestrator.java:54)
        at org.junit.platform.launcher.core.EngineExecutionOrchestrator.withInterceptedStreams(EngineExecutionOrchestrator.java:67)
        at org.junit.platform.launcher.core.EngineExecutionOrchestrator.execute(EngineExecutionOrchestrator.java:52)
        at org.junit.platform.launcher.core.DefaultLauncher.execute(DefaultLauncher.java:96)
        at org.junit.platform.launcher.core.DefaultLauncher.execute(DefaultLauncher.java:75)
        at org.apache.maven.surefire.junitplatform.JUnitPlatformProvider.execute(JUnitPlatformProvider.java:188)
        at org.apache.maven.surefire.junitplatform.JUnitPlatformProvider.invokeAllTests(JUnitPlatformProvider.java:154)
        at org.apache.maven.surefire.junitplatform.JUnitPlatformProvider.invoke(JUnitPlatformProvider.java:128)
        at org.apache.maven.surefire.booter.ForkedBooter.runSuitesInProcess(ForkedBooter.java:428)
        at org.apache.maven.surefire.booter.ForkedBooter.execute(ForkedBooter.java:162)
        at org.apache.maven.surefire.booter.ForkedBooter.run(ForkedBooter.java:562)
        at org.apache.maven.surefire.booter.ForkedBooter.main(ForkedBooter.java:548)
Caused by: java.io.IOException: An established connection was aborted by the software in your host machine
        at java.base/sun.nio.ch.SocketDispatcher.read0(Native Method)
        at java.base/sun.nio.ch.SocketDispatcher.read(SocketDispatcher.java:46)
        at java.base/sun.nio.ch.IOUtil.readIntoNativeBuffer(IOUtil.java:330)
        at java.base/sun.nio.ch.IOUtil.read(IOUtil.java:284)
        at java.base/sun.nio.ch.IOUtil.read(IOUtil.java:259)
        at java.base/sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:417)
        at io.netty.buffer.PooledByteBuf.setBytes(PooledByteBuf.java:256)
        at io.netty.buffer.AbstractByteBuf.writeBytes(AbstractByteBuf.java:1132)
        at io.netty.channel.socket.nio.NioSocketChannel.doReadBytes(NioSocketChannel.java:357)
        at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:151)
        at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:788)
        at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:724)
        at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:650)
        at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:562)
        at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:997)
        at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
        at io.helidon.common.context.Contexts.runInContext(Contexts.java:117)
        at io.helidon.common.context.ContextAwareExecutorImpl.lambda$wrap$7(ContextAwareExecutorImpl.java:154)
        at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
        at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
        at java.base/java.lang.Thread.run(Thread.java:833)

Here is some relevant snippet of logs with level ALL when the test fails:

2023.05.31 12:36:45 FINEST io.helidon.webclient.RequestContentSubscriber Thread[helidon-client-0,5,main]: (client reqID:1) Data chunk sent with result: true
2023.05.31 12:36:45 FINEST io.helidon.webclient.RequestContentSubscriber Thread[helidon-client-0,5,main]: (client reqID:1) Sending last http content
2023.05.31 12:36:45 FINEST io.helidon.webclient.NettyClientInitializer$ClientNettyLog Thread[helidon-client-0,5,main]: [id:0x04436acc, L:/127.0.0.1:50865 - R:localhost/127.0.0.1:50864] WRITE: 0B
2023.05.31 12:36:45 FINEST io.helidon.webclient.NettyClientInitializer$ClientNettyLog Thread[helidon-client-0,5,main]: [id:0x04436acc, L:/127.0.0.1:50865 - R:localhost/127.0.0.1:50864] FLUSH
2023.05.31 12:36:45 FINEST io.helidon.webclient.RequestContentSubscriber Thread[helidon-client-0,5,main]: (client reqID:1) Request sent
2023.05.31 12:36:45 FINEST io.helidon.webclient.NettyClientInitializer$ClientNettyLog Thread[helidon-client-0,5,main]: [id:0x04436acc, L:/127.0.0.1:50865 - R:localhost/127.0.0.1:50864] ACTIVE
2023.05.31 12:36:45 FINEST io.helidon.webclient.NettyClientInitializer$ClientNettyLog Thread[helidon-client-0,5,main]: [id:0x04436acc, L:/127.0.0.1:50865 - R:localhost/127.0.0.1:50864] READ COMPLETE
2023.05.31 12:36:45 FINEST io.helidon.webclient.NettyClientInitializer$ClientNettyLog Thread[helidon-client-0,5,main]: [id:0x04436acc, L:/127.0.0.1:50865 - R:localhost/127.0.0.1:50864] FLUSH
2023.05.31 12:36:45 FINEST io.helidon.webclient.NettyClientInitializer$ClientNettyLog Thread[helidon-client-0,5,main]: [id:0x04436acc, L:/127.0.0.1:50865 - R:localhost/127.0.0.1:50864] EXCEPTION: java.io.IOException:An established connection was aborted by the software in your host machine
java.io.IOException: An established connection was aborted by the software in your host machine
at java.base/sun.nio.ch.SocketDispatcher.read0(Native Method)
at java.base/sun.nio.ch.SocketDispatcher.read(SocketDispatcher.java:46)
at java.base/sun.nio.ch.IOUtil.readIntoNativeBuffer(IOUtil.java:330)
at java.base/sun.nio.ch.IOUtil.read(IOUtil.java:284)
at java.base/sun.nio.ch.IOUtil.read(IOUtil.java:259)
at java.base/sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:417)
at io.netty.buffer.PooledByteBuf.setBytes(PooledByteBuf.java:256)
at io.netty.buffer.AbstractByteBuf.writeBytes(AbstractByteBuf.java:1132)
at io.netty.channel.socket.nio.NioSocketChannel.doReadBytes(NioSocketChannel.java:357)
at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:151)
at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:788)
at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:724)
at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:650)
at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:562)
at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:997)
at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
at io.helidon.common.context.Contexts.runInContext(Contexts.java:117)
at io.helidon.common.context.ContextAwareExecutorImpl.lambda$wrap$7(ContextAwareExecutorImpl.java:154)
at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
at java.base/java.lang.Thread.run(Thread.java:833)
2023.05.31 12:36:45 FINEST io.helidon.webclient.NettyClientInitializer$ClientNettyLog Thread[helidon-client-0,5,main]: [id:0x04436acc, L:/127.0.0.1:50865 - R:localhost/127.0.0.1:50864] CLOSE
2023.05.31 12:36:45 FINEST io.helidon.webclient.NettyClientInitializer$ClientNettyLog Thread[helidon-client-0,5,main]: [id:0x04436acc, L:/127.0.0.1:50865 ! R:localhost/127.0.0.1:50864] USER_EVENT: io.netty.channel.socket.ChannelInputShutdownReadComplete@329967b1
2023.05.31 12:36:45 FINEST io.helidon.webclient.NettyClientInitializer$ClientNettyLog Thread[helidon-client-0,5,main]: [id:0x04436acc, L:/127.0.0.1:50865 ! R:localhost/127.0.0.1:50864] INACTIVE
2023.05.31 12:36:45 FINEST io.helidon.webclient.NettyClientInitializer$IdleConnectionHandler Thread[helidon-client-0,5,main]: Channel closed -> -220217593
2023.05.31 12:36:45 FINEST io.helidon.webclient.WebClientRequestBuilderImpl Thread[helidon-client-0,5,main]: Removing from channel cache. Connection ident ->  ConnectionIdent{base=http://localhost:50864, readTimeout=PT10M, proxy=io.helidon.webclient.Proxy@7d7ebe09, tls=io.helidon.webclient.WebClientTls@4338ae5f}, channel -> -220217593
2023.05.31 12:36:45 FINEST io.helidon.webclient.NettyClientInitializer$ClientNettyLog Thread[helidon-client-0,5,main]: [id:0x04436acc, L:/127.0.0.1:50865 ! R:localhost/127.0.0.1:50864] UNREGISTERED

Here is the equivalent when the test passes:

2023.05.31 12:22:50 FINEST io.helidon.webclient.RequestContentSubscriber Thread[helidon-client-0,5,main]: (client reqID:1) Data chunk sent with result: true
2023.05.31 12:22:50 FINEST io.helidon.webclient.RequestContentSubscriber Thread[helidon-client-0,5,main]: (client reqID:1) Sending last http content
2023.05.31 12:22:50 FINEST io.helidon.webclient.NettyClientInitializer$ClientNettyLog Thread[helidon-client-0,5,main]: [id:0x549ad5fb, L:/127.0.0.1:50829 - R:localhost/127.0.0.1:50828] WRITE: 0B
2023.05.31 12:22:50 FINEST io.helidon.webclient.NettyClientInitializer$ClientNettyLog Thread[helidon-client-0,5,main]: [id:0x549ad5fb, L:/127.0.0.1:50829 - R:localhost/127.0.0.1:50828] FLUSH
2023.05.31 12:22:50 FINEST io.helidon.webclient.RequestContentSubscriber Thread[helidon-client-0,5,main]: (client reqID:1) Request sent
2023.05.31 12:22:50 FINEST io.helidon.webclient.NettyClientInitializer$ClientNettyLog Thread[helidon-client-0,5,main]: [id:0x549ad5fb, L:/127.0.0.1:50829 - R:localhost/127.0.0.1:50828] ACTIVE
2023.05.31 12:22:50 FINEST io.helidon.common.serviceloader.HelidonServiceLoader Thread[nioEventLoopGroup-3-1,10,main]: Final order of enabled service implementations for service:java.util.ServiceLoader[io.helidon.webserver.spi.UpgradeCodecProvider]
2023.05.31 12:22:50 FINEST io.helidon.common.serviceloader.HelidonServiceLoader Thread[nioEventLoopGroup-3-1,10,main]: Final order of enabled service implementations for service:java.util.ServiceLoader[io.helidon.logging.common.spi.MdcProvider]
2023.05.31 12:22:50 FINEST io.helidon.webclient.NettyClientInitializer$ClientNettyLog Thread[helidon-client-0,5,main]: [id:0x549ad5fb, L:/127.0.0.1:50829 - R:localhost/127.0.0.1:50828] READ: 60B
+-------------------------------------------------+
|  0  1  2  3  4  5  6  7  8  9  a  b  c  d  e  f |
+--------+-------------------------------------------------+----------------+
|00000000| 48 54 54 50 2f 31 2e 31 20 34 31 33 20 52 65 71 |HTTP/1.1 413 Req|
|00000010| 75 65 73 74 20 45 6e 74 69 74 79 20 54 6f 6f 20 |uest Entity Too |
|00000020| 4c 61 72 67 65 0d 0a 63 6f 6e 6e 65 63 74 69 6f |Large..connectio|
|00000030| 6e 3a 20 63 6c 6f 73 65 0d 0a 0d 0a             |n: close....    |
+--------+-------------------------------------------------+----------------+
2023.05.31 12:22:50 WARNING io.helidon.webserver.ForwardingHandler Thread[nioEventLoopGroup-3-1,10,main]: 413:Payload is too large
2023.05.31 12:22:51 WARNING io.helidon.webserver.ForwardingHandler Thread[nioEventLoopGroup-3-1,10,main]: 413:Payload is too large
java.lang.Error: 413:Payload is too large
at io.helidon.webserver.ForwardingHandler.send413PayloadTooLarge(ForwardingHandler.java:565)
at io.helidon.webserver.ForwardingHandler.channelReadHttpRequest(ForwardingHandler.java:382)
at io.helidon.webserver.ForwardingHandler.lambda$channelRead0$3(ForwardingHandler.java:156)
at io.helidon.common.context.Contexts.runInContext(Contexts.java:137)
at io.helidon.webserver.ForwardingHandler.channelRead0(ForwardingHandler.java:155)
at io.netty.channel.SimpleChannelInboundHandler.channelRead(SimpleChannelInboundHandler.java:99)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:444)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420)
at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:412)
at io.netty.channel.CombinedChannelDuplexHandler$DelegatingChannelHandlerContext.fireChannelRead(CombinedChannelDuplexHandler.java:436)
at io.netty.handler.codec.ByteToMessageDecoder.fireChannelRead(ByteToMessageDecoder.java:346)
at io.netty.handler.codec.ByteToMessageDecoder.fireChannelRead(ByteToMessageDecoder.java:333)
at io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:454)
at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:290)
at io.netty.channel.CombinedChannelDuplexHandler.channelRead(CombinedChannelDuplexHandler.java:251)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:442)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420)
at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:412)
at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1410)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:440)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420)
at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:919)
at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:166)
at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:788)
at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:724)
at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:650)
at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:562)
at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:997)
at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
at java.base/java.lang.Thread.run(Thread.java:833)
2023.05.31 12:22:51 FINE io.netty.handler.codec.compression.Brotli Thread[helidon-client-0,5,main]: brotli4j not in the classpath; Brotli support will be unavailable.
2023.05.31 12:22:51 FINEST io.helidon.webclient.NettyClientHandler Thread[helidon-client-0,5,main]: (client reqID:1) Initial http response message received
2023.05.31 12:22:51 FINEST io.helidon.webclient.NettyClientHandler Thread[helidon-client-0,5,main]: (client reqID:1) Closing the response from the server
2023.05.31 12:22:51 FINEST io.helidon.webclient.NettyClientInitializer$ClientNettyLog Thread[helidon-client-0,5,main]: [id:0x549ad5fb, L:/127.0.0.1:50829 - R:localhost/127.0.0.1:50828] CLOSE
2023.05.31 12:22:51 FINEST io.helidon.webclient.NettyClientHandler Thread[helidon-client-0,5,main]: (client reqID:1) Response from the server has been closed
2023.05.31 12:22:51 FINEST io.helidon.webclient.NettyClientHandler Thread[helidon-client-0,5,main]: Response automatically closed. No entity expected
2023.05.31 12:22:51 FINEST io.helidon.webclient.NettyClientInitializer$ClientNettyLog Thread[helidon-client-0,5,main]: [id:0x549ad5fb, L:/127.0.0.1:50829 ! R:localhost/127.0.0.1:50828] READ COMPLETE
2023.05.31 12:22:51 FINEST io.helidon.webclient.NettyClientInitializer$ClientNettyLog Thread[helidon-client-0,5,main]: [id:0x549ad5fb, L:/127.0.0.1:50829 ! R:localhost/127.0.0.1:50828] FLUSH
2023.05.31 12:22:51 FINEST io.helidon.webclient.NettyClientInitializer$ClientNettyLog Thread[helidon-client-0,5,main]: [id:0x549ad5fb, L:/127.0.0.1:50829 ! R:localhost/127.0.0.1:50828] INACTIVE
2023.05.31 12:22:51 FINEST io.helidon.webclient.NettyClientInitializer$ClientNettyLog Thread[helidon-client-0,5,main]: [id:0x549ad5fb, L:/127.0.0.1:50829 ! R:localhost/127.0.0.1:50828] FLUSH
2023.05.31 12:22:51 FINEST io.helidon.webclient.NettyClientInitializer$IdleConnectionHandler Thread[helidon-client-0,5,main]: Channel closed -> -399084565
2023.05.31 12:22:51 FINEST io.helidon.webclient.WebClientRequestBuilderImpl Thread[helidon-client-0,5,main]: Removing from channel cache. Connection ident ->  ConnectionIdent{base=http://localhost:50828, readTimeout=PT10M, proxy=io.helidon.webclient.Proxy@7d7ebe09, tls=io.helidon.webclient.WebClientTls@4338ae5f}, channel -> -399084565
2023.05.31 12:22:51 FINEST io.helidon.webclient.NettyClientInitializer$ClientNettyLog Thread[helidon-client-0,5,main]: [id:0x549ad5fb, L:/127.0.0.1:50829 ! R:localhost/127.0.0.1:50828] UNREGISTERED

The key difference is that when it works we get this:

ACTIVE
READ: 60B
CLOSE
READ COMPLETE
FLUSH

However when it fails we get this:

ACTIVE
READ COMPLETE
FLUSH
EXCEPTION: java.io.IOException:An established connection was aborted by the software in your host machine

Since JDK13 and JEP 353 Windows Socket error codes use system messages.
The error message An established connection was aborted by the software in your host machine corresponds to the following:

Return code/value Description
WSAECONNABORTED
10053		 Software caused connection abort.
An established connection was aborted by the software in your host computer, possibly due to a data transmission time-out or protocol error.

I found a good explanation of this issue here: https://www.chilkatsoft.com/p/p_299.asp
Here is a TLDR:

  1. Client sends a request
  2. Server returns a response without reading the full request, and closes the connection
  3. Meanwhile, client is still writing data into an half-open connection, data is buffered to Winsock
  4. Outgoing retransmission fails and Winsock shuts down the connection
  5. Client fails to read the HTTP response

The test has been passing reliably on UNIX (Linux and MacOS), however it is clearly not reliable on Windows and it does not seem to be something we can fix with configuration.

We should avoid running this test on Windows for now.

If the test starts failing intermittently on UNIX, we can decide to re-write it to accept IOException as valid.
@spericas
Copy link
Member

spericas commented Jun 1, 2023

Seems like a rather OS specific behavior. There's a few things that we can potentially do:

  1. Make the payload in the test smaller hoping it gets sent in one chunk
  2. Handle IOException and either (a) try to read the response if possible or (b) simply accept the test as valid.

In general, handling the exception seems like a reasonable option. I would volunteer to explore this if I had a Win VM ready to go. Perhaps someone with such a VM or a machine can try these options.

@m0mus m0mus added the P3 label Jun 1, 2023
@spericas
Copy link
Member

spericas commented Jun 2, 2023

Updated test in @tvallin private branch. We can close this issue after further testing is completed.

@barchetta barchetta mentioned this issue Jun 3, 2023
Closed
@spericas
Copy link
Member

@tvallin Can we close this issue?

@tvallin
Copy link
Member

tvallin commented Jun 13, 2023

Yes, it can be closed !

@tvallin tvallin closed this as completed Jun 13, 2023
@tvallin tvallin mentioned this issue Mar 21, 2024
Open
@m0mus m0mus added this to Backlog Aug 12, 2024
@m0mus m0mus moved this to Closed in Backlog Aug 12, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@spericas spericas

Labels
3.x Issues for 3.x version branch intermittent P3 testing webclient webserver
Projects
Backlog
Archived in project
Milestone
No milestone
Development

No branches or pull requests
4 participants
@romain-grecourt @spericas @m0mus @tvallin