Re: DeferredSessionStorageHandler race condition?

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 <mkochmotive.com> 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:carlin.rogersgmail.com]
> 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.
>
> ht
tps://issues.apache.org/jira/browse/BEEHIVE-1100
>
> Kind regards,
> Carlin
>
> On 6/27/07, Micah Koch <mkochmotive.com> 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.DefaultPageFlowEventRepor
ter|beginA
> > |ct
> > ionRequest:
> >
Request=org.apache.beehive.netui.pageflow.internal.PageFlowR
equestWrap
> > pe r3aac61,
> >
Response=weblogic.servlet.internal.ServletResponseImplb3224
> > 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.DeferredSessionS
torageHand
> > |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.DefaultPageFlowEventRepor
ter|beginA
> > |ct
> > ionRequest:
> >
Request=org.apache.beehive.netui.pageflow.internal.PageFlowR
equestWrap
> > pe r3aac61,
> >
Response=weblogic.servlet.internal.ServletResponseImplb3224
> > 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.DeferredSessionS
torageHand
> > |le
> > r|getAttribute: _netui:sharedFlow:global.Global
> > 2007-06-27 14:22:01,187|DEBUG|csm                
|Thread-16
> >
|org.apache.beehive.netui.pageflow.internal.DeferredSessionS
torageHand
> > |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.DeferredSessionS
torageHand
> > |le
> > r|getAttribute: _netui:sharedFlow:global.Global
> > 2007-06-27 14:22:01,234|DEBUG|csm                
|Thread-16
> >
|org.apache.beehive.netui.pageflow.internal.DeferredSessionS
torageHand
> > |le
> > r|getAttribute: _netui:curLongLivedModule
> > 2007-06-27 14:22:01,234|DEBUG|csm                
|Thread-16
> >
|org.apache.beehive.netui.pageflow.internal.DeferredSessionS
torageHand
> > |le
> > r|getAttribute: _netui:curPageFlow
> > 2007-06-27 14:22:01,234|DEBUG|csm                
|Thread-16
> >
|org.apache.beehive.netui.pageflow.internal.DeferredSessionS
torageHand
> > |le
> > r|getAttribute: _netui:nestingStack
> > 2007-06-27 14:22:01,234|DEBUG|csm                
|Thread-16
> >
|org.apache.beehive.netui.pageflow.FlowControllerFactory|Cre
ating
> > 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
dispatcher.Controller5acb37
> > 2007-06-27 14:22:01,515|DEBUG|csm                
|Thread-16
> >
|org.apache.beehive.netui.pageflow.internal.DeferredSessionS
torageHand
> > |le
> > r|getAttribute:
_netui:PageFlowControlContainerInstance
> > 2007-06-27 14:22:01,546|DEBUG|csm                
|Thread-16
> >
|org.apache.beehive.netui.pageflow.internal.DeferredSessionS
torageHand
> > |le
> > r|setAttribute:
> >
_netui:PageFlowControlContainerInstance=org.apache.beehive.n
etui.pagef
> > lo
> > w.PageFlowControlContainerImplaab045
> > 2007-06-27 14:22:01,625|DEBUG|csm                
|Thread-16
> >
|org.apache.beehive.netui.pageflow.internal.DeferredSessionS
torageHand
> > |le
> > r|getAttribute:
_netui:PageFlowControlContainerInstance
> > 2007-06-27 14:22:01,625|DEBUG|csm                
|Thread-16
> >
|org.apache.beehive.netui.pageflow.DefaultPageFlowEventRepor
ter|flowCo
> > |nt
> > rollerCreated:
FlowController=dispatcher.Controller5acb37,
> >
Request=org.apache.beehive.netui.pageflow.internal.PageFlowR
equestWrap
> > pe r3aac61,
> >
Response=weblogic.servlet.internal.ServletResponseImplb3224
> > 2007-06-27 14:22:01,625|DEBUG|csm                
|Thread-16
> >
|org.apache.beehive.netui.pageflow.internal.DeferredSessionS
torageHand
> > |le
> > r|getAttribute: _netui:curLongLivedModule
> > 2007-06-27 14:22:01,625|DEBUG|csm                
|Thread-16
> >
|org.apache.beehive.netui.pageflow.internal.DeferredSessionS
torageHand
> > |le
> > r|getAttribute: _netui:curPageFlow
> > 2007-06-27 14:22:01,625|DEBUG|csm                
|Thread-16
> >
|org.apache.beehive.netui.pageflow.internal.DeferredSessionS
torageHand
> > |le
> > r|getAttribute: _netui:curLongLivedModule
> > 2007-06-27 14:22:01,625|DEBUG|csm                
|Thread-16
> >
|org.apache.beehive.netui.pageflow.internal.DeferredSessionS
torageHand
> > |le
> > r|getAttribute: _netui:curPageFlow
> > 2007-06-27 14:22:01,625|DEBUG|csm                
|Thread-16
> >
|org.apache.beehive.netui.pageflow.internal.DeferredSessionS
torageHand
> > |le
> > r|setAttribute:
_netui:curPageFlow=dispatcher.Controller5acb37
> > 2007-06-27 14:22:01,625|DEBUG|csm                
|Thread-16
> >
|org.apache.beehive.netui.pageflow.internal.DeferredSessionS
torageHand
> > |le
> > r|removeAttribute: _netui:curLongLivedModule
> > 2007-06-27 14:22:01,625|DEBUG|csm                
|Thread-16
> >
|org.apache.beehive.netui.pageflow.internal.DeferredSessionS
torageHand
> > |le
> > r|getAttribute: _netui:curLongLivedModule
> > 2007-06-27 14:22:01,625|DEBUG|csm                
|Thread-16
> >
|org.apache.beehive.netui.pageflow.internal.DeferredSessionS
torageHand
> > |le
> > r|getAttribute: _netui:curPageFlow
> > 2007-06-27 14:22:01,625|DEBUG|csm                
|Thread-16
> >
|org.apache.beehive.netui.pageflow.internal.DeferredSessionS
torageHand
> > |le
> > r|removeAttribute: _netui:facesBacking
> > 2007-06-27 14:22:01,625|DEBUG|csm                
|Thread-16
> >
|org.apache.beehive.netui.pageflow.internal.DeferredSessionS
torageHand
> > |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|u
sing 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.DeferredSessionS
torageHand
> > |le
> > r|getAttribute:
_netui:PageFlowControlContainerInstance
> > 2007-06-27 14:22:02,421|DEBUG|csm                
|Thread-16
> >
|org.apache.beehive.netui.pageflow.DefaultPageFlowEventRepor
ter|action
> > |Ra
> > ised: FlowController=dispatcher.Controller5acb37,
> > ActionMapping=[delegate to
> >
ActionConfig[path=/begin,name=baseConfigBean,parameter=com.m
otive.comm
> > sf
> >
low.arch.pageflow.ComponentPageFlowController,scope=request,
type=org.a
> > pa
che.beehive.netui.pageflow.internal.FlowControllerAction],
> > ActionForm=[AnyBeanActionForm wrapper for
> >
com.motive.commsflow.arch.component.BaseConfigBean19a9deb],
> >
Request=org.apache.beehive.netui.pageflow.internal.PageFlowR
equestWrap
> > pe r3aac61,
> >
Response=weblogic.servlet.internal.ServletResponseImplb3224
> > 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.DefaultActionFor
wardHandle
> > |r|
> > Redirecting to /start.do
> > 2007-06-27 14:22:02,625|DEBUG|csm                
|Thread-16
> >
|org.apache.beehive.netui.pageflow.DefaultPageFlowEventRepor
ter|action
> > |Su
> > ccess: FlowController=dispatcher.Controller5acb37,
> > ActionMapping=[delegate to
> >
ActionConfig[path=/begin,name=baseConfigBean,parameter=com.m
otive.comm
> > sf
> >
low.arch.pageflow.ComponentPageFlowController,scope=request,
type=org.a
> > pa
che.beehive.netui.pageflow.internal.FlowControllerAction],
> > ActionForm=[AnyBeanActionForm wrapper for
> >
com.motive.commsflow.arch.component.BaseConfigBean19a9deb],
> >
Request=org.apache.beehive.netui.pageflow.internal.PageFlowR
equestWrap
> > pe r3aac61,
> >
Response=weblogic.servlet.internal.ServletResponseImplb3224,
> >
ActionForward=ForwardConfig[name=start,path=/start.do,redire
ct=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=tr
ue,context
> > Re
> > lative=false])
> > 2007-06-27 14:22:02,687|DEBUG|csm                
|Thread-16
> >
|org.apache.beehive.netui.pageflow.DefaultPageFlowEventRepor
ter|endAct
> > |io
> > nRequest:
> >
Request=org.apache.beehive.netui.pageflow.internal.PageFlowR
equestWrap
> > pe r3aac61,
> >
Response=weblogic.servlet.internal.ServletResponseImplb3224,
> > 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.ComponentR
equestFilt
> > 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.De
ferredSess
> > 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.De
ferredSess
> > 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.ComponentR
equestFilt
> > 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.DeferredSessionS
torageHand
> > |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.DeferredSessionS
torageHand
> > |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.DeferredSessionS
torageHand
> > |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.DeferredSessionS
torageHand
> > |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.DeferredSessionS
torageHand
> > |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.DeferredSessionS
torageHand
> > |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.DeferredSessionS
torageHand
> > |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.DefaultPageFlowEventRepor
ter|endAct
> > |io
> > nRequest:
> >
Request=org.apache.beehive.netui.pageflow.internal.PageFlowR
equestWrap
> > pe r3aac61,
> >
Response=weblogic.servlet.internal.ServletResponseImplb3224,
> > 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
> >
>

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 <carlin.rogersgmail.com> 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 <mkochmotive.com> 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:carlin.rogersgmail.com]
> > 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.
> >
> > ht
tps://issues.apache.org/jira/browse/BEEHIVE-1100
> >
> > Kind regards,
> > Carlin
> >
> > On 6/27/07, Micah Koch <mkochmotive.com> 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.DefaultPageFlowEventRepor
ter|beginA
> > > |ct
> > > ionRequest:
> > >
Request=org.apache.beehive.netui.pageflow.internal.PageFlowR
equestWrap
> > > pe r3aac61,
> > >
Response=weblogic.servlet.internal.ServletResponseImplb3224
> > > 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.DeferredSessionS
torageHand
> > > |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.DefaultPageFlowEventRepor
ter|beginA
> > > |ct
> > > ionRequest:
> > >
Request=org.apache.beehive.netui.pageflow.internal.PageFlowR
equestWrap
> > > pe r3aac61,
> > >
Response=weblogic.servlet.internal.ServletResponseImplb3224
> > > 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.DeferredSessionS
torageHand
> > > |le
> > > r|getAttribute:
_netui:sharedFlow:global.Global
> > > 2007-06-27 14:22:01,187|DEBUG|csm            
    |Thread-16
> > >
|org.apache.beehive.netui.pageflow.internal.DeferredSessionS
torageHand
> > > |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.DeferredSessionS
torageHand
> > > |le
> > > r|getAttribute:
_netui:sharedFlow:global.Global
> > > 2007-06-27 14:22:01,234|DEBUG|csm            
    |Thread-16
> > >
|org.apache.beehive.netui.pageflow.internal.DeferredSessionS
torageHand
> > > |le
> > > r|getAttribute: _netui:curLongLivedModule
> > > 2007-06-27 14:22:01,234|DEBUG|csm            
    |Thread-16
> > >
|org.apache.beehive.netui.pageflow.internal.DeferredSessionS
torageHand
> > > |le
> > > r|getAttribute: _netui:curPageFlow
> > > 2007-06-27 14:22:01,234|DEBUG|csm            
    |Thread-16
> > >
|org.apache.beehive.netui.pageflow.internal.DeferredSessionS
torageHand
> > > |le
> > > r|getAttribute: _netui:nestingStack
> > > 2007-06-27 14:22:01,234|DEBUG|csm            
    |Thread-16
> > >
|org.apache.beehive.netui.pageflow.FlowControllerFactory|Cre
ating
> > > 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
dispatcher.Controller5acb37
> > > 2007-06-27 14:22:01,515|DEBUG|csm            
    |Thread-16
