12 Replies Latest reply on Feb 26, 2009 2:06 PM by wolfgangknauf

    'Failed to get the test results' error

    wolfgangknauf

      Hi Stan,

      this fails with my sample at http://www.informatik.fh-wiesbaden.de/~knauf/private/JSFDataTable.war (the sample contains a jboss-jsfunit-core-1.0.0.GA snapshot of 2009-01-05).
      You need JBoss 5.0GA (JDK 1.6 version) and JDK 1.6.

      To reproduce, I started my server, copied the WAR file to the jboss deploy folder, called my test results page (http://localhost:8080/JSFDataTable/ServletTestRunner?suite=de.knauf.jsfunit.test.ValueObjectTest&xsl=cactus-report.xsl), deleted the WAR, waited until jboss showed the undeploy message, and repeated those steps.

      After three or four times, the test results page shows this exception:

      Failed to get the test results at [http://localhost:8080/JSFDataTable/ServletRedirector]
      
      org.apache.cactus.util.ChainedRuntimeException: Failed to get the test results at [http://localhost:8080/JSFDataTable/ServletRedirector]
      at org.apache.cactus.internal.client.connector.http.DefaultHttpClient.doTest_aroundBody0(DefaultHttpClient.java:92)
      at org.apache.cactus.internal.client.connector.http.DefaultHttpClient.doTest_aroundBody1$advice(DefaultHttpClient.java:306)
      at org.apache.cactus.internal.client.connector.http.DefaultHttpClient.doTest(DefaultHttpClient.java)
      at org.apache.cactus.internal.client.connector.http.HttpProtocolHandler.runWebTest(HttpProtocolHandler.java:159)
      at org.apache.cactus.internal.client.connector.http.HttpProtocolHandler.runTest_aroundBody0(HttpProtocolHandler.java:80)
      at org.apache.cactus.internal.client.connector.http.HttpProtocolHandler.runTest_aroundBody1$advice(HttpProtocolHandler.java:306)
      at org.apache.cactus.internal.client.connector.http.HttpProtocolHandler.runTest(HttpProtocolHandler.java)
      at org.apache.cactus.internal.client.ClientTestCaseCaller.runTest(ClientTestCaseCaller.java:144)
      at org.apache.cactus.internal.AbstractCactusTestCase.runBareClient(AbstractCactusTestCase.java:215)
      at org.apache.cactus.internal.AbstractCactusTestCase.runBare(AbstractCactusTestCase.java:133)
      at org.apache.cactus.server.runner.ServletTestRunner.run(ServletTestRunner.java:308)
      at org.apache.cactus.server.runner.ServletTestRunner.doGet_aroundBody0(ServletTestRunner.java:186)
      at org.apache.cactus.server.runner.ServletTestRunner.doGet_aroundBody1$advice(ServletTestRunner.java:224)
      at org.apache.cactus.server.runner.ServletTestRunner.doGet(ServletTestRunner.java)
      at javax.servlet.http.HttpServlet.service(HttpServlet.java:690)
      at javax.servlet.http.HttpServlet.service(HttpServlet.java:803)
      at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290)
      at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
      at org.jboss.jsfunit.framework.JSFUnitFilter.doFilter(JSFUnitFilter.java:116)
      at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
      at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
      at org.jboss.web.tomcat.filters.ReplyHeaderFilter.doFilter(ReplyHeaderFilter.java:96)
      at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
      at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
      at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:235)
      at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:191)
      at org.jboss.web.tomcat.security.SecurityAssociationValve.invoke(SecurityAssociationValve.java:190)
      at org.jboss.web.tomcat.security.JaccContextValve.invoke(JaccContextValve.java:92)
      at org.jboss.web.tomcat.security.SecurityContextEstablishmentValve.process(SecurityContextEstablishmentValve.java:126)
      at org.jboss.web.tomcat.security.SecurityContextEstablishmentValve.invoke(SecurityContextEstablishmentValve.java:70)
      at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:127)
      at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102)
      at org.jboss.web.tomcat.service.jca.CachedConnectionValve.invoke(CachedConnectionValve.java:158)
      at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109)
      at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:330)
      at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:828)
      at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:601)
      at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:447)
      at java.lang.Thread.run(Unknown Source)
      org.apache.cactus.internal.client.ParsingException: Not a valid response [500 Internal Server Error]
      at org.apache.cactus.internal.client.connector.http.DefaultHttpClient.callGetResult(DefaultHttpClient.java:211)
      at org.apache.cactus.internal.client.connector.http.DefaultHttpClient.doTest_aroundBody0(DefaultHttpClient.java:87)
      at org.apache.cactus.internal.client.connector.http.DefaultHttpClient.doTest_aroundBody1$advice(DefaultHttpClient.java:306)
      at org.apache.cactus.internal.client.connector.http.DefaultHttpClient.doTest(DefaultHttpClient.java)
      at org.apache.cactus.internal.client.connector.http.HttpProtocolHandler.runWebTest(HttpProtocolHandler.java:159)
      at org.apache.cactus.internal.client.connector.http.HttpProtocolHandler.runTest_aroundBody0(HttpProtocolHandler.java:80)
      at org.apache.cactus.internal.client.connector.http.HttpProtocolHandler.runTest_aroundBody1$advice(HttpProtocolHandler.java:306)
      at org.apache.cactus.internal.client.connector.http.HttpProtocolHandler.runTest(HttpProtocolHandler.java)
      at org.apache.cactus.internal.client.ClientTestCaseCaller.runTest(ClientTestCaseCaller.java:144)
      at org.apache.cactus.internal.AbstractCactusTestCase.runBareClient(AbstractCactusTestCase.java:215)
      at org.apache.cactus.internal.AbstractCactusTestCase.runBare(AbstractCactusTestCase.java:133)
      at org.apache.cactus.server.runner.ServletTestRunner.run(ServletTestRunner.java:308)
      at org.apache.cactus.server.runner.ServletTestRunner.doGet_aroundBody0(ServletTestRunner.java:186)
      at org.apache.cactus.server.runner.ServletTestRunner.doGet_aroundBody1$advice(ServletTestRunner.java:224)
      at org.apache.cactus.server.runner.ServletTestRunner.doGet(ServletTestRunner.java)
      at javax.servlet.http.HttpServlet.service(HttpServlet.java:690)
      at javax.servlet.http.HttpServlet.service(HttpServlet.java:803)
      at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290)
      at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
      at org.jboss.jsfunit.framework.JSFUnitFilter.doFilter(JSFUnitFilter.java:116)
      at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
      at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
      at org.jboss.web.tomcat.filters.ReplyHeaderFilter.doFilter(ReplyHeaderFilter.java:96)
      at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
      at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
      at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:235)
      at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:191)
      at org.jboss.web.tomcat.security.SecurityAssociationValve.invoke(SecurityAssociationValve.java:190)
      at org.jboss.web.tomcat.security.JaccContextValve.invoke(JaccContextValve.java:92)
      at org.jboss.web.tomcat.security.SecurityContextEstablishmentValve.process(SecurityContextEstablishmentValve.java:126)
      at org.jboss.web.tomcat.security.SecurityContextEstablishmentValve.invoke(SecurityContextEstablishmentValve.java:70)
      at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:127)
      at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102)
      at org.jboss.web.tomcat.service.jca.CachedConnectionValve.invoke(CachedConnectionValve.java:158)
      at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109)
      at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:330)
      at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:828)
      at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:601)
      at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:447)
      at java.lang.Thread.run(Unknown Source)


      The server console contains this (first line is output of my test):

      21:14:04,625 ERROR [STDERR] suite
      21:14:04,734 ERROR [[ServletRedirector]] Servlet.service() for servlet ServletRedirector threw exception
      java.lang.IllegalStateException
       at com.sun.faces.context.FacesContextImpl.assertNotReleased(FacesContextImpl.java:395)
       at com.sun.faces.context.FacesContextImpl.getViewRoot(FacesContextImpl.java:294)
       at org.jboss.jsfunit.context.JSFUnitFacesContext.getViewRoot(JSFUnitFacesContext.java:199)
       at org.jboss.jsfunit.context.JSFUnitFacesContext.viewHasChildren(JSFUnitFacesContext.java:285)
       at org.jboss.jsfunit.context.JSFUnitFacesContext.release(JSFUnitFacesContext.java:215)
       at org.jboss.jsfunit.context.JSFUnitFacesContext.cleanUpOldFacesContext(JSFUnitFacesContext.java:332)
       at org.jboss.jsfunit.framework.JSFUnitFilter.doFilter(JSFUnitFilter.java:99)
       at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
       at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
       at org.jboss.web.tomcat.filters.ReplyHeaderFilter.doFilter(ReplyHeaderFilter.java:96)
       at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
       at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
       at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:235)
       at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:191)
       at org.jboss.web.tomcat.security.SecurityAssociationValve.invoke(SecurityAssociationValve.java:190)
       at org.jboss.web.tomcat.security.JaccContextValve.invoke(JaccContextValve.java:92)
       at org.jboss.web.tomcat.security.SecurityContextEstablishmentValve.process(SecurityContextEstablishmentValve.java:126)
       at org.jboss.web.tomcat.security.SecurityContextEstablishmentValve.invoke(SecurityContextEstablishmentValve.java:70)
       at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:127)
       at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102)
       at org.jboss.web.tomcat.service.jca.CachedConnectionValve.invoke(CachedConnectionValve.java:158)
       at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109)
       at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:330)
       at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:828)
       at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:601)
       at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:447)
       at java.lang.Thread.run(Unknown Source)
      21:14:04,750 ERROR [[ServletRedirector]] Servlet.service() for servlet ServletRedirector threw exception
      java.lang.IllegalStateException
       at com.sun.faces.context.FacesContextImpl.assertNotReleased(FacesContextImpl.java:395)
       at com.sun.faces.context.FacesContextImpl.getViewRoot(FacesContextImpl.java:294)
       at org.jboss.jsfunit.context.JSFUnitFacesContext.getViewRoot(JSFUnitFacesContext.java:199)
       at org.jboss.jsfunit.context.JSFUnitFacesContext.viewHasChildren(JSFUnitFacesContext.java:285)
       at org.jboss.jsfunit.context.JSFUnitFacesContext.release(JSFUnitFacesContext.java:215)
       at org.jboss.jsfunit.context.JSFUnitFacesContext.cleanUpOldFacesContext(JSFUnitFacesContext.java:332)
       at org.jboss.jsfunit.framework.JSFUnitFilter.doFilter(JSFUnitFilter.java:99)
       at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
       at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
       at org.jboss.web.tomcat.filters.ReplyHeaderFilter.doFilter(ReplyHeaderFilter.java:96)
       at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
       at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
       at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:235)
       at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:191)
       at org.jboss.web.tomcat.security.SecurityAssociationValve.invoke(SecurityAssociationValve.java:190)
       at org.jboss.web.tomcat.security.JaccContextValve.invoke(JaccContextValve.java:92)
       at org.jboss.web.tomcat.security.SecurityContextEstablishmentValve.process(SecurityContextEstablishmentValve.java:126)
       at org.jboss.web.tomcat.security.SecurityContextEstablishmentValve.invoke(SecurityContextEstablishmentValve.java:70)
       at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:127)
       at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102)
       at org.jboss.web.tomcat.service.jca.CachedConnectionValve.invoke(CachedConnectionValve.java:158)
       at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109)
       at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:330)
       at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:828)
       at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:601)
       at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:447)
       at java.lang.Thread.run(Unknown Source)


      I need to restart my server after this.

      Best regards

      Wolfgang

        • 1. Re: 'Failed to get the test results' error
          ssilvert

          I think this has to be either a JDK bug or a JBoss AS bug. Look at the code for JSFUnitFacesContext.cleanUpOldFacesContext:

          322 public static void cleanUpOldFacesContext()
          323 {
          324 FacesContext facesContext = FacesContext.getCurrentInstance();
          325 if (facesContext == null) return;
          326
          327 if (facesContext instanceof JSFUnitFacesContext)
          328 {
          329 JSFUnitFacesContext ctx = (JSFUnitFacesContext)facesContext;
          330 ctx.cleanUp();
          331 } else {
          332 facesContext.release();
          333 }
          334 }

          Your stack trace looks like this:
          java.lang.IllegalStateException
           at com.sun.faces.context.FacesContextImpl.assertNotReleased(FacesContextImpl.java:395)
           at com.sun.faces.context.FacesContextImpl.getViewRoot(FacesContextImpl.java:294)
           at org.jboss.jsfunit.context.JSFUnitFacesContext.getViewRoot(JSFUnitFacesContext.java:199)
           at org.jboss.jsfunit.context.JSFUnitFacesContext.viewHasChildren(JSFUnitFacesContext.java:285)
           at org.jboss.jsfunit.context.JSFUnitFacesContext.release(JSFUnitFacesContext.java:215)
           at org.jboss.jsfunit.context.JSFUnitFacesContext.cleanUpOldFacesContext(JSFUnitFacesContext.java:33
          2)
           at org.jboss.jsfunit.framework.JSFUnitFilter.doFilter(JSFUnitFilter.java:99)


          Correct me if I'm wrong here, but if you get to line 332 then you can't possibly call JSFUnitFacesContext.release().

          The wrinkle here is that FacesContext.getCurrentInstance() returns the value of a thread-local variable. But once I have a reference to the variable it should not change. That makes me think it is a JDK bug, unless there is something unusual about ThreadLocal references.

          Any ideas?

          Stan

          • 2. Re: 'Failed to get the test results' error
            wolfgangknauf

            Hi Stan,

            sorry, but I don't have enough insight in JBoss or JSF to be of any help :-(.
            Is the old FacesContext not released when the app is undeployed, and somehow the next request hits the old one?
            My only idea: You could add some logging to JSFUnitFacesContext to see what is called when.

            Wolfgang

            • 3. Re: 'Failed to get the test results' error
              ssilvert

              My question is really just a plain java question. I don't see how you can possibly get that stack trace from that code - unless the JVM is broken, or I'm not reading things right.

              Have you tried it with JDK 1.5?

              Stan

              • 4. Re: 'Failed to get the test results' error
                wolfgangknauf

                Hi Stan,

                I tried it with JDK 1.5.0_12 and the Java5 JBoss 5.0GA.
                Same errors. I used my "nested data table" sample, build with Java 1.5. New version is here (still using your jsfunit jars from yesterday):
                http://www.informatik.fh-wiesbaden.de/~knauf/private/jsfdatatable_15_2009-01-15/

                I also uploaded four snippets of "server.log". All result in the same unit test result. Server.log shows two times the "IllegalStateException", the third and fourth error are different. Strange indeed.

                One thing I noticed: directly after calling the test, there seems to be a timeframe of some seconds where the WAR file is locked (my redeploy batch cannot delete it).
                Some timing issue because of too fast app calling after redeployment? I always waited until jboss showed the "undeployed"/"deployed" messages + some seconds.

                The Java 1.6 errors from my original post were created by a JBoss started by eclipse, but deployment was done as hot deploy in the "deploy" folder, no JSR88 magic (though it happens with JSR88, too).

                Hope you find this helpful. Unfortunately, testing with different java/jboss versions is very time consuming.

                Best regards

                Wolfgang

                • 5. Re: 'Failed to get the test results' error
                  wolfgangknauf

                  Hi Stan,

                  any progress on that?

                  Thanks

                  Wolfgang

                  • 6. Re: 'Failed to get the test results' error
                    ssilvert

                    Hi Wolfgang,

                    I pretty stumped on this one. But I'll take a deeper look after I look at freemarket's problem.

                    Stan

                    • 7. Re: 'Failed to get the test results' error
                      ssilvert

                      I've got a "permanent" workaround for you. I'm pretty sure this is a JBoss/Tomcat problem, but I don't know when/if we can do anything about it.

                      Here is what I think is happening:
                      You are doing a redeploy of the WAR at a time when Tomcat still has an open socket to your browser or to JSFUnit. That socket has an associated thread with ThreadLocal variables. Those ThreadLocals don't get cleaned up properly after redeploy. You establish a new connection with old ThreadLocals, which causes some strange errors.

                      I've found that if you set connectionTimeout to a lower value then the problem goes away. Go to deploy/jbossweb.sar/server.xml. You'll see:

                      <!-- A HTTP/1.1 Connector on port 8080 -->
                       <Connector protocol="HTTP/1.1" port="8080" address="${jboss.bind.address}"
                       connectionTimeout="20000" redirectPort="8443" maxThreads="40" />


                      Change connectionTimeout from 20 seconds to maybe 1 or 2 seconds:
                      <!-- A HTTP/1.1 Connector on port 8080 -->
                       <Connector protocol="HTTP/1.1" port="8080" address="${jboss.bind.address}"
                       connectionTimeout="1000" redirectPort="8443" maxThreads="40" />


                      That should take care of the problem. I think that it also might improve test performance for large test suites. I'm looking into that now.

                      Stan

                      • 8. Re: 'Failed to get the test results' error
                        ssilvert

                         

                        "stan.silvert@jboss.com" wrote:
                        I think that it also might improve test performance for large test suites. I'm looking into that now.

                        Stan


                        Looks like 3% - 6% improvement for the RichFaces demo. Not the big boost I was hoping for.

                        Stan

                        • 9. Re: 'Failed to get the test results' error
                          wolfgangknauf

                          Hi Stan,

                          I can confirm that the problem is gone after changing the config.
                          Are there side effects of this change?

                          Is this a JBoss or tomcat bug or just something one has to accept?

                          Thanks

                          Wolfgang

                          • 10. Re: 'Failed to get the test results' error
                            ssilvert

                            It's certainly not a config that you usually want to go with in production, but it's perfect for JSFUnit where you have sessions that start, rapidly submit a few requests, and then stop. There is no need for a 20 second connection timeout.

                            I'd call it a bug, but I'm not sure who's fault it is. Usually, hot deploy bugs boil down to limitations of the JVM. But that's not to say that there isn't somewhere we could improve. I just don't know enough about this particular case to say for sure.

                            Glad the workaround is taking care of the problem for now. I'll make sure this is documented on the wiki.

                            Stan

                            • 11. Re: 'Failed to get the test results' error
                              wolfgangknauf

                              Yesterday, on a slower machine, the issue did not come up (deploy took longer, about 20 seconds). Seems to be one of the very rare moments where low-end-computers are the better choice ;-)

                              Wolfgang

                              • 12. Re: 'Failed to get the test results' error
                                wolfgangknauf

                                With JBoss 5.0.1GA, I could not reproduce the problem.

                                Hopefully something was fixed/changed.

                                Wolfgang