[Zope] Strange session behavior [SOLVED?]
Chris McDonough
chrism@zope.com
24 Jan 2003 09:46:03 -0500
Thanks again for tracking this.
Is there any level of concurrency to these tests? (e.g. are you using
"ab -n 1000 -c 10" or are you using "ab -n 1000"?)
On Fri, 2003-01-24 at 09:34, Andrew Athan wrote:
> I think there are major bugs with OOBtree. I will do some testing.
>
> The ID of interest here is 91303318A0po38A8Exk. Look at the lines
> marked <><><><><><>. First, the bucket of 913...Exk is given as
> 1043388140, then 1043388160 and then later it "miraculously" goes back
> to 104338140. Of course, the object can't be found in the old place and
> we get hammered.
>
> It seems that OOBtree has a bug in which replacing a key in setitem
> sometimes leaves the old key/value in place. Thus, line 740 in
> Transience.py
>
> index[k]=current
>
> Is the culprit. If I replace this with
>
> del index[k]
> index[k]=current
>
> Then the bug becomes harder (impossible?) to reproduce.
>
> Not all the problems are gone though. With this change, Zope's
> sessioning runs correctly for a while. Later, I start to get
> __setitem__ bugs in OOBtree.
>
> A.
>
>
> new or existing!!!!!!!!!!!!!!!!<TransientObjectContainer at
> session_data>
> new_or_existing called with 91303318A0po38A8Exk
> get: called with k=91303318A0po38A8Exk
> bucket of 91303318A0po38A8Exk is 1043388140 <><><><><><><><><><><><>
> _getCurrentBucket: new timeslice (pnow) 1043388160
> _roll: roll loser
> _getCurrentBucket: slices_since (2)<t_slices (3)
> _getCurrentBucket: available_spares 11
> get: current is 1043388160
> get: b was not current, it was 1043388140 <><><><><><><><><><><><>
> new or existing!!!!!!!!!!!!!!!!<TransientObjectContainer at
> session_data>
> new_or_existing called with 91303318A0po38A8Exk
> get: called with k=91303318A0po38A8Exk
> bucket of 91303318A0po38A8Exk is 1043388160 <><><><><><><><><><><><>
> _getCurrentBucket: new timeslice (pnow) 1043388160
> _roll: roll loser
> _getCurrentBucket: slices_since (2)<t_slices (3)
> _getCurrentBucket: available_spares 11
> get: current is 1043388160
> new or existing!!!!!!!!!!!!!!!!<TransientObjectContainer at
> session_data>
> new_or_existing called with 64571139A0pogWqRi2Y
> get: called with k=64571139A0pogWqRi2Y
> bucket of 91303318A0po38A8Exk is 1043388160
> _getCurrentBucket: new timeslice (pnow) 1043388160
> _roll: roll loser
> _getCurrentBucket: slices_since (2)<t_slices (3)
> _getCurrentBucket: available_spares 11
> get: current is 1043388160
> new or existing!!!!!!!!!!!!!!!!<TransientObjectContainer at
> session_data>
> new_or_existing called with 91303318A0po38A8Exk
> get: called with k=91303318A0po38A8Exk
> bucket of 91303318A0po38A8Exk is 1043388140 <><><><><><><><><><><><>
> _getCurrentBucket: new timeslice (pnow) 1043388160
> _roll: roll loser
> _getCurrentBucket: slices_since (2)<t_slices (3)
> _getCurrentBucket: available_spares 11
> get: current is 1043388160
> get: 91303318A0po38A8Exk was not found in index bucket (1043388140)
> ****************************not found!
> _getCurrentBucket: new timeslice (pnow) 1043388160
> _roll: roll loser
> _getCurrentBucket: slices_since (2)<t_slices (3)
> _getCurrentBucket: available_spares 11
> setitem: setting current[91303318A0po38A8Exk]=id: 10433881662107346588,
> token: 9
> 1303318A0po38A8Exk, contents: []
> &&&&&&&&&&&&&&&&&&&&&&&&&&&&&&&&&&&&&&&&&&&010101010101010101010
> new or existing!!!!!!!!!!!!!!!!<TransientObjectContainer at
> session_data>
> new_or_existing called with 64571139A0pogWqRi2Y
> get: called with k=64571139A0pogWqRi2Y
>
>
> -----Original Message-----
> From: zope-admin@zope.org [mailto:zope-admin@zope.org] On Behalf Of
> Andrew Athan
> Sent: Thursday, January 23, 2003 11:21 PM
> To: 'Chris McDonough'
> Cc: zope@zope.org
> Subject: RE: [Zope] Strange session behavior
>
>
>
> Zope is definitely not crashing. The behavior is more apparent when I
> set the limits in the session data manager (time & # of subobjects) to
> 0. Strange, since these are supposed to be special values that mean
> infinity.
>
> I bet this is a problem in OOBtree or in the bucketing mechanism of
> Transience.py
>
> A.
>
>
> -----Original Message-----
> From: zope-admin@zope.org [mailto:zope-admin@zope.org] On Behalf Of
> Chris McDonough
> Sent: Thursday, January 23, 2003 11:05 PM
> To: Andrew Athan
> Cc: zope@zope.org
> Subject: RE: [Zope] Strange session behavior
>
>
> Hi Andrew,
>
> Is it possible that Zope is crashing during the test? Might you try
> pointing the session data manager at a different transient object
> container (one not in the temp folder)?
>
> On Thu, 2003-01-23 at 22:48, Andrew Athan wrote:
> > Stranger and stranger. When the objects disappear, there is no slew
> > of calls to the deleteScript ... it is looking like the session data
> > manager just goes "poof"
> >
> > A.
> >
> > -----Original Message-----
> > From: zope-admin@zope.org [mailto:zope-admin@zope.org] On Behalf Of
> > Andrew Athan
> > Sent: Thursday, January 23, 2003 10:32 PM
> > To: zope@zope.org
> > Subject: RE: [Zope] Strange session behavior
> >
> >
> > Further information:
> >
> > By printing request['_ZopeId'] I am able to see that the session ID is
>
> > being maintained even after the session data disappears (thus, cookies
>
> > are working fine). The problem is probably NOT in the browser ID
> > manager.
> >
> > By monitoring the transient object folder after setting all timeouts
> > to 0 and using "ab -n 1000 http://localhost:8080/debug_test" to hit my
>
> > little debug ZPT I see that the number of objects in the transient
> > folder is periodically reset to 0 through no obvious action of my own.
> >
> > Any clues or known bugs here?
> >
> > Andrew Athan
> >
> > -----Original Message-----
> > From: zope-admin@zope.org [mailto:zope-admin@zope.org] On Behalf Of
> > Andrew Athan
> > Sent: Thursday, January 23, 2003 9:49 PM
> > To: zope@zope.org
> > Subject: [Zope] Strange session behavior
> >
> >
> >
> > Hi, I'm using Zope 2.6.1b1 (but the same behavior is exhibited by
> > 2.6.0) and IE6 on XP. Before I spend a long time debugging this I
> > thought I'd ask the list:
> >
> > Either IE's cookie handling (doubt it, since I tried this with highly
> > permissive privacy settinngs) or Zope's browser id manager, or Zope's
> > session manager or Zope's transient objects folder is misbehaving.
> >
> > Symptom: Session data is periodically and intermittently lost within
> > a period of time much much shorter than the transient object timeout.
> >
> > To test this I use a single IE window reloading the very same
> > "test.html" ZPT that simply checks for the existance of the key 'foo'
> > in REQUEST.SESSION and reports the result (and sets it to 1 always).
> >
> > Preliminary evidence is that the problem is exacerbated by concurrent
> > request handling. I test this using a windows client that utilizes
> > the WinHTTP COM+ object to generate requests running on a separate
> > machine (no chance of IE stepping on itself).
> >
> > Of possible relevance is that external python methods are invoked to
> > fulfill the WinHTTP generated requests.
> >
> > Any initial hints on where to look?
> >
> > Thanks,
> > Andrew Athan
> >
> >
>
>
>
> _______________________________________________
> Zope maillist - Zope@zope.org
> http://lists.zope.org/mailman/listinfo/zope
> ** No cross posts or HTML encoding! **
> (Related lists -
> http://lists.zope.org/mailman/listinfo/zope-announce
> http://lists.zope.org/mailman/listinfo/zope-dev )
>
>
>
> _______________________________________________
> Zope maillist - Zope@zope.org
> http://lists.zope.org/mailman/listinfo/zope
> ** No cross posts or HTML encoding! **
> (Related lists -
> http://lists.zope.org/mailman/listinfo/zope-announce
> http://lists.zope.org/mailman/listinfo/zope-dev )
--
Chris McDonough <chrism@zope.com>
Zope Corporation