RSS

“Buffer underflow in doHandshake” SSL error in Oracle Service Bus

11 Jun

We are using Oracle Service Bus for SSL communication to an external party. Due to security regulations we use a proxy server configuration (note: not proxy service, but proxy server) on these specific business services.

After upgrading our OSB to 11g PS4 we wanted to use the JSSE implementation for SSL because in the near future we will need to implement SHA2 certificates. After enabling JSSE (weblogic console -> managed server -> SSL -> Advanced) the outgoing connections still seem to work. However when we send a large message (in our case > 20kb) we receive the following error in our logging:


<Debug> <Socket> <someHostname> <someManagedServer> <[ACTIVE] ExecuteThread: '2' for queue: 'weblogic.kernel.Default (self-tuning)'> <<anonymous>> <> <3fe931....> <13...> <BEA-000400> <buffer underflow in doHandshake>

The source of all knowlegde Wikipedia tells us that:
In computing buffer underrun or buffer underflow is a state occurring when a buffer used to communicate between two devices or processes is fed with data at a lower speed than the data is being read from it. This requires the program or device reading from the buffer to pause its processing while the buffer refills. This can cause undesired and sometimes serious side effects because the data being buffered is generally not suited to stop-start access of this kind.

After enabling Weblogic SSL logging we see the below output (simplified) in the logfiles when sending a small message. The SSLEngine both shows wrap and unwrap methods.


<Debug> <SecurityCertPath> <BEA-000000> <CertPathTrustManagerUtils.doCertPathValidation: >
<Debug> <SecurityCertPath> <BEA-000000> <CertPathTrustManagerUtils.doCertPathValidation: configured to defer to the admin>
<Debug> <SecurityCertPath> <BEA-000000> <CertPathTrustManagerUtils.doCertPathValidation: outbound = true>
<Debug> <SecurityCertPath> <BEA-000000> <CertPathTrustManagerUtils.doCertPathValidation: style = BuiltinSSLValidationOnly>
<Debug> <SecurityCertPath> <BEA-000000> <CertPathTrustManagerUtils.doCertPathValidation: returning false>
<Debug> <SecurityCertPath> <BEA-000000> <CertPathTrustManagerUtils.certificateCallback: returning true because the CertPathValidators should not be called>
<Debug> <SecuritySSL> <BEA-000000> <weblogic user specified trustmanager validation status 0>
<Debug> <SecuritySSL> <BEA-000000> <SSLTrustValidator returns: 0>
<Debug> <SecuritySSL> <BEA-000000> <[Thread[[ACTIVE] ExecuteThread: '2' for queue: 'weblogic.kernel.Default (self-tuning)',5,Pooled Threads]]...SSLENGINE: No trust failure, validateErr=0.>
<Debug> <SecuritySSL> <BEA-000000> <Performing hostname validation checks: remote.website.nl>
<Debug> <SecuritySSL> <BEA-000000> <Proxying through ourDMZproxyserver.local>
<Debug> <SecuritySSL> <BEA-000000> <[Thread[[ACTIVE] ExecuteThread: '2' for queue: 'weblogic.kernel.Default (self-tuning)',5,Pooled Threads]]...SSLENGINE: Successfully completed post-handshake processing.>
<Debug> <SecuritySSL> <BEA-000000> <[Thread[[ACTIVE] ExecuteThread: '2' for queue: 'weblogic.kernel.Default (self-tuning)',5,Pooled Threads]]...SSLENGINE: SSLEngine.wrap(ByteBuffer,ByteBuffer) called: result=Status = OK HandshakeStatus = NOT_HANDSHAKING bytesConsumed = 304 bytesProduced = 325.>
<Debug> <SecuritySSL> <BEA-000000> <[Thread[[ACTIVE] ExecuteThread: '2' for queue: 'weblogic.kernel.Default (self-tuning)',5,Pooled Threads]]...SSLENGINE: SSLEngine.wrap(ByteBuffer,ByteBuffer) called: result=Status = OK HandshakeStatus = NOT_HANDSHAKING bytesConsumed = 2167 bytesProduced = 2188.>
<Debug> <SecuritySSL> <BEA-000000> <[Thread[[ACTIVE] ExecuteThread: '1' for queue: 'weblogic.kernel.Default (self-tuning)',5,Pooled Threads]]...SSLENGINE: SSLEngine.unwrap(ByteBuffer,ByteBuffer) called: result=Status = OK HandshakeStatus = NOT_HANDSHAKING bytesConsumed = 164 bytesProduced = 143.>
<Debug> <SecuritySSL> <BEA-000000> <[Thread[[ACTIVE] ExecuteThread: '1' for queue: 'weblogic.kernel.Default (self-tuning)',5,Pooled Threads]]...SSLENGINE: SSLEngine.unwrap(ByteBuffer,ByteBuffer) called: result=Status = OK HandshakeStatus = NOT_HANDSHAKING bytesConsumed = 1036 bytesProduced = 1015.>

