ICEfaces
  1. ICEfaces
  2. ICE-8851

NullPointerException in Mojarra code

    Details

    • Type: Bug Bug
    • Status: Closed
    • Priority: Major Major
    • Resolution: Fixed
    • Affects Version/s: 3.2.BETA1, 3.2
    • Fix Version/s: EE-3.2.0.GA, 3.3
    • Component/s: Framework
    • Labels:
      None
    • Environment:
      Mojarra
    • Assignee Priority:
      P1

      Description

      When running the QA tests in automation, the first test in the test suite fails because of an HTTP error 500 (see also attachment):
      HTTP Status 500 -
      type Exception report
      message
      description The server encountered an internal error () that prevented it from fulfilling this request.
      exception
      java.lang.NullPointerException
      javax.faces.component.UIViewRoot$ViewMap.clear(UIViewRoot.java:1779)
      com.sun.faces.config.InitFacesContext.release(InitFacesContext.java:239)
      javax.faces.webapp.FacesServlet.service(FacesServlet.java:577)
      note The full stack trace of the root cause is available in the Apache Tomcat/6.0.26 logs.
      In tomcat log, the error is:
      17-Dec-2012 4:14:08 PM org.apache.catalina.core.StandardWrapperValve invoke
      SEVERE: Servlet.service() for servlet Faces Servlet threw exception
      java.lang.NullPointerException
      at javax.faces.component.UIViewRoot$ViewMap.clear(UIViewRoot.java:1779)
      at com.sun.faces.config.InitFacesContext.release(InitFacesContext.java:239)
      at javax.faces.webapp.FacesServlet.service(FacesServlet.java:577)
      at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290)
      at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
      at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:233)
      at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:191)
      at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:127)
      at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102)
      at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109)
      at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:298)
      at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:852)
      at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:588)
      at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:489)
      at java.lang.Thread.run(Thread.java:662)

      This error is not an issue when deploying/testing manually.

        Activity

        Hide
        Mircea Toma added a comment -

        This issue is a follow up of ICE-8798. After some investigation, the exception seemed to be caused only by the Mojarra code.

        Show
        Mircea Toma added a comment - This issue is a follow up of ICE-8798 . After some investigation, the exception seemed to be caused only by the Mojarra code.
        Hide
        Deryk Sinotte added a comment -

        Could this issue be related to this one that I logged with them?

        http://java.net/jira/browse/JAVASERVERFACES-2644

        Show
        Deryk Sinotte added a comment - Could this issue be related to this one that I logged with them? http://java.net/jira/browse/JAVASERVERFACES-2644
        Hide
        Deryk Sinotte added a comment -

        Ignore my previous comment. It looks like the problem is occurring with Mojarra 2.1.6 and the issue I noted was related to 2.1.16 (fixed for 2.1.17).

        Show
        Deryk Sinotte added a comment - Ignore my previous comment. It looks like the problem is occurring with Mojarra 2.1.6 and the issue I noted was related to 2.1.16 (fixed for 2.1.17).
        Hide
        Deryk Sinotte added a comment -

        I'm seeing a similar (but slightly different) problem when undeploying the showcase.war:

        java.lang.NullPointerException
        	at javax.faces.component.UIViewRoot$ViewMap.clear(UIViewRoot.java:1779)
        	at com.sun.faces.config.InitFacesContext.release(InitFacesContext.java:239)
        	at com.sun.faces.config.ConfigureListener.contextDestroyed(ConfigureListener.java:352)
        	at org.apache.catalina.core.StandardContext.listenerStop(StandardContext.java:4831)
        	at org.apache.catalina.core.StandardContext.stopInternal(StandardContext.java:5478)
        	at org.apache.catalina.util.LifecycleBase.stop(LifecycleBase.java:232)
        	at org.apache.catalina.core.ContainerBase.removeChild(ContainerBase.java:1028)
        	at org.apache.catalina.startup.HostConfig.deleteRedeployResources(HostConfig.java:1300)
        	at org.apache.catalina.startup.HostConfig.checkResources(HostConfig.java:1230)
        	at org.apache.catalina.startup.HostConfig.check(HostConfig.java:1440)
        	at org.apache.catalina.startup.HostConfig.lifecycleEvent(HostConfig.java:301)
        	at org.apache.catalina.util.LifecycleSupport.fireLifecycleEvent(LifecycleSupport.java:119)
        	at org.apache.catalina.util.LifecycleBase.fireLifecycleEvent(LifecycleBase.java:90)
        	at org.apache.catalina.core.ContainerBase.backgroundProcess(ContainerBase.java:1374)
        	at org.apache.catalina.core.ContainerBase$ContainerBackgroundProcessor.processChildren(ContainerBase.java:1530)
        	at org.apache.catalina.core.ContainerBase$ContainerBackgroundProcessor.processChildren(ContainerBase.java:1540)
        	at org.apache.catalina.core.ContainerBase$ContainerBackgroundProcessor.run(ContainerBase.java:1519)
        	at java.lang.Thread.run(Thread.java:680)
        

        During redeployment, whenever it tries to clear the ViewMap, it can't find the FacesContext. I used the debugger to confirm that the FacesContext is null in the following method:

                @Override
                public void clear() {
        
                    FacesContext context = FacesContext.getCurrentInstance();
                    context.getApplication().publishEvent(context,
                                                          PreDestroyViewMapEvent.class,
                                                          context.getViewRoot());
                    super.clear();
        
                }
        

        It didn't make much sense why this would start happening now, though, as we've been using 2.1.6 for a long time.

        So I did a clean checkout of the trunk and was not able to reproduce the problem. I then compared the showcase.war file that was seeing the problem with the clean version that wasn't showing the problem. The thing that seemed to make a difference was removing a logging.properties file that I had added in for development purposes. Removing it made the problem go away. Adding it to the clean version caused the problem to return. Can QA confirm whether or not they are running their tests with a logging.properties file? Does removing it help?

        Show
        Deryk Sinotte added a comment - I'm seeing a similar (but slightly different) problem when undeploying the showcase.war: java.lang.NullPointerException at javax.faces.component.UIViewRoot$ViewMap.clear(UIViewRoot.java:1779) at com.sun.faces.config.InitFacesContext.release(InitFacesContext.java:239) at com.sun.faces.config.ConfigureListener.contextDestroyed(ConfigureListener.java:352) at org.apache.catalina.core.StandardContext.listenerStop(StandardContext.java:4831) at org.apache.catalina.core.StandardContext.stopInternal(StandardContext.java:5478) at org.apache.catalina.util.LifecycleBase.stop(LifecycleBase.java:232) at org.apache.catalina.core.ContainerBase.removeChild(ContainerBase.java:1028) at org.apache.catalina.startup.HostConfig.deleteRedeployResources(HostConfig.java:1300) at org.apache.catalina.startup.HostConfig.checkResources(HostConfig.java:1230) at org.apache.catalina.startup.HostConfig.check(HostConfig.java:1440) at org.apache.catalina.startup.HostConfig.lifecycleEvent(HostConfig.java:301) at org.apache.catalina.util.LifecycleSupport.fireLifecycleEvent(LifecycleSupport.java:119) at org.apache.catalina.util.LifecycleBase.fireLifecycleEvent(LifecycleBase.java:90) at org.apache.catalina.core.ContainerBase.backgroundProcess(ContainerBase.java:1374) at org.apache.catalina.core.ContainerBase$ContainerBackgroundProcessor.processChildren(ContainerBase.java:1530) at org.apache.catalina.core.ContainerBase$ContainerBackgroundProcessor.processChildren(ContainerBase.java:1540) at org.apache.catalina.core.ContainerBase$ContainerBackgroundProcessor.run(ContainerBase.java:1519) at java.lang. Thread .run( Thread .java:680) During redeployment, whenever it tries to clear the ViewMap, it can't find the FacesContext. I used the debugger to confirm that the FacesContext is null in the following method: @Override public void clear() { FacesContext context = FacesContext.getCurrentInstance(); context.getApplication().publishEvent(context, PreDestroyViewMapEvent.class, context.getViewRoot()); super .clear(); } It didn't make much sense why this would start happening now, though, as we've been using 2.1.6 for a long time. So I did a clean checkout of the trunk and was not able to reproduce the problem. I then compared the showcase.war file that was seeing the problem with the clean version that wasn't showing the problem. The thing that seemed to make a difference was removing a logging.properties file that I had added in for development purposes. Removing it made the problem go away. Adding it to the clean version caused the problem to return. Can QA confirm whether or not they are running their tests with a logging.properties file? Does removing it help?
        Hide
        Deryk Sinotte added a comment -

        I was finally able to reproduce the problem with the QA framework. I see the NPE when the page is first requested. Subsequent testing seems to continue on as normal. I hooked up a debugger to Tomcat instance that was running the tests and was able to determine the following.

        Mojarra has a class called InitFacesContext. This is a special class that is supposed to be used as a "lightweight" instance of the FacesContext for when the application initially starts up. The JavaDoc for the class states:

        A special, minimal implementation of FacesContext used at application initialization time. The ExternalContext returned by this FacesContext only exposes the ApplicationMap.

        During the initial request that comes into the FacesServlet, it checks to see if this initial context has been released yet and if it hasn't, run some one-time code:

                if (!initFacesContextReleased) {
                    FacesContext initFacesContext = FacesContext.getCurrentInstance();
                    if (null != initFacesContext) {
                        initFacesContext.release();
                    }
                    initFacesContextReleased = true;
                }
        

        During the release() method is when we see the problem occur. Normally, the first request doesn't even get this far because there is no FacesContext instance for this thread yet (it's set after this cleanup logic). Somehow, the test framework ends up with a request thread that still has a reference to the InitFacesContext. Because it's not null, it runs the release() logic.

        Here's where I believe Mojarra has a bug. As part of the release logic, the lightweight InitFacesContext removes itself as the thread local context and replaces it with the "original" FacesContext instance:

            public void release() {
                setCurrentInstance(orig);
        ...
        

        However, there was no "original" FacesContext so this basically sets it to null. When clear() is called on the ViewMap, it needs an instance of the FacesContext:

                @Override
                public void clear() {
        
                    FacesContext context = FacesContext.getCurrentInstance();
                    context.getApplication().publishEvent(context,
                                                          PreDestroyViewMapEvent.class,
                                                          context.getViewRoot());
                    super.clear();
        
                }
        

        But because it was set to null during release(), we get the NPE.

        Currently, the only way that I can envision this happening is if the thread used to deploy the application and get it started (which would have the InitFacesContext set as the thread local) is somehow the same thread used to do the initial page request in the test harness. When I finally managed to hook up the debugger, it appears that this might be what is happening. The same thread (http-8080-1,5) that was used to deploy and start the application (using the Tomcat deployment manager and an Ant task) appeared to have the same name as the thread used to make the initial request. Subsequent requests had a different thread name.

        Now that I knew what to look for, I found the following:

        http://java.net/jira/browse/JAVASERVERFACES-2398
        http://java.net/jira/browse/JAVASERVERFACES-2533

        I looked at the QA trunk and while there are a number of changes in December, I didn't see anything relevant that matched the dates we think the problem started. So I'm not sure how or when it started but it is a likely a known Mojarra issue that has been fixed in the latest releases.

        Show
        Deryk Sinotte added a comment - I was finally able to reproduce the problem with the QA framework. I see the NPE when the page is first requested. Subsequent testing seems to continue on as normal. I hooked up a debugger to Tomcat instance that was running the tests and was able to determine the following. Mojarra has a class called InitFacesContext. This is a special class that is supposed to be used as a "lightweight" instance of the FacesContext for when the application initially starts up. The JavaDoc for the class states: A special, minimal implementation of FacesContext used at application initialization time. The ExternalContext returned by this FacesContext only exposes the ApplicationMap. During the initial request that comes into the FacesServlet, it checks to see if this initial context has been released yet and if it hasn't, run some one-time code: if (!initFacesContextReleased) { FacesContext initFacesContext = FacesContext.getCurrentInstance(); if ( null != initFacesContext) { initFacesContext.release(); } initFacesContextReleased = true ; } During the release() method is when we see the problem occur. Normally, the first request doesn't even get this far because there is no FacesContext instance for this thread yet (it's set after this cleanup logic). Somehow, the test framework ends up with a request thread that still has a reference to the InitFacesContext. Because it's not null, it runs the release() logic. Here's where I believe Mojarra has a bug. As part of the release logic, the lightweight InitFacesContext removes itself as the thread local context and replaces it with the "original" FacesContext instance: public void release() { setCurrentInstance(orig); ... However, there was no "original" FacesContext so this basically sets it to null. When clear() is called on the ViewMap, it needs an instance of the FacesContext: @Override public void clear() { FacesContext context = FacesContext.getCurrentInstance(); context.getApplication().publishEvent(context, PreDestroyViewMapEvent.class, context.getViewRoot()); super .clear(); } But because it was set to null during release(), we get the NPE. Currently, the only way that I can envision this happening is if the thread used to deploy the application and get it started (which would have the InitFacesContext set as the thread local) is somehow the same thread used to do the initial page request in the test harness. When I finally managed to hook up the debugger, it appears that this might be what is happening. The same thread (http-8080-1,5) that was used to deploy and start the application (using the Tomcat deployment manager and an Ant task) appeared to have the same name as the thread used to make the initial request. Subsequent requests had a different thread name. Now that I knew what to look for, I found the following: http://java.net/jira/browse/JAVASERVERFACES-2398 http://java.net/jira/browse/JAVASERVERFACES-2533 I looked at the QA trunk and while there are a number of changes in December, I didn't see anything relevant that matched the dates we think the problem started. So I'm not sure how or when it started but it is a likely a known Mojarra issue that has been fixed in the latest releases.
        Hide
        Deryk Sinotte added a comment -

        After updating to Mojarra 2.1.17 (as per ICE-8866), the problem has gone away. Resolving as fixed.

        Show
        Deryk Sinotte added a comment - After updating to Mojarra 2.1.17 (as per ICE-8866 ), the problem has gone away. Resolving as fixed.

          People

          • Assignee:
            Deryk Sinotte
            Reporter:
            Mircea Toma
          • Votes:
            0 Vote for this issue
            Watchers:
            4 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved: