Thursday, September 8, 2011

JSF 2 - Global Exception Handling

Build-in exception handling in JEE 6

As I described in a former article we replaced JEE 5 / Seam 2 with JEE 6. One of the features we really liked about Seam 2 was the global exception handling. You could declare exception handling rules in the global pages.xml such as logging, navigation, actions etc. Some might argue that the Servlet Container already allowed this in the web.xml:

<error-page>
 <error-code>404</error-code>
 <location>/404.xhtml</location>
</error-page>
...
<error-page>
 <exception-type>javax.faces.application.ViewExpiredException</exception-type>
 <location>/error.xhtml</location>
</error-page>

But this is really a poor replacement for the Seam features. First of all this JSF/Facelets-based exception page doesn't work because of a bug (with Weld on current JBoss AS 7):
ERROR [org.apache.catalina.core.ContainerBase.[jboss.web].[default-host]] (http--127.0.0.1-8082-1) Exception Processing ErrorPage[exceptionType=javax.faces.application.ViewExpiredException, location=/error.xhtml]: javax.servlet.ServletException: Context is already active
 at javax.faces.webapp.FacesServlet.service(FacesServlet.java:606) [jboss-jsf-api_2.1_spec-2.0.0.Beta1.jar:2.0.0.Beta1]
 at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:329) [jbossweb-7.0.1.Final.jar:7.1.0.Alpha1-SNAPSHOT]
...
Caused by: java.lang.IllegalStateException: Context is already active
 at org.jboss.weld.context.AbstractConversationContext.activate(AbstractConversationContext.java:311) [weld-core-1.1.2.Final.jar:2011-07-26 15:02]
 at org.jboss.weld.jsf.WeldPhaseListener.activateConversations(WeldPhaseListener.java:114) [weld-core-1.1.2.Final.jar:2011-07-26 15:02]
So you need to use a static HTML, Servlet or JSP for this. I really don't have a problem with that because in this case you will not be tempted to include too much in your global exception handling page. Why this? Facelets make it really easy to reuse global templates. Think about a navigation tree that is configurable and stored in a database. Than you get database exceptions and redirect to an error page that uses a global layout template with navigation...nasty things could happen here. Best practice: Keep exception handling pages simple.

But there are further problems. The given <exception-type> doesn't catch super types, it needs to be an exact match (think about things like a myriad of O/R mapper exceptions with a super exception). And by far the worst problem: You can do nothing about the logging of this catched exceptions via this configuration. In Seam you could define if such exceptions should be logged at all and on which severity level. I don't know about your customers or operation team but for us such log entries are a no-go:
ERROR [org.apache.catalina.core.ContainerBase.[jboss.web].[default-host].[/ifos].[Faces Servlet]] (http--127.0.0.1-8082-1) Servlet.service() for servlet Faces Servlet threw exception: ...controller.nutzer.AuthorizationException: Permission 'PERSON_LESEN_NUTZERDATEN' not granted!
 at ...controller.nutzer.Principal.check(Principal.java:46) [classes:]
...
ERROR [org.apache.catalina.core.ContainerBase.[jboss.web].[default-host].[/ifos].[Faces Servlet]] (http--127.0.0.1-8082-1) Servlet.service() for servlet Faces Servlet threw exception: javax.faces.application.ViewExpiredException: viewId:/Veranstaltungstypen/filter.xhtml - Ansicht /Veranstaltungstypen/filter.xhtml konnte nicht wiederhergestellt werden.
 at com.sun.faces.lifecycle.RestoreViewPhase.execute(RestoreViewPhase.java:205) [jsf-impl-2.1.3-b02-jbossorg-2.jar:2.1.3-SNAPSHOT]
...
ERROR [org.apache.catalina.core.ContainerBase.[jboss.web].[default-host].[/ifos].[Faces Servlet]] (http--127.0.0.1-8082-2) Servlet.service() for servlet Faces Servlet threw exception: com.sun.faces.context.FacesFileNotFoundException: /Veranstaltungstypen/filtr.xhtml Not Found in ExternalContext as a Resource
 at com.sun.faces.facelets.impl.DefaultFaceletFactory.resolveURL(DefaultFaceletFactory.java:232) [jsf-impl-2.1.3-b02-jbossorg-2.jar:2.1.3-SNAPSHOT]