When sending a larger message the logging seems identical, however the logging stops after the outbound communication (wrap method) and no inbound traphic seems to return (unwrap method).


<Debug> <SecurityCertPath> <BEA-000000> <CertPathTrustManagerUtils.doCertPathValidation: >
<Debug> <SecurityCertPath> <CertPathTrustManagerUtils.doCertPathValidation: configured to defer to the admin>
<Debug> <SecurityCertPath> <CertPathTrustManagerUtils.doCertPathValidation: outbound = true>
<Debug> <SecurityCertPath> <CertPathTrustManagerUtils.doCertPathValidation: style = BuiltinSSLValidationOnly>
<Debug> <SecurityCertPath> <CertPathTrustManagerUtils.doCertPathValidation: returning false>
<Debug> <SecurityCertPath> <CertPathTrustManagerUtils.certificateCallback: returning true because the CertPathValidators should not be called>
<Debug> <SecuritySSL> <weblogic user specified trustmanager validation status 0>
<Debug> <SecuritySSL> <SSLTrustValidator returns: 0>
<Debug> <SecuritySSL> <[Thread[[ACTIVE] ExecuteThread: '8' for queue: 'weblogic.kernel.Default (self-tuning)',5,Pooled Threads]]...SSLENGINE: No trust failure, validateErr=0.>
<Debug> <SecuritySSL> <Performing hostname validation checks: remote.website.nl>
<Debug> <SecuritySSL> <Proxying through ourDMZproxyserver.local>
<Debug> <SecuritySSL> <BEA-000000> <[Thread[[ACTIVE] ExecuteThread: '8' for queue: 'weblogic.kernel.Default (self-tuning)',5,Pooled Threads]]...SSLENGINE: Successfully completed post-handshake processing.>
<Debug> <SecuritySSL> <BEA-000000> <[Thread[[ACTIVE] ExecuteThread: '8' for queue: 'weblogic.kernel.Default (self-tuning)',5,Pooled Threads]]...SSLENGINE: SSLEngine.wrap(ByteBuffer,ByteBuffer) called: result=Status = OK HandshakeStatus = NOT_HANDSHAKING bytesConsumed = 306 bytesProduced = 327.>
<Debug> <SecuritySSL> <BEA-000000> <[Thread[[ACTIVE] ExecuteThread: '8' for queue: 'weblogic.kernel.Default (self-tuning)',5,Pooled Threads]]...SSLENGINE: SSLEngine.wrap(ByteBuffer,ByteBuffer) called: result=Status = OK HandshakeStatus = NOT_HANDSHAKING bytesConsumed = 16384 bytesProduced = 16405.>

At a very high level, the SSLEngine works like this (source: Class SSLEngine @ Oracle):

                |           ^
                |     |     |
                v     |     |
           +----+-----|-----+----+
           |          |          |
           |       SSL|Engine    |
   wrap()  |          |          |  unwrap()
           | OUTBOUND | INBOUND  |
           |          |          |
           +----+-----|-----+----+
                |     |     ^
                |     |     |
                v           |

