Sunday, March 10, 2013

Learning Switchyard, from the inside out

My job with Red Hat is exciting.  I'm a maintenance engineer on the SOA (and sometimes BRMS) products, both of which are constantly growing and introducing new features.  Keeping up can be quite a task.

The next big change for SOA is going to be the introduction of the new 'Switchyard' infrastructure.  Learning to use Switchyard is one thing-- there are lots of videos, blogs, etc. for that.  But how do you learn how it really works?

This question is one I often describe to people with an analogy.  Using software is like learning to drive a car.  Supporting software is a superset of that-- it's more like having to know what makes the engine, transmission, etc. work.  It's impossible to help people solve their software problems without understanding what makes it all tick.

So I'm trying to learn about the innards of Switchyard.  I'll share an important technique today, one that can be re-used with different applications.  I hope you find it helpful.

First, let's decide on a use case to investigate.  Switchyard has a nice 'quickstarts' directory that you can use to see how Switchyard apps are built.  For today, I'm interested in how Switchyard transforms data so I thought I'd work with the transform-jaxb example.

This quickstart exposes a service through SOAP.  You just use maven ('mvn clean install') to package the project, deploy it to Switchyard, then invoke the application with SOAPUI or another SOAP client.  (Hint:  Sometimes you may wonder which URL to use in situations like this.  The console may not always tell you.  If you grep the log for 'wsdl' you'll often find one you can use.)

So now that we've 'learned to drive the car' (deployed an application, tested it') let's 'learn how the car works'.

STEP1:  Look over the source, pick a class that is likely to be invoked.  In this case, there is a bean used to represent the Order we input to SOAPUI.  I'm guessing the getters will need to be invoked on this class as the SOAP is marsheled on input.

STEP2:  Let's write a Byteman rule to give us a stack trace when this method is invoked.  (If you don't know about Byteman, please go find out ASAP!  Every Java programmer should know about Byteman....)
Here's the rule I cooked up:

RULE Learn about transformation
CLASS org.switchyard.quickstarts.transform.jaxb.Order
METHOD getOrderId
AT ENTRY
IF TRUE
DO traceStack("CALLED ORDER GETTER " + "\n", 100)
ENDRULE

STEP3: Deploy that rule (again, please be familiar with Byteman-- install Byteman into your app server, submit this rule).

STEP4:  Re-run your SOAPUI test.  Then go to your server.log for the Byteman output.  Looking over the output (included below)  we get a wealth of information.  Just in one quick pass, here's some of what we can gather: 

- This work is being done on an http thread (http--127.0.0.1-8080-1)
- CXF is handling the web-servicey stuff
- There's a Switchyard 'ExchangeImpl' being used.  (We should expect this!)
- Apache Camel is involved early on.  Camel users will recognize the 'Producer'

From here, I'll look for other classes and methods to use in Byteman rules to learn about how Switchyard is going about it's work.  Since we're working with high-quality open source software, we can also look at the classes and methods cited in this stacktrace. 

A stack trace like this (or better yet, a few of them taken off the same user use-case) can tell us a lot about what's going on under the hood.

Happy learning!


