weblogic ssl performance issue

Question

I have a web service client running on WebLogic 10.3. Below is a snippet of the server log when the app begins to connect to the hosting server.

<Feb 25, 2011 2:27:52 PM EST> <Debug> <SecuritySSL> <BEA-000000> <SSLSetup: loading trusted CA certificates>
<Feb 25, 2011 2:28:15 PM EST> <Debug> <SecuritySSL> <BEA-000000> <Filtering JSSE SSLSocket>
<Feb 25, 2011 2:28:15 PM EST> <Debug> <SecuritySSL> <BEA-000000> <SSLIOContextTable.addContext(ctx): 15837882>
<Feb 25, 2011 2:28:15 PM EST> <Debug> <SecuritySSL> <BEA-000000> <SSLSocket will  be Muxing>

Notice that the between the first message and the second message, there is a 23 second delay in this case. Can anybody explain to me what's going on here and what I can do to improve this?

There is a stacktrace warning that pops up later in the log, but I don't see how it could cause this. A valid response ends up coming back from the hosting server, but the total time is about 24 seconds. Thanks for any help that any of you can give.

Respectfully,

Kal

Edit: Adding new log messages...

<Mar 1, 2011 2:18:38 PM EST> <Debug> <SecuritySSL> <BEA-000000> <Use Certicom SSL with Domestic strength>
<Mar 1, 2011 2:18:38 PM EST> <Debug> <SecuritySSL> <BEA-000000> <Will use default Mac for algorithm HmacSHA1>
<Mar 1, 2011 2:18:38 PM EST> <Debug> <SecuritySSL> <BEA-000000> <Will use default Mac for algorithm HmacMD5>
<Mar 1, 2011 2:18:38 PM EST> <Debug> <SecuritySSL> <BEA-000000> <Will use default KeyAgreement for algorithm DiffieHellman>
<Mar 1, 2011 2:18:38 PM EST> <Debug> <SecuritySSL> <BEA-000000> <Will use default KeyAgreement for algorithm ECDH>
<Mar 1, 2011 2:18:38 PM EST> <Debug> <SecuritySSL> <BEA-000000> <Will use default Cipher for algorithm DESede>
<Mar 1, 2011 2:18:38 PM EST> <Debug> <SecuritySSL> <BEA-000000> <Will use default Cipher for algorithm DES>
<Mar 1, 2011 2:18:38 PM EST> <Debug> <SecuritySSL> <BEA-000000> <Will use default Cipher for algorithm AES>
<Mar 1, 2011 2:18:38 PM EST> <Debug> <SecuritySSL> <BEA-000000> <Will use default Cipher for algorithm RC4>
<Mar 1, 2011 2:18:38 PM EST> <Debug> <SecuritySSL> <BEA-000000> <Will use default Cipher for algorithm RSA/ECB/PKCS1Padding>
<Mar 1, 2011 2:18:38 PM EST> <Debug> <SecuritySSL> <BEA-000000> <Will use default Cipher for algorithm RSA/ECB/NoPadding>
<Mar 1, 2011 2:18:38 PM EST> <Debug> <SecuritySSL> <BEA-000000> <SSL Session TTL :90000>
<Mar 1, 2011 2:18:38 PM EST> <Debug> <SecuritySSL> <BEA-000000> <DefaultHostnameVerifier: allowReverseDNS=false>
<Mar 1, 2011 2:18:38 PM EST> <Debug> <SecuritySSL> <BEA-000000> <SSLSetup: loading trusted CA certificates>
<Mar 1, 2011 2:18:38 PM EST> <Debug> <SecuritySSL> <BEA-000000> <SSL enableUnencryptedNullCipher= false>
<Mar 1, 2011 2:18:38 PM EST> <Debug> <SecuritySSL> <BEA-000000> <SSLContextManager: loading server SSL identity>
<Mar 1, 2011 2:18:38 PM EST> <Notice> <Security> <BEA-090171> <Loading the identity certificate and private key stored under the alias {myAlias} from the jks keystore file /app/local/BEA/certificates/tmp/IdentityKeyStore.jks.>
<Mar 1, 2011 2:18:38 PM EST> <Debug> <SecuritySSL> <BEA-000000> <Loaded public identity certificate chain:>
<Mar 1, 2011 2:18:38 PM EST> <Debug> <SecuritySSL> <BEA-000000> <Subject: CN={common name}, OU=Integrated Advertising IT P50, O="{company name}", L=Kansas City, ST=Missouri, C=US; Issuer: CN=VeriSign Class 3 Secure Server CA - G2, OU=Terms of use at https://www.verisign.com/rpa (c)09, OU=VeriSign Trust Network, O="VeriSign, Inc.", C=US>
<Mar 1, 2011 2:18:38 PM EST> <Debug> <SecuritySSL> <BEA-000000> <Subject: CN=VeriSign Class 3 Secure Server CA - G2, OU=Terms of use at https://www.verisign.com/rpa (c)09, OU=VeriSign Trust Network, O="VeriSign, Inc.", C=US; Issuer: OU=VeriSign Trust Network, OU="(c) 1998 VeriSign, Inc. - For authorized use only", OU=Class 3 Public Primary Certification Authority - G2, O="VeriSign, Inc.", C=US>
<Mar 1, 2011 2:18:38 PM EST> <Debug> <SecuritySSL> <BEA-000000> <Subject: OU=VeriSign Trust Network, OU="(c) 1998 VeriSign, Inc. - For authorized use only", OU=Class 3 Public Primary Certification Authority - G2, O="VeriSign, Inc.", C=US; Issuer: OU=VeriSign Trust Network, OU="(c) 1998 VeriSign, Inc. - For authorized use only", OU=Class 3 Public Primary Certification Authority - G2, O="VeriSign, Inc.", C=US>
<Mar 1, 2011 2:18:38 PM EST> <Debug> <SecuritySSL> <BEA-000000> <Will use default Cipher for algorithm RSA/ECB/NoPadding>
<Mar 1, 2011 2:18:40 PM EST> <Notice> <Security> <BEA-090169> <Loading trusted certificates from the jks keystore file /app/local/BEA/certificates/tmp/TrustKeyStore.jks.>
<Mar 1, 2011 2:18:40 PM EST> <Debug> <SecuritySSL> <BEA-000000> <SSLContextManager: loaded 1 trusted CAs from /app/local/BEA/certificates/tmp/TrustKeyStore.jks>
<Mar 1, 2011 2:18:40 PM EST> <Debug> <SecuritySSL> <BEA-000000> <Subject: CN=VeriSign Class 3 Secure Server CA - G2, OU=Terms of use at https://www.verisign.com/rpa (c)09, OU=VeriSign Trust Network, O="VeriSign, Inc.", C=US; Issuer: OU=VeriSign Trust Network, OU="(c) 1998 VeriSign, Inc. - For authorized use only", OU=Class 3 Public Primary Certification Authority - G2, O="VeriSign, Inc.", C=US>
<Mar 1, 2011 2:18:40 PM EST> <Info> <WebLogicServer> <BEA-000307> <Exportable key maximum lifespan set to 500 uses.>
<Mar 1, 2011 2:19:08 PM EST> <Debug> <SecuritySSL> <BEA-000000> <Filtering JSSE SSLSocket>
<Mar 1, 2011 2:19:08 PM EST> <Debug> <SecuritySSL> <BEA-000000> <SSLIOContextTable.addContext(ctx): 25094672>
<Mar 1, 2011 2:19:08 PM EST> <Debug> <SecuritySSL> <BEA-000000> <SSLSocket will  be Muxing>
<Mar 1, 2011 2:19:08 PM EST> <Debug> <SecuritySSL> <BEA-000000> <write SSL_20_RECORD>
<Mar 1, 2011 2:19:08 PM EST> <Debug> <SecuritySSL> <BEA-000000> <isMuxerActivated: false>
<Mar 1, 2011 2:19:08 PM EST> <Debug> <SecuritySSL> <BEA-000000> <23512240 SSL3/TLS MAC>
<Mar 1, 2011 2:19:08 PM EST> <Debug> <SecuritySSL> <BEA-000000> <23512240 received HANDSHAKE>
<Mar 1, 2011 2:19:08 PM EST> <Debug> <SecuritySSL> <BEA-000000> <HANDSHAKEMESSAGE: ServerHello>
<Mar 1, 2011 2:19:08 PM EST> <Debug> <SecuritySSL> <BEA-000000> <HANDSHAKEMESSAGE: Certificate>
<Mar 1, 2011 2:19:08 PM EST> <Debug> <SecuritySSL> <BEA-000000> <Validating certificate 0 in the chain: Serial number: {serial number}
Issuer:C=US, O=VeriSign, Inc., OU=VeriSign Trust Network, OU=Terms of use at https://www.verisign.com/rpa (c)09, CN=VeriSign Class 3 Secure Server CA - G2
Subject:C=US, ST=Washington, O={company}, OU=IT, CN={hosting server}
Not Valid Before:Thu Sep 16 20:00:00 EDT 2010
Not Valid After:Thu Oct 13 19:59:59 EDT 2011
Signature Algorithm:SHA1withRSA
>
<Mar 1, 2011 2:19:08 PM EST> <Debug> <SecuritySSL> <BEA-000000> <Validating certificate 1 in the chain: Serial number: {serial number}
Issuer:C=US, O=VeriSign, Inc., OU=Class 3 Public Primary Certification Authority - G2, OU=(c) 1998 VeriSign, Inc. - For authorized use only, OU=VeriSign Trust Network
Subject:C=US, O=VeriSign, Inc., OU=VeriSign Trust Network, OU=Terms of use at https://www.verisign.com/rpa (c)09, CN=VeriSign Class 3 Secure Server CA - G2
Not Valid Before:Tue Mar 24 20:00:00 EDT 2009
Not Valid After:Sun Mar 24 19:59:59 EDT 2019
Signature Algorithm:SHA1withRSA
>
<Mar 1, 2011 2:19:08 PM EST> <Debug> <SecuritySSL> <BEA-000000> <validationCallback: validateErr = 0>
<Mar 1, 2011 2:19:08 PM EST> <Debug> <SecuritySSL> <BEA-000000> <  cert[0] = Serial number: {serial number}
Issuer:C=US, O=VeriSign, Inc., OU=VeriSign Trust Network, OU=Terms of use at https://www.verisign.com/rpa (c)09, CN=VeriSign Class 3 Secure Server CA - G2
Subject:C=US, ST=Washington, O={company}, OU=IT, CN={hosting server}
Not Valid Before:Thu Sep 16 20:00:00 EDT 2010
Not Valid After:Thu Oct 13 19:59:59 EDT 2011
Signature Algorithm:SHA1withRSA
>
<Mar 1, 2011 2:19:08 PM EST> <Debug> <SecuritySSL> <BEA-000000> <  cert[1] = Serial number: {serial number}
Issuer:C=US, O=VeriSign, Inc., OU=Class 3 Public Primary Certification Authority - G2, OU=(c) 1998 VeriSign, Inc. - For authorized use only, OU=VeriSign Trust Network
Subject:C=US, O=VeriSign, Inc., OU=VeriSign Trust Network, OU=Terms of use at https://www.verisign.com/rpa (c)09, CN=VeriSign Class 3 Secure Server CA - G2
Not Valid Before:Tue Mar 24 20:00:00 EDT 2009
Not Valid After:Sun Mar 24 19:59:59 EDT 2019
Signature Algorithm:SHA1withRSA
>
<Mar 1, 2011 2:19:08 PM EST> <Debug> <SecuritySSL> <BEA-000000> <weblogic user specified trustmanager validation status 0>
<Mar 1, 2011 2:19:08 PM EST> <Debug> <SecuritySSL> <BEA-000000> <SSLTrustValidator returns: 0>
<Mar 1, 2011 2:19:08 PM EST> <Debug> <SecuritySSL> <BEA-000000> <Trust status (0): NONE>
<Mar 1, 2011 2:19:08 PM EST> <Debug> <SecuritySSL> <BEA-000000> <Performing hostname validation checks: {hosting server}>
<Mar 1, 2011 2:19:08 PM EST> <Debug> <SecuritySSL> <BEA-000000> <HANDSHAKEMESSAGE: ServerHelloDone>
<Mar 1, 2011 2:19:08 PM EST> <Debug> <SecuritySSL> <BEA-000000> <Will use default Mac for algorithm HmacMD5>
<Mar 1, 2011 2:19:08 PM EST> <Debug> <SecuritySSL> <BEA-000000> <Will use default Mac for algorithm HmacSHA1>
<Mar 1, 2011 2:19:08 PM EST> <Debug> <SecuritySSL> <BEA-000000> <Will use default Mac for algorithm MD5>
<Mar 1, 2011 2:19:08 PM EST> <Debug> <SecuritySSL> <BEA-000000> <Will use default Cipher for algorithm RC4>
<Mar 1, 2011 2:19:08 PM EST> <Debug> <SecuritySSL> <BEA-000000> <Will use default Mac for algorithm HmacMD5>
<Mar 1, 2011 2:19:08 PM EST> <Debug> <SecuritySSL> <BEA-000000> <Will use default Mac for algorithm HmacSHA1>
<Mar 1, 2011 2:19:08 PM EST> <Debug> <SecuritySSL> <BEA-000000> <Will use default Cipher for algorithm RSA/ECB/PKCS1Padding>
<Mar 1, 2011 2:19:08 PM EST> <Debug> <SecuritySSL> <BEA-000000> <write HANDSHAKE, offset = 0, length = 134>
<Mar 1, 2011 2:19:08 PM EST> <Debug> <SecuritySSL> <BEA-000000> <write CHANGE_CIPHER_SPEC, offset = 0, length = 1>
<Mar 1, 2011 2:19:08 PM EST> <Debug> <SecuritySSL> <BEA-000000> <Will use default Cipher for algorithm RC4>
<Mar 1, 2011 2:19:08 PM EST> <Debug> <SecuritySSL> <BEA-000000> <Will use default Mac for algorithm HMACMD5>
<Mar 1, 2011 2:19:08 PM EST> <Debug> <SecuritySSL> <BEA-000000> <Will use default Mac for algorithm HmacMD5>
<Mar 1, 2011 2:19:08 PM EST> <Debug> <SecuritySSL> <BEA-000000> <Will use default Mac for algorithm HmacSHA1>
<Mar 1, 2011 2:19:08 PM EST> <Debug> <SecuritySSL> <BEA-000000> <write HANDSHAKE, offset = 0, length = 16>
<Mar 1, 2011 2:19:08 PM EST> <Debug> <SecuritySSL> <BEA-000000> <isMuxerActivated: false>
<Mar 1, 2011 2:19:08 PM EST> <Debug> <SecuritySSL> <BEA-000000> <23512240 SSL3/TLS MAC>
<Mar 1, 2011 2:19:08 PM EST> <Debug> <SecuritySSL> <BEA-000000> <23512240 received CHANGE_CIPHER_SPEC>
<Mar 1, 2011 2:19:08 PM EST> <Debug> <SecuritySSL> <BEA-000000> <Will use default Cipher for algorithm RC4>
<Mar 1, 2011 2:19:08 PM EST> <Debug> <SecuritySSL> <BEA-000000> <Will use default Mac for algorithm HMACMD5>
<Mar 1, 2011 2:19:08 PM EST> <Debug> <SecuritySSL> <BEA-000000> <isMuxerActivated: false>
<Mar 1, 2011 2:19:08 PM EST> <Debug> <SecuritySSL> <BEA-000000> <23512240 SSL3/TLS MAC>
<Mar 1, 2011 2:19:08 PM EST> <Debug> <SecuritySSL> <BEA-000000> <23512240 received HANDSHAKE>
<Mar 1, 2011 2:19:08 PM EST> <Debug> <SecuritySSL> <BEA-000000> <HANDSHAKEMESSAGE: Finished>
<Mar 1, 2011 2:19:08 PM EST> <Debug> <SecuritySSL> <BEA-000000> <Will use default Mac for algorithm HmacMD5>
<Mar 1, 2011 2:19:08 PM EST> <Debug> <SecuritySSL> <BEA-000000> <Will use default Mac for algorithm HmacSHA1>
<Mar 1, 2011 2:19:08 PM EST> <Debug> <SecuritySSL> <BEA-000000> <write APPLICATION_DATA, offset = 0, length = 372>
<Mar 1, 2011 2:19:08 PM EST> <Debug> <SecuritySSL> <BEA-000000> <write APPLICATION_DATA, offset = 0, length = 2770>
<Mar 1, 2011 2:19:08 PM EST> <Debug> <SecuritySSL> <BEA-000000> <4836513 read(offset=0, length=8192)>
<Mar 1, 2011 2:19:08 PM EST> <Debug> <SecuritySSL> <BEA-000000> <isMuxerActivated: false>
<Mar 1, 2011 2:19:09 PM EST> <Debug> <SecuritySSL> <BEA-000000> <23512240 SSL3/TLS MAC>
<Mar 1, 2011 2:19:09 PM EST> <Debug> <SecuritySSL> <BEA-000000> <23512240 received APPLICATION_DATA: databufferLen 0, contentLength 2920>
<Mar 1, 2011 2:19:09 PM EST> <Debug> <SecuritySSL> <BEA-000000> <4836513 read databufferLen 2920>
<Mar 1, 2011 2:19:09 PM EST> <Debug> <SecuritySSL> <BEA-000000> <4836513 read A returns 2920>
<Mar 1, 2011 2:19:09 PM EST> <Debug> <SecuritySSL> <BEA-000000> <avalable(): 4836513 : 0 + 948 = 948>
<Mar 1, 2011 2:19:09 PM EST> <Debug> <SecuritySSL> <BEA-000000> <4836513 read(offset=2920, length=5272)>
<Mar 1, 2011 2:19:09 PM EST> <Debug> <SecuritySSL> <BEA-000000> <isMuxerActivated: false>
<Mar 1, 2011 2:19:09 PM EST> <Debug> <SecuritySSL> <BEA-000000> <23512240 SSL3/TLS MAC>
<Mar 1, 2011 2:19:09 PM EST> <Debug> <SecuritySSL> <BEA-000000> <23512240 received APPLICATION_DATA: databufferLen 0, contentLength 904>
<Mar 1, 2011 2:19:09 PM EST> <Debug> <SecuritySSL> <BEA-000000> <4836513 read databufferLen 904>
<Mar 1, 2011 2:19:09 PM EST> <Debug> <SecuritySSL> <BEA-000000> <4836513 read A returns 904>
<Mar 1, 2011 2:19:09 PM EST> <Debug> <SecuritySSL> <BEA-000000> <avalable(): 4836513 : 0 + 23 = 23>
<Mar 1, 2011 2:19:09 PM EST> <Debug> <SecuritySSL> <BEA-000000> <4836513 read(offset=3824, length=4368)>
<Mar 1, 2011 2:19:09 PM EST> <Debug> <SecuritySSL> <BEA-000000> <isMuxerActivated: false>
<Mar 1, 2011 2:19:09 PM EST> <Debug> <SecuritySSL> <BEA-000000> <23512240 SSL3/TLS MAC>
<Mar 1, 2011 2:19:09 PM EST> <Debug> <SecuritySSL> <BEA-000000> <23512240 received ALERT>
<Mar 1, 2011 2:19:09 PM EST> <Debug> <SecuritySSL> <BEA-000000> <NEW ALERT with Severity: WARNING, Type: 0
java.lang.Exception: New alert stack
        at com.certicom.tls.record.alert.Alert.<init>(Unknown Source)
        at com.certicom.tls.record.alert.AlertHandler.handleAlertMessages(Unknown Source)
        at com.certicom.tls.record.MessageInterpreter.interpretContent(Unknown Source)
        at com.certicom.tls.record.MessageInterpreter.decryptMessage(Unknown Source)
        at com.certicom.tls.record.ReadHandler.processRecord(Unknown Source)
        at com.certicom.tls.record.ReadHandler.readRecord(Unknown Source)
        at com.certicom.tls.record.ReadHandler.read(Unknown Source)
        at com.certicom.io.InputSSLIOStreamWrapper.read(Unknown Source)
        at java.io.BufferedInputStream.fill(BufferedInputStream.java:218)
        at java.io.BufferedInputStream.read1(BufferedInputStream.java:258)
        at java.io.BufferedInputStream.read(BufferedInputStream.java:317)
        at weblogic.net.http.KeepAliveStream.read(KeepAliveStream.java:86)
        at java.io.FilterInputStream.read(FilterInputStream.java:116)
        at com.ctc.wstx.io.StreamBootstrapper.ensureLoaded(StreamBootstrapper.java:443)
        at com.ctc.wstx.io.StreamBootstrapper.resolveStreamEncoding(StreamBootstrapper.java:267)
        at com.ctc.wstx.io.StreamBootstrapper.bootstrapInput(StreamBootstrapper.java:131)
        at com.ctc.wstx.stax.WstxInputFactory.doCreateSR(WstxInputFactory.java:543)
        at com.ctc.wstx.stax.WstxInputFactory.createSR(WstxInputFactory.java:604)
        at com.ctc.wstx.stax.WstxInputFactory.createSR(WstxInputFactory.java:619)
        at com.ctc.wstx.stax.WstxInputFactory.createXMLStreamReader(WstxInputFactory.java:348)
        at com.sun.xml.ws.api.streaming.XMLStreamReaderFactory$NoLock.doCreate(XMLStreamReaderFactory.java:377)
        at com.sun.xml.ws.api.streaming.XMLStreamReaderFactory$Woodstox.doCreate(XMLStreamReaderFactory.java:407)
        at com.sun.xml.ws.api.streaming.XMLStreamReaderFactory.create(XMLStreamReaderFactory.java:144)
        at com.sun.xml.ws.api.streaming.XMLStreamReaderFactory.create(XMLStreamReaderFactory.java:148)
        at com.sun.xml.ws.encoding.StreamSOAPCodec.decode(StreamSOAPCodec.java:294)
        at com.sun.xml.ws.encoding.StreamSOAPCodec.decode(StreamSOAPCodec.java:128)
        at com.sun.xml.ws.encoding.SOAPBindingCodec.decode(SOAPBindingCodec.java:287)
        at com.sun.xml.ws.transport.http.client.HttpTransportPipe.process(HttpTransportPipe.java:171)
        at com.sun.xml.ws.transport.http.client.HttpTransportPipe.processRequest(HttpTransportPipe.java:86)
        at com.sun.xml.ws.api.pipe.Fiber.__doRun(Fiber.java:598)
        at com.sun.xml.ws.api.pipe.Fiber._doRun(Fiber.java:557)
        at com.sun.xml.ws.api.pipe.Fiber.doRun(Fiber.java:542)
        at com.sun.xml.ws.api.pipe.Fiber.runSync(Fiber.java:439)
        at com.sun.xml.ws.client.Stub.process(Stub.java:248)
        at com.sun.xml.ws.client.sei.SEIStub.doProcess(SEIStub.java:135)
        at com.sun.xml.ws.client.sei.SyncMethodHandler.invoke(SyncMethodHandler.java:109)
        at com.sun.xml.ws.client.sei.SyncMethodHandler.invoke(SyncMethodHandler.java:89)
        at com.sun.xml.ws.client.sei.SEIStub.invoke(SEIStub.java:118)
        at $Proxy93.inquireUnifiedCustomerLoginProfile(Unknown Source)
        at com.csi.CsiWSClient.getSubscbrAcctPrfle(CsiWSClient.java:137)
        at com.itv.WSMainProcessor.getSubscbrAcctPrfle(WSMainProcessor.java:314)
        at com.itv.DMPAdService_DMPAdSoapHttpPortImpl.getSubscbrAcctPrfle(DMPAdService_DMPAdSoapHttpPortImpl.java:87)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
        at java.lang.reflect.Method.invoke(Method.java:597)
        at weblogic.wsee.jaxws.WLSInstanceResolver$WLSInvoker.invoke(WLSInstanceResolver.java:89)
        at weblogic.wsee.jaxws.WLSInstanceResolver$WLSInvoker.invoke(WLSInstanceResolver.java:71)
        at com.sun.xml.ws.server.InvokerTube$2.invoke(InvokerTube.java:146)
        at com.sun.xml.ws.server.sei.EndpointMethodHandler.invoke(EndpointMethodHandler.java:257)
        at com.sun.xml.ws.server.sei.SEIInvokerTube.processRequest(SEIInvokerTube.java:93)
        at weblogic.wsee.jaxws.tubeline.FlowControlTube$FlowControlAwareTube.processRequest(FlowControlTube.java:123)
        at weblogic.wsee.jaxws.tubeline.FlowControlTube.processRequest(FlowControlTube.java:75)
        at com.sun.xml.ws.api.pipe.Fiber.__doRun(Fiber.java:598)
        at com.sun.xml.ws.api.pipe.Fiber._doRun(Fiber.java:557)
        at com.sun.xml.ws.api.pipe.Fiber.doRun(Fiber.java:542)
        at com.sun.xml.ws.api.pipe.Fiber.runSync(Fiber.java:439)
        at com.sun.xml.ws.server.WSEndpointImpl$2.process(WSEndpointImpl.java:243)
        at com.sun.xml.ws.transport.http.HttpAdapter$HttpToolkit.handle(HttpAdapter.java:444)
        at com.sun.xml.ws.transport.http.HttpAdapter.handle(HttpAdapter.java:244)
        at com.sun.xml.ws.transport.http.servlet.ServletAdapter.handle(ServletAdapter.java:134)
        at weblogic.wsee.jaxws.HttpServletAdapter$AuthorizedInvoke.run(HttpServletAdapter.java:272)
        at weblogic.wsee.jaxws.HttpServletAdapter.post(HttpServletAdapter.java:185)
        at weblogic.wsee.jaxws.VerboseHttpProcessor.post(VerboseHttpProcessor.java:43)
        at weblogic.wsee.jaxws.JAXWSServlet.doPost(JAXWSServlet.java:180)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:727)
        at weblogic.wsee.jaxws.JAXWSServlet.service(JAXWSServlet.java:64)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:820)
        at weblogic.servlet.internal.StubSecurityHelper$ServletServiceAction.run(StubSecurityHelper.java:227)
        at weblogic.servlet.internal.StubSecurityHelper.invokeServlet(StubSecurityHelper.java:125)
        at weblogic.servlet.internal.ServletStubImpl.execute(ServletStubImpl.java:292)
        at weblogic.servlet.internal.ServletStubImpl.execute(ServletStubImpl.java:175)
        at weblogic.servlet.internal.WebAppServletContext$ServletInvocationAction.run(WebAppServletContext.java:3498)
        at weblogic.security.acl.internal.AuthenticatedSubject.doAs(AuthenticatedSubject.java:321)
        at weblogic.security.service.SecurityManager.runAs(Unknown Source)
        at weblogic.servlet.internal.WebAppServletContext.securedExecute(WebAppServletContext.java:2180)
        at weblogic.servlet.internal.WebAppServletContext.execute(WebAppServletContext.java:2086)
        at weblogic.servlet.internal.ServletRequestImpl.run(ServletRequestImpl.java:1406)
        at weblogic.work.ExecuteThread.execute(ExecuteThread.java:201)
        at weblogic.work.ExecuteThread.run(ExecuteThread.java:173)
>
<Mar 1, 2011 2:19:09 PM EST> <Debug> <SecuritySSL> <BEA-000000> <Alert received from peer, notifying peer we received it: com.certicom.tls.record.alert.Alert@44e906>
<Mar 1, 2011 2:19:09 PM EST> <Debug> <SecuritySSL> <BEA-000000> <CLOSE_NOTIFY received from peer, closing connection: >
<Mar 1, 2011 2:19:09 PM EST> <Debug> <SecuritySSL> <BEA-000000> <close(): 4836513>
<Mar 1, 2011 2:19:09 PM EST> <Debug> <SecuritySSL> <BEA-000000> <NEW ALERT with Severity: WARNING, Type: 0
java.lang.Exception: New alert stack
        at com.certicom.tls.record.alert.Alert.<init>(Unknown Source)
        at com.certicom.tls.interfaceimpl.TLSConnectionImpl.closeWriteHandler(Unknown Source)
        at com.certicom.tls.interfaceimpl.TLSConnectionImpl.close(Unknown Source)
        at javax.net.ssl.impl.SSLLayeredSocket.close(Unknown Source)
        at com.certicom.tls.record.alert.AlertHandler.handle(Unknown Source)
        at com.certicom.tls.record.alert.AlertHandler.handleAlertMessages(Unknown Source)
        at com.certicom.tls.record.MessageInterpreter.interpretContent(Unknown Source)
        at com.certicom.tls.record.MessageInterpreter.decryptMessage(Unknown Source)
        at com.certicom.tls.record.ReadHandler.processRecord(Unknown Source)
        at com.certicom.tls.record.ReadHandler.readRecord(Unknown Source)
        at com.certicom.tls.record.ReadHandler.read(Unknown Source)
        at com.certicom.io.InputSSLIOStreamWrapper.read(Unknown Source)
        at java.io.BufferedInputStream.fill(BufferedInputStream.java:218)
        at java.io.BufferedInputStream.read1(BufferedInputStream.java:258)
        at java.io.BufferedInputStream.read(BufferedInputStream.java:317)
        at weblogic.net.http.KeepAliveStream.read(KeepAliveStream.java:86)
        at java.io.FilterInputStream.read(FilterInputStream.java:116)
        at com.ctc.wstx.io.StreamBootstrapper.ensureLoaded(StreamBootstrapper.java:443)
        at com.ctc.wstx.io.StreamBootstrapper.resolveStreamEncoding(StreamBootstrapper.java:267)
        at com.ctc.wstx.io.StreamBootstrapper.bootstrapInput(StreamBootstrapper.java:131)
        at com.ctc.wstx.stax.WstxInputFactory.doCreateSR(WstxInputFactory.java:543)
        at com.ctc.wstx.stax.WstxInputFactory.createSR(WstxInputFactory.java:604)
        at com.ctc.wstx.stax.WstxInputFactory.createSR(WstxInputFactory.java:619)
        at com.ctc.wstx.stax.WstxInputFactory.createXMLStreamReader(WstxInputFactory.java:348)
        at com.sun.xml.ws.api.streaming.XMLStreamReaderFactory$NoLock.doCreate(XMLStreamReaderFactory.java:377)
        at com.sun.xml.ws.api.streaming.XMLStreamReaderFactory$Woodstox.doCreate(XMLStreamReaderFactory.java:407)
        at com.sun.xml.ws.api.streaming.XMLStreamReaderFactory.create(XMLStreamReaderFactory.java:144)
        at com.sun.xml.ws.api.streaming.XMLStreamReaderFactory.create(XMLStreamReaderFactory.java:148)
        at com.sun.xml.ws.encoding.StreamSOAPCodec.decode(StreamSOAPCodec.java:294)
        at com.sun.xml.ws.encoding.StreamSOAPCodec.decode(StreamSOAPCodec.java:128)
        at com.sun.xml.ws.encoding.SOAPBindingCodec.decode(SOAPBindingCodec.java:287)
        at com.sun.xml.ws.transport.http.client.HttpTransportPipe.process(HttpTransportPipe.java:171)
        at com.sun.xml.ws.transport.http.client.HttpTransportPipe.processRequest(HttpTransportPipe.java:86)
        at com.sun.xml.ws.api.pipe.Fiber.__doRun(Fiber.java:598)
        at com.sun.xml.ws.api.pipe.Fiber._doRun(Fiber.java:557)
        at com.sun.xml.ws.api.pipe.Fiber.doRun(Fiber.java:542)
        at com.sun.xml.ws.api.pipe.Fiber.runSync(Fiber.java:439)
        at com.sun.xml.ws.client.Stub.process(Stub.java:248)
        at com.sun.xml.ws.client.sei.SEIStub.doProcess(SEIStub.java:135)
        at com.sun.xml.ws.client.sei.SyncMethodHandler.invoke(SyncMethodHandler.java:109)
        at com.sun.xml.ws.client.sei.SyncMethodHandler.invoke(SyncMethodHandler.java:89)
        at com.sun.xml.ws.client.sei.SEIStub.invoke(SEIStub.java:118)
        at $Proxy93.inquireUnifiedCustomerLoginProfile(Unknown Source)
        at com.csi.CsiWSClient.getSubscbrAcctPrfle(CsiWSClient.java:137)
        at com.itv.WSMainProcessor.getSubscbrAcctPrfle(WSMainProcessor.java:314)
        at com.itv.DMPAdService_DMPAdSoapHttpPortImpl.getSubscbrAcctPrfle(DMPAdService_DMPAdSoapHttpPortImpl.java:87)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
        at java.lang.reflect.Method.invoke(Method.java:597)
        at weblogic.wsee.jaxws.WLSInstanceResolver$WLSInvoker.invoke(WLSInstanceResolver.java:89)
        at weblogic.wsee.jaxws.WLSInstanceResolver$WLSInvoker.invoke(WLSInstanceResolver.java:71)
        at com.sun.xml.ws.server.InvokerTube$2.invoke(InvokerTube.java:146)
        at com.sun.xml.ws.server.sei.EndpointMethodHandler.invoke(EndpointMethodHandler.java:257)
        at com.sun.xml.ws.server.sei.SEIInvokerTube.processRequest(SEIInvokerTube.java:93)
        at weblogic.wsee.jaxws.tubeline.FlowControlTube$FlowControlAwareTube.processRequest(FlowControlTube.java:123)
        at weblogic.wsee.jaxws.tubeline.FlowControlTube.processRequest(FlowControlTube.java:75)
        at com.sun.xml.ws.api.pipe.Fiber.__doRun(Fiber.java:598)
        at com.sun.xml.ws.api.pipe.Fiber._doRun(Fiber.java:557)
        at com.sun.xml.ws.api.pipe.Fiber.doRun(Fiber.java:542)

