Friday, November 02, 2007

Fix: ClassCastException in Struts getRequestProcessor under WebLogic 7

At work yesterday, we were having a problem with one of our internal web applications running on BEA WebLogic Server 7 SP 7, Struts 1.1, and Java 1.4, where following an application redeployment, users of the application would get HTTP 500 errors. The WebLogic server output log file showed multiple ClassCastException errors with the following call stack:

java.lang.ClassCastException
at org.apache.struts.action.ActionServlet.getRequestProcessor(ActionServlet.java:871)
at org.apache.struts.action.ActionServlet.process(ActionServlet.java:1508)
at org.apache.struts.action.ActionServlet.doGet(ActionServlet.java:507)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:740)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:853)
. . .
at weblogic.servlet.internal.ServletRequestImpl.execute(ServletRequestImpl.java:2642)
at weblogic.kernel.ExecuteThread.execute(ExecuteThread.java:262)
at weblogic.kernel.ExecuteThread.run(ExecuteThread.java:224)

After some troubleshooting, we determined that this error would only occur when the application was under some load (from being hit by multiple users) while it was starting up; the error wouldn't occur if only a single user accessed the application while it was starting.

So, restarting the application while it was not under load (e.g. overnight) turned out to be a viable workaround in our case. Although we were back up and running at this point, I continued to research the issue to get a better understanding of the underlying cause, and to come up with a better solution should we ever need to restart the server during the work day in the future.

Researching the Issue

Some research via Google didn't turn up any obvious solutions on the issue. The exception was being thrown from the Struts class ActionServlet.getRequestProcessor; since Struts is open source, I decided to download the Struts source, and add some additional instrumentation to the getRequestProcessor method to see if that would shed any additional light on the issue.

ActionServlet.java line 871 (from the ClassCastException stack trace) turned out to be the second of these two lines, at the top of the ActionServlet.getRequestProcessor method:

String key = Globals.REQUEST_PROCESSOR_KEY + config.getPrefix();
RequestProcessor processor = (RequestProcessor)getServletContext().getAttribute(key);

So the exception was happening on the attempt to cast the result of getServletContext().getAttribute(key) to type RequestProcessor.

I added some logging to the getRequestProcessor method to log the class name of the result of the getServletContext().getAttribute(key) call to stderr (so that it would be visible in the WebLogic server log), along with the name of the current thread (so I would hopefully be able to get visibility into whether different application threads were getting different results).

Object o = getServletContext().getAttribute(key);
if (o == null)
{ 
  System.err.println("$$$ " + java.lang.Thread.currentThread().getName() + ": " 
    + "getServletContext().getAttribute(key) is null"); 
}
else
{
  System.err.println("$$$ " + java.lang.Thread.currentThread().getName() + ": " 
    + "type=" + o.getClass().toString());
}

