[z3-five] weird ZEO cache error during five:registerPackage processing

[Rob Miller]

hi all,

i've got a very strange problem happening.  whenever i start my Zope server 
against a brand new ZODB being served up by ZEO, Zope dies while in the ZCML 
processing for a five:registerPackage call.  here's the traceback:

Traceback (most recent call last):
   File "/home/rob/openplans/lib/zope/lib/python/Zope2/Startup/run.py", line 
56, in ?
     run()
   File "/home/rob/openplans/lib/zope/lib/python/Zope2/Startup/run.py", line 
21, in run
     starter.prepare()
   File 
"/home/rob/openplans/lib/Zope-2.9.6/lib/python/Zope2/Startup/__init__.py", 
line 98, in prepare
     self.startZope()
   File 
"/home/rob/openplans/lib/Zope-2.9.6/lib/python/Zope2/Startup/__init__.py", 
line 257, in startZope
     Zope2.startup()
   File "/home/rob/openplans/lib/Zope-2.9.6/lib/python/Zope2/__init__.py", 
line 47, in startup
     _startup()
   File "/home/rob/openplans/lib/Zope-2.9.6/lib/python/Zope2/App/startup.py", 
line 103, in startup
     OFS.Application.initialize(application)
   File "/home/rob/openplans/lib/Zope-2.9.6/lib/python/OFS/Application.py", 
line 304, in initialize
     initializer.initialize()
   File "/home/rob/openplans/lib/Zope-2.9.6/lib/python/OFS/Application.py", 
line 333, in initialize
     self.install_products()
   File "/home/rob/openplans/lib/Zope-2.9.6/lib/python/OFS/Application.py", 
line 605, in install_products
     return install_products(app)
   File "/home/rob/openplans/lib/Zope-2.9.6/lib/python/OFS/Application.py", 
line 636, in install_products
     folder_permissions, raise_exc=debug_mode)
   File "/home/rob/openplans/lib/Zope-2.9.6/lib/python/OFS/Application.py", 
line 783, in install_product
     initmethod(context)
   File "/home/rob/openplans/zope/Products/Five/__init__.py", line 31, in 
initialize
     zcml.load_site()
   File "/home/rob/openplans/zope/Products/Five/zcml.py", line 41, in load_site
     _context = xmlconfig.file(file)
   File 
"/home/rob/openplans/lib/zope/lib/python/zope/configuration/xmlconfig.py", 
line 559, in file
     context.execute_actions()
   File 
"/home/rob/openplans/lib/Zope-2.9.6/lib/python/zope/configuration/config.py", 
line 612, in execute_actions
     callable(*args, **kw)
   File "/home/rob/openplans/zope/Products/Five/fiveconfigure.py", line 284, 
in _registerPackage
     transaction.commit()
   File 
"/home/rob/openplans/lib/Zope-2.9.6/lib/python/transaction/_manager.py", line 
96, in commit
     return self.get().commit(sub, deprecation_wng=False)
   File 
"/home/rob/openplans/lib/Zope-2.9.6/lib/python/transaction/_transaction.py", 
line 380, in commit
     self._saveCommitishError() # This raises!
   File 
"/home/rob/openplans/lib/Zope-2.9.6/lib/python/transaction/_transaction.py", 
line 378, in commit
     self._commitResources()
   File 
"/home/rob/openplans/lib/Zope-2.9.6/lib/python/transaction/_transaction.py", 
line 441, in _commitResources
     rm.tpc_finish(self)
   File "/home/rob/openplans/lib/Zope-2.9.6/lib/python/ZODB/Connection.py", 
line 679, in tpc_finish
     self._storage.tpc_finish(transaction, callback)
   File "/home/rob/openplans/lib/Zope-2.9.6/lib/python/ZEO/ClientStorage.py", 
line 974, in tpc_finish
     self._update_cache(tid)
   File "/home/rob/openplans/lib/Zope-2.9.6/lib/python/ZEO/ClientStorage.py", 
line 999, in _update_cache
     self._cache.invalidate(oid, version, tid)
   File "/home/rob/openplans/lib/Zope-2.9.6/lib/python/ZEO/cache.py", line 
367, in invalidate
     assert tid is not None and cur_tid < tid
zope.configuration.config.ConfigurationExecutionError: exceptions.AssertionError:
   in:
   File 
"/home/rob/openplans/src/opencore_trunk/opencore/siteui/configure.zcml", line 
9.2-12.7
     <five:registerPackage
        package="opencore.siteui"
        initialize="opencore.siteui.zope2.initialize"
        />


this is using Zope 2.9.6 and the Five 1.4 branch.  the tag that is causing the 
problem can be found at http://tinyurl.com/yqoaw7.

i've absolutely verified that the registerPackage directive is causing the 
problem; if i remove that tag Zope starts with no problem.  similarly, if i 
don't use ZEO it starts w/o trouble.  and subsequent starts, once there is a 
Data.fs file to connect to, also seem to work.  it's only this one combination 
that causes the problem.  it's a bit of a headache, though, b/c it means that 
our buildbot processes, which construct an environment from scratch every 
time, fail before they even begin.

i know very little about the ZEO caching infrastructure, and don't even know 
where to being in debugging this.  anyone have any clues what might be going on?

-r