ICEfaces
  1. ICEfaces
  2. ICE-7392

EPS 500 error on /eps/block/receive-updated-views

    Details

    • Type: Bug Bug
    • Status: Closed
    • Priority: Major Major
    • Resolution: Fixed
    • Affects Version/s: EE-1.8.2.GA_P03
    • Fix Version/s: EE-1.8.2.GA_P04
    • Component/s: Framework
    • Labels:
      None
    • Environment:
      Weblogic 10.3.5

      Description

      A customer has reported the following issue:

      If I visit a page and sit still long enough without a push update, eventually, a hit to /eps/block/receive-updated-views will result in a 500 error. This generates a JS error as follows:
      "NetworkError: 500 Internal Server Error - http://hutch:7092/eps/block/receive-updated-views"

      The stack trace in the weblogic log looks like:
      ####<Oct 20, 2011 10:14:55 PM GMT> <Error> <HTTP> <hutch.networkcar.com> <GAMMA.portal1> <[ACTIVE] ExecuteThread: '0' for queue: 'weblogic.kernel.Default (self-tuning)'> <<WLS Kernel>> <> <> <1319148895057> <BEA-101017> <[ServletContext@2015307879[app:eps module:eps.war path:/eps spec-version:null]] Root cause of ServletException.
      java.io.IOException: Response has already been committed for: weblogic.servlet.http.RequestResponseKey@850c241b
             at weblogic.servlet.http.AbstractAsyncServlet.notify(AbstractAsyncServlet.java:128)
             at com.icesoft.faces.push.server.arp.internal.WebLogicAdaptingServlet.doRequest(WebLogicAdaptingServlet.java:117)
             at weblogic.servlet.http.AbstractAsyncServlet.service(AbstractAsyncServlet.java:99)
             at javax.servlet.http.HttpServlet.service(HttpServlet.java:820)
             at weblogic.servlet.internal.StubSecurityHelper$ServletServiceAction.run(StubSecurityHelper.java:227)
             at weblogic.servlet.internal.StubSecurityHelper.invokeServlet(StubSecurityHelper.java:125)
             at weblogic.servlet.internal.ServletStubImpl.execute(ServletStubImpl.java:300)
             at weblogic.servlet.internal.ServletStubImpl.execute(ServletStubImpl.java:183)
             at weblogic.servlet.internal.WebAppServletContext$ServletInvocationAction.wrapRun(WebAppServletContext.java:3717)
             at weblogic.servlet.internal.WebAppServletContext$ServletInvocationAction.run(WebAppServletContext.java:3681)
             at weblogic.security.acl.internal.AuthenticatedSubject.doAs(AuthenticatedSubject.java:321)
             at weblogic.security.service.SecurityManager.runAs(SecurityManager.java:120)
             at weblogic.servlet.internal.WebAppServletContext.securedExecute(WebAppServletContext.java:2277)
             at weblogic.servlet.internal.WebAppServletContext.execute(WebAppServletContext.java:2183)
             at weblogic.servlet.internal.ServletRequestImpl.run(ServletRequestImpl.java:1454)
             at weblogic.work.ExecuteThread.execute(ExecuteThread.java:209)
             at weblogic.work.ExecuteThread.run(ExecuteThread.java:178)


      I will upload to the ftp server a war that deploys on 10.3.5 and will reproduce this error consistently. To see the error, visit http://[hostname]/nwf-sample/xhtml/doNothing.seam and wait. A few requests to receive-updated-views will likely complete successfully, but eventually there will be a 500 error.

      In contrast, if you visit http://[hostname]/nwf-sample/push-clock the 500 error doesn't occur (the major difference between the two pages being that on push-clock there is a push update every second).

      The un/pw for the sample app is icefaces/icefaces.

      Please let me know if there's a change that needs to be made to my web.xml, weblogic config, or something else to prevent this error. I'd rather not have my logifles filling up with this stacktrace, but more importantly, I don't want my users' browser to be getting this js error.

        Activity

        Hide
        Jack Van Ooststroom added a comment -

        First explaining what happened in here. When a receive-updated-views comes into WebLogicAdaptingServlet and no update is ready this request gets "parked" by being pushed to the RequestManager. The original approach has to then pull the pending request from the RequestManager in the following two scenarios:

        1. An update became available and a response containing the views to be updated is send to the pending request.
        2. A new receive-updated-views comes in for the same session but the pending request is still in the RequestManager. In this case a Close response is send to the pending request.

        In both cases the pending request was pulled from the RequestManager.

        Apparently we overlooked a third scenario. WebLogic uses a timeout on any pending request. By default this seems to be 40 seconds. Now what happened here is that the 40 second timeout happens before our default heartbeatTimeout value of 50 seconds. As the ping doesn't come in before the WebLogic 40 second timeout to generate a NOOP response, WebLogic invokes the AbstractAsyncServlet.doTimeout(RequestResponseKey) method. Our implementation here was pretty blunt: just send a NOOP response. Unfortunately, the pending request (which now received a NOOP response) was not pulled from the RequestManager. Eventually a new receive-updated-views comes in. The logic in our doRequest(RequestResponseKey) implementation still detects a pending request and tries to send a Close response in order to close the previous connection. This results in the mentioned exception.

        Our implementation logic of the doTimeout(...) method is now corrected to take this into account. As it is a WebLogic driven timeout, I decided to switch from a NOOP to a Close response in this case. At this point we can't be sure the client is still there and or still active. It made more sense to me to send a Close response and clean up the connection.

        However, one additional thing needs to be done to the configuration in order to keep things under ICEfaces control. The heartbeatTimeout should be shorter then the WebLogic timeout. To give an example, if the WebLogic timeout is left to the default, the heartbeatTimeout can be set as follows:

        <context-param>
        <param-name>com.icesoft.faces.heartbeatInterval</param-name>
        <param-value>30000</param-value>
        </context-param>

        Marking this one as FIXED.

        Show
        Jack Van Ooststroom added a comment - First explaining what happened in here. When a receive-updated-views comes into WebLogicAdaptingServlet and no update is ready this request gets "parked" by being pushed to the RequestManager. The original approach has to then pull the pending request from the RequestManager in the following two scenarios: 1. An update became available and a response containing the views to be updated is send to the pending request. 2. A new receive-updated-views comes in for the same session but the pending request is still in the RequestManager. In this case a Close response is send to the pending request. In both cases the pending request was pulled from the RequestManager. Apparently we overlooked a third scenario. WebLogic uses a timeout on any pending request. By default this seems to be 40 seconds. Now what happened here is that the 40 second timeout happens before our default heartbeatTimeout value of 50 seconds. As the ping doesn't come in before the WebLogic 40 second timeout to generate a NOOP response, WebLogic invokes the AbstractAsyncServlet.doTimeout(RequestResponseKey) method. Our implementation here was pretty blunt: just send a NOOP response. Unfortunately, the pending request (which now received a NOOP response) was not pulled from the RequestManager. Eventually a new receive-updated-views comes in. The logic in our doRequest(RequestResponseKey) implementation still detects a pending request and tries to send a Close response in order to close the previous connection. This results in the mentioned exception. Our implementation logic of the doTimeout(...) method is now corrected to take this into account. As it is a WebLogic driven timeout, I decided to switch from a NOOP to a Close response in this case. At this point we can't be sure the client is still there and or still active. It made more sense to me to send a Close response and clean up the connection. However, one additional thing needs to be done to the configuration in order to keep things under ICEfaces control. The heartbeatTimeout should be shorter then the WebLogic timeout. To give an example, if the WebLogic timeout is left to the default, the heartbeatTimeout can be set as follows: <context-param> <param-name>com.icesoft.faces.heartbeatInterval</param-name> <param-value>30000</param-value> </context-param> Marking this one as FIXED.
        Hide
        Tyler Johnson added a comment -

        Feedback from the customer regarding the patch:

        While I'm no longer getting the 500 error, and I'm able to successfully do push updates, post push update my ice:outputLinks are written incorrectly. The context path gets replaced with 'eps'. So, for example, in my xhtml an ice:outputLink looks like:
        <ice:outputLink value="/xhtml/messages/messageHistory.xhtml">

        Upon initial render, the link gets written as:
        http://gamma.networkfleet.com/portal/connect/message-history/

        after a push update, it gets written as:
        http://gamma.networkfleet.com/eps/connect/message-history/

        He has provided a new sample application and in order to recreate the error, visit http://hostname/nwf-sample/push-clock/30. You can replace 30 with any number. The number you use will be the number of seconds between push updates. You'll see a link on the page "Link to myself (30s interval)". Upon initial load, the value of this link will be http://hostname/nwf-sample/push-clock/30 after the first push update, the value will change to http://hostname/eps/push-clock/30

        Show
        Tyler Johnson added a comment - Feedback from the customer regarding the patch: While I'm no longer getting the 500 error, and I'm able to successfully do push updates, post push update my ice:outputLinks are written incorrectly. The context path gets replaced with 'eps'. So, for example, in my xhtml an ice:outputLink looks like: <ice:outputLink value="/xhtml/messages/messageHistory.xhtml"> Upon initial render, the link gets written as: http://gamma.networkfleet.com/portal/connect/message-history/ after a push update, it gets written as: http://gamma.networkfleet.com/eps/connect/message-history/ He has provided a new sample application and in order to recreate the error, visit http://hostname/nwf-sample/push-clock/30 . You can replace 30 with any number. The number you use will be the number of seconds between push updates. You'll see a link on the page "Link to myself (30s interval)". Upon initial load, the value of this link will be http://hostname/nwf-sample/push-clock/30 after the first push update, the value will change to http://hostname/eps/push-clock/30
        Hide
        Jack Van Ooststroom added a comment -

        Closing this one again, as the follow-up issue is addressed in http://jira.icesoft.org/browse/ICE-7991

        Show
        Jack Van Ooststroom added a comment - Closing this one again, as the follow-up issue is addressed in http://jira.icesoft.org/browse/ICE-7991

          People

          • Assignee:
            Jack Van Ooststroom
            Reporter:
            Tyler Johnson
          • Votes:
            1 Vote for this issue
            Watchers:
            1 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved: