Created attachment 36793 [details] curl -v output from the failed request and a successful one immediately after The first request to Tomcat after a restart always hangs (on two of my machines) and fails with an "Empty reply from server" after one minute when using NIO2 with JSSE+OpenSSL limited to the TLSv1.3 protocol. If you wait for the request to end, or terminate it, then the subsequent requests succeed without issue. I've tried to trace it down, but I don't see any activity in Tomcat to hint at where this would be :( From my curl output, it's after the handshake is done. My environment is Fedora 30 laptop using a local build of Tomcat master (9.0.27-dev), tomcat-native (1.2.23-dev), APR 1.6.5, and OpenSSL 1.1.1.c. To reproduce: 1) Configure your Connector <Connector port="8443" protocol="org.apache.coyote.http11.Http11Nio2Protocol" maxThreads="150" SSLEnabled="true" > <SSLHostConfig protocols="TLSv1.3"> <Certificate certificateKeyFile="conf/localhost.server.key.pem" certificateFile="conf/localhost.server.cert.pem" certificateKeyPassword="changeit" certificateChainFile="conf/ca-chain.cert.pem" type="RSA" /> </SSLHostConfig> </Connector> 2) Start tomcat 3) Initiate a request with curl and observe the one minute delay and empty response curl --insecure -v https://localhost:8443
This looked like the usual not-unwrapping-enough "IO" issue, so changing the initial value of unwrapBeforeRead to true in SecureNio2Channel.reset avoids it. Not sure if it is 100% safe (although it looks rather similar to NIO with its non blocking read returning 0). I cannot reproduce this that reliably personally, it may be only visible on localhost.
> I cannot reproduce this that reliably personally, it may be only visible on localhost. Weird. I can reproduce this between two machines as well, so it doesn't seem to be a lo only issue.
I can also reproduce on SLES 12 and RHEL 7 but not on Solaris. For me it does not happen with a real remote connection, but always with local ones and with connections from another virtual guest on the same host system, so specifics of the IP stack might be relevant. I am using tcnative 1.2.23 build against APR 1.7.0 and OpenSSL 1.1.1d. My curl is 7.66.0 also build against OpenSSL 1.1.1d. Java is 1.8.0, also observable with Java 11. TC is TC9 git 6a173978c5865421192578da21ec8f418e5a3da4 (2019-09-19). Some debug log lines: End of startup: 24-Sep-2019 13:48:29.200 INFO [main] org.apache.catalina.startup.Catalina.start Server startup in [2,003] milliseconds Start of request: 24-Sep-2019 13:49:09.410 FINE [https-openssl-nio2-8443-exec-3] org.apache.tomcat.util.threads.LimitLatch.countUpOrAwait Counting up[https-openssl-nio2-8443-exec-3] latch=1 24-Sep-2019 13:49:09.436 FINE [https-openssl-nio2-8443-exec-2] org.apache.tomcat.util.net.SecureNio2Channel.processSNI The SNI host name extracted for connection [sun.nio.ch.UnixAsynchronousSocketChannelImpl[connected local=/0:0:0:0:0:0:0:1:8443 remote=/0:0:0:0:0:0:0:1:50367]] was [localhost] 24-Sep-2019 13:49:09.457 FINE [https-openssl-nio2-8443-exec-4] org.apache.coyote.AbstractProtocol$ConnectionHandler.process Processing socket [org.apache.tomcat.util.net.SecureNio2Channel@76110ba6:sun.nio.ch.UnixAsynchronousSocketChannelImpl[connected local=/0:0:0:0:0:0:0:1:8443 remote=/0:0:0:0:0:0:0:1:50367]] with status [OPEN_READ] 24-Sep-2019 13:49:09.457 FINE [https-openssl-nio2-8443-exec-4] org.apache.coyote.AbstractProtocol$ConnectionHandler.process Found processor [null] for socket [org.apache.tomcat.util.net.SecureNio2Channel@76110ba6:sun.nio.ch.UnixAsynchronousSocketChannelImpl[connected local=/0:0:0:0:0:0:0:1:8443 remote=/0:0:0:0:0:0:0:1:50367]] 24-Sep-2019 13:49:09.458 FINE [https-openssl-nio2-8443-exec-4] org.apache.coyote.AbstractProtocol$ConnectionHandler.process Popped processor [null] from cache 24-Sep-2019 13:49:09.493 FINE [https-openssl-nio2-8443-exec-4] org.apache.coyote.AbstractProtocol$ConnectionHandler.register Register Catalina:type=RequestProcessor,worker="https-openssl-nio2-8443",name=HttpRequest1 24-Sep-2019 13:49:09.497 FINE [https-openssl-nio2-8443-exec-4] org.apache.tomcat.util.net.SocketWrapperBase.populateReadBuffer Socket: [org.apache.tomcat.util.net.Nio2Endpoint$Nio2SocketWrapper@4ed079d9:org.apache.tomcat.util.net.SecureNio2Channel@76110ba6:sun.nio.ch.UnixAsynchronousSocketChannelImpl[connected local=/0:0:0:0:0:0:0:1:8443 remote=/0:0:0:0:0:0:0:1:50367]], Read from buffer: [0] 24-Sep-2019 13:49:09.499 FINE [https-openssl-nio2-8443-exec-4] org.apache.tomcat.util.net.Nio2Endpoint$Nio2SocketWrapper.read Socket: [org.apache.tomcat.util.net.Nio2Endpoint$Nio2SocketWrapper@4ed079d9:org.apache.tomcat.util.net.SecureNio2Channel@76110ba6:sun.nio.ch.UnixAsynchronousSocketChannelImpl[connected local=/0:0:0:0:0:0:0:1:8443 remote=/0:0:0:0:0:0:0:1:50367]], Read into buffer: [0] 24-Sep-2019 13:49:09.499 FINE [https-openssl-nio2-8443-exec-4] org.apache.coyote.AbstractProcessorLight.process Socket: [org.apache.tomcat.util.net.Nio2Endpoint$Nio2SocketWrapper@4ed079d9:org.apache.tomcat.util.net.SecureNio2Channel@76110ba6:sun.nio.ch.UnixAsynchronousSocketChannelImpl[connected local=/0:0:0:0:0:0:0:1:8443 remote=/0:0:0:0:0:0:0:1:50367]], Status in: [OPEN_READ], State out: [OPEN] 24-Sep-2019 13:49:09.500 FINE [https-openssl-nio2-8443-exec-4] org.apache.coyote.AbstractProtocol$ConnectionHandler.release Pushed Processor [org.apache.coyote.http11.Http11Processor@20d73a43] then the hang occurs. After a minute, curl gets "empty reply from server" and the logs show: 24-Sep-2019 13:50:09.501 FINE [https-openssl-nio2-8443-exec-6] org.apache.coyote.AbstractProtocol$ConnectionHandler.process Processing socket [org.apache.tomcat.util.net.SecureNio2Channel@76110ba6:sun.nio.ch.UnixAsynchronousSocketChannelImpl[connected local=/0:0:0:0:0:0:0:1:8443 remote=/0:0:0:0:0:0:0:1:50367]] with status [ERROR] 24-Sep-2019 13:50:09.502 FINE [https-openssl-nio2-8443-exec-6] org.apache.coyote.AbstractProtocol$ConnectionHandler.process Found processor [null] for socket [org.apache.tomcat.util.net.SecureNio2Channel@76110ba6:sun.nio.ch.UnixAsynchronousSocketChannelImpl[connected local=/0:0:0:0:0:0:0:1:8443 remote=/0:0:0:0:0:0:0:1:50367]] 24-Sep-2019 13:50:09.502 FINE [https-openssl-nio2-8443-exec-6] org.apache.tomcat.util.net.Nio2Endpoint$Nio2SocketWrapper.doClose Calling [org.apache.tomcat.util.net.Nio2Endpoint@6d79b7f7].closeSocket([org.apache.tomcat.util.net.Nio2Endpoint$Nio2SocketWrapper@4ed079d9:org.apache.tomcat.util.net.SecureNio2Channel@76110ba6:sun.nio.ch.UnixAsynchronousSocketChannelImpl[connected local=/0:0:0:0:0:0:0:1:8443 remote=/0:0:0:0:0:0:0:1:50367]]) java.lang.Exception at org.apache.tomcat.util.net.Nio2Endpoint$Nio2SocketWrapper.doClose(Nio2Endpoint.java:915) at org.apache.tomcat.util.net.SocketWrapperBase.close(SocketWrapperBase.java:394) at org.apache.tomcat.util.net.Nio2Endpoint$SocketProcessor.doRun(Nio2Endpoint.java:1682) at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61) at java.lang.Thread.run(Thread.java:748) 24-Sep-2019 13:50:09.502 FINE [https-openssl-nio2-8443-exec-6] org.apache.tomcat.util.threads.LimitLatch.countDown Counting down[https-openssl-nio2-8443-exec-6] latch=1 Regards, Rainer
For comparison the Nio (not NIO2) log snippet where the request works: 24-Sep-2019 13:54:40.068 FINE [https-openssl-nio-8443-Acceptor] org.apache.tomcat.util.threads.LimitLatch.countUpOrAwait Counting up[https-openssl-nio-8443-Acceptor] latch=1 24-Sep-2019 13:54:40.076 FINE [https-openssl-nio-8443-exec-1] org.apache.tomcat.util.net.SecureNioChannel.processSNI The SNI host name extracted for connection [java.nio.channels.SocketChannel[connected local=/0:0:0:0:0:0:0:1:8443 remote=/0:0:0:0:0:0:0:1:51197]] was [localhost] 24-Sep-2019 13:54:40.094 FINE [https-openssl-nio-8443-exec-3] org.apache.coyote.AbstractProtocol$ConnectionHandler.process Processing socket [org.apache.tomcat.util.net.SecureNioChannel@39172781:java.nio.channels.SocketChannel[connected local=/0:0:0:0:0:0:0:1:8443 remote=/0:0:0:0:0:0:0:1:51197]] with status [OPEN_READ] 24-Sep-2019 13:54:40.095 FINE [https-openssl-nio-8443-exec-3] org.apache.coyote.AbstractProtocol$ConnectionHandler.process Found processor [null] for socket [org.apache.tomcat.util.net.SecureNioChannel@39172781:java.nio.channels.SocketChannel[connected local=/0:0:0:0:0:0:0:1:8443 remote=/0:0:0:0:0:0:0:1:51197]] 24-Sep-2019 13:54:40.095 FINE [https-openssl-nio-8443-exec-3] org.apache.coyote.AbstractProtocol$ConnectionHandler.process Popped processor [null] from cache 24-Sep-2019 13:54:40.132 FINE [https-openssl-nio-8443-exec-3] org.apache.coyote.AbstractProtocol$ConnectionHandler.register Register Catalina:type=RequestProcessor,worker="https-openssl-nio-8443",name=HttpRequest1 24-Sep-2019 13:54:40.135 FINE [https-openssl-nio-8443-exec-3] org.apache.tomcat.util.net.SocketWrapperBase.populateReadBuffer Socket: [org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper@6c99b5c8:org.apache.tomcat.util.net.SecureNioChannel@39172781:java.nio.channels.SocketChannel[connected local=/0:0:0:0:0:0:0:1:8443 remote=/0:0:0:0:0:0:0:1:51197]], Read from buffer: [0] Looks the same until here, but now Nio does: 24-Sep-2019 13:54:40.136 FINE [https-openssl-nio-8443-exec-3] org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper.read Socket: [org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper@6c99b5c8:org.apache.tomcat.util.net.SecureNioChannel@39172781:java.nio.channels.SocketChannel[connected local=/0:0:0:0:0:0:0:1:8443 remote=/0:0:0:0:0:0:0:1:51197]], Read direct from socket: [78] 24-Sep-2019 13:54:40.136 FINE [https-openssl-nio-8443-exec-3] org.apache.coyote.http11.Http11InputBuffer.parseRequestLine Received [GET / HTTP/1.1 Host: localhost:8443 User-Agent: curl/7.66.0 Accept: */* ] 24-Sep-2019 13:54:40.161 FINE [https-openssl-nio-8443-exec-3] org.apache.tomcat.util.http.Parameters.setQueryStringCharset Set query string encoding to UTF-8 24-Sep-2019 13:54:40.375 FINE [https-openssl-nio-8443-exec-3] org.apache.tomcat.util.net.SocketWrapperBase.populateReadBuffer Socket: [org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper@6c99b5c8:org.apache.tomcat.util.net.SecureNioChannel@39172781:java.nio.channels.SocketChannel[connected local=/0:0:0:0:0:0:0:1:8443 remote=/0:0:0:0:0:0:0:1:51197]], Read from buffer: [0] 24-Sep-2019 13:54:40.376 FINE [https-openssl-nio-8443-exec-3] org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper.read Socket: [org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper@6c99b5c8:org.apache.tomcat.util.net.SecureNioChannel@39172781:java.nio.channels.SocketChannel[connected local=/0:0:0:0:0:0:0:1:8443 remote=/0:0:0:0:0:0:0:1:51197]], Read direct from socket: [0] 24-Sep-2019 13:54:40.377 FINE [https-openssl-nio-8443-exec-3] org.apache.coyote.AbstractProcessorLight.process Socket: [org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper@6c99b5c8:org.apache.tomcat.util.net.SecureNioChannel@39172781:java.nio.channels.SocketChannel[connected local=/0:0:0:0:0:0:0:1:8443 remote=/0:0:0:0:0:0:0:1:51197]], Status in: [OPEN_READ], State out: [OPEN] ...
And here Nio2 using TLS 1.2: ... 24-Sep-2019 15:16:55.232 FINE [https-openssl-nio2-8443-exec-4] org.apache.tomcat.util.net.SocketWrapperBase.populateReadBuffer Socket: [org.apache.tomcat.util.net.Nio2Endpoint$Nio2SocketWrapper@281c779a:org.apache.tomcat.util.net.SecureNio2Channel@1f564c66:sun.nio.ch.UnixAsynchronousSocketChannelImpl[connected local=/0:0:0:0:0:0:0:1:8443 remote=/0:0:0:0:0:0:0:1:19684]], Read from buffer: [0] but now 24-Sep-2019 15:16:55.236 FINE [https-openssl-nio2-8443-exec-4] org.apache.tomcat.util.net.Nio2Endpoint$Nio2SocketWrapper$2.completed Socket: [org.apache.tomcat.util.net.Nio2Endpoint$Nio2SocketWrapper@281c779a:org.apache.tomcat.util.net.SecureNio2Channel@1f564c66:sun.nio.ch.UnixAsynchronousSocketChannelImpl[connected local=/0:0:0:0:0:0:0:1:8443 remote=/0:0:0:0:0:0:0:1:19684]], Interest: [false] 24-Sep-2019 15:16:55.237 FINE [https-openssl-nio2-8443-exec-4] org.apache.tomcat.util.net.Nio2Endpoint$Nio2SocketWrapper.read Socket: [org.apache.tomcat.util.net.Nio2Endpoint$Nio2SocketWrapper@281c779a:org.apache.tomcat.util.net.SecureNio2Channel@1f564c66:sun.nio.ch.UnixAsynchronousSocketChannelImpl[connected local=/0:0:0:0:0:0:0:1:8443 remote=/0:0:0:0:0:0:0:1:19684]], Read into buffer: [78] 24-Sep-2019 15:16:55.237 FINE [https-openssl-nio2-8443-exec-4] org.apache.tomcat.util.net.SocketWrapperBase.populateReadBuffer Socket: [org.apache.tomcat.util.net.Nio2Endpoint$Nio2SocketWrapper@281c779a:org.apache.tomcat.util.net.SecureNio2Channel@1f564c66:sun.nio.ch.UnixAsynchronousSocketChannelImpl[connected local=/0:0:0:0:0:0:0:1:8443 remote=/0:0:0:0:0:0:0:1:19684]], Read from buffer: [78]
(In reply to Remy Maucherat from comment #1) > This looked like the usual not-unwrapping-enough "IO" issue, so changing the > initial value of unwrapBeforeRead to true in SecureNio2Channel.reset avoids > it. Not sure if it is 100% safe (although it looks rather similar to NIO > with its non blocking read returning 0). > I cannot reproduce this that reliably personally, it may be only visible on > localhost. At least it fixes the problem for me: diff --git a/java/org/apache/tomcat/util/net/SecureNio2Channel.java b/java/org/apache/tomcat/util/net/SecureNio2Channel.java index 9e5ab07ea0..da899b26aa 100644 --- a/java/org/apache/tomcat/util/net/SecureNio2Channel.java +++ b/java/org/apache/tomcat/util/net/SecureNio2Channel.java @@ -132,6 +132,7 @@ public class SecureNio2Channel extends Nio2Channel { handshakeComplete = false; closed = false; closing = false; + unwrapBeforeRead = true; netInBuffer.clear(); } Can't say whether it is safe though.
(In reply to Rainer Jung from comment #6) > Can't say whether it is safe though. It likely sounds safe to unwrap first (it would do an underflow and cause a read) reading some previous comment: https://github.com/apache/tomcat/commit/3f3dfc63e12e816d68f1a2e21e80d77513e2a2d4 At least I am not getting any test issues so it's worth trying ...
The fix will be in 9.0.27 and 8.5.47.