Answer 1

Thanks EJP for putting me on the right track. This issue had nothing to do with SSL. It was actually a DNS issue. The authoritative name server for the domain wasn't IPv6 compliant. I was able to solve the issue by adding the following start-up parameter to WebLogic to force IPv4 name resolution: -Djava.net.preferIPv4Stack=true

Answer 2

SSL doesn't impose overheads on that scale. I suggest that what you are seeing is the time between the accept() returning for the first time, which will trigger all the cert loading stuff, and the first data being sent by the client, which will trigger the SSL handshake. Or else you are running on truly antique hardware, network, etc.

Answer 3

I've been looking over some similar stacktraces on the Oracle forums http://forums.oracle.com/forums/thread.jspa?messageID=4580980 and http://kr.forums.oracle.com/forums/thread.jspa?threadID=1068642

There are a lot of lines happening between your stacktrace lines 1 & 2.

One example below:

<May 10, 2010 2:36:05 PM CEST> <Debug> <SecuritySSL> <BEA-000000> <SSLSetup: loading trusted CA certificates> 

<May 10, 2010 2:36:05 PM CEST> <Debug> <SecuritySSL> <BEA-000000> <SSL enableUnencryptedNullCipher= false> 
<May 10, 2010 2:36:05 PM CEST> <Debug> <SecuritySSL> <BEA-000000> <SSLContextManager: loading server SSL identity> 

