glassfish
  1. glassfish
  2. GLASSFISH-18060

[JRockit-intermittent] ClassCastException observed in instance logs when running lb tests (com.sun.grizzly.config.ContextRootInfo cannot be cast to org.apache.catalina.Context)

    Details

    • Type: Bug Bug
    • Status: Resolved
    • Priority: Major Major
    • Resolution: Fixed
    • Affects Version/s: 3.1.2_b14
    • Fix Version/s: 3.1.2_b22
    • Component/s: web_container
    • Labels:
      None

      Description

      GF build 14
      Setup: Cluster with 10 instances
      Platform: OEL6 with JRockit
      Has this passed before: OEL + JRockit combination was last used in GF 3.1 where the LB tests did pass and the ClassCastExceptions were not seen.

      When running the HA - LB tests we found that some of the tests failed with the response - "400 Bad Request". All of the tests that failed were found to have one of the instance's containing the below ClassCastException. The exception does not seem to appear on the passed tests (checked on a few of the passed tests). No other information could be obtained from the logs to indicate any other cause for the response. This is still only a guess that the below exception was causing the bad response.

      The exception appears about 10 to 20 seconds after the app is successfully deployed. It appeared only on instance107 (see attached logs from one of the failed tests - 10 instance set up). Now, curiously, mostly of the tests that failed showed successful requests served by instance 102, 103, 104 & 105, and then would throw the bad response when LB was to forward the subsequent request to instance106.

      [#|2011-12-17T02:45:48.500-0800|SEVERE|glassfish3.1.2|org.apache.catalina.connector.CoyoteAdapter|_ThreadID=56;_ThreadName=Thread-2;|PWC3989: An exception or error occurred in the container during the request processing
      java.lang.ClassCastException: com.sun.grizzly.config.ContextRootInfo cannot be cast to org.apache.catalina.Context
      at org.apache.catalina.connector.CoyoteAdapter.postParseRequest(CoyoteAdapter.java:534)
      at org.apache.catalina.connector.CoyoteAdapter.doService(CoyoteAdapter.java:271)
      at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:231)
      at com.sun.enterprise.v3.services.impl.ContainerMapper.service(ContainerMapper.java:174)
      at com.sun.grizzly.http.ProcessorTask.invokeAdapter(ProcessorTask.java:849)
      at com.sun.grizzly.http.ProcessorTask.doProcess(ProcessorTask.java:746)
      at com.sun.grizzly.http.ProcessorTask.process(ProcessorTask.java:1045)
      at com.sun.grizzly.http.DefaultProtocolFilter.execute(DefaultProtocolFilter.java:228)
      at com.sun.grizzly.DefaultProtocolChain.executeProtocolFilter(DefaultProtocolChain.java:137)
      at com.sun.grizzly.DefaultProtocolChain.execute(DefaultProtocolChain.java:104)
      at com.sun.grizzly.DefaultProtocolChain.execute(DefaultProtocolChain.java:90)
      at com.sun.grizzly.http.HttpProtocolChain.execute(HttpProtocolChain.java:79)
      at com.sun.grizzly.ProtocolChainContextTask.doCall(ProtocolChainContextTask.java:54)
      at com.sun.grizzly.SelectionKeyContextTask.call(SelectionKeyContextTask.java:59)
      at com.sun.grizzly.ContextTask.run(ContextTask.java:71)
      at com.sun.grizzly.util.AbstractThreadPool$Worker.doWork(AbstractThreadPool.java:532)
      at com.sun.grizzly.util.AbstractThreadPool$Worker.run(AbstractThreadPool.java:513)
      at java.lang.Thread.run(Thread.java:662)

      #]

      Please send a mail if you like to view logs from other failed tests.

      1. instr.tar.gz
        1.90 MB
        Ryan Lubke

        Issue Links

          Activity

          Hide
          Shing Wai Chan added a comment -

          The corresponding code in CoyoteAdapter is as follows:

           
                 Object context = request.getMappingData().context;
                  if (context instanceof ContextRootInfo) {
                      // this block of code will be invoked when an AJP request is intended
                      // for an Adapter other than the CoyoteAdapter
                      final Adapter toInvoke = ((ContextRootInfo) context).getAdapter();
                      // Ensure the Adapter isn't the ContainerMapper.  It could be there
                      // is only one container/adapter currently active.  If this is the
                      // case, it could cause recursion and blow the stack.
                      if (!"com.sun.enterprise.v3.services.impl.ContainerMapper".equals(toInvoke.getClass().getName())) {
                          toInvoke.service(req, res);
                          toInvoke.afterService(req, res);
                          return false;
                      }    
                  }
          
                  Context ctx = (Context) context;
          

          This is introduced in rev 40454 for fixing http://java.net/jira/browse/GLASSFISH-12458
          ("EJB Webservices not available via mod_jk listener").

          Show
          Shing Wai Chan added a comment - The corresponding code in CoyoteAdapter is as follows: Object context = request.getMappingData().context; if (context instanceof ContextRootInfo) { // this block of code will be invoked when an AJP request is intended // for an Adapter other than the CoyoteAdapter final Adapter toInvoke = ((ContextRootInfo) context).getAdapter(); // Ensure the Adapter isn't the ContainerMapper. It could be there // is only one container/adapter currently active. If this is the // case , it could cause recursion and blow the stack. if (! "com.sun.enterprise.v3.services.impl.ContainerMapper" .equals(toInvoke.getClass().getName())) { toInvoke.service(req, res); toInvoke.afterService(req, res); return false ; } } Context ctx = (Context) context; This is introduced in rev 40454 for fixing http://java.net/jira/browse/GLASSFISH-12458 ("EJB Webservices not available via mod_jk listener").
          Hide
          Ryan Lubke added a comment -
          • What is the impact on the customer of the bug?
            Potential issue with load balancing.

          How likely is it that a customer will see the bug and how serious is the bug?
          Is it a regression? Does it meet other bug fix criteria (security, performance, etc.)?
          Given the test scenario, most likely will be seen.

          • What is the cost/risk of fixing the bug?
            Cost is low. The code in question may be removed now that grizzly provides AJP services. Hack
            is no longer needed.

          How risky is the fix? How much work is the fix? Is the fix complicated?
          Low. Revert the code back to the state before the change was introduced. Not complex - it's a single block.

          • Is there an impact on documentation or message strings?
            No.
          • Which tests should QA (re)run to verify the fix did not destabilize GlassFish?
            The tests that found the issue would be fine.
          • Which is the targeted build of 3.1.2 for this fix?
            17
          Show
          Ryan Lubke added a comment - What is the impact on the customer of the bug? Potential issue with load balancing. How likely is it that a customer will see the bug and how serious is the bug? Is it a regression? Does it meet other bug fix criteria (security, performance, etc.)? Given the test scenario, most likely will be seen. What is the cost/risk of fixing the bug? Cost is low. The code in question may be removed now that grizzly provides AJP services. Hack is no longer needed. How risky is the fix? How much work is the fix? Is the fix complicated? Low. Revert the code back to the state before the change was introduced. Not complex - it's a single block. Is there an impact on documentation or message strings? No. Which tests should QA (re)run to verify the fix did not destabilize GlassFish? The tests that found the issue would be fine. Which is the targeted build of 3.1.2 for this fix? 17
          Hide
          Ryan Lubke added a comment -

          Changes applied (3.1.2: 51860; 4.0: 51862).

          Show
          Ryan Lubke added a comment - Changes applied (3.1.2: 51860; 4.0: 51862).
          Hide
          varunrupela added a comment - - edited

          Issue exists with build 17.
          Tests were run on OEL6 with JRockit.

          The stack trace has one difference - the line of code from which the exception is thrown:

          [#|2012-01-11T09:49:24.039-0800|SEVERE|glassfish3.1.2|org.apache.catalina.connector.CoyoteAdapter|_ThreadID=70;_ThreadName=Thread-2;|PWC3989: An exception or error occurred in the container during the request processing
          java.lang.ClassCastException: com.sun.grizzly.config.ContextRootInfo
          at org.apache.catalina.connector.CoyoteAdapter.postParseRequest(CoyoteAdapter.java:519)
          at org.apache.catalina.connector.CoyoteAdapter.doService(CoyoteAdapter.java:271)
          at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:231)
          at com.sun.enterprise.v3.services.impl.ContainerMapper.service(ContainerMapper.java:174)
          at com.sun.grizzly.http.ProcessorTask.invokeAdapter(ProcessorTask.java:849)
          at com.sun.grizzly.http.ProcessorTask.doProcess(ProcessorTask.java:747)
          at com.sun.grizzly.http.ProcessorTask.process(ProcessorTask.java:1046)
          at com.sun.grizzly.http.DefaultProtocolFilter.execute(DefaultProtocolFilter.java:228)
          at com.sun.grizzly.DefaultProtocolChain.executeProtocolFilter(DefaultProtocolChain.java:137)
          at com.sun.grizzly.DefaultProtocolChain.execute(DefaultProtocolChain.java:105)
          at com.sun.grizzly.DefaultProtocolChain.execute(DefaultProtocolChain.java:91)
          at com.sun.grizzly.http.HttpProtocolChain.execute(HttpProtocolChain.java:79)
          at com.sun.grizzly.ProtocolChainContextTask.doCall(ProtocolChainContextTask.java:56)
          at com.sun.grizzly.SelectionKeyContextTask.call(SelectionKeyContextTask.java:59)
          at com.sun.grizzly.ContextTask.run(ContextTask.java:71)
          at com.sun.grizzly.util.AbstractThreadPool$Worker.doWork(AbstractThreadPool.java:532)
          at com.sun.grizzly.util.AbstractThreadPool$Worker.run(AbstractThreadPool.java:513)
          at java.lang.Thread.run(Thread.java:662)

          #]
          Show
          varunrupela added a comment - - edited Issue exists with build 17. Tests were run on OEL6 with JRockit. The stack trace has one difference - the line of code from which the exception is thrown: [#|2012-01-11T09:49:24.039-0800|SEVERE|glassfish3.1.2|org.apache.catalina.connector.CoyoteAdapter|_ThreadID=70;_ThreadName=Thread-2;|PWC3989: An exception or error occurred in the container during the request processing java.lang.ClassCastException: com.sun.grizzly.config.ContextRootInfo at org.apache.catalina.connector.CoyoteAdapter.postParseRequest(CoyoteAdapter.java:519) at org.apache.catalina.connector.CoyoteAdapter.doService(CoyoteAdapter.java:271) at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:231) at com.sun.enterprise.v3.services.impl.ContainerMapper.service(ContainerMapper.java:174) at com.sun.grizzly.http.ProcessorTask.invokeAdapter(ProcessorTask.java:849) at com.sun.grizzly.http.ProcessorTask.doProcess(ProcessorTask.java:747) at com.sun.grizzly.http.ProcessorTask.process(ProcessorTask.java:1046) at com.sun.grizzly.http.DefaultProtocolFilter.execute(DefaultProtocolFilter.java:228) at com.sun.grizzly.DefaultProtocolChain.executeProtocolFilter(DefaultProtocolChain.java:137) at com.sun.grizzly.DefaultProtocolChain.execute(DefaultProtocolChain.java:105) at com.sun.grizzly.DefaultProtocolChain.execute(DefaultProtocolChain.java:91) at com.sun.grizzly.http.HttpProtocolChain.execute(HttpProtocolChain.java:79) at com.sun.grizzly.ProtocolChainContextTask.doCall(ProtocolChainContextTask.java:56) at com.sun.grizzly.SelectionKeyContextTask.call(SelectionKeyContextTask.java:59) at com.sun.grizzly.ContextTask.run(ContextTask.java:71) at com.sun.grizzly.util.AbstractThreadPool$Worker.doWork(AbstractThreadPool.java:532) at com.sun.grizzly.util.AbstractThreadPool$Worker.run(AbstractThreadPool.java:513) at java.lang.Thread.run(Thread.java:662) #]
          Hide
          Ryan Lubke added a comment -

          Shing-Wai, I removed the code that was added as a workaround for the old ajp listener implementation. It appears that it wasn't responsible for the issue.

          Passing back to you as you're more familiar with the web container.

          Show
          Ryan Lubke added a comment - Shing-Wai, I removed the code that was added as a workaround for the old ajp listener implementation. It appears that it wasn't responsible for the issue. Passing back to you as you're more familiar with the web container.
          Hide
          Ryan Lubke added a comment -

          Is it possible to get the full server log for the instance that is failing? Looking through what was originally attached, the log was truncated (i.e., all activity prior to application deployment isn't present).

          Show
          Ryan Lubke added a comment - Is it possible to get the full server log for the instance that is failing? Looking through what was originally attached, the log was truncated (i.e., all activity prior to application deployment isn't present).
          Hide
          Ryan Lubke added a comment -

          Working though the code now, however, if it is possible to provide a scaled-down reproduction, it would help us nail this down.

          Show
          Ryan Lubke added a comment - Working though the code now, however, if it is possible to provide a scaled-down reproduction, it would help us nail this down.
          Hide
          Ryan Lubke added a comment -

          Instrumented Jars

          Show
          Ryan Lubke added a comment - Instrumented Jars
          Hide
          Ryan Lubke added a comment -

          I've attached instrumented jars to aid debugging in the QE environment. These JARs are specifically for b17. Please install them into the modules directory of the server(s) and run the tests again.

          I'll need the full log of the server that fails the test.

          Show
          Ryan Lubke added a comment - I've attached instrumented jars to aid debugging in the QE environment. These JARs are specifically for b17. Please install them into the modules directory of the server(s) and run the tests again. I'll need the full log of the server that fails the test.
          Hide
          varunrupela added a comment -

          In the attached logs, the ClassCastException appears in instances instance102 & instance109. The logs for those can be seen under 18160-logs-b17/st-cluster

          Show
          varunrupela added a comment - In the attached logs, the ClassCastException appears in instances instance102 & instance109. The logs for those can be seen under 18160-logs-b17/st-cluster
          Hide
          varunrupela added a comment -

          Attached logs obtained from one of the failed test cases.

          Since the issue is intermittent and we haven't been able to identify a fixed set of steps to reproduce the issue yet, we will need to re-run a number of LB tests to be able to reproduce the issue using the instrumented jars.

          Will provide logs obtained while using the instrumented jars after running the tests again.

          Show
          varunrupela added a comment - Attached logs obtained from one of the failed test cases. Since the issue is intermittent and we haven't been able to identify a fixed set of steps to reproduce the issue yet, we will need to re-run a number of LB tests to be able to reproduce the issue using the instrumented jars. Will provide logs obtained while using the instrumented jars after running the tests again.
          Hide
          Ryan Lubke added a comment -

          Yep, understand the difficulties. But if you could reduce the cluster size to say two and still reproduce it, it would be much simpler on this end to deal with.

          Will keep an eye out for the instrumented logs.

          Show
          Ryan Lubke added a comment - Yep, understand the difficulties. But if you could reduce the cluster size to say two and still reproduce it, it would be much simpler on this end to deal with. Will keep an eye out for the instrumented logs.
          Hide
          varunrupela added a comment -

          Attaching logs from a test run that saw the ClassCastException. These logs have been generated from an instrumented build 17.
          Please see the logs for instances: instance102, instance105 or instance107 under

          Ryan: Do we still need logs from a 2 instance cluster ?

          Show
          varunrupela added a comment - Attaching logs from a test run that saw the ClassCastException. These logs have been generated from an instrumented build 17. Please see the logs for instances: instance102, instance105 or instance107 under Ryan: Do we still need logs from a 2 instance cluster ?
          Hide
          varunrupela added a comment -

          Contrary to what was reported in the description of this bug, this exception has now been observed to appear on some of the test that passed. QE needs to further analyze the tests to check if the failed tests have a different or additional cause. Its also possible that the tests that passed did not get affected by the exception due to the nature of the scenarios contained in those tests.

          QE will continue to analyze tests that show this exception.

          Ryan: Could you help explain the effect that this exception may have on new/subsequent requests that land on an affected instance ? Thanks.

          Show
          varunrupela added a comment - Contrary to what was reported in the description of this bug, this exception has now been observed to appear on some of the test that passed. QE needs to further analyze the tests to check if the failed tests have a different or additional cause. Its also possible that the tests that passed did not get affected by the exception due to the nature of the scenarios contained in those tests. QE will continue to analyze tests that show this exception. Ryan: Could you help explain the effect that this exception may have on new/subsequent requests that land on an affected instance ? Thanks.
          Hide
          Ryan Lubke added a comment -

          No need for logs for a two instance cluster. I was more curious if the issue could be resolved in such a scenario. If it was the case, then it would be likely I could repeat on my machine.

          I'll review the logs and follow up with the question regarding the impact of the CCE.

          Show
          Ryan Lubke added a comment - No need for logs for a two instance cluster. I was more curious if the issue could be resolved in such a scenario. If it was the case, then it would be likely I could repeat on my machine. I'll review the logs and follow up with the question regarding the impact of the CCE.
          Hide
          Ryan Lubke added a comment -

          Ok, in the cast of the CCE, the response will be a 200 with no content. So the CCE isn't causing the 400.

          Show
          Ryan Lubke added a comment - Ok, in the cast of the CCE, the response will be a 200 with no content. So the CCE isn't causing the 400.
          Hide
          Ryan Lubke added a comment -

          So looking through the code, there are several cases where a 400 may be send as a response to a request.

          • if the request is HTTP/1.1 but there is no Host header.
          • invalid characters in the host header value
          • if the runtime is unable to parse the request URI
          • if the header is so large that it overflows the buffer (in this case, severe messages are written to the log,
            so this isn't the case here).

          It would be useful to use something like ngrep (or whatever your tool of choice is) to capture the traffic between the
          loadbalancer and the cluster instances so we can see the actual request content that is triggering the issue.

          Show
          Ryan Lubke added a comment - So looking through the code, there are several cases where a 400 may be send as a response to a request. if the request is HTTP/1.1 but there is no Host header. invalid characters in the host header value if the runtime is unable to parse the request URI if the header is so large that it overflows the buffer (in this case, severe messages are written to the log, so this isn't the case here). It would be useful to use something like ngrep (or whatever your tool of choice is) to capture the traffic between the loadbalancer and the cluster instances so we can see the actual request content that is triggering the issue.
          Hide
          Ryan Lubke added a comment -

          Added further instrumentation to web-core.jar. Please run the tests with the new jar.

          Thanks,
          -rl

          Show
          Ryan Lubke added a comment - Added further instrumentation to web-core.jar. Please run the tests with the new jar. Thanks, -rl
          Hide
          varunrupela added a comment -

          Thanks for the details Ryan.

          Working on this now. Will update the bug once we have reproduced the issue with the new jar. Will also try and capture more information regarding the 400 Bad Request and file a separate bug.

          Show
          varunrupela added a comment - Thanks for the details Ryan. Working on this now. Will update the bug once we have reproduced the issue with the new jar. Will also try and capture more information regarding the 400 Bad Request and file a separate bug.
          Hide
          Ryan Lubke added a comment -

          Please use this web-core.jar instead.

          Show
          Ryan Lubke added a comment - Please use this web-core.jar instead.
          Hide
          varunrupela added a comment -

          Attaching logs with the latest instrumented jars.
          Please see st-cluster/instance101/logs/server.log for the ClassCastException.

          Also, updated Summary as the 400 Bad Request does not seem to appear due to the ClassCastException. Will investigate more and file a separate bug for that. The ClassCastException appears in the logs of tests that have passed and 400 Bad Request seems to show up after the setup has been up and running for some hours and then the lb tests are run.

          Show
          varunrupela added a comment - Attaching logs with the latest instrumented jars. Please see st-cluster/instance101/logs/server.log for the ClassCastException. Also, updated Summary as the 400 Bad Request does not seem to appear due to the ClassCastException. Will investigate more and file a separate bug for that. The ClassCastException appears in the logs of tests that have passed and 400 Bad Request seems to show up after the setup has been up and running for some hours and then the lb tests are run.
          Hide
          Ryan Lubke added a comment -

          Ok, narrowed further. Further instrumentation to follow. Thanks for the help!

          Show
          Ryan Lubke added a comment - Ok, narrowed further. Further instrumentation to follow. Thanks for the help!
          Hide
          Ryan Lubke added a comment -

          Ok, there's a total of three jars now. All go in the modules directory.

          For the server that exhibits the issue, I will need the full log (including startup).

          Show
          Ryan Lubke added a comment - Ok, there's a total of three jars now. All go in the modules directory. For the server that exhibits the issue, I will need the full log (including startup).
          Hide
          varunrupela added a comment -

          Attached instance startup logs and those of a test (CCE appears in the logs of instance102 and instance107)

          Show
          varunrupela added a comment - Attached instance startup logs and those of a test (CCE appears in the logs of instance102 and instance107)
          Hide
          varunrupela added a comment -

          The CCE reported in issue 17006 is similar to what is seen in 18060.

          Show
          varunrupela added a comment - The CCE reported in issue 17006 is similar to what is seen in 18060.
          Hide
          Ryan Lubke added a comment -

          Would it be possible to include the log segment where deployment of the test application occurs on instance 102?

          Show
          Ryan Lubke added a comment - Would it be possible to include the log segment where deployment of the test application occurs on instance 102?
          Hide
          varunrupela added a comment -

          Instance102's logs are at test-logs/st-cluster/instance102/logs/server.log

          The client logs in ant.output show the following deploy message at time 1:15:32:
          [testng] Jan 19, 2012 1:15:32 AM com.sun.dft.glassfish.utils.Utility logCommandOutput
          [testng] INFO: Command Executed at agent machine agent1: /space/gf-ha/glassfish3/bin/asadmin --user admin deploy --availabilityenabled=true --force=true --target st-cluster /space/gf-ha/agent-repository/glassfish-samples/clusterjsp.ear
          [testng] Output : Application deployed with name clusterjsp.
          [testng] Command deploy executed successfully.

          Ryan: Can you help provide some details on the information we are trying to gather through the instrumented code ? Would it help if the setup is made available ?

          Show
          varunrupela added a comment - Instance102's logs are at test-logs/st-cluster/instance102/logs/server.log The client logs in ant.output show the following deploy message at time 1:15:32: [testng] Jan 19, 2012 1:15:32 AM com.sun.dft.glassfish.utils.Utility logCommandOutput [testng] INFO: Command Executed at agent machine agent1: /space/gf-ha/glassfish3/bin/asadmin --user admin deploy --availabilityenabled=true --force=true --target st-cluster /space/gf-ha/agent-repository/glassfish-samples/clusterjsp.ear [testng] Output : Application deployed with name clusterjsp. [testng] Command deploy executed successfully. Ryan: Can you help provide some details on the information we are trying to gather through the instrumented code ? Would it help if the setup is made available ?
          Hide
          Ryan Lubke added a comment -

          Trying to trace the creation of particular mapper instances (at which point in time, etc) to try to narrow down why/when the incorrect mapper is used.

          If you can give me access to the setup, that would be useful, as well as details on how to reproduce.

          Show
          Ryan Lubke added a comment - Trying to trace the creation of particular mapper instances (at which point in time, etc) to try to narrow down why/when the incorrect mapper is used. If you can give me access to the setup, that would be useful, as well as details on how to reproduce.
          Hide
          Ryan Lubke added a comment -

          If it would be possible to gain access to the setup over the weekend, that would be great.

          Show
          Ryan Lubke added a comment - If it would be possible to gain access to the setup over the weekend, that would be great.
          Hide
          varunrupela added a comment -

          Hi Ryan:

          I just sent a mail to you with details of the setup and how to reproduce the issue.

          good luck !!

          Show
          varunrupela added a comment - Hi Ryan: I just sent a mail to you with details of the setup and how to reproduce the issue. good luck !!
          Hide
          Ryan Lubke added a comment - - edited

          After reviewing the instrumentation, I've seen instances where two requests to two different connector/mapper instances fail with the ClassCastException, then several seconds later the same request to the same two connector/mapper instances pass.

          Based on this, it seems that the MapperListener which will replace the default host/context (via a call to Mapper.addHost()) with the implementation it expects hasn't been called when the request has arrived (intermittently of course).

          Based on this information, I don't believe this to be an issue with Grizzly.

          Passing back to the Shing-Wai.

          Show
          Ryan Lubke added a comment - - edited After reviewing the instrumentation, I've seen instances where two requests to two different connector/mapper instances fail with the ClassCastException, then several seconds later the same request to the same two connector/mapper instances pass. Based on this, it seems that the MapperListener which will replace the default host/context (via a call to Mapper.addHost()) with the implementation it expects hasn't been called when the request has arrived (intermittently of course). Based on this information, I don't believe this to be an issue with Grizzly. Passing back to the Shing-Wai.
          Hide
          Shing Wai Chan added a comment -

          During the web container start, Connector#start is invoked.
          And mapper.removeContext(defaultHost, ""); is invoked.
          Also, when the default web module is started (as part of WebContainer#postConstruct), StandardContext#registerJMX will be invoked and then MapperListener#registerContext will be invoked.
          In both cases, the ContextRootInfo is cleared in mapping information.

          Note that in com.sun.grizzly.util.http,mapper.Mapper, the internal data structure Host, ContextList, etc are consisted of public elements. And they are used in a multi-thread elements. So, the change in one thread may not be reflected in another thread.

          This may explain the intermittent behavior. And is happening at the beginning.

          Show
          Shing Wai Chan added a comment - During the web container start, Connector#start is invoked. And mapper.removeContext(defaultHost, ""); is invoked. Also, when the default web module is started (as part of WebContainer#postConstruct), StandardContext#registerJMX will be invoked and then MapperListener#registerContext will be invoked. In both cases, the ContextRootInfo is cleared in mapping information. Note that in com.sun.grizzly.util.http,mapper.Mapper, the internal data structure Host, ContextList, etc are consisted of public elements. And they are used in a multi-thread elements. So, the change in one thread may not be reflected in another thread. This may explain the intermittent behavior. And is happening at the beginning.
          Hide
          mzh777 added a comment -

          The ClassCastException was observed with Oracle JDK 1.6.0_30 also.

          Show
          mzh777 added a comment - The ClassCastException was observed with Oracle JDK 1.6.0_30 also.
          Hide
          Shing Wai Chan added a comment -

          The scenario for com.sun.dft.glassfish.lb.RR.http.MultipleFailoverHttpOnly is as follows
          1. delete http-listener-2
          2. deploy a war,run a test
          3. stop the cluster, start the cluster
          4. create http-listener-2
          5. undeploy the war

          In (4), the following two APIs will be called.:
          (a) com.sun.enterprise.v3.services.impl.ContainerMapper.configureMapper
          (b) org.apache.catalina.connector.Connector.start

          The former will set mapper data to ContextRootInfo.
          The latter will reset it to null.
          Under normal circumstance, (a) is called before (b) as follows:
          (see com.sun.dft.glassfish.lb.RR.http.MultipleFailoverHttpOnly instance103 logs)
          for (a)
          at java.lang.Thread.dumpStack(Thread.java:1249)
          at com.sun.grizzly.util.http.mapper.Mapper.addContext(Mapper.java:411)
          at com.sun.grizzly.util.http.mapper.Mapper.addContext(Mapper.java:330)
          at org.glassfish.internal.grizzly.ContextMapper.addContext(ContextMapper.java:119)
          at org.glassfish.internal.grizzly.V3Mapper.addContext(V3Mapper.java:135)
          at com.sun.enterprise.v3.services.impl.ContainerMapper.configureMapper(ContainerMapper.java:144)
          at com.sun.enterprise.v3.services.impl.GrizzlyProxy.configureGrizzly(GrizzlyProxy.java:159)
          at com.sun.enterprise.v3.services.impl.GrizzlyProxy.<init>(GrizzlyProxy.java:121)
          at com.sun.enterprise.v3.services.impl.GrizzlyService.createNetworkProxy(GrizzlyService.java:445)
          at com.sun.enterprise.v3.services.impl.DynamicConfigListener.processNetworkListener(DynamicConfigListener.java:155)
          at com.sun.enterprise.v3.services.impl.DynamicConfigListener.access$100(DynamicConfigListener.java:79)
          at com.sun.enterprise.v3.services.impl.DynamicConfigListener$1.changed(DynamicConfigListener.java:104)
          at org.jvnet.hk2.config.ConfigSupport.sortAndDispatch(ConfigSupport.java:289)
          at com.sun.enterprise.v3.services.impl.DynamicConfigListener.changed(DynamicConfigListener.java:94)
          at org.jvnet.hk2.config.Transactions$ConfigListenerJob.process(Transactions.java:401)
          at org.jvnet.hk2.config.Transactions$ConfigListenerJob.process(Transactions.java:391)
          at org.jvnet.hk2.config.Transactions$ConfigListenerNotifier$1$1.call(Transactions.java:281)
          at org.jvnet.hk2.config.Transactions$ConfigListenerNotifier$1$1.call(Transactions.java:279)
          at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303)
          at java.util.concurrent.FutureTask.run(FutureTask.java:138)
          at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
          at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
          at java.lang.Thread.run(Thread.java:662)

          for (b)
          at java.lang.Thread.dumpStack(Thread.java:1249)
          at org.apache.catalina.connector.Connector.start(Connector.java:1536)
          at com.sun.enterprise.web.connector.coyote.PECoyoteConnector.start(PECoyoteConnector.java:529)
          at com.sun.enterprise.web.WebContainer.addConnector(WebContainer.java:3253)
          at com.sun.enterprise.web.reconfig.WebConfigListener$1.changed(WebConfigListener.java:125)
          at org.jvnet.hk2.config.ConfigSupport.sortAndDispatch(ConfigSupport.java:289)
          at com.sun.enterprise.web.reconfig.WebConfigListener.changed(WebConfigListener.java:114)
          at org.jvnet.hk2.config.Transactions$ConfigListenerJob.process(Transactions.java:401)
          at org.jvnet.hk2.config.Transactions$ConfigListenerJob.process(Transactions.java:391)
          at org.jvnet.hk2.config.Transactions$ConfigListenerNotifier$1$1.call(Transactions.java:281)
          at org.jvnet.hk2.config.Transactions$ConfigListenerNotifier$1$1.call(Transactions.java:279)
          at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303)
          at java.util.concurrent.FutureTask.run(FutureTask.java:138)
          at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
          at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
          at java.lang.Thread.run(Thread.java:662)

          But when there is ClassCastException in the next test, com.sun.dft.glassfish.lb.RR.http.URLRewritingSticky, I notice the (b) is called before (a) as follows:
          (see com.sun.dft.glassfish.lb.RR.http.MultipleFailoverHttpOnly instance104 logs)
          for (b)
          at java.lang.Thread.dumpStack(Thread.java:1249)
          at org.apache.catalina.connector.Connector.start(Connector.java:1536)
          at com.sun.enterprise.web.connector.coyote.PECoyoteConnector.start(PECoyoteConnector.java:529)
          at com.sun.enterprise.web.WebContainer.addConnector(WebContainer.java:3253)
          at com.sun.enterprise.web.reconfig.WebConfigListener$1.changed(WebConfigListener.java:125)
          at org.jvnet.hk2.config.ConfigSupport.sortAndDispatch(ConfigSupport.java:289)
          at com.sun.enterprise.web.reconfig.WebConfigListener.changed(WebConfigListener.java:114)
          at org.jvnet.hk2.config.Transactions$ConfigListenerJob.process(Transactions.java:401)
          at org.jvnet.hk2.config.Transactions$ConfigListenerJob.process(Transactions.java:391)
          at org.jvnet.hk2.config.Transactions$ConfigListenerNotifier$1$1.call(Transactions.java:281)
          at org.jvnet.hk2.config.Transactions$ConfigListenerNotifier$1$1.call(Transactions.java:279)
          at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303)
          at java.util.concurrent.FutureTask.run(FutureTask.java:138)
          at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
          at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
          at java.lang.Thread.run(Thread.java:662)

          for (a)
          at java.lang.Thread.dumpStack(Thread.java:1249)
          at com.sun.grizzly.util.http.mapper.Mapper.addContext(Mapper.java:411)
          at com.sun.grizzly.util.http.mapper.Mapper.addContext(Mapper.java:330)
          at org.glassfish.internal.grizzly.ContextMapper.addContext(ContextMapper.java:119)
          at org.glassfish.internal.grizzly.V3Mapper.addContext(V3Mapper.java:135)
          at com.sun.enterprise.v3.services.impl.ContainerMapper.configureMapper(ContainerMapper.java:144)
          at com.sun.enterprise.v3.services.impl.GrizzlyProxy.configureGrizzly(GrizzlyProxy.java:159)
          at com.sun.enterprise.v3.services.impl.GrizzlyProxy.<init>(GrizzlyProxy.java:121)
          at com.sun.enterprise.v3.services.impl.GrizzlyService.createNetworkProxy(GrizzlyService.java:445)
          at com.sun.enterprise.v3.services.impl.DynamicConfigListener.processNetworkListener(DynamicConfigListener.java:155)
          at com.sun.enterprise.v3.services.impl.DynamicConfigListener.access$100(DynamicConfigListener.java:79)
          at com.sun.enterprise.v3.services.impl.DynamicConfigListener$1.changed(DynamicConfigListener.java:104)
          at org.jvnet.hk2.config.ConfigSupport.sortAndDispatch(ConfigSupport.java:289)
          at com.sun.enterprise.v3.services.impl.DynamicConfigListener.changed(DynamicConfigListener.java:94)
          at org.jvnet.hk2.config.Transactions$ConfigListenerJob.process(Transactions.java:401)
          at org.jvnet.hk2.config.Transactions$ConfigListenerJob.process(Transactions.java:391)
          at org.jvnet.hk2.config.Transactions$ConfigListenerNotifier$1$1.call(Transactions.java:281)
          at org.jvnet.hk2.config.Transactions$ConfigListenerNotifier$1$1.call(Transactions.java:279)
          at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303)
          at java.util.concurrent.FutureTask.run(FutureTask.java:138)
          at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
          at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
          at java.lang.Thread.run(Thread.java:662)

          Show
          Shing Wai Chan added a comment - The scenario for com.sun.dft.glassfish.lb.RR.http.MultipleFailoverHttpOnly is as follows 1. delete http-listener-2 2. deploy a war,run a test 3. stop the cluster, start the cluster 4. create http-listener-2 5. undeploy the war In (4), the following two APIs will be called.: (a) com.sun.enterprise.v3.services.impl.ContainerMapper.configureMapper (b) org.apache.catalina.connector.Connector.start The former will set mapper data to ContextRootInfo. The latter will reset it to null. Under normal circumstance, (a) is called before (b) as follows: (see com.sun.dft.glassfish.lb.RR.http.MultipleFailoverHttpOnly instance103 logs) for (a) at java.lang.Thread.dumpStack(Thread.java:1249) at com.sun.grizzly.util.http.mapper.Mapper.addContext(Mapper.java:411) at com.sun.grizzly.util.http.mapper.Mapper.addContext(Mapper.java:330) at org.glassfish.internal.grizzly.ContextMapper.addContext(ContextMapper.java:119) at org.glassfish.internal.grizzly.V3Mapper.addContext(V3Mapper.java:135) at com.sun.enterprise.v3.services.impl.ContainerMapper.configureMapper(ContainerMapper.java:144) at com.sun.enterprise.v3.services.impl.GrizzlyProxy.configureGrizzly(GrizzlyProxy.java:159) at com.sun.enterprise.v3.services.impl.GrizzlyProxy.<init>(GrizzlyProxy.java:121) at com.sun.enterprise.v3.services.impl.GrizzlyService.createNetworkProxy(GrizzlyService.java:445) at com.sun.enterprise.v3.services.impl.DynamicConfigListener.processNetworkListener(DynamicConfigListener.java:155) at com.sun.enterprise.v3.services.impl.DynamicConfigListener.access$100(DynamicConfigListener.java:79) at com.sun.enterprise.v3.services.impl.DynamicConfigListener$1.changed(DynamicConfigListener.java:104) at org.jvnet.hk2.config.ConfigSupport.sortAndDispatch(ConfigSupport.java:289) at com.sun.enterprise.v3.services.impl.DynamicConfigListener.changed(DynamicConfigListener.java:94) at org.jvnet.hk2.config.Transactions$ConfigListenerJob.process(Transactions.java:401) at org.jvnet.hk2.config.Transactions$ConfigListenerJob.process(Transactions.java:391) at org.jvnet.hk2.config.Transactions$ConfigListenerNotifier$1$1.call(Transactions.java:281) at org.jvnet.hk2.config.Transactions$ConfigListenerNotifier$1$1.call(Transactions.java:279) at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303) at java.util.concurrent.FutureTask.run(FutureTask.java:138) at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908) at java.lang.Thread.run(Thread.java:662) for (b) at java.lang.Thread.dumpStack(Thread.java:1249) at org.apache.catalina.connector.Connector.start(Connector.java:1536) at com.sun.enterprise.web.connector.coyote.PECoyoteConnector.start(PECoyoteConnector.java:529) at com.sun.enterprise.web.WebContainer.addConnector(WebContainer.java:3253) at com.sun.enterprise.web.reconfig.WebConfigListener$1.changed(WebConfigListener.java:125) at org.jvnet.hk2.config.ConfigSupport.sortAndDispatch(ConfigSupport.java:289) at com.sun.enterprise.web.reconfig.WebConfigListener.changed(WebConfigListener.java:114) at org.jvnet.hk2.config.Transactions$ConfigListenerJob.process(Transactions.java:401) at org.jvnet.hk2.config.Transactions$ConfigListenerJob.process(Transactions.java:391) at org.jvnet.hk2.config.Transactions$ConfigListenerNotifier$1$1.call(Transactions.java:281) at org.jvnet.hk2.config.Transactions$ConfigListenerNotifier$1$1.call(Transactions.java:279) at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303) at java.util.concurrent.FutureTask.run(FutureTask.java:138) at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908) at java.lang.Thread.run(Thread.java:662) But when there is ClassCastException in the next test, com.sun.dft.glassfish.lb.RR.http.URLRewritingSticky, I notice the (b) is called before (a) as follows: (see com.sun.dft.glassfish.lb.RR.http.MultipleFailoverHttpOnly instance104 logs) for (b) at java.lang.Thread.dumpStack(Thread.java:1249) at org.apache.catalina.connector.Connector.start(Connector.java:1536) at com.sun.enterprise.web.connector.coyote.PECoyoteConnector.start(PECoyoteConnector.java:529) at com.sun.enterprise.web.WebContainer.addConnector(WebContainer.java:3253) at com.sun.enterprise.web.reconfig.WebConfigListener$1.changed(WebConfigListener.java:125) at org.jvnet.hk2.config.ConfigSupport.sortAndDispatch(ConfigSupport.java:289) at com.sun.enterprise.web.reconfig.WebConfigListener.changed(WebConfigListener.java:114) at org.jvnet.hk2.config.Transactions$ConfigListenerJob.process(Transactions.java:401) at org.jvnet.hk2.config.Transactions$ConfigListenerJob.process(Transactions.java:391) at org.jvnet.hk2.config.Transactions$ConfigListenerNotifier$1$1.call(Transactions.java:281) at org.jvnet.hk2.config.Transactions$ConfigListenerNotifier$1$1.call(Transactions.java:279) at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303) at java.util.concurrent.FutureTask.run(FutureTask.java:138) at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908) at java.lang.Thread.run(Thread.java:662) for (a) at java.lang.Thread.dumpStack(Thread.java:1249) at com.sun.grizzly.util.http.mapper.Mapper.addContext(Mapper.java:411) at com.sun.grizzly.util.http.mapper.Mapper.addContext(Mapper.java:330) at org.glassfish.internal.grizzly.ContextMapper.addContext(ContextMapper.java:119) at org.glassfish.internal.grizzly.V3Mapper.addContext(V3Mapper.java:135) at com.sun.enterprise.v3.services.impl.ContainerMapper.configureMapper(ContainerMapper.java:144) at com.sun.enterprise.v3.services.impl.GrizzlyProxy.configureGrizzly(GrizzlyProxy.java:159) at com.sun.enterprise.v3.services.impl.GrizzlyProxy.<init>(GrizzlyProxy.java:121) at com.sun.enterprise.v3.services.impl.GrizzlyService.createNetworkProxy(GrizzlyService.java:445) at com.sun.enterprise.v3.services.impl.DynamicConfigListener.processNetworkListener(DynamicConfigListener.java:155) at com.sun.enterprise.v3.services.impl.DynamicConfigListener.access$100(DynamicConfigListener.java:79) at com.sun.enterprise.v3.services.impl.DynamicConfigListener$1.changed(DynamicConfigListener.java:104) at org.jvnet.hk2.config.ConfigSupport.sortAndDispatch(ConfigSupport.java:289) at com.sun.enterprise.v3.services.impl.DynamicConfigListener.changed(DynamicConfigListener.java:94) at org.jvnet.hk2.config.Transactions$ConfigListenerJob.process(Transactions.java:401) at org.jvnet.hk2.config.Transactions$ConfigListenerJob.process(Transactions.java:391) at org.jvnet.hk2.config.Transactions$ConfigListenerNotifier$1$1.call(Transactions.java:281) at org.jvnet.hk2.config.Transactions$ConfigListenerNotifier$1$1.call(Transactions.java:279) at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303) at java.util.concurrent.FutureTask.run(FutureTask.java:138) at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908) at java.lang.Thread.run(Thread.java:662)
          Hide
          Shing Wai Chan added a comment -

          debug logs files

          Show
          Shing Wai Chan added a comment - debug logs files
          Hide
          Shing Wai Chan added a comment -

          Since the event behaves differently, we would assign the issue to Mahesh to investigate the hk2 side.

          Show
          Shing Wai Chan added a comment - Since the event behaves differently, we would assign the issue to Mahesh to investigate the hk2 side.
          Hide
          varunrupela added a comment -

          Issue not seen with the patch fix for 18211.

          Show
          varunrupela added a comment - Issue not seen with the patch fix for 18211.
          Hide
          oleksiys added a comment -

          resolved for 3.1.2

          Show
          oleksiys added a comment - resolved for 3.1.2
          Hide
          scatari added a comment -

          Updating with correct build#.

          Show
          scatari added a comment - Updating with correct build#.

            People

            • Assignee:
              oleksiys
              Reporter:
              varunrupela
            • Votes:
              0 Vote for this issue
              Watchers:
              3 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved: