Since upgrading to Zope-2.6 we've been getting KeyErrors when using Sessions. They seem to happen more now that we've started using hasSessionData(), but I'm pretty sure they happened prior to that. Anyways, here are the 2 related tracebacks. Has anyone else seen these? Traceback #1 occurs most frequently. The KeyError's value is an unprintable string of non-ascii characters. * Module ZPublisher.Publish, line 150, in publish_module * Module ZPublisher.Publish, line 114, in publish * Module The application server.App.startup, line 182, in zpublisher_exception_hook * Module ZPublisher.Publish, line 98, in publish * Module ZPublisher.mapply, line 88, in mapply * Module ZPublisher.Publish, line 39, in call_object * Module App.special_dtml, line 61, in __call__ * Module DocumentTemplate.DT_String, line 474, in __call__ * Module Products.Transience.Transience, line 342, in nudge * Module Products.Transience.Transience, line 467, in _getCurrentBucket * Module Products.TemporaryFolder.LowConflictConnection, line 34, in setstate * Module Products.TemporaryFolder.TemporaryStorage, line 94, in load KeyError: Traceback #2 happens less frequently, though today it seemed like it was trying to catch up (3 of these today). * Module ZPublisher.Publish, line 98, in publish * Module ZPublisher.mapply, line 88, in mapply * Module ZPublisher.Publish, line 39, in call_object * Module OFS.DTMLMethod, line 126, in __call__ * Module DocumentTemplate.DT_String, line 474, in __call__ * Module Products.DotOrg.Pages.KContent, line 149, in __call__ * Module Products.DotOrg.Pages.KContent, line 194, in getEditInfo * Module Products.DotOrg.Pages.KContent, line 506, in hasSessionData * Module Products.Sessions.SessionDataManager, line 101, in hasSessionData * Module Products.Sessions.SessionDataManager, line 175, in _hasSessionDataObject * Module Products.Transience.Transience, line 838, in has_key * Module Products.Transience.Transience, line 807, in get KeyError: 1047409860 -- John Eikenberry [jae@kavi.com] ______________________________________________________________ "A society that will trade a little liberty for a little order will deserve neither and lose both." --B. Franklin
John, Which Zope 2.6? Zope 2.6.1? Here's what line 807 of the current Transience.py looks like: v = self._data[b].get(k, notfound) Does yours look like that? What is the value of the __version__ variable at the top of the Transience.py file? On Thu, 2003-03-13 at 07:11, John Eikenberry wrote:
Since upgrading to Zope-2.6 we've been getting KeyErrors when using Sessions. They seem to happen more now that we've started using hasSessionData(), but I'm pretty sure they happened prior to that.
Anyways, here are the 2 related tracebacks. Has anyone else seen these?
Traceback #1 occurs most frequently. The KeyError's value is an unprintable string of non-ascii characters.
* Module ZPublisher.Publish, line 150, in publish_module * Module ZPublisher.Publish, line 114, in publish * Module The application server.App.startup, line 182, in zpublisher_exception_hook * Module ZPublisher.Publish, line 98, in publish * Module ZPublisher.mapply, line 88, in mapply * Module ZPublisher.Publish, line 39, in call_object * Module App.special_dtml, line 61, in __call__ * Module DocumentTemplate.DT_String, line 474, in __call__ * Module Products.Transience.Transience, line 342, in nudge * Module Products.Transience.Transience, line 467, in _getCurrentBucket * Module Products.TemporaryFolder.LowConflictConnection, line 34, in setstate * Module Products.TemporaryFolder.TemporaryStorage, line 94, in load KeyError:
Traceback #2 happens less frequently, though today it seemed like it was trying to catch up (3 of these today).
* Module ZPublisher.Publish, line 98, in publish * Module ZPublisher.mapply, line 88, in mapply * Module ZPublisher.Publish, line 39, in call_object * Module OFS.DTMLMethod, line 126, in __call__ * Module DocumentTemplate.DT_String, line 474, in __call__ * Module Products.DotOrg.Pages.KContent, line 149, in __call__ * Module Products.DotOrg.Pages.KContent, line 194, in getEditInfo * Module Products.DotOrg.Pages.KContent, line 506, in hasSessionData * Module Products.Sessions.SessionDataManager, line 101, in hasSessionData * Module Products.Sessions.SessionDataManager, line 175, in _hasSessionDataObject * Module Products.Transience.Transience, line 838, in has_key * Module Products.Transience.Transience, line 807, in get
KeyError: 1047409860
--
John Eikenberry [jae@kavi.com] ______________________________________________________________ "A society that will trade a little liberty for a little order will deserve neither and lose both." --B. Franklin
_______________________________________________ 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 )
Sorry, its Zope 2.6.1. Chris McDonough wrote:
John,
Which Zope 2.6? Zope 2.6.1? Here's what line 807 of the current Transience.py looks like:
v = self._data[b].get(k, notfound)
Does yours look like that?
Yes.
What is the value of the __version__ variable at the top of the Transience.py file?
__version__='$Revision: 1.28.6.4 $'[11:-2]
On Thu, 2003-03-13 at 07:11, John Eikenberry wrote:
Since upgrading to Zope-2.6 we've been getting KeyErrors when using Sessions. They seem to happen more now that we've started using hasSessionData(), but I'm pretty sure they happened prior to that.
Anyways, here are the 2 related tracebacks. Has anyone else seen these?
Traceback #1 occurs most frequently. The KeyError's value is an unprintable string of non-ascii characters.
* Module ZPublisher.Publish, line 150, in publish_module * Module ZPublisher.Publish, line 114, in publish * Module The application server.App.startup, line 182, in zpublisher_exception_hook * Module ZPublisher.Publish, line 98, in publish * Module ZPublisher.mapply, line 88, in mapply * Module ZPublisher.Publish, line 39, in call_object * Module App.special_dtml, line 61, in __call__ * Module DocumentTemplate.DT_String, line 474, in __call__ * Module Products.Transience.Transience, line 342, in nudge * Module Products.Transience.Transience, line 467, in _getCurrentBucket * Module Products.TemporaryFolder.LowConflictConnection, line 34, in setstate * Module Products.TemporaryFolder.TemporaryStorage, line 94, in load KeyError:
Traceback #2 happens less frequently, though today it seemed like it was trying to catch up (3 of these today).
* Module ZPublisher.Publish, line 98, in publish * Module ZPublisher.mapply, line 88, in mapply * Module ZPublisher.Publish, line 39, in call_object * Module OFS.DTMLMethod, line 126, in __call__ * Module DocumentTemplate.DT_String, line 474, in __call__ * Module Products.DotOrg.Pages.KContent, line 149, in __call__ * Module Products.DotOrg.Pages.KContent, line 194, in getEditInfo * Module Products.DotOrg.Pages.KContent, line 506, in hasSessionData * Module Products.Sessions.SessionDataManager, line 101, in hasSessionData * Module Products.Sessions.SessionDataManager, line 175, in _hasSessionDataObject * Module Products.Transience.Transience, line 838, in has_key * Module Products.Transience.Transience, line 807, in get
KeyError: 1047409860
--
John Eikenberry [jae@kavi.com] ______________________________________________________________ "A society that will trade a little liberty for a little order will deserve neither and lose both." --B. Franklin
_______________________________________________ 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 )
-- John Eikenberry [jae@kavi.com] ______________________________________________________________ "A society that will trade a little liberty for a little order will deserve neither and lose both." --B. Franklin
Hi John, Can you apply the attached diff to your Transience.py file and run with it in place for a couple of days? It will not fix the problem (the symptoms will remain) but it should print some diagnostic information to the Zope event log (the STUPID_LOG_FILE, hopefully you've got that going) that will help us track down what this might be. Once you notice it happen, send the relevant parts of your logfile to me and I will see if I can analyze it. - C On Thu, 2003-03-13 at 15:19, John Eikenberry wrote:
Sorry, its Zope 2.6.1.
Chris McDonough wrote:
John,
Which Zope 2.6? Zope 2.6.1? Here's what line 807 of the current Transience.py looks like:
v = self._data[b].get(k, notfound)
Does yours look like that?
Yes.
What is the value of the __version__ variable at the top of the Transience.py file?
__version__='$Revision: 1.28.6.4 $'[11:-2]
On Thu, 2003-03-13 at 07:11, John Eikenberry wrote:
Since upgrading to Zope-2.6 we've been getting KeyErrors when using Sessions. They seem to happen more now that we've started using hasSessionData(), but I'm pretty sure they happened prior to that.
Anyways, here are the 2 related tracebacks. Has anyone else seen these?
Traceback #1 occurs most frequently. The KeyError's value is an unprintable string of non-ascii characters.
* Module ZPublisher.Publish, line 150, in publish_module * Module ZPublisher.Publish, line 114, in publish * Module The application server.App.startup, line 182, in zpublisher_exception_hook * Module ZPublisher.Publish, line 98, in publish * Module ZPublisher.mapply, line 88, in mapply * Module ZPublisher.Publish, line 39, in call_object * Module App.special_dtml, line 61, in __call__ * Module DocumentTemplate.DT_String, line 474, in __call__ * Module Products.Transience.Transience, line 342, in nudge * Module Products.Transience.Transience, line 467, in _getCurrentBucket * Module Products.TemporaryFolder.LowConflictConnection, line 34, in setstate * Module Products.TemporaryFolder.TemporaryStorage, line 94, in load KeyError:
Traceback #2 happens less frequently, though today it seemed like it was trying to catch up (3 of these today).
* Module ZPublisher.Publish, line 98, in publish * Module ZPublisher.mapply, line 88, in mapply * Module ZPublisher.Publish, line 39, in call_object * Module OFS.DTMLMethod, line 126, in __call__ * Module DocumentTemplate.DT_String, line 474, in __call__ * Module Products.DotOrg.Pages.KContent, line 149, in __call__ * Module Products.DotOrg.Pages.KContent, line 194, in getEditInfo * Module Products.DotOrg.Pages.KContent, line 506, in hasSessionData * Module Products.Sessions.SessionDataManager, line 101, in hasSessionData * Module Products.Sessions.SessionDataManager, line 175, in _hasSessionDataObject * Module Products.Transience.Transience, line 838, in has_key * Module Products.Transience.Transience, line 807, in get
KeyError: 1047409860
--
John Eikenberry [jae@kavi.com] ______________________________________________________________ "A society that will trade a little liberty for a little order will deserve neither and lose both." --B. Franklin
_______________________________________________ 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 )
--
John Eikenberry [jae@kavi.com] ______________________________________________________________ "A society that will trade a little liberty for a little order will deserve neither and lose both." --B. Franklin
_______________________________________________ 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 )
Patch applied and the first results are in... so far its a lot of these: 2003-03-13T15:18:07 PROBLEM(100) Transience KeyError raised in get, checking _data BTree ------ 2003-03-13T15:18:07 PROBLEM(100) Transience BTree check succeeded Chris McDonough wrote:
Hi John,
Can you apply the attached diff to your Transience.py file and run with it in place for a couple of days? It will not fix the problem (the symptoms will remain) but it should print some diagnostic information to the Zope event log (the STUPID_LOG_FILE, hopefully you've got that going) that will help us track down what this might be.
Once you notice it happen, send the relevant parts of your logfile to me and I will see if I can analyze it.
- C
On Thu, 2003-03-13 at 15:19, John Eikenberry wrote:
Sorry, its Zope 2.6.1.
Chris McDonough wrote:
John,
Which Zope 2.6? Zope 2.6.1? Here's what line 807 of the current Transience.py looks like:
v = self._data[b].get(k, notfound)
Does yours look like that?
Yes.
What is the value of the __version__ variable at the top of the Transience.py file?
__version__='$Revision: 1.28.6.4 $'[11:-2]
On Thu, 2003-03-13 at 07:11, John Eikenberry wrote:
Since upgrading to Zope-2.6 we've been getting KeyErrors when using Sessions. They seem to happen more now that we've started using hasSessionData(), but I'm pretty sure they happened prior to that.
Anyways, here are the 2 related tracebacks. Has anyone else seen these?
Traceback #1 occurs most frequently. The KeyError's value is an unprintable string of non-ascii characters.
* Module ZPublisher.Publish, line 150, in publish_module * Module ZPublisher.Publish, line 114, in publish * Module The application server.App.startup, line 182, in zpublisher_exception_hook * Module ZPublisher.Publish, line 98, in publish * Module ZPublisher.mapply, line 88, in mapply * Module ZPublisher.Publish, line 39, in call_object * Module App.special_dtml, line 61, in __call__ * Module DocumentTemplate.DT_String, line 474, in __call__ * Module Products.Transience.Transience, line 342, in nudge * Module Products.Transience.Transience, line 467, in _getCurrentBucket * Module Products.TemporaryFolder.LowConflictConnection, line 34, in setstate * Module Products.TemporaryFolder.TemporaryStorage, line 94, in load KeyError:
Traceback #2 happens less frequently, though today it seemed like it was trying to catch up (3 of these today).
* Module ZPublisher.Publish, line 98, in publish * Module ZPublisher.mapply, line 88, in mapply * Module ZPublisher.Publish, line 39, in call_object * Module OFS.DTMLMethod, line 126, in __call__ * Module DocumentTemplate.DT_String, line 474, in __call__ * Module Products.DotOrg.Pages.KContent, line 149, in __call__ * Module Products.DotOrg.Pages.KContent, line 194, in getEditInfo * Module Products.DotOrg.Pages.KContent, line 506, in hasSessionData * Module Products.Sessions.SessionDataManager, line 101, in hasSessionData * Module Products.Sessions.SessionDataManager, line 175, in _hasSessionDataObject * Module Products.Transience.Transience, line 838, in has_key * Module Products.Transience.Transience, line 807, in get
KeyError: 1047409860
--
John Eikenberry [jae@kavi.com] ______________________________________________________________ "A society that will trade a little liberty for a little order will deserve neither and lose both." --B. Franklin
_______________________________________________ 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 )
--
John Eikenberry [jae@kavi.com] ______________________________________________________________ "A society that will trade a little liberty for a little order will deserve neither and lose both." --B. Franklin
_______________________________________________ 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 )
? btreecheck.diff ? kedaipatch Index: Transience.py =================================================================== RCS file: /cvs-repository/Zope/lib/python/Products/Transience/Transience.py,v retrieving revision 1.28.6.4 diff -r1.28.6.4 Transience.py 34a35
from BTrees.check import check, display 45a47 from cStringIO import StringIO 807c809,830 < v = self._data[b].get(k, notfound)
try: v = self._data[b].get(k, notfound) except KeyError: LOG('Transience', WARNING, 'KeyError raised in get, checking _data BTree') try: check(self._data) LOG('Transience', WARNING,'BTree check succeeded') except: # BTree check failed oldstdout = sys.stdout tmp = StringIO() try: sys.stdout = tmp display(self._data) tmp.seek(0) LOG('Transience', WARNING,'BTree check failed', tmp.read(), error=sys.exc_info()) tmp.close() finally: sys.stdout = oldstdout raise
-- John Eikenberry [jae@kavi.com] ______________________________________________________________ "A society that will trade a little liberty for a little order will deserve neither and lose both." --B. Franklin
OK, thanks John. I hate to ask this (I should have done this to start with), but would you be willing to use the following patch --against the original file, not your recently patched version-- and try again? I only checked one of the two BTrees that might be at the heart of the problem with the first patch, this patch checks the second as well. - C On Thu, 2003-03-13 at 18:18, John Eikenberry wrote:
Patch applied and the first results are in... so far its a lot of these:
2003-03-13T15:18:07 PROBLEM(100) Transience KeyError raised in get, checking _data BTree ------ 2003-03-13T15:18:07 PROBLEM(100) Transience BTree check succeeded
Chris McDonough wrote:
Hi John,
Can you apply the attached diff to your Transience.py file and run with it in place for a couple of days? It will not fix the problem (the symptoms will remain) but it should print some diagnostic information to the Zope event log (the STUPID_LOG_FILE, hopefully you've got that going) that will help us track down what this might be.
Once you notice it happen, send the relevant parts of your logfile to me and I will see if I can analyze it.
- C
On Thu, 2003-03-13 at 15:19, John Eikenberry wrote:
Sorry, its Zope 2.6.1.
Chris McDonough wrote:
John,
Which Zope 2.6? Zope 2.6.1? Here's what line 807 of the current Transience.py looks like:
v = self._data[b].get(k, notfound)
Does yours look like that?
Yes.
What is the value of the __version__ variable at the top of the Transience.py file?
__version__='$Revision: 1.28.6.4 $'[11:-2]
On Thu, 2003-03-13 at 07:11, John Eikenberry wrote:
Since upgrading to Zope-2.6 we've been getting KeyErrors when using Sessions. They seem to happen more now that we've started using hasSessionData(), but I'm pretty sure they happened prior to that.
Anyways, here are the 2 related tracebacks. Has anyone else seen these?
Traceback #1 occurs most frequently. The KeyError's value is an unprintable string of non-ascii characters.
* Module ZPublisher.Publish, line 150, in publish_module * Module ZPublisher.Publish, line 114, in publish * Module The application server.App.startup, line 182, in zpublisher_exception_hook * Module ZPublisher.Publish, line 98, in publish * Module ZPublisher.mapply, line 88, in mapply * Module ZPublisher.Publish, line 39, in call_object * Module App.special_dtml, line 61, in __call__ * Module DocumentTemplate.DT_String, line 474, in __call__ * Module Products.Transience.Transience, line 342, in nudge * Module Products.Transience.Transience, line 467, in _getCurrentBucket * Module Products.TemporaryFolder.LowConflictConnection, line 34, in setstate * Module Products.TemporaryFolder.TemporaryStorage, line 94, in load KeyError:
Traceback #2 happens less frequently, though today it seemed like it was trying to catch up (3 of these today).
* Module ZPublisher.Publish, line 98, in publish * Module ZPublisher.mapply, line 88, in mapply * Module ZPublisher.Publish, line 39, in call_object * Module OFS.DTMLMethod, line 126, in __call__ * Module DocumentTemplate.DT_String, line 474, in __call__ * Module Products.DotOrg.Pages.KContent, line 149, in __call__ * Module Products.DotOrg.Pages.KContent, line 194, in getEditInfo * Module Products.DotOrg.Pages.KContent, line 506, in hasSessionData * Module Products.Sessions.SessionDataManager, line 101, in hasSessionData * Module Products.Sessions.SessionDataManager, line 175, in _hasSessionDataObject * Module Products.Transience.Transience, line 838, in has_key * Module Products.Transience.Transience, line 807, in get
KeyError: 1047409860
--
John Eikenberry [jae@kavi.com] ______________________________________________________________ "A society that will trade a little liberty for a little order will deserve neither and lose both." --B. Franklin
_______________________________________________ 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 )
--
John Eikenberry [jae@kavi.com] ______________________________________________________________ "A society that will trade a little liberty for a little order will deserve neither and lose both." --B. Franklin
_______________________________________________ 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 )
? btreecheck.diff ? kedaipatch Index: Transience.py =================================================================== RCS file: /cvs-repository/Zope/lib/python/Products/Transience/Transience.py,v retrieving revision 1.28.6.4 diff -r1.28.6.4 Transience.py 34a35
from BTrees.check import check, display 45a47 from cStringIO import StringIO 807c809,830 < v = self._data[b].get(k, notfound)
try: v = self._data[b].get(k, notfound) except KeyError: LOG('Transience', WARNING, 'KeyError raised in get, checking _data BTree') try: check(self._data) LOG('Transience', WARNING,'BTree check succeeded') except: # BTree check failed oldstdout = sys.stdout tmp = StringIO() try: sys.stdout = tmp display(self._data) tmp.seek(0) LOG('Transience', WARNING,'BTree check failed', tmp.read(), error=sys.exc_info()) tmp.close() finally: sys.stdout = oldstdout raise
--
John Eikenberry [jae@kavi.com] ______________________________________________________________ "A society that will trade a little liberty for a little order will deserve neither and lose both." --B. Franklin
_______________________________________________ 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:
OK, thanks John.
Thank you for helping.
I hate to ask this (I should have done this to start with), but would you be willing to use the following patch --against the original file, not your recently patched version-- and try again? I only checked one of the two BTrees that might be at the heart of the problem with the first patch, this patch checks the second as well.
Put the patch in place and have a couple errors already. Doesn't look like its going to be much help though. Just a couple repetitions of this: ------ 2003-03-14T03:35:53 PROBLEM(100) Transience KeyError raised in get, checking BTrees ------ 2003-03-14T03:35:53 PROBLEM(100) Transience BTree check for data succeeded ------ 2003-03-14T03:35:53 PROBLEM(100) Transience BTree check for index succeeded
- C
On Thu, 2003-03-13 at 18:18, John Eikenberry wrote:
Patch applied and the first results are in... so far its a lot of these:
2003-03-13T15:18:07 PROBLEM(100) Transience KeyError raised in get, checking _data BTree ------ 2003-03-13T15:18:07 PROBLEM(100) Transience BTree check succeeded
Chris McDonough wrote:
Hi John,
Can you apply the attached diff to your Transience.py file and run with it in place for a couple of days? It will not fix the problem (the symptoms will remain) but it should print some diagnostic information to the Zope event log (the STUPID_LOG_FILE, hopefully you've got that going) that will help us track down what this might be.
Once you notice it happen, send the relevant parts of your logfile to me and I will see if I can analyze it.
- C
On Thu, 2003-03-13 at 15:19, John Eikenberry wrote:
Sorry, its Zope 2.6.1.
Chris McDonough wrote:
John,
Which Zope 2.6? Zope 2.6.1? Here's what line 807 of the current Transience.py looks like:
v = self._data[b].get(k, notfound)
Does yours look like that?
Yes.
What is the value of the __version__ variable at the top of the Transience.py file?
__version__='$Revision: 1.28.6.4 $'[11:-2]
On Thu, 2003-03-13 at 07:11, John Eikenberry wrote:
Since upgrading to Zope-2.6 we've been getting KeyErrors when using Sessions. They seem to happen more now that we've started using hasSessionData(), but I'm pretty sure they happened prior to that.
Anyways, here are the 2 related tracebacks. Has anyone else seen these?
Traceback #1 occurs most frequently. The KeyError's value is an unprintable string of non-ascii characters.
* Module ZPublisher.Publish, line 150, in publish_module * Module ZPublisher.Publish, line 114, in publish * Module The application server.App.startup, line 182, in zpublisher_exception_hook * Module ZPublisher.Publish, line 98, in publish * Module ZPublisher.mapply, line 88, in mapply * Module ZPublisher.Publish, line 39, in call_object * Module App.special_dtml, line 61, in __call__ * Module DocumentTemplate.DT_String, line 474, in __call__ * Module Products.Transience.Transience, line 342, in nudge * Module Products.Transience.Transience, line 467, in _getCurrentBucket * Module Products.TemporaryFolder.LowConflictConnection, line 34, in setstate * Module Products.TemporaryFolder.TemporaryStorage, line 94, in load KeyError:
Traceback #2 happens less frequently, though today it seemed like it was trying to catch up (3 of these today).
* Module ZPublisher.Publish, line 98, in publish * Module ZPublisher.mapply, line 88, in mapply * Module ZPublisher.Publish, line 39, in call_object * Module OFS.DTMLMethod, line 126, in __call__ * Module DocumentTemplate.DT_String, line 474, in __call__ * Module Products.DotOrg.Pages.KContent, line 149, in __call__ * Module Products.DotOrg.Pages.KContent, line 194, in getEditInfo * Module Products.DotOrg.Pages.KContent, line 506, in hasSessionData * Module Products.Sessions.SessionDataManager, line 101, in hasSessionData * Module Products.Sessions.SessionDataManager, line 175, in _hasSessionDataObject * Module Products.Transience.Transience, line 838, in has_key * Module Products.Transience.Transience, line 807, in get
KeyError: 1047409860
--
John Eikenberry [jae@kavi.com] ______________________________________________________________ "A society that will trade a little liberty for a little order will deserve neither and lose both." --B. Franklin
_______________________________________________ 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 )
--
John Eikenberry [jae@kavi.com] ______________________________________________________________ "A society that will trade a little liberty for a little order will deserve neither and lose both." --B. Franklin
_______________________________________________ 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 )
? btreecheck.diff ? kedaipatch Index: Transience.py =================================================================== RCS file: /cvs-repository/Zope/lib/python/Products/Transience/Transience.py,v retrieving revision 1.28.6.4 diff -r1.28.6.4 Transience.py 34a35
from BTrees.check import check, display 45a47 from cStringIO import StringIO 807c809,830 < v = self._data[b].get(k, notfound)
try: v = self._data[b].get(k, notfound) except KeyError: LOG('Transience', WARNING, 'KeyError raised in get, checking _data BTree') try: check(self._data) LOG('Transience', WARNING,'BTree check succeeded') except: # BTree check failed oldstdout = sys.stdout tmp = StringIO() try: sys.stdout = tmp display(self._data) tmp.seek(0) LOG('Transience', WARNING,'BTree check failed', tmp.read(), error=sys.exc_info()) tmp.close() finally: sys.stdout = oldstdout raise
--
John Eikenberry [jae@kavi.com] ______________________________________________________________ "A society that will trade a little liberty for a little order will deserve neither and lose both." --B. Franklin
_______________________________________________ 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 )
Index: Transience.py =================================================================== RCS file: /cvs-repository/Zope/lib/python/Products/Transience/Transience.py,v retrieving revision 1.28.6.4 diff -r1.28.6.4 Transience.py 807c807,814 < v = self._data[b].get(k, notfound) ---
try: v = self._data[b].get(k, notfound) except KeyError: LOG('Transience', WARNING, 'KeyError raised in get, checking BTrees') check_btree(self._data, 'data') check_btree(index, 'index') raise
954a962,981
def check_btree(btree, name): from BTrees.check import check, display from cStringIO import StringIO try: check(btree) LOG('Transience', WARNING,'BTree check for %s succeeded' % name) except: # BTree check failed oldstdout = sys.stdout tmp = StringIO() try: sys.stdout = tmp display(btree) tmp.seek(0) LOG('Transience', WARNING, 'BTree check for %s failed' % name, tmp.read(), error=sys.exc_info()) tmp.close() finally: sys.stdout = oldstdout
-- John Eikenberry [jae@kavi.com] ______________________________________________________________ "A society that will trade a little liberty for a little order will deserve neither and lose both." --B. Franklin
OK, thanks John. Let's try one more thing... currently the mounted database used to store the session data uses a connection that ignores read conflicts. This is known to be bad because the machinery which deals with keeping the sessioning index data will also ignore read conflicts, which may create inconcstencies between two data structures (BTrees) that need to be kept in sync. Here's a patch to lib/python/Products/TemporaryFolder/TemporaryFolder.py that reenables read conflict generation on the database. Index: TemporaryFolder.py =================================================================== RCS file: /cvs-repository/Zope/lib/python/Products/TemporaryFolder/TemporaryFolder.py,v retrieving revision 1.7 diff -r1.7 TemporaryFolder.py 72c72 < db.klass = LowConflictConnection ---
#db.klass = LowConflictConnection
You may see many more conflicts with this running. But maybe the data structures will not become desynchronized. Another problem, still unexplained, experienced by Andrew Athan, is that if a reference is made to a session data object from within the standard error message, somehow things get screwy under high load. If you're doing the same, please let me know. - C On Fri, 2003-03-14 at 06:48, John Eikenberry wrote:
Chris McDonough wrote:
OK, thanks John.
Thank you for helping.
I hate to ask this (I should have done this to start with), but would you be willing to use the following patch --against the original file, not your recently patched version-- and try again? I only checked one of the two BTrees that might be at the heart of the problem with the first patch, this patch checks the second as well.
Put the patch in place and have a couple errors already. Doesn't look like its going to be much help though. Just a couple repetitions of this:
------ 2003-03-14T03:35:53 PROBLEM(100) Transience KeyError raised in get, checking BTrees ------ 2003-03-14T03:35:53 PROBLEM(100) Transience BTree check for data succeeded ------ 2003-03-14T03:35:53 PROBLEM(100) Transience BTree check for index succeeded
- C
On Thu, 2003-03-13 at 18:18, John Eikenberry wrote:
Patch applied and the first results are in... so far its a lot of these:
2003-03-13T15:18:07 PROBLEM(100) Transience KeyError raised in get, checking _data BTree ------ 2003-03-13T15:18:07 PROBLEM(100) Transience BTree check succeeded
Chris McDonough wrote:
Hi John,
Can you apply the attached diff to your Transience.py file and run with it in place for a couple of days? It will not fix the problem (the symptoms will remain) but it should print some diagnostic information to the Zope event log (the STUPID_LOG_FILE, hopefully you've got that going) that will help us track down what this might be.
Once you notice it happen, send the relevant parts of your logfile to me and I will see if I can analyze it.
- C
On Thu, 2003-03-13 at 15:19, John Eikenberry wrote:
Sorry, its Zope 2.6.1.
Chris McDonough wrote:
John,
Which Zope 2.6? Zope 2.6.1? Here's what line 807 of the current Transience.py looks like:
v = self._data[b].get(k, notfound)
Does yours look like that?
Yes.
What is the value of the __version__ variable at the top of the Transience.py file?
__version__='$Revision: 1.28.6.4 $'[11:-2]
On Thu, 2003-03-13 at 07:11, John Eikenberry wrote: > Since upgrading to Zope-2.6 we've been getting KeyErrors when using > Sessions. They seem to happen more now that we've started using > hasSessionData(), but I'm pretty sure they happened prior to that. > > Anyways, here are the 2 related tracebacks. Has anyone else seen these? > > Traceback #1 occurs most frequently. The KeyError's value is an unprintable > string of non-ascii characters. > > * Module ZPublisher.Publish, line 150, in publish_module > * Module ZPublisher.Publish, line 114, in publish > * Module The application server.App.startup, line 182, in > zpublisher_exception_hook > * Module ZPublisher.Publish, line 98, in publish > * Module ZPublisher.mapply, line 88, in mapply > * Module ZPublisher.Publish, line 39, in call_object > * Module App.special_dtml, line 61, in __call__ > * Module DocumentTemplate.DT_String, line 474, in __call__ > * Module Products.Transience.Transience, line 342, in nudge > * Module Products.Transience.Transience, line 467, in _getCurrentBucket > * Module Products.TemporaryFolder.LowConflictConnection, line 34, in > setstate > * Module Products.TemporaryFolder.TemporaryStorage, line 94, in load > KeyError: > > Traceback #2 happens less frequently, though today it seemed like it was > trying to catch up (3 of these today). > > * Module ZPublisher.Publish, line 98, in publish > * Module ZPublisher.mapply, line 88, in mapply > * Module ZPublisher.Publish, line 39, in call_object > * Module OFS.DTMLMethod, line 126, in __call__ > * Module DocumentTemplate.DT_String, line 474, in __call__ > * Module Products.DotOrg.Pages.KContent, line 149, in __call__ > * Module Products.DotOrg.Pages.KContent, line 194, in getEditInfo > * Module Products.DotOrg.Pages.KContent, line 506, in hasSessionData > * Module Products.Sessions.SessionDataManager, line 101, in hasSessionData > * Module Products.Sessions.SessionDataManager, line 175, in > _hasSessionDataObject > * Module Products.Transience.Transience, line 838, in has_key > * Module Products.Transience.Transience, line 807, in get > > KeyError: 1047409860 > > > -- > > John Eikenberry [jae@kavi.com] > ______________________________________________________________ > "A society that will trade a little liberty for a little order > will deserve neither and lose both." > --B. Franklin > > _______________________________________________ > 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 )
--
John Eikenberry [jae@kavi.com] ______________________________________________________________ "A society that will trade a little liberty for a little order will deserve neither and lose both." --B. Franklin
_______________________________________________ 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 )
? btreecheck.diff ? kedaipatch Index: Transience.py =================================================================== RCS file: /cvs-repository/Zope/lib/python/Products/Transience/Transience.py,v retrieving revision 1.28.6.4 diff -r1.28.6.4 Transience.py 34a35
from BTrees.check import check, display 45a47 from cStringIO import StringIO 807c809,830 < v = self._data[b].get(k, notfound)
try: v = self._data[b].get(k, notfound) except KeyError: LOG('Transience', WARNING, 'KeyError raised in get, checking _data BTree') try: check(self._data) LOG('Transience', WARNING,'BTree check succeeded') except: # BTree check failed oldstdout = sys.stdout tmp = StringIO() try: sys.stdout = tmp display(self._data) tmp.seek(0) LOG('Transience', WARNING,'BTree check failed', tmp.read(), error=sys.exc_info()) tmp.close() finally: sys.stdout = oldstdout raise
--
John Eikenberry [jae@kavi.com] ______________________________________________________________ "A society that will trade a little liberty for a little order will deserve neither and lose both." --B. Franklin
_______________________________________________ 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 )
Index: Transience.py =================================================================== RCS file: /cvs-repository/Zope/lib/python/Products/Transience/Transience.py,v retrieving revision 1.28.6.4 diff -r1.28.6.4 Transience.py 807c807,814 < v = self._data[b].get(k, notfound) ---
try: v = self._data[b].get(k, notfound) except KeyError: LOG('Transience', WARNING, 'KeyError raised in get, checking BTrees') check_btree(self._data, 'data') check_btree(index, 'index') raise
954a962,981
def check_btree(btree, name): from BTrees.check import check, display from cStringIO import StringIO try: check(btree) LOG('Transience', WARNING,'BTree check for %s succeeded' % name) except: # BTree check failed oldstdout = sys.stdout tmp = StringIO() try: sys.stdout = tmp display(btree) tmp.seek(0) LOG('Transience', WARNING, 'BTree check for %s failed' % name, tmp.read(), error=sys.exc_info()) tmp.close() finally: sys.stdout = oldstdout
--
John Eikenberry [jae@kavi.com] ______________________________________________________________ "A society that will trade a little liberty for a little order will deserve neither and lose both." --B. Franklin
_______________________________________________ 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 )
Sorry for the length of this one... but I'm trying to braindump to give you as much info about the problem as possible. To be sure it doesn't get lost in my below ramblings, there is probably important peice of information I haven't mentioned yet... that is that these errors seem to coincide with the session data timeout setting [1]. I don't get the errors at all until the timeout is reached or has passed. [1] The timeout setting I'm refering to is denoted by the label: "Data object timeout value in minutes" on the /temp_folder/session_data object. Chris McDonough wrote:
OK, thanks John. Let's try one more thing... currently the mounted database used to store the session data uses a connection that ignores read conflicts. This is known to be bad because the machinery which deals with keeping the sessioning index data will also ignore read conflicts, which may create inconcstencies between two data structures (BTrees) that need to be kept in sync.
I tried this and it seemed to help some. I haven't seen the get() error we've been dicussing yet, but a the load() error just occurred (line 94 in TemporaryStorage - this was error #1 in my original email). Though the traceback is a bit different from my original email, as the LowConflictConnection isn't being used. Here's the new Traceback: Error Type: KeyError Error Value: [non-ascii chars] Traceback (innermost last): * Module ZPublisher.Publish, line 98, in publish * Module ZPublisher.mapply, line 88, in mapply * Module ZPublisher.Publish, line 39, in call_object * Module Products.DotOrg.Pages.KPage, line 110, in testSession * Module Products.DotOrg.Utils.Spawn, line 42, in launchProcess * Module Products.DotOrg.Utils.Spawn, line 73, in storeArgs * Module Products.Sessions.SessionDataManager, line 180, in * _getSessionDataObject * Module Products.Transience.Transience, line 175, in new_or_existing * Module Products.Transience.Transience, line 797, in get * Module Products.Transience.Transience, line 546, in _getCurrentBucket * Module ZODB.Connection, line 509, in setstate * Module Products.TemporaryFolder.TemporaryStorage, line 94, in load
Here's a patch to lib/python/Products/TemporaryFolder/TemporaryFolder.py that reenables read conflict generation on the database.
Index: TemporaryFolder.py =================================================================== RCS file: /cvs-repository/Zope/lib/python/Products/TemporaryFolder/TemporaryFolder.py,v retrieving revision 1.7 diff -r1.7 TemporaryFolder.py 72c72 < db.klass = LowConflictConnection ---
#db.klass = LowConflictConnection
You may see many more conflicts with this running. But maybe the data structures will not become desynchronized.
You weren't kidding about the increase in conflict errors.
Another problem, still unexplained, experienced by Andrew Athan, is that if a reference is made to a session data object from within the standard error message, somehow things get screwy under high load. If you're doing the same, please let me know.
Before this started happening there was a hasSessionData check getting called during standard error publishing, though we removed that early this week when this started happening. --- It might help you to better understand what might be causing the problem if you know where we're using sessions and how we can force this problem to occur. Not sure if this willl be of much help, but thought it couldn't hurt. We use sessions primarily as a sort of authenticated user marker. It just stored their username and a state field that get used in non-authenticated sections of our site to detect the user as having logged into the site (we can then raise an unautorized error to get the basic auth info for that user). Anyways, these calls happen on our basic Content class (subclassed from DTMLMethod) in its __call__() method. We use it a couple other places for small things, but this one sees the most use. I've figured out how to force these errors to happen to some extent. I've written a method that starts up a thread, which uses Client.call to call another method, which then basically just loops endlessly calling hasSessionData and getSessionData, incrementing a number in the session data and sleeping for a N number of seconds between loops. One of these guys will run forever without a problem. Once you start a second thread ReadConflictErrors start getting raised. Which thread gets the conflict and which one keeps working seems variable (probably just a timing thing). If I start enough of these threads I can cause the error to happen. But only once the session timeout is reached. Note that to help speed up getting the errors I either set the session time to 1 minute via _setTimeout() call or even manually tweak the appropriate session data managers attributes (_timeout_secs, _period and _timeout_slices) to very small values (ie. a few seconds). -- John Eikenberry [jae@kavi.com] ______________________________________________________________ "A society that will trade a little liberty for a little order will deserve neither and lose both." --B. Franklin
John Eikenberry wrote:
Once you start a second thread ReadConflictErrors start getting raised. Which thread gets the conflict and which one keeps working seems variable (probably just a timing thing). If I start enough of these threads I can cause the error to happen. But only once the session timeout is reached.
Of course, once I finally post this I notice that the behaviour is not really this way. If the sleep delay is set higher and in a way such that the 2 threads won't run at the same time very often, they will both run fine. Its only if they try to access the sessions at the same time that the ReadConflictError gets raised. Oh, and in my threading code I catch/print/ignore these errors so my threads will keep going. The threads also do a full commit each time through (to help better simulate actual usage). -- John Eikenberry [jae@kavi.com] ______________________________________________________________ "A society that will trade a little liberty for a little order will deserve neither and lose both." --B. Franklin
Thanks so much for helping to pin this down. Thanks for the observation that the error occurs more frequently when the timeout is small. This is likely because the timeout value directly impacts the frequency of "housekeeping" operations, where old buckets are garbage collected and new buckets are added. The housekeeping operations must confuse the underlying storage. I don't know how this could happen, but it does. I suspect it's related somehow to conflict errors. So we seem to have two bugs: - The first is that turning off read conflicts allows for the potential for the session data bucket and the session data index to become out of sync. I admit that I knew this already, but haven't figured out a way around it yet without having massive numbers of conflicts. That said, it may be that we can't avoid them and I may turn this behavior off in the next revision. Another alternative is to use a nonpersistent index, but that has other challenges ( it could also prevent the shared use of session data between ZEO clients). - The second is an unidentified (yet) bug in TemporaryStorage. Most of the code for TemporaryStorage came right out of the Berkeley "Packless" storage. I should probably try to replicate this under load (this should not be difficult).To verify the assertion that there really is a bug in TemporaryStorage without much trouble, you could temporarily put your transient object container (session_data) in the main database and point the session data manager at it and run for a while under this config. This is not recommended for production as it will cause main database bloat, however. If I find and fix the TemporaryStorage bug I will let you know. In the meantime, you can probably work around this by using a different non-undoing storage to put your session data in (e.g. Berkeley, or maybe DirectoryStorage?). - C On Fri, 2003-03-14 at 20:28, John Eikenberry wrote:
Sorry for the length of this one... but I'm trying to braindump to give you as much info about the problem as possible.
To be sure it doesn't get lost in my below ramblings, there is probably important peice of information I haven't mentioned yet... that is that these errors seem to coincide with the session data timeout setting [1]. I don't get the errors at all until the timeout is reached or has passed.
[1] The timeout setting I'm refering to is denoted by the label: "Data object timeout value in minutes" on the /temp_folder/session_data object.
Chris McDonough wrote:
OK, thanks John. Let's try one more thing... currently the mounted database used to store the session data uses a connection that ignores read conflicts. This is known to be bad because the machinery which deals with keeping the sessioning index data will also ignore read conflicts, which may create inconcstencies between two data structures (BTrees) that need to be kept in sync.
I tried this and it seemed to help some. I haven't seen the get() error we've been dicussing yet, but a the load() error just occurred (line 94 in TemporaryStorage - this was error #1 in my original email). Though the traceback is a bit different from my original email, as the LowConflictConnection isn't being used. Here's the new Traceback:
Error Type: KeyError Error Value: [non-ascii chars]
Traceback (innermost last):
* Module ZPublisher.Publish, line 98, in publish * Module ZPublisher.mapply, line 88, in mapply * Module ZPublisher.Publish, line 39, in call_object * Module Products.DotOrg.Pages.KPage, line 110, in testSession * Module Products.DotOrg.Utils.Spawn, line 42, in launchProcess * Module Products.DotOrg.Utils.Spawn, line 73, in storeArgs * Module Products.Sessions.SessionDataManager, line 180, in * _getSessionDataObject * Module Products.Transience.Transience, line 175, in new_or_existing * Module Products.Transience.Transience, line 797, in get * Module Products.Transience.Transience, line 546, in _getCurrentBucket * Module ZODB.Connection, line 509, in setstate * Module Products.TemporaryFolder.TemporaryStorage, line 94, in load
Here's a patch to lib/python/Products/TemporaryFolder/TemporaryFolder.py that reenables read conflict generation on the database.
Index: TemporaryFolder.py =================================================================== RCS file: /cvs-repository/Zope/lib/python/Products/TemporaryFolder/TemporaryFolder.py,v retrieving revision 1.7 diff -r1.7 TemporaryFolder.py 72c72 < db.klass = LowConflictConnection ---
#db.klass = LowConflictConnection
You may see many more conflicts with this running. But maybe the data structures will not become desynchronized.
You weren't kidding about the increase in conflict errors.
Another problem, still unexplained, experienced by Andrew Athan, is that if a reference is made to a session data object from within the standard error message, somehow things get screwy under high load. If you're doing the same, please let me know.
Before this started happening there was a hasSessionData check getting called during standard error publishing, though we removed that early this week when this started happening.
---
It might help you to better understand what might be causing the problem if you know where we're using sessions and how we can force this problem to occur. Not sure if this willl be of much help, but thought it couldn't hurt.
We use sessions primarily as a sort of authenticated user marker. It just stored their username and a state field that get used in non-authenticated sections of our site to detect the user as having logged into the site (we can then raise an unautorized error to get the basic auth info for that user). Anyways, these calls happen on our basic Content class (subclassed from DTMLMethod) in its __call__() method. We use it a couple other places for small things, but this one sees the most use.
I've figured out how to force these errors to happen to some extent. I've written a method that starts up a thread, which uses Client.call to call another method, which then basically just loops endlessly calling hasSessionData and getSessionData, incrementing a number in the session data and sleeping for a N number of seconds between loops. One of these guys will run forever without a problem.
Once you start a second thread ReadConflictErrors start getting raised. Which thread gets the conflict and which one keeps working seems variable (probably just a timing thing). If I start enough of these threads I can cause the error to happen. But only once the session timeout is reached.
Note that to help speed up getting the errors I either set the session time to 1 minute via _setTimeout() call or even manually tweak the appropriate session data managers attributes (_timeout_secs, _period and _timeout_slices) to very small values (ie. a few seconds).
--
John Eikenberry [jae@kavi.com] ______________________________________________________________ "A society that will trade a little liberty for a little order will deserve neither and lose both." --B. Franklin
_______________________________________________ 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 Saturday 15 March 2003 5:40 pm, Chris McDonough wrote:
- The second is an unidentified (yet) bug in TemporaryStorage.
As a cause of the KeyError exception? Could be.... I have seen equivalent exceptions with plain FileStorage in applications that do not use sessions, so I suspect there might be a hard-to-hit zodb bug that can cause this too. (In FileStorage the equivalent exception is POSKeyError, a subclass of KeyError)
If I find and fix the TemporaryStorage bug I will let you know. In the meantime, you can probably work around this by using a different non-undoing storage to put your session data in (e.g. Berkeley, or maybe DirectoryStorage?).
It would be interesting to hear if this exception is repeatable with the session state stored in a FileStorage too.
You may see many more conflicts with this running. But maybe the data structures will not become desynchronized.
You weren't kidding about the increase in conflict errors.
Read conflicts occur if a change is committed in between the start of a transaction, and the transaction needing to load the object. A workaround to reduce the number of read conflicts is to touch the objects that are likely to change early in the transaction. -- Toby Dickenson http://www.geminidataloggers.com/people/tdickenson
Toby Dickenson wrote:
Read conflicts occur if a change is committed in between the start of a transaction, and the transaction needing to load the object. A workaround to reduce the number of read conflicts is to touch the objects that are likely to change early in the transaction.
Thanks for the tip. My sessions test script had a sleep() call right after the transaction commit, thus making it right at the beginning of the next transaction. Moving it to right before the commit (after all the session tests) pretty much eliminated all the read conflict errors. Just get a standard ConflictError occasionally now (not nearly as often). -- John Eikenberry [jae@kavi.com] ______________________________________________________________ "A society that will trade a little liberty for a little order will deserve neither and lose both." --B. Franklin
John Eikenberry wrote:
Toby Dickenson wrote:
Read conflicts occur if a change is committed in between the start of a transaction, and the transaction needing to load the object. A workaround to reduce the number of read conflicts is to touch the objects that are likely to change early in the transaction.
Thanks for the tip. My sessions test script had a sleep() call right after the transaction commit, thus making it right at the beginning of the next transaction. Moving it to right before the commit (after all the session tests) pretty much eliminated all the read conflict errors. Just get a standard ConflictError occasionally now (not nearly as often).
This turned out to be better than I thought. After nearly 3 hours of constant abuse I have yet to see a ReadConflictError and have yet to get either the load() or get() KeyErrors, previously I could force one of these in a 2-3 minutes of abuse. Our live sessions code uses the sessions about half to two-thirds of the way through the transaction. Given what can happen in that first half, there is easily plenty of time for read conflicts. I think I might be able to move our session use to the beginning of the transaction (just storing stuff in the REQUEST object for later usage) and hopefully fix our issue. The KeyErrors happen under similar circumstances to the ReadConflictErrors. The significant difference being that the KeyErrors happen after the transience timeout has occured. When I am running with the LowConflictConnection disabled the KeyErrors occur in the Connection.setstate method at line 509, before the ReadConflictError check. So say you have 2 threads; A and B. If A starts first, hits the session code and triggers a _housekeep() call during which time B has started but has not reached the Sessions code until after _housekeep() has finished. When it does reach the sessions code, you get the KeyErrors. Sound reasonable? -- John Eikenberry [jae@kavi.com] ______________________________________________________________ "A society that will trade a little liberty for a little order will deserve neither and lose both." --B. Franklin
On Mon, 2003-03-17 at 20:34, John Eikenberry wrote:
John Eikenberry wrote:
Toby Dickenson wrote:
Read conflicts occur if a change is committed in between the start of a transaction, and the transaction needing to load the object. A workaround to reduce the number of read conflicts is to touch the objects that are likely to change early in the transaction.
Thanks for the tip. My sessions test script had a sleep() call right after the transaction commit, thus making it right at the beginning of the next transaction. Moving it to right before the commit (after all the session tests) pretty much eliminated all the read conflict errors. Just get a standard ConflictError occasionally now (not nearly as often).
This turned out to be better than I thought. After nearly 3 hours of constant abuse I have yet to see a ReadConflictError and have yet to get either the load() or get() KeyErrors, previously I could force one of these in a 2-3 minutes of abuse.
Our live sessions code uses the sessions about half to two-thirds of the way through the transaction. Given what can happen in that first half, there is easily plenty of time for read conflicts. I think I might be able to move our session use to the beginning of the transaction (just storing stuff in the REQUEST object for later usage) and hopefully fix our issue.
Interesting, and I'm very glad you got it working reliably. But I'm not sure I understand why touching an object at the start of a transaction would fix the consistency problem. If a object A is read at the beginning of a transaction that uses the data from object A during write of object B and later object A changes and is invalidated by another transaction (before the first finishes), no conflict errors will be raised. Isn't there the potential for the first transaction to write inconsistent data into object B? In my mind, this is the same thing as using a "low conflict connection" (ie. you are essentially "turning off" read conflicts, albeit by circumstance rather than by code). I guess the question boils down to: why *don't* you see consistency problems now? I would expect to continue to see the "get" errors you reported earlier. I think this exact problem is being discussed on ZODB-Dev under the title "Database Read Conflicts -- neither safe nor robust".
The KeyErrors happen under similar circumstances to the ReadConflictErrors. The significant difference being that the KeyErrors happen after the transience timeout has occured. When I am running with the LowConflictConnection disabled the KeyErrors occur in the Connection.setstate method at line 509, before the ReadConflictError check.
Is this the same KeyError you reported as coming out of TemporaryStorage.load?
So say you have 2 threads; A and B. If A starts first, hits the session code and triggers a _housekeep() call during which time B has started but has not reached the Sessions code until after _housekeep() has finished. When it does reach the sessions code, you get the KeyErrors.
Would you mind restating that? I think this is important, and I'm not sure I understand the second sentence above. Thanks! - C
On Tuesday 18 March 2003 3:24 pm, Chris McDonough wrote:
Our live sessions code uses the sessions about half to two-thirds of the way through the transaction. Given what can happen in that first half, there is easily plenty of time for read conflicts. I think I might be able to move our session use to the beginning of the transaction (just storing stuff in the REQUEST object for later usage) and hopefully fix our issue.
Depending on what your sessioning involves, you might not need to change when you do all the "work". Possibly just touching (an attribute of) the persistent session object will be enough.
But I'm not sure I understand why touching an object at the start of a transaction would fix the consistency problem. If a object A is read at the beginning of a transaction that uses the data from object A during write of object B and later object A changes and is invalidated by another transaction (before the first finishes), no conflict errors will be raised. Isn't there the potential for the first transaction to write inconsistent data into object B?
Today you are guaranteed that your transaction reads a consistent initial state of A and B. That is, there is no chance that you only see half the changes of a recent transaction that modified both. Yes, it is possible for one transaction to modify A and a concurrent transaction to modify B. This is what Deiter describes as "not safe" in that zodb-dev thread. IMO, it is only not safe if you are not aware of it. And it is critical for performance with concurrency - consider these two transactions occuring on different zeo nodes.
In my mind, this is the same thing as using a "low conflict connection" (ie. you are essentially "turning off" read conflicts, albeit by circumstance rather than by code).
There is a significant difference. The low conflict connection permits the possibility of seeing half the changes of a recent transaction that modified both objects. "low conflict connection" is a misleadnig name. The conflicts are still there - just not reported as exceptions. "low consistency connection" would be more accurate ;-)
Today you are guaranteed that your transaction reads a consistent initial state of A and B. That is, there is no chance that you only see half the changes of a recent transaction that modified both.
Yes, it is possible for one transaction to modify A and a concurrent transaction to modify B. This is what Deiter describes as "not safe" in that zodb-dev thread. IMO, it is only not safe if you are not aware of it. And it is critical for performance with concurrency - consider these two transactions occuring on different zeo nodes.
Right, I understand now, thank you.
In my mind, this is the same thing as using a "low conflict connection" (ie. you are essentially "turning off" read conflicts, albeit by circumstance rather than by code).
There is a significant difference. The low conflict connection permits the possibility of seeing half the changes of a recent transaction that modified both objects.
"low conflict connection" is a misleadnig name. The conflicts are still there - just not reported as exceptions. "low consistency connection" would be more accurate ;-)
Yup. Maybe I should rename it? ;-) So... I'm wondering what the hell I should do. ;-) Obviously I need to deactivate the "low consistency connection" in the default setup. I'm thinking that I also may just need to move the housekeeping duties to a separate scheduled thread that only happens when the system is "not busy" (e.g. when the asyncore poll select timeout is reached maybe) in order to reduce the potential for conflicts. But I'm not sure what else to do, and I still don't understand what is causing the KeyErrors in the storage code. Sigh. - C
On Tuesday 18 March 2003 6:12 pm, Chris McDonough wrote:
I'm thinking that I also may just need to move the housekeeping duties to a separate scheduled thread that only happens when the system is "not busy" (e.g. when the asyncore poll select timeout is reached maybe) in order to reduce the potential for conflicts.
Thats hard to define, when zeo is installed.
But I'm not sure what else to do, and I still don't understand what is causing the KeyErrors in the storage code. Sigh.
Ive never looked at nor used your Sessioning support, but I am interested in things that can cause (POS)KeyErrors in Storages..... This might not be a storage bug. There are several known corner cases in zodb that mean semi-legitimate applications can cause KeyErrors. DirectoryStorage tries to guard against them, and will raise a DanglingReferenceError rather than commit a transaction that will cause a POSKeyError when read. Can the problem be reproduced using DirectoryStorage? (without the "low consistency connection") -- Toby Dickenson http://www.geminidataloggers.com/people/tdickenson
On Tue, 2003-03-18 at 14:01, Toby Dickenson wrote:
On Tuesday 18 March 2003 6:12 pm, Chris McDonough wrote:
I'm thinking that I also may just need to move the housekeeping duties to a separate scheduled thread that only happens when the system is "not busy" (e.g. when the asyncore poll select timeout is reached maybe) in order to reduce the potential for conflicts.
Thats hard to define, when zeo is installed.
It would only make sense for shared session data if the housekeeping thread was enabled on a single ZEO client in a cluster. Of course this scenario has its own configuration and management difficulties.
But I'm not sure what else to do, and I still don't understand what is causing the KeyErrors in the storage code. Sigh.
Ive never looked at nor used your Sessioning support, but I am interested in things that can cause (POS)KeyErrors in Storages.....
This might not be a storage bug. There are several known corner cases in zodb that mean semi-legitimate applications can cause KeyErrors. DirectoryStorage tries to guard against them, and will raise a DanglingReferenceError rather than commit a transaction that will cause a POSKeyError when read. Can the problem be reproduced using DirectoryStorage? (without the "low consistency connection")
That's a fine question. ;-) John, did you see these Key Errors happen under a storage other than TemporaryStorage (e.g. if the session data container is in the main database)? I will check myself as well when possible. Dieter also observed that this may be a behavior specific to mounted storages, so I will need to try that as well. - C
Chris McDonough wrote:
On Mon, 2003-03-17 at 20:34, John Eikenberry wrote:
The KeyErrors happen under similar circumstances to the ReadConflictErrors. The significant difference being that the KeyErrors happen after the transience timeout has occured. When I am running with the LowConflictConnection disabled the KeyErrors occur in the Connection.setstate method at line 509, before the ReadConflictError check.
Is this the same KeyError you reported as coming out of TemporaryStorage.load?
Yes. I'm referring to the traceback I reported in a previous mail: http://mail.zope.org/pipermail/zope-dev/2003-March/019118.html The error occurs on the same line in TemporaryStorage.load(), whether it gets called from ZODB/Connection.py or TemporaryFolder/LowConflictConnection.py.
So say you have 2 threads; A and B. If A starts first, hits the session code and triggers a _housekeep() call during which time B has started but has not reached the Sessions code until after _housekeep() has finished. When it does reach the sessions code, you get the KeyErrors.
Would you mind restating that? I think this is important, and I'm not sure I understand the second sentence above.
I'm working off the idea that the load() KeyErrors went away when the ReadConflictErrors did. So it seemed like they were probably triggered by similar scenarios. The difference being that for the former, the timeout had been reached and the _housekeep() code had been run (and possibly some additional code in _getCurrentBucket). Now given Toby's description of how ReadConflicts occur [1], it seems that instead of a change being committed to the object it is instead deleted (in _housekeep). Thus instead of getting the object and seeing it is marked as invalid, it cannot get the object at all when it expects to be able to... resulting in the KeyError in load(). [1] "Read conflicts occur if a change is committed in between the start of a transaction, and the transaction needing to load the object. A workaround to reduce the number of read conflicts is to touch the objects that are likely to change early in the transaction." -- John Eikenberry [jae@kavi.com] ______________________________________________________________ "A society that will trade a little liberty for a little order will deserve neither and lose both." --B. Franklin
Hi Chris, Chris McDonough wrote at 2003-3-15 12:40 -0500:
... - The first is that turning off read conflicts allows for the potential for the session data bucket and the session data index to become out of sync. I admit that I knew this already, but haven't figured out a way around it yet without having massive numbers of conflicts. That said, it may be that we can't avoid them and I may turn this behavior off in the next revision. Another alternative is to use a nonpersistent index, but that has other challenges ( it could also prevent the shared use of session data between ZEO clients).
You know that we use a Transience implementation with minimal (and not very essential) administrative data which is immune to inconsistencies and can be used across several ZEO clients (although we do not use that). We have good experience with this implementation.
- The second is an unidentified (yet) bug in TemporaryStorage. Most of the code for TemporaryStorage came right out of the Berkeley "Packless" storage. I should probably try to replicate this under load (this should not be difficult).To verify the assertion that there really is a bug in TemporaryStorage without much trouble, you could temporarily put your transient object container (session_data) in the main database and point the session data manager at it and run for a while under this config. This is not recommended for production as it will cause main database bloat, however.
The problem might also be the "MountPoint" -- with the connection to the TemporaryStorage not correctly synchronized with the transaction. Dieter
On Mon, 2003-03-17 at 15:02, Dieter Maurer wrote:
You know that we use a Transience implementation with minimal (and not very essential) administrative data which is immune to inconsistencies and can be used across several ZEO clients (although we do not use that).
We have good experience with this implementation.
Does this package implement a similar API as the existing Transience package? Would you be willing to send it to me?
The problem might also be the "MountPoint" -- with the connection to the TemporaryStorage not correctly synchronized with the transaction.
Good point, thanks. - C
participants (4)
-
Chris McDonough -
Dieter Maurer -
John Eikenberry -
Toby Dickenson