Debugging Webservice clients - Log HTTP transport content

Many times it is useful to see the actual content that is send and received through the wire in order to troubleshoot webservice clients. Unfortunately, there does not seem to be a standard way to enable logging across all the webservice clients. Depending on the client you use for accessing the webservice, the debugging method varies. Here are a few tips that will help.

If you are using Axis client to access a webservice and using log4j for logging, you can enable printing of the http request and response contents by setting the "httpclient.wire.content" property to "debug". For example if using the log4j.properties file set the following property:

log4j.category.httpclient.wire.content=debug,stdout

If the webservice is connecting to a secure url using https protocol, setting the java system property "javax.net.debug" to "plaintext" will provide a hex dump of the content send and received.

If you are using the web service proxy provided by oc4j within jdeveloper or the oc4j container, you can enable the java logging property "oracle.webservices.client" in logging.properties file to FINE

oracle.webservices.client.level=FINE

Setting this option will allow a standalone client to log the request and response content to the log file specified by the logging.properties file.

If the client is running within the oc4j container, you can enable the oracle diagnostics logging for "oracle.webservices.client". This can be done by navigating to the <oc4j container> -> Administration --> Logger Configuration page and setting the log level as "FINE" for "oracle.webservices.client" property.
You can view the request and response contents in the log.xml file.

Oracle ESB deploy script

If you need to deploy your ESB projects to multiple environments without jDeveloper, there is not a elegant solution. The ANT deployment tasks that comes part of the 10.3.1.3 packages helps a good deal. You can refer to the documentation on that at
http://www.oracle.com/technology/products/integration/esb/files/esbdeploymentautomation.zip or it is included in your ORACLE_HOME/integration/deployment/documentation.zip file.

Using the deployment script described there, you can extract the deployment plan from the esb project files. Once you have extracted the deployment plan file, all your settings will be in one single file which you can edit/make multiple copies with different settings for different environments. Even though this approach is far better than having to maintain several versions of several esb file, it still falls short of my expectation.

For most of the ESB projects dealing with various adapters and such, the deployment plan file has too much information it it so every time the ESB project changes (adding/removing adaptors or adaptor settings), you will have to regenerate the deployment plan file and make the copies for your different information. However, in most cases the only information that changes per environment are the endpoint properties that specify file directories, server specific properties etc. From a development and deployment perspective, it would be much nicer, if oracle had provided a way to specify the endpoint properties in a single location on the server, so every time a new version of ESB project is deployed, the endpoint properties are not impacted. In the absence of such feature, the closest that I could do minimize the impact of maintaining the endpoint properties is to generate the deployment plan file using the ant task and edit it using another custom task that takes the endpoint properties from a properties file that just has the properties you want to be different for each environment.

The source code and the sample ant task for this can be found here.

Using this approach, you create a property file that contains the endpoint property as the key and the value you want as a simple java style property file. You will need to create one such file per environment. The java program takes the template file, the properties file and the new deployment file name as arguments and creates the deployment file that can be used by the ant task that comes with oracle. Using this procedure, a typical build will have the following steps.
1) Extract deployment plan file using the oracle provided task.
2) Invole the ESBDeploymentPlanEditor class to create a server/environment specific deployment plan using the custom task
3) Deploy the ESB project using the deployment plan created on the above step using the oracle provided task.

oc4j classloading diagnostics using MBean

Class Loading can be tricky in a J2EE environment. The Oracle Application server documentation provides good explanation on how the classloading works. However, at times, it is easier to just test if the classloader can find a class without having to go through the hops to execute the class. Fortunately, oc4j offers a MBean that can be used for that purpose. Here is the detail step to test if a class can be found by the classloader.

1. Log in enterprise manager console.
2. Click on your OC4J container name on the main topology web site.
3. Click on the link "Administration".
4. Click on the "Go To Task" icon as follows.

JMX -> System MBean Browser

5. Expand the ClassLoading node in the navigation pane, then select the singleton MBean instance.
6. Click the Operations tab in the right-hand pane, then click the executeQuery operation.

Three versions of the executeQuery operation are exposed. Click the version that takes one parameter.

7. Enter in a value as follows under the "Parameters" heading -> LoaderTree
8. Click the Invoke button to call the operation.

This will display the class loading hirearchy.

To test if a given class can be found by the classloader, repeat steps 7 & 8 with the following command in the parameters tree

FindResource(packagename.classname)


There are other queries/commands that you can run on the MBean. For a complete list reffer to the oracle documentation here

ESB ftp adaptor missing class oracle.tip.adapter.file.outbound.FileIoInteractionSpec

