Brought to you live: The Bug (RE: Randomness (RE: [Zope-dev] CoreSessionTracking 0.8))

[Bjorn Stabell]

By the way, Chris, you can see the bug in action at our site by going
to:

	http://www.beijingsammies.com:7380/sammies/

The website has not been launched yet, so be careful guys.  Also, don't
try ordering, unless you're in Chaoyang district, Beijing, China. :)
The site may be slow since it's hosted in China.

Try adding some items to the shopping cart, and then clicking on the
navigation menu, browsing the various brochureware pages (only cart_show
is called; no modification is done).  At some point, the shopping cart
should suddenly disappear.  If you continue browsing, it may appear
again.  Actually, if you add items to the shopping cart while it is
disappeared/empty, they'll get accepted and you'll have two different
shopping carts.  Which one you see is random.

The session objects are set up like this:

	/session_id_mgr		(session id manager)
	/sammies/session_mgr	(session data manager)

There are no other session id or data managers.  The session data
manager is using the default internal RAM-based session data container
with no onStart or onEnd methods.

Here's the test run I just did:

- I added a few items to the shopping cart
- Then I clicked on different brochureware pages for about one hundred
clicks (2 minutes? a trial in patience :) I managed to get the error:
- The shopping cart became emptied
- Checking the session data manager, it still showed one item/session
- I added more items to the new, blank session
- After about 30-40 clicks, it changed into the old session again

I notice that this kind of 'change' OFTEN HAPPENS WHEN I CLICK A NEW
LINK BEFORE THE OLD PAGE HAS LOADED COMPLETELY, i.e., I interrupt the
page half-way.  Sometimes I also think that I notice a delay in Zope
(the requests seems to take one second longer) when this kind of switch
happens, but that may be me imagining things.

There's nothing unusual in the STUPID_LOG_FILE when the switch occurs.
I can, however, see that the previous time we ran zope we had the errors
I've attached below (shouldn't make any difference).


Bye,
--=20
Bjorn



[...]
------
2001-05-25T07:41:03 ERROR(200) ZODB Couldn't load state for
'\000\000\000\000\00
0\000)\247'
Traceback (innermost last):
  File /zope/zope-dc-2.3.2/lib/python/ZODB/Connection.py, line 508, in
setstate
AttributeError: 'None' object has no attribute 'load'


------
2001-05-25T07:43:58 INFO(0) ApplicationManager Shutdown requested by
"jey"
------
2001-05-25T07:43:58 ERROR(200) ZODB Couldn't load state for
'\000\000\000\000\00
0\000)\247'
Traceback (innermost last):
  File /zope/zope-dc-2.3.2/lib/python/ZODB/Connection.py, line 508, in
setstate
  File /zope/zope-dc-2.3.2/lib/python/ZODB/FileStorage.py, line 595, in
load
    (Object: /zope/site-cn:7300-sammies/var/Data.fs)
  File /zope/zope-dc-2.3.2/lib/python/ZODB/FileStorage.py, line 572, in
_load
    (Object: /zope/site-cn:7300-sammies/var/Data.fs)
ValueError: I/O operation on closed file


------
2001-05-25T07:43:58 PROBLEM(100) zdaemon zdaemon: Fri May 25 15:43:58
2001: The=20
kid, 16615, died on me.
------
2001-05-25T07:47:23 INFO(0) zdaemon zdaemon: Fri May 25 15:47:23 2001:
Houston,=20
we have forked
------
2001-05-25T07:47:23 INFO(0) zdaemon zdaemon: Fri May 25 15:47:23 2001:
Hi, I jus
t forked off a kid: 18005
------
2001-05-25T07:47:23 INFO(0) zdaemon zdaemon: Fri May 25 15:47:23 2001:
Houston,=20
we have forked
------
2001-05-25T07:47:27 INFO(0) ZServer HTTP server started at Fri May 25
15:47:27 2
001
        Hostname: box.exoweb.net
        Port: 7380
------
2001-05-25T07:47:27 INFO(0) ZServer FTP server started at Fri May 25
15:47:27 20
01
        Hostname: box
        Port: 7321