search

helidon-io / helidon

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

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

Closed romain-grecourt closed 1 year ago

romain-grecourt commented 1 year ago

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 commented 1 year ago

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.

spericas commented 1 year ago

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

spericas commented 1 year ago

@tvallin Can we close this issue?

tvallin commented 1 year ago

Yes, it can be closed !