<May 10, 2010 2:36:05 PM CEST> <Notice> <Security> <BEA-090171> <Loading the identity certificate and private key stored under the alias mavir from the JKS keystore file /opt/oracle/osb_home/user_projects/domains/osb_domain/security/mavir.jks.> 

<May 10, 2010 2:36:05 PM CEST> <Debug> <SecuritySSL> <BEA-000000> <Loaded public identity certificate chain:> 

<May 10, 2010 2:36:05 PM CEST> <Debug> <SecuritySSL> <BEA-000000> <Subject: CN=kapalk1.mavir.hu, OU=FIO, O=MAVIR ZRt., L=Budapest, ST=Budapest, C=HU; Issuer: CN=NetLock Uzleti (Class B) Tanusitvanykiado, OU=Tanusitvanykiadok, O=NetLock Halozatbiztonsagi Kft., L=Budapest, C=HU> 

<May 10, 2010 2:36:05 PM CEST> <Debug> <SecuritySSL> <BEA-000000> <Subject: CN=NetLock Uzleti (Class B) Tanusitvanykiado, OU=Tanusitvanykiadok, O=NetLock Halozatbiztonsagi Kft., L=Budapest, C=HU; Issuer: CN=NetLock Uzleti (Class B) Tanusitvanykiado, OU=Tanusitvanykiadok, O=NetLock Halozatbiztonsagi Kft., L=Budapest, C=HU> 

