Using a PhaseListener to Debug JSF Development Defects

Many traditional Java developers quickly embraced the Java Server Faces (JSF) framework and the various library extensions for Java Web development. JSF frameworks hide a large number of details from the developer, who typically has either always used JSF frameworks or is familiar with non-JSF frameworks that implement their solutions in a very different manner. This abstraction can make debugging a JSF application very difficult.

Perhaps one of the most difficult types of defect to isolate and identify in JSF are performance issues, because they are often the result of introducing one or more new technologies into a well-known software ecosystem. The more complex the architecture, such as Web applications that are exposing enterprise SOA functionalities, the more potential points of failure exist. Such systems are generally run by multiple teams, and each team is generally confident enough in their own experience and skills to assume that the root of the issue is somewhere outside their area of responsibility. Also, the more technologies are involved, the less likely it is that someone will understand enough about all of the components to determine the most likely starting point for troubleshooting. Enter the PhaseListener.

JSF does its work in phases, and knowing what is happening in which phase can yield much more useful clues as to where the trouble is originating. JSF includes the notion of running filters on given phases by implementing the PhaseListener Interface javax.faces.event.PhaseListener. In a discussion list, I came across the notion of logging the start and finish of each phase. By doing so, the log files can clearly delineate what action is occurring during which phase by using the three methods of the PhaseListener Interface and not limiting which phase it is executed in. In this article, I explain how to use a PhaseListener to help demystify debugging development defects.

Amp Up Your Logging with a PhaseListener

The first place most developers check for information about where issues are occurring is the application logs. In the case of JSF applications, simply following logging best practices may not be enough to find the precise point where the issue begins, especially if the team is new to JSF or the JSF development team is integrating with an unfamiliar backend service.

Just as complex applications are difficult to debug, they also make for poor learning references. For demonstration, this article uses a variation of the basic JSF application described for the Eclipse Web Tools Project. After the application is built, you can add your own preferred logger to follow along. I used log4j, and the basic logging results are something like this:

DEBUG LoginBean : getName(): null
DEBUG LoginBean : getPassword(): null
DEBUG LoginBean : getName(): null
DEBUG ValidatePassword: validate(FacesContext arg0, UIComponent arg1, Object arg2)
DEBUG LoginBean : getPassword(): null
DEBUG LoginBean : setName() sdfasdf
DEBUG LoginBean : setPassword(): asdfasdf
DEBUG LoginBean : getName(): sdfasdf

The three concrete class methods of the PhaseListener interface are simple:

public PhaseId getPhaseId()
{
 return PhaseId.ANY_PHASE;
} 

public void beforePhase(PhaseEvent event)
{
 logger.debug("n++++++ START PHASE " + event.getPhaseId()+" ++++++");
}

public void afterPhase(PhaseEvent event)
{
 logger.debug("n++++++ END PHASE " + event.getPhaseId()+" ++++++");
}

And the listener is registered in faces-config.xml with the following:

com.fyw.demo.LifeCycleListener

And then we have our new log output:

DEBUG LifeCycleListener:
++++++ START PHASE RESTORE_VIEW 1 ++++++
DEBUG LifeCycleListener:
++++++ END PHASE RESTORE_VIEW 1 ++++++
DEBUG LifeCycleListener:
++++++ START PHASE RENDER_RESPONSE 6 ++++++
DEBUG LoginBean : getName(): null
DEBUG LoginBean : getPassword(): null
DEBUG LifeCycleListener:
++++++ END PHASE RENDER_RESPONSE 6 ++++++
DEBUG LifeCycleListener:
++++++ START PHASE RESTORE_VIEW 1 ++++++
DEBUG LifeCycleListener:
++++++ END PHASE RESTORE_VIEW 1 ++++++
DEBUG LifeCycleListener:
++++++ START PHASE APPLY_REQUEST_VALUES 2 ++++++
DEBUG LifeCycleListener:
++++++ END PHASE APPLY_REQUEST_VALUES 2 ++++++
DEBUG LifeCycleListener:
++++++ START PHASE PROCESS_VALIDATIONS 3 ++++++
DEBUG LoginBean : getName(): null
DEBUG ValidatePassword: validate(FacesContext arg0, UIComponent arg1, Object arg2)
DEBUG LoginBean : getPassword(): null
DEBUG LifeCycleListener:
++++++ END PHASE PROCESS_VALIDATIONS 3 ++++++
DEBUG LifeCycleListener:
++++++ START PHASE UPDATE_MODEL_VALUES 4 ++++++
DEBUG LoginBean : setName() Scott
DEBUG LoginBean : setPassword(): secret
DEBUG LifeCycleListener:
++++++ END PHASE UPDATE_MODEL_VALUES 4 ++++++
DEBUG LifeCycleListener:
++++++ START PHASE INVOKE_APPLICATION 5 ++++++
DEBUG LifeCycleListener:
++++++ END PHASE INVOKE_APPLICATION 5 ++++++
DEBUG LifeCycleListener:
++++++ START PHASE RENDER_RESPONSE 6 ++++++
DEBUG LoginBean : getName(): Scott
DEBUG LifeCycleListener:
++++++ END PHASE RENDER_RESPONSE 6 ++++++

