Uploaded image for project: 'MINA'
  1. MINA
  2. DIRMINA-937

sslfilter hangs with openjdk works with oracle?

    Details

    • Type: Bug
    • Status: Open
    • Priority: Major
    • Resolution: Unresolved
    • Affects Version/s: 2.0.7
    • Fix Version/s: 2.0.8
    • Component/s: Filter
    • Labels:
      None
    • Environment:
      OpenJDK Runtime Environment (IcedTea6 1.12.1) (6b27-1.12.1-2ubuntu0.12.04.2)
      OpenJDK 64-Bit Server VM (build 20.0-b12, mixed mode)

      Description

      Still gathering information, however ...

      I've a server that's using SslFilter. When I test a connection using curl (two different versions; curl -k --trace - https://localhost:4321) it hangs:

      • curl sends the client hello
      • never gets any response

      looking at an extract of the logs I see:

      [read] MD5 and SHA1 hashes: len = 235
      0000: 01 00 00 E7 03 02 51 35 14 CC 56 9F 1B 4E B0 80 ......Q5..V..N..
      ...
      00E0: 00 0F 00 10 00 11 00 0F 00 01 01 ...........
      matching alias: mykey
      [2013-03-04=16:40:28.836] [NioProcessor-1] DEBUG org.apache.mina.filter.ssl.SslHandler - Session Server[2](ssl...) processing the NEED_UNWRAP state
      [2013-03-04=16:40:28.836] [NioProcessor-1] DEBUG org.apache.mina.filter.ssl.SslFilter - Session Server[2](ssl...): Processing the SSL Data

      i.e., SSLEngine's indicated that it is expecting more data from curl.

      If I switch to oracle's jvm, things work - that is the NEED_UNWRAP doesn't appear and SSLEngine starts sending data back to the curl client:

      ...
      00E0: 00 0F 00 10 00 11 00 0F 00 01 01 ...........
      matching alias: mykey
      %% Created: [Session-1, SSL_DHE_RSA_WITH_3DES_EDE_CBC_SHA]

          • ServerHello, TLSv1
            ...

      any one else seen this?

      1. TestJDK.java
        1 kB
        Jeff MAURY

        Activity

        Hide
        elecharny Emmanuel Lecharny added a comment -

        Couldn't it be a problem with the cipher suite you use ?

        However, in any case, it should not hang. Can you share the code that you use so that I can debug the code using OpenJDK ? (just the initialization part, it should be enough)

        Show
        elecharny Emmanuel Lecharny added a comment - Couldn't it be a problem with the cipher suite you use ? However, in any case, it should not hang. Can you share the code that you use so that I can debug the code using OpenJDK ? (just the initialization part, it should be enough)
        Hide
        fixmo-cagney Andrew C added a comment - - edited

        > Couldn't it be a problem with the cipher suite you use ?

        Perhaps - for instance, bouncy castle isn't in the class path - and it was an early suspect. However, the only thing I change to get it working is the JVM - class paths are identical.

        The OpenJDK 6 could do with an update, which I'll try once I've spun up a new test VM.

        > However, in any case, it should not hang. Can you share the code that you use so that I can debug the code using OpenJDK ? (just the initialization part, it should be enough)

        This is the relevant part:

            private NioSocketAcceptor createNewAcceptor(InetSocketAddress address, KeyStoreProxy keyStoreProxy) throws Exception {
                NioSocketAcceptor acceptor = new DefaultForwardingAcceptorFactory().createNioSocketAcceptor(null);
                logger.info("Network interface {}", address);
                acceptor.setDefaultLocalAddress(address);
                if (keyStoreProxy == null) {
                    logger.info("SSL Disabled");
                } else {
                    logger.info("SSL enabled using key store {}", keyStoreProxy);
                    KeyStore keyStore = keyStoreProxy.loadKeyStore();
                    SslContextFactory sslContextFactory = new SslContextFactory();
                    sslContextFactory.setKeyManagerFactoryKeyStore(keyStore);
                    sslContextFactory.setKeyManagerFactoryKeyStorePassword(keyStoreProxy.getPassword());
                    acceptor.getFilterChain().addLast("SslFilter", new SslFilter(sslContextFactory.newInstance()));
                    acceptor.getFilterChain().addLast("logger", new LoggingFilter());
                }
                logger.info("Installing network session adaptor");
                acceptor.setHandler(new NetworkServerSessionAdapter(this));
                return acceptor;
            }
        

        Hmm, however, I wonder....

        Tweaking examples.echoserver.Main to use a spare port and turn on ssl I can reproduce the behaviour using just mina:

        $ ls -1 lib
        annotations-api-6.0.35.jar
        catalina-6.0.35.jar
        commons-lang-2.6.jar
        coyote-6.0.35.jar
        javassist-3.11.0.GA.jar
        javassist-3.7.ga.jar
        jcl-over-slf4j-1.6.6.jar
        juli-6.0.35.jar
        ognl-3.0.5.jar
        servlet-api-6.0.35.jar
        slf4j-api-1.7.2.jar
        slf4j-api-1.7.2-javadoc.jar
        slf4j-api-1.7.2-sources.jar
        slf4j-simple-1.7.2.jar
        slf4j-simple-1.7.2-javadoc.jar
        slf4j-simple-1.7.2-sources.jar
        spring-2.5.6.SEC03.jar
        sshd-core-0.9.0-SNAPSHOT.jar

        $ java -version
        java version "1.6.0_27"
        OpenJDK Runtime Environment (IcedTea6 1.12.1) (6b27-1.12.1-2ubuntu0.12.04.2)
        OpenJDK 64-Bit Server VM (build 20.0-b12, mixed mode)

        curl looks like:

        $ curl --trace - -k https://127.0.0.1:4321
        == Info: About to connect() to 127.0.0.1 port 4321 (#0)
        == Info: Trying 127.0.0.1... == Info: connected
        == Info: successfully set certificate verify locations:
        == Info: CAfile: none
        CApath: /etc/ssl/certs
        == Info: SSLv3, TLS handshake, Client hello (1):
        => Send SSL data, 217 bytes (0xd9)
        0000: 01 00 00 d5 03 02 51 36 34 e6 ac 2e e2 35 72 e1 ......Q64....5r.
        0010: 38 55 04 af 05 40 00 87 8e 47 e7 80 87 d4 d1 a6 8U...@...G......
        0020: 43 82 2f e4 c7 3e 00 00 66 c0 14 c0 0a c0 22 c0 C./..>..f.....".
        0030: 21 00 39 00 38 00 88 00 87 c0 0f c0 05 00 35 00 !.9.8.........5.
        0040: 84 c0 12 c0 08 c0 1c c0 1b 00 16 00 13 c0 0d c0 ................
        0050: 03 00 0a c0 13 c0 09 c0 1f c0 1e 00 33 00 32 00 ............3.2.
        0060: 9a 00 99 00 45 00 44 c0 0e c0 04 00 2f 00 96 00 ....E.D...../...
        0070: 41 c0 11 c0 07 c0 0c c0 02 00 05 00 04 00 15 00 A...............
        0080: 12 00 09 00 14 00 11 00 08 00 06 00 03 00 ff 02 ................
        0090: 01 00 00 45 00 0b 00 04 03 00 01 02 00 0a 00 34 ...E...........4
        00a0: 00 32 00 0e 00 0d 00 19 00 0b 00 0c 00 18 00 09 .2..............
        00b0: 00 0a 00 16 00 17 00 08 00 06 00 07 00 14 00 15 ................
        00c0: 00 04 00 05 00 12 00 13 00 01 00 02 00 03 00 0f ................
        00d0: 00 10 00 11 00 0f 00 01 01 .........
        [hung - should get server hello]

        and the echo server looks like:

        $ java -Djavax.net.debug=all -Dorg.slf4j.simpleLogger.defaultLogLevel=trace -cp lib/*:mina-example/target/classes:mina-core/target/classes org.apache.mina.example.echoserver.Main
        ***
        found key for : bogus
        chain [0] = [
        [
        Version: V1
        Subject: CN=bogus.com, OU=XXX CA, O=Bogus Inc, L=Stockholm, ST=Stockholm, C=SE
        Signature Algorithm: MD5withRSA, OID = 1.2.840.113549.1.1.4

        Key: Sun RSA public key, 511 bits
        modulus: 4716266305158955097619267184819536762192336460125269747936292391072221240753144246603767639670387155212663695306712305083753837008428026689179662428434397
        public exponent: 65537
        Validity: [From: Mon Mar 07 10:16:35 EST 2005,
        To: Thu Mar 05 10:16:35 EST 2015]
        Issuer: CN=bogus.com, OU=XXX CA, O=Bogus Inc, L=Stockholm, ST=Stockholm, C=SE
        SerialNumber: [ 422c7053]

        ]
        Algorithm: [MD5withRSA]
        Signature:
        0000: 49 40 0E D4 06 42 85 18 B5 B3 61 9B EC 3F 3E B3 I@...B....a..?>.
        0010: C2 D4 32 6E 28 DD F6 A2 85 39 4F A7 64 6D 10 BA ..2n(....9O.dm..
        0020: 03 1C 88 B4 D4 69 4A 45 09 35 A9 17 E8 A4 CC E1 .....iJE.5......
        0030: 13 0B 40 17 79 20 F4 7C 0F 5B 92 95 A5 3A 6B 23 ..@.y ...[...:k#

        ]
        ***
        trigger seeding of SecureRandom
        done seeding SecureRandom
        SSL ON
        Listening on port 4321
        R: 0.0, W: 0.0
        R: 0.0, W: 0.0
        [NioProcessor-2] DEBUG org.apache.mina.filter.ssl.SslFilter - Adding the SSL Filter sslFilter to the chain
        [NioProcessor-2] DEBUG org.apache.mina.filter.ssl.SslHandler - Session Server[1](no sslEngine) Initializing the SSL Handler
        Using SSLEngineImpl.
        Allow unsafe renegotiation: false
        Allow legacy hello messages: true
        Is initial handshake: true
        Is secure renegotiation: false
        [NioProcessor-2] DEBUG org.apache.mina.filter.ssl.SslHandler - Session Server[1](no sslEngine) SSL Handler Initialization done.
        [NioProcessor-2] DEBUG org.apache.mina.filter.ssl.SslFilter - Session Server[1](ssl...) : Starting the first handshake
        [NioProcessor-2] DEBUG org.apache.mina.filter.ssl.SslHandler - Session Server[1](ssl...) processing the NEED_UNWRAP state
        [NioProcessor-2] INFO org.apache.mina.example.echoserver.EchoProtocolHandler - OPENED
        [NioProcessor-2] DEBUG org.apache.mina.filter.ssl.SslFilter - Session Server[1](ssl...): Message received : HeapBuffer[pos=0 lim=222 cap=2048: 16 03 01 00 D9 01 00 00 D5 03 02 51 36 35 B6 40...]
        [NioProcessor-2] DEBUG org.apache.mina.filter.ssl.SslHandler - Session Server[1](ssl...) Processing the received message
        [NioProcessor-2] DEBUG org.apache.mina.filter.ssl.SslHandler - Session Server[1](ssl...) processing the NEED_UNWRAP state
        [Raw read]: length = 5
        0000: 16 03 01 00 D9 .....
        [Raw read]: length = 217
        0000: 01 00 00 D5 03 02 51 36 35 B6 40 C7 E2 FF 32 79 ......Q65.@...2y
        0010: 0E 99 7E B0 9F F3 70 66 E9 B2 07 75 D1 E0 7D CC ......pf...u....
        0020: 2D F7 82 45 A3 56 00 00 66 C0 14 C0 0A C0 22 C0 -..E.V..f.....".
        0030: 21 00 39 00 38 00 88 00 87 C0 0F C0 05 00 35 00 !.9.8.........5.
        0040: 84 C0 12 C0 08 C0 1C C0 1B 00 16 00 13 C0 0D C0 ................
        0050: 03 00 0A C0 13 C0 09 C0 1F C0 1E 00 33 00 32 00 ............3.2.
        0060: 9A 00 99 00 45 00 44 C0 0E C0 04 00 2F 00 96 00 ....E.D...../...
        0070: 41 C0 11 C0 07 C0 0C C0 02 00 05 00 04 00 15 00 A...............
        0080: 12 00 09 00 14 00 11 00 08 00 06 00 03 00 FF 02 ................
        0090: 01 00 00 45 00 0B 00 04 03 00 01 02 00 0A 00 34 ...E...........4
        00A0: 00 32 00 0E 00 0D 00 19 00 0B 00 0C 00 18 00 09 .2..............
        00B0: 00 0A 00 16 00 17 00 08 00 06 00 07 00 14 00 15 ................
        00C0: 00 04 00 05 00 12 00 13 00 01 00 02 00 03 00 0F ................
        00D0: 00 10 00 11 00 0F 00 01 01 .........
        NioProcessor-2, READ: TLSv1 Handshake, length = 217
        [NioProcessor-2] DEBUG org.apache.mina.filter.ssl.SslHandler - Session Server[1](ssl...) processing the NEED_TASK state

            • ClientHello, TLSv1.1
              RandomCookie: GMT: 1362506934 bytes = { 64, 199, 226, 255, 50, 121, 14, 153, 126, 176, 159, 243, 112, 102, 233, 178, 7, 117, 209, 224, 125, 204, 45, 247, 130, 69, 163, 86 }

              Session ID: {}
              Cipher Suites: [TLS_ECDHE_RSA_WITH_AES_256_CBC_SHA, TLS_ECDHE_ECDSA_WITH_AES_256_CBC_SHA, Unknown 0xc0:0x22, Unknown 0xc0:0x21, TLS_DHE_RSA_WITH_AES_256_CBC_SHA, TLS_DHE_DSS_WITH_AES_256_CBC_SHA, Unknown 0x0:0x88, Unknown 0x0:0x87, TLS_ECDH_RSA_WITH_AES_256_CBC_SHA, TLS_ECDH_ECDSA_WITH_AES_256_CBC_SHA, TLS_RSA_WITH_AES_256_CBC_SHA, Unknown 0x0:0x84, TLS_ECDHE_RSA_WITH_3DES_EDE_CBC_SHA, TLS_ECDHE_ECDSA_WITH_3DES_EDE_CBC_SHA, Unknown 0xc0:0x1c, Unknown 0xc0:0x1b, SSL_DHE_RSA_WITH_3DES_EDE_CBC_SHA, SSL_DHE_DSS_WITH_3DES_EDE_CBC_SHA, TLS_ECDH_RSA_WITH_3DES_EDE_CBC_SHA, TLS_ECDH_ECDSA_WITH_3DES_EDE_CBC_SHA, SSL_RSA_WITH_3DES_EDE_CBC_SHA, TLS_ECDHE_RSA_WITH_AES_128_CBC_SHA, TLS_ECDHE_ECDSA_WITH_AES_128_CBC_SHA, Unknown 0xc0:0x1f, Unknown 0xc0:0x1e, TLS_DHE_RSA_WITH_AES_128_CBC_SHA, TLS_DHE_DSS_WITH_AES_128_CBC_SHA, Unknown 0x0:0x9a, Unknown 0x0:0x99, Unknown 0x0:0x45, Unknown 0x0:0x44, TLS_ECDH_RSA_WITH_AES_128_CBC_SHA, TLS_ECDH_ECDSA_WITH_AES_128_CBC_SHA, TLS_RSA_WITH_AES_128_CBC_SHA, Unknown 0x0:0x96, Unknown 0x0:0x41, TLS_ECDHE_RSA_WITH_RC4_128_SHA, TLS_ECDHE_ECDSA_WITH_RC4_128_SHA, TLS_ECDH_RSA_WITH_RC4_128_SHA, TLS_ECDH_ECDSA_WITH_RC4_128_SHA, SSL_RSA_WITH_RC4_128_SHA, SSL_RSA_WITH_RC4_128_MD5, SSL_DHE_RSA_WITH_DES_CBC_SHA, SSL_DHE_DSS_WITH_DES_CBC_SHA, SSL_RSA_WITH_DES_CBC_SHA, SSL_DHE_RSA_EXPORT_WITH_DES40_CBC_SHA, SSL_DHE_DSS_EXPORT_WITH_DES40_CBC_SHA, SSL_RSA_EXPORT_WITH_DES40_CBC_SHA, SSL_RSA_EXPORT_WITH_RC2_CBC_40_MD5, SSL_RSA_EXPORT_WITH_RC4_40_MD5, TLS_EMPTY_RENEGOTIATION_INFO_SCSV]
              Compression Methods:

              { 1, 0 }

              Extension ec_point_formats, formats: [uncompressed, ansiX962_compressed_prime, ansiX962_compressed_char2]
              Extension elliptic_curves, curve names:

              {sect571r1, sect571k1, secp521r1, sect409k1, sect409r1, secp384r1, sect283k1, sect283r1, secp256k1, secp256r1, sect239k1, sect233k1, sect233r1, secp224k1, secp224r1, sect193r1, sect193r2, secp192k1, secp192r1, sect163k1, sect163r1, sect163r2, secp160k1, secp160r1, secp160r2}

              Unsupported extension type_15, data: 01
              ***
              [read] MD5 and SHA1 hashes: len = 217
              0000: 01 00 00 D5 03 02 51 36 35 B6 40 C7 E2 FF 32 79 ......Q65.@...2y
              0010: 0E 99 7E B0 9F F3 70 66 E9 B2 07 75 D1 E0 7D CC ......pf...u....
              0020: 2D F7 82 45 A3 56 00 00 66 C0 14 C0 0A C0 22 C0 -..E.V..f.....".
              0030: 21 00 39 00 38 00 88 00 87 C0 0F C0 05 00 35 00 !.9.8.........5.
              0040: 84 C0 12 C0 08 C0 1C C0 1B 00 16 00 13 C0 0D C0 ................
              0050: 03 00 0A C0 13 C0 09 C0 1F C0 1E 00 33 00 32 00 ............3.2.
              0060: 9A 00 99 00 45 00 44 C0 0E C0 04 00 2F 00 96 00 ....E.D...../...
              0070: 41 C0 11 C0 07 C0 0C C0 02 00 05 00 04 00 15 00 A...............
              0080: 12 00 09 00 14 00 11 00 08 00 06 00 03 00 FF 02 ................
              0090: 01 00 00 45 00 0B 00 04 03 00 01 02 00 0A 00 34 ...E...........4
              00A0: 00 32 00 0E 00 0D 00 19 00 0B 00 0C 00 18 00 09 .2..............
              00B0: 00 0A 00 16 00 17 00 08 00 06 00 07 00 14 00 15 ................
              00C0: 00 04 00 05 00 12 00 13 00 01 00 02 00 03 00 0F ................
              00D0: 00 10 00 11 00 0F 00 01 01 .........
              matching alias: bogus
              [NioProcessor-2] DEBUG org.apache.mina.filter.ssl.SslHandler - Session Server[1](ssl...) processing the NEED_UNWRAP state
              [NioProcessor-2] DEBUG org.apache.mina.filter.ssl.SslFilter - Session Server[1](ssl...): Processing the SSL Data
              R: 0.0, W: 0.0
              R: 0.0, W: 0.0
              R: 0.0, W: 0.0
              R: 0.0, W: 0.0
              [NioProcessor-2] INFO org.apache.mina.example.echoserver.EchoProtocolHandler - *** IDLE #1 ***
              R: 0.0, W: 0.0
              R: 0.0, W: 0.0
              R: 0.0, W: 0.0
              [NioProcessor-2] INFO org.apache.mina.example.echoserver.EchoProtocolHandler - *** IDLE #2 ***

        and, again, switching to oracle's jvm and it works.

        Show
        fixmo-cagney Andrew C added a comment - - edited > Couldn't it be a problem with the cipher suite you use ? Perhaps - for instance, bouncy castle isn't in the class path - and it was an early suspect. However, the only thing I change to get it working is the JVM - class paths are identical. The OpenJDK 6 could do with an update, which I'll try once I've spun up a new test VM. > However, in any case, it should not hang. Can you share the code that you use so that I can debug the code using OpenJDK ? (just the initialization part, it should be enough) This is the relevant part: private NioSocketAcceptor createNewAcceptor(InetSocketAddress address, KeyStoreProxy keyStoreProxy) throws Exception { NioSocketAcceptor acceptor = new DefaultForwardingAcceptorFactory().createNioSocketAcceptor( null ); logger.info( "Network interface {}" , address); acceptor.setDefaultLocalAddress(address); if (keyStoreProxy == null ) { logger.info( "SSL Disabled" ); } else { logger.info( "SSL enabled using key store {}" , keyStoreProxy); KeyStore keyStore = keyStoreProxy.loadKeyStore(); SslContextFactory sslContextFactory = new SslContextFactory(); sslContextFactory.setKeyManagerFactoryKeyStore(keyStore); sslContextFactory.setKeyManagerFactoryKeyStorePassword(keyStoreProxy.getPassword()); acceptor.getFilterChain().addLast( "SslFilter" , new SslFilter(sslContextFactory.newInstance())); acceptor.getFilterChain().addLast( "logger" , new LoggingFilter()); } logger.info( "Installing network session adaptor" ); acceptor.setHandler( new NetworkServerSessionAdapter( this )); return acceptor; } Hmm, however, I wonder.... Tweaking examples.echoserver.Main to use a spare port and turn on ssl I can reproduce the behaviour using just mina: $ ls -1 lib annotations-api-6.0.35.jar catalina-6.0.35.jar commons-lang-2.6.jar coyote-6.0.35.jar javassist-3.11.0.GA.jar javassist-3.7.ga.jar jcl-over-slf4j-1.6.6.jar juli-6.0.35.jar ognl-3.0.5.jar servlet-api-6.0.35.jar slf4j-api-1.7.2.jar slf4j-api-1.7.2-javadoc.jar slf4j-api-1.7.2-sources.jar slf4j-simple-1.7.2.jar slf4j-simple-1.7.2-javadoc.jar slf4j-simple-1.7.2-sources.jar spring-2.5.6.SEC03.jar sshd-core-0.9.0-SNAPSHOT.jar $ java -version java version "1.6.0_27" OpenJDK Runtime Environment (IcedTea6 1.12.1) (6b27-1.12.1-2ubuntu0.12.04.2) OpenJDK 64-Bit Server VM (build 20.0-b12, mixed mode) curl looks like: $ curl --trace - -k https://127.0.0.1:4321 == Info: About to connect() to 127.0.0.1 port 4321 (#0) == Info: Trying 127.0.0.1... == Info: connected == Info: successfully set certificate verify locations: == Info: CAfile: none CApath: /etc/ssl/certs == Info: SSLv3, TLS handshake, Client hello (1): => Send SSL data, 217 bytes (0xd9) 0000: 01 00 00 d5 03 02 51 36 34 e6 ac 2e e2 35 72 e1 ......Q64....5r. 0010: 38 55 04 af 05 40 00 87 8e 47 e7 80 87 d4 d1 a6 8U...@...G...... 0020: 43 82 2f e4 c7 3e 00 00 66 c0 14 c0 0a c0 22 c0 C./..>..f.....". 0030: 21 00 39 00 38 00 88 00 87 c0 0f c0 05 00 35 00 !.9.8.........5. 0040: 84 c0 12 c0 08 c0 1c c0 1b 00 16 00 13 c0 0d c0 ................ 0050: 03 00 0a c0 13 c0 09 c0 1f c0 1e 00 33 00 32 00 ............3.2. 0060: 9a 00 99 00 45 00 44 c0 0e c0 04 00 2f 00 96 00 ....E.D...../... 0070: 41 c0 11 c0 07 c0 0c c0 02 00 05 00 04 00 15 00 A............... 0080: 12 00 09 00 14 00 11 00 08 00 06 00 03 00 ff 02 ................ 0090: 01 00 00 45 00 0b 00 04 03 00 01 02 00 0a 00 34 ...E...........4 00a0: 00 32 00 0e 00 0d 00 19 00 0b 00 0c 00 18 00 09 .2.............. 00b0: 00 0a 00 16 00 17 00 08 00 06 00 07 00 14 00 15 ................ 00c0: 00 04 00 05 00 12 00 13 00 01 00 02 00 03 00 0f ................ 00d0: 00 10 00 11 00 0f 00 01 01 ......... [hung - should get server hello] and the echo server looks like: $ java -Djavax.net.debug=all -Dorg.slf4j.simpleLogger.defaultLogLevel=trace -cp lib/*:mina-example/target/classes:mina-core/target/classes org.apache.mina.example.echoserver.Main *** found key for : bogus chain [0] = [ [ Version: V1 Subject: CN=bogus.com, OU=XXX CA, O=Bogus Inc, L=Stockholm, ST=Stockholm, C=SE Signature Algorithm: MD5withRSA, OID = 1.2.840.113549.1.1.4 Key: Sun RSA public key, 511 bits modulus: 4716266305158955097619267184819536762192336460125269747936292391072221240753144246603767639670387155212663695306712305083753837008428026689179662428434397 public exponent: 65537 Validity: [From: Mon Mar 07 10:16:35 EST 2005, To: Thu Mar 05 10:16:35 EST 2015] Issuer: CN=bogus.com, OU=XXX CA, O=Bogus Inc, L=Stockholm, ST=Stockholm, C=SE SerialNumber: [ 422c7053] ] Algorithm: [MD5withRSA] Signature: 0000: 49 40 0E D4 06 42 85 18 B5 B3 61 9B EC 3F 3E B3 I@...B....a..?>. 0010: C2 D4 32 6E 28 DD F6 A2 85 39 4F A7 64 6D 10 BA ..2n(....9O.dm.. 0020: 03 1C 88 B4 D4 69 4A 45 09 35 A9 17 E8 A4 CC E1 .....iJE.5...... 0030: 13 0B 40 17 79 20 F4 7C 0F 5B 92 95 A5 3A 6B 23 ..@.y ...[...:k# ] *** trigger seeding of SecureRandom done seeding SecureRandom SSL ON Listening on port 4321 R: 0.0, W: 0.0 R: 0.0, W: 0.0 [NioProcessor-2] DEBUG org.apache.mina.filter.ssl.SslFilter - Adding the SSL Filter sslFilter to the chain [NioProcessor-2] DEBUG org.apache.mina.filter.ssl.SslHandler - Session Server [1] (no sslEngine) Initializing the SSL Handler Using SSLEngineImpl. Allow unsafe renegotiation: false Allow legacy hello messages: true Is initial handshake: true Is secure renegotiation: false [NioProcessor-2] DEBUG org.apache.mina.filter.ssl.SslHandler - Session Server [1] (no sslEngine) SSL Handler Initialization done. [NioProcessor-2] DEBUG org.apache.mina.filter.ssl.SslFilter - Session Server [1] (ssl...) : Starting the first handshake [NioProcessor-2] DEBUG org.apache.mina.filter.ssl.SslHandler - Session Server [1] (ssl...) processing the NEED_UNWRAP state [NioProcessor-2] INFO org.apache.mina.example.echoserver.EchoProtocolHandler - OPENED [NioProcessor-2] DEBUG org.apache.mina.filter.ssl.SslFilter - Session Server [1] (ssl...): Message received : HeapBuffer [pos=0 lim=222 cap=2048: 16 03 01 00 D9 01 00 00 D5 03 02 51 36 35 B6 40...] [NioProcessor-2] DEBUG org.apache.mina.filter.ssl.SslHandler - Session Server [1] (ssl...) Processing the received message [NioProcessor-2] DEBUG org.apache.mina.filter.ssl.SslHandler - Session Server [1] (ssl...) processing the NEED_UNWRAP state [Raw read] : length = 5 0000: 16 03 01 00 D9 ..... [Raw read] : length = 217 0000: 01 00 00 D5 03 02 51 36 35 B6 40 C7 E2 FF 32 79 ......Q65.@...2y 0010: 0E 99 7E B0 9F F3 70 66 E9 B2 07 75 D1 E0 7D CC ......pf...u.... 0020: 2D F7 82 45 A3 56 00 00 66 C0 14 C0 0A C0 22 C0 -..E.V..f.....". 0030: 21 00 39 00 38 00 88 00 87 C0 0F C0 05 00 35 00 !.9.8.........5. 0040: 84 C0 12 C0 08 C0 1C C0 1B 00 16 00 13 C0 0D C0 ................ 0050: 03 00 0A C0 13 C0 09 C0 1F C0 1E 00 33 00 32 00 ............3.2. 0060: 9A 00 99 00 45 00 44 C0 0E C0 04 00 2F 00 96 00 ....E.D...../... 0070: 41 C0 11 C0 07 C0 0C C0 02 00 05 00 04 00 15 00 A............... 0080: 12 00 09 00 14 00 11 00 08 00 06 00 03 00 FF 02 ................ 0090: 01 00 00 45 00 0B 00 04 03 00 01 02 00 0A 00 34 ...E...........4 00A0: 00 32 00 0E 00 0D 00 19 00 0B 00 0C 00 18 00 09 .2.............. 00B0: 00 0A 00 16 00 17 00 08 00 06 00 07 00 14 00 15 ................ 00C0: 00 04 00 05 00 12 00 13 00 01 00 02 00 03 00 0F ................ 00D0: 00 10 00 11 00 0F 00 01 01 ......... NioProcessor-2, READ: TLSv1 Handshake, length = 217 [NioProcessor-2] DEBUG org.apache.mina.filter.ssl.SslHandler - Session Server [1] (ssl...) processing the NEED_TASK state ClientHello, TLSv1.1 RandomCookie: GMT: 1362506934 bytes = { 64, 199, 226, 255, 50, 121, 14, 153, 126, 176, 159, 243, 112, 102, 233, 178, 7, 117, 209, 224, 125, 204, 45, 247, 130, 69, 163, 86 } Session ID: {} Cipher Suites: [TLS_ECDHE_RSA_WITH_AES_256_CBC_SHA, TLS_ECDHE_ECDSA_WITH_AES_256_CBC_SHA, Unknown 0xc0:0x22, Unknown 0xc0:0x21, TLS_DHE_RSA_WITH_AES_256_CBC_SHA, TLS_DHE_DSS_WITH_AES_256_CBC_SHA, Unknown 0x0:0x88, Unknown 0x0:0x87, TLS_ECDH_RSA_WITH_AES_256_CBC_SHA, TLS_ECDH_ECDSA_WITH_AES_256_CBC_SHA, TLS_RSA_WITH_AES_256_CBC_SHA, Unknown 0x0:0x84, TLS_ECDHE_RSA_WITH_3DES_EDE_CBC_SHA, TLS_ECDHE_ECDSA_WITH_3DES_EDE_CBC_SHA, Unknown 0xc0:0x1c, Unknown 0xc0:0x1b, SSL_DHE_RSA_WITH_3DES_EDE_CBC_SHA, SSL_DHE_DSS_WITH_3DES_EDE_CBC_SHA, TLS_ECDH_RSA_WITH_3DES_EDE_CBC_SHA, TLS_ECDH_ECDSA_WITH_3DES_EDE_CBC_SHA, SSL_RSA_WITH_3DES_EDE_CBC_SHA, TLS_ECDHE_RSA_WITH_AES_128_CBC_SHA, TLS_ECDHE_ECDSA_WITH_AES_128_CBC_SHA, Unknown 0xc0:0x1f, Unknown 0xc0:0x1e, TLS_DHE_RSA_WITH_AES_128_CBC_SHA, TLS_DHE_DSS_WITH_AES_128_CBC_SHA, Unknown 0x0:0x9a, Unknown 0x0:0x99, Unknown 0x0:0x45, Unknown 0x0:0x44, TLS_ECDH_RSA_WITH_AES_128_CBC_SHA, TLS_ECDH_ECDSA_WITH_AES_128_CBC_SHA, TLS_RSA_WITH_AES_128_CBC_SHA, Unknown 0x0:0x96, Unknown 0x0:0x41, TLS_ECDHE_RSA_WITH_RC4_128_SHA, TLS_ECDHE_ECDSA_WITH_RC4_128_SHA, TLS_ECDH_RSA_WITH_RC4_128_SHA, TLS_ECDH_ECDSA_WITH_RC4_128_SHA, SSL_RSA_WITH_RC4_128_SHA, SSL_RSA_WITH_RC4_128_MD5, SSL_DHE_RSA_WITH_DES_CBC_SHA, SSL_DHE_DSS_WITH_DES_CBC_SHA, SSL_RSA_WITH_DES_CBC_SHA, SSL_DHE_RSA_EXPORT_WITH_DES40_CBC_SHA, SSL_DHE_DSS_EXPORT_WITH_DES40_CBC_SHA, SSL_RSA_EXPORT_WITH_DES40_CBC_SHA, SSL_RSA_EXPORT_WITH_RC2_CBC_40_MD5, SSL_RSA_EXPORT_WITH_RC4_40_MD5, TLS_EMPTY_RENEGOTIATION_INFO_SCSV] Compression Methods: { 1, 0 } Extension ec_point_formats, formats: [uncompressed, ansiX962_compressed_prime, ansiX962_compressed_char2] Extension elliptic_curves, curve names: {sect571r1, sect571k1, secp521r1, sect409k1, sect409r1, secp384r1, sect283k1, sect283r1, secp256k1, secp256r1, sect239k1, sect233k1, sect233r1, secp224k1, secp224r1, sect193r1, sect193r2, secp192k1, secp192r1, sect163k1, sect163r1, sect163r2, secp160k1, secp160r1, secp160r2} Unsupported extension type_15, data: 01 *** [read] MD5 and SHA1 hashes: len = 217 0000: 01 00 00 D5 03 02 51 36 35 B6 40 C7 E2 FF 32 79 ......Q65.@...2y 0010: 0E 99 7E B0 9F F3 70 66 E9 B2 07 75 D1 E0 7D CC ......pf...u.... 0020: 2D F7 82 45 A3 56 00 00 66 C0 14 C0 0A C0 22 C0 -..E.V..f.....". 0030: 21 00 39 00 38 00 88 00 87 C0 0F C0 05 00 35 00 !.9.8.........5. 0040: 84 C0 12 C0 08 C0 1C C0 1B 00 16 00 13 C0 0D C0 ................ 0050: 03 00 0A C0 13 C0 09 C0 1F C0 1E 00 33 00 32 00 ............3.2. 0060: 9A 00 99 00 45 00 44 C0 0E C0 04 00 2F 00 96 00 ....E.D...../... 0070: 41 C0 11 C0 07 C0 0C C0 02 00 05 00 04 00 15 00 A............... 0080: 12 00 09 00 14 00 11 00 08 00 06 00 03 00 FF 02 ................ 0090: 01 00 00 45 00 0B 00 04 03 00 01 02 00 0A 00 34 ...E...........4 00A0: 00 32 00 0E 00 0D 00 19 00 0B 00 0C 00 18 00 09 .2.............. 00B0: 00 0A 00 16 00 17 00 08 00 06 00 07 00 14 00 15 ................ 00C0: 00 04 00 05 00 12 00 13 00 01 00 02 00 03 00 0F ................ 00D0: 00 10 00 11 00 0F 00 01 01 ......... matching alias: bogus [NioProcessor-2] DEBUG org.apache.mina.filter.ssl.SslHandler - Session Server [1] (ssl...) processing the NEED_UNWRAP state [NioProcessor-2] DEBUG org.apache.mina.filter.ssl.SslFilter - Session Server [1] (ssl...): Processing the SSL Data R: 0.0, W: 0.0 R: 0.0, W: 0.0 R: 0.0, W: 0.0 R: 0.0, W: 0.0 [NioProcessor-2] INFO org.apache.mina.example.echoserver.EchoProtocolHandler - *** IDLE #1 *** R: 0.0, W: 0.0 R: 0.0, W: 0.0 R: 0.0, W: 0.0 [NioProcessor-2] INFO org.apache.mina.example.echoserver.EchoProtocolHandler - *** IDLE #2 *** and, again, switching to oracle's jvm and it works.
        Hide
        elecharny Emmanuel Lecharny added a comment -

        I can't reproduce the pb with the coe snippet you provided. I need everything related to the KeyStore creation and initialization.

        Does it work with OpenJDK 7 btw ? (I don't have OpnJDK 6 installed locally)

        Thanks !

        Show
        elecharny Emmanuel Lecharny added a comment - I can't reproduce the pb with the coe snippet you provided. I need everything related to the KeyStore creation and initialization. Does it work with OpenJDK 7 btw ? (I don't have OpnJDK 6 installed locally) Thanks !
        Hide
        fixmo-cagney Andrew C added a comment -

        > I can't reproduce the pb with the coe snippet you provided. I need everything related to the KeyStore creation and initialization.

        Not needed. See further down in the comment; I can reproduce it using just the MINA sources by tweaking examples.echoserver.Main.

        > Does it work with OpenJDK 7 btw ? (I don't have OpnJDK 6 installed locally)

        That's part of the information I'm still gathering; will hopefully end up with a table

        Show
        fixmo-cagney Andrew C added a comment - > I can't reproduce the pb with the coe snippet you provided. I need everything related to the KeyStore creation and initialization. Not needed. See further down in the comment; I can reproduce it using just the MINA sources by tweaking examples.echoserver.Main. > Does it work with OpenJDK 7 btw ? (I don't have OpnJDK 6 installed locally) That's part of the information I'm still gathering; will hopefully end up with a table
        Hide
        elecharny Emmanuel Lecharny added a comment -

        Ah, sorry... I have stopped reading the boring SSL debug data a bit too quickly

        Ok I'll give it a try then.

        Thanks for your patience !

        Show
        elecharny Emmanuel Lecharny added a comment - Ah, sorry... I have stopped reading the boring SSL debug data a bit too quickly Ok I'll give it a try then. Thanks for your patience !
        Hide
        fixmo-cagney Andrew C added a comment -

        Finally got a scratch/clean Ubuntu system set up - 12.04.02 LTS (server):

        (Finally got a vm up) these hang:

        java version "1.6.0_27"
        OpenJDK Runtime Environment (IcedTea6 1.12.3) (6b27-1.12.3-0ubuntu1~12.04.1)
        OpenJDK 64-Bit Server VM (build 20.0-b12, mixed mode)

        java version "1.7.0_15"
        OpenJDK Runtime Environment (IcedTea7 2.3.7) (7u15-2.3.7-0ubuntu1~12.04.1)
        OpenJDK 64-Bit Server VM (build 23.7-b01, mixed mode)

        These work:

        java version "1.7.0_17"
        Java(TM) SE Runtime Environment (build 1.7.0_17-b02)
        Java HotSpot(TM) 64-Bit Server VM (build 23.7-b01, mixed mode)

        java version "1.6.0_43"
        Java(TM) SE Runtime Environment (build 1.6.0_43-b01)
        Java HotSpot(TM) 64-Bit Server VM (build 20.14-b01, mixed mode)

        Looking carefully at the OpenJDK 7 trace I see an additional line "%% Initialized", note the algorithm selected:

        00D0: 00 15 00 04 00 05 00 12 00 13 00 01 00 02 00 03 ................
        00E0: 00 0F 00 10 00 11 00 0F 00 01 01 ...........
        %% Initialized: [Session-1, SSL_NULL_WITH_NULL_NULL]
        matching alias: bogus
        [hang]

        presumably this is because I don't have bouncy castle's jars installed?

        Show
        fixmo-cagney Andrew C added a comment - Finally got a scratch/clean Ubuntu system set up - 12.04.02 LTS (server): (Finally got a vm up) these hang: java version "1.6.0_27" OpenJDK Runtime Environment (IcedTea6 1.12.3) (6b27-1.12.3-0ubuntu1~12.04.1) OpenJDK 64-Bit Server VM (build 20.0-b12, mixed mode) java version "1.7.0_15" OpenJDK Runtime Environment (IcedTea7 2.3.7) (7u15-2.3.7-0ubuntu1~12.04.1) OpenJDK 64-Bit Server VM (build 23.7-b01, mixed mode) These work: java version "1.7.0_17" Java(TM) SE Runtime Environment (build 1.7.0_17-b02) Java HotSpot(TM) 64-Bit Server VM (build 23.7-b01, mixed mode) java version "1.6.0_43" Java(TM) SE Runtime Environment (build 1.6.0_43-b01) Java HotSpot(TM) 64-Bit Server VM (build 20.14-b01, mixed mode) Looking carefully at the OpenJDK 7 trace I see an additional line "%% Initialized", note the algorithm selected: 00D0: 00 15 00 04 00 05 00 12 00 13 00 01 00 02 00 03 ................ 00E0: 00 0F 00 10 00 11 00 0F 00 01 01 ........... %% Initialized: [Session-1, SSL_NULL_WITH_NULL_NULL] matching alias: bogus [hang] presumably this is because I don't have bouncy castle's jars installed?
        Hide
        jeffmaury Jeff MAURY added a comment - - edited

        Was able to reproduce on an Ubuntu 12.10 Desktop.
        Almost working if using a MacOSX based curl: almost because no echo message is generated, probably because the SSL nego fails
        If using the Ubuntu based curl, hangs but according to the logs, not a MINA bug as the SSL nego is managed by a JDK/JRE provided SSLEngine.
        Will check to make sure using a debugging session

        Show
        jeffmaury Jeff MAURY added a comment - - edited Was able to reproduce on an Ubuntu 12.10 Desktop. Almost working if using a MacOSX based curl: almost because no echo message is generated, probably because the SSL nego fails If using the Ubuntu based curl, hangs but according to the logs, not a MINA bug as the SSL nego is managed by a JDK/JRE provided SSLEngine. Will check to make sure using a debugging session
        Hide
        jeffmaury Jeff MAURY added a comment -

        I was able to reproduce the problem with a non MINA sample program.
        Works well if using an SSLSocket and SSLServerSocketFactory
        The problem us related to SLLEngine.
        As there is some unknown extension in the Hello Client message,
        the SLLEngine works the following way:
        message arrives --> engine.unwrap --> handshake status switch to NEED-TASK --> task run --> handshake status switch to NEED-UNWRAP
        In the non MINA sample, I call again engine.unwrap with the same input (remainging = 0 because it has already been consumed) and an alert is generated back to the client.
        In MINA, as the buffer has been consumed by the first unwrap call, MINA is waiting for data from the client and this is why it is hanging.
        So I changed my opinion and I think this is a MINA bug.

        Show
        jeffmaury Jeff MAURY added a comment - I was able to reproduce the problem with a non MINA sample program. Works well if using an SSLSocket and SSLServerSocketFactory The problem us related to SLLEngine. As there is some unknown extension in the Hello Client message, the SLLEngine works the following way: message arrives --> engine.unwrap --> handshake status switch to NEED-TASK --> task run --> handshake status switch to NEED-UNWRAP In the non MINA sample, I call again engine.unwrap with the same input (remainging = 0 because it has already been consumed) and an alert is generated back to the client. In MINA, as the buffer has been consumed by the first unwrap call, MINA is waiting for data from the client and this is why it is hanging. So I changed my opinion and I think this is a MINA bug.
        Hide
        elecharny Emmanuel Lecharny added a comment -

        Jeff, can you post a sample that demonstrates the issue ?

        I have fixed may bugs in MINA SSL handling 2 years ago, so it's a bit old in my mind, but I can probably get a clue about what's going wrong if I can reproduce the pb.

        Thanks !

        Show
        elecharny Emmanuel Lecharny added a comment - Jeff, can you post a sample that demonstrates the issue ? I have fixed may bugs in MINA SSL handling 2 years ago, so it's a bit old in my mind, but I can probably get a clue about what's going wrong if I can reproduce the pb. Thanks !
        Hide
        jeffmaury Jeff MAURY added a comment -

        The code is dirty but I you run it with the same debug flags as the MINA code, you will see that the alert is generated in the unwrap call that follows the delegated task run.
        Seems to me that when a delegated task generated an exception, it is cached into the SSLEngine and the corresponding alert is generated when the unwrap call is done.
        I am working on a more simple test case (no IcedTea restricted) using incompatible cipher suites between the client and the server.

        Show
        jeffmaury Jeff MAURY added a comment - The code is dirty but I you run it with the same debug flags as the MINA code, you will see that the alert is generated in the unwrap call that follows the delegated task run. Seems to me that when a delegated task generated an exception, it is cached into the SSLEngine and the corresponding alert is generated when the unwrap call is done. I am working on a more simple test case (no IcedTea restricted) using incompatible cipher suites between the client and the server.
        Hide
        jeffmaury Jeff MAURY added a comment -

        I have been able to reproduce it on a non IcedTea/non Linux only configuration.
        On the client side, ask to do TLSv1.1 only by setting sslFilter.setEnabledProtocols(new String[]

        { "TLSv1.1" }

        );
        On the server side, ask to do TLSv1 only and the client will hang the same way when receiving the ServerHello message.
        Tested on MacOS JDK1.7.0_17

        Show
        jeffmaury Jeff MAURY added a comment - I have been able to reproduce it on a non IcedTea/non Linux only configuration. On the client side, ask to do TLSv1.1 only by setting sslFilter.setEnabledProtocols(new String[] { "TLSv1.1" } ); On the server side, ask to do TLSv1 only and the client will hang the same way when receiving the ServerHello message. Tested on MacOS JDK1.7.0_17
        Hide
        elecharny Emmanuel Lecharny added a comment -

        Jeff, can you add an @Ignored test for this ? Thanks !

        Show
        elecharny Emmanuel Lecharny added a comment - Jeff, can you add an @Ignored test for this ? Thanks !

          People

          • Assignee:
            Unassigned
            Reporter:
            fixmo-cagney Andrew C
          • Votes:
            0 Vote for this issue
            Watchers:
            3 Start watching this issue

            Dates

            • Created:
              Updated:

              Development