<May 10, 2010 2:36:05 PM CEST> <Debug> <SecuritySSL> <BEA-000000> <Using JCE Cipher: SunJCE version 1.6 for algorithm RSA/ECB/NoPadding> 

<May 10, 2010 2:36:29 PM CEST> <Info> <Health> <BEA-310002> <32% of the total memory in the server is free> <May 10, 2010 2:36:41 PM CEST> <Notice> <Security> <BEA-090169> <Loading trusted certificates from the JKS keystore file /opt/oracle/osb_home/user_projects/domains/osb_domain/security/mavir.jks.> 

<May 10, 2010 2:36:41 PM CEST> <Debug> <SecuritySSL> <BEA-000000> <SSLContextManager: loaded 2 trusted CAs from /opt/oracle/osb_home/user_projects/domains/osb_domain/security/mavir.jks> 

<May 10, 2010 2:36:41 PM CEST> <Debug> <SecuritySSL> <BEA-000000> <Subject: SERIALNUMBER=ICA - 595029, OU=Damas Energy, O="Slovenska elektrizacna prenosova sustava, a.s.", L=Bratislava, ST=Slovakia, CN=damas.sepsas.sk, C=SK; Issuer: O=Prvni certifikacni autorita a.s., CN=I.CA - Standard root certificate, C=CZ> 