So, for example, if there were an issue with the wrong name value showing up in a component log, we can see that the name value provided by the user is not actually available to other components until the UPDATE_MODEL_VALUES phase. Obviously more complex issues occur, and being able to identify the full lifecycle can often be the key to unraveling the problem.

Don't Let Listener Logging Lower Performance

While knowing in what phase each debug statement is occurring is useful, it is not always necessary or desirable. To make listener logging a useful tool, we can add a bit of control over it by using a property file to turn the behavior on or off as needed:

public static final boolean DO_PHASE_DEBUG = getDoPhaseDebug();
private static boolean getDoPhaseDebug()
{
 boolean doPhaseDebug = false;
 Properties props = new Properties();
 try
 {
 props.load(new FileInputStream("phaseDebugger.properties"));
 doPhaseDebug = Boolean.parseBoolean(props.getProperty("doPhaseDebug"));
 logger.info("doPhaseDebug: "+doPhaseDebug);
 }
 catch(Exception e)
 {
 logger.error("Oops");
 }
 return doPhaseDebug;
}

Then wrap our debug statements with a check:

 public void beforePhase(PhaseEvent event)
{
 if(LifeCycleListener.DO_PHASE_DEBUG)
 {
 ... {

Dig Deeper with a Component Tree Output

One area of complexity in highly customized UIs is the number of components involved and how they interact. While volumes of books and blog entries discuss the topic, component interaction can still be hard to visualize. Adding another level of detail to the debug logs can help with that. We can do that by adding two simple methods to our PhaseListener:

private void outputComponentTree(PhaseEvent event)
{
 FacesContext context = event.getFacesContext();
 UIViewRoot root = context.getViewRoot();
 outputComponentTreeRecur(context, root, "");
}
private void outputComponentTreeRecur(FacesContext context, UIComponent component, String prefix)
{
 Iterator compIt = null;
 String compId = null;
 UIComponent subComp = null;
 if(component!=null)
 {
 compId = component.getClientId(context); 
 compIt = component.getChildren().iterator();
 logger.debug(prefix+"ID: "+compId+"tType: "+component.getRendererType());
 while (compIt.hasNext())
 {
 subComp = compIt.next();
 outputComponentTreeRecur(context, subComp, prefix+"t");
 }
 }
}

Now we can see much more detail about each phase and the sequence of the individual components with the structure:

++++++ START PHASE RENDER_RESPONSE 6 ++++++
DEBUG LifeCycleListener: %%%%%%%%%
DEBUG LifeCycleListener: DebugPhaseListener Tree Before Phase RENDER_RESPONSE 6
DEBUG LifeCycleListener: ID: j_id0 Type: null
DEBUG LifeCycleListener: %%%%%%%%%
DEBUG LoginBean : getName(): Scott
DEBUG LifeCycleListener: %%%%%%%%%
DEBUG LifeCycleListener: DebugPhaseListener Tree AFTER Phase RENDER_RESPONSE 6
DEBUG LifeCycleListener: ID: j_id_jsp_887103952_0 Type: null
DEBUG LifeCycleListener: ID: j_id_jsp_887103952_1 Type: javax.faces.Form
DEBUG LifeCycleListener: ID: j_id_jsp_887103952_1:j_id1 Type: javax.faces.Text
DEBUG LifeCycleListener: ID: j_id_jsp_887103952_1:j_id_jsp_887103952_2 Type: javax.faces.Text
DEBUG LifeCycleListener: %%%%%%%%%
DEBUG LifeCycleListener:
++++++ END PHASE RENDER_RESPONSE 6 ++++++

Granted, this is not as readable because it is so verbose. However, it can be useful when simply knowing the phase is not enough, such as when a third-party framework is being used in addition to the standard JSF libraries. One option would be to have a separate switch to set the level of logging as well as turning it on or off.

One Other Non-Standard Tweak

Consider logging when the class is created to monitor that it is being created when you expect it to be. You can accomplish this by adding the following:

{
 if(LOGGER.isDebugEnabled())LOGGER.debug("Creating LoginBean"); 
}

Conclusion

I had begun investigating the PhaseListener tool for debugging after having read about it on a distribution list. I found it educational when making my first forays into JSF, and it was handy for following the lifecycle on those days when it wasn't always clear what was happening when. In one case, I ran a PhaseListener in an application with a framework that used a JSR 329 portlet bridge and discovered that the RESTORE_VIEW was called twice for each form submission. This knowledge enabled the team to catch some potential performance issues before the application went into production and saved us all from those dreaded evening and weekend support calls.

About the Author

Scott Nelson helps companies of all sizes in planning, designing, developing and maintaining Web-accessible applications. He has worked as both an independent contractor and professional services consultant for system integrators and J2EE product vendors since 1993. Scott blogs on three separate topics: personal investing (http://money.fywservices.com), forwarded jokes (http://humor.fywservices.com) and IT (http://techblog.fywservices.com).