Remember when we disable JSSE and use the Certicom implementation the process still works perfectly. So everything pointed to the direction of a combination: JSSE + large message = error. Sadly the .log and .out didn’t help in the problem solving here so experimenting with a few tuning parameters did the trick for us.

After configuring the Business Service to use Chunked Streaming Mode the problem was solved and we again succeeded in sending out messages of multiple MB’s to our external trading partners.

When I initially used Google and Oracle Knowledge base to look for the “BEA-000400 buffer underflow in doHandshake” error this was not very helpfull. So hopefully this blogpost is helpfull for others in the future when they have the same problem as us.

About these ads
 
14 Comments

Posted by on 11-06-2012 in Oracle, OSB, Security, SSL

 

Tags: , , ,

14 responses to ““Buffer underflow in doHandshake” SSL error in Oracle Service Bus

  1. shuttle

    11-07-2012 at 10:45

    two-way SSL not working with JSSE:

    in OSB: The invocation resulted in an error: General SSLEngine problem.

    Starting parameters are set:

    startWeblogic.sh -Djavax.net.ssl.keyStore=keystore.jks -Djavax.net.ssl.keyStorePassword=password -Djavax.net.ssl.keyStoreType=jks -Djavax.net.ssl.trustStore=truststore.jks -Djavax.net.ssl.trustStorePassword=password -Djavax.net.ssl.trustStoreType=jks -Djava.protocol.handler.pkgs=com.sun.net.ssl.internal.www.protocol

    Caused By: sun.security.validator.ValidatorException: PKIX path building failed: sun.security.provider.certpath.SunCertPathBuilderException: unable to find valid certification path to requested target

    have you any idea?

     
    • jvzoggel

      11-07-2012 at 13:30

      I usually configure the keystore and truststore using the /console Managed Server configuration. But I guess this might get you there as well. :) Looking at the error my 1st guess would be your Weblogic connection doesn’t trust the endpoint. So you might wanna check your truststore.jks if all certificates from the other party are there. Including any Certifcate Authority or Intermediate certificate in that certificate chain.

      Dont forget to import the root CA with the keytool parameter -trustcacerts

      examples:

      http://jvzoggel.wordpress.com/2011/08/04/weblogic-default-demoidentity-and-demotrust-password/

      http://jvzoggel.wordpress.com/2011/12/16/configuring-ssl-for-oracle-weblogic-and-ofmw/

       
      • shuttle

        11-07-2012 at 19:27

        Txh for answer.
        Weird. Setting the proper certificate in truststore, I am faced with NPE. :(

        With OSB Test client:

        [ACTIVE] ExecuteThread: ‘0’ for queue: ‘weblogic.kernel.Default (self-tuning)’, WRITE: TLSv1 Application Data, length = 304

        [ACTIVE] ExecuteThread: ‘0’ for queue: ‘weblogic.kernel.Default (self-tuning)’, WRITE: TLSv1 Application Data, length = 6569

        [ACTIVE] ExecuteThread: ‘0’ for queue: ‘weblogic.kernel.Default (self-tuning)’, WRITE: TLSv1 Application Data, length = 8

         
      • shuttle

        11-07-2012 at 19:29

        Log in better format:

        -Jul 11, 2012 7:23:16 PM CEST- -Debug- -SecuritySSL- -BEA-000000- -weblogic user specified trustmanager validation status 0-
        -Jul 11, 2012 7:23:16 PM CEST- -Debug- -SecuritySSL- -BEA-000000- -SSLTrustValidator returns: 0-
        -Jul 11, 2012 7:23:16 PM CEST- -Debug- -SecuritySSL- -BEA-000000- -[Thread[[ACTIVE] ExecuteThread: ‘0’ for queue: ‘weblogic.kernel.Default (self-tuning)’,5,Pooled Threads]]weblogic.security.SSL.jsseadapter: SSLENGINE: No trust failure, validateErr=0.-
        -Jul 11, 2012 7:23:16 PM CEST- -Debug- -SecuritySSL- -BEA-000000- -Performing hostname validation checks: test.com-
        -Jul 11, 2012 7:23:16 PM CEST- -Debug- -SecuritySSL- -BEA-000000- -Proxying through proxy.example.com-
        -Jul 11, 2012 7:23:16 PM CEST- -Debug- -SecuritySSL- -BEA-000000- -[Thread[[ACTIVE] ExecuteThread: ‘0’ for queue: ‘weblogic.kernel.Default (self-tuning)’,5,Pooled Threads]]weblogic.security.SSL.jsseadapter: SSLENGINE: Successfully completed post-handshake processing.-
        [ACTIVE] ExecuteThread: ‘0’ for queue: ‘weblogic.kernel.Default (self-tuning)’, WRITE: TLSv1 Application Data, length = 304
        -Jul 11, 2012 7:23:16 PM CEST- -Debug- -SecuritySSL- -BEA-000000- -[Thread[[ACTIVE] ExecuteThread: ‘0’ for queue: ‘weblogic.kernel.Default (self-tuning)’,5,Pooled Threads]]weblogic.security.SSL.jsseadapter: SSLENGINE: SSLEngine.wrap(ByteBuffer,ByteBuffer) called: result=Status = OK HandshakeStatus = NOT_HANDSHAKING
        bytesConsumed = 304 bytesProduced = 325.-
        [ACTIVE] ExecuteThread: ‘0’ for queue: ‘weblogic.kernel.Default (self-tuning)’, WRITE: TLSv1 Application Data, length = 6569
        -Jul 11, 2012 7:23:16 PM CEST- -Debug- -SecuritySSL- -BEA-000000- -[Thread[[ACTIVE] ExecuteThread: ‘0’ for queue: ‘weblogic.kernel.Default (self-tuning)’,5,Pooled Threads]]weblogic.security.SSL.jsseadapter: SSLENGINE: SSLEngine.wrap(ByteBuffer,ByteBuffer) called: result=Status = OK HandshakeStatus = NOT_HANDSHAKING
        bytesConsumed = 6569 bytesProduced = 6590.-
        [ACTIVE] ExecuteThread: ‘0’ for queue: ‘weblogic.kernel.Default (self-tuning)’, WRITE: TLSv1 Application Data, length = 8
        -Jul 11, 2012 7:23:16 PM CEST- -Debug- -SecuritySSL- -BEA-000000- -[Thread[[ACTIVE] ExecuteThread: ‘0’ for queue: ‘weblogic.kernel.Default (self-tuning)’,5,Pooled Threads]]weblogic.security.SSL.jsseadapter: SSLENGINE: SSLEngine.wrap(ByteBuffer,ByteBuffer) called: result=Status = OK HandshakeStatus = NOT_HANDSHAKING
        bytesConsumed = 8 bytesProduced = 29.-
        -Jul 11, 2012 7:23:16 PM CEST- -Debug- -SecuritySSL- -BEA-000000- -SSLIOContextTable.findContext(sock): 499044511-
        -Jul 11, 2012 7:23:16 PM CEST- -Info- -OSB Kernel- -BEA-398205- –
        [OSB Tracing] Outbound request caused an exception

        Service Ref = TEST_BS
        URI = https://….
        Error Message = java.lang.NullPointerException
        Payload =

        -

         
      • shuttle

        21-07-2012 at 10:34

        There was a bug in Weblogic.

        Patch 14255420: SU Patch [TJHY]: NPE IN JSSEFILTERIMPL DOHANDSHAKE solved this issue.

         
  2. jvzoggel

    12-07-2012 at 09:52

    I can see the handshake fails but don’t recognize why. Since you refer to using 2-way SSL. Did you In the OSB project: configure a Service Key Provider for SSL, connect SKP to Proxy on security tab, select client certificate on business service http tab ?

     
    • shuttle

      12-07-2012 at 10:24

      I’ve tried this with another ssl service (no 2-way) but It didn’t work :(

      I’ve experienced the same thing like in this forum thread: https://forums.oracle.com/forums/thread.jspa?threadID=2263305

       
      • jvzoggel

        12-07-2012 at 12:48

        You also tried the -Dweblogic.security.SSL.enable.renegotiation=true solution mentioned there ?

         
    • shuttle

      12-07-2012 at 12:22

      OS: RHEL / 2.6.18-238.el5 #1 SMP Sun Dec 19 14:22:44 EST 2010 x86_64 x86_64 x86_64 GNU/Linux
      Oracle Service Bus Version: 11.1.1.4
      WebLogic Server Version: 10.3.4.0

       
    • shuttle

      12-07-2012 at 12:49

      Running with the newest OSB from windows box:

      Oracle Service Bus Version: [Oracle Service Bus 11.1 Sun Dec 18 03:49:34 PST 2011 1447174]
      Oracle Weblogic Server Version: [WebLogic Server 10.3.6.0 Tue Nov 15 08:52:36 PST 2011 1441050 ]

      [ACTIVE] ExecuteThread: ‘2’ for queue: ‘weblogic.kernel.Default (self-tuning)’, READ: TLSv1 Handshake, length = 20
      Allow unsafe renegotiation: true
      Allow legacy hello messages: true
      Is initial handshake: false
      Is secure renegotiation: true
      [2012.07.12. 12:43:47 CEST] [Debug] [SecuritySSL] [BEA-000000] [[Thread[[ACTIVE] ExecuteThread: ‘2’ for queue: ‘weblogic.kernel.Default (self-tuning)’,5,Poole
      d Threads]]weblogic.security.SSL.jsseadapter: SSLENGINE: SSLEngine.unwrap(ByteBuffer,ByteBuffer[]) called: result=Status = OK HandshakeStatus = NEED_TASK
      bytesConsumed = 25 bytesProduced = 0.]
      *** HelloRequest (empty)
      %% Client cached [Session-9, SSL_RSA_WITH_RC4_128_MD5]
      %% Try resuming [Session-9, SSL_RSA_WITH_RC4_128_MD5] from port -1
      *** ClientHello, TLSv1
      RandomCookie: GMT: 1325247075 bytes = { 112, 138, 149, 137, 213, 113, 190, 13, 80, 207, 39, 174, 95, 26, 92, 13, 161, 176, 87, 73, 198, 176, 196, 74, 238, 11
      8, 84, 206 }
      Session ID: {229, 22, 0, 0, 78, 104, 202, 145, 134, 235, 123, 52, 188, 38, 249, 154, 131, 184, 66, 225, 189, 160, 214, 38, 202, 235, 61, 229, 14, 17, 222, 93
      }
      Cipher Suites: [SSL_RSA_WITH_RC4_128_MD5, SSL_RSA_WITH_RC4_128_SHA, TLS_RSA_WITH_AES_128_CBC_SHA, TLS_DHE_RSA_WITH_AES_128_CBC_SHA, TLS_DHE_DSS_WITH_AES_128_C
      BC_SHA, SSL_RSA_WITH_3DES_EDE_CBC_SHA, SSL_DHE_RSA_WITH_3DES_EDE_CBC_SHA, SSL_DHE_DSS_WITH_3DES_EDE_CBC_SHA, SSL_RSA_WITH_DES_CBC_SHA, SSL_DHE_RSA_WITH_DES_CB
      C_SHA, SSL_DHE_DSS_WITH_DES_CBC_SHA, SSL_RSA_EXPORT_WITH_RC4_40_MD5, SSL_RSA_EXPORT_WITH_DES40_CBC_SHA, SSL_DHE_RSA_EXPORT_WITH_DES40_CBC_SHA, SSL_DHE_DSS_EXP
      ORT_WITH_DES40_CBC_SHA]
      Compression Methods: { 0 }
      Extension renegotiation_info, renegotiated_connection: 35:ec:cd:48:47:89:be:40:5e:5f:35:0e
      ***
      [ACTIVE] ExecuteThread: ‘2’ for queue: ‘weblogic.kernel.Default (self-tuning)’, WRITE: TLSv1 Handshake, length = 140
      [2012.07.12. 12:43:47 CEST] [Error] [WliSbTransports] [BEA-381304] [Exception in HttpOutboundMessageContext.RetrieveHttpResponseWork.run: java.lang.NullPointe
      rException
      java.lang.NullPointerException
      at weblogic.socket.JSSEFilterImpl.doHandshake(JSSEFilterImpl.java:101)
      at weblogic.socket.JSSEFilterImpl.handleResultsCommonly(JSSEFilterImpl.java:659)
      at weblogic.socket.JSSEFilterImpl.handleUnwrapResults(JSSEFilterImpl.java:550)
      at weblogic.socket.JSSEFilterImpl.unwrapAndHandleResults(JSSEFilterImpl.java:456)
      at weblogic.socket.JSSEFilterImpl.read(JSSEFilterImpl.java:370)
      at weblogic.socket.JSSESocket$JSSEInputStream.read(JSSESocket.java:58)
      at java.io.BufferedInputStream.fill(BufferedInputStream.java:218)
      at java.io.BufferedInputStream.read(BufferedInputStream.java:237)
      at java.io.SequenceInputStream.read(SequenceInputStream.java:149)
      at java.io.SequenceInputStream.read(SequenceInputStream.java:152)
      at weblogic.net.http.MessageHeader.parseHeader(MessageHeader.java:151)
      at weblogic.net.http.HttpClient.parseHTTP(HttpClient.java:468)
      at weblogic.net.http.HttpURLConnection.getInputStream(HttpURLConnection.java:401)
      at weblogic.net.http.SOAPHttpsURLConnection.getInputStream(SOAPHttpsURLConnection.java:37)
      at weblogic.net.http.HttpURLConnection.getResponseCode(HttpURLConnection.java:1005)
      at com.bea.wli.sb.transports.http.HttpOutboundMessageContext.getResponse(HttpOutboundMessageContext.java:679)
      at com.bea.wli.sb.transports.http.wls.HttpOutboundMessageContextWls.access$100(HttpOutboundMessageContextWls.java:26)
      at com.bea.wli.sb.transports.http.wls.HttpOutboundMessageContextWls$RetrieveHttpResponseWork.handleResponse(HttpOutboundMessageContextWls.java:96)
      at weblogic.net.http.AsyncResponseHandler$MuxableSocketHTTPAsyncResponse$RunnableCallback.run(AsyncResponseHandler.java:535)
      at weblogic.work.ContextWrap.run(ContextWrap.java:41)
      at weblogic.work.SelfTuningWorkManagerImpl$WorkAdapterImpl.run(SelfTuningWorkManagerImpl.java:545)
      at weblogic.work.ExecuteThread.execute(ExecuteThread.java:256)
      at weblogic.work.ExecuteThread.run(ExecuteThread.java:221)
      ]
      [2012.07.12. 12:44:11 CEST] [Info] [Health] [BEA-310002] [43% of the total memory in the server is free]

       
      • Subodh

        23-11-2012 at 06:04

        Have you got any solution for this issue? I am also facing same problem with wl10.3

        Thanks

         
    • shuttle

      12-07-2012 at 15:48

      “-Dweblogic.security.SSL.enable.renegotiation=true” and “-Dsun.security.ssl.allowUnsafeRenegotiation=true” is also set :(

       
    • shuttle

      12-07-2012 at 23:46

      Tested with SoapUI everything works like a charm. But with IIS it fails.

       
  3. nexus

    12-08-2014 at 09:23

    Thank you for this great article. We had exact the same problem and could solve it with your help. This saved a lot of time.

     

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s

 
Follow

Get every new post delivered to your Inbox.

Join 355 other followers

%d bloggers like this: