Re: POSKeyError when getting Zope SESSION

Hi again,

Today I *did* get a traceback, including debugging info.
It probably happens when the browser tries to load several resources in 
parallel, handled by different threads.
In each request I write something to the session (which I shouldn't do, 
but that seems to help in triggering the error).

At first some debugging info where all still seems fine:

2018-03-07 11:39:12 INFO Transience 123145425707008 1520419152.26 
_move_item: keys for ts 1520418980 (bucket 4534646400)-- 
['89172937J1x4MDNceGM1XHhlOVx4MTBceGUyXHhkOFx4MGYiJw']
2018-03-07 11:39:12 INFO Transience 123145429913600 1520419152.26 
_move_item: bucket for ts 1520419020 is 4542801248
2018-03-07 11:39:12 INFO Transience 123145425707008 1520419152.26 
_move_item: found_ts is 1520418980
2018-03-07 11:39:12 INFO Transience 123145429913600 1520419152.27 
_move_item: keys for ts 1520419020 (bucket 4542801248)-- []
2018-03-07 11:39:12 INFO Transience 123145425707008 1520419152.27 
_move_item: current_ts (1520419140) != found_ts (1520418980), moving to 
current
2018-03-07 11:39:12 INFO Transience 123145429913600 1520419152.27 
_move_item: bucket for ts 1520419000 is 4542801392
2018-03-07 11:39:12 INFO Transience 123145425707008 1520419152.27 
_move_item: keys for found_ts 1520418980 (bucket 4534646400): 
['89172937J1x4MDNceGM1XHhlOVx4MTBceGUyXHhkOFx4MGYiJw']
2018-03-07 11:39:12 INFO Transience 123145429913600 1520419152.27 
_move_item: keys for ts 1520419000 (bucket 4542801392)-- []
2018-03-07 11:39:12 INFO Transience 123145425707008 1520419152.27 
_move_item: copied item 
89172937J1x4MDNceGM1XHhlOVx4MTBceGUyXHhkOFx4MGYiJw from 1520418980 to 
1520419140 (bucket 4544108016)
2018-03-07 11:39:12 INFO Transience 123145429913600 1520419152.27 
_move_item: bucket for ts 1520418980 is 4542801824
2018-03-07 11:39:12 INFO Transience 123145425707008 1520419152.27 
_move_item: deleted item 
89172937J1x4MDNceGM1XHhlOVx4MTBceGUyXHhkOFx4MGYiJw from ts 1520418980 
(bucket 4534646400)
2018-03-07 11:39:12 INFO Transience 123145429913600 1520419152.27 
_move_item: keys for ts 1520418980 (bucket 4542801824)-- 
['89172937J1x4MDNceGM1XHhlOVx4MTBceGUyXHhkOFx4MGYiJw']
2018-03-07 11:39:12 INFO Transience 123145425707008 1520419152.27 
_move_item: returning 89172937J1x4MDNceGM1XHhlOVx4MTBceGUyXHhkOFx4MGYiJw 
from current_ts 1520419140
2018-03-07 11:39:12 INFO Transience 123145429913600 1520419152.27 
_move_item: found_ts is 1520418980
2018-03-07 11:39:12 INFO Transience 123145429913600 1520419152.27 
_move_item: current_ts (1520419140) != found_ts (1520418980), moving to 
current
2018-03-07 11:39:12 INFO Transience 123145429913600 1520419152.27 
_move_item: keys for found_ts 1520418980 (bucket 4542801824): 
['89172937J1x4MDNceGM1XHhlOVx4MTBceGUyXHhkOFx4MGYiJw']
2018-03-07 11:39:12 INFO Transience 123145429913600 1520419152.27 
_move_item: copied item 
89172937J1x4MDNceGM1XHhlOVx4MTBceGUyXHhkOFx4MGYiJw from 1520418980 to 
1520419140 (bucket 4542800384)
2018-03-07 11:39:12 INFO Transience 123145429913600 1520419152.27 
_move_item: deleted item 
89172937J1x4MDNceGM1XHhlOVx4MTBceGUyXHhkOFx4MGYiJw from ts 1520418980 
(bucket 4542801824)

And then, presumably in a different request, it starts going wrong:

2018-03-07 11:39:12 INFO ZPublisher.Conflict ReadConflictError at 
/Plone/++plone++static/++unique++2018-03-02 
16:36:34.751840/plone-legacy-compiled.css: 
'\x00\x00\x00\x00\x00\x00\x00+' (1 conflicts (0 unresolved) since 
startup at Wed Mar  7 11:36:11 2018)
2018-03-07 11:39:12 INFO Transience 123145425707008 1520419152.27 
new_or_existing called with 
89172937J1x4MDNceGM1XHhlOVx4MTBceGUyXHhkOFx4MGYiJw
2018-03-07 11:39:12 INFO Transience 123145425707008 1520419152.27 get: 
called with key 89172937J1x4MDNceGM1XHhlOVx4MTBceGUyXHhkOFx4MGYiJw, 
default []
2018-03-07 11:39:12 INFO Transience 123145425707008 1520419152.27 
_finalize: lock acquired successfully
2018-03-07 11:39:12 INFO Transience 123145429913600 1520419152.58 
new_or_existing called with 
89172937J1x4MDNceGM1XHhlOVx4MTBceGUyXHhkOFx4MGYiJw
2018-03-07 11:39:12 INFO Transience 123145429913600 1520419152.58 get: 
called with key 89172937J1x4MDNceGM1XHhlOVx4MTBceGUyXHhkOFx4MGYiJw, 
default []
2018-03-07 11:39:12 INFO Transience 123145429913600 1520419152.58 
_finalize: could not acquire lock, returning
2018-03-07 11:39:12 INFO Transience 123145429913600 1520419152.58 
_replentish: attempting optional replentish (lock acquired)
2018-03-07 11:39:12 INFO Transience 123145429913600 1520419152.58 roll: 
low: 76020957, high: 76020977: lost with 76020967 (optional replentish)
2018-03-07 11:39:12 INFO Transience 123145429913600 1520419152.58 roll: 
low: 0, high: 5: won with 0 (gc)
2018-03-07 11:39:12 INFO Transience 123145429913600 1520419152.58 _gc: 
(1520419140 -1520418960) > 160.0, gc invoked
2018-03-07 11:39:12 INFO Transience 123145429913600 1520419152.58 
_do_gc_work: entering
2018-03-07 11:39:12 ERROR ZODB.Connection Couldn't load state for 
Products.Transience.Transience.Increaser 0x09
Traceback (most recent call last):
   File 
"/Users/maurits/shared-eggs/cp27m/ZODB-5.3.0-py2.7.egg/ZODB/Connection.py", 
line 796, in setstate
     p, serial = self._storage.load(oid)
   File 
"/Users/maurits/shared-eggs/cp27m/ZODB-5.3.0-py2.7.egg/ZODB/mvccadapter.py", 
line 143, in load
     r = self._storage.loadBefore(oid, self._start)
   File 
"/Users/maurits/shared-eggs/cp27m/tempstorage-4.0.1-py2.7.egg/tempstorage/TemporaryStorage.py", 
line 187, in loadBefore
     raise POSException.POSKeyError(oid)
POSKeyError: 0x09

And a couple more for good measure:

2018-03-07 11:39:12 ERROR ZODB.Connection Couldn't load state for 
Products.Transience.Transience.Increaser 0x09
Traceback (most recent call last):
   File 
"/Users/maurits/shared-eggs/cp27m/ZODB-5.3.0-py2.7.egg/ZODB/Connection.py", 
line 796, in setstate
     p, serial = self._storage.load(oid)
   File 
"/Users/maurits/shared-eggs/cp27m/ZODB-5.3.0-py2.7.egg/ZODB/mvccadapter.py", 
line 143, in load
     r = self._storage.loadBefore(oid, self._start)
   File 
"/Users/maurits/shared-eggs/cp27m/tempstorage-4.0.1-py2.7.egg/tempstorage/TemporaryStorage.py", 
line 187, in loadBefore
     raise POSException.POSKeyError(oid)
POSKeyError: 0x09
2018-03-07 11:39:12 ERROR client.myplugin KeyError getting SESSION for 
request 
http://localhost:8080/Plone/++theme++barceloneta/less/barceloneta-compiled.css
Traceback (most recent call last):
   File 
"/Users/maurits/clients/client/project/src/client.myplugin/src/client/myplugin/plugins.py", 
line 31, in get_session
     return request.SESSION
   File 
"/Users/maurits/shared-eggs/cp27m/Zope2-2.13.26-py2.7.egg/ZPublisher/HTTPRequest.py", 
line 1380, in __getattr__
     v = self.get(key, default, returnTaints=returnTaints)
   File 
"/Users/maurits/shared-eggs/cp27m/Zope2-2.13.26-py2.7.egg/ZPublisher/HTTPRequest.py", 
line 1337, in get
     v = v()
   File 
"/Users/maurits/shared-eggs/cp27m/Zope2-2.13.26-py2.7.egg/Products/Sessions/SessionDataManager.py", 
line 101, in getSessionData
     return self._getSessionDataObject(key)
   File 
"/Users/maurits/shared-eggs/cp27m/Zope2-2.13.26-py2.7.egg/Products/Sessions/SessionDataManager.py", 
line 188, in _getSessionDataObject
     ob = container.new_or_existing(key)
   File 
"/Users/maurits/shared-eggs/cp27m/Zope2-2.13.26-py2.7.egg/Products/Transience/Transience.py", 
line 839, in new_or_existing
     item = self.get(key, _marker)
   File 
"/Users/maurits/shared-eggs/cp27m/Zope2-2.13.26-py2.7.egg/Products/Transience/Transience.py", 
line 495, in get
     item = self._move_item(k, current_ts, default)
   File 
"/Users/maurits/shared-eggs/cp27m/Zope2-2.13.26-py2.7.egg/Products/Transience/Transience.py", 
line 285, in _move_item
     self._housekeep(current_ts)
   File 
"/Users/maurits/shared-eggs/cp27m/Zope2-2.13.26-py2.7.egg/Products/Transience/Transience.py", 
line 934, in _housekeep
     self._finalize(now)
   File 
"/Users/maurits/shared-eggs/cp27m/Zope2-2.13.26-py2.7.egg/Products/Transience/Transience.py", 
line 551, in _finalize
     last_finalized = self._last_finalized_timeslice()
   File 
"/Users/maurits/shared-eggs/cp27m/Zope2-2.13.26-py2.7.egg/Products/Transience/Transience.py", 
line 1071, in __call__
     return self.value
   File 
"/Users/maurits/shared-eggs/cp27m/ZODB-5.3.0-py2.7.egg/ZODB/Connection.py", 
line 796, in setstate
     p, serial = self._storage.load(oid)
   File 
"/Users/maurits/shared-eggs/cp27m/ZODB-5.3.0-py2.7.egg/ZODB/mvccadapter.py", 
line 143, in load
     r = self._storage.loadBefore(oid, self._start)
   File 
"/Users/maurits/shared-eggs/cp27m/tempstorage-4.0.1-py2.7.egg/tempstorage/TemporaryStorage.py", 
line 187, in loadBefore
     raise POSException.POSKeyError(oid)
POSKeyError: 0x09
2018-03-07 11:39:12 WARNING client.myplugin SESSION is None in 
extractCredentials.

So the error happens in Products.Transience in _do_gc_work.  At least 
that is the last line before the first error:

2018-03-07 11:39:12 INFO Transience 123145429913600 1520419152.58 
_do_gc_work: entering

That method looks like this:


     def _do_gc_work(self, now):
         # this is only separated from _gc for readability; it should
         # generally not be called by anything but _gc

         # we garbage collect any buckets that have already been run
         # through finalization
         DEBUG and TLOG('_do_gc_work: entering')

         max_ts = self._last_finalized_timeslice()

         DEBUG and TLOG('_do_gc_work: max_ts is %s' % max_ts)
	...

Since the second DEBUG line is not printed, it must go wrong in the line 
between, when calling self._last_finalized_timeslice.
That is an instance of a very simple Persistent class in Transience.py:


class Increaser(Persistent):
     """
     A persistent object representing a typically increasing integer that
     has conflict resolution which uses the greatest integer out of the 
three
     available states.
     """
     def __init__(self, v):
         self.value = v

     def set(self, v):
         self.value = v

     def __getstate__(self):
         return self.value

     def __setstate__(self, v):
         self.value = v

     def __call__(self):
         return self.value

     def _p_resolveConflict(self, old, state1, state2):
         return max(old, state1, state2)

Looks okay, but I am not used to checking code that handles persistence.
This is in Zope 2.13, but the Transience.py file has not changed between 
than and current Zope 4 (apart from being separated out into the 
Products.Sessions package.)  The last code change before that, was in 
2010.  So it seems weird if I were to be the first one to run into 
problems with this. :-)

I'll create an issue on github in one of the zopefoundation repos too.

But does the above look like anything that would require a fix in ZODB, 
or that points to wrong usage of the ZODB?
For clarity again: this is all in temporarystorage.

Kind regards,

Maurits van Rees
Zest Software


Op 06-03-18 om 18:36 schreef Maurits van Rees:
> I tried creating a simple script to reproduce it, but I failed.
> Today I did not see the error at all.
> I enabled a debugging environment variable Z_TOC_DEBUG from 
> Products.Transience, but since the error did not happen since then, I 
> have no debug data from it...
> Maybe it only fails when a BTree in the session needs to be reshuffled 
> or something.
> 
> My current plan is to avoid using a session for this, and instead store 
> what I need in a cookie.  That should also avoid possible problems in a 
> setup with multiple zeoclients.
> 
> But does anyone have an idea what is going on here and how to avoid this?
> 
> Again, full details are at:
> https://community.plone.org/t/sessions-and-poskeyerrors/5939

-- 
You received this message because you are subscribed to the Google Groups "zodb" group.
To unsubscribe from this group and stop receiving emails from it, send an email to [email protected].
For more options, visit https://groups.google.com/d/optout.