[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