Hi all,<div><br></div><div>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.</div>
<div><br></div><div>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.</div>
<div><br></div><div>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.</div>
<div><br></div><div><div><span class="Apple-style-span" style="font-family: 'courier new', monospace; ">2010-07-11T14:46:03 INFO ZEO.ClientStorage (6132) Disconnected from storage: "('<a href="http://ITIS.mentzdv.de">ITIS.mentzdv.de</a>', 8100)"</span></div>
<div><span class="Apple-style-span" style="font-family: 'courier new', monospace; ">2010-07-11T14:46:03 INFO ZEO.ClientStorage (6132) Disconnected from storage: "('<a href="http://ITIS.mentzdv.de">ITIS.mentzdv.de</a>', 8100)"</span></div>
<div><span class="Apple-style-span" style="font-family: 'courier new', monospace; ">2010-07-11T14:46:09 INFO ZEO.ClientStorage (6132) Testing connection <ManagedClientConnection ('127.0.0.1', 8100)></span></div>
<div><span class="Apple-style-span" style="font-family: 'courier new', monospace; ">2010-07-11T14:46:09 INFO ZEO.zrpc.Connection(C) (<a href="http://127.0.0.1:8100">127.0.0.1:8100</a>) received handshake 'Z303'</span></div>
<div><span class="Apple-style-span" style="font-family: 'courier new', monospace; ">2010-07-11T14:46:09 INFO ZEO.ClientStorage (6132) Server authentication protocol None</span></div><div><span class="Apple-style-span" style="font-family: 'courier new', monospace; ">2010-07-11T14:46:09 INFO ZEO.ClientStorage (6132) Connected to storage: ('<a href="http://ITIS.mentzdv.de">ITIS.mentzdv.de</a>', 8100)</span></div>
<div><span class="Apple-style-span" style="font-family: 'courier new', monospace; ">2010-07-11T14:46:09 INFO ZEO.ClientStorage (6132) Testing connection <ManagedClientConnection ('127.0.0.1', 8100)></span></div>
<div><span class="Apple-style-span" style="font-family: 'courier new', monospace; ">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</span></div>
<div><font class="Apple-style-span" face="'courier new', monospace"><br></font></div><div><span class="Apple-style-span" style="font-family: 'courier new', monospace; ">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</span></div>
<div><span class="Apple-style-span" style="font-family: 'courier new', monospace; ">2010-07-11T14:46:09 INFO ZEO.zrpc.Connection(C) (<a href="http://127.0.0.1:8100">127.0.0.1:8100</a>) received handshake 'Z303'</span></div>
<div><span class="Apple-style-span" style="font-family: 'courier new', monospace; ">2010-07-11T14:46:10 INFO ZEO.ClientStorage (6132) Verifying cache</span></div><div><span class="Apple-style-span" style="font-family: 'courier new', monospace; ">2010-07-11T14:46:10 INFO ZEO.ClientStorage (6132) Server authentication protocol None</span></div>
<div><span class="Apple-style-span" style="font-family: 'courier new', monospace; ">2010-07-11T14:46:10 INFO ZEO.ClientStorage (6132) Connected to storage: ('<a href="http://ITIS.mentzdv.de">ITIS.mentzdv.de</a>', 8100)</span></div>
<div><span class="Apple-style-span" style="font-family: 'courier new', monospace; ">2010-07-11T14:46:10 INFO ZEO.ClientStorage (6132) No verification necessary (last_inval_tid up-to-date)</span></div><div><span class="Apple-style-span" style="font-family: 'courier new', monospace; ">2010-07-11T14:46:10 INFO ZEO.ClientStorage (6132) endVerify finishing</span></div>
<div><span class="Apple-style-span" style="font-family: 'courier new', monospace; ">2010-07-11T14:46:10 INFO ZEO.ClientStorage (6132) endVerify finished</span></div></div><div><font class="Apple-style-span" face="'courier new', monospace"><br>
</font></div><div><br></div><div>The problem is that whenever we hit a session bound page we get following error and stack trace:</div><div><br></div><div><div><font class="Apple-style-span" face="'courier new', monospace">2010-07-11T14:58:12 ERROR ZODB.Connection Couldn't load state for 0x82</font></div>
<div><font class="Apple-style-span" face="'courier new', monospace">Traceback (most recent call last):</font></div><div><font class="Apple-style-span" face="'courier new', monospace"> File "g:\mentzdv\plone\instances\zeo04\zope2\lib\python\ZODB\Connection.py", line 761, in setstate</font></div>
<div><font class="Apple-style-span" face="'courier new', monospace"> self._setstate(obj)</font></div><div><font class="Apple-style-span" face="'courier new', monospace"> File "g:\mentzdv\plone\instances\zeo04\zope2\lib\python\ZODB\Connection.py", line 801, in _setstate</font></div>
<div><font class="Apple-style-span" face="'courier new', monospace"> p, serial = self._storage.load(obj._p_oid, self._version)</font></div><div><font class="Apple-style-span" face="'courier new', monospace"> File "G:\mentzdv\plone\instances\zeo04\zope2\lib\python\ZEO\ClientStorage.py", line 727, in load</font></div>
<div><font class="Apple-style-span" face="'courier new', monospace"> return self.loadEx(oid, version)[:2]</font></div><div><font class="Apple-style-span" face="'courier new', monospace"> File "G:\mentzdv\plone\instances\zeo04\zope2\lib\python\ZEO\ClientStorage.py", line 750, in loadEx</font></div>
<div><font class="Apple-style-span" face="'courier new', monospace"> data, tid, ver = self._server.loadEx(oid, version)</font></div><div><font class="Apple-style-span" face="'courier new', monospace"> File "G:\mentzdv\plone\instances\zeo04\zope2\lib\python\ZEO\ServerStub.py", line 196, in loadEx</font></div>
<div><font class="Apple-style-span" face="'courier new', monospace"> return self.rpc.call("loadEx", oid, version)</font></div><div><font class="Apple-style-span" face="'courier new', monospace"> File "G:\mentzdv\plone\instances\zeo04\zope2\lib\python\ZEO\zrpc\connection.py", line 650, in call</font></div>
<div><font class="Apple-style-span" face="'courier new', monospace"> raise inst # error raised by server</font></div><div><font class="Apple-style-span" face="'courier new', monospace">KeyError: '\x00\x00\x00\x00\x00\x00\x00\x82'</font></div>
</div><div><br></div><div><br></div><div>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:</div><div><h2><font class="Apple-style-span" face="'courier new', monospace">Site Error</font></h2>
<p><font class="Apple-style-span" face="'courier new', monospace">An error was encountered while publishing this resource.
</font></p>
<p><strong><font class="Apple-style-span" face="'courier new', monospace">KeyError</font></strong></p><font class="Apple-style-span" face="'courier new', monospace">
Sorry, a site error occurred.</font><p></p><p><font class="Apple-style-span" face="'courier new', monospace">Traceback (innermost last):
</font></p><ul>
<li><font class="Apple-style-span" face="'courier new', monospace"> Module ZPublisher.Publish, line 202, in publish_module_standard</font></li>
<li><font class="Apple-style-span" face="'courier new', monospace"> Module ZPublisher.Publish, line 150, in publish</font></li>
<li><font class="Apple-style-span" face="'courier new', monospace"> Module plone.app.linkintegrity.monkey, line 21, in zpublisher_exception_hook_wrapper</font></li>
<li><font class="Apple-style-span" face="'courier new', monospace"> Module Zope2.App.startup, line 221, in zpublisher_exception_hook</font></li>
<li><font class="Apple-style-span" face="'courier new', monospace"> Module ZPublisher.Publish, line 119, in publish</font></li>
<li><font class="Apple-style-span" face="'courier new', monospace"> Module ZPublisher.mapply, line 88, in mapply</font></li>
<li><font class="Apple-style-span" face="'courier new', monospace"> Module ZPublisher.Publish, line 42, in call_object</font></li>
<li><font class="Apple-style-span" face="'courier new', monospace"> Module App.special_dtml, line 65, in __call__</font></li>
<li><font class="Apple-style-span" face="'courier new', monospace"> Module DocumentTemplate.DT_String, line 476, in __call__</font></li>
<li><font class="Apple-style-span" face="'courier new', monospace"> Module Products.Transience.Transience, line 926, in housekeep</font></li>
<li><font class="Apple-style-span" face="'courier new', monospace"> Module Products.Transience.Transience, line 929, in _housekeep</font></li>
<li><font class="Apple-style-span" face="'courier new', monospace"> Module Products.Transience.Transience, line 569, in _finalize</font></li>
<li><font class="Apple-style-span" face="'courier new', monospace"> Module Products.Transience.Transience, line 593, in _do_finalize_work</font></li>
<li><font class="Apple-style-span" face="'courier new', monospace"> Module ZODB.Connection, line 761, in setstate</font></li>
<li><font class="Apple-style-span" face="'courier new', monospace"> Module ZODB.Connection, line 801, in _setstate</font></li>
<li><font class="Apple-style-span" face="'courier new', monospace"> Module ZEO.ClientStorage, line 727, in load</font></li>
<li><font class="Apple-style-span" face="'courier new', monospace"> Module ZEO.ClientStorage, line 750, in loadEx</font></li>
<li><font class="Apple-style-span" face="'courier new', monospace"> Module ZEO.ServerStub, line 196, in loadEx</font></li>
<li><font class="Apple-style-span" face="'courier new', monospace"> Module ZEO.zrpc.connection, line 650, in call</font></li>
</ul><font class="Apple-style-span" face="'courier new', monospace">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)</font></div><div><div><br></div><div>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.</div>
<div><br></div><div>Is that behavior intentional? Any kind of help is very much appreciated.</div><div><br></div><div>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).</div>
<div><br></div><div><div class="form-label"><font class="Apple-style-span" face="'courier new', monospace">Zope Version
</font></div>
<div class="form-text"><font class="Apple-style-span" face="'courier new', monospace">
(Zope 2.10.9-final, python 2.4.4, win32)
</font></div>
<div class="form-label"><font class="Apple-style-span" face="'courier new', monospace">
Python Version
</font></div>
<div class="form-text"><font class="Apple-style-span" face="'courier new', monospace">
2.4.4 (#71, Oct 18 2006, 08:34:43) [MSC v.1310 32 bit (Intel)]
</font></div>
<div class="form-label"><font class="Apple-style-span" face="'courier new', monospace">
System Platform
</font></div>
<div class="form-text"><font class="Apple-style-span" face="'courier new', monospace">
win32
</font></div>
<div class="form-label"><font class="Apple-style-span" face="'courier new', monospace">
SOFTWARE_HOME
</font></div>
<div class="form-text"><font class="Apple-style-span" face="'courier new', monospace">
G:\mentzdv\plone\instances\zeo04\zope2\lib\python
</font></div>
<div class="form-label"><font class="Apple-style-span" face="'courier new', monospace">
ZOPE_HOME
</font></div>
<div class="form-text"><font class="Apple-style-span" face="'courier new', monospace">
G:\mentzdv\plone\instances\zeo04\zope2
</font></div>
<div class="form-label"><font class="Apple-style-span" face="'courier new', monospace">
INSTANCE_HOME
</font></div>
<div class="form-text"><font class="Apple-style-span" face="'courier new', monospace">
G:\mentzdv\plone\instances\zeo04\parts\instance1
</font></div>
<div class="form-label"><font class="Apple-style-span" face="'courier new', monospace">
CLIENT_HOME
</font></div>
<div class="form-text"><font class="Apple-style-span" face="'courier new', monospace">
G:\mentzdv\plone\instances\zeo04\var\instance1
</font></div>
<div class="form-label"><font class="Apple-style-span" face="'courier new', monospace">
Network Services
</font></div>
<div class="form-text"><font class="Apple-style-span" face="'courier new', monospace">
ZServer.HTTPServer.zhttp_server (Port: 8101)<br></font>
</div>
<div class="form-label"><font class="Apple-style-span" face="'courier new', monospace">
Process Id
</font></div>
<div class="form-text"><font class="Apple-style-span" face="'courier new', monospace">
6132 (5328)
</font></div>
<div class="form-label"><font class="Apple-style-span" face="'courier new', monospace">
Running For
</font></div>
<div class="form-text"><font class="Apple-style-span" face="'courier new', monospace">
1 hour 3 min 34 sec </font></div></div><div><br></div><div>Thanks,</div><div>Sebastian</div></div>