The OSB framework, intercepting an logging all requests

The base issue is that whenever we have a stuck thread, we don't have a means to tell which Proxy Service it was processing. This is a sample StackTrace:

"[STUCK] ExecuteThread: '27' for queue: 'weblogic.kernel.Default (self-tuning)'" RUNNABLE native
 java.net.SocketInputStream.socketRead0(Native Method)
 java.net.SocketInputStream.read(SocketInputStream.java:129)
 oracle.net.nt.MetricsEnabledInputStream.read(TcpNTAdapter.java:718)
 oracle.net.ns.Packet.receive(Packet.java:295)
 oracle.net.ns.DataPacket.receive(DataPacket.java:106)
 oracle.net.ns.NetInputStream.getNextPacket(NetInputStream.java:317)
 oracle.net.ns.NetInputStream.read(NetInputStream.java:262)
 oracle.net.ns.NetInputStream.read(NetInputStream.java:187)
 oracle.net.ns.NetInputStream.read(NetInputStream.java:104)
 oracle.jdbc.driver.T4CSocketInputStreamWrapper.readNextPacket(T4CSocketInputStreamWrapper.java:126)
 oracle.jdbc.driver.T4CSocketInputStreamWrapper.read(T4CSocketInputStreamWrapper.java:82)
 oracle.jdbc.driver.T4CMAREngine.unmarshalUB1(T4CMAREngine.java:1177)
 oracle.jdbc.driver.T4CMAREngine.unmarshalSB1(T4CMAREngine.java:1153)
 oracle.jdbc.driver.T4CTTIfun.receive(T4CTTIfun.java:312)
 oracle.jdbc.driver.T4CTTIfun.doRPC(T4CTTIfun.java:204)
 oracle.jdbc.driver.T4C8Oall.doOALL(T4C8Oall.java:540)
 oracle.jdbc.driver.T4CCallableStatement.doOall8(T4CCallableStatement.java:213)
 oracle.jdbc.driver.T4CCallableStatement.executeForRows(T4CCallableStatement.java:1075)
 oracle.jdbc.driver.OracleStatement.doExecuteWithTimeout(OracleStatement.java:1466)
 oracle.jdbc.driver.OraclePreparedStatement.executeInternal(OraclePreparedStatement.java:3752)
 oracle.jdbc.driver.OraclePreparedStatement.execute(OraclePreparedStatement.java:3937)
 oracle.jdbc.driver.OracleCallableStatement.execute(OracleCallableStatement.java:9259)
 oracle.jdbc.driver.OraclePreparedStatementWrapper.execute(OraclePreparedStatementWrapper.java:1535)
 weblogic.jdbc.wrapper.PreparedStatement.execute(PreparedStatement.java:99)
 oracle.tip.adapter.db.sp.AbstractStoredProcedure.execute(AbstractStoredProcedure.java:123)
 oracle.tip.adapter.db.sp.SPInteraction.executeStoredProcedure(SPInteraction.java:141)
 oracle.tip.adapter.db.DBInteraction.executeStoredProcedure(DBInteraction.java:1102)
 oracle.tip.adapter.db.DBInteraction.execute(DBInteraction.java:247)
 oracle.tip.adapter.sa.impl.fw.wsif.jca.WSIFOperation_JCA.performOperation(WSIFOperation_JCA.java:529)
 oracle.tip.adapter.sa.impl.fw.wsif.jca.WSIFOperation_JCA.executeOperation(WSIFOperation_JCA.java:353)
 oracle.tip.adapter.sa.impl.fw.wsif.jca.WSIFOperation_JCA.executeRequestResponseOperation(WSIFOperation_JCA.java:312)
 oracle.tip.adapter.sa.impl.JCABindingReferenceImpl.invokeWsifProvider(JCABindingReferenceImpl.java:350)
 oracle.tip.adapter.sa.impl.JCABindingReferenceImpl.request(JCABindingReferenceImpl.java:253)
 com.bea.wli.sb.transports.jca.binding.JCATransportOutboundOperationBindingServiceImpl.invoke(JCATransportOutboundOperationBindingServiceImpl.java:150)
 com.bea.wli.sb.transports.jca.JCATransportEndpoint.sendRequestResponse(JCATransportEndpoint.java:209)
 com.bea.wli.sb.transports.jca.JCATransportEndpoint.send(JCATransportEndpoint.java:170)
 com.bea.wli.sb.transports.jca.JCATransportProvider.sendMessageAsync(JCATransportProvider.java:598)
 sun.reflect.GeneratedMethodAccessor645.invoke(Unknown Source)
 sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
 java.lang.reflect.Method.invoke(Method.java:597)
 com.bea.wli.sb.transports.Util$1.invoke(Util.java:83)
 $Proxy140.sendMessageAsync(Unknown Source)
 com.bea.wli.sb.transports.LoadBalanceFailoverListener.sendMessageAsync(LoadBalanceFailoverListener.java:148)
 com.bea.wli.sb.transports.LoadBalanceFailoverListener.sendMessageToServiceAsync(LoadBalanceFailoverListener.java:603)
 com.bea.wli.sb.transports.LoadBalanceFailoverListener.sendMessageToService(LoadBalanceFailoverListener.java:538)
 com.bea.wli.sb.transports.TransportManagerImpl.sendMessageToService(TransportManagerImpl.java:558)
 com.bea.wli.sb.transports.TransportManagerImpl.sendMessageAsync(TransportManagerImpl.java:426)
 com.bea.wli.sb.pipeline.PipelineContextImpl.doDispatch(PipelineContextImpl.java:670)
 com.bea.wli.sb.pipeline.PipelineContextImpl.dispatchSync(PipelineContextImpl.java:551)
 stages.transform.runtime.WsCalloutRuntimeStep$WsCalloutDispatcher.dispatch(WsCalloutRuntimeStep.java:1391)
 stages.transform.runtime.WsCalloutRuntimeStep.processMessage(WsCalloutRuntimeStep.java:236)
 com.bea.wli.sb.stages.StageMetadataImpl$WrapperRuntimeStep.processMessage(StageMetadataImpl.java:346)
 com.bea.wli.sb.pipeline.PipelineStage.processMessage(PipelineStage.java:84)
 com.bea.wli.sb.pipeline.PipelineContextImpl.execute(PipelineContextImpl.java:1055)
 com.bea.wli.sb.pipeline.Pipeline.processMessage(Pipeline.java:141)
 com.bea.wli.sb.pipeline.PipelineContextImpl.execute(PipelineContextImpl.java:1055)
 com.bea.wli.sb.pipeline.PipelineNode.doRequest(PipelineNode.java:55)
 com.bea.wli.sb.pipeline.Node.processMessage(Node.java:67)
 com.bea.wli.sb.pipeline.PipelineContextImpl.execute(PipelineContextImpl.java:1055)
 com.bea.wli.sb.pipeline.Router.processMessage(Router.java:214)
 com.bea.wli.sb.pipeline.MessageProcessor.processRequest(MessageProcessor.java:96)
 com.bea.wli.sb.pipeline.RouterManager$1.run(RouterManager.java:593)
 com.bea.wli.sb.pipeline.RouterManager$1.run(RouterManager.java:591)
 weblogic.security.acl.internal.AuthenticatedSubject.doAs(AuthenticatedSubject.java:363)
 weblogic.security.service.SecurityManager.runAs(SecurityManager.java:146)
 com.bea.wli.sb.security.WLSSecurityContextService.runAs(WLSSecurityContextService.java:55)
 com.bea.wli.sb.pipeline.RouterManager.processMessage(RouterManager.java:590)
 com.bea.wli.sb.transports.TransportManagerImpl.receiveMessage(TransportManagerImpl.java:375)
 com.bea.wli.sb.transports.local.LocalMessageContext$1.run(LocalMessageContext.java:179)
 weblogic.security.acl.internal.AuthenticatedSubject.doAs(AuthenticatedSubject.java:363)
 weblogic.security.service.SecurityManager.runAs(SecurityManager.java:146)
 weblogic.security.Security.runAs(Security.java:61)
 com.bea.wli.sb.transports.local.LocalMessageContext.send(LocalMessageContext.java:174)
 com.bea.wli.sb.transports.local.LocalTransportProvider.sendMessageAsync(LocalTransportProvider.java:322)
 sun.reflect.GeneratedMethodAccessor645.invoke(Unknown Source)
 sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
 java.lang.reflect.Method.invoke(Method.java:597)
 com.bea.wli.sb.transports.Util$1.invoke(Util.java:83)
 $Proxy125.sendMessageAsync(Unknown Source)
 com.bea.wli.sb.transports.LoadBalanceFailoverListener.sendMessageAsync(LoadBalanceFailoverListener.java:148)
 com.bea.wli.sb.transports.LoadBalanceFailoverListener.sendMessageToServiceAsync(LoadBalanceFailoverListener.java:603)
 com.bea.wli.sb.transports.LoadBalanceFailoverListener.sendMessageToService(LoadBalanceFailoverListener.java:538)
 com.bea.wli.sb.transports.TransportManagerImpl.sendMessageToService(TransportManagerImpl.java:558)
 com.bea.wli.sb.transports.TransportManagerImpl.sendMessageAsync(TransportManagerImpl.java:426)
 com.bea.wli.sb.pipeline.PipelineContextImpl.doDispatch(PipelineContextImpl.java:670)
 com.bea.wli.sb.pipeline.PipelineContextImpl.dispatchSync(PipelineContextImpl.java:551)
 stages.transform.runtime.WsCalloutRuntimeStep$WsCalloutDispatcher.dispatch(WsCalloutRuntimeStep.java:1391)
 stages.transform.runtime.WsCalloutRuntimeStep.processMessage(WsCalloutRuntimeStep.java:236)
 com.bea.wli.sb.stages.StageMetadataImpl$WrapperRuntimeStep.processMessage(StageMetadataImpl.java:346)
 com.bea.wli.sb.stages.impl.SequenceRuntimeStep.processMessage(SequenceRuntimeStep.java:33)
 com.bea.wli.sb.pipeline.PipelineStage.processMessage(PipelineStage.java:84)
 com.bea.wli.sb.pipeline.PipelineContextImpl.execute(PipelineContextImpl.java:1055)
 com.bea.wli.sb.pipeline.Pipeline.processMessage(Pipeline.java:141)
 com.bea.wli.sb.pipeline.PipelineContextImpl.execute(PipelineContextImpl.java:1055)
 com.bea.wli.sb.pipeline.PipelineNode.doRequest(PipelineNode.java:55)
 com.bea.wli.sb.pipeline.Node.processMessage(Node.java:67)
 com.bea.wli.sb.pipeline.PipelineContextImpl.execute(PipelineContextImpl.java:1055)
 com.bea.wli.sb.pipeline.Router.processMessage(Router.java:214)
 com.bea.wli.sb.pipeline.MessageProcessor.processRequest(MessageProcessor.java:96)
 com.bea.wli.sb.pipeline.RouterManager$1.run(RouterManager.java:593)
 com.bea.wli.sb.pipeline.RouterManager$1.run(RouterManager.java:591)
 weblogic.security.acl.internal.AuthenticatedSubject.doAs(AuthenticatedSubject.java:363)
 weblogic.security.service.SecurityManager.runAs(SecurityManager.java:146)
 com.bea.wli.sb.security.WLSSecurityContextService.runAs(WLSSecurityContextService.java:55)
 com.bea.wli.sb.pipeline.RouterManager.processMessage(RouterManager.java:590)
 com.bea.wli.sb.transports.TransportManagerImpl.receiveMessage(TransportManagerImpl.java:375)
 com.bea.wli.sb.transports.local.LocalMessageContext$1.run(LocalMessageContext.java:179)
 weblogic.security.acl.internal.AuthenticatedSubject.doAs(AuthenticatedSubject.java:363)
 weblogic.security.service.SecurityManager.runAs(SecurityManager.java:146)
 weblogic.security.Security.runAs(Security.java:61)
 com.bea.wli.sb.transports.local.LocalMessageContext.send(LocalMessageContext.java:174)
 com.bea.wli.sb.transports.local.LocalTransportProvider.sendMessageAsync(LocalTransportProvider.java:322)
 sun.reflect.GeneratedMethodAccessor645.invoke(Unknown Source)
 sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
 java.lang.reflect.Method.invoke(Method.java:597)
 com.bea.wli.sb.transports.Util$1.invoke(Util.java:83)
 $Proxy125.sendMessageAsync(Unknown Source)
 com.bea.wli.sb.transports.LoadBalanceFailoverListener.sendMessageAsync(LoadBalanceFailoverListener.java:148)
 com.bea.wli.sb.transports.LoadBalanceFailoverListener.sendMessageToServiceAsync(LoadBalanceFailoverListener.java:603)
 com.bea.wli.sb.transports.LoadBalanceFailoverListener.sendMessageToService(LoadBalanceFailoverListener.java:538)
 com.bea.wli.sb.transports.TransportManagerImpl.sendMessageToService(TransportManagerImpl.java:558)
 com.bea.wli.sb.transports.TransportManagerImpl.sendMessageAsync(TransportManagerImpl.java:426)
 com.bea.wli.sb.pipeline.PipelineContextImpl.doDispatch(PipelineContextImpl.java:670)
 com.bea.wli.sb.pipeline.PipelineContextImpl.dispatch(PipelineContextImpl.java:585)
 stages.publish.runtime.PublishRuntimeStep.processMessage(PublishRuntimeStep.java:181)
 com.bea.wli.sb.pipeline.StatisticUpdaterRuntimeStep.processMessage(StatisticUpdaterRuntimeStep.java:41)
 com.bea.wli.sb.stages.StageMetadataImpl$WrapperRuntimeStep.processMessage(StageMetadataImpl.java:346)
 com.bea.wli.sb.stages.impl.SequenceRuntimeStep.processMessage(SequenceRuntimeStep.java:33)
 stages.transform.runtime.ForEachRuntimeStep.processMessage(ForEachRuntimeStep.java:101)
 com.bea.wli.sb.pipeline.StatisticUpdaterRuntimeStep.processMessage(StatisticUpdaterRuntimeStep.java:41)
 com.bea.wli.sb.stages.StageMetadataImpl$WrapperRuntimeStep.processMessage(StageMetadataImpl.java:346)
 com.bea.wli.sb.pipeline.PipelineStage.processMessage(PipelineStage.java:84)
 com.bea.wli.sb.pipeline.PipelineContextImpl.execute(PipelineContextImpl.java:1055)
 com.bea.wli.sb.pipeline.Pipeline.processMessage(Pipeline.java:141)
 com.bea.wli.sb.pipeline.PipelineContextImpl.execute(PipelineContextImpl.java:1055)
 com.bea.wli.sb.pipeline.PipelineNode.doRequest(PipelineNode.java:55)
 com.bea.wli.sb.pipeline.Node.processMessage(Node.java:67)
 com.bea.wli.sb.pipeline.PipelineContextImpl.execute(PipelineContextImpl.java:1055)
 com.bea.wli.sb.pipeline.Router.processMessage(Router.java:214)
 com.bea.wli.sb.pipeline.MessageProcessor.processRequest(MessageProcessor.java:96)
 com.bea.wli.sb.pipeline.RouterManager$1.run(RouterManager.java:593)
 com.bea.wli.sb.pipeline.RouterManager$1.run(RouterManager.java:591)
 weblogic.security.acl.internal.AuthenticatedSubject.doAs(AuthenticatedSubject.java:363)
 weblogic.security.service.SecurityManager.runAs(SecurityManager.java:146)
 com.bea.wli.sb.security.WLSSecurityContextService.runAs(WLSSecurityContextService.java:55)
 com.bea.wli.sb.pipeline.RouterManager.processMessage(RouterManager.java:590)
 com.bea.wli.sb.transports.TransportManagerImpl.receiveMessage(TransportManagerImpl.java:375)
 com.bea.wli.sb.transports.http.generic.RequestHelperBase.invokePipeline(RequestHelperBase.java:179)
 com.bea.wli.sb.transports.http.wls.HttpTransportServlet$RequestHelperWLS.invokePipeline(HttpTransportServlet.java:227)
 com.bea.wli.sb.transports.http.generic.RequestHelperBase$1.run(RequestHelperBase.java:154)
 com.bea.wli.sb.transports.http.generic.RequestHelperBase$1.run(RequestHelperBase.java:152)
 weblogic.security.acl.internal.AuthenticatedSubject.doAs(AuthenticatedSubject.java:363)
 weblogic.security.service.SecurityManager.runAs(SecurityManager.java:146)
 com.bea.wli.sb.transports.http.generic.RequestHelperBase.securedInvoke(RequestHelperBase.java:151)
 com.bea.wli.sb.transports.http.generic.RequestHelperBase.service(RequestHelperBase.java:107)
 com.bea.wli.sb.transports.http.wls.HttpTransportServlet.service(HttpTransportServlet.java:129)
 weblogic.servlet.FutureResponseServlet.service(FutureResponseServlet.java:24)
 javax.servlet.http.HttpServlet.service(HttpServlet.java:820)
 weblogic.servlet.internal.StubSecurityHelper$ServletServiceAction.run(StubSecurityHelper.java:227)
 weblogic.servlet.internal.StubSecurityHelper.invokeServlet(StubSecurityHelper.java:125)
 weblogic.servlet.internal.ServletStubImpl.execute(ServletStubImpl.java:300)
 weblogic.servlet.internal.ServletStubImpl.execute(ServletStubImpl.java:183)
 weblogic.servlet.internal.WebAppServletContext$ServletInvocationAction.wrapRun(WebAppServletContext.java:3717)
 weblogic.servlet.internal.WebAppServletContext$ServletInvocationAction.run(WebAppServletContext.java:3681)
 weblogic.security.acl.internal.AuthenticatedSubject.doAs(AuthenticatedSubject.java:321)
 weblogic.security.service.SecurityManager.runAs(SecurityManager.java:120)
 weblogic.servlet.internal.WebAppServletContext.securedExecute(WebAppServletContext.java:2277)
 weblogic.servlet.internal.WebAppServletContext.execute(WebAppServletContext.java:2183)
 weblogic.servlet.internal.ServletRequestImpl.run(ServletRequestImpl.java:1454)
 weblogic.work.ExecuteThread.execute(ExecuteThread.java:209)
 weblogic.work.ExecuteThread.run(ExecuteThread.java:178)
 

