Re: DeferredSessionStorageHandler race condition?

Thu, 26 Jul 2007 14:41:35 -0700 

Hi Micah,

Do you have another request that your filter is trying to handle where
it makes a call to PageFlowUtils.getCurrentPageFlow()? The output from
your log shows two threads, thread 16 and thread 2. I don't see the
request where thread 2 comes from. Maybe multiple simultaneous
requests for a given session?

I think that the null returned from PageFlowUtils.getCurrentPageFlow()
in your filter happens on a direct call to start.do. I've walked
through the code and believe that a call to either Controller.jpf or
the begin action will save the current page flow in the session before
returning the response to the browser for the redirect to start.do.

When the FlowControllerFactory creates the new page flow controller
instance it calls persistInSession() so it can be stored in the user
session. To avoid some concurrency issues with multiple requests from
the same user the actual storage to the session happens at the end of
the processing of the request in the DeferredSessionStorageHandler (as
you noted).


From your log, the sequence you mentioned really looks like this...


Thread-16:
0) Request from browser to the page flow Controller.jpf (Marked as "Request #1")
1) PageFlowRequestProcessor forwards the request for *.jpf to begin.do
2) New request to begin.do is being handled (Marked as "Request #2")
3) The new Controller instance is created and set to be stored in the session
4) Controller's begin() method is executed
5) begin() forwards to another action with redirect = true
  - The response is committed using response.sendRedirect() with the
URI to the next action
6) PageFlowRequestProcessor returns from handling the begin.do request
- "Request #2" (the forward from Controller.jpf to begin.do)
7) The session is updated so that this Controller is set as the
current page flow
8) PageFlowRequestProcessor returns from handling the Controller.jpf -
"Request #1"
9) The response (as a redirect) is returned to the browser.

Note that there still has not been an actual request to start.do in
the log. However, the log output from thread 2 (note different thread)
shows your request filter begin fired. Again, not sure what this
request is from but I don't believe this is thread 16 and the handling
of the begin.do request.

Expected follow up handling after thread 16 returns to redirect
response to the browser...
10) The browser gets the redirect response and makes another request to start.do
11) Your request filter fires.

An initial direct call to start.do would have the behavior that the
current page flow would not be set in the session, but a call to
either Controller.jpf or begin.do sets the current page flow attribute
in the session before returning the redirect response.

Kind regards,
Carlin

On 7/13/07, Carlin Rogers <[EMAIL PROTECTED]> wrote:

Hi Micah,

Sorry for the delay. I've been out on vacation with very limited
access and won't be back online until late next week. I agree, a
simple case will be best for me to reproduce the issue and either
provide an explanation of the issue or some kind of resolution. When I
return I'll try to create the simple app you described and see if I
can get the same behavior.

Kind regards,
Carlin