> > >
|org.apache.beehive.netui.pageflow.internal.DeferredSessionS
torageHand
> > > |le
> > > r|getAttribute:
_netui:PageFlowControlContainerInstance
> > > 2007-06-27 14:22:01,546|DEBUG|csm            
    |Thread-16
> > >
|org.apache.beehive.netui.pageflow.internal.DeferredSessionS
torageHand
> > > |le
> > > r|setAttribute:
> > >
_netui:PageFlowControlContainerInstance=org.apache.beehive.n
etui.pagef
> > > lo
> > > w.PageFlowControlContainerImplaab045
> > > 2007-06-27 14:22:01,625|DEBUG|csm            
    |Thread-16
> > >
|org.apache.beehive.netui.pageflow.internal.DeferredSessionS
torageHand
> > > |le
> > > r|getAttribute:
_netui:PageFlowControlContainerInstance
> > > 2007-06-27 14:22:01,625|DEBUG|csm            
    |Thread-16
> > >
|org.apache.beehive.netui.pageflow.DefaultPageFlowEventRepor
ter|flowCo
> > > |nt
> > > rollerCreated:
FlowController=dispatcher.Controller5acb37,
> > >
Request=org.apache.beehive.netui.pageflow.internal.PageFlowR
equestWrap
> > > pe r3aac61,
> > >
Response=weblogic.servlet.internal.ServletResponseImplb3224
> > > 2007-06-27 14:22:01,625|DEBUG|csm            
    |Thread-16
