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