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()) + ";");"