Don't Show Me the Wrapper; Show Me the Inside

Are you frustrated with how exceptions and errors are reported in some Java applications? I know I am when I see some simple errors are wrapped and disguised multiple times. It seems as if Java exception has been used as a way to hide root causes from end users.

I've seen this in quite a few Java software, including some otherwise great ones. Take Glassfish (JavaEE SDK, Sun Java System Application Server 9.0) for example.

My JSP failed with the following exceptions when trying to open a connection on a DataSource:
javax.servlet.ServletException:
java.sql.SQLException:
Error in allocating a connection.
Cause: Connection could not be allocated because:
java.security.PrivilegedActionException :
Error opening socket to server localhost on port 1527 with message : null
org.apache.jasper.runtime.PageContextImpl.doHandlePageException(PageContextImpl.java:930)
org.apache.jasper.runtime.PageContextImpl.handlePageException(PageContextImpl.java:863)
org.apache.jsp.index_jsp._jspService(index_jsp.java:103)
org.apache.jasper.runtime.HttpJspBase.service(HttpJspBase.java:111)
javax.servlet.http.HttpServlet.service(HttpServlet.java:820)
org.apache.jasper.servlet.JspServletWrapper.service(JspServletWrapper.java:353)
org.apache.jasper.servlet.JspServlet.serviceJspFile(JspServlet.java:412)
org.apache.jasper.servlet.JspServlet.service(JspServlet.java:318)
javax.servlet.http.HttpServlet.service(HttpServlet.java:820)
com.sun.enterprise.web.WebPipeline.invoke(WebPipeline.java:73)
com.sun.enterprise.web.VirtualServerPipeline.invoke(VirtualServerPipeline.java:120)
org.apache.coyote.tomcat5.CoyoteAdapter.service(CoyoteAdapter.java:231)
com.sun.enterprise.web.connector.grizzly.ProcessorTask.invokeAdapter(ProcessorTask.java:667)
com.sun.enterprise.web.connector.grizzly.ProcessorTask.processNonBlocked(ProcessorTask.java:574)
com.sun.enterprise.web.connector.grizzly.ProcessorTask.process(ProcessorTask.java:844)
com.sun.enterprise.web.connector.grizzly.ReadTask.executeProcessorTask(ReadTask.java:325)
com.sun.enterprise.web.connector.grizzly.ReadTask.doTask(ReadTask.java:250)
If you also get this error, I suggest you check if Derby/JavaDB database is started or not. I know it must be a user error on my part, since it's a pretty simple JSP and worked before. The stacktrace here shows 3 layers of nested exceptions:

1. javax.servlet.ServletException
2. java.sql.SQLException
3. java.security.PrivilegedActionException

But that's no problem, I said to myself. I sort of got used to it and usually go directly to the inner-most root cause. It would be java.security.PrivilegedActionException in this case. So I naturally thought I might have missed some socket-related security permission in my server.policy.

Wait, the SecurityManager is off by default, and my web app was running with no SecurityManager. How come I got this security exception? Well, the real reason was, I forgot to start Derby database. But this is not obvious anywhere in the output or server.log. I only see "with message : null" where the root cause should've been shown.

Below are just a few thoughts I have after this mini-adventure:
  • Connecting to database is executed inside a doPriviledged block, even when SecurityManager is off. Maybe we can optimize it away?

  • Calling PrivilegedActionException.getMessage() will almost always return a null, since PrivilegedActionException is just a wrapper exception, and usually constructed with no message. So any method that receives an instance of PrivilegedActionException should really peel if off to get the real cause, then either further throw out, or wrap up the real cause in another higher-level exception.

  • The same error message (not the real cause) was logged 3 times in a row in server.log. When it's not clear which component is responsible for logging errors, all parties do it. IMO, these logging entries are mostly redundant at INFO level, as the error message is already part of the exception. Less is better.

PS: To start the Derby/JavaDB database server bundled in Glassfish/J2EESDK/SJSAS, just run this command:
glassfish-install-dir/bin/asadmin start-database [--dbhost 0.0.0.0] [--dbport 1527]  [--dbhome
 current_directory] [--echo=false] [--terse=false]
To stop the database server, run this command:
glassfish-install-dir/bin/asadmin stop-database [--dbhost 0.0.0.0] [--dbport 1527]
For more info, run the help command for the two sub-commands:
./asadmin help start-database
./asadmin help stop-database
Alternatively, you can also directly run Derby/JavaDB's own start scripts in derby-or-JavaDB/frameworks/NetworkServer/bin, but you are more likely to get ksh script errors. I have two suggestions if you can't start derby/javaDB:
  • Make sure you set environment variables JAVA_HOME and DERBY_INSTALL. For example,
    set JAVA_HOME=C:\jdk5
    set DERBY_INSTALL=C:\Sun\Appserver\derby
  • On Solaris or Linux, do not directly run startNetworkServer.ksh, stopNetworkServer.ksh, or other ksh scripts. Instead, run ksh command with these scripts as parameter. For example,
    ksh setNetworkServerCP.ksh
    ksh ij.ksh
    Why? because ksh in your system may be in /usr/bin/ksh, or /bin/ksh, but Derby ksh scripts don't the usual first line like #! /bin/ksh, or #! /usr/bin/ksh. When derby has trouble finding the correct ksh, it reports some totally confusing error:
    CLASSPATH: Undefined variable.
    This is because Derby is using some ksh script (setNetworkClientCP.ksh) to set the environment variabel $CLASSPATH, and failed. So it complains CLASSPATH: Undefined variable. Any way, the lesson is to always run derby/javadb ksh scripts with ksh command.

Followers

Pageviews Last 7 Days