Seam 2.1.1.GA appears to hold reference to stale HTTPRequest

Discussions

Web tier: servlets, JSP, Web frameworks: Seam 2.1.1.GA appears to hold reference to stale HTTPRequest

  1. Hello, I am encountering an issue where Seam appears to be holding a reference to a stale HTTP Request object and using the stale reference to retrieve one or more attributes from the request during the processing of subsequent HTTP requests. This issue is intermittent; it does not occur on every HTTP request, but does occur frequently in a production WebSphere Application Server (WAS) 6.1 environment. The issue originally manifested as a NPE being thrown in WebSphere's SRTServletRequest class (this is IBM's implemenation of the HTTPServletRequest). Given the nature of the issue, we opened a support ticket with IBM, and at IBM's request we turned on low-level tracing in our production environment. The tracing generated voluminous output (around 200 MB per minute), but recorded every single HTTP Request being processed, the thread id for the thread processing the request, the id of the initial HTTPServlet instance for the request and each call that was made to get attributes from the request (including the id of the SRTServletRequest instance used for the specific getAttribute call). IBM then reviewed the trace output and provided the following statement: The error occurs when the application uses the incorrect request object. From trace_09.06.26_21.24.08.log.gz thread 00000048 is using two different request objects: Good: com.ibm.ws.webcontainer.srt.SRTServletRequest@2d382d38 Bad: com.ibm.ws.webcontainer.srt.SRTServletRequest@468c468c The application works with the correct object: e.g.: [6/26/09 21:23:40:978 EDT] 00000048 SRTServletReq 3 getAttributeNames [com.ibm.ws.webcontainer.srt.SRTServletRequest@2d382d38] [6/26/09 21:23:40:978 EDT] 00000048 SRTServletReq 3 getAttribute name --> com.ibm.websphere.servlet.uri_non_decoded [com.ibm.ws.webcontainer.srt.SRTServletRequest@2d382d38] [6/26/09 21:23:40:979 EDT] 00000048 SRTServletReq 3 getSession --> create false [com.ibm.ws.webcontainer.srt.SRTServletRequest@2d382d38] [6/26/09 21:23:40:979 EDT] 00000048 SRTServletReq 3 getWebAppDispatcherContext [com.ibm.ws.webcontainer.srt.SRTServletRequest@2d382d38] [6/26/09 21:23:40:979 EDT] 00000048 SRTServletReq 3 getResponse [com.ibm.ws.webcontainer.srt.SRTServletRequest@2d382d38] but the failure occurs when the bad object is used: [6/26/09 21:23:40:981 EDT] 00000048 SRTServletReq 3 getAttribute name --> org.jboss.seam.core.events [com.ibm.ws.webcontainer.srt.SRTServletRequest@468c468c] [6/26/09 21:23:40:987 EDT] 00000048 ServiceLogger I com.ibm.ws.ffdc.IncidentStreamImpl open FFDC0009I: FFDC opened incident stream file /XXXX/XXXX/XXXXX/XXXXXX/XXX/XXXXX/logs/ffdc/server1_0000 0048_09.06.26_21.23.40_1.txt [6/26/09 21:23:41:145 EDT] 00000048 ServiceLogger I com.ibm.ws.ffdc.IncidentStreamImpl resetIncidentStream FFDC0010I: FFDC closed incident stream file /XXXX/XXXXX/XXXXXXXX/XXX/XXXX/XXXXXX/logs/ffdc/server1_0000 0048_09.06.26_21.23.40_1.txt Each request is assigned a request object and that object must be used only for that request and be the only request object used for that request. Please update your application development team with the above to work on the application code to rectify the problem. Based on this response, I have written a parser to read through several gigabytes of trace logs that were generated and analyze the thread and HTTPRequest instance usage patterns. I have found that this issue does not occur on every HTTP request processed, but that it does occur frequently on all the pages of the site, including remoting and A4J requests. It appears that a given thread from the Web container thread pool may successfully process some requests using the correct request instance, then process one or more requests using a mix of the correct request instance and the stale request instance, and then resume successfully processing requests with the correct instance. It also appears that the stale reference used is a reference to the first request processed by the given thread (tracing was enabled just after a WAS restart). The issue appears to always occur with getAttribute calls for various attributes added to the request by the Seam framework. Following is a short excerpt from my parser that shows an example of the behavior for a single thread: Begin processing Thread 0000003c with HTTPRequest instance 4f804f8 URI for current request is: .../landing.xhtml Done processing Thread 0000003c with HTTPRequest instance 4f804f8 Begin processing Thread 0000003c with HTTPRequest instance 2d382d38 URI for current request is: .../seam/resource/remoting/execute Done processing Thread 0000003c with HTTPRequest instance 2d382d38 Begin processing Thread 0000003c with HTTPRequest instance 1e821e82 URI for current request is: .../seam/resource/remoting/execute Done processing Thread 0000003c with HTTPRequest instance 1e821e82 Begin processing Thread 0000003c with HTTPRequest instance 4f804f8 URI for current request is: .../seam/resource/remoting/execute Done processing Thread 0000003c with HTTPRequest instance 4f804f8 Begin processing Thread 0000003c with HTTPRequest instance 1e821e82 URI for current request is: .../seam/resource/remoting/execute Done processing Thread 0000003c with HTTPRequest instance 1e821e82 Begin processing Thread 0000003c with HTTPRequest instance 4f804f8 URI for current request is: .../seam/resource/remoting/execute Done processing Thread 0000003c with HTTPRequest instance 4f804f8 Begin processing Thread 0000003c with HTTPRequest instance 1ec21ec2 URI for current request is: .../seam/resource/remoting/execute WARNING: Thread 0000003c initialized with HTTPRequest instance 1ec21ec2, but used 4f804f8 for attribute name org.jboss.seam.core.events at line 812160 timestamp: [6/26/09 21:23:53:713 EDT] WARNING: Thread 0000003c initialized with HTTPRequest instance 1ec21ec2, but used 4f804f8 for attribute name org.jboss.seam.core.events at line 812170 timestamp: [6/26/09 21:23:53:716 EDT] Done processing Thread 0000003c with HTTPRequest instance 1ec21ec2 Begin processing Thread 0000003c with HTTPRequest instance 1ec21ec2 URI for current request is: .../landing.xhtml WARNING: Thread 0000003c initialized with HTTPRequest instance 1ec21ec2, but used 4f804f8 for attribute name org.jboss.seam.core.events at line 812315 timestamp: [6/26/09 21:23:54:279 EDT] WARNING: Thread 0000003c initialized with HTTPRequest instance 1ec21ec2, but used 4f804f8 for attribute name org.jboss.seam.core.events at line 812316 timestamp: [6/26/09 21:23:54:281 EDT] WARNING: Thread 0000003c initialized with HTTPRequest instance 1ec21ec2, but used 4f804f8 for attribute name org.jboss.seam.core.manager at line 812317 timestamp: [6/26/09 21:23:54:282 EDT] Done processing Thread 0000003c with HTTPRequest instance 1ec21ec2 Begin processing Thread 0000003c with HTTPRequest instance 1ec21ec2 URI for current request is: .../landing.xhtml WARNING: Thread 0000003c initialized with HTTPRequest instance 1ec21ec2, but used 4f804f8 for attribute name org.jboss.seam.core.events at line 812417 timestamp: [6/26/09 21:24:03:835 EDT] WARNING: Thread 0000003c initialized with HTTPRequest instance 1ec21ec2, but used 4f804f8 for attribute name org.jboss.seam.core.events at line 812426 timestamp: [6/26/09 21:24:03:847 EDT] Done processing Thread 0000003c with HTTPRequest instance 1ec21ec2 Begin processing Thread 0000003c with HTTPRequest instance 1ec21ec2 URI for current request is: .../seam/resource/remoting/execute WARNING: Thread 0000003c initialized with HTTPRequest instance 1ec21ec2, but used 4f804f8 for attribute name org.jboss.seam.core.events at line 812505 timestamp: [6/26/09 21:24:07:306 EDT] WARNING: Thread 0000003c initialized with HTTPRequest instance 1ec21ec2, but used 4f804f8 for attribute name org.jboss.seam.core.events at line 812514 timestamp: [6/26/09 21:24:07:482 EDT] Done processing Thread 0000003c with HTTPRequest instance 1ec21ec2 Please advise as to what could be the source of this issue, or what additional logging or debugging we can perform in order to find a path to the resolution of this issue.
  2. SAME EXACT PROBLEM but with FLEX[ Go to top ]

    We have a Flex remoting application that uses BlazeDS as the messaging transport. When we run our stress tests using TomCat, we can run a hundred thousand web transactions without fail. When we run under WAS 6.1, we first hit a NPE in SRTServletRequest, so we opened the ticket with IBM. They said what they told you: that an older request object was being utilized, and that caused Flex to report that Duplicate Sessions were detected. This is frustrating. we have debugged everything and the only common issue that we share with you is WAS 6.1 and IBM telling us it is not their fault. Funny that it only happens under WAS 6.1. have you made any progress? tomeuchre at yahoo dot com