If you happen to get an error in the ftp adaptor that it is unable to find the class oracle.tip.adapter.file.outbound.FileIoInteractionSpec, the most likely reason is that there is a class loading issue. To validate the issue, you can use the MBean for class loading and run the following command.

FindResource(oracle.tip.adapter.file.outbound.FileIoInteractionSpec)

If the above command indicate that the class is not found, you may run the following command to verify it it is atleast in your system.

Depends(oracle.tip.adapter.file.outbound.FileIoInteractionSpec)

If this command shows that the class in in the FTPAdaptor jar file, you may simply delete the /j2ee//connectors/FileAdapter/FileAdapter directory and restart the container. This will reimport the files in the fileadaptor directory with the right files.

ESB rejected Message Handlers doesnot work

If you ever wondered to change the default place where the ESB drops the files it rejected, you might have came across the endproperty "rejectedMessageHandlers". However JDeveloper 10.1.3.3 does not allow to add this property. You have to close the jDeveloper, edit the file manually and re-register the service. I also noticed that the property seems to be disappearing some times. (so keep a backup handy all the time)

There is also another catch to the way you specify the value of the property. The developer guide example specifies a sample value as below.

<property name="rejectedMessageHandlers" value="file://c:\rejectSample\reject"/>

However, it will not work. As pointed out in the OTN thread
you need to add a additional slash after the file: as shown below.

<property name="rejectedMessageHandlers" value="file:///c:\rejectSample\reject"/>

I agree this is pretty dump. However it if you are reading this you might be already used to such dump things from the SOA suite.


P.S. In case you are wondering the location of the default folder for the rejected messages, it is /j2ee/home/jca/service.name.routingservice.name/rejectedMessages.
I have not yet found a way to keep the name of the original input file.
rejectedMessageHandlers

How to: Get filename from ESB adaptor

Oracle ESB provides header functions that allows designers to access inbound and outbound header functions. The following are the functions available.

1. String getRequestHeader(String xpathExpression,String namespaceDecl)
2. void setOutboundHeader(String xpathExpression,String value, String namespaceDecl)
3. String getInboundResponseHeader(String xpathExpression,String namespaceDecl)
4. void setResponseHeader(String xpathExpression,String value, String namespaceDecl)
Where,
xpathExpression : XPath expression to get/set
value : value to be set for the xpathExpression
namespaceDecl : namespace declarations in the form ‘prefix=namespace;’


You can use the following code snippet in your transformation xslt to get the name of the file that is read by the file adaptor in ESB.

<xsl:variable name="GET_INFILENAME" select="ehdr:getRequestHeader('/fhdr:InboundFileHeaderType/fhdr:fileName',
'fhdr=http://xmlns.oracle.com/pcbpel/adapter/file/;')"/>

Viewing JSP Stack Traces with OC4J 10.1.3.1.

When an error occurs in the translation or runtime execution of a JSP page, the container would return the exception, message and a stacktrace to the client. However, the exception is not displayed in the page by default in OC4j.

This can be a little annoying for development machines. There are several ways to change this behavior. The easiest way is to set the development flag at the container level. This can be done by updating the element of the global-web-application.xml file.

Here is an example:

<orion-web-app
xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
xsi:noNamespaceSchemaLocation="http://xmlns.oracle.com/oracleas/schema/orion-web-10_0.xsd"
jsp-cache-directory="./persistence"
servlet-webdir="/servlet"
development="true"
jsp-timeout="0"
jsp-cache-tlds="standard"
schema-major-version="10"
schema-minor-version="0"
>


I like this option because, this can be set once for the container and dont have to worry about it.

If this cannot be done because you are working on a shared server, you can override individually by setting this flag on the application level by including orion-web.xml file in WEB-INF directory of your application. However, you have to make sure you remove this or change it when you deploy to production.

As a temporery measure, you can change it during deployment on the jdeveloper deployment wizard. The "Buttso Blathers" has a screen shot of this screen.

ORA-12516 error with oc4j SOA suite

One of the common errors I see when running the SOA suite from oracle is the ORA-12516 error. This typically happens in a development environment where the backend database is oracle XE. The root cause of the issue is the XE process is running out of sessions/process threads as the default values for these in XE is too small. To fix the error, verify the current values for the processes and sessions and increase them to atleast 300.

To increase the sessions and process use the following sqls.

sqlplus "sys as sysdba"
SQL> show parameter processes;
SQL> show parameter sessions;

If the values are less than 300, set them to 300 using the following sqls,

SQL> alter system set processes=300 scope=spfile;
SQL> alter system set sessions=300 scope=spfile;
SQL> shutdown immediate
SQL> startup

Now, restart the oracle process using the following commands.

opmnctl stopall
opmnctl startall

Struts/Tiles/oc4j logging

Recently I was troubleshooting an issue with a web application that uses struts/tiles and runs in an oc4j container. I application was getting a exception and oc4j will not print the exception stack trace in the output. It was hard to understand what is going on and it took me a while to figure out. So I am documenting here the process, so it can be a handy reference next time around or for some one who comes across the same issue.

To understand what was going on, the first step was to see what was the exception. To do this I set the development mode to true in the global_application.xml file. The global-web-application.xml file can be found under %ORACLE_HOME%/j2ee/%instance%/config/global-web-application.xml. Update the development attrubute on the orion-web-app tag to true and restart the instance.

<orion-web-app development="true" xsi="http://www.w3.org/2001/XMLSchema-instance" nonamespaceschemalocation="http://xmlns.oracle.com/oracleas/schema/orion-web-10_0.xsd" directory="./persistence" webdir="/servlet" timeout="0" tlds="false" version="0">

Now, if you visit the page on the browser, you will see the stack trace on the browser. This is a handy method, if your log files are cluttered. Alternatively you may view the stacktrace in the log files if you have configured oc4j to print standard out and error to a file. (for more information on how to setup refer to my earlier entry)

In my current situation, the stacktrace was not very useful as it did not point to any application code directly. The following is the stacktrace I received.

[   ERROR] [2008-07-01 09:23:13,500] [AJPRequestHandler-HTTPThreadGroup-5:] {{ServletException in '/StrutsAction2.do?QueryParm=parmvalue': null}} [org.apache.struts.taglib.tiles.InsertTag]
javax.servlet.ServletException: Error in servlet
 at com.evermind.server.http.ServletRequestDispatcher.invoke(ServletRequestDispatcher.java:757)
 at com.evermind.server.http.ServletRequestDispatcher.unprivileged_include(ServletRequestDispatcher.java:160)
 at com.evermind.server.http.ServletRequestDispatcher.access$000(ServletRequestDispatcher.java:50)
 at com.evermind.server.http.ServletRequestDispatcher$1.oc4jRun(ServletRequestDispatcher.java:97)
 at oracle.oc4j.security.OC4JSecurity.doPrivileged(OC4JSecurity.java:283)
 at com.evermind.server.http.ServletRequestDispatcher.include(ServletRequestDispatcher.java:102)
 at com.evermind.server.http.EvermindPageContext.include(EvermindPageContext.java:396)
 at com.evermind.server.http.EvermindPageContext.include(EvermindPageContext.java:349)
 at org.apache.struts.tiles.TilesUtilImpl.doInclude(TilesUtilImpl.java:101)
 at org.apache.struts.tiles.TilesUtil.doInclude(TilesUtil.java:137)
 at org.apache.struts.taglib.tiles.InsertTag.doInclude(InsertTag.java:758)
 at org.apache.struts.taglib.tiles.InsertTag$InsertHandler.doEndTag(InsertTag.java:890)
 at org.apache.struts.taglib.tiles.InsertTag.doEndTag(InsertTag.java:460)
 at _layouts._template._jspService(_template.java:324)
 at com.orionserver.http.OrionHttpJspPage.service(OrionHttpJspPage.java:59)
 at oracle.jsp.runtimev2.JspPageTable.service(JspPageTable.java:453)
 at oracle.jsp.runtimev2.JspServlet.internalService(JspServlet.java:591)
 at oracle.jsp.runtimev2.JspServlet.service(JspServlet.java:515)
 at javax.servlet.http.HttpServlet.service(HttpServlet.java:856)
 at com.evermind.server.http.ServletRequestDispatcher.invoke(ServletRequestDispatcher.java:711)
 at com.evermind.server.http.ServletRequestDispatcher.forwardInternal(ServletRequestDispatcher.java:368)
 at com.evermind.server.http.ServletRequestDispatcher.unprivileged_forward(ServletRequestDispatcher.java:259)
 at com.evermind.server.http.ServletRequestDispatcher.access$100(ServletRequestDispatcher.java:50)
 at com.evermind.server.http.ServletRequestDispatcher$2.oc4jRun(ServletRequestDispatcher.java:193)
 at oracle.oc4j.security.OC4JSecurity.doPrivileged(OC4JSecurity.java:283)
 at com.evermind.server.http.ServletRequestDispatcher.forward(ServletRequestDispatcher.java:198)
 at org.apache.struts.action.RequestProcessor.doForward(RequestProcessor.java:1056)
 at org.apache.struts.tiles.TilesRequestProcessor.doForward(TilesRequestProcessor.java:261)
 at org.apache.struts.tiles.TilesRequestProcessor.processTilesDefinition(TilesRequestProcessor.java:237)
 at org.apache.struts.tiles.TilesRequestProcessor.processForwardConfig(TilesRequestProcessor.java:300)
 at org.apache.struts.action.RequestProcessor.process(RequestProcessor.java:231)
 at org.apache.struts.action.ActionServlet.process(ActionServlet.java:1164)
 at org.apache.struts.action.ActionServlet.doPost(ActionServlet.java:415)
 at javax.servlet.http.HttpServlet.service(HttpServlet.java:763)
 at javax.servlet.http.HttpServlet.service(HttpServlet.java:856)
 at com.evermind.server.http.ServletRequestDispatcher.invoke(ServletRequestDispatcher.java:711)
 at com.evermind.server.http.ServletRequestDispatcher.forwardInternal(ServletRequestDispatcher.java:368)
 at com.evermind.server.http.HttpRequestHandler.doProcessRequest(HttpRequestHandler.java:866)
 at com.evermind.server.http.HttpRequestHandler.processRequest(HttpRequestHandler.java:448)
 at com.evermind.server.http.AJPRequestHandler.run(AJPRequestHandler.java:302)
 at com.evermind.server.http.AJPRequestHandler.run(AJPRequestHandler.java:190)
 at oracle.oc4j.network.ServerSocketReadHandler$SafeRunnable.run(ServerSocketReadHandler.java:260)
 at com.evermind.util.ReleasableResourcePooledExecutor$MyWorker.run(ReleasableResourcePooledExecutor.java:303)
 at java.lang.Thread.run(Thread.java:595)

As you can see, all I can see is it getting a null exception when the jvm is trying to process the request for StrutsAction2. Unfortunately it was not printing the application class that was causing the exception. The reason for the issue is the exception is happening in a different thread than the one the stacktrace is printed.
Here is what was happening. I was actually calling url accociated with StrutsAction1. The tile definition for the StrutsAction1 includes StrutsAction2 in its response. The stacktrace oc4j was printing was from the thread that was processing StrutsAction2 which is a seperate thread. The only clue I could get from here is that the error is occoring during StrutsAction2. If I try to invoke StrutsAction2 directly it seems to be working fine.

This made things a bit more complex and I started adding more and more debugging statements to the strutsaction2. Then I realized there is a Custom tiles plugin we have defined for the app and it had a debug statement. On the outlook, the debug statement looked harmless to me. However, I was a bit surprised by the fact that I was not even seeing the debugline on the logfile even after turning debug on.

Here is the debug statement.

Logger.debug("Processing Request: " + request.getContextPath() + request.getServletPath() +" Req Detail: " + getLogString(request));

 private String getLogString (HttpServletRequest req) {
  StringBuffer buf = new StringBuffer("Request Parms:");
  Enumeration parms = req.getParameterNames() ;
                if (parms != null) {
                while ( parms.hasMoreElements() ) {
   String parm = parms.nextElement() ;
   String pVal = req.getParameter(parm);
   buf.append(parm + "=" + pVal + ";");
  }
                }
  buf.append(": Req Headers: ");
  Enumeration headers = req.getHeaderNames() ;
                if (headers != null ) {
  while ( headers.hasMoreElements() ) {
   String parm = headers.nextElement() ;
   String pVal = req.getHeader(parm);
   buf.append(parm + "=" + pVal + ";");
  }
                }
                
  Enumeration attribs = req.getAttributeNames() ;
  if(attribs != null) {
                while ( attribs.hasMoreElements() ) {
   String parm = attribs.nextElement() ;
   Object pVal = req.getAttribute(parm);
   buf.append(parm + "=" + pVal.toString() + ";");
  }
                }
  return buf.toString();
 }

Not seeing the debug line in the log provided me the next clue. The issue might be somewhere in the debug statement. I came to the conclusion because this debug statement was the first thinging happening in the preprocess method for the plugin.

So my next step is to add a try catch around the debug line and printed the stacktrace in case of ecxeption. This pointed to the bug in the getLogString method. It was the line getting the attribute value "pVal.toString()" as the specific call flow, it was running in to an attribute that had a null value.

So I added a null check to the line as follows to get going. This was interesting beacause the common code that was suposed to be helping with debug was itself the one causing the bug. The leason here is be extra carefull with debug statements especially when adding to comon code.

buf.append(parm + "=" + (pVal==null?"null":pVal.toString()) + ";");"