Hi Chris, On Fri, 05 Mar 2004 13:08:01 -0500, Chris McDonough <chrism@plope.com> wrote:

...

I am monitoring site now, and will tell you about the results. OK, many thanks!

Running For: 3 days 4 hours 28 min 29 sec. I have enabled 400 error_log ex exceptions to keep, and during 3 days I got 2 errors on the site: Time Username (User Id) Exception 16:35:01 Anonymous User (None) KeyError: 1078763620 21:59:05 Anonymous User (None) KeyError: 1078696720 But it seems I forget to install new Transience module to the new Zope instance. Should I? -- Alex V. Koval http://www.halogen-dg.com http://www.zwarehouse.org

On 10/03/2004, at 6:29 AM, Chris McDonough wrote:

On Tue, 2004-03-09 at 06:36, Alex V. Koval wrote:

...

I have enabled 400 error_log ex exceptions to keep, and during 3 days I got 2 errors on the site:

Time Username (User Id) Exception 16:35:01 Anonymous User (None) KeyError: 1078763620 21:59:05 Anonymous User (None) KeyError: 1078696720

I have been trying on and off to recreate this error via brute force loading of the simplest possible site that uses sessions. I failed to see this particular KeyError *until* I tried reading a session variable from standard_error_message. Now I can recreate these quite frequently. My *guess* is that this error happens when a ZODB conflict error is thrown from Transience while rendering standard_error_message. I need to do some more testing and probably worth detailing just how I'm doing the tests. Currently using Zope 2.7.0, Python 2.3.3. Yet to try with the Transience branch. Or use FileStorage. Just happy to have actually provoked this error in some kind of test arena :-) Michael

michael wrote at 2004-3-10 15:22 +1300:

... I have been trying on and off to recreate this error via brute force loading of the simplest possible site that uses sessions. I failed to see this particular KeyError *until* I tried reading a session variable from standard_error_message. Now I can recreate these quite frequently.

This is a well known problem in Zope, lengthy discussed but apparently still not yet fixed... The problem is that error handling starts after the main transaction has been aborted. Aborting or committing a transaction implicitely starts a new transaction. If error handling causes objects to be registered in the transaction (because it writes some objects and this can happen for session variables even when they are only read), this transaction is tainted. As the transaction is not aborted after error handling, the transaction and the modified cache are spilled (independently!) into a later request. As the connection/cache may later end up in a different thread, objects can be invalidated asynchronously. This is disastrous. Zope *MUST* abort (or commit) the transaction after error handling!!! -- Dieter

On 11/03/2004, at 11:48 AM, Chris McDonough wrote:

On Wed, 2004-03-10 at 15:20, Dieter Maurer wrote:

...

michael wrote at 2004-3-10 15:22 +1300:

...

... I have been trying on and off to recreate this error via brute force loading of the simplest possible site that uses sessions. I failed to see this particular KeyError *until* I tried reading a session variable from standard_error_message. Now I can recreate these quite frequently.

This is a well known problem in Zope, lengthy discussed but apparently still not yet fixed...

The problem is that error handling starts after the main transaction has been aborted. Aborting or committing a transaction implicitely starts a new transaction.

If error handling causes objects to be registered in the transaction (because it writes some objects and this can happen for session variables even when they are only read), this transaction is tainted. As the transaction is not aborted after error handling, the transaction and the modified cache are spilled (independently!) into a later request.

As the connection/cache may later end up in a different thread, objects can be invalidated asynchronously. This is disastrous.

Zope *MUST* abort (or commit) the transaction after error handling!!!

I think the transaction in which the error code operates in should be aborted. There is no other sane thing to do. I think this might be as easy as adding a few strategic get_transaction().abort() calls to various cases in Zope/App/startup.py's zpublisher_exception_hook. I don't have the time to untangle that mess at the moment, but I will enter a collector issue in.

On closer inspection I have another small detail - I'm only seeing these KeyError's for sessions that have had a chance to expire and when trying to access the session from standard_error_message. Also I'm seeing behaviour that suggests my first guess is not right. In other words - I'm seeing some healthy behaviour when a conflict error is thrown while attempting to render the standard_error_message. Michael

On 11/03/2004, at 1:07 PM, Chris McDonough wrote:

On Wed, 2004-03-10 at 18:30, michael wrote:

...

On closer inspection I have another small detail - I'm only seeing these KeyError's for sessions that have had a chance to expire and when trying to access the session from standard_error_message.

Can you provide a complete traceback for the error message? I'm guessing that it happens during session garbage collection but I can't be sure without the traceback.

hmmm... continuing to refine what I think I'm seeing :-O I don't get a KeyError thrown until *after* at least one rendering of standard_error_message that includes an access to a session variable. And I'm only getting KeyError's for sessions that have had a chance to expire. And that KeyError will be thrown whenever any access is made for the session. (Previously I thought I was *only* seeing KeyError's being thrown from standard_error_message.) I can't yet say from what I'm seeing if the session accessed in standard_error_message which somehow corrupts the consistency of transience is the same session for which the KeyError is thrown further down the track. Here is an example traceback when the KeyError is thrown from a Script (Python) that reads the session variable. Followed by a similar traceback thrown when Zope tries to read that same sesssion variable in my standard_error_message: 2004-03-11T16:13:03 ERROR(200) SiteError http://localhost:8080/test/read Traceback (most recent call last): File "/Users/michael/Desktop/Zope-2.7.0/lib/python/ZPublisher/Publish.py", line 101, in publish request, bind=1) File "/Users/michael/Desktop/Zope-2.7.0/lib/python/ZPublisher/mapply.py", line 88, in mapply if debug is not None: return debug(object,args,context) File "/Users/michael/Desktop/Zope-2.7.0/lib/python/ZPublisher/Publish.py", line 41, in call_object result=apply(object,args) # Type s<cr> to step into published object. File "/Users/michael/Desktop/Zope-2.7.0/lib/python/Shared/DC/Scripts/ Bindings.py", line 306, in __call__ return self._bindAndExec(args, kw, None) File "/Users/michael/Desktop/Zope-2.7.0/lib/python/Shared/DC/Scripts/ Bindings.py", line 343, in _bindAndExec return self._exec(bound_data, args, kw) File "/Users/michael/Desktop/Zope-2.7.0/lib/python/Products/PythonScripts/ PythonScript.py", line 318, in _exec result = f(*args, **kw) File "Script (Python)", line 2, in read File "/Users/michael/Desktop/Zope-2.7.0/lib/python/ZPublisher/ HTTPRequest.py", line 1218, in __getattr__ v = self.get(key, default, returnTaints=returnTaints) File "/Users/michael/Desktop/Zope-2.7.0/lib/python/ZPublisher/ HTTPRequest.py", line 1178, in get if callable(v): v = v() File "/Users/michael/Desktop/Zope-2.7.0/lib/python/Products/Sessions/ SessionDataManager.py", line 93, in getSessionData return self._getSessionDataObject(key) File "/Users/michael/Desktop/Zope-2.7.0/lib/python/Products/Sessions/ SessionDataManager.py", line 180, in _getSessionDataObject ob = container.new_or_existing(key) File "/Users/michael/Desktop/Zope-2.7.0/lib/python/Products/Transience/ Transience.py", line 176, in new_or_existing item = self.get(key, notfound) File "/Users/michael/Desktop/Zope-2.7.0/lib/python/Products/Transience/ Transience.py", line 809, in get v = self._data[b].get(k, notfound) KeyError: 1078974700 ------ 2004-03-11T16:13:04 BLATHER(-100) OFS Exception while rendering an error message Traceback (most recent call last): File "/Users/michael/Desktop/Zope-2.7.0/lib/python/OFS/SimpleItem.py", line 204, in raise_standardErrorMessage v = s(**kwargs) File "/Users/michael/Desktop/Zope-2.7.0/lib/python/Shared/DC/Scripts/ Bindings.py", line 306, in __call__ return self._bindAndExec(args, kw, None) File "/Users/michael/Desktop/Zope-2.7.0/lib/python/Shared/DC/Scripts/ Bindings.py", line 343, in _bindAndExec return self._exec(bound_data, args, kw) File "/Users/michael/Desktop/Zope-2.7.0/lib/python/Products/PythonScripts/ PythonScript.py", line 318, in _exec result = f(*args, **kw) File "Script (Python)", line 12, in standard_error_message File "/Users/michael/Desktop/Zope-2.7.0/lib/python/ZPublisher/ HTTPRequest.py", line 1218, in __getattr__ v = self.get(key, default, returnTaints=returnTaints) File "/Users/michael/Desktop/Zope-2.7.0/lib/python/ZPublisher/ HTTPRequest.py", line 1178, in get if callable(v): v = v() File "/Users/michael/Desktop/Zope-2.7.0/lib/python/Products/Sessions/ SessionDataManager.py", line 93, in getSessionData return self._getSessionDataObject(key) File "/Users/michael/Desktop/Zope-2.7.0/lib/python/Products/Sessions/ SessionDataManager.py", line 180, in _getSessionDataObject ob = container.new_or_existing(key) File "/Users/michael/Desktop/Zope-2.7.0/lib/python/Products/Transience/ Transience.py", line 176, in new_or_existing item = self.get(key, notfound) File "/Users/michael/Desktop/Zope-2.7.0/lib/python/Products/Transience/ Transience.py", line 809, in get v = self._data[b].get(k, notfound) KeyError: 1078974700 And the Python (Script) 'read' looks like: request = container.REQUEST session = request.SESSION count = session.get('count',0) return str(count) Michael

On 11/03/2004, at 7:25 PM, Chris McDonough wrote:

On Wed, 2004-03-10 at 23:14, michael wrote:

Thanks for your excellent isolation here.

...

I don't get a KeyError thrown until *after* at least one rendering of standard_error_message that includes an access to a session variable. And I'm only getting KeyError's for sessions that have had a chance to expire. And that KeyError will be thrown whenever any access is made for the session. (Previously I thought I was *only* seeing KeyError's being thrown from standard_error_message.)

I think after provide transaction isolation for the duration of an error, we will not see this symptom occur again. That's the first step, at least. We are going to have a "bugathon" at the Zope 2 sprint at PyCon 9 days from now, and I will put this high on the list. Would you be willing to test a Zope 2.7 version that contains a fix?

Sure. Michael

Whew. I finally got a chance to review at least a bit of Michael's excellent work... On Mon, 2004-04-26 at 18:34, Michael Dunstan wrote:

Okay - I've gone ahead and implemented a flavour of transaction isolation for errors. (See below for patch.) That seems to have done the trick just nicely. I have not seen any more KeyError's thrown from Transience.py. Yay!

So what do folks think of this error-case transaction isolation patch? Michael's original patch is preserved here (although it didn't survive cut and paste from my mail client in a pristine way, you'll get the idea): http://www.plope.com/Members/chrism/transaction_isolation_error.patch/file_v... Personally it looks fine to me. It wraps each error invocation in its own transaction. We need to do something like this to fix problems exposed by session writes (or any other database writes) that occur during an error. I know there were some opinions about this before as to whether the error should occur as part of the preceding transaction or whether the error should be wrapped in its own transaction, but I've forgotten the pros and cons (I've even forgotten which side I was on at that point ;-). Does anyone have a strong opinion? I think I remember that there were issues here with ZPatterns, mail-on-error, and some other things.

However there is another KeyError reported in 848 too. This one is thrown from TempoaryStoarge. After some further tweaking of my test rig I was able to produce such KeyErrors quite frequently. Using Zope 2.7.0 and recent the rewrite of Transience.py:

http://cvs.zope.org/*checkout*/Products/Transience/Transience.py? rev=1.32.12.2.2.2&only_with_tag=chrism-sessiongeddon

errors look like:

<snip 90% of traceback>

TemporaryStorage.py", line 94, in load s=self._index[oid] KeyError: '\x00\x00\x00\x00\x00\x00\x08\x82'

So far it looks like commenting out the construction of the to_notify list in _gc makes this go away. So _gc looks like:

def _gc(self, now=None): if self._timeout_slices == 0: return # dont do gc if there is no timeout

if now is None: now = getCurrentTimeslice() # for unit tests max_ts = now - (PERIOD * (self._timeout_slices + 1)) keys = self._data.keys(None, max_ts)

#to_notify = []

for key in list(self._data.keys(None, max_ts)): assert(key <= max_ts) STRICT and _assert(self._data.has_key(key)) #for v in self._data[key].values(): # to_notify.append(v) del self._data[key]

#for v in to_notify: # self.notifyDel(v)

Note that the test rig does not set onAdd or onDelete.

I was unable to verify/review this, but I believe you! However, I think the above might be fixing the symptom rather than the underlying problem. I was able to provoke these errors out of temporary storage in a completely different way. There is a "session stress test" in the Sessions product (stresstests/stressTestMultipleThreads) that kicks off multiple threads emulating simultaneous reads and writes to a temporary storage that exposes some key errors out of Transience as well. I took a look at this and I have a sneaky suspicion that the "conflict cache" in TemporaryStorage may be causing problems. TemporaryStorage attempts to emulate a revisioning/undoing storage (which it isn't), where older revisions of objects are kept around in order to play with the conflict resolution strategy in ConflictResolvingStorage. I think TemporaryStorage fails to clear this cache at some appropriate times (particularly when an object is gc'ed in the storage by the _takeOutGarbage method... TemporaryStorage does its own form of in-band "packing" via reference counts). In the amount of time I could devote to this, I was unable to prove or disprove this objectively, but looking at the code made me believe it was possible.

Along the way there where a few things that I was not too sure about so I tried fiddling with to see what would happen:

(1) Use of hasattr in Transience.py. hasattr should be avoided? See http://mail.zope.org/pipermail/zodb-dev/2003-October/005968.html. I did change usage of hasattr to match the recipe given by Tim. And added some logging to explicitly look for ConflictError's at those points. Found a few of these in the logs. But that did not solve the KeyErrors.

Good point, the hasattrs should all be changed to getattrs.

(2) _p_resolveConflict of Increaser of Transience does not always return the max of the three given states. I replaced the implementation with return max(old, state1, state2). But that did not solve the KeyErrors.

Whoops. ;-) Thanks!

(3) Use of try/except in TempoaryStorage. For example:

try: del referenceCount[oid] except: pass

I removed all such try/except wrappings of del. But that did not solve the KeyErrors. Nor did it raise any new errors in the test rig.

(4) Checking consistency of btrees. I added the following code to _gc just before the assignment of keys:

from BTrees.check import check, display try: self._data._check() check(self._data) except AssertionError: LOG('Transience',ERROR,'yikes') display(self._data) raise

I never saw any noise from this. Looks like self._data is healthy.

Just to be explicit... I removed all the above hacks leaving just the one that comments out the construction of the to_notify list. Reran the test rig. And have yet to see any KeyErrors.

Have you seen any since the time you reported this? Thanks for your patience and work! - C

On Tue, 2004-05-11 at 13:04, Dieter Maurer wrote:

Hi Chris,

Chris McDonough wrote at 2004-5-11 00:54 -0400:

...

... So what do folks think of this error-case transaction isolation patch? Michael's original patch is preserved here (although it didn't survive cut and paste from my mail client in a pristine way, you'll get the idea):

http://www.plope.com/Members/chrism/transaction_isolation_error.patch/file_v...

Personally it looks fine to me. It wraps each error invocation in its own transaction.

Please revisit the discussion (mostly between Toby and me) on "zope-dev" about how to fix this problem.

Toby convinced me that error handling should take place in the same transaction as the original request (and not in its own).

His main argument: the traceback can contain references to persistent objects that should not be there. If they are written to ZODB in any way, all kinds of dubious inconsistencies can occur.

Meanwhile, I saw several questions in the mailing lists of people that wanted to access the SESSION object during error handling (probably) because it contained useful information for error handling. This is impossible when the transaction is aborted before error handling.

Right. I will try to work up another patch then. - C

On Wed, 2004-05-12 at 22:54, Michael Dunstan wrote:

On 11/05/2004, at 4:54 PM, Chris McDonough wrote:

...

On Mon, 2004-04-26 at 18:34, Michael Dunstan wrote:

...

I removed all the above hacks leaving just the one that comments out the construction of the to_notify list. Reran the test rig. And have yet to see any KeyErrors.

Have you seen any since the time you reported this?

Since the last report I have not run been running the test rig. I Needed my laptop back so I could get on with a few other things. :-(

So I'm going to see if I can show others how to recreate the test rig that I'm using here. A trivial site and the script for testing that site are attached.

Thanks very much for this, I'm running it at the moment. So far, with the transaction isolation patch (the one which does not run the error in its own transaction) and the "new" Transience.py, and an unmodified-from-stock TemporaryStorage I haven't yet been able to provoke any unseemly errors out of transience... <wait>... as I typed that, I just saw one go by! ;-) Excellent. I will diagnose. - C

Chris McDonough wrote:

Largely due to Michael I believe I have isolated and fixed every reported sessioning error except this (still-difficult-to-reproduce-but-definitely-still-existing) KeyError bug in temporary storage. I can let the test rig run for several hours; it happens maybe once every hour or two, so I've not gotten the provocation of it down to a science yet. It doesn't occur when the transient object container is placed in a FileStorage.

I am tempted to check the following into the 2.7 branch and HEAD:

- "error occurs in same transaction as main request" patch to Publish.py. See http://www.plope.com/Members/chrism/publishpy_errorinmaintrainsaction.patch/... for the patch.

- new Transience implementation (changed only slightly from chrism-sessiongeddon-branch)

... and worry about the TemporaryStorage bug as a separate issue. Thoughts?

+1 from me. Tres. -- =============================================================== Tres Seaver tseaver@zope.com Zope Corporation "Zope Dealers" http://www.zope.com

Chris, Okay, correct me if I'm wrong. This means the big ugly SESSION problem his completely fixed. If so, you are my new best friend! (whether you like it or not). Anyway, I'll put your updates (TemporaryStorage.py and Transience.py) on a couple of my customer's systems (that have been experiencing regular KeyErrors in SESSION) on Monday and I'll let you know if I see any problems. This is pretty big. If all goes well with testing (I assume Michael will be testing your latest stuff as well), I think this is important enough that y'all should consider a 2.7.1 release with this fix. Thanks again! (I know you've probably lost some hair and a bit of sanity over this one.) Chris McDonough wrote:

On Thu, 2004-05-13 at 18:11, Tres Seaver wrote:

...

Chris McDonough wrote:

...

Largely due to Michael I believe I have isolated and fixed every reported sessioning error except this (still-difficult-to-reproduce-but-definitely-still-existing) KeyError bug in temporary storage. I can let the test rig run for several hours; it happens maybe once every hour or two, so I've not gotten the provocation of it down to a science yet. It doesn't occur when the transient object container is placed in a FileStorage.

I have now figured out where the KeyError from TemporaryStorage was coming from and have checked in a fix on the 2.7 branch and HEAD.

- C

_______________________________________________ Zope-Dev maillist - Zope-Dev@zope.org http://mail.zope.org/mailman/listinfo/zope-dev ** No cross posts or HTML encoding! ** (Related lists - http://mail.zope.org/mailman/listinfo/zope-announce http://mail.zope.org/mailman/listinfo/zope )

Chris McDonough wrote:

On Sat, 2004-05-15 at 23:11, Steve Jibson wrote:

...

Chris,

Okay, correct me if I'm wrong. This means the big ugly SESSION problem his completely fixed. If so, you are my new best friend! (whether you like it or not).

Well, I'm afraid I will need to correct you. ;-) There is one more corner case that hasn't been covered that exhibits itself when a session is accessed from within the standard_error_message. It requires a change in the main publishing code, for which exists a patch that hasn't quite yet been vetted (see earlier posts in this thread regarding Publish.py). This should work itself out over the next week or so I suspect.

Relatively speaking, this is only a minor concern. It just means I shouldn't try to access session in the standard_error_message until a solution is found. We were doing that in our product and I've already pulled that out. After all, there are NEVER any errors, so why should we need to monkey with standard_error_message ;-) It would be nice, for completeness, if this were resolved for 2.7.1.

...

Anyway, I'll put your updates (TemporaryStorage.py and Transience.py) on a couple of my customer's systems (that have been experiencing regular KeyErrors in SESSION) on Monday and I'll let you know if I see any problems.

Thanks... make sure you use the latest code from the Zope-2_7-branch in CVS.

Am I safe just dropping those two files from CVS into an existing 2.7 site or do I need to grab everything else from the Zope-2_7-branch?

:-( I grabbed Transience.py and TemporaryStorage.py from the Zope-2_7-branch of CVS this morning and dropped them onto one of our customer's systems. About 20 minutes later I found the following in the error_log: ---------------------------------------- Traceback (most recent call last): File "c:\Zope-2.7\lib\python\ZPublisher\Publish.py", line 100, in publish request, bind=1) File "c:\Zope-2.7\lib\python\ZPublisher\mapply.py", line 88, in mapply if debug is not None: return debug(object,args,context) File "c:\Zope-2.7\lib\python\ZPublisher\Publish.py", line 40, in call_object result=apply(object,args) # Type s<cr> to step into published object. File "c:\Zope-2.7\lib\python\OFS\DTMLDocument.py", line 128, in __call__ r=apply(HTML.__call__, (self, (client, bself), REQUEST), kw) File "c:\Zope-2.7\lib\python\DocumentTemplate\DT_String.py", line 474, in __call__ try: result = render_blocks(self._v_blocks, md) File "c:\Zope-2.7\lib\python\OFS\DTMLDocument.py", line 121, in __call__ r=apply(HTML.__call__, (self, bself, REQUEST), kw) File "c:\Zope-2.7\lib\python\DocumentTemplate\DT_String.py", line 474, in __call__ try: result = render_blocks(self._v_blocks, md) File "c:\Zope-2.7\lib\python\OFS\DTMLDocument.py", line 121, in __call__ r=apply(HTML.__call__, (self, bself, REQUEST), kw) File "c:\Zope-2.7\lib\python\DocumentTemplate\DT_String.py", line 474, in __call__ try: result = render_blocks(self._v_blocks, md) File "c:\Zope-2.7\lib\python\DocumentTemplate\DT_Util.py", line 201, in eval return eval(code, d) File "<string>", line 1, in <expression> File "c:\Zope-2.7\lib\python\AccessControl\ZopeGuards.py", line 67, in guarded_getitem v = object[index] File "c:\Zope-2.7\lib\python\Products\Transience\TransientObject.py", line 170, in __getitem__ return self._container[k] KeyError: 'accountType' ---------------------------------------- After getting the error, I changed them over to FileStorage. I haven't seen any errors since then. I will be more than happy to spend some time doing whatever I can to help track this down and/or test updates. Steve Chris McDonough wrote:

On Sat, 2004-05-15 at 23:55, Steve Jibson wrote:

...

...

quite yet been vetted (see earlier posts in this thread regarding Publish.py). This should work itself out over the next week or so I suspect.

Relatively speaking, this is only a minor concern. It just means I shouldn't try to access session in the standard_error_message until a solution is found. We were doing that in our product and I've already pulled that out. After all, there are NEVER any errors, so why should we need to monkey with standard_error_message ;-) It would be nice, for completeness, if this were resolved for 2.7.1.