:19,729 INFO  [org.jboss.as.server] (DeploymentScanner-threads - 2) JBAS018559: Deployed "switchyard-quickstart-transform-jaxb.jar"
14:38:51,432 INFO  [stdout] (http--127.0.0.1-8080-1) CALLED ORDER GETTER
14:38:51,433 INFO  [stdout] (http--127.0.0.1-8080-1) org.switchyard.quickstarts.transform.jaxb.Order.getOrderId(Order.java:-1)
14:38:51,434 INFO  [stdout] (http--127.0.0.1-8080-1) org.switchyard.quickstarts.transform.jaxb.OrderServiceBean.submitOrder(OrderServiceBean.java:31)
14:38:51,434 INFO  [stdout] (http--127.0.0.1-8080-1) sun.reflect.NativeMethodAccessorImpl.invoke0(NativeMethodAccessorImpl.java:-2)
14:38:51,435 INFO  [stdout] (http--127.0.0.1-8080-1) sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
14:38:51,436 INFO  [stdout] (http--127.0.0.1-8080-1) sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
14:38:51,436 INFO  [stdout] (http--127.0.0.1-8080-1) java.lang.reflect.Method.invoke(Method.java:616)
14:38:51,436 INFO  [stdout] (http--127.0.0.1-8080-1) org.switchyard.component.bean.ServiceProxyHandler.handle(ServiceProxyHandler.java:130)
14:38:51,437 INFO  [stdout] (http--127.0.0.1-8080-1) org.switchyard.component.bean.ServiceProxyHandler.handleMessage(ServiceProxyHandler.java:89)
14:38:51,437 INFO  [stdout] (http--127.0.0.1-8080-1) org.switchyard.bus.camel.processors.ProviderProcessor.process(ProviderProcessor.java:39)
14:38:51,438 INFO  [stdout] (http--127.0.0.1-8080-1) org.apache.camel.util.AsyncProcessorConverterHelper$ProcessorToAsyncProcessorBridge.process(AsyncProcessorConverterHelper.java:61)
14:38:51,438 INFO  [stdout] (http--127.0.0.1-8080-1) org.apache.camel.util.AsyncProcessorHelper.process(AsyncProcessorHelper.java:73)
14:38:51,439 INFO  [stdout] (http--127.0.0.1-8080-1) org.apache.camel.processor.DelegateAsyncProcessor.processNext(DelegateAsyncProcessor.java:99)
14:38:51,439 INFO  [stdout] (http--127.0.0.1-8080-1) org.apache.camel.processor.DelegateAsyncProcessor.process(DelegateAsyncProcessor.java:90)
14:38:51,440 INFO  [stdout] (http--127.0.0.1-8080-1) org.apache.camel.util.AsyncProcessorHelper.process(AsyncProcessorHelper.java:73)
14:38:51,440 INFO  [stdout] (http--127.0.0.1-8080-1) org.apache.camel.processor.DelegateAsyncProcessor.processNext(DelegateAsyncProcessor.java:99)
14:38:51,441 INFO  [stdout] (http--127.0.0.1-8080-1) org.apache.camel.processor.DelegateAsyncProcessor.process(DelegateAsyncProcessor.java:90)
14:38:51,441 INFO  [stdout] (http--127.0.0.1-8080-1) org.apache.camel.management.InstrumentationProcessor.process(InstrumentationProcessor.java:73)
14:38:51,441 INFO  [stdout] (http--127.0.0.1-8080-1) org.apache.camel.util.AsyncProcessorHelper.process(AsyncProcessorHelper.java:73)
14:38:51,442 INFO  [stdout] (http--127.0.0.1-8080-1) org.apache.camel.processor.DelegateAsyncProcessor.processNext(DelegateAsyncProcessor.java:99)
14:38:51,442 INFO  [stdout] (http--127.0.0.1-8080-1) org.apache.camel.processor.DelegateAsyncProcessor.process(DelegateAsyncProcessor.java:90)
14:38:51,443 INFO  [stdout] (http--127.0.0.1-8080-1) org.apache.camel.processor.interceptor.TraceInterceptor.process(TraceInterceptor.java:91)
14:38:51,443 INFO  [stdout] (http--127.0.0.1-8080-1) org.apache.camel.util.AsyncProcessorHelper.process(AsyncProcessorHelper.java:73)
14:38:51,444 INFO  [stdout] (http--127.0.0.1-8080-1) org.apache.camel.processor.DelegateAsyncProcessor.processNext(DelegateAsyncProcessor.java:99)
14:38:51,444 INFO  [stdout] (http--127.0.0.1-8080-1) org.apache.camel.processor.DelegateAsyncProcessor.process(DelegateAsyncProcessor.java:90)
14:38:51,445 INFO  [stdout] (http--127.0.0.1-8080-1) org.switchyard.bus.camel.audit.FaultProcessor.process(FaultProcessor.java:52)
14:38:51,446 INFO  [stdout] (http--127.0.0.1-8080-1) org.apache.camel.util.AsyncProcessorHelper.process(AsyncProcessorHelper.java:73)
14:38:51,446 INFO  [stdout] (http--127.0.0.1-8080-1) org.apache.camel.processor.RedeliveryErrorHandler.processErrorHandler(RedeliveryErrorHandler.java:330)
14:38:51,447 INFO  [stdout] (http--127.0.0.1-8080-1) org.apache.camel.processor.RedeliveryErrorHandler.process(RedeliveryErrorHandler.java:220)
14:38:51,447 INFO  [stdout] (http--127.0.0.1-8080-1) org.apache.camel.processor.RouteContextProcessor.processNext(RouteContextProcessor.java:45)
14:38:51,448 INFO  [stdout] (http--127.0.0.1-8080-1) org.apache.camel.processor.DelegateAsyncProcessor.process(DelegateAsyncProcessor.java:90)
14:38:51,449 INFO  [stdout] (http--127.0.0.1-8080-1) org.apache.camel.processor.interceptor.DefaultChannel.process(DefaultChannel.java:303)
14:38:51,449 INFO  [stdout] (http--127.0.0.1-8080-1) org.apache.camel.util.AsyncProcessorHelper.process(AsyncProcessorHelper.java:73)
14:38:51,450 INFO  [stdout] (http--127.0.0.1-8080-1) org.apache.camel.processor.Pipeline.process(Pipeline.java:117)
14:38:51,450 INFO  [stdout] (http--127.0.0.1-8080-1) org.apache.camel.processor.Pipeline.process(Pipeline.java:80)
14:38:51,451 INFO  [stdout] (http--127.0.0.1-8080-1) org.apache.camel.processor.RouteContextProcessor.processNext(RouteContextProcessor.java:45)
14:38:51,451 INFO  [stdout] (http--127.0.0.1-8080-1) org.apache.camel.processor.DelegateAsyncProcessor.process(DelegateAsyncProcessor.java:90)
14:38:51,452 INFO  [stdout] (http--127.0.0.1-8080-1) org.apache.camel.processor.UnitOfWorkProcessor.process(UnitOfWorkProcessor.java:122)
14:38:51,453 INFO  [stdout] (http--127.0.0.1-8080-1) org.apache.camel.processor.RouteInflightRepositoryProcessor.processNext(RouteInflightRepositoryProcessor.java:48)
14:38:51,453 INFO  [stdout] (http--127.0.0.1-8080-1) org.apache.camel.processor.DelegateAsyncProcessor.process(DelegateAsyncProcessor.java:90)
14:38:51,454 INFO  [stdout] (http--127.0.0.1-8080-1) org.apache.camel.util.AsyncProcessorHelper.process(AsyncProcessorHelper.java:73)
14:38:51,454 INFO  [stdout] (http--127.0.0.1-8080-1) org.apache.camel.processor.DelegateAsyncProcessor.processNext(DelegateAsyncProcessor.java:99)
14:38:51,455 INFO  [stdout] (http--127.0.0.1-8080-1) org.apache.camel.processor.DelegateAsyncProcessor.process(DelegateAsyncProcessor.java:90)
14:38:51,456 INFO  [stdout] (http--127.0.0.1-8080-1) org.apache.camel.management.InstrumentationProcessor.process(InstrumentationProcessor.java:73)
14:38:51,456 INFO  [stdout] (http--127.0.0.1-8080-1) org.apache.camel.util.AsyncProcessorHelper.process(AsyncProcessorHelper.java:73)
14:38:51,457 INFO  [stdout] (http--127.0.0.1-8080-1) org.apache.camel.component.direct.DirectProducer.process(DirectProducer.java:61)
14:38:51,457 INFO  [stdout] (http--127.0.0.1-8080-1) org.apache.camel.processor.UnitOfWorkProcessor.processAsync(UnitOfWorkProcessor.java:150)
14:38:51,458 INFO  [stdout] (http--127.0.0.1-8080-1) org.apache.camel.processor.UnitOfWorkProcessor.process(UnitOfWorkProcessor.java:117)
14:38:51,459 INFO  [stdout] (http--127.0.0.1-8080-1) org.apache.camel.util.AsyncProcessorHelper.process(AsyncProcessorHelper.java:99)
14:38:51,459 INFO  [stdout] (http--127.0.0.1-8080-1) org.apache.camel.processor.DelegateAsyncProcessor.process(DelegateAsyncProcessor.java:86)
14:38:51,460 INFO  [stdout] (http--127.0.0.1-8080-1) org.apache.camel.processor.UnitOfWorkProducer.process(UnitOfWorkProducer.java:63)
14:38:51,460 INFO  [stdout] (http--127.0.0.1-8080-1) org.apache.camel.impl.ProducerCache$2.doInProducer(ProducerCache.java:360)
14:38:51,461 INFO  [stdout] (http--127.0.0.1-8080-1) org.apache.camel.impl.ProducerCache$2.doInProducer(ProducerCache.java:331)
14:38:51,461 INFO  [stdout] (http--127.0.0.1-8080-1) org.apache.camel.impl.ProducerCache.doInProducer(ProducerCache.java:227)
14:38:51,462 INFO  [stdout] (http--127.0.0.1-8080-1) org.apache.camel.impl.ProducerCache.sendExchange(ProducerCache.java:331)
14:38:51,462 INFO  [stdout] (http--127.0.0.1-8080-1) org.apache.camel.impl.ProducerCache.send(ProducerCache.java:169)
14:38:51,463 INFO  [stdout] (http--127.0.0.1-8080-1) org.apache.camel.impl.DefaultProducerTemplate.send(DefaultProducerTemplate.java:111)
14:38:51,464 INFO  [stdout] (http--127.0.0.1-8080-1) org.apache.camel.impl.DefaultProducerTemplate.send(DefaultProducerTemplate.java:97)
14:38:51,464 INFO  [stdout] (http--127.0.0.1-8080-1) org.switchyard.bus.camel.ExchangeDispatcher.dispatch(ExchangeDispatcher.java:64)
14:38:51,465 INFO  [stdout] (http--127.0.0.1-8080-1) org.switchyard.internal.ExchangeImpl.sendInternal(ExchangeImpl.java:203)
14:38:51,467 INFO  [stdout] (http--127.0.0.1-8080-1) org.switchyard.internal.ExchangeImpl.send(ExchangeImpl.java:114)
14:38:51,468 INFO  [stdout] (http--127.0.0.1-8080-1) org.switchyard.component.soap.InboundHandler.invoke(InboundHandler.java:213)
14:38:51,470 INFO  [stdout] (http--127.0.0.1-8080-1) org.switchyard.component.soap.endpoint.BaseWebService.invoke(BaseWebService.java:113)
14:38:51,470 INFO  [stdout] (http--127.0.0.1-8080-1) org.switchyard.component.soap.endpoint.BaseWebService.invoke(BaseWebService.java:43)
14:38:51,470 INFO  [stdout] (http--127.0.0.1-8080-1) sun.reflect.NativeMethodAccessorImpl.invoke0(NativeMethodAccessorImpl.java:-2)
14:38:51,472 INFO  [stdout] (http--127.0.0.1-8080-1) sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
14:38:51,473 INFO  [stdout] (http--127.0.0.1-8080-1) sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
14:38:51,474 INFO  [stdout] (http--127.0.0.1-8080-1) java.lang.reflect.Method.invoke(Method.java:616)
14:38:51,474 INFO  [stdout] (http--127.0.0.1-8080-1) org.jboss.ws.common.invocation.AbstractInvocationHandlerJSE.invoke(AbstractInvocationHandlerJSE.java:111)
14:38:51,475 INFO  [stdout] (http--127.0.0.1-8080-1) org.jboss.wsf.stack.cxf.JBossWSInvoker._invokeInternal(JBossWSInvoker.java:181)
14:38:51,475 INFO  [stdout] (http--127.0.0.1-8080-1) org.jboss.wsf.stack.cxf.JBossWSInvoker.invoke(JBossWSInvoker.java:127)
14:38:51,476 INFO  [stdout] (http--127.0.0.1-8080-1) org.apache.cxf.interceptor.ServiceInvokerInterceptor$1.run(ServiceInvokerInterceptor.java:58)
14:38:51,476 INFO  [stdout] (http--127.0.0.1-8080-1) java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
14:38:51,477 INFO  [stdout] (http--127.0.0.1-8080-1) java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334)
14:38:51,477 INFO  [stdout] (http--127.0.0.1-8080-1) java.util.concurrent.FutureTask.run(FutureTask.java:166)
14:38:51,478 INFO  [stdout] (http--127.0.0.1-8080-1) org.apache.cxf.workqueue.SynchronousExecutor.execute(SynchronousExecutor.java:37)
14:38:51,478 INFO  [stdout] (http--127.0.0.1-8080-1) org.apache.cxf.interceptor.ServiceInvokerInterceptor.handleMessage(ServiceInvokerInterceptor.java:106)
14:38:51,479 INFO  [stdout] (http--127.0.0.1-8080-1) org.apache.cxf.phase.PhaseInterceptorChain.doIntercept(PhaseInterceptorChain.java:263)
14:38:51,480 INFO  [stdout] (http--127.0.0.1-8080-1) org.apache.cxf.transport.ChainInitiationObserver.onMessage(ChainInitiationObserver.java:121)
14:38:51,480 INFO  [stdout] (http--127.0.0.1-8080-1) org.apache.cxf.transport.http.AbstractHTTPDestination.invoke(AbstractHTTPDestination.java:207)
14:38:51,481 INFO  [stdout] (http--127.0.0.1-8080-1) org.jboss.wsf.stack.cxf.RequestHandlerImpl.handleHttpRequest(RequestHandlerImpl.java:91)
14:38:51,481 INFO  [stdout] (http--127.0.0.1-8080-1) org.jboss.wsf.stack.cxf.transport.ServletHelper.callRequestHandler(ServletHelper.java:169)
14:38:51,482 INFO  [stdout] (http--127.0.0.1-8080-1) org.jboss.wsf.stack.cxf.CXFServletExt.invoke(CXFServletExt.java:87)
14:38:51,482 INFO  [stdout] (http--127.0.0.1-8080-1) org.apache.cxf.transport.servlet.AbstractHTTPServlet.handleRequest(AbstractHTTPServlet.java:185)
14:38:51,483 INFO  [stdout] (http--127.0.0.1-8080-1) org.apache.cxf.transport.servlet.AbstractHTTPServlet.doPost(AbstractHTTPServlet.java:108)
14:38:51,484 INFO  [stdout] (http--127.0.0.1-8080-1) javax.servlet.http.HttpServlet.service(HttpServlet.java:754)
14:38:51,484 INFO  [stdout] (http--127.0.0.1-8080-1) org.jboss.wsf.stack.cxf.CXFServletExt.service(CXFServletExt.java:135)
14:38:51,484 INFO  [stdout] (http--127.0.0.1-8080-1) org.jboss.wsf.spi.deployment.WSFServlet.service(WSFServlet.java:140)
14:38:51,485 INFO  [stdout] (http--127.0.0.1-8080-1) javax.servlet.http.HttpServlet.service(HttpServlet.java:847)
14:38:51,485 INFO  [stdout] (http--127.0.0.1-8080-1) org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:329)
14:38:51,486 INFO  [stdout] (http--127.0.0.1-8080-1) org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:248)
14:38:51,487 INFO  [stdout] (http--127.0.0.1-8080-1) org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:275)
14:38:51,487 INFO  [stdout] (http--127.0.0.1-8080-1) org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:161)
14:38:51,488 INFO  [stdout] (http--127.0.0.1-8080-1) org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:155)
14:38:51,488 INFO  [stdout] (http--127.0.0.1-8080-1) org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102)
14:38:51,489 INFO  [stdout] (http--127.0.0.1-8080-1) org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109)
14:38:51,489 INFO  [stdout] (http--127.0.0.1-8080-1) org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:368)
14:38:51,490 INFO  [stdout] (http--127.0.0.1-8080-1) org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:877)
14:38:51,491 INFO  [stdout] (http--127.0.0.1-8080-1) org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:671)
14:38:51,491 INFO  [stdout] (http--127.0.0.1-8080-1) org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:930)
14:38:51,492 INFO  [stdout] (http--127.0.0.1-8080-1) java.lang.Thread.run(Thread.java:679)

No comments: