Created attachment 999759 [details] Simple war with static content Description of problem: When having defined https with NIO2 connector [1] and doing multiple requests in parallel it results in Exceptions being written in debug log [2]. The exception is usually ClosedChannelException [3] or IOException [4]. Version-Release number of selected component (if applicable): EAP 6.4.0.ER3 How reproducible: always Steps to Reproduce: 1. Unzip EAP distro 2. Deploy attached test.war (contains some static files with different byte length) 3. Load certificate and keystore to $JBOSS_HOME/standalone 4. Configure https and set protocol to NIO2 ([1] or see attached config) 5. Enable debug logging for "org.apache" ([2] or see attached config) 6. Do concurrent requests via ApacheBench (ab -n 3 -c 2 -Z DHE-RSA-AES256-SHA -v 3 https://127.0.0.1:8443/test/f256) Actual results: Requests are processed and exception is shown in debug (all exceptions which occur on the channel are logged as debug) Expected results: Requests are processed without the exception being thrown Additional info: This behaviour was detected only with enabled ssl (https). [1] <connector name="https" protocol="org.apache.coyote.http11.Http11NioProtocol" scheme="https" socket-binding="https" enabled="true"> <ssl name="http-perf" key-alias="jboss" password="jbossas" certificate-key-file="${jboss.server.base.dir}/server.keystore" cipher-suite="ALL" protocol="TLSv1" verify-client="none" certificate-file="${jboss.server.base.dir}/server.crt"/> </connector> [2] To enable debug logging for org.apache: <logger category="org.apache"> <level name="DEBUG"/> </logger> [3] 14:21:16,832 DEBUG [org.apache.coyote.http11] (http-/127.0.0.1:8443-70) JBWEB003064: Error during blocking read: java.nio.channels.ClosedChannelException at org.apache.tomcat.util.net.jsse.SecureNioChannel.readBytes(SecureNioChannel.java:130) [jbossweb-7.5.7.Final-redhat-1.jar:7.5.7.Final-redhat-1] at org.apache.coyote.http11.InternalNioInputBuffer.fill0(InternalNioInputBuffer.java:515) [jbossweb-7.5.7.Final-redhat-1.jar:7.5.7.Final-redhat-1] at org.apache.coyote.http11.InternalNioInputBuffer.fill(InternalNioInputBuffer.java:469) [jbossweb-7.5.7.Final-redhat-1.jar:7.5.7.Final-redhat-1] at org.apache.coyote.http11.InternalNioInputBuffer.parseRequestLine(InternalNioInputBuffer.java:285) [jbossweb-7.5.7.Final-redhat-1.jar:7.5.7.Final-redhat-1] at org.apache.coyote.http11.Http11NioProcessor.process(Http11NioProcessor.java:290) [jbossweb-7.5.7.Final-redhat-1.jar:7.5.7.Final-redhat-1] at org.apache.coyote.http11.Http11NioProtocol$Http11ConnectionHandler.process(Http11NioProtocol.java:911) [jbossweb-7.5.7.Final-redhat-1.jar:7.5.7.Final-redhat-1] at org.apache.tomcat.util.net.NioEndpoint$ChannelProcessor.run(NioEndpoint.java:936) [jbossweb-7.5.7.Final-redhat-1.jar:7.5.7.Final-redhat-1] at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) [rt.jar:1.7.0_75] at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) [rt.jar:1.7.0_75] at org.apache.tomcat.util.net.NioEndpoint$DefaultThreadFactory$1$1.run(NioEndpoint.java:1249) [jbossweb-7.5.7.Final-redhat-1.jar:7.5.7.Final-redhat-1] at java.lang.Thread.run(Thread.java:745) [rt.jar:1.7.0_75] [4] This is one of IO Exceptions I am seeing in log: 14:24:01,962 DEBUG [org.apache.tomcat.util] (http-/127.0.0.1:8443-93) JBWEB003023: Channel processing failed: javax.net.ssl.SSLException: java.util.concurrent.ExecutionException: java.io.IOException: Broken pipe at org.apache.tomcat.util.net.jsse.SecureNioChannel.handshake(SecureNioChannel.java:636) [jbossweb-7.5.7.Final-redhat-1.jar:7.5.7.Final-redhat-1] at org.apache.tomcat.util.net.jsse.NioJSSESocketChannelFactory.handshake(NioJSSESocketChannelFactory.java:227) [jbossweb-7.5.7.Final-redhat-1.jar:7.5.7.Final-redhat-1] at org.apache.tomcat.util.net.NioEndpoint$HandshakeHandler.run(NioEndpoint.java:635) [jbossweb-7.5.7.Final-redhat-1.jar:7.5.7.Final-redhat-1] at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) [rt.jar:1.7.0_75] at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) [rt.jar:1.7.0_75] at org.apache.tomcat.util.net.NioEndpoint$DefaultThreadFactory$1$1.run(NioEndpoint.java:1249) [jbossweb-7.5.7.Final-redhat-1.jar:7.5.7.Final-redhat-1] at java.lang.Thread.run(Thread.java:745) [rt.jar:1.7.0_75] Caused by: java.util.concurrent.ExecutionException: java.io.IOException: Broken pipe at sun.nio.ch.CompletedFuture.get(CompletedFuture.java:69) [rt.jar:1.7.0_75] at org.apache.tomcat.util.net.jsse.SecureNioChannel.doHandshake(SecureNioChannel.java:754) [jbossweb-7.5.7.Final-redhat-1.jar:7.5.7.Final-redhat-1] at org.apache.tomcat.util.net.jsse.SecureNioChannel.handshake(SecureNioChannel.java:634) [jbossweb-7.5.7.Final-redhat-1.jar:7.5.7.Final-redhat-1] ... 6 more Caused by: java.io.IOException: Broken pipe at sun.nio.ch.FileDispatcherImpl.write0(Native Method) [rt.jar:1.7.0_75] at sun.nio.ch.SocketDispatcher.write(SocketDispatcher.java:47) [rt.jar:1.7.0_75] at sun.nio.ch.IOUtil.writeFromNativeBuffer(IOUtil.java:93) [rt.jar:1.7.0_75] at sun.nio.ch.IOUtil.write(IOUtil.java:51) [rt.jar:1.7.0_75] at sun.nio.ch.UnixAsynchronousSocketChannelImpl.implWrite(UnixAsynchronousSocketChannelImpl.java:691) [rt.jar:1.7.0_75] at sun.nio.ch.AsynchronousSocketChannelImpl.write(AsynchronousSocketChannelImpl.java:381) [rt.jar:1.7.0_75] at sun.nio.ch.AsynchronousSocketChannelImpl.write(AsynchronousSocketChannelImpl.java:386) [rt.jar:1.7.0_75] ... 8 more
Created attachment 999761 [details] Example config file
Created attachment 999762 [details] Server certificate
Created attachment 999763 [details] Server key
Since this looked 100% SSL related, I tried porting the Tomcat changes to handle incomplete writes, and this does seem to fix the issues for me.
So is it possible to test with the change I committed ?
I have tried it with the committed change [1] and I am getting still the same behaviour, I am still seeing [2] in debug log. Could it be somehow related to "Connection: close" header send by ApacheBench client for non keep alive connections? [1] https://source.jboss.org/changelog/JBossWeb?cs=2597 [2] 11:20:33,412 DEBUG [org.apache.tomcat.util] (http-/127.0.0.1:8443-9) JBWEB003023: Channel processing failed: javax.net.ssl.SSLException: java.util.concurrent.ExecutionException: java.io.IOException: Broken pipe at org.apache.tomcat.util.net.jsse.SecureNioChannel.handshake(SecureNioChannel.java:642) [jbossweb-7.5.7.Final.jar:7.5.7.Final] at org.apache.tomcat.util.net.jsse.NioJSSESocketChannelFactory.handshake(NioJSSESocketChannelFactory.java:227) [jbossweb-7.5.7.Final.jar:7.5.7.Final] at org.apache.tomcat.util.net.NioEndpoint$HandshakeHandler.run(NioEndpoint.java:635) [jbossweb-7.5.7.Final.jar:7.5.7.Final] at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) [rt.jar:1.7.0_75] at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) [rt.jar:1.7.0_75] at org.apache.tomcat.util.net.NioEndpoint$DefaultThreadFactory$1$1.run(NioEndpoint.java:1249) [jbossweb-7.5.7.Final.jar:7.5.7.Final] at java.lang.Thread.run(Thread.java:745) [rt.jar:1.7.0_75] Caused by: java.util.concurrent.ExecutionException: java.io.IOException: Broken pipe at sun.nio.ch.CompletedFuture.get(CompletedFuture.java:69) [rt.jar:1.7.0_75] at org.apache.tomcat.util.net.jsse.SecureNioChannel.doHandshake(SecureNioChannel.java:760) [jbossweb-7.5.7.Final.jar:7.5.7.Final] at org.apache.tomcat.util.net.jsse.SecureNioChannel.handshake(SecureNioChannel.java:640) [jbossweb-7.5.7.Final.jar:7.5.7.Final] ... 6 more Caused by: java.io.IOException: Broken pipe at sun.nio.ch.FileDispatcherImpl.write0(Native Method) [rt.jar:1.7.0_75] at sun.nio.ch.SocketDispatcher.write(SocketDispatcher.java:47) [rt.jar:1.7.0_75] at sun.nio.ch.IOUtil.writeFromNativeBuffer(IOUtil.java:93) [rt.jar:1.7.0_75] at sun.nio.ch.IOUtil.write(IOUtil.java:51) [rt.jar:1.7.0_75] at sun.nio.ch.UnixAsynchronousSocketChannelImpl.implWrite(UnixAsynchronousSocketChannelImpl.java:691) [rt.jar:1.7.0_75] at sun.nio.ch.AsynchronousSocketChannelImpl.write(AsynchronousSocketChannelImpl.java:381) [rt.jar:1.7.0_75] at sun.nio.ch.AsynchronousSocketChannelImpl.write(AsynchronousSocketChannelImpl.java:386) [rt.jar:1.7.0_75] ... 8 more
I'm not running into any handshake issue, but let's assume there's a problem there. Can you verify the keepalive variant too by adding -k ? Handshake occurs less often obviously, and I think the rest is probably fine now.
With keepalive variant it also behaves still the same => via two concurrent clients sending three messages results in only two messages written to access log, third timeouts on ApacheBench side. I am going to debug it a little bit more and if I find out anything interesting, I will post here my findings.
Ok, something went wrong again during my testing, so problem solved.
According to my testing, hopefully correct now (...), it seems sendfile is causing the issue in this case and can be disabled to fix it. I will continue testing.
I have tried it with disabled sendfile done in [1] and I no longer see the issues connected to both bugs. [1] https://source.jboss.org/changelog/JBossWeb?cs=2598
Disabled sendfile on NIO2 connector makes all data to be transmitted as whole in both cases (for connection using keep-alive and without it). => The main issue is fixed, nevertheless I still see for non keep-alive connections the exception described in comment 9 in debug log. Not sure why I haven't notice during pretesting. There seems that there are still remaining some incomplete writes resulting in exception being thrown even when all data were already delivered to client (from statistics of apachebench client I see that client received all the data)
This issue is partially fixed. The first and main issue was that not all data were delivered to requestor, which is now fixed. The second is that there occurs exception (IO exception or closed channel exception) in debug log of JBoss Web. The first part is fixed, the second isn't as the exceptions still occur with non-keepalive connection. Hypothesis is that there are still attempts to write to the channel which is closed in the meantime resulting in the broken pipe exceptions in the log.
From the ab client the behaviour seems correct (all requested data are recieved). The exceptions in the debug log needs to be further investigated.
Comment 9 is an exception during handshake, so if it is exclusively this one it is not related to the other issue.
Yes, the exception I am seeing is the one from comment 9.
As per https://bugzilla.redhat.com/show_bug.cgi?id=1200276#c28 the functionality works and the exception is a 'debug' exception thrown during connection setup. If we really want to deal with that exception differently we should have a new BZ (which I might just consider a RFE).
I have created separate BZ#1225403 to track the occurrence of the exception in the debug log during handshaking. Setting this one as verified as per comment 27 and comment 28 the behaviour is otherwise correct and the exception in log appears as different issue tracked now in separate BZ.
Retroactively bulk-closing issues from released EAP 6.4 cummulative patches.