HttpClientCodec cannot upgrade to TLS according to RFC2817 #7293
Description
Expected behavior
- Client sends an OPTION request with
Connection: UpgradeandUpgrade: TLS/1.2headers. - The server installs an
SslHandler, responds withHTTP 101 Switching Protocolsand is ready to handle TLS handshake. - The client receives
HTTP 101, installsSslHandlerwhich initiates TLS handshake. - TLS handshake completes.
- The server sends the remaining final HTTP 200 response to the client, per requirement 3.3 of RFC2817: "Once the TLS handshake completes successfully, the server MUST continue with the response to the original request."
HttpClientCodecon the client side receives this response, decodes it and passes it down the pipeline asHttpResponseobject.
Actual behavior
Step 6. is broken.
6. HttpClientCodec on the client side receives the response content correctly (see log below), but does not decode it and passes it down the pipeline as a DirectByteBuf object.
TEST DEBUG [dsefs-netty-worker-1] 2017-10-12 16:44:28,513 i.n.h.l.LoggingHandler (Slf4JLogger.java:71) [id: 0xabe43583] CONNECT: localhost/127.0.0.1:6000
TEST DEBUG [dsefs-netty-worker-1] 2017-10-12 16:44:28,516 i.n.h.l.LoggingHandler (Slf4JLogger.java:71) [id: 0xabe43583, L:/127.0.0.1:47174 - R:localhost/127.0.0.1:6000] ACTIVE
TEST DEBUG [dsefs-netty-worker-1] 2017-10-12 16:44:28,516 c.d.b.f.r.c.StartTlsClientHandler (StartTlsClientHandler.scala:45) [id: 0xabe43583, L:/127.0.0.1:47174 - R:localhost/127.0.0.1:6000] Requesting connection upgrade to TLS/1.2
TEST DEBUG [dsefs-netty-worker-2] 2017-10-12 16:44:28,520 i.n.h.l.LoggingHandler (Slf4JLogger.java:71) [id: 0xceec753c, L:/127.0.0.1:6000 - R:/127.0.0.1:47174] REGISTERED
TEST DEBUG [dsefs-netty-worker-2] 2017-10-12 16:44:28,520 i.n.h.l.LoggingHandler (Slf4JLogger.java:71) [id: 0xceec753c, L:/127.0.0.1:6000 - R:/127.0.0.1:47174] ACTIVE
TEST DEBUG [dsefs-netty-worker-1] 2017-10-12 16:44:28,533 i.n.h.l.LoggingHandler (Slf4JLogger.java:71) [id: 0xabe43583, L:/127.0.0.1:47174 - R:localhost/127.0.0.1:6000] WRITE, DefaultFullHttpRequest(decodeResult: success, version: HTTP/1.1, content: UnpooledByteBufAllocator$In
strumentedUnpooledUnsafeHeapByteBuf(ridx: 0, widx: 0, cap: 0))
OPTIONS /info HTTP/1.1
connection: upgrade
upgrade: TLS/1.2, 0B
TEST DEBUG [dsefs-netty-worker-1] 2017-10-12 16:44:28,535 i.n.u.Recycler (Slf4JLogger.java:76) -Dio.netty.recycler.maxCapacityPerThread: 32768
TEST DEBUG [dsefs-netty-worker-1] 2017-10-12 16:44:28,535 i.n.u.Recycler (Slf4JLogger.java:76) -Dio.netty.recycler.maxSharedCapacityFactor: 2
TEST DEBUG [dsefs-netty-worker-1] 2017-10-12 16:44:28,535 i.n.u.Recycler (Slf4JLogger.java:76) -Dio.netty.recycler.linkCapacity: 16
TEST DEBUG [dsefs-netty-worker-1] 2017-10-12 16:44:28,536 i.n.u.Recycler (Slf4JLogger.java:76) -Dio.netty.recycler.ratio: 8
TEST DEBUG [dsefs-netty-worker-1] 2017-10-12 16:44:28,545 i.n.h.l.LoggingHandler (Slf4JLogger.java:71) [id: 0xabe43583, L:/127.0.0.1:47174 - R:localhost/127.0.0.1:6000] FLUSH
TEST DEBUG [dsefs-netty-worker-2] 2017-10-12 16:44:28,547 i.n.h.l.LoggingHandler (Slf4JLogger.java:71) [id: 0xceec753c, L:/127.0.0.1:6000 - R:/127.0.0.1:47174] READ: DefaultHttpRequest(decodeResult: success, version: HTTP/1.1)
OPTIONS /info HTTP/1.1
connection: upgrade
upgrade: TLS/1.2
TEST DEBUG [dsefs-netty-worker-2] 2017-10-12 16:44:28,567 i.n.h.l.LoggingHandler (Slf4JLogger.java:71) [id: 0xceec753c, L:/127.0.0.1:6000 - R:/127.0.0.1:47174] READ, EmptyLastHttpContent, 0B
TEST DEBUG [dsefs-netty-worker-2] 2017-10-12 16:44:28,568 i.n.h.l.LoggingHandler (Slf4JLogger.java:71) [id: 0xceec753c, L:/127.0.0.1:6000 - R:/127.0.0.1:47174] READ COMPLETE
TEST DEBUG [dsefs-netty-worker-2] 2017-10-12 16:44:28,568 c.d.b.f.r.s.StartTlsServerHandler (StartTlsServerHandler.scala:51) [id: 0xceec753c, L:/127.0.0.1:6000 - R:/127.0.0.1:47174] Requested to upgrade connection to TLS/1.2
TEST DEBUG [dsefs-netty-worker-2] 2017-10-12 16:44:28,592 i.n.h.s.OpenSsl (Slf4JLogger.java:71) netty-tcnative not in the classpath; OpenSslEngine will be unavailable.
TEST DEBUG [dsefs-netty-worker-2] 2017-10-12 16:44:28,655 i.n.h.s.JdkSslContext (Slf4JLogger.java:76) Default protocols (JDK): [TLSv1.2, TLSv1.1, TLSv1]
TEST DEBUG [dsefs-netty-worker-2] 2017-10-12 16:44:28,656 i.n.h.s.JdkSslContext (Slf4JLogger.java:76) Default cipher suites (JDK): [TLS_ECDHE_ECDSA_WITH_AES_128_GCM_SHA256, TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256, TLS_ECDHE_RSA_WITH_AES_128_CBC_SHA, TLS_RSA_WITH_AES_128_GCM_SHA2
56, TLS_RSA_WITH_AES_128_CBC_SHA]
TEST DEBUG [dsefs-netty-worker-2] 2017-10-12 16:44:28,657 c.d.b.f.r.s.StartTlsServerHandler (StartTlsServerHandler.scala:58) [id: 0xceec753c, L:/127.0.0.1:6000 - R:/127.0.0.1:47174] Upgrading connection to TLS/1.2
TEST DEBUG [dsefs-netty-worker-2] 2017-10-12 16:44:28,666 i.n.h.l.LoggingHandler (Slf4JLogger.java:71) [id: 0xceec753c, L:/127.0.0.1:6000 - R:/127.0.0.1:47174] WRITE, DefaultFullHttpResponse(decodeResult: success, version: HTTP/1.1, content: UnpooledByteBufAllocator$Instrument
edUnpooledUnsafeHeapByteBuf(ridx: 0, widx: 0, cap: 0))
HTTP/1.1 101 Switching Protocols
connection: Upgrade
upgrade: TLS/1.2, HTTP/1.1
content-length: 0, 0B
TEST DEBUG [dsefs-netty-worker-2] 2017-10-12 16:44:28,668 i.n.h.l.LoggingHandler (Slf4JLogger.java:71) [id: 0xceec753c, L:/127.0.0.1:6000 - R:/127.0.0.1:47174] FLUSH
TEST DEBUG [dsefs-netty-worker-1] 2017-10-12 16:44:28,670 i.n.h.l.LoggingHandler (Slf4JLogger.java:71) [id: 0xabe43583, L:/127.0.0.1:47174 - R:localhost/127.0.0.1:6000] READ: DefaultHttpResponse(decodeResult: success, version: HTTP/1.1)
HTTP/1.1 101 Switching Protocols
connection: Upgrade
upgrade: TLS/1.2, HTTP/1.1
content-length: 0
TEST DEBUG [dsefs-netty-worker-1] 2017-10-12 16:44:28,670 c.d.b.f.r.c.StartTlsClientHandler (StartTlsClientHandler.scala:80) Client received: DefaultHttpResponse(decodeResult: success, version: HTTP/1.1)
HTTP/1.1 101 Switching Protocols
connection: Upgrade
upgrade: TLS/1.2, HTTP/1.1
content-length: 0
TEST DEBUG [dsefs-netty-worker-1] 2017-10-12 16:44:28,671 i.n.h.l.LoggingHandler (Slf4JLogger.java:71) [id: 0xabe43583, L:/127.0.0.1:47174 - R:localhost/127.0.0.1:6000] READ, EmptyLastHttpContent, 0B
TEST DEBUG [dsefs-netty-worker-1] 2017-10-12 16:44:28,671 c.d.b.f.r.c.StartTlsClientHandler (StartTlsClientHandler.scala:80) Client received: EmptyLastHttpContent
TEST DEBUG [dsefs-netty-worker-1] 2017-10-12 16:44:28,672 c.d.b.f.r.c.StartTlsClientHandler (StartTlsClientHandler.scala:54) [id: 0xabe43583, L:/127.0.0.1:47174 - R:localhost/127.0.0.1:6000] Upgrading connection to TLS/1.2
TEST DEBUG [dsefs-netty-worker-1] 2017-10-12 16:44:28,685 c.d.b.f.r.c.StartTlsClientHandler (StartTlsClientHandler.scala:60) ****** PIPELINE after adding SSL: DefaultChannelPipeline{(SslHandler#0 = io.netty.handler.ssl.SslHandler), (HttpClientCodec#0 = io.netty.handler.codec.h
ttp.HttpClientCodec), (LoggingHandler#0 = io.netty.handler.logging.LoggingHandler), (StartTlsClientHandler#0 = com.datastax.bdp.fs.rest.client.StartTlsClientHandler), (StartTlsHandlerSpec$HelloClient$HelloHandler#0 = com.datastax.bdp.fs.rest.StartTlsHandlerSpec$HelloClient$HelloH
andler)}
TEST DEBUG [dsefs-netty-worker-1] 2017-10-12 16:44:28,685 i.n.h.l.LoggingHandler (Slf4JLogger.java:71) [id: 0xabe43583, L:/127.0.0.1:47174 - R:localhost/127.0.0.1:6000] READ COMPLETE
TEST DEBUG [dsefs-netty-worker-2] 2017-10-12 16:44:28,701 i.n.h.l.LoggingHandler (Slf4JLogger.java:71) [id: 0xceec753c, L:/127.0.0.1:6000 - R:/127.0.0.1:47174] READ COMPLETE
TEST DEBUG [dsefs-netty-worker-1] 2017-10-12 16:44:28,773 i.n.h.l.LoggingHandler (Slf4JLogger.java:71) [id: 0xabe43583, L:/127.0.0.1:47174 - R:localhost/127.0.0.1:6000] READ COMPLETE
TEST DEBUG [dsefs-netty-worker-2] 2017-10-12 16:44:28,776 i.n.h.s.SslHandler (Slf4JLogger.java:81) [id: 0xceec753c, L:/127.0.0.1:6000 - R:/127.0.0.1:47174] HANDSHAKEN: TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256
TEST DEBUG [dsefs-netty-worker-2] 2017-10-12 16:44:28,778 i.n.h.l.LoggingHandler (Slf4JLogger.java:71) [id: 0xceec753c, L:/127.0.0.1:6000 - R:/127.0.0.1:47174] USER_EVENT: SslHandshakeCompletionEvent(SUCCESS)
TEST DEBUG [dsefs-netty-worker-2] 2017-10-12 16:44:28,778 i.n.h.l.LoggingHandler (Slf4JLogger.java:71) [id: 0xceec753c, L:/127.0.0.1:6000 - R:/127.0.0.1:47174] READ COMPLETE
TEST DEBUG [dsefs-netty-worker-2] 2017-10-12 16:44:28,778 i.n.h.l.LoggingHandler (Slf4JLogger.java:71) [id: 0xceec753c, L:/127.0.0.1:6000 - R:/127.0.0.1:47174] WRITE, DefaultFullHttpResponse(decodeResult: success, version: HTTP/1.1, content: UnpooledByteBufAllocator$Instrument
edUnpooledUnsafeHeapByteBuf(ridx: 0, widx: 0, cap: 0))
HTTP/1.1 200 OK
content-length: 0, 0B
TEST DEBUG [dsefs-netty-worker-2] 2017-10-12 16:44:28,779 i.n.h.l.LoggingHandler (Slf4JLogger.java:71) [id: 0xceec753c, L:/127.0.0.1:6000 - R:/127.0.0.1:47174] FLUSH
TEST DEBUG [dsefs-netty-worker-1] 2017-10-12 16:44:28,779 i.n.h.s.SslHandler (Slf4JLogger.java:81) [id: 0xabe43583, L:/127.0.0.1:47174 - R:localhost/127.0.0.1:6000] HANDSHAKEN: TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256
TEST DEBUG [dsefs-netty-worker-1] 2017-10-12 16:44:28,779 i.n.h.l.LoggingHandler (Slf4JLogger.java:71) [id: 0xabe43583, L:/127.0.0.1:47174 - R:localhost/127.0.0.1:6000] USER_EVENT: SslHandshakeCompletionEvent(SUCCESS)
TEST DEBUG [dsefs-netty-worker-1] 2017-10-12 16:44:28,779 i.n.h.l.LoggingHandler (Slf4JLogger.java:71) [id: 0xabe43583, L:/127.0.0.1:47174 - R:localhost/127.0.0.1:6000] READ COMPLETE
TEST DEBUG [dsefs-netty-worker-1] 2017-10-12 16:44:28,780 i.n.h.l.LoggingHandler (Slf4JLogger.java:71) [id: 0xabe43583, L:/127.0.0.1:47174 - R:localhost/127.0.0.1:6000] READ: 38B
+-------------------------------------------------+
| 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 32 30 30 20 4f 4b 0d |HTTP/1.1 200 OK.|
|00000010| 0a 63 6f 6e 74 65 6e 74 2d 6c 65 6e 67 74 68 3a |.content-length:|
|00000020| 20 30 0d 0a 0d 0a | 0.... |
+--------+-------------------------------------------------+----------------+
TEST DEBUG [dsefs-netty-worker-1] 2017-10-12 16:44:28,780 c.d.b.f.r.c.StartTlsClientHandler (StartTlsClientHandler.scala:80) Client received: PooledUnsafeDirectByteBuf(ridx: 0, widx: 38, cap: 38)
TEST WARN [dsefs-netty-worker-1] 2017-10-12 16:44:28,785 i.n.c.DefaultChannelPipeline (Slf4JLogger.java:151) An exceptionCaught() event was fired, and it reached at the tail of the pipeline. It usually means the last handler in the pipeline did not handle the exception.
java.lang.IllegalStateException: Received unexpected PooledUnsafeDirectByteBuf(ridx: 0, widx: 38, cap: 38) in state com.datastax.bdp.fs.rest.client.StartTlsClientHandler$State$SwitchingProtocolFullyReceived$@430445ac
at com.datastax.bdp.fs.rest.client.StartTlsClientHandler.channelRead0(StartTlsClientHandler.scala:121) ~[main/:na]
Steps to reproduce
Probably requires most of the code I'm writing that is unfortunately closed source. Would have to get permission to post the test.
Minimal yet complete reproducer code (or URL to code)
Netty version
Originally found in 4.1.13, but the problem exists in recent 4.0.x and 4.1.17 as well.
JVM version (e.g. java -version)
1.8.0_144
OS version (e.g. uname -a)
Linux p5520 4.14.0-041400rc4-generic #201710100030 SMP Tue Oct 10 04:31:55 UTC 2017 x86_64 x86_64 x86_64 GNU/Linux
Please let me know if there is any workaround...