ZEO TempStorage: Odd behavior on ZEO restart
Hi all, We're working on a large scale Plone deployment and recently came across some odd behavior with tempstorage at our ZEO server. A limited number, yet highly frequented, of pages on our Plone site query backend web services that provide location based services such as geocoding and routing (a to b). Since those calls to the services are rather computation intense we decided to store intermediate and resulting data in sessions vs. re-querying the service for no reason. The system setup consists of a central ZEO server that provides the storage for content as well as a temp storage for sessioning. There are multiple other servers that run multiple Plone instances with ZEO clients. The ZEO server setup is straight forward but I'm happy to provide the configuration files. Generally the concept works great. However, whenever we restart the ZEO server and keep the client instances running we get odd behavior with the client instances' sessioning. Every client appears to reconnect and, if required, revalidates its cache. 2010-07-11T14:46:03 INFO ZEO.ClientStorage (6132) Disconnected from storage: "('ITIS.mentzdv.de', 8100)" 2010-07-11T14:46:03 INFO ZEO.ClientStorage (6132) Disconnected from storage: "('ITIS.mentzdv.de', 8100)" 2010-07-11T14:46:09 INFO ZEO.ClientStorage (6132) Testing connection <ManagedClientConnection ('127.0.0.1', 8100)> 2010-07-11T14:46:09 INFO ZEO.zrpc.Connection(C) (127.0.0.1:8100) received handshake 'Z303' 2010-07-11T14:46:09 INFO ZEO.ClientStorage (6132) Server authentication protocol None 2010-07-11T14:46:09 INFO ZEO.ClientStorage (6132) Connected to storage: (' ITIS.mentzdv.de', 8100) 2010-07-11T14:46:09 INFO ZEO.ClientStorage (6132) Testing connection <ManagedClientConnection ('127.0.0.1', 8100)> 2010-07-11T14:46:09 INFO ZEO.ClientStorage (6132) last inval tid: '\x03\x87n\x9d|\x1a\xc2\xaa' 2010-07-11 04:45:29.087000 2010-07-11T14:46:09 INFO ZEO.ClientStorage (6132) last transaction: '\x00\x00\x00\x00\x00\x00\x00\x00' 1900-01-01 00:00:00.000000 2010-07-11T14:46:09 INFO ZEO.zrpc.Connection(C) (127.0.0.1:8100) received handshake 'Z303' 2010-07-11T14:46:10 INFO ZEO.ClientStorage (6132) Verifying cache 2010-07-11T14:46:10 INFO ZEO.ClientStorage (6132) Server authentication protocol None 2010-07-11T14:46:10 INFO ZEO.ClientStorage (6132) Connected to storage: (' ITIS.mentzdv.de', 8100) 2010-07-11T14:46:10 INFO ZEO.ClientStorage (6132) No verification necessary (last_inval_tid up-to-date) 2010-07-11T14:46:10 INFO ZEO.ClientStorage (6132) endVerify finishing 2010-07-11T14:46:10 INFO ZEO.ClientStorage (6132) endVerify finished The problem is that whenever we hit a session bound page we get following error and stack trace: 2010-07-11T14:58:12 ERROR ZODB.Connection Couldn't load state for 0x82 Traceback (most recent call last): File "g:\mentzdv\plone\instances\zeo04\zope2\lib\python\ZODB\Connection.py", line 761, in setstate self._setstate(obj) File "g:\mentzdv\plone\instances\zeo04\zope2\lib\python\ZODB\Connection.py", line 801, in _setstate p, serial = self._storage.load(obj._p_oid, self._version) File "G:\mentzdv\plone\instances\zeo04\zope2\lib\python\ZEO\ClientStorage.py", line 727, in load return self.loadEx(oid, version)[:2] File "G:\mentzdv\plone\instances\zeo04\zope2\lib\python\ZEO\ClientStorage.py", line 750, in loadEx data, tid, ver = self._server.loadEx(oid, version) File "G:\mentzdv\plone\instances\zeo04\zope2\lib\python\ZEO\ServerStub.py", line 196, in loadEx return self.rpc.call("loadEx", oid, version) File "G:\mentzdv\plone\instances\zeo04\zope2\lib\python\ZEO\zrpc\connection.py", line 650, in call raise inst # error raised by server KeyError: '\x00\x00\x00\x00\x00\x00\x00\x82' In the ZMI under the Control-Panel/Database Tab the temporary database seems to be fine. The /temp_folder returns a similar stack trace though: Site Error An error was encountered while publishing this resource. *KeyError* Sorry, a site error occurred. Traceback (innermost last): - Module ZPublisher.Publish, line 202, in publish_module_standard - Module ZPublisher.Publish, line 150, in publish - Module plone.app.linkintegrity.monkey, line 21, in zpublisher_exception_hook_wrapper - Module Zope2.App.startup, line 221, in zpublisher_exception_hook - Module ZPublisher.Publish, line 119, in publish - Module ZPublisher.mapply, line 88, in mapply - Module ZPublisher.Publish, line 42, in call_object - Module App.special_dtml, line 65, in __call__ - Module DocumentTemplate.DT_String, line 476, in __call__ - Module Products.Transience.Transience, line 926, in housekeep - Module Products.Transience.Transience, line 929, in _housekeep - Module Products.Transience.Transience, line 569, in _finalize - Module Products.Transience.Transience, line 593, in _do_finalize_work - Module ZODB.Connection, line 761, in setstate - Module ZODB.Connection, line 801, in _setstate - Module ZEO.ClientStorage, line 727, in load - Module ZEO.ClientStorage, line 750, in loadEx - Module ZEO.ServerStub, line 196, in loadEx - Module ZEO.zrpc.connection, line 650, in call KeyError: '\x00\x00\x00\x00\x00\x00\x00\x82' (Also, the following error occurred while attempting to render the standard error message, please see the event log for full details: You are not allowed to access 'title_or_id' in this context) We know for a fact that one client instance needs to create the actual temporary container at the ZEO server upon its restart. Restarting a single client instance will make make this instance work but unfortunately won't recover all other client instances. All of those problems disappear as soon as we restart all instances; until the next ZEO server restart of course. The problem doesn't appear to happen if connections drops happen but the ZEO server keeps running. Is that behavior intentional? Any kind of help is very much appreciated. We're currently using following versions (yes, we're also running on windows but I find it hard to believe that the OS is causing those issues). Zope Version (Zope 2.10.9-final, python 2.4.4, win32) Python Version 2.4.4 (#71, Oct 18 2006, 08:34:43) [MSC v.1310 32 bit (Intel)] System Platform win32 SOFTWARE_HOME G:\mentzdv\plone\instances\zeo04\zope2\lib\python ZOPE_HOME G:\mentzdv\plone\instances\zeo04\zope2 INSTANCE_HOME G:\mentzdv\plone\instances\zeo04\parts\instance1 CLIENT_HOME G:\mentzdv\plone\instances\zeo04\var\instance1 Network Services ZServer.HTTPServer.zhttp_server (Port: 8101) Process Id 6132 (5328) Running For 1 hour 3 min 34 sec Thanks, Sebastian
On Sun, Jul 11, 2010 at 1:41 AM, Sebastian Tiedtke <st@mdvtts.com> wrote:
We're working on a large scale Plone deployment and recently came across some odd behavior with tempstorage at our ZEO server.
The system setup consists of a central ZEO server that provides the storage for content as well as a temp storage for sessioning. There are multiple other servers that run multiple Plone instances with ZEO clients.
Let me make sure I understand your setup: you have a TemporaryStorage running on a central server that is exposed via ZEO to clients. Right? So, when the ZEO server restarts the temp storage is reset (it's contents don't survive a restart by design), but the clients don't know all the objects they "know" about in the temp storage just disappeared. Therefore when they go to load one (because it wasn't in their object or ZEO caches), the load fails. Not surprising really. -- Benji York
On Wed, Jul 14, 2010 at 19:22, Benji York <benji@benjiyork.com> wrote:
[...]
Let me make sure I understand your setup: you have a TemporaryStorage running on a central server that is exposed via ZEO to clients. Right?
So, when the ZEO server restarts the temp storage is reset (it's contents don't survive a restart by design), but the clients don't know all the objects they "know" about in the temp storage just disappeared. Therefore when they go to load one (because it wasn't in their object or ZEO caches), the load fails.
Not surprising really.
What could be surprising is that, since the objects are not in the object cache or the ZEO cache, how can the clients 'know' about them to request them? And the answer is probably that there are other objects which ARE in the object cache, or the ZEO cache and that hold references (ghost objects in the case of the object-cache) to the objects in the zeo-distributed temporary storage. So, perhaps, Sebastian can avoid a Zope restart if he finds a way to flush all caches. Flushing the object caches is easy, it's in the Control_Panel. Flushing the ZEO cache is something else. Perhaps he can run with a 0-sized ZEO cache for the TempStorages? Cheers, Leo
On Wed, Jul 14, 2010 at 6:59 PM, Leonardo Rochael Almeida <leorochael@gmail.com> wrote:
On Wed, Jul 14, 2010 at 19:22, Benji York <benji@benjiyork.com> wrote:
[...] Not surprising really.
What could be surprising is that, since the objects are not in the object cache or the ZEO cache, how can the clients 'know' about them to request them?
And the answer is probably that there are other objects which ARE in the object cache, or the ZEO cache and that hold references (ghost objects in the case of the object-cache) to the objects in the zeo-distributed temporary storage.
Indeed. My jet lag ate that part of the story. Thanks.
So, perhaps, Sebastian can avoid a Zope restart if he finds a way to flush all caches. Flushing the object caches is easy, it's in the Control_Panel. Flushing the ZEO cache is something else. Perhaps he can run with a 0-sized ZEO cache for the TempStorages?
If this were me, I'd use a non-temporary storage and implement an expiry policy for the results cache. The bforest package would be a good start (http://pypi.python.org/pypi/zope.bforest). In fact, I would expect they already have an expiry policy in place, so they might be able to just start using a non-temporary storage right away. -- Benji York
Hi Sebastian, Why don’t you consider to use memcached for caching the results instead of using sessions? By using this, Zeo server/Zeo clients restart wont affect cached data. HTH, Dragos On Sun, Jul 11, 2010 at 8:41 AM, Sebastian Tiedtke <st@mdvtts.com> wrote:
Hi all,
We're working on a large scale Plone deployment and recently came across some odd behavior with tempstorage at our ZEO server. A limited number, yet highly frequented, of pages on our Plone site query backend web services that provide location based services such as geocoding and routing (a to b). Since those calls to the services are rather computation intense we decided to store intermediate and resulting data in sessions vs. re-querying the service for no reason.
The system setup consists of a central ZEO server that provides the storage for content as well as a temp storage for sessioning. There are multiple other servers that run multiple Plone instances with ZEO clients. The ZEO server setup is straight forward but I'm happy to provide the configuration files. Generally the concept works great.
However, whenever we restart the ZEO server and keep the client instances running we get odd behavior with the client instances' sessioning. Every client appears to reconnect and, if required, revalidates its cache.
2010-07-11T14:46:03 INFO ZEO.ClientStorage (6132) Disconnected from storage: "('ITIS.mentzdv.de', 8100)" 2010-07-11T14:46:03 INFO ZEO.ClientStorage (6132) Disconnected from storage: "('ITIS.mentzdv.de', 8100)" 2010-07-11T14:46:09 INFO ZEO.ClientStorage (6132) Testing connection <ManagedClientConnection ('127.0.0.1', 8100)> 2010-07-11T14:46:09 INFO ZEO.zrpc.Connection(C) (127.0.0.1:8100) received handshake 'Z303' 2010-07-11T14:46:09 INFO ZEO.ClientStorage (6132) Server authentication protocol None 2010-07-11T14:46:09 INFO ZEO.ClientStorage (6132) Connected to storage: (' ITIS.mentzdv.de', 8100) 2010-07-11T14:46:09 INFO ZEO.ClientStorage (6132) Testing connection <ManagedClientConnection ('127.0.0.1', 8100)> 2010-07-11T14:46:09 INFO ZEO.ClientStorage (6132) last inval tid: '\x03\x87n\x9d|\x1a\xc2\xaa' 2010-07-11 04:45:29.087000
2010-07-11T14:46:09 INFO ZEO.ClientStorage (6132) last transaction: '\x00\x00\x00\x00\x00\x00\x00\x00' 1900-01-01 00:00:00.000000 2010-07-11T14:46:09 INFO ZEO.zrpc.Connection(C) (127.0.0.1:8100) received handshake 'Z303' 2010-07-11T14:46:10 INFO ZEO.ClientStorage (6132) Verifying cache 2010-07-11T14:46:10 INFO ZEO.ClientStorage (6132) Server authentication protocol None 2010-07-11T14:46:10 INFO ZEO.ClientStorage (6132) Connected to storage: (' ITIS.mentzdv.de', 8100) 2010-07-11T14:46:10 INFO ZEO.ClientStorage (6132) No verification necessary (last_inval_tid up-to-date) 2010-07-11T14:46:10 INFO ZEO.ClientStorage (6132) endVerify finishing 2010-07-11T14:46:10 INFO ZEO.ClientStorage (6132) endVerify finished
The problem is that whenever we hit a session bound page we get following error and stack trace:
2010-07-11T14:58:12 ERROR ZODB.Connection Couldn't load state for 0x82 Traceback (most recent call last): File "g:\mentzdv\plone\instances\zeo04\zope2\lib\python\ZODB\Connection.py", line 761, in setstate self._setstate(obj) File "g:\mentzdv\plone\instances\zeo04\zope2\lib\python\ZODB\Connection.py", line 801, in _setstate p, serial = self._storage.load(obj._p_oid, self._version) File "G:\mentzdv\plone\instances\zeo04\zope2\lib\python\ZEO\ClientStorage.py", line 727, in load return self.loadEx(oid, version)[:2] File "G:\mentzdv\plone\instances\zeo04\zope2\lib\python\ZEO\ClientStorage.py", line 750, in loadEx data, tid, ver = self._server.loadEx(oid, version) File "G:\mentzdv\plone\instances\zeo04\zope2\lib\python\ZEO\ServerStub.py", line 196, in loadEx return self.rpc.call("loadEx", oid, version) File "G:\mentzdv\plone\instances\zeo04\zope2\lib\python\ZEO\zrpc\connection.py", line 650, in call raise inst # error raised by server KeyError: '\x00\x00\x00\x00\x00\x00\x00\x82'
In the ZMI under the Control-Panel/Database Tab the temporary database seems to be fine. The /temp_folder returns a similar stack trace though: Site Error
An error was encountered while publishing this resource.
*KeyError* Sorry, a site error occurred.
Traceback (innermost last):
- Module ZPublisher.Publish, line 202, in publish_module_standard - Module ZPublisher.Publish, line 150, in publish - Module plone.app.linkintegrity.monkey, line 21, in zpublisher_exception_hook_wrapper - Module Zope2.App.startup, line 221, in zpublisher_exception_hook - Module ZPublisher.Publish, line 119, in publish - Module ZPublisher.mapply, line 88, in mapply - Module ZPublisher.Publish, line 42, in call_object - Module App.special_dtml, line 65, in __call__ - Module DocumentTemplate.DT_String, line 476, in __call__ - Module Products.Transience.Transience, line 926, in housekeep - Module Products.Transience.Transience, line 929, in _housekeep - Module Products.Transience.Transience, line 569, in _finalize - Module Products.Transience.Transience, line 593, in _do_finalize_work - Module ZODB.Connection, line 761, in setstate - Module ZODB.Connection, line 801, in _setstate - Module ZEO.ClientStorage, line 727, in load - Module ZEO.ClientStorage, line 750, in loadEx - Module ZEO.ServerStub, line 196, in loadEx - Module ZEO.zrpc.connection, line 650, in call
KeyError: '\x00\x00\x00\x00\x00\x00\x00\x82' (Also, the following error occurred while attempting to render the standard error message, please see the event log for full details: You are not allowed to access 'title_or_id' in this context)
We know for a fact that one client instance needs to create the actual temporary container at the ZEO server upon its restart. Restarting a single client instance will make make this instance work but unfortunately won't recover all other client instances. All of those problems disappear as soon as we restart all instances; until the next ZEO server restart of course. The problem doesn't appear to happen if connections drops happen but the ZEO server keeps running.
Is that behavior intentional? Any kind of help is very much appreciated.
We're currently using following versions (yes, we're also running on windows but I find it hard to believe that the OS is causing those issues).
Zope Version (Zope 2.10.9-final, python 2.4.4, win32) Python Version 2.4.4 (#71, Oct 18 2006, 08:34:43) [MSC v.1310 32 bit (Intel)] System Platform win32 SOFTWARE_HOME G:\mentzdv\plone\instances\zeo04\zope2\lib\python ZOPE_HOME G:\mentzdv\plone\instances\zeo04\zope2 INSTANCE_HOME G:\mentzdv\plone\instances\zeo04\parts\instance1 CLIENT_HOME G:\mentzdv\plone\instances\zeo04\var\instance1 Network Services ZServer.HTTPServer.zhttp_server (Port: 8101) Process Id 6132 (5328) Running For 1 hour 3 min 34 sec
Thanks, Sebastian
_______________________________________________ Zope-Dev maillist - Zope-Dev@zope.org https://mail.zope.org/mailman/listinfo/zope-dev ** No cross posts or HTML encoding! ** (Related lists - https://mail.zope.org/mailman/listinfo/zope-announce https://mail.zope.org/mailman/listinfo/zope )
-- Dragos Chirila objectValues@gmail.com (+4) 0722 395375
On 7/15/10 17:03 , Dragos Chirila wrote:
Hi Sebastian,
Why don’t you consider to use memcached for caching the results instead of using sessions? By using this, Zeo server/Zeo clients restart wont affect cached data.
or plone.memoize, using either a RAMCache or memcached as backend. Wichert.
participants (5)
-
Benji York -
Dragos Chirila -
Leonardo Rochael Almeida -
Sebastian Tiedtke -
Wichert Akkerman