"Buffer underflow in doHandshake" SSL error in Oracle Service Bus

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