You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@tomcat.apache.org by bu...@apache.org on 2019/09/23 18:03:41 UTC
[Bug 63765] New: NIO2 Connector with OpenSSL 1.1.1 hangs with
TLSv1.3
https://bz.apache.org/bugzilla/show_bug.cgi?id=63765
Bug ID: 63765
Summary: NIO2 Connector with OpenSSL 1.1.1 hangs with TLSv1.3
Product: Tomcat 9
Version: 9.0.x
Hardware: PC
OS: Linux
Status: NEW
Severity: normal
Priority: P2
Component: Connectors
Assignee: dev@tomcat.apache.org
Reporter: csutherl@apache.org
Target Milestone: -----
Created attachment 36793
--> https://bz.apache.org/bugzilla/attachment.cgi?id=36793&action=edit
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
--
You are receiving this mail because:
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org
[Bug 63765] NIO2 Connector with OpenSSL 1.1.1 hangs with TLSv1.3
Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=63765
--- Comment #7 from Remy Maucherat <re...@apache.org> ---
(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 ...
--
You are receiving this mail because:
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org
[Bug 63765] NIO2 Connector with OpenSSL 1.1.1 hangs with TLSv1.3
Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=63765
--- Comment #2 from Coty Sutherland <cs...@apache.org> ---
> 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.
--
You are receiving this mail because:
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org
[Bug 63765] NIO2 Connector with OpenSSL 1.1.1 hangs with TLSv1.3
Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=63765
--- Comment #3 from Rainer Jung <ra...@kippdata.de> ---
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
--
You are receiving this mail because:
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org
[Bug 63765] NIO2 Connector with OpenSSL 1.1.1 hangs with TLSv1.3
Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=63765
--- Comment #6 from Rainer Jung <ra...@kippdata.de> ---
(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.
--
You are receiving this mail because:
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org
[Bug 63765] NIO2 Connector with OpenSSL 1.1.1 hangs with TLSv1.3
Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=63765
Remy Maucherat <re...@apache.org> changed:
What |Removed |Added
----------------------------------------------------------------------------
Resolution|--- |FIXED
Status|NEW |RESOLVED
--- Comment #8 from Remy Maucherat <re...@apache.org> ---
The fix will be in 9.0.27 and 8.5.47.
--
You are receiving this mail because:
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org
[Bug 63765] NIO2 Connector with OpenSSL 1.1.1 hangs with TLSv1.3
Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=63765
--- Comment #4 from Rainer Jung <ra...@kippdata.de> ---
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]
...
--
You are receiving this mail because:
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org
[Bug 63765] NIO2 Connector with OpenSSL 1.1.1 hangs with TLSv1.3
Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=63765
--- Comment #1 from Remy Maucherat <re...@apache.org> ---
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.
--
You are receiving this mail because:
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org
[Bug 63765] NIO2 Connector with OpenSSL 1.1.1 hangs with TLSv1.3
Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=63765
--- Comment #5 from Rainer Jung <ra...@kippdata.de> ---
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]
--
You are receiving this mail because:
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org