Yes, it should work itself out over the next week or so, and definitely before 2.7.1.

...

Am I safe just dropping those two files from CVS into an existing 2.7 site or do I need to grab everything else from the Zope-2_7-branch?

I think you should be safe with just those two, but were I you I would just get the 2.7 branch out of CVS in its entirety (then you can update more easily if there are fixes). Note that if you have transient object containers in a "permanent" storage (like FileStorage), the operation is pretty much a "one way" one if you want to keep the data in the transient object container: you can go to the new code, then go back to the "old" code if necessarfy, but you will likely lose data in the TOC if you do. Obviously this doesn't effect stuff in a TemporaryStorage (because it goes away when Zope is shut down).

- C

Chris McDonough wrote:

On Mon, 2004-05-17 at 12:09, Steve Jibson wrote:

...

:-(

I grabbed Transience.py and TemporaryStorage.py from the Zope-2_7-branch of CVS this morning and dropped them onto one of our customer's systems. About 20 minutes later I found the following in the error_log:

---------------------------------------- Traceback (most recent call last): File "c:\Zope-2.7\lib\python\ZPublisher\Publish.py", line 100, in publish request, bind=1) File "c:\Zope-2.7\lib\python\ZPublisher\mapply.py", line 88, in mapply if debug is not None: return debug(object,args,context) File "c:\Zope-2.7\lib\python\ZPublisher\Publish.py", line 40, in call_object result=apply(object,args) # Type s<cr> to step into published object. File "c:\Zope-2.7\lib\python\OFS\DTMLDocument.py", line 128, in __call__ r=apply(HTML.__call__, (self, (client, bself), REQUEST), kw) File "c:\Zope-2.7\lib\python\DocumentTemplate\DT_String.py", line 474, in __call__ try: result = render_blocks(self._v_blocks, md) File "c:\Zope-2.7\lib\python\OFS\DTMLDocument.py", line 121, in __call__ r=apply(HTML.__call__, (self, bself, REQUEST), kw) File "c:\Zope-2.7\lib\python\DocumentTemplate\DT_String.py", line 474, in __call__ try: result = render_blocks(self._v_blocks, md) File "c:\Zope-2.7\lib\python\OFS\DTMLDocument.py", line 121, in __call__ r=apply(HTML.__call__, (self, bself, REQUEST), kw) File "c:\Zope-2.7\lib\python\DocumentTemplate\DT_String.py", line 474, in __call__ try: result = render_blocks(self._v_blocks, md) File "c:\Zope-2.7\lib\python\DocumentTemplate\DT_Util.py", line 201, in eval return eval(code, d) File "<string>", line 1, in <expression> File "c:\Zope-2.7\lib\python\AccessControl\ZopeGuards.py", line 67, in guarded_getitem v = object[index] File "c:\Zope-2.7\lib\python\Products\Transience\TransientObject.py", line 170, in __getitem__ return self._container[k] KeyError: 'accountType' ----------------------------------------

This looks to me like an application error, not a Transience error.

...

After getting the error, I changed them over to FileStorage. I haven't seen any errors since then. I will be more than happy to spend some time doing whatever I can to help track this down and/or test updates.

It looks like the code assumes 'accountType' is available in the session; change it to not make that assumption (perhaps via SESSION.get('accountType', 'default')).

- C

I'm sure 'accountType' should have been in the session. Immediately after a user logs in we populate his session with a bunch of stuff (including accountType). What I don't want to do is hide problems with session/tempstorage by using "get" and a default. In this particular case, there is no good default and having the application assume an incorrect accountType will cause me all kids of trouble. Also of note: 1 - After having the system run for 45 minutes, I had 8 similar errors. Some were on different web pages and some had different "keys" that were causing the error. 2 - I have also traced through Z2.log and followed the same path through the web site that produced one of the errors and I did not get an error. 3 - Since changing this server to use FileStorage (1hr 39min ago), there has not been a single error. Is there anything I can do to help here?

Chris McDonough wrote:

On Mon, 2004-05-17 at 13:06, Steve Jibson wrote:

...

I'm sure 'accountType' should have been in the session. Immediately after a user logs in we populate his session with a bunch of stuff (including accountType).

What happens when the session expires and he's still logged in?

We're using ExUserFolder for authentication. We have it set to log users out after 10 minutes. We have sessions set to expire after 20 minutes. So, in theory, it should never happen. Also, since my last Zope restart (3hr 30min), I've had 57 users let their authentication timeout and then access the site (forcing another login), and still no errors with session. (It's still using FileStorage).

...

1 - After having the system run for 45 minutes, I had 8 similar errors. Some were on different web pages and some had different "keys" that were causing the error. 2 - I have also traced through Z2.log and followed the same path through the web site that produced one of the errors and I did not get an error. 3 - Since changing this server to use FileStorage (1hr 39min ago), there has not been a single error.

Is there anything I can do to help here?

A small reproducible test case would help if you still believe this error is not in your own application.

I'm sure you know by now that this is easier said than done. Over the past few weeks, I've probably put close to 30 hours into just trying to reproduce (on demand) these session errors. I'll probably want to look at the test rig you and Michael have been using.

On 18/05/2004, at 5:42 AM, Chris McDonough wrote:

On Mon, 2004-05-17 at 13:06, Steve Jibson wrote:

...

Also of note:

1 - After having the system run for 45 minutes, I had 8 similar errors. Some were on different web pages and some had different "keys" that were causing the error. 2 - I have also traced through Z2.log and followed the same path through the web site that produced one of the errors and I did not get an error. 3 - Since changing this server to use FileStorage (1hr 39min ago), there has not been a single error.

Is there anything I can do to help here?

A small reproducible test case would help if you still believe this error is not in your own application.

Looks like session data can expire prematurely. See attached files for small changes to the test rig that reports cases where context.session_data_manager.hasSessionData() is False. Michael

There indeed is a minor off-by-one error: it manifests itself as sessions timing out at most 20 seconds early. But there is also a deeper issue which involves the fact that a session data object is not properly removed from an older bucket when it "moves" due to being accessed in a later timeslice; the symptom only appears when a browser id is "reused" to start a session after it was used to start an older one that had timed out normally. I've got almost no clue why this happens at this point, but I'm working on it. Ugh. This is almost certainly what Steve is experiencing. - C On Mon, 2004-05-17 at 20:26, Chris McDonough wrote:

On Mon, 2004-05-17 at 17:52, Michael Dunstan wrote:

...

Looks like session data can expire prematurely. See attached files for small changes to the test rig that reports cases where context.session_data_manager.hasSessionData() is False.

Michael

I think you're right, good eye! The symptoms aren't consistent with what Steve is reporting, however (where the problem appears when using TemporaryStorage but not FileStorage), so I this may be a distinct issue. I am looking in to it now. It feels like an off-by-one error.

- C

_______________________________________________ Zope-Dev maillist - Zope-Dev@zope.org http://mail.zope.org/mailman/listinfo/zope-dev ** No cross posts or HTML encoding! ** (Related lists - http://mail.zope.org/mailman/listinfo/zope-announce http://mail.zope.org/mailman/listinfo/zope )

Good morning. I just got in and checked on my customer's system. In the past 22 1/2 hours they've had 15000 page hits and last night at about 9:30, ONE person got a KeyError. Actually, this same person got twenty KeyErrors over a period of about 45 seconds. I'm downloading their log files now and plan to spend some time this morning going through them. Anyway, it appears that I was wrong when I said that the problem doesn't show up when I use FileStorage (although it does seem to happen less frequently -- but who can be sure of anything at this point?). In answer to your questions earlier, Chris, we set up the user session at login time because we make the user answer some questions at login time that determine which portions of the interface to present to him/her. For example, using the same login id and password, a user may choose to login as an administrator or as a normal user. We store this choice and other info based on this choice in the session. Also, we don't rely on the browser to time out the authentication cookie. Once a user authenticates with ExUserFolder, ExUserFolder keeps their credentials in a cache until they have been inactive for 10 minutes (the timer resets with each cache hit). If their credentials are not in the cache, rather than looking them up again, the user is logged out and must re-authenticate. It seems like a reasonable way to handle logins and sessions. In addition to going through log files, I will spend some more time today making sure we're not doing something stupid in our app. Thanks again (to Chris, Michael, Alex and everyone else who has lost sleep over this session stuff). I'll keep you posted on any new information I find. Steve Chris McDonough wrote:

On Mon, 2004-05-17 at 23:08, Chris McDonough wrote:

...

There indeed is a minor off-by-one error: it manifests itself as sessions timing out at most 20 seconds early.

But there is also a deeper issue which involves the fact that a session data object is not properly removed from an older bucket when it "moves" due to being accessed in a later timeslice; the symptom only appears when a browser id is "reused" to start a session after it was used to start an older one that had timed out normally. I've got almost no clue why this happens at this point, but I'm working on it. Ugh. This is almost certainly what Steve is experiencing.

I take that back. Actually, I think I was just reading the test results and debug output wrong. It appears to be operating normally except for the off-by-one problem (which is minor). I need to jack up the tests to do some comparisons of data values; currently I'm just testing to ensure that *something* is in the session.. I need to test if the "right" thing is in the session over time.

- C

_______________________________________________ Zope-Dev maillist - Zope-Dev@zope.org http://mail.zope.org/mailman/listinfo/zope-dev ** No cross posts or HTML encoding! ** (Related lists - http://mail.zope.org/mailman/listinfo/zope-announce http://mail.zope.org/mailman/listinfo/zope )

On Tue, 2004-05-18 at 13:11, Steve Jibson wrote:

Well, after much log reading, I have found that the KeyError we got last night was OUR fault.

Thanks for reporting this, it's reasurring. I was fixing to go insane. ;-)

I will fix the problem with our app, then I want to change back to TemporaryStorage and watch the system some more. I'll keep you posted.

Great, thanks.

Here's the brief explanation of our problem (you can skip it if you like):

A user logged in and did some stuff then left his browser for almost an hour. When he returned and tried to do more stuff, he was no longer in the ExUserFolder's credential cache and his session had expired. He was forced to log in again. Upon supplying his ID and password, he was sent to the "loginSuccess" page. This is the one that calls our method to set up his user session. The Z2.log shows a 302 result code on this page.

Ooh, that's bad. I guess that means that your users might not be logging in as whom they think they're logging in as... CookieCrumbler handles this by injecting Pragma: No-Cache and the HTTP/1.1 equivalent into the header (currently on *every* request, not so great actually).

His browser had the "loginSuccess" page in cache, so it did not request it again and his session was never re-created.

Score one for Chris's suggestion on how we should be setting up the user's session. For now, however, I think I'll just add the please-don't-cache-me header stuff to the RESPONSE.

Right... although caching+auth is kind of tricky. I wouldn't be surprised if you found other places where caching is defeating some other intentions you had. If the site is meant to be accessed only by authenticated users, I'd be tempted to arrange for the no-cache headers to be injected by the main template itself. I don't understand your setup 100%, although it sounds interesting. By your description of it sounds like you're implementing a bit of your own security machinery (a user can either be an "admin" or a normal user, depending on some setting he chooses at login time, even though it's physically only one account). But maybe an alternate way to implement the machinery to do this is to do the following: - Associate "member data" with each user. This is built in to CMF, or you can roll your own if you're not using CMF (maybe by manually using a Transient Object Container in a FileStorage with the timeout set to 0... it basically then just becomes a big dictionary). Store user "preferences" there. Give each user a default set of preferences for first-time login. - Allow the user to log in with just a username and password (don't require him to enter his profile data on each login). - In the session "add notify" script, copy his prefs into his session. Your existing code will then work normally. - In the session "delete notify" script, copy the prefs data in the session back into the member data. Just an idea... - C

Andrea Patuzzo wrote:

We are now randomly getting this kind of error:

Note: once the error happens, zope has to be restarted to function again. Before applying patches we were getting "get" errors (instead of "__setitem__") and we just had to close browser to get back to work.

That's right. Under Plone 2.0 and Zope 2.7 I had the same kind of problem. But when I restarted the browser it would be solved. That could point in the direction of a session id being somehow involved. -- hilsen/regards Max M, Denmark http://www.mxm.dk/ IT's Mad Science

Michael Dunstan wrote:

On 18/05/2004, at 10:03 PM, Andrea Patuzzo wrote:

...

Hi, dear developers:

We are now randomly getting this kind of error:

[...] File "/usr/local/Zope270CVS/lib/python/Products/Transience/Transience.py", line 341, in __setitem__ current_bucket = self._data[current_ts] KeyError: 1084872640 ====

This one was with the latest publish.py / startup.py patch and the new Transience.py implementation, on a yesterday's Zope-2_7-branch checkout. New Zope instance with FileStorage does not solve the problem. Same happens with the patches applied to the official Zope-2.7.0 release.

Note: once the error happens, zope has to be restarted to function again. Before applying patches we were getting "get" errors (instead of "__setitem__") and we just had to close browser to get back to work. Here we have to restart Zope (with TemporaryStorage) or delete Sessions.fs and restart (with FileStorage).

My guess at the moment is that somewhere a ConflictError is being swallowed. There are a few things that can be responsible for this:

- Use of hasattr on Persistent objects.

- try/except blocks that don't raise ConflictErrors.

From your trace that looks like a Plone site. A very quick glance through Plone and its friends indicates that there may be some chance of either of the above causing some problems. Although Plone 2.0.1 includes the following fix:

- Fixed bare 'except:' statements in Plone so we don't swallow ZODB ConflictErrors. Mostly by adding 'except ConflictError: raise'. [stefan]

Someone please shoot me down and claim that Plone and friends all do the right thing. ;-)

We should have a 'hasattr-geddon' and remove every trace of that monstrosity from Zope and the CMF; likewise a 'bareexcept-geddon' (there might be a few places which are smart enough to do 'except:', but I doubt it). Tres. -- =============================================================== Tres Seaver tseaver@zope.com Zope Corporation "Zope Dealers" http://www.zope.com

I've looked at that issue many times during various bug days and it sounded reasonable enough but it always seemed like slightly higher-hanging fruit than other issues because it introduces new features as well as fixes bugs. Personally I prefer that someone who wants to introduce new features (even small ones, like API additions) into the core do it via their own committer privileges and thus sign up to maintain it for the rest of eternity, or longer ;-) The reason I think people don't jump on collector issues like this one is because of the natural "he who touched it last owns it" policy of the core code. I own enough of Zope 2 core code to make me uncomfortable at this point; owning more just isn't very attractive to me unless the upside is very up. Straightforward obvious bugfix patches with limited scopes are another matter; those usually get applied first during bug days. This is also why "geddons" are attractive; they focus effort on an isomorphic class of bugs without requring that the fixer wade through proposals for features, API improvements, and provides an effective loophole for "he who touched it last" problem. - C On Wed, 2004-05-19 at 14:43, Jamie Heilman wrote:

Tres Seaver wrote:

...

We should have a 'hasattr-geddon' and remove every trace of that monstrosity from Zope and the CMF; likewise a 'bareexcept-geddon' (there might be a few places which are smart enough to do 'except:', but I doubt it).

Now its not a geddon by any means, but the code I wrote and offered in bug 911 fixes 3 (iirc) bare excepts, a couple of privacy holes, several bugs, and adds some enhancements that my tests have shown are basically backwards compatible with everything out there (though I didn't realize at the time CMF had a cache manager of its own and I'm not sure how they interact). Its been a year now since I offered that code and I haven't gotten so much as a comment on it. Maybe its time to wander over and give it a look?

Chris McDonough wrote:

I've looked at that issue many times during various bug days and it sounded reasonable enough but it always seemed like slightly higher-hanging fruit than other issues because it introduces new features as well as fixes bugs.

Oh granted, it totally is. It just happens to be high hanging fruit I have a vested interest in, and don't mind squeeking about once a year. Now I've done my squeeking, so I'm good till '05.

Personally I prefer that someone who wants to introduce new features (even small ones, like API additions) into the core do it via their own committer privileges and thus sign up to maintain it for the rest of

Yeah well... we've been over that before, I refuse to sign that agreement. If that means my patches go ignored for eternity, so be it, but it really seems like ZC is just cutting of their nose to spite their face.

The reason I think people don't jump on collector issues like this one is because of the natural "he who touched it last owns it" policy of the core code. I own enough of Zope 2 core code to make me uncomfortable at this point; owning more just isn't very attractive to me unless the upside is very up.

Thats an unfortunate situation to be sure, I don't have any solutions to offer as its not a technical issue. All I can say is that we know the code doesn't care who touched it last, its going to break or work regardless. The sooner the community accepts that, the sooner we can get out of the rut and make some more progress.

Straightforward obvious bugfix patches with limited scopes are another matter; those usually get applied first during bug days. This is also why "geddons" are attractive; they focus effort on an isomorphic class of bugs without requring that the fixer wade through proposals for features, API improvements, and provides an effective loophole for "he who touched it last" problem.

Sure, I have nothing against geddons per se[1], but they just won't fix every class of problem. One of the advantages of OOP is being able to focus on a component of the larger system, replace it, and see how the system around it reacts. The clearly defined component boundries are a big advantage to that kind of development strategy, its a great way to make localized behavioral changes. I don't think any amount of geddon activity would solve the problems I've faced with the current result caching API. -- Jamie Heilman http://audible.transient.net/~jamie/ "I was in love once -- a Sinclair ZX-81. People said, "No, Holly, she's not for you." She was cheap, she was stupid and she wouldn't load -- well, not for me, anyway." -Holly [1] I'd love to see the DTML namespace qualification (see bug 1217) geddon occur, if for no other reason than to watch the resulting code-bloat totally school some of the "dtml uber alles" hold outs.

Chris McDonough wrote at 2004-5-15 13:04 -0400:

... Dieter, do you think you can read this patch and give a thumbs up or down on it?

The patch looks good.

On a different subject, the publisher probably shouldn't pass around traceback objects (e.g. when it calls into err_hook) as Tres believes that may be a memory leak waiting to happen.

The traceback is vital for error analysis. It may not be necessary that ZPublisher touches the traceback but we will definitely need access to it during error handling. -- Dieter

Casey Duncan wrote:

On Mon, 17 May 2004 19:00:16 +0200 Dieter Maurer <dieter@handshake.de> wrote:

...

Chris McDonough wrote at 2004-5-15 13:04 -0400:

...

... Dieter, do you think you can read this patch and give a thumbs up or down on it?

The patch looks good.

...

On a different subject, the publisher probably shouldn't pass around traceback objects (e.g. when it calls into err_hook) as Tres believes that may be a memory leak waiting to happen.

The traceback is vital for error analysis.

It may not be necessary that ZPublisher touches the traceback but we will definitely need access to it during error handling.

Because the traceback contains stack frames, passing it through another stack frame (via a function call) is inherently tricky: the called function must *not* raise another exception.

Perhaps the traceback can be passed as a string to avoid leaks? Furthermore why can't the traceback be retrieved later from sys.exc_info()?

+1; I don't want untrusted code handling tracebacks anyway. Tres. -- =============================================================== Tres Seaver tseaver@zope.com Zope Corporation "Zope Dealers" http://www.zope.com

On Mon, 2004-05-17 at 13:00, Dieter Maurer wrote:

Chris McDonough wrote at 2004-5-15 13:04 -0400:

...

... Dieter, do you think you can read this patch and give a thumbs up or down on it?

The patch looks good.

Great, thanks for looking at it. - C

On Thu, 2004-03-11 at 06:52, Chris Withers wrote:

Well, what if you want to make a note in some object (say the error_log), that something bad happened?

The error_log doesn't use persistent objects to keep its messages.

What if you want to make a change in the error handler?

If anyone had been depending on this behavior in their current error handlers, they would have seen weirdnesses in their applications like those being reported now. And no one has really complained, AFAICT. That leads me to believe it's a case of YAGNI (or even YNNI -- you never needed it).

My view is that the error handler should oeprate in it's own transaction, and be aborted if any exceptions are raised in it...

I guess this is a reasonable strategy too, but I just wonder if it's worth the bother. I guess you might want to write to a transactional relational database in your error page, but as far as I can tell no one does this, because if they did they would probably be complaining about lost records every so often. Unless they just never noticed.

...that said, I guess if you _really_ wanted to make changes in your error handler, would anything bad happen if your proposed changes are made, but the user's error handling code does a manaual get_transaction().commit() itself?

Not that I can tell. - C

On Thu, 2004-03-11 at 07:29, Toby Dickenson wrote:

I have applications that send emails in error handlers. MailHost isnt transactional today, but Ive always wanted it to be.

I suppose that's true. If someone else doesn't do it first, during the bug day we'll try to support this use case, then, unless it turns out to be very problematic. - C

On Thu, Mar 11, 2004 at 12:29:51PM +0000, Toby Dickenson wrote:

On Thursday 11 March 2004 12:19, Chris McDonough wrote:

...

...

What if you want to make a change in the error handler?

If anyone had been depending on this behavior in their current error handlers, they would have seen weirdnesses in their applications like those being reported now.

I have applications that send emails in error handlers. MailHost isnt transactional today, but Ive always wanted it to be.

MaildropHost? http://zope.org/Members/jens/Folder.2003-08-11.1400/MaildropHost -- Paul Winkler http://www.slinkp.com Look! Up in the sky! It's INVESTIGATOR GAMMA! (random hero from isometric.spaceninja.com)

On Wed, 10 Mar 2004 17:50:41 -0500 Chris McDonough <chrism@plope.com> wrote:

Nevermind. http://zope.org/Collectors/Zope/789 and http://zope.org/Collectors/Zope/786

The bug neglector is really living up to its name lately (not pointing fingers, mea culpa).

'Bout time fer a bug day I reckon... ;^) -Casey

On Wed, 2004-03-10 at 19:30, Paul Winkler wrote:

I suggested doing a bug day as part of the pycon z2 sprint, but we haven't really discussed the various sprint proposals in depth yet.

Since you and I are going to be there on Saturday and Sunday, why don't we do this on those days and encourage people to participate via IRC? We can decide to do something else (or not) for Monday and Tuesday, if the mood strikes. - C

Saturday Mar 20, Sun Mar 21... On Thu, 2004-03-11 at 06:54, Chris Withers wrote:

Chris McDonough wrote:

...

On Wed, 2004-03-10 at 19:30, Paul Winkler wrote:

...

I suggested doing a bug day as part of the pycon z2 sprint, but we haven't really discussed the various sprint proposals in depth yet.

Since you and I are going to be there on Saturday and Sunday, why don't we do this on those days and encourage people to participate via IRC? We can decide to do something else (or not) for Monday and Tuesday, if the mood strikes.

What dates are those Saturday and Sunday? I'm not at PyCon but might see if I can pitch in from the UK...

cheers,

Chris

On Thu, 2004-03-11 at 08:32, alex@halogen-dg.com wrote:

Hi Chris,

On Tue, 9 Mar 2004, Chris McDonough wrote:

...

...

But it seems I forget to install new Transience module to the new Zope instance. Should I? Yes, please!

Sorry, it does not seems to work on my first attempt:

Right. Could you delete your Session.fs file and retry? - C