> > >
|org.apache.beehive.netui.pageflow.internal.DeferredSessionS
torageHand
> > > |le
> > > r|getAttribute: _netui:curLongLivedModule
> > > 2007-06-27 14:22:01,625|DEBUG|csm            
    |Thread-16
> > >
|org.apache.beehive.netui.pageflow.internal.DeferredSessionS
torageHand
> > > |le
> > > r|getAttribute: _netui:curPageFlow
> > > 2007-06-27 14:22:01,625|DEBUG|csm            
    |Thread-16
> > >
|org.apache.beehive.netui.pageflow.internal.DeferredSessionS
torageHand
> > > |le
> > > r|getAttribute: _netui:curLongLivedModule
> > > 2007-06-27 14:22:01,625|DEBUG|csm            
    |Thread-16
> > >
|org.apache.beehive.netui.pageflow.internal.DeferredSessionS
torageHand
> > > |le
> > > r|getAttribute: _netui:curPageFlow
> > > 2007-06-27 14:22:01,625|DEBUG|csm            
    |Thread-16
> > >
|org.apache.beehive.netui.pageflow.internal.DeferredSessionS
torageHand
> > > |le
> > > r|setAttribute:
_netui:curPageFlow=dispatcher.Controller5acb37
> > > 2007-06-27 14:22:01,625|DEBUG|csm            
    |Thread-16
> > >
|org.apache.beehive.netui.pageflow.internal.DeferredSessionS
torageHand
> > > |le
> > > r|removeAttribute: _netui:curLongLivedModule
> > > 2007-06-27 14:22:01,625|DEBUG|csm            
    |Thread-16
> > >
|org.apache.beehive.netui.pageflow.internal.DeferredSessionS
torageHand
> > > |le
> > > r|getAttribute: _netui:curLongLivedModule
> > > 2007-06-27 14:22:01,625|DEBUG|csm            
    |Thread-16
> > >
|org.apache.beehive.netui.pageflow.internal.DeferredSessionS
torageHand
> > > |le
> > > r|getAttribute: _netui:curPageFlow
> > > 2007-06-27 14:22:01,625|DEBUG|csm            
    |Thread-16
