1 Reply Latest reply on Nov 19, 2013 9:24 AM by jrack

Seam 2.1.1.GA appears to hold reference to stale HTTPRequest instance and uses it for subsequent HTTPRequests

wbrazille Jul 7, 2009 12:10 AM

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:

<Begin Quote of IBM Response>

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.

<End Quote of IBM Response>

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.

1. Re: Seam 2.1.1.GA appears to hold reference to stale HTTPRequest instance and uses it for subsequent HTTPRequests

jrack Nov 19, 2013 9:24 AM (in response to wbrazille)

Hello Wayne,

I just stumbled upon your problem description.
We have very similar problems right now and I'm curious, if you received any help in the past - or how you solved your problem.

Yes I saw that your post is 4 years old, but I did not find any other post in the web, that matches our problem that good.

Our problem occurs on a WebSphere 8.0.0.5 in combination with Seam 2.3.0.Final.

Like in your description a NullPointerException is thrown on the SRTServletRequest. We called IBM support, too, and they confirmed that a class (to be precise: org.jboss.seam.context.BasicContext) tries
to get attributes from an old request not valid anymore.

I analyzed the seam source code and found that within Contexts EventContext and SessionContext are stored in a ThreadLocal variables. Those context objects access the Request indirectly oveer
the SessionMap and RequestMap. It looks like the thread local content is overwritten at some point of time, when the handling of the request is not yet finished.

Thank you in advance for any help.

Best regards
- juergen
Actions