We vaguely understand that (bottom to top):

this was a HTTP Proxy, since at transport level it's initiated by a ServletRequest

after a LOT of layers of transport and security related processing, we reach the core RouterManager.processMessage() method. We understand that the RouterManager is the core on the Proxy Message Flow processing.

the RouterManager creates a RouterContext, which contains a reference both to the MessageContext
public MessageContext getMessageContext();
and to the ProxyService:
public ProxyService getProxyService();
these 2 classes identify both the message (messageId) and the proxy being invoked.

a static call to MessageProcessor.processRequest(RouterContext context) will then deal with getting the right Pipeline and pushing the message through the Message Flow (Router, PipelineContextImpl, PipelineStage....).


The problem is that there is no means to grab a reference to a collection of the running messages with associated proxy. We can't even override the implementation of these classes, because OSB doesn't use Dependency Injection, and implementations are instantiated with a new().

The only way to log these messages being processed is either using some instrumentation to intercept the static MessageProcessor.processRequest(RouterContext context) call (like BTrace), or by explicitely call a Java Callout / Custom XPath at the beginning of each Proxy, logging to a file the Thread Name, the Proxy Service and the messageId.

Caveat: if you use a Route node, the thread used to process the response is different from the one used for the request. You should use intercept also MessageProcessor.processResponse()

I have also been thinking of storing all that info (messageID, proxy) in a ThreadLocal variable, and use log4j MDC to log that info in the WebLogic logs. But again this requires a Java Callout.

One could also change the thread name by appending the Proxy Name http://stackoverflow.com/questions/5532864/thread-setnamename-caveats

See also https://forums.oracle.com/thread/2449899