I'm trying to write a HTTP client using Netty 5.0.0.Alpha2 to connect to a proprietary server. I can only describe the connection as being similar to Websockets but not. The server utilizes StartTLS which is expected to be initialized by the client after the server responds with 200 and Content Type and if you don't, the server disconnects you. Once the connection is secure, the server will keep the connection alive indefinitely while responding to client commands. Anyways, below is my SSLDump log and regarding the line "Unknown SSL content type 1", this happens once I try to send my first command to the server. Traffic from the server seems to be unhindered since the server sends a ping heartbeat every 30-60 seconds and I can read it just fine.
SSLDump log:
New TCP connection #1: Chiori-chan.local(54679) <-> ***.***.***.***(443)
0.1110 (0.1110) C>S
---------------------------------------------------------------
GET /fwd/xControl HTTP/1.0
---------------------------------------------------------------
0.1776 (0.0666) S>C
---------------------------------------------------------------
HTTP/1.0 200 OK
Content-Type: application/octet-stream
---------------------------------------------------------------
0.2440 (0.0664) S>C
---------------------------------------------------------------
---------------------------------------------------------------
1 1 0.2582 (0.0142) C>SV3.1(54) Handshake
ClientHello
Version 3.1
random[32]=
55 0c 50 be 81 96 8d 83 b2 8d 91 fd 02 3d f5 ff
1e 9d 65 48 3a 3b 8c a1 63 d4 e1 17 45 24 c8 90
cipher suites
TLS_RSA_WITH_RC4_128_SHA
TLS_RSA_WITH_RC4_128_MD5
compression methods
NULL
1 2 0.3332 (0.0749) S>CV3.1(81) Handshake
ServerHello
Version 3.1
random[32]=
fb 50 d9 c3 2d f2 b1 2f 43 ac 69 eb 54 6b 79 1e
34 68 0b e8 5b 90 74 d8 0a bd 0e 46 be 9b 80 54
session_id[32]=
cf 67 a2 86 b4 c0 26 08 6a f4 4c 86 16 8a da df
34 fc da 75 66 cd 38 a6 c6 42 21 cf 3e a4 c9 73
cipherSuite TLS_RSA_WITH_RC4_128_SHA
compressionMethod NULL
1 3 0.3332 (0.0000) S>CV3.1(471) Handshake
Certificate
certificate[461]=
30 82 01 ... omitted ... fa 3f 56
1 4 0.3332 (0.0000) S>CV3.1(4) Handshake
ServerHelloDone
1 5 0.3490 (0.0157) C>SV3.1(134) Handshake
ClientKeyExchange
EncryptedPreMasterSecret[128]=
c5 f6 2e ... omitted ... 4b f2 64
1 6 0.3490 (0.0000) C>SV3.1(1) ChangeCipherSpec
1 7 0.3490 (0.0000) C>SV3.1(36) Handshake
1 8 0.4161 (0.0671) S>CV3.1(1) ChangeCipherSpec
1 9 0.4161 (0.0000) S>CV3.1(36) Handshake
Unknown SSL content type 1
1 10 0.4891 (0.0729) S>CV3.1(22) Alert
1 11 0.4892 (0.0001) S>CV3.1(22) Alert
1 12 0.4893 (0.0000) S>CV3.1(22) Alert
1 13 0.4930 (0.0036) C>SShort record
1 2.7379 (2.2449) C>S TCP FIN
1 2.8043 (0.0663) S>C TCP FIN
Java log:
Mar 20, 2015 11:54:21 AM io.netty.handler.logging.LoggingHandler channelRegistered
INFO: [id: 0x811e4e4d] REGISTERED
Mar 20, 2015 11:54:21 AM io.netty.handler.logging.LoggingHandler connect
INFO: [id: 0x811e4e4d] CONNECT: /omitted:443
Mar 20, 2015 11:54:21 AM io.netty.handler.logging.LoggingHandler channelActive
INFO: [id: 0x811e4e4d, /10.0.0.152:54679 => /omitted:443] ACTIVE
Mar 20, 2015 11:54:22 AM io.netty.handler.logging.LoggingHandler write
INFO: [id: 0x811e4e4d, /10.0.0.152:54679 => /omitted:443] WRITE: 40B
GET /fwd/xControl HTTP/1.0
Mar 20, 2015 11:54:22 AM io.netty.handler.logging.LoggingHandler flush
INFO: [id: 0x811e4e4d, /10.0.0.152:54679 => /omitted:443] FLUSH
Mar 20, 2015 11:54:22 AM io.netty.handler.logging.LoggingHandler channelRead
INFO: [id: 0x811e4e4d, /10.0.0.152:54679 => /omitted:443] RECEIVED: 57B
HTTP/1.0 200 OK
Content-Type: application/octet-stream
Mar 20, 2015 11:54:22 AM io.netty.handler.logging.LoggingHandler channelRead
INFO: [id: 0x811e4e4d, /10.0.0.152:54679 => /omitted:443] RECEIVED: 2B
+-------------------------------------------------+
| 0 1 2 3 4 5 6 7 8 9 a b c d e f |
+--------+-------------------------------------------------+----------------+
|00000000| 0d 0a |.. |
+--------+-------------------------------------------------+----------------+
RCVD: DefaultHttpResponse(decodeResult: success, version: HTTP/1.0)
HTTP/1.0 200 OK
Content-Type: application/octet-stream
Mar 20, 2015 11:54:22 AM io.netty.handler.logging.LoggingHandler userEventTriggered
INFO: [id: 0x811e4e4d, /10.0.0.152:54679 => /omitted:443] USER_EVENT: io.netty.handler.ssl.SslHandshakeCompletionEvent@1dc9b12c
Mar 20, 2015 11:54:22 AM io.netty.handler.logging.LoggingHandler write
INFO: [id: 0x811e4e4d, /10.0.0.152:54679 => /omitted:443] WRITE: 66B
+-------------------------------------------------+
| 0 1 2 3 4 5 6 7 8 9 a b c d e f |
+--------+-------------------------------------------------+----------------+
|00000000| 01 00 1a 00 16 00 00 00 0b 03 06 05 7e 4c 47 49 |............~LGI|
|00000010| 4e 03 00 00 00 00 00 98 9a c0 0b 02 02 02 01 00 |N...............|
|00000020| 20 00 1c 00 00 00 0b 03 06 05 7e 4c 47 49 4e 03 | .........~LGIN.|
|00000030| 00 00 00 00 00 9c 9a c0 0b 02 06 05 61 64 6d 69 |............admi|
|00000040| 6e 02 |n. |
+--------+-------------------------------------------------+----------------+
Mar 20, 2015 11:54:22 AM io.netty.handler.logging.LoggingHandler flush
INFO: [id: 0x811e4e4d, /10.0.0.152:54679 => /omitted:443] FLUSH
Mar 20, 2015 11:54:22 AM io.netty.handler.logging.LoggingHandler exceptionCaught
INFO: [id: 0x811e4e4d, /10.0.0.152:54679 => /omitted:443] EXCEPTION: io.netty.handler.codec.DecoderException: javax.net.ssl.SSLException: Received fatal alert: protocol_version
io.netty.handler.codec.DecoderException: javax.net.ssl.SSLException: Received fatal alert: protocol_version
at io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:347)
at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:230)
at io.netty.channel.ChannelHandlerInvokerUtil.invokeChannelReadNow(ChannelHandlerInvokerUtil.java:84)
at io.netty.channel.DefaultChannelHandlerInvoker.invokeChannelRead(DefaultChannelHandlerInvoker.java:153)
at io.netty.channel.PausableChannelEventExecutor.invokeChannelRead(PausableChannelEventExecutor.java:86)
at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:389)
at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:956)
at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:127)
at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:514)
at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:471)
at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:385)
at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:351)
at io.netty.util.concurrent.SingleThreadEventExecutor$2.run(SingleThreadEventExecutor.java:116)
at io.netty.util.internal.chmv8.ForkJoinTask$RunnableExecuteAction.exec(ForkJoinTask.java:1412)
at io.netty.util.internal.chmv8.ForkJoinTask.doExec(ForkJoinTask.java:280)
at io.netty.util.internal.chmv8.ForkJoinPool$WorkQueue.runTask(ForkJoinPool.java:877)
at io.netty.util.internal.chmv8.ForkJoinPool.scan(ForkJoinPool.java:1706)
at io.netty.util.internal.chmv8.ForkJoinPool.runWorker(ForkJoinPool.java:1661)
at io.netty.util.internal.chmv8.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:126)
Caused by: javax.net.ssl.SSLException: Received fatal alert: protocol_version
at sun.security.ssl.Alerts.getSSLException(Alerts.java:208)
at sun.security.ssl.SSLEngineImpl.fatal(SSLEngineImpl.java:1619)
at sun.security.ssl.SSLEngineImpl.fatal(SSLEngineImpl.java:1587)
at sun.security.ssl.SSLEngineImpl.recvAlert(SSLEngineImpl.java:1756)
at sun.security.ssl.SSLEngineImpl.readRecord(SSLEngineImpl.java:1060)
at sun.security.ssl.SSLEngineImpl.readNetRecord(SSLEngineImpl.java:884)
at sun.security.ssl.SSLEngineImpl.unwrap(SSLEngineImpl.java:758)
at javax.net.ssl.SSLEngine.unwrap(SSLEngine.java:624)
at io.netty.handler.ssl.SslHandler.unwrap(SslHandler.java:1071)
at io.netty.handler.ssl.SslHandler.unwrap(SslHandler.java:938)
at io.netty.handler.ssl.SslHandler.decode(SslHandler.java:891)
at io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:316)
... 18 more
Mar 20, 2015 11:54:22 AM io.netty.channel.DefaultChannelPipeline$TailContext exceptionCaught
WARNING: 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.
io.netty.handler.codec.DecoderException: javax.net.ssl.SSLException: Received fatal alert: protocol_version
at io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:347)
at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:230)
at io.netty.channel.ChannelHandlerInvokerUtil.invokeChannelReadNow(ChannelHandlerInvokerUtil.java:84)
at io.netty.channel.DefaultChannelHandlerInvoker.invokeChannelRead(DefaultChannelHandlerInvoker.java:153)
at io.netty.channel.PausableChannelEventExecutor.invokeChannelRead(PausableChannelEventExecutor.java:86)
at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:389)
at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:956)
at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:127)
at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:514)
at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:471)
at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:385)
at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:351)
at io.netty.util.concurrent.SingleThreadEventExecutor$2.run(SingleThreadEventExecutor.java:116)
at io.netty.util.internal.chmv8.ForkJoinTask$RunnableExecuteAction.exec(ForkJoinTask.java:1412)
at io.netty.util.internal.chmv8.ForkJoinTask.doExec(ForkJoinTask.java:280)
at io.netty.util.internal.chmv8.ForkJoinPool$WorkQueue.runTask(ForkJoinPool.java:877)
at io.netty.util.internal.chmv8.ForkJoinPool.scan(ForkJoinPool.java:1706)
at io.netty.util.internal.chmv8.ForkJoinPool.runWorker(ForkJoinPool.java:1661)
at io.netty.util.internal.chmv8.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:126)
Caused by: javax.net.ssl.SSLException: Received fatal alert: protocol_version
at sun.security.ssl.Alerts.getSSLException(Alerts.java:208)
at sun.security.ssl.SSLEngineImpl.fatal(SSLEngineImpl.java:1619)
at sun.security.ssl.SSLEngineImpl.fatal(SSLEngineImpl.java:1587)
at sun.security.ssl.SSLEngineImpl.recvAlert(SSLEngineImpl.java:1756)
at sun.security.ssl.SSLEngineImpl.readRecord(SSLEngineImpl.java:1060)
at sun.security.ssl.SSLEngineImpl.readNetRecord(SSLEngineImpl.java:884)
at sun.security.ssl.SSLEngineImpl.unwrap(SSLEngineImpl.java:758)
at javax.net.ssl.SSLEngine.unwrap(SSLEngine.java:624)
at io.netty.handler.ssl.SslHandler.unwrap(SslHandler.java:1071)
at io.netty.handler.ssl.SslHandler.unwrap(SslHandler.java:938)
at io.netty.handler.ssl.SslHandler.decode(SslHandler.java:891)
at io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:316)
... 18 more
Mar 20, 2015 11:54:22 AM io.netty.handler.logging.LoggingHandler exceptionCaught
INFO: [id: 0x811e4e4d, /10.0.0.152:54679 => /omitted:443] EXCEPTION: io.netty.handler.codec.DecoderException: javax.net.ssl.SSLException: Received fatal alert: bad_record_mac
io.netty.handler.codec.DecoderException: javax.net.ssl.SSLException: Received fatal alert: bad_record_mac
at io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:347)
at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:230)
at io.netty.channel.ChannelHandlerInvokerUtil.invokeChannelReadNow(ChannelHandlerInvokerUtil.java:84)
at io.netty.channel.DefaultChannelHandlerInvoker.invokeChannelRead(DefaultChannelHandlerInvoker.java:153)
at io.netty.channel.PausableChannelEventExecutor.invokeChannelRead(PausableChannelEventExecutor.java:86)
at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:389)
at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:956)
at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:127)
at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:514)
at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:471)
at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:385)
at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:351)
at io.netty.util.concurrent.SingleThreadEventExecutor$2.run(SingleThreadEventExecutor.java:116)
at io.netty.util.internal.chmv8.ForkJoinTask$RunnableExecuteAction.exec(ForkJoinTask.java:1412)
at io.netty.util.internal.chmv8.ForkJoinTask.doExec(ForkJoinTask.java:280)
at io.netty.util.internal.chmv8.ForkJoinPool$WorkQueue.runTask(ForkJoinPool.java:877)
at io.netty.util.internal.chmv8.ForkJoinPool.scan(ForkJoinPool.java:1706)
at io.netty.util.internal.chmv8.ForkJoinPool.runWorker(ForkJoinPool.java:1661)
at io.netty.util.internal.chmv8.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:126)
Caused by: javax.net.ssl.SSLException: Received fatal alert: bad_record_mac
at sun.security.ssl.Alerts.getSSLException(Alerts.java:208)
at sun.security.ssl.SSLEngineImpl.fatal(SSLEngineImpl.java:1619)
at sun.security.ssl.SSLEngineImpl.fatal(SSLEngineImpl.java:1587)
at sun.security.ssl.SSLEngineImpl.recvAlert(SSLEngineImpl.java:1756)
at sun.security.ssl.SSLEngineImpl.readRecord(SSLEngineImpl.java:1060)
at sun.security.ssl.SSLEngineImpl.readNetRecord(SSLEngineImpl.java:884)
at sun.security.ssl.SSLEngineImpl.unwrap(SSLEngineImpl.java:758)
at javax.net.ssl.SSLEngine.unwrap(SSLEngine.java:624)
at io.netty.handler.ssl.SslHandler.unwrap(SslHandler.java:1071)
at io.netty.handler.ssl.SslHandler.unwrap(SslHandler.java:938)
at io.netty.handler.ssl.SslHandler.decode(SslHandler.java:891)
at io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:316)
... 18 more
Mar 20, 2015 11:54:22 AM io.netty.channel.DefaultChannelPipeline$TailContext exceptionCaught
WARNING: 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.
io.netty.handler.codec.DecoderException: javax.net.ssl.SSLException: Received fatal alert: bad_record_mac
at io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:347)
at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:230)
at io.netty.channel.ChannelHandlerInvokerUtil.invokeChannelReadNow(ChannelHandlerInvokerUtil.java:84)
at io.netty.channel.DefaultChannelHandlerInvoker.invokeChannelRead(DefaultChannelHandlerInvoker.java:153)
at io.netty.channel.PausableChannelEventExecutor.invokeChannelRead(PausableChannelEventExecutor.java:86)
at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:389)
at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:956)
at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:127)
at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:514)
at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:471)
at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:385)
at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:351)
at io.netty.util.concurrent.SingleThreadEventExecutor$2.run(SingleThreadEventExecutor.java:116)
at io.netty.util.internal.chmv8.ForkJoinTask$RunnableExecuteAction.exec(ForkJoinTask.java:1412)
at io.netty.util.internal.chmv8.ForkJoinTask.doExec(ForkJoinTask.java:280)
at io.netty.util.internal.chmv8.ForkJoinPool$WorkQueue.runTask(ForkJoinPool.java:877)
at io.netty.util.internal.chmv8.ForkJoinPool.scan(ForkJoinPool.java:1706)
at io.netty.util.internal.chmv8.ForkJoinPool.runWorker(ForkJoinPool.java:1661)
at io.netty.util.internal.chmv8.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:126)
Caused by: javax.net.ssl.SSLException: Received fatal alert: bad_record_mac
at sun.security.ssl.Alerts.getSSLException(Alerts.java:208)
at sun.security.ssl.SSLEngineImpl.fatal(SSLEngineImpl.java:1619)
at sun.security.ssl.SSLEngineImpl.fatal(SSLEngineImpl.java:1587)
at sun.security.ssl.SSLEngineImpl.recvAlert(SSLEngineImpl.java:1756)
at sun.security.ssl.SSLEngineImpl.readRecord(SSLEngineImpl.java:1060)
at sun.security.ssl.SSLEngineImpl.readNetRecord(SSLEngineImpl.java:884)
at sun.security.ssl.SSLEngineImpl.unwrap(SSLEngineImpl.java:758)
at javax.net.ssl.SSLEngine.unwrap(SSLEngine.java:624)
at io.netty.handler.ssl.SslHandler.unwrap(SslHandler.java:1071)
at io.netty.handler.ssl.SslHandler.unwrap(SslHandler.java:938)
at io.netty.handler.ssl.SslHandler.decode(SslHandler.java:891)
at io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:316)
... 18 more
Could someone please explain to me why I would be getting this error and what I could do to remedy it? I first thought it was the type of object I was using to write the data, i.e. ByteBuf, but I tried many other objects and it seemed to have no effect. I'm certain there's an obvious cause, I'm just not seeing it. I'm pretty new to using SSL with Netty and it's also a shame that I can't find as much documentation as I would think Netty would feature being as widely used as it is.
I would appreciate any help people could offer.
Edit:
Interestingly, using the server (Also Netty and Java) I programmed using same SSL Engine claims it can also make the connection but where it should be receiving my command, it prints this error. This would lead me to believe my client is not properly encoding the ssl packet since the record it reports is in plaintext.
Mar 20, 2015 3:18:36 PM io.netty.channel.DefaultChannelPipeline$TailHandler exceptionCaught
WARNING: 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.
io.netty.handler.ssl.NotSslRecordException: not an SSL/TLS record: 01000c00080000000b01060470696e67
at io.netty.handler.ssl.SslHandler.decode(SslHandler.java:832)
at io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:228)
at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:141)
at io.netty.channel.DefaultChannelHandlerContext.invokeChannelRead(DefaultChannelHandlerContext.java:341)
at io.netty.channel.DefaultChannelHandlerContext.fireChannelRead(DefaultChannelHandlerContext.java:327)
at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:785)
at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:116)
at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:494)
at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:461)
at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:378)
at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:350)
at io.netty.util.concurrent.SingleThreadEventExecutor$2.run(SingleThreadEventExecutor.java:116)
at java.lang.Thread.run(Thread.java:745)
It would seem I'm a total idiot. Like I said, I'm new at using SSL with Netty.
Turns out within my code under my constructor for SslHandler() there is a second optional boolean named startTLS. If set to True the SslHandler will output your first message as plaintext. I was confused by the javadoc which said StartTLS is the communication pattern that secures the wire in the middle of the plaintext connection. Please note that it is different from SSL/TLS, that secures the wire from the beginning of the connection.
and because I was starting the SSL after the HTTP headers were sent, I assumed that StartTLS was what I wanted.
Again, I'm disappointed in the lack of Netty Documentation I can find. I'm just relieved that this silly issue is now fixed and I can proceed with reverse engineering this network protocol.