Tuxedo SALT Having Communication Hang Problems On XA-transactions Between SALT And Weblogic (Doc ID 2079116.1)

Last updated on NOVEMBER 27, 2016

Applies to:

Oracle Service Architecture Leveraging Tuxedo (SALT) - Version 12.1.3 and later
Information in this document applies to any platform.

Symptoms

Having problems with Oracle SALT XA-transactions. In the Weblogic application first call a JPA service and then after that a Tuxedo service, both in the same transaction.
The JPA-call works fine, but when calling Tuxedo through SALT the process never finishes. From the ULOG it seems that the information about the transaction is passed to SALT,
but after that nothing happens. The SALT call hangs and finally Weblogic kills the thread after 600 seconds.
Originally using WLS 12.1.3 with Tuxedo with SALT 12.1.1 when the problem was seen. Upgraded to Tuxedo and SALT 12.1.3 but still it hangs.

WebLogic side log:

=>myTxSvc service call is made with WSTX/WSAT
####<28.10.2015 20.16.40 EET> <Notice> <Stdout> <mybus> <mks_srv> <[ACTIVE] ExecuteThread: '0' for queue: 'weblogic.kernel.Default
(self-tuning)'> <<WLS Kernel>> <> <> <1446056200994> <BEA-000000> <---[HTTP request - http://mytuxmach:10020/URA]---
Accept: text/xml, multipart/related
Content-Type: text/xml; charset=utf-8
SOAPAction: "myTxSvc"
User-Agent: JAX-WS RI 2.2.10-b140319.1121
svn-revision#7b34660d6bc70e587e8ec81a17e4d76af68816a6

=>No response, then a transaction timeout exception occurs
####<28.10.2015 20.17.38 EET> <Info> <JTA> <mybus> <mks_srv> <[ACTIVE] ExecuteThread: '4' for queue: 'weblogic.kernel.Default (self-tuning)'> <<WLS Kernel>> <> <> <1446056258425> <BEA-111015> <The commit operation for transaction BEA1-006963BB4797901E5049 timed out after 61 seconds.>
####<28.10.2015 20.17.38 EET> <Debug> <JTA2PC> <mybus> <mks_srv>
<[ACTIVE] ExecuteThread: '4' for queue: 'weblogic.kernel.Default (self-tuning)'> <<WLS Kernel>> <> <> <1446056258425>
<BEA-000000> <Name=[EJB myapp.mysvc.MyService.Mks(myapp.mksts.model.Mks,java.lang.String,java.lang.String)],
Xid=BEA1-006963BB4797901E5049(492595422),Status=Marked rollback.
[Reason=weblogic.transaction.internal.TimedOutException: Transaction timed out after 61 seconds

=>Finally a STUCK thread is detected on this myTxSvc proxy service call
####<28.10.2015 20.27.21 EET> <Error> <WebLogicServer> <mybus> <mks_srv> <[ACTIVE] ExecuteThread: '4' for queue: 'weblogic.kernel.Default
(self-tuning)'> <<WLS Kernel>> <> <> <1446056841789> <BEA-000337> <[STUCK] ExecuteThread: '0' for queue: 'weblogic.kernel.Default
(self-tuning)' has been busy for "644" seconds working on the request "Workmanager:
default, Version: 0, Scheduled=true, Started=true, Started time: 644855 ms
", which is more than the configured time (StuckThreadMaxTime) of "600"
seconds in "server-failure-trigger". Stack trace:
       sun.nio.ch.DevPollArrayWrapper.poll0(Native Method)
       sun.nio.ch.DevPollArrayWrapper.poll(DevPollArrayWrapper.java:223)
       sun.nio.ch.DevPollSelectorImpl.doSelect(DevPollSelectorImpl.java:84)
       sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:86)
       sun.nio.ch.SelectorImpl.select(SelectorImpl.java:97)
       weblogic.socket.NIOSocketMuxer$NIOInputStream.readInternal(NIOSocketMuxer.java:801)
       weblogic.socket.NIOSocketMuxer$NIOInputStream.read(NIOSocketMuxer.java:745)
       weblogic.socket.NIOSocketMuxer$NIOInputStream.read(NIOSocketMuxer.java:728)
       java.io.BufferedInputStream.fill(BufferedInputStream.java:246)
       java.io.BufferedInputStream.read1(BufferedInputStream.java:286)
       java.io.BufferedInputStream.read(BufferedInputStream.java:345)
       weblogic.net.http.MessageHeader.isHTTP(MessageHeader.java:310)
       weblogic.net.http.MessageHeader.parseHeader(MessageHeader.java:232)
       weblogic.net.http.HttpClient.parseHTTP(HttpClient.java:549)
       weblogic.net.http.HttpURLConnection.getInputStream(HttpURLConnection.java:639)
       weblogic.net.http.SOAPHttpURLConnection.getInputStream(SOAPHttpURLConnection.java:37)
       weblogic.net.http.HttpURLConnection.getResponseCode(HttpURLConnection.java:1444)
       com.sun.xml.ws.transport.http.client.HttpClientTransport.readResponseCodeAndMessage(HttpClientTransport.java:206)
       com.sun.xml.ws.transport.http.client.HttpTransportPipe.createResponsePacket(HttpTransportPipe.java:241)
       com.sun.xml.ws.transport.http.client.HttpTransportPipe.process(HttpTransportPipe.java:232)
       com.sun.xml.ws.transport.http.client.HttpTransportPipe.processRequest(HttpTransportPipe.java:145)
       com.sun.xml.ws.transport.DeferredTransportPipe.processRequest(DeferredTransportPipe.java:110)
       com.sun.xml.ws.api.pipe.Fiber.__doRun(Fiber.java:1136)
       com.sun.xml.ws.api.pipe.Fiber._doRun(Fiber.java:1050)
       com.sun.xml.ws.api.pipe.Fiber.doRun(Fiber.java:1019)
       com.sun.xml.ws.api.pipe.Fiber.runSync(Fiber.java:877)
       com.sun.xml.ws.client.Stub.process(Stub.java:463)
       com.sun.xml.ws.client.sei.SEIStub.doProcess(SEIStub.java:191)
       com.sun.xml.ws.client.sei.SyncMethodHandler.invoke(SyncMethodHandler.java:108)
       com.sun.xml.ws.client.sei.SyncMethodHandler.invoke(SyncMethodHandler.java:92)
       com.sun.xml.ws.client.sei.SEIStub.invoke(SEIStub.java:161)
       com.sun.proxy.$Proxy194.myTxSvc(Unknown Source)

  

Tuxedo side ULOG:

=>the requst for transactional myTxSvc service arrives using WS-TX/WS-AT
201640.mytuxmach!GWWS.60638.6.0: TRACE:ws:HTTP Parsing: Buffer length 4096 -- POST /URA HTTP/1.1
Accept: text/xml, multipart/related
Content-Type: text/xml; charset=utf-8
SOAPAction: "myTxSvc"
User-Agent: JAX-WS RI 2.2.10-b140319.1121
svn-revision#7b34660d6bc70e587e8ec81a17e4d76af68816a6
Host: mytuxmach:10020
Connection: Keep-Alive
Content-Length: 5345

<?xml version='1.0' encoding='UTF-8'?>
<S:Envelope xmlns:S="http://schemas.xmlsoap.org/soap/envelope/">
<S:Header>
<CoordinationContext xmlns="http://docs.oasis-
201640.mytuxmach!GWWS.60638.6.0: TRACE:ws:
open.org/ws-tx/wscoor/2006/06"
xmlns:ns2="http://www.w3.org/2005/08/addressing"
xmlns:ns3="http://schemas.xmlsoap.org/soap/envelope/" ns3:mustUnderstand="1"><Identifier>urn:uuid:BEA1-006963BB4797901E5049</Identifier>
<Expires>57000</Expires>
<CoordinationType>http://docs.oasis-open.org/ws-tx/wsat/2006/06</CoordinationType>
<RegistrationService>
<ns2:Address>http://mybus:7513/wls-wsat/RegistrationPortTypeRPC11</ns2:Address>
<ns2:ReferenceParameters>
<wls-wsat:txId xmlns:wls-wsat="http://webl
201640.mytuxmach!GWWS.60638.6.0: TRACE:ws:
ogic.wsee.wstx.wsat/ws/2008/10/wsat"
xmlns:wsa="http://www.w3.org/2005/08/addressing">BEA1-006963BB4797901E5049</wls-wsat:txId>
<wls-wsat:routing xmlns:wls-wsat="http://weblogic.wsee.wstx.wsat/ws/2008/10/wsat"
xmlns:wsa="http://www.w3.org/2005/08/addressing">mks_srv</wls-wsat:routing>
</ns2:ReferenceParameters>
</RegistrationService>
</CoordinationContext>
</S:Header>
<S:Body>
<myTxSvc xmlns="urn:pack.URA_typedef.salt11">
<inbuf>
...
...
=>the request takes another receive to complete the inbuf
201640.mytuxmach!GWWS.60638.6.0: TRACE:ws:GWWS_CAT:1605: TRACE: Exiting <FSM.c>
201640.mytuxmach!GWWS.60638.6.0: TRACE:ws:GWWS_CAT:1604: TRACE: Entering <FSM.c>
201640.mytuxmach!GWWS.60638.6.0: TRACE:ws:parse_header_field() return 7
.....

.....
201640.mytuxmach!GWWS.60638.6.0: TRACE:ws:GWWS_CAT:1605: TRACE: Exiting <FSM.c>
201640.mytuxmach!GWWS.60638.6.0: TRACE:ws:GWWS_CAT:1605: TRACE: Exiting <FSM.c>
201640.mytuxmach!GWWS.60638.6.0: TRACE:ws:GWWS_CAT:1604: TRACE: Entering <FSM.c>
201640.mytuxmach!GWWS.60638.6.0: TRACE:ws:GWWS_CAT:1604: TRACE: Entering <FSM.c>
201640.mytuxmach!GWWS.60638.6.0: TRACE:ws:SCO[4094] FSM State Transition: --Found-->ParseHTTP
201640.mytuxmach!GWWS.60638.6.0: TRACE:ws:GWWS_CAT:1605: TRACE: Exiting <FSM.c>
201640.mytuxmach!GWWS.60638.6.0: TRACE:ws:GWWS_CAT:1604: TRACE: Entering <FSM.c>
201640.mytuxmach!GWWS.60638.6.0: TRACE:ws:HTTP Parsing: Buffer length 1555
--
....
....
</inbuf>
</myTxSvc>
</S:Body>
</S:Envelope>
201640.mytuxmach!GWWS.60638.6.0: TRACE:ws:GWWS_CAT:1605: TRACE: Exiting <FSM.c>
201640.mytuxmach!GWWS.60638.6.0: TRACE:ws:add_body_string 1555

=>then the request is parsed but nothing further happens (transaction activity is not seen on the server processes which provide the service)
201640.mytuxmach!GWWS.60638.6.0: TRACE:ws:GWWS_CAT:1605: TRACE: Exiting <FSM.c>
201640.mytuxmach!GWWS.60638.6.0: TRACE:ws:GWWS_CAT:1604: TRACE: Entering <FSM.c>
201640.mytuxmach!GWWS.60638.6.0: TRACE:ws:GWWS_CAT:1604: TRACE: Entering <FSM.c>
201640.mytuxmach!GWWS.60638.6.0: TRACE:ws:SCO[4094] FSM State Transition: --OK-->HTTPDispatch
201640.mytuxmach!GWWS.60638.6.0: TRACE:ws:GWWS_CAT:1605: TRACE: Exiting <FSM.c>
201640.mytuxmach!GWWS.60638.6.0: TRACE:ws:GWWS_CAT:1604: TRACE: Entering <FSM.c>
201640.mytuxmach!GWWS.60638.6.0: TRACE:ws:GWWS_CAT:1628: TRACE: A HTTP message is received, SCO index=4094
201640.mytuxmach!GWWS.60638.6.0: TRACE:ws:GWWS_CAT:1604: TRACE: Entering <FSM.c>
201640.mytuxmach!GWWS.60638.6.0: TRACE:ws:Finding endpoint, soap->path is /URA, request_uri is /URA
201640.mytuxmach!GWWS.60638.6.0: TRACE:ws:GWWS_CAT:1605: TRACE: Exiting <FSM.c>
201640.mytuxmach!GWWS.60638.6.0: TRACE:ws:GWWS_CAT:1605: TRACE: Exiting <FSM.c>
201640.mytuxmach!GWWS.60638.6.0: TRACE:ws:GWWS_CAT:1604: TRACE: Entering <FSM.c>
201640.mytuxmach!GWWS.60638.6.0: TRACE:ws:GWWS_CAT:1604: TRACE: Entering <FSM.c>
201640.mytuxmach!GWWS.60638.6.0: TRACE:ws:SCO[4094] FSM State Transition: --Post-->ParseSOAPHeader
201640.mytuxmach!GWWS.60638.6.0: TRACE:ws:GWWS_CAT:1605: TRACE: Exiting <FSM.c>
201640.mytuxmach!GWWS.60638.6.0: TRACE:ws:GWWS_CAT:1604: TRACE: Entering <FSM.c>
201640.mytuxmach!GWWS.60638.6.0: TRACE:ws:GWWS_CAT:1604: TRACE: Entering <FSM.c>
201640.mytuxmach!GWWS.60638.6.0: TRACE:ws:GWWS_CAT:1604: TRACE: Entering <FSM.c>
201640.mytuxmach!GWWS.60638.6.0: TRACE:ws:GWWS_CAT:1604: TRACE: Entering <FSM.c>
201640.mytuxmach!GWWS.60638.6.0: TRACE:ws:GWWS_CAT:1604: TRACE: Entering <FSM.c>
201640.mytuxmach!GWWS.60638.6.0: TRACE:ws:SCO[4094] FSM State Transition: --Default-->ParseHeaderRoot
201640.mytuxmach!GWWS.60638.6.0: TRACE:ws:GWWS_CAT:1605: TRACE: Exiting <FSM.c>
201640.mytuxmach!GWWS.60638.6.0: TRACE:ws:GWWS_CAT:1604: TRACE: Entering <FSM.c>
201640.mytuxmach!GWWS.60638.6.0: TRACE:ws:GWWS_CAT:1612: TRACE: A SOAP message is received, SCO index=4094
201640.mytuxmach!GWWS.60638.6.0: TRACE:ws:GWWS_CAT:1605: TRACE: Exiting <FSM.c>
201640.mytuxmach!GWWS.60638.6.0: TRACE:ws:GWWS_CAT:1605: TRACE: Exiting <FSM.c>
201640.mytuxmach!GWWS.60638.6.0: TRACE:ws:GWWS_CAT:1604: TRACE: Entering <FSM.c>
201640.mytuxmach!GWWS.60638.6.0: TRACE:ws:GWWS_CAT:1604: TRACE: Entering <FSM.c>
201640.mytuxmach!GWWS.60638.6.0: TRACE:ws:SCO[4094] FSM State Transition: --OK-->ParseHeaderElement
201640.mytuxmach!GWWS.60638.6.0: TRACE:ws:GWWS_CAT:1605: TRACE: Exiting <FSM.c>
201640.mytuxmach!GWWS.60638.6.0: TRACE:ws:GWWS_CAT:1604: TRACE: Entering <FSM.c>

  

 

Cause

Sign In with your My Oracle Support account

Don't have a My Oracle Support account? Click to get started

My Oracle Support provides customers with access to over a
Million Knowledge Articles and hundreds of Community platforms