(The "$$$" here is just a poor man's bookmark to let me easily search for my debug logging in the server log file.)

In the WebLogic log file, the type of the object causing the ClassCastException upon the attempt to cast it to type RequestProcessor was of type PIRequestProcessor, a custom type used by my company's application. I was initially confused by this, because PIRequestProcessor is declared to extend RequestProcessor in its class declaration, so casting a PIRequestProcessor to a RequestProcessor should be a valid operation. Yet this operation was definitely causing the ClassCastException.

At this point, I remembered a post on Java class loaders that I had just recently read on Kevin Bourrillion's blog (some slightly NSFW content). From Kevin's post:

But now we're finally getting to the interesting part: every class in memory in your runtime environment can be uniquely identified by the pair of (a) its full name (b) the class loader that loaded it

And also:

You may have heard someone explain, or you may have explained yourself, "see, you can't cast a foo.Bar to a foo.Bar here even though it's the same class, because they came from different class loaders, so there's funny class loader hoodoo going on there."

Aha! I improved my instrumentation on the getRequestProcessor method to include the classloader of the PIRequestProcessor instance, and of the current thread:

System.err.println("$$$ " + java.lang.Thread.currentThread().getName() + ": " 
  + type=" + o.getClass().toString() 
  + " | classloader of o: " + o.getClass().getClassLoader().toString() 
  + " | current thread classloader: " + java.lang.Thread.currentThread().getContextClassLoader());

Sure enough, I got two sets of output in the log. One set like the following, for the first thread that got into the getRequestProcessor method, which looked like this:

$$$ ExecuteThread: '5' for queue: 'default': type=class com.gfs.mps.application.productInquiry.struts.PIRequestProcessor instanceof:true classloader of o: weblogic.utils.classloaders.ChangeAwareClassLoader@4b4b50 finder: weblogic.utils.classloaders.MultiClassFinder@6edffb current thread classloader: weblogic.utils.classloaders.ChangeAwareClassLoader@4b4b50 finder: weblogic.utils.classloaders.MultiClassFinder@6edffb

And another set of logged output, for the subsequent threads that get into getRequestProcessor, like this:

$$$ ExecuteThread: '7' for queue: 'default': type=class com.gfs.mps.application.productInquiry.struts.PIRequestProcessor instanceof:false classloader of o: weblogic.utils.classloaders.ChangeAwareClassLoader@4b4b50 finder: weblogic.utils.classloaders.MultiClassFinder@6edffb current thread classloader: weblogic.utils.classloaders.ChangeAwareClassLoader@dfb821 finder: weblogic.utils.classloaders.MultiClassFinder@1a1569b

(Bolded emphasis added by me; note the different class loader ID in the second log output.) The problem was that WebLogic was using two different class loaders in the different threads. The PIRequestProcessor[4b4b50] instance (i.e. a PIRequestProcessor instance created via the class loader with ID 4b4b50) was created and cached in the first thread in the call to getRequestProcessor. When the cached PIRequestProcessor was retrieved by the second thread in its call to getRequestProcessor, the PIRequestProcessor[4b4b50] instance was returned, and when the attempt was made to cast that to a RequestProcessor[dfb821] (created by the dfb821 class loader rather than the 4b4b50 class loader), the ClassCastException resulted.

Most likely this issue between Struts 1.1 and WebLogic Server 7 SP 7 has been addressed in the current versions of one or both products; both are fairly old versions of their respective products. (A poster in that BEA forum thread claims to have been sent a patch by BEA, CR189815, that resolves this issue in WebLogic 8.1.) But in the meantime, I still wanted to come up with a solution to the issue for our application running in that environment.

The Solution

In my initial research on Google, one of the items I had come across was an article on avoiding unnecessary JSP recompilations under WebLogic 8.1 on the BEA site by Nagesh Susarla. Among other things, the article mentions a WebLogic Server parameter, "servlet-reload-check-secs", which can be set to have WebLogic not monitor during runtime whether any new Java class files have been put into place. I also came across a thread in the BEA forums which mentioned someone else running WebLogic Server having a similar problem with a ClassCastException (not really in similar circumstances my own issue, but with a similar exception call stack) and with one of the replies suggesting that the WebLogic setting to disable to disable servlet reloading at runtime be set.

I decided to give that solution a try. Initially it wasn't obvious to me where the WebLogic 7 equivalent of the servlet-reload-check-secs parameter could be set, or even whether that parameter was supported at all under WebLogic 7; my web searches turned out some documentation on the setting for WebLogic 8.1, but not for earlier versions.

After some poking around in the WebLogic 7 console, I did find the place where the equivalent of "servlet-reload-check-secs" can be set: The setting is called "Reload Period", located in the console at [domain] | Deployments | Web Applications | [app name] | Configuration tab | Files sub-tab. The setting's default is 1; setting the value to -1 and restarting the WebLogic server disables WebLogic's runtime servlet reload checking for the web application where the setting was made. (The underlying WebLogic domain config.xml setting is called "ServletReloadCheckSecs".)

After making that setting change, things started working correctly! In my log, I could see that WebLogic was no longer using different class loaders in calls to the Struts ActionServlet.getRequestProcessor method; therefore, no ClassCastException was occurring, and the application was loading properly.