[Zope] Strange session behavior [SOLVED?]

Fri, 24 Jan 2003 09:34:07 -0500

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 )