[Zope] Strange session behavior [SOLVED?]

Chris McDonough chrism@zope.com
24 Jan 2003 09:59:45 -0500


FWIW, it might be helpful to do two things here so we can make sure
we're not finding bugs that may have already been fixed in the latest
revisions of BTress and Transience:

- Use the latest Transience package from
http://cvs.zope.org/Products/Transience/

- Use the latest BTrees package from 
http://cvs.zope.org/ZODB3/BTrees/

(you'll need to recompile the BTrees package by rerunning "wo_pcgi.py"
in the Zope root dir).

If you'd be willing to replace your existing packages with these for
testing purposes and rerun the tests that you've already run, we could
confirm that this is a new bug.

Many thanks!

- C


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 )
> 
> 
> 
> _______________________________________________
> 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