On 7/5/07, Micah Koch <[EMAIL PROTECTED]> wrote:
> Thanks for replying Carlin,
>
> I've been trying to reproduce this with a simple test, but haven't been
> able to.  At the simplest level all that is in play is a Controller with
> 2 action methods, begin() and start().  begin() forwards to start() with
> redirect = true in the annotation.  There is a servlet filter that is
> calling the PageFlowUtils.getCurrentPageFlow() method because it needs
> to pull various items from the Controller.  We expect for the requests
> to Controller.jpf/begin.do that getCurrentPageFlow will return null.
> However, it is also happening (sometimes) for the request to start.do.
> It usually is only for the first pass through after I have deployed my
> application.  Thereafter, even if I start a new session, it all seems to
> work normally.
>
> As you saw from the logs, what is happening in the failure case is that
> the servlet filter gets run for start.do request before the
> DeferredSessionStorageHandler applies its changes to the session for the
> Controller.jpf/begin.do request.  The DeferredSessionStorageHandler I
> don't believe is being called as a result of anything the servlet filter
> does, but rather the DeferredSessionStorageHandler is called because the
> Controller.jpf/begin.do request has finished.  But there seems to be
> some kind of timing issue.
>
> I'll continue to see if I can come up with a simple test case that
> reproduces this...but if you have any insight as to what may be
> happening I'd appreciate it.  I looked over the issue you mentioned, but
> it looks a little bit different than what I'm seeing.  In my case all
> the action is within one controller, and the multiple thread part is
> just a function of redirect=true I believe.  Thanks,
> Micah
>
> -----Original Message-----
> From: Carlin Rogers [mailto:[EMAIL PROTECTED]
> Sent: Thursday, June 28, 2007 1:54 PM
> To: Beehive Users
> Subject: Re: DeferredSessionStorageHandler race condition?
>
> Hi Micah,
>
> Thanks for the detail and the log information. I'm not sure I fully
> understand what's happening and am curious about the
> ComponentRequestFilter. Is it a servlet filter? What exactly does that
> do or call? I noticed that when that fires the thread enters into the
> DeferredSessionStorageHandler but am unclear as to how this occurs.
> What is the other request doing in thread #2 and what is the user
> interaction that has the two concurrent threads. Sorry if I'm missing
> this from the original post.
>
> There is a similar and known issue described in BEEHIVE-1100 but the
> issue is that one thread goes to a different page flow. It's not a
> common scenario but may shed some light on what happens here.
>
> https://issues.apache.org/jira/browse/BEEHIVE-1100
>
> Kind regards,
> Carlin
>
> On 6/27/07, Micah Koch <[EMAIL PROTECTED]> wrote:
> > We are having an issue in our application whereby we have a request
> > filter that calls PageFlowUtils.getCurrentPageFlow( HttpServletRequest
>
> > request, ServletContext servletContext ).  Sometimes(but not always)
> > this is returning null even though the filter is running for the
> > request after the begin() method is called on our Controller.  Here's
> > the sequence of events:
> > 1) Controller's begin() method is called
> > 2) begin() forwards to another action with redirect = true
> > 3) request filter fires
> >
> > Now, at the point the request filter fires for the request
> > corresponding to the next action the DeferredSessionStorageHandler may
>
> > not have yet applied its changes so _netui:curPageFlow isn't yet
> > committed to the session and this causes
> PageFlowUtils.getCurrentPageFlow to return null.
> > This usually only happens the first time I try to run the flow.  Even
> > if I close my browser and make sure I get a new session, the following
>
> > attempts all seem to work just fine.  I'm not sure what it is about
> > the first run that seems to make things fail.  Here's the relevant log
> > information:
> > 2007-06-27 14:22:01,000|DEBUG|csm                 |Thread-16
> > |org.apache.beehive.netui.pageflow.PageFlowRequestProcessor|----------
> > |--
> > ------------------- Start Request #1
> -----------------------------------
> > 2007-06-27 14:22:01,078|DEBUG|csm                 |Thread-16
> > |org.apache.beehive.netui.pageflow.DefaultPageFlowEventReporter|beginA
> > |ct
> > ionRequest:
> > Request=org.apache.beehive.netui.pageflow.internal.PageFlowRequestWrap
> > pe [EMAIL PROTECTED],
> > [EMAIL PROTECTED]
> > 2007-06-27 14:22:01,156|DEBUG|csm                 |Thread-16
> > |org.apache.beehive.netui.pageflow.PageFlowRequestProcessor|Got
> > |request
> > for /csm/dispatcher/Controller.jpf, forwarding to /dispatcher/begin.do
> > 2007-06-27 14:22:01,187|DEBUG|csm                 |Thread-16
> > |org.apache.beehive.netui.pageflow.internal.DeferredSessionStorageHand
> > |le
> > r|getAttribute: _netui:nestingStack
> > 2007-06-27 14:22:01,187|DEBUG|csm                 |Thread-16
> > |org.apache.beehive.netui.pageflow.PageFlowRequestProcessor|----------
> > |--
> > ------------------- Start Request #2
> -----------------------------------
> > 2007-06-27 14:22:01,187|DEBUG|csm                 |Thread-16
> > |org.apache.beehive.netui.pageflow.DefaultPageFlowEventReporter|beginA
> > |ct
> > ionRequest:
> > Request=org.apache.beehive.netui.pageflow.internal.PageFlowRequestWrap
> > pe [EMAIL PROTECTED],
> > [EMAIL PROTECTED]
> > 2007-06-27 14:22:01,187|INFO |csm                 |Thread-16
> > |org.apache.beehive.netui.pageflow.PageFlowRequestProcessor|Attempting
> > to instantiate SharedFlowControllers for request
> > /csm/dispatcher/begin.do
> > 2007-06-27 14:22:01,187|DEBUG|csm                 |Thread-16
> > |org.apache.beehive.netui.pageflow.internal.DeferredSessionStorageHand
> > |le
> > r|getAttribute: _netui:sharedFlow:global.Global
> > 2007-06-27 14:22:01,187|DEBUG|csm                 |Thread-16
> > |org.apache.beehive.netui.pageflow.internal.DeferredSessionStorageHand
> > |le
> > r|getAttribute: _netui:sharedFlow:global.Global
> > 2007-06-27 14:22:01,203|INFO |csm                 |Thread-16
> > |org.apache.beehive.netui.pageflow.FlowControllerFactory|No Global.app
> > was found in /csm
> > 2007-06-27 14:22:01,234|DEBUG|csm                 |Thread-16
> > |org.apache.beehive.netui.pageflow.internal.DeferredSessionStorageHand
> > |le
> > r|getAttribute: _netui:sharedFlow:global.Global
> > 2007-06-27 14:22:01,234|DEBUG|csm                 |Thread-16
> > |org.apache.beehive.netui.pageflow.internal.DeferredSessionStorageHand
> > |le
> > r|getAttribute: _netui:curLongLivedModule
> > 2007-06-27 14:22:01,234|DEBUG|csm                 |Thread-16
> > |org.apache.beehive.netui.pageflow.internal.DeferredSessionStorageHand
> > |le
> > r|getAttribute: _netui:curPageFlow
> > 2007-06-27 14:22:01,234|DEBUG|csm                 |Thread-16
> > |org.apache.beehive.netui.pageflow.internal.DeferredSessionStorageHand
> > |le
> > r|getAttribute: _netui:nestingStack
> > 2007-06-27 14:22:01,234|DEBUG|csm                 |Thread-16
> > |org.apache.beehive.netui.pageflow.FlowControllerFactory|Creating
> > PageFlowController of type dispatcher.Controller
> > 2007-06-27 14:22:01,484|DEBUG|csm                 |Thread-16
> > |org.apache.beehive.netui.pageflow.internal.JavaControlUtils|No
> > |control
> > field annotations were found for [EMAIL PROTECTED]
> > 2007-06-27 14:22:01,515|DEBUG|csm                 |Thread-16
> > |org.apache.beehive.netui.pageflow.internal.DeferredSessionStorageHand
> > |le
> > r|getAttribute: _netui:PageFlowControlContainerInstance
> > 2007-06-27 14:22:01,546|DEBUG|csm                 |Thread-16
> > |org.apache.beehive.netui.pageflow.internal.DeferredSessionStorageHand
> > |le
> > r|setAttribute:
> > _netui:PageFlowControlContainerInstance=org.apache.beehive.netui.pagef
> > lo
> > [EMAIL PROTECTED]
> > 2007-06-27 14:22:01,625|DEBUG|csm                 |Thread-16
> > |org.apache.beehive.netui.pageflow.internal.DeferredSessionStorageHand
> > |le
> > r|getAttribute: _netui:PageFlowControlContainerInstance
> > 2007-06-27 14:22:01,625|DEBUG|csm                 |Thread-16
> > |org.apache.beehive.netui.pageflow.DefaultPageFlowEventReporter|flowCo
> > |nt
> > rollerCreated: [EMAIL PROTECTED],
> > Request=org.apache.beehive.netui.pageflow.internal.PageFlowRequestWrap
> > pe [EMAIL PROTECTED],
> > [EMAIL PROTECTED]
> > 2007-06-27 14:22:01,625|DEBUG|csm                 |Thread-16
> > |org.apache.beehive.netui.pageflow.internal.DeferredSessionStorageHand
> > |le
> > r|getAttribute: _netui:curLongLivedModule
> > 2007-06-27 14:22:01,625|DEBUG|csm                 |Thread-16
> > |org.apache.beehive.netui.pageflow.internal.DeferredSessionStorageHand
> > |le
> > r|getAttribute: _netui:curPageFlow
> > 2007-06-27 14:22:01,625|DEBUG|csm                 |Thread-16
> > |org.apache.beehive.netui.pageflow.internal.DeferredSessionStorageHand
> > |le
> > r|getAttribute: _netui:curLongLivedModule
> > 2007-06-27 14:22:01,625|DEBUG|csm                 |Thread-16
> > |org.apache.beehive.netui.pageflow.internal.DeferredSessionStorageHand
> > |le
> > r|getAttribute: _netui:curPageFlow
> > 2007-06-27 14:22:01,625|DEBUG|csm                 |Thread-16
> > |org.apache.beehive.netui.pageflow.internal.DeferredSessionStorageHand
> > |le
> > r|setAttribute: _netui:[EMAIL PROTECTED]
> > 2007-06-27 14:22:01,625|DEBUG|csm                 |Thread-16
> > |org.apache.beehive.netui.pageflow.internal.DeferredSessionStorageHand
> > |le
> > r|removeAttribute: _netui:curLongLivedModule
> > 2007-06-27 14:22:01,625|DEBUG|csm                 |Thread-16
> > |org.apache.beehive.netui.pageflow.internal.DeferredSessionStorageHand
> > |le
> > r|getAttribute: _netui:curLongLivedModule
> > 2007-06-27 14:22:01,625|DEBUG|csm                 |Thread-16
> > |org.apache.beehive.netui.pageflow.internal.DeferredSessionStorageHand
> > |le
> > r|getAttribute: _netui:curPageFlow
> > 2007-06-27 14:22:01,625|DEBUG|csm                 |Thread-16
> > |org.apache.beehive.netui.pageflow.internal.DeferredSessionStorageHand
> > |le
> > r|removeAttribute: _netui:facesBacking
> > 2007-06-27 14:22:01,625|DEBUG|csm                 |Thread-16
> > |org.apache.beehive.netui.pageflow.internal.DeferredSessionStorageHand
> > |le
> > r|getAttribute: _netui:facesBacking
> > 2007-06-27 14:22:01,765|DEBUG|csm                 |Thread-16
> > |org.apache.beehive.netui.pageflow.PageFlowRequestProcessor|Populating
> > bean properties from this request
> > 2007-06-27 14:22:02,046|DEBUG|csm                 |Thread-16
> > |org.apache.beehive.netui.script.common.ImplicitObjectUtil|using form
> > |of
> > type: org.apache.beehive.netui.pageflow.internal.AnyBeanActionForm
> > 2007-06-27 14:22:02,421|DEBUG|csm                 |Thread-16
> > |org.apache.beehive.netui.pageflow.internal.DeferredSessionStorageHand
> > |le
> > r|getAttribute: _netui:PageFlowControlContainerInstance
> > 2007-06-27 14:22:02,421|DEBUG|csm                 |Thread-16
> > |org.apache.beehive.netui.pageflow.DefaultPageFlowEventReporter|action
> > |Ra
> > ised: [EMAIL PROTECTED],
> > ActionMapping=[delegate to
> > ActionConfig[path=/begin,name=baseConfigBean,parameter=com.motive.comm
> > sf
> > low.arch.pageflow.ComponentPageFlowController,scope=request,type=org.a
> > pa che.beehive.netui.pageflow.internal.FlowControllerAction],
> > ActionForm=[AnyBeanActionForm wrapper for
> > [EMAIL PROTECTED],
> > Request=org.apache.beehive.netui.pageflow.internal.PageFlowRequestWrap
> > pe [EMAIL PROTECTED],
> > [EMAIL PROTECTED]
> > 2007-06-27 14:22:02,562|DEBUG|csm                 |Thread-16
> > |org.apache.beehive.netui.pageflow.FlowController|Invoking action
> > |method
> > begin(com.motive.commsflow.arch.component.BaseConfigBean)
> > 2007-06-27 14:22:02,625|DEBUG|csm                 |Thread-16
> > |org.apache.beehive.netui.pageflow.internal.DefaultActionForwardHandle
> > |r|
> > Redirecting to /start.do
> > 2007-06-27 14:22:02,625|DEBUG|csm                 |Thread-16
> > |org.apache.beehive.netui.pageflow.DefaultPageFlowEventReporter|action
> > |Su
> > ccess: [EMAIL PROTECTED],
> > ActionMapping=[delegate to
> > ActionConfig[path=/begin,name=baseConfigBean,parameter=com.motive.comm
> > sf
> > low.arch.pageflow.ComponentPageFlowController,scope=request,type=org.a
> > pa che.beehive.netui.pageflow.internal.FlowControllerAction],
> > ActionForm=[AnyBeanActionForm wrapper for
> > [EMAIL PROTECTED],
> > Request=org.apache.beehive.netui.pageflow.internal.PageFlowRequestWrap
> > pe [EMAIL PROTECTED],
> > [EMAIL PROTECTED],
> > ActionForward=ForwardConfig[name=start,path=/start.do,redirect=true,co
> > nt extRelative=false], TimeTakenMillis=204
> > 2007-06-27 14:22:02,640|DEBUG|csm                 |Thread-16
> > |org.apache.beehive.netui.pageflow.PageFlowRequestProcessor|processFor
> > |wa
> > rdConfig(ForwardConfig[name=start,path=/start.do,redirect=true,context
> > Re
> > lative=false])
> > 2007-06-27 14:22:02,687|DEBUG|csm                 |Thread-16
> > |org.apache.beehive.netui.pageflow.DefaultPageFlowEventReporter|endAct
> > |io
> > nRequest:
> > Request=org.apache.beehive.netui.pageflow.internal.PageFlowRequestWrap
> > pe [EMAIL PROTECTED],
> > [EMAIL PROTECTED],
> > TimeTakenMillis=1500
> > 2007-06-27 14:22:02,687|DEBUG|                    |[ACTIVE]
> > ExecuteThread: '2' for queue: 'weblogic.kernel.Default
> > (self-tuning)'|com.motive.commsflow.arch.pageflow.ComponentRequestFilt
> > er
> > |Entering ComponentRequestFilter...
> > 2007-06-27 14:22:02,687|DEBUG|                    |[ACTIVE]
> > ExecuteThread: '2' for queue: 'weblogic.kernel.Default
> > (self-tuning)'|org.apache.beehive.netui.pageflow.internal.DeferredSess
> > io
> > nStorageHandler|getAttribute: _netui:curLongLivedModule
> > 2007-06-27 14:22:02,687|DEBUG|                    |[ACTIVE]
> > ExecuteThread: '2' for queue: 'weblogic.kernel.Default
> > (self-tuning)'|org.apache.beehive.netui.pageflow.internal.DeferredSess
> > io
> > nStorageHandler|getAttribute: _netui:curPageFlow
> > 2007-06-27 14:22:02,687|DEBUG|                    |[ACTIVE]
> > ExecuteThread: '2' for queue: 'weblogic.kernel.Default
> > (self-tuning)'|com.motive.commsflow.arch.pageflow.ComponentRequestFilt
> > er
> > |componentController = null
> > 2007-06-27 14:22:02,718|DEBUG|csm                 |Thread-16
> > |org.apache.beehive.netui.pageflow.PageFlowRequestProcessor|----------
> > |--
> > -------------------- End Request #2
> ------------------------------------
> > 2007-06-27 14:22:02,718|DEBUG|csm                 |Thread-16
> > |org.apache.beehive.netui.pageflow.internal.DeferredSessionStorageHand
> > |le
> > r|Applying changes for request /csm/dispatcher/Controller.jpf.
> > Identity: 3845217
> > 2007-06-27 14:22:02,765|DEBUG|csm                 |Thread-16
> > |org.apache.beehive.netui.util.internal.ServletUtils|Using session
> > |lock
> > of type: class weblogic.servlet.internal.session.MemorySessionData
> > 2007-06-27 14:22:02,765|DEBUG|csm                 |Thread-16
> > |org.apache.beehive.netui.pageflow.internal.DeferredSessionStorageHand
> > |le
> > r|Removing attribute _netui:facesBacking from the session.
> > 2007-06-27 14:22:02,765|DEBUG|csm                 |Thread-16
> > |org.apache.beehive.netui.pageflow.internal.DeferredSessionStorageHand
> > |le
> > r|Removing attribute _netui:curLongLivedModule from the session.
> > 2007-06-27 14:22:02,765|DEBUG|csm                 |Thread-16
> > |org.apache.beehive.netui.pageflow.internal.DeferredSessionStorageHand
> > |le
> > r|Committing attribute _netui:PageFlowControlContainerInstance to the
> > session.
> > 2007-06-27 14:22:02,765|DEBUG|csm                 |Thread-16
> > |org.apache.beehive.netui.pageflow.internal.DeferredSessionStorageHand
> > |le
> > r|Committing attribute _netui:curPageFlow to the session.
> > 2007-06-27 14:22:02,765|DEBUG|csm                 |Thread-16
> > |org.apache.beehive.netui.pageflow.internal.DeferredSessionStorageHand
> > |le
> > r|Ensure failover for attribute _netui:curPageFlow
> > 2007-06-27 14:22:02,765|DEBUG|csm                 |Thread-16
> > |org.apache.beehive.netui.pageflow.internal.DeferredSessionStorageHand
> > |le
> > r|Completed applying changes for request
> /csm/dispatcher/Controller.jpf.
> > Identity: 3845217
> > 2007-06-27 14:22:02,765|DEBUG|csm                 |Thread-16
> > |org.apache.beehive.netui.pageflow.DefaultPageFlowEventReporter|endAct
> > |io
> > nRequest:
> > Request=org.apache.beehive.netui.pageflow.internal.PageFlowRequestWrap
> > pe [EMAIL PROTECTED],
> > [EMAIL PROTECTED],
> > TimeTakenMillis=1687
> > 2007-06-27 14:22:02,765|DEBUG|csm                 |Thread-16
> > |org.apache.beehive.netui.pageflow.PageFlowRequestProcessor|----------
> > |--
> > -------------------- End Request #1
> > ------------------------------------
> >
> >
> > Should I log a bug, or am I doing something wrong?  I haven't yet
> > tried to create a simple test case.  I'm on WebLogic 9.2 MP1, BTW.  If
>
> > it is a bug, is there any suggested work around?  I'd like/need to
> > keep my redirect = true.  Thanks, Micah
> >
>

Reply via email to