No communication after SSL handshake - HTTPS over JMS
I've been trying to setup my JMS connection to use HTTPS running on Wildfly 8.2. My server configuration and client application are identical to the instructions specified in the recent post https://developer.jboss.org/message/933591?tstart=0#933591.
The connection when I run connectionFactory.createTopicConnection("user", "omitted") throws the following exception.
Exception in thread "main" javax.jms.JMSException: Failed to create session factory
at org.hornetq.jms.client.HornetQConnectionFactory.createConnectionInternal(HornetQConnectionFactory.java:673)
at org.hornetq.jms.client.HornetQConnectionFactory.createTopicConnection(HornetQConnectionFactory.java:193)
at com.example.JmsClient.sendRequest(JmsClient.java:81)
at com.example.JmsClient.main(JmsClient.java:51)
Caused by: HornetQConnectionTimedOutException[errorType=CONNECTION_TIMEDOUT message=HQ119013: Timed out waiting to receive cluster topology. Group:null]
at org.hornetq.core.client.impl.ServerLocatorImpl.createSessionFactory(ServerLocatorImpl.java:946)
at org.hornetq.jms.client.HornetQConnectionFactory.createConnectionInternal(HornetQConnectionFactory.java:669)
... 3 more
Looking at the logs, it seems like SSL handshaking is successful, however once the client/server reach Cached client/server session: [Session-2, TLS_ECDHE_RSA_WITH_AES_128_CBC_SHA], there is no activity for ~10 seconds, and then the connection closes and the client throws the following error.
Thread-0 (HornetQ-client-netty-threads-1443391944), fatal error: 80: Inbound closed before receiving peer's close_notify: possible truncation attack?
javax.net.ssl.SSLException: Inbound closed before receiving peer's close_notify: possible truncation attack?
%% Invalidated: [Session-2, TLS_ECDHE_RSA_WITH_AES_128_CBC_SHA]
Thread-0 (HornetQ-client-netty-threads-1443391944), SEND SSLv3 ALERT: fatal, description = internal_error
Thread-0 (HornetQ-client-netty-threads-1443391944), Exception sending alert: java.io.IOException: writer side was already closed.
It is worth noting that when I initialise context = new InitialContext(properties); connectionFactory = (TopicConnectionFactory) context.lookup(JndiProperties.getJmsConnectionFactoryName()), SSL appears to work and there is no exception thrown.
I was wondering if anyone has come across this similar issue and knows what the problem is. I've included the server and client logs with the VM flag -Djavax.net.debug=all.
SERVER LOG
13:45:19,793 INFO [stdout] (default I/O-1) *** Finished
13:45:19,794 INFO [stdout] (default I/O-1) verify_data: { 11, 49, 176, 105, 70, 210, 172, 251, 72, 72, 228, 205, 93, 70, 148, 56, 92, 196, 239, 248, 118, 15, 24, 110, 100, 66, 150, 66, 94, 195, 185, 100, 113, 91, 76, 218 }
13:45:19,794 INFO [stdout] (default I/O-1) ***
13:45:19,794 INFO [stdout] (default I/O-1) [read] MD5 and SHA1 hashes: len = 40
13:45:19,796 INFO [stdout] (default I/O-1) 0000: 14 00 00 24 0B 31 B0 69 46 D2 AC FB 48 48 E4 CD ...$.1.iF...HH..
13:45:19,801 INFO [stdout] (default I/O-1) 0010: 5D 46 94 38 5C C4 EF F8 76 0F 18 6E 64 42 96 42 ]F.8\...v..ndB.B
13:45:19,803 INFO [stdout] (default I/O-1) 0020: 5E C3 B9 64 71 5B 4C DA ^..dq[L.
13:45:19,805 INFO [stdout] (default I/O-1) default I/O-1, WRITE: SSLv3 Change Cipher Spec, length = 1
13:45:19,813 INFO [stdout] (default I/O-1) *** Finished
13:45:19,815 INFO [stdout] (default I/O-1) verify_data: { 145, 207, 204, 111, 0, 53, 148, 82, 245, 181, 190, 153, 189, 178, 13, 84, 125, 182, 207, 33, 134, 98, 250, 235, 163, 121, 180, 125, 172, 91, 115, 33, 9, 132, 17, 222 }
13:45:19,816 INFO [stdout] (default I/O-1) ***
13:45:19,816 INFO [stdout] (default I/O-1) [write] MD5 and SHA1 hashes: len = 40
13:45:19,817 INFO [stdout] (default I/O-1) 0000: 14 00 00 24 91 CF CC 6F 00 35 94 52 F5 B5 BE 99 ...$...o.5.R....
13:45:19,820 INFO [stdout] (default I/O-1) 0010: BD B2 0D 54 7D B6 CF 21 86 62 FA EB A3 79 B4 7D ...T...!.b...y..
13:45:19,821 INFO [stdout] (default I/O-1) 0020: AC 5B 73 21 09 84 11 DE .[s!....
13:45:19,821 INFO [stdout] (default I/O-1) Padded plaintext before ENCRYPTION: len = 64
13:45:19,823 INFO [stdout] (default I/O-1) 0000: 14 00 00 24 91 CF CC 6F 00 35 94 52 F5 B5 BE 99 ...$...o.5.R....
13:45:19,825 INFO [stdout] (default I/O-1) 0010: BD B2 0D 54 7D B6 CF 21 86 62 FA EB A3 79 B4 7D ...T...!.b...y..
13:45:19,828 INFO [stdout] (default I/O-1) 0020: AC 5B 73 21 09 84 11 DE 87 57 F6 4A 5F 06 25 B9 .[s!.....W.J_.%.
13:45:19,829 INFO [stdout] (default I/O-1) 0030: DC 34 9A FE 3B 63 47 1D 0E 5D 02 FB 03 03 03 03 .4..;cG..]......
13:45:19,830 INFO [stdout] (default I/O-1) default I/O-1, WRITE: SSLv3 Handshake, length = 64
13:45:19,830 INFO [stdout] (default I/O-1) %% Cached server session: [Session-2, TLS_ECDHE_RSA_WITH_AES_128_CBC_SHA]
13:45:19,830 INFO [stdout] (default I/O-1) [Raw write]: length = 6
13:45:19,831 INFO [stdout] (default I/O-1) 0000: 14 03 00 00 01 01 ......
13:45:19,831 INFO [stdout] (default I/O-1) [Raw write]: length = 69
13:45:19,832 INFO [stdout] (default I/O-1) 0000: 16 03 00 00 40 CE CE F7 40 CB D8 C3 A8 B0 C8 12 ....@...@.......
13:45:19,833 INFO [stdout] (default I/O-1) 0010: 9A CD B7 91 B2 A6 AC 3B BF F1 D5 CB B8 31 B7 81 .......;.....1..
13:45:19,835 INFO [stdout] (default I/O-1) 0020: 7C 41 64 73 B5 ED 6C 62 93 1B 73 44 45 0A 10 92 .Ads..lb..sDE...
13:45:19,836 INFO [stdout] (default I/O-1) 0030: D1 EF 40 8C 0E 48 A6 46 8D 43 F8 83 49 BC 9A DC ..@..H.F.C..I...
13:45:19,837 INFO [stdout] (default I/O-1) 0040: 95 42 A6 5B 34 .B.[4
13:45:49,916 INFO [stdout] (default I/O-1) [Raw read]: length = 5
13:45:49,917 INFO [stdout] (default I/O-1) 0000: 15 03 00 00 20 ....
13:45:49,917 INFO [stdout] (default I/O-1) [Raw read]: length = 32
13:45:49,920 INFO [stdout] (default I/O-1) 0000: 7B 88 84 2A 82 34 80 E5 1E A5 FD 48 19 16 B0 8C ...*.4.....H....
13:45:49,922 INFO [stdout] (default I/O-1) 0010: 43 5C B7 B0 6B BC 87 95 B2 12 CF 1F 27 14 97 17 C\..k.......'...
13:45:49,923 INFO [stdout] (default I/O-1) default I/O-1, READ: SSLv3 Alert, length = 32
13:45:49,923 INFO [stdout] (default I/O-1) Padded plaintext after DECRYPTION: len = 32
13:45:49,924 INFO [stdout] (default I/O-1) 0000: 01 00 2E A5 8E 9E 44 C2 21 DF D4 EC 50 96 E4 BD ......D.!...P...
13:45:49,925 INFO [stdout] (default I/O-1) 0010: F1 88 C7 B8 EE 68 09 09 09 09 09 09 09 09 09 09 .....h..........
13:45:49,926 INFO [stdout] (default I/O-1) default I/O-1, RECV SSLv3 ALERT: warning, close_notify
13:45:49,926 INFO [stdout] (default I/O-1) default I/O-1, closeInboundInternal()
13:45:49,926 INFO [stdout] (default I/O-1) default I/O-1, closeOutboundInternal()
13:45:49,926 INFO [stdout] (default I/O-1) default I/O-1, SEND SSLv3 ALERT: warning, description = close_notify
13:45:49,927 INFO [stdout] (default I/O-1) Padded plaintext before ENCRYPTION: len = 32
13:45:49,928 INFO [stdout] (default I/O-1) 0000: 01 00 8D 18 44 20 FC F4 C9 80 20 A6 CF B5 56 24 ....D .... ...V$
13:45:49,932 INFO [stdout] (default I/O-1) 0010: 9A 09 AD 85 08 46 09 09 09 09 09 09 09 09 09 09 .....F..........
13:45:49,932 INFO [stdout] (default I/O-1) default I/O-1, WRITE: SSLv3 Alert, length = 32
13:45:49,932 INFO [stdout] (default I/O-1) [Raw write]: length = 37
13:45:49,933 INFO [stdout] (default I/O-1) 0000: 15 03 00 00 20 CD E4 03 53 BA BD 8D A0 47 DA C3 .... ...S....G..
13:45:49,935 INFO [stdout] (default I/O-1) 0010: FC 73 A4 94 A1 9B 0D 09 63 1B 17 08 D8 32 11 39 .s......c....2.9
13:45:49,935 INFO [stdout] (default I/O-1) 0020: A0 9D 64 30 D1 ..d0.
13:45:49,947 INFO [stdout] (default I/O-1) default I/O-1, called closeOutbound()
13:45:49,948 INFO [stdout] (default I/O-1) default I/O-1, closeOutboundInternal()
13:45:49,959 INFO [stdout] (default I/O-1) [Raw read (bb)]: length = 37
13:45:49,961 INFO [stdout] (default I/O-1) 0000: 17 03 00 00 20 12 56 C9 94 60 F8 FA FE 7E CC E9 .... .V..`......
13:45:49,963 INFO [stdout] (default I/O-1) 0010: B8 8D FA 48 AC BB 40 0E 69 E4 7F 09 A3 8F 5D 8F ...H..@.i.....].
13:45:49,964 INFO [stdout] (default I/O-1) 0020: 1E 8C 8F CE E2 .....
13:45:49,964 INFO [stdout] (default I/O-1) Padded plaintext after DECRYPTION: len = 32
13:45:49,966 INFO [stdout] (default I/O-1) 0000: 00 36 ED 02 06 CF C1 16 B5 32 AF 6E D5 32 15 2F .6.......2.n.2./
13:45:49,967 INFO [stdout] (default I/O-1) 0010: 03 3F BD 3B 8A 0A 0A 0A 0A 0A 0A 0A 0A 0A 0A 0A .?.;............
13:45:49,967 INFO [stdout] (default I/O-1) [Raw read (bb)]: length = 37
13:45:49,969 INFO [stdout] (default I/O-1) 0000: 17 03 00 00 20 48 E1 A0 BC C9 C4 40 D3 E0 70 B8 .... H.....@..p.
13:45:49,971 INFO [stdout] (default I/O-1) 0010: B5 42 9F 6B 5C 99 D1 93 6F C9 4C D8 E5 BC EA E0 .B.k\...o.L.....
13:45:49,971 INFO [stdout] (default I/O-1) 0020: 77 CA 71 5C DE w.q\.
13:45:49,972 INFO [stdout] (default I/O-1) Padded plaintext after DECRYPTION: len = 32
13:45:49,973 INFO [stdout] (default I/O-1) 0000: 00 00 01 FF 6D E9 27 87 B7 6C EE 31 B8 8B D6 DD ....m.'..l.1....
13:45:49,975 INFO [stdout] (default I/O-1) 0010: 4B 9B EC 81 01 E3 1F 11 07 07 07 07 07 07 07 07 K...............
13:45:49,975 INFO [stdout] (default I/O-1) [Raw read]: length = 5
13:45:49,976 INFO [stdout] (default I/O-1) 0000: 15 03 00 00 20 ....
13:45:49,976 INFO [stdout] (default I/O-1) [Raw read]: length = 32
13:45:49,978 INFO [stdout] (default I/O-1) 0000: 27 6B 17 63 09 65 A4 A1 BB B4 F2 91 FD 17 17 95 'k.c.e..........
13:45:49,979 INFO [stdout] (default I/O-1) 0010: 7F AE 23 F4 10 54 C1 9D 40 5C DF 7F 95 D1 50 89 ..#..T..@\....P.
13:45:49,979 INFO [stdout] (default I/O-1) default I/O-1, READ: SSLv3 Alert, length = 32
13:45:49,979 INFO [stdout] (default I/O-1) Padded plaintext after DECRYPTION: len = 32
13:45:49,981 INFO [stdout] (default I/O-1) 0000: 01 00 FF 00 D9 2D 5F BF 05 FB D0 14 0C 5A 54 C2 .....-_......ZT.
13:45:49,983 INFO [stdout] (default I/O-1) 0010: 59 52 21 C9 34 C4 09 09 09 09 09 09 09 09 09 09 YR!.4...........
13:45:49,983 INFO [stdout] (default I/O-1) default I/O-1, RECV SSLv3 ALERT: warning, close_notify
13:45:49,983 INFO [stdout] (default I/O-1) default I/O-1, closeInboundInternal()
13:45:49,983 INFO [stdout] (default I/O-1) default I/O-1, closeOutboundInternal()
13:45:49,984 INFO [stdout] (default I/O-1) default I/O-1, SEND SSLv3 ALERT: warning, description = close_notify
13:45:49,984 INFO [stdout] (default I/O-1) Padded plaintext before ENCRYPTION: len = 32
13:45:49,985 INFO [stdout] (default I/O-1) 0000: 01 00 EF CA 9B 90 B4 B8 BC FC B5 A3 A9 13 9D 38 ...............8
13:45:49,987 INFO [stdout] (default I/O-1) 0010: 14 0C 54 B6 F9 3F 09 09 09 09 09 09 09 09 09 09 ..T..?..........
13:45:49,987 INFO [stdout] (default I/O-1) default I/O-1, WRITE: SSLv3 Alert, length = 32
13:45:49,987 INFO [stdout] (default I/O-1) [Raw write]: length = 37
13:45:49,989 INFO [stdout] (default I/O-1) 0000: 15 03 00 00 20 E9 E4 72 C6 A0 E5 4D 92 6A 10 FD .... ..r...M.j..
13:45:49,990 INFO [stdout] (default I/O-1) 0010: B1 19 7F 30 BF B2 E1 39 E5 AE 01 77 7E 13 2F 83 ...0...9...w../.
13:45:49,991 INFO [stdout] (default I/O-1) 0020: F8 5A 70 88 FC .Zp..
13:45:49,992 INFO [stdout] (default I/O-1) default I/O-1, called closeOutbound()
13:45:49,992 INFO [stdout] (default I/O-1) default I/O-1, closeOutboundInternal()
13:45:49,996 INFO [org.jboss.as.naming] (default task-8) JBAS011806: Channel end notification received, closing channel Channel ID 3bea21ec (inbound) of Remoting connection 3302922c to /127.0.0.1:59104
CLIENT LOG
*** Finished
verify_data: { 145, 207, 204, 111, 0, 53, 148, 82, 245, 181, 190, 153, 189, 178, 13, 84, 125, 182, 207, 33, 134, 98, 250, 235, 163, 121, 180, 125, 172, 91, 115, 33, 9, 132, 17, 222 }
***
%% Cached client session: [Session-2, TLS_ECDHE_RSA_WITH_AES_128_CBC_SHA]
[read] MD5 and SHA1 hashes: len = 40
0000: 14 00 00 24 91 CF CC 6F 00 35 94 52 F5 B5 BE 99 ...$...o.5.R....
0010: BD B2 0D 54 7D B6 CF 21 86 62 FA EB A3 79 B4 7D ...T...!.b...y..
0020: AC 5B 73 21 09 84 11 DE .[s!....
[Raw write (bb)]: length = 0
[Raw write (bb)]: length = 0
[Raw write (bb)]: length = 0
[Raw write (bb)]: length = 0
[Raw write (bb)]: length = 0
Thread-0 (HornetQ-client-netty-threads-1443391944), called closeOutbound()
Thread-0 (HornetQ-client-netty-threads-1443391944), closeOutboundInternal()
Thread-0 (HornetQ-client-netty-threads-1443391944), SEND SSLv3 ALERT: warning, description = close_notify
Padded plaintext before ENCRYPTION: len = 32
0000: 01 00 2E A5 8E 9E 44 C2 21 DF D4 EC 50 96 E4 BD ......D.!...P...
0010: F1 88 C7 B8 EE 68 09 09 09 09 09 09 09 09 09 09 .....h..........
Thread-0 (HornetQ-client-netty-threads-1443391944), WRITE: SSLv3 Alert, length = 32
[Raw write]: length = 37
0000: 15 03 00 00 20 7B 88 84 2A 82 34 80 E5 1E A5 FD .... ...*.4.....
0010: 48 19 16 B0 8C 43 5C B7 B0 6B BC 87 95 B2 12 CF H....C\..k......
0020: 1F 27 14 97 17 .'...
Thread-0 (HornetQ-client-netty-threads-1443391944), called closeOutbound()
Thread-0 (HornetQ-client-netty-threads-1443391944), closeOutboundInternal()
Thread-0 (HornetQ-client-netty-threads-1443391944), called closeInbound()
Thread-0 (HornetQ-client-netty-threads-1443391944), fatal error: 80: Inbound closed before receiving peer's close_notify: possible truncation attack?
javax.net.ssl.SSLException: Inbound closed before receiving peer's close_notify: possible truncation attack?
%% Invalidated: [Session-2, TLS_ECDHE_RSA_WITH_AES_128_CBC_SHA]
Thread-0 (HornetQ-client-netty-threads-1443391944), SEND SSLv3 ALERT: fatal, description = internal_error
Thread-0 (HornetQ-client-netty-threads-1443391944), Exception sending alert: java.io.IOException: writer side was already closed.
Padded plaintext before ENCRYPTION: len = 32
0000: 00 36 ED 02 06 CF C1 16 B5 32 AF 6E D5 32 15 2F .6.......2.n.2./
0010: 03 3F BD 3B 8A 0A 0A 0A 0A 0A 0A 0A 0A 0A 0A 0A .?.;............
Thread-1, WRITE: SSLv3 Application Data, length = 1
Padded plaintext before ENCRYPTION: len = 32
0000: 00 00 01 FF 6D E9 27 87 B7 6C EE 31 B8 8B D6 DD ....m.'..l.1....
0010: 4B 9B EC 81 01 E3 1F 11 07 07 07 07 07 07 07 07 K...............
Thread-1, WRITE: SSLv3 Application Data, length = 4
[Raw write (bb)]: length = 74
0000: 17 03 00 00 20 12 56 C9 94 60 F8 FA FE 7E CC E9 .... .V..`......
0010: B8 8D FA 48 AC BB 40 0E 69 E4 7F 09 A3 8F 5D 8F ...H..@.i.....].
0020: 1E 8C 8F CE E2 17 03 00 00 20 48 E1 A0 BC C9 C4 ......... H.....
0030: 40 D3 E0 70 B8 B5 42 9F 6B 5C 99 D1 93 6F C9 4C @..p..B.k\...o.L
0040: D8 E5 BC EA E0 77 CA 71 5C DE .....w.q\.
Thread-1, called closeOutbound()
Thread-1, closeOutboundInternal()
Thread-1, SEND SSLv3 ALERT: warning, description = close_notify
Padded plaintext before ENCRYPTION: len = 32
0000: 01 00 FF 00 D9 2D 5F BF 05 FB D0 14 0C 5A 54 C2 .....-_......ZT.
0010: 59 52 21 C9 34 C4 09 09 09 09 09 09 09 09 09 09 YR!.4...........
Thread-1, WRITE: SSLv3 Alert, length = 32
[Raw write]: length = 37
0000: 15 03 00 00 20 27 6B 17 63 09 65 A4 A1 BB B4 F2 .... 'k.c.e.....
0010: 91 FD 17 17 95 7F AE 23 F4 10 54 C1 9D 40 5C DF .......#..T..@\.
0020: 7F 95 D1 50 89 ...P.
[Raw read]: length = 5
0000: 15 03 00 00 20 ....
[Raw read]: length = 32
0000: E9 E4 72 C6 A0 E5 4D 92 6A 10 FD B1 19 7F 30 BF ..r...M.j.....0.
0010: B2 E1 39 E5 AE 01 77 7E 13 2F 83 F8 5A 70 88 FC ..9...w../..Zp..
Remoting "config-based-naming-client-endpoint" I/O-1, READ: SSLv3 Alert, length = 32
Padded plaintext after DECRYPTION: len = 32
0000: 01 00 EF CA 9B 90 B4 B8 BC FC B5 A3 A9 13 9D 38 ...............8
0010: 14 0C 54 B6 F9 3F 09 09 09 09 09 09 09 09 09 09 ..T..?..........
Remoting "config-based-naming-client-endpoint" I/O-1, RECV SSLv3 ALERT: warning, close_notify
Remoting "config-based-naming-client-endpoint" I/O-1, closeInboundInternal()
Remoting "config-based-naming-client-endpoint" I/O-1, closeOutboundInternal()
Thanks in advance.