<May 10, 2010 2:36:41 PM CEST> <Debug> <SecuritySSL> <BEA-000000> <Subject: CN=NetLock Uzleti (Class B) Tanusitvanykiado, OU=Tanusitvanykiadok, O=NetLock Halozatbiztonsagi Kft., L=Budapest, C=HU; Issuer: CN=NetLock Uzleti (Class B) Tanusitvanykiado, OU=Tanusitvanykiadok, O=NetLock Halozatbiztonsagi Kft., L=Budapest, C=HU> 
<May 10, 2010 2:36:41 PM CEST> <Info> <WebLogicServer> <BEA-000307> <Exportable key maximum lifespan set to 500 uses.>



<May 10, 2010 2:36:41 PM CEST> <Debug> <SecuritySSL> <BEA-000000> <clientInfo has new style certificate and key> 
<May 10, 2010 2:36:43 PM CEST> <Debug> <SecuritySSL> <BEA-000000> <Filtering JSSE SSLSocket>

It seems that the CA certs are not getting loaded in your case, if you are indeed getting a valid response - is the server set up to only accept valid certs?

I'd suggest you try running your WLS with -Dssl.debug=true and you should get verbose messages showing what's happening.

See this similar thread on SF

Answer 4

I'm not sure if this will resolve your issue but most security related phases require random numbers to be generated by your server. If there isn't enough randomness or "entropy", the system will wait until it can provide a number that is random enough.

Try adding -Djava.security.egd=file:/dev/./urandom to your startup arguments to see if this resolves the issue. You can think of urandom as a system generated set of random numbers that aren't as unique as /dev/random and is not ideal for use in a production environment.