> > >
|org.apache.beehive.netui.pageflow.internal.DeferredSessionS
torageHand
> > > |le
> > > r|removeAttribute: _netui:facesBacking
> > > 2007-06-27 14:22:01,625|DEBUG|csm            
    |Thread-16
> > >
|org.apache.beehive.netui.pageflow.internal.DeferredSessionS
torageHand
> > > |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|u
sing 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.DeferredSessionS
torageHand
> > > |le
> > > r|getAttribute:
_netui:PageFlowControlContainerInstance
> > > 2007-06-27 14:22:02,421|DEBUG|csm            
    |Thread-16
> > >
|org.apache.beehive.netui.pageflow.DefaultPageFlowEventRepor
ter|action
> > > |Ra
> > > ised:
FlowController=dispatcher.Controller5acb37,
> > > ActionMapping=[delegate to
> > >
ActionConfig[path=/begin,name=baseConfigBean,parameter=com.m
otive.comm
> > > sf
> > >
low.arch.pageflow.ComponentPageFlowController,scope=request,
type=org.a
> > > pa
che.beehive.netui.pageflow.internal.FlowControllerAction],
> > > ActionForm=[AnyBeanActionForm wrapper for
> > >
com.motive.commsflow.arch.component.BaseConfigBean19a9deb],
> > >
Request=org.apache.beehive.netui.pageflow.internal.PageFlowR
equestWrap
> > > pe r3aac61,
> > >
Response=weblogic.servlet.internal.ServletResponseImplb3224
> > > 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.DefaultActionFor
wardHandle
> > > |r|
> > > Redirecting to /start.do
> > > 2007-06-27 14:22:02,625|DEBUG|csm            
    |Thread-16
> > >
|org.apache.beehive.netui.pageflow.DefaultPageFlowEventRepor
ter|action
> > > |Su
> > > ccess:
FlowController=dispatcher.Controller5acb37,
> > > ActionMapping=[delegate to
> > >
ActionConfig[path=/begin,name=baseConfigBean,parameter=com.m
otive.comm
> > > sf
> > >
low.arch.pageflow.ComponentPageFlowController,scope=request,
type=org.a
> > > pa
che.beehive.netui.pageflow.internal.FlowControllerAction],
> > > ActionForm=[AnyBeanActionForm wrapper for
> > >
com.motive.commsflow.arch.component.BaseConfigBean19a9deb],
> > >
Request=org.apache.beehive.netui.pageflow.internal.PageFlowR
equestWrap
> > > pe r3aac61,
> > >
Response=weblogic.servlet.internal.ServletResponseImplb3224,
> > >
ActionForward=ForwardConfig[name=start,path=/start.do,redire
ct=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=tr
ue,context
> > > Re
> > > lative=false])
> > > 2007-06-27 14:22:02,687|DEBUG|csm            
    |Thread-16
> > >
|org.apache.beehive.netui.pageflow.DefaultPageFlowEventRepor
ter|endAct
> > > |io
> > > nRequest:
> > >
Request=org.apache.beehive.netui.pageflow.internal.PageFlowR
equestWrap
> > > pe r3aac61,
> > >
Response=weblogic.servlet.internal.ServletResponseImplb3224,
> > > 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.ComponentR
equestFilt
> > > 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.De
ferredSess
> > > 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.De
ferredSess
> > > 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.ComponentR
equestFilt
> > > 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.DeferredSessionS
torageHand
> > > |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.DeferredSessionS
torageHand
> > > |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.DeferredSessionS
torageHand
> > > |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.DeferredSessionS
torageHand
> > > |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.DeferredSessionS
torageHand
> > > |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.DeferredSessionS
torageHand
> > > |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.DeferredSessionS
torageHand
> > > |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.DefaultPageFlowEventRepor
ter|endAct
> > > |io
> > > nRequest:
> > >
Request=org.apache.beehive.netui.pageflow.internal.PageFlowR
equestWrap
> > > pe r3aac61,
> > >
Response=weblogic.servlet.internal.ServletResponseImplb3224,
> > > 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
> > >
> >
>