The log is triggered (JSF 2.1.3) via ExceptionHandlerImpl.handle() -> log(context) -> LOGGER.log(Level.SEVERE, ... with Logger name "context" which is used throughout JSF for all kind of things. Grossly said this <exception-type> feature is outright unusable in the current form.

Wait for JEE 10? Nope...

I really don't know why the standard hasn't added a simple extension like a log severity attribute in the last years. Sometimes I really wonder about some decisions in regards to production requirements, e.g. why is the new JSF resources folder in the web application root path and not under WEB-INF (where the Servlet Container doesn't allow access by default)? The hackers say thank you.

At least in JEE 6 there has been added a somewhat hidden feature - a custom exception handler class.

Remove the <exception-type> garbage from your web.xml. Add this to your faces-config.xml:
<faces-config>
 ...
 <factory>
  <exception-handler-factory>...controller.util.exception.ExceptionHandlerFactory</exception-handler-factory>
 </factory>
</faces-config>
This references the factory class for a custom exception handler:
public class ExceptionHandlerFactory extends javax.faces.context.ExceptionHandlerFactory {

 private final javax.faces.context.ExceptionHandlerFactory parent;

 public ExceptionHandlerFactory(final javax.faces.context.ExceptionHandlerFactory parent) {
  this.parent = parent;
 }

 @Override
 public ExceptionHandler getExceptionHandler() {
  return new ExceptionHandler(this.parent.getExceptionHandler());
 }

}
And finally our exception handler:
public class ExceptionHandler extends ExceptionHandlerWrapper {

 private static final Logger LOG = LoggerFactory.getLogger(ExceptionHandler.class);

 private final javax.faces.context.ExceptionHandler wrapped;

 public ExceptionHandler(final javax.faces.context.ExceptionHandler wrapped) {
  this.wrapped = wrapped;
 }

 @Override
 public javax.faces.context.ExceptionHandler getWrapped() {
  return this.wrapped;
 }

 @Override
 public void handle() throws FacesException {
  for (final Iterator<ExceptionQueuedEvent> it = getUnhandledExceptionQueuedEvents().iterator(); it.hasNext();) {
   Throwable t = it.next().getContext().getException();
   while ((t instanceof FacesException || t instanceof EJBException || t instanceof ELException)
     && t.getCause() != null) {
    t = t.getCause();
   }
   if (t instanceof FileNotFoundException || t instanceof HandledException
     || t instanceof ViewExpiredException) {
    final FacesContext facesContext = FacesContext.getCurrentInstance();
    final ExternalContext externalContext = facesContext.getExternalContext();
    final Map<String, Object> requestMap = externalContext.getRequestMap();
    try {
     LOG.info("{}: {}", t.getClass().getSimpleName(), t.getMessage());
     String message;
     if (t instanceof ViewExpiredException) {
      final String viewId = ((ViewExpiredException) t).getViewId();
      message = "View is expired. <a href='/ifos"   viewId   "'>Back</a>";
     } else {
      message = t.getMessage(); // beware, don't leak internal info!
     }
     requestMap.put("errorMsg", message);
     try {
      externalContext.dispatch("/error.jsp");
     } catch (final IOException e) {
      LOG.error("Error view '/error.jsp' unknown!", e);
     }
     facesContext.responseComplete();
    } finally {
     it.remove();
    }
   }
  }
  getWrapped().handle();
 }

}
And a (simple example) error.jsp:
<!DOCTYPE HTML>
<html>
<head>
<meta charset="utf-8" />
<meta http-equiv="Content-Type" content="text/html; charset=UTF-8" />
<title>Error</title>
</head>
<body>
 <h1>Error</h1>
 <p><%= request.getAttribute("errorMsg") %></p>
</body>
</html>

This is a heavily reduced example with only some example exceptions. HandledException is our abstract super exception for custom service exceptions. You can freely decide what you do for which exception type:
  • dispatch to different views in dependance from exception (what we do)
  • provide different messages
  • specialized logging
  • etc. - all is possible

Now we see such infos in the log file:
INFO  [...controller.util.exception.ExceptionHandler] (http--127.0.0.1-8082-2) AuthorizationException: Permission 'PERSON_LESEN_NUTZERDATEN' not granted!
...
INFO  [...controller.util.exception.ExceptionHandler] (http--127.0.0.1-8082-2) ViewExpiredException: viewId:/Veranstaltungstypen/filter.xhtml - Ansicht /Veranstaltungstypen/filter.xhtml konnte nicht wiederhergestellt werden.
...
INFO  [...controller.util.exception.ExceptionHandler] (http--127.0.0.1-8082-2) FacesFileNotFoundException: /Personen/ter.xhtml Not Found in ExternalContext as a Resource

You might say this all looks a little bit shirtsleeved - no annotations or abstractions etc. The Seam 3 Catch module does exactly that. But we like the freedom of the programmable custom exception handler even if the API is a little bit strange. Currently we are heavily into our "Back to the Roots" trip and don't like to add too many further libraries for such simple things. Another reason: Even the advanced Seam 2 exception features where sometimes not enough for us. If you provide an abstraction then you also give up flexibility. I think the ExceptionHandler code is simple enough and doesn't change often.

Thursday, September 1, 2011

JVM - Out of swap space! Really?

Houston, ...

One of our hosted Portal systems had suddenly stability problems and the production team found this exception in the server logs:
Exception java.lang.OutOfMemoryError: requested 20971520 bytes for GrET* in
/BUILD_AREA/jdk1.5.0_23/hotspot/src/share/vm/utilities/growableArray.cpp.
Out of swap space?
The Portal has been running for years without such problems and suddenly the JVM reboots once a day with this unexpected C++ (!?) related exception.

Pavlovian conditioning

The team started to look for the usual OutOfMemoryError stuff like open sessions, medium session sizes, Garbage Collection behaviour etc. But there was nothing unusual. The JVM had sufficient free heap and the GC behaved well. This research doesn't cause any harm but will not solve this issue - this is no typical OutOfMemory Error that follows a Java Object allocation.

The message Out of swap space? also triggered some reasonable researches. But the machine had enough swap space and didn't even use that. This should be the expected behaviour for Java server systems - swapping is the Garbage Collectors worst enemy.

What to do if nothing helps? Google is your friend...Bug reports, Forums and Blogs ;) But as often as not the found solutions don't match, contain stale information or even sometimes are simply wrong. The hits for this exceptions contain things like (forget about it):
  • Hotspot should be deactivated, JVM bug
  • Garbage Collector type CMS has a bug, switch to another one
  • Java Heap space too fragmented
  • you should run JProbe, Memory Analyzer and activate verbose GC
  • update Java Version (OK....nothing wrong about that)

    What's really up?

    The error simply means that the JVM process - a (complex) C++ program (forget Java for a moment) - cannot allocate a continuous 20 MB virtual memory element. The JVM process only takes a guess here and claims there may not be enough system swap space: But really, the JVM process cannot know from the memory allocation response. The malloc only delivers a ‘null’ as memory pointer and that’s it. The well-intentioned hint 'swap space' is more often wrong and misleading than true.

    growableArray is used at all kind of places in the JVM, not only for Heap and PermSpace but also for allocating additional working space for Code generation (Hotspot), Thread stacks, Garbage Collection etc. This error has nothing to do with insufficient Heap or Perm space.

    There are many possible reasons, e.g.:
    • Really not enough physical memory or swap space. The claimed continuous memory cannot be in swap space (!) but other memory pages could swap out and indirectly the guess “not enough swap space” could be true. This is very likely not the problem. You should deactivate swap on JVM server systems anyway because the Garbage Collector and swapping don't go well together.
    • You have a 32 Bit JVM and simply overflow the 32 Bit process size of the underlying operating system. Remember only Solaris allows nearly 4 GB 32 Bit processes, the maximum JVM 32 Bit process size on Windows or older Linux is more like 3 GB.
    • An additional problem in the 32 Bit case could be a fragmented process space. Use the best practice for server JVMs and set -Xms equal to -Xmx and this shouldn't be the reason for this problem.

    4 GB ought to be enough for anybody.

    The JVM process size is not only the sum of Heap and Perm space. There is also the thread stack space (-Xss), Garbage Collector working space, Hotspot compilation space, general process space (e.g. for I/O or array copy) and much more - many of them have no specific JVM maximum settings - and this are none-trivial sizes and can also sum up to multiple 100 MB in a well frequented system with lots of threads and GC (and maybe large memory page sizes).

    Indirectly Hotspot compilation or Garbage Collection can be a trigger for the Error because this functionality needs process memory too on top of the Java Heap space. E.g. the GC type CMS needs much more additional memory as other types (interesting statistics). But the real reason are too generous settings for Heap and Perm space in the restricted 32 Bit JVM process size. Many developers know the following image and the important Xmx and MaxPermSize settings. With them you can restrict the largest chunk of the used process memory and you will be tempted to optimize the maximum settings too much:


    The initially mentioned (suddenly instable) Portal server runs with -Xms2600m -Xmx2600m -Xss128k on Solaris and uses 350 MB Perm space. But the real process size is on the verge of the 4 GB hazard zone:

    PID USERNAME SIZE RSS STATE PRI NICE TIME CPU PROCESS/NLWP
    25732 bea 3799M 3487M sleep 59 0 0:42:37 2.2% java/94

    Maybe we used more Perm space over the time because the Portal functionality is growing with each deployment. Or we used more worker threads because we have increasing peek traffic etc. It's really not important - lower the Heap settings by a small margin (the system runs nearly a full day before the error is triggered) and all is good ;)

    Switching to a 64 Bit VM is a possibility but keep the overhead in mind. For older JVMs this was an important decision. With modern JVMs CompressedOops may be an interesting option to alleviate the effects. In each case I cringe when I see a stateless high throughput system like an ESB with huge Heap sizes in 64 Bit mode.