PLIP3211 / ES6: strange test failures fixed, cause still unkown

thet · December 23, 2021, 12:40am

After ignoring the testfailures in PLIP3211 (Mockup ES6) for a while ( ) I finally fixed the test setup.
I didn't thought that this would take me that long...

Tests were always failing with a similar strange error message like this one:

Traceback (most recent call last):
  File "/home/_thet/data/dev/sprints/plone6ui/REPOS/buildout.coredev/src/plone.testing/src/plone/testing/zope.py", line 273, in zopeApp
    app.REQUEST.close()
  File "/home/_thet/data/dev/sprints/plone6ui/REPOS/buildout.coredev/src/Zope/src/ZPublisher/BaseRequest.py", line 215, in close
    notify(EndRequestEvent(None, self))
  File "/home/_thet/repos-config/dotfiles-thet/dot.buildout/eggs/zope.event-4.5.0-py3.9.egg/zope/event/__init__.py", line 32, in notify
    subscriber(event)
  File "/home/_thet/repos-config/dotfiles-thet/dot.buildout/eggs/zope.component-4.6.2-py3.9.egg/zope/component/event.py", line 27, in dispatch
    component_subscribers(event, None)
  File "/home/_thet/repos-config/dotfiles-thet/dot.buildout/eggs/zope.component-4.6.2-py3.9.egg/zope/component/_api.py", line 134, in subscribers
    return sitemanager.subscribers(objects, interface)
  File "/home/_thet/repos-config/dotfiles-thet/dot.buildout/eggs/zope.interface-5.4.0-py3.9-linux-x86_64.egg/zope/interface/registry.py", line 448, in subscribers
    return self.adapters.subscribers(objects, provided)
ZODB.POSException.POSKeyError: 'RequestContainer' object has no attribute 'adapters'

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/home/_thet/repos-config/dotfiles-thet/dot.buildout/eggs/zope.testrunner-5.4.0-py3.9.egg/zope/testrunner/runner.py", line 467, in run_layer
    setup_layer(options, layer, setup_layers)
  File "/home/_thet/repos-config/dotfiles-thet/dot.buildout/eggs/zope.testrunner-5.4.0-py3.9.egg/zope/testrunner/runner.py", line 837, in setup_layer
    setup_layer(options, base, setup_layers)
  File "/home/_thet/repos-config/dotfiles-thet/dot.buildout/eggs/zope.testrunner-5.4.0-py3.9.egg/zope/testrunner/runner.py", line 837, in setup_layer
    setup_layer(options, base, setup_layers)
  File "/home/_thet/repos-config/dotfiles-thet/dot.buildout/eggs/zope.testrunner-5.4.0-py3.9.egg/zope/testrunner/runner.py", line 842, in setup_layer
    layer.setUp()
  File "/home/_thet/data/dev/sprints/plone6ui/REPOS/buildout.coredev/src/plone.app.testing/src/plone/app/testing/layers.py", line 106, in setUp
    self.setUpDefaultContent(app)
  File "/usr/lib/python3.9/contextlib.py", line 126, in __exit__
    next(self.gen)
  File "/home/_thet/data/dev/sprints/plone6ui/REPOS/buildout.coredev/src/plone.testing/src/plone/testing/zope.py", line 279, in zopeApp
    raise inner_exception
  File "/home/_thet/data/dev/sprints/plone6ui/REPOS/buildout.coredev/src/plone.testing/src/plone/testing/zope.py", line 268, in zopeApp
    transaction.commit()
  File "/home/_thet/repos-config/dotfiles-thet/dot.buildout/eggs/transaction-3.0.1-py3.9.egg/transaction/_manager.py", line 257, in commit
    return self.manager.commit()
  File "/home/_thet/repos-config/dotfiles-thet/dot.buildout/eggs/transaction-3.0.1-py3.9.egg/transaction/_manager.py", line 134, in commit
    return self.get().commit()
  File "/home/_thet/repos-config/dotfiles-thet/dot.buildout/eggs/transaction-3.0.1-py3.9.egg/transaction/_transaction.py", line 282, in commit
    reraise(t, v, tb)
  File "/home/_thet/repos-config/dotfiles-thet/dot.buildout/eggs/transaction-3.0.1-py3.9.egg/transaction/_compat.py", line 49, in reraise
    raise value
  File "/home/_thet/repos-config/dotfiles-thet/dot.buildout/eggs/transaction-3.0.1-py3.9.egg/transaction/_transaction.py", line 273, in commit
    self._commitResources()
  File "/home/_thet/repos-config/dotfiles-thet/dot.buildout/eggs/transaction-3.0.1-py3.9.egg/transaction/_transaction.py", line 456, in _commitResources
    reraise(t, v, tb)
  File "/home/_thet/repos-config/dotfiles-thet/dot.buildout/eggs/transaction-3.0.1-py3.9.egg/transaction/_compat.py", line 49, in reraise
    raise value
  File "/home/_thet/repos-config/dotfiles-thet/dot.buildout/eggs/transaction-3.0.1-py3.9.egg/transaction/_transaction.py", line 430, in _commitResources
    rm.commit(self)
  File "/home/_thet/repos-config/dotfiles-thet/dot.buildout/eggs/ZODB-5.6.0-py3.9.egg/ZODB/Connection.py", line 492, in commit
    self._commit_savepoint(transaction)
  File "/home/_thet/repos-config/dotfiles-thet/dot.buildout/eggs/ZODB-5.6.0-py3.9.egg/ZODB/Connection.py", line 1046, in _commit_savepoint
    obj._p_estimated_size = len(data)
  File "/home/_thet/data/dev/sprints/plone6ui/REPOS/buildout.coredev/src/Products.CMFPlone/Products/CMFPlone/Portal.py", line 69, in __setattr__
    if self._tree is not None and name in self:
  File "/home/_thet/repos-config/dotfiles-thet/dot.buildout/eggs/ZODB-5.6.0-py3.9.egg/ZODB/Connection.py", line 791, in setstate
    p, serial = self._storage.load(oid)
  File "/home/_thet/repos-config/dotfiles-thet/dot.buildout/eggs/ZODB-5.6.0-py3.9.egg/ZODB/mvccadapter.py", line 153, in load
    r = self._storage.loadBefore(oid, self._start)
  File "/home/_thet/repos-config/dotfiles-thet/dot.buildout/eggs/ZODB-5.6.0-py3.9.egg/ZODB/DemoStorage.py", line 225, in loadBefore
    return self.base.loadBefore(oid, tid)
  File "/home/_thet/repos-config/dotfiles-thet/dot.buildout/eggs/ZODB-5.6.0-py3.9.egg/ZODB/DemoStorage.py", line 225, in loadBefore
    return self.base.loadBefore(oid, tid)
  File "/home/_thet/repos-config/dotfiles-thet/dot.buildout/eggs/ZODB-5.6.0-py3.9.egg/ZODB/utils.py", line 288, in __call__
    return func(*args, **kw)
  File "/home/_thet/repos-config/dotfiles-thet/dot.buildout/eggs/ZODB-5.6.0-py3.9.egg/ZODB/MappingStorage.py", line 168, in loadBefore
    raise ZODB.POSException.POSKeyError(oid)
ZODB.POSException.POSKeyError: 0x2bec75a38a64a63c

No fun involved wherever a POSKeyError pops up.

After unsuccessfully trying to understand the failure and hunting down the error with pdb without finding the cause I began to narrow down the problem on per repository basis.
There are already quite a few repositories involved, see: buildout.coredev/plip-3211-mockup-redone-source-checkouts.cfg at 6.0 · plone/buildout.coredev · GitHub

I could identify the failure in two repositories: Products.CMFPlone and plone.staticresources.

In CMFPlone the problem was the removed exportimport handler for the resource registry, which was removed when switching to the webresource-based resource registry (which is awesome).
The fix is here: TMP - Fixes test setup for yet unknown reason. · plone/Products.CMFPlone@3e9ab29 · GitHub

In plone.staticresources the problem was the removed registration of the plone-logged-in bundle, this is the fix: TMP - Fixes test setup for yet unknown reason. · plone/plone.staticresources@48a14ee · GitHub

I do absolutely not understand why this is happening.
Do we have a hidden ZODB in our test environment which expects some code to be exactly there as-is?
For example, in the CMFPlone exportimport hander: When trying to remove function bodies or even just add a print statement (!) within the involved functions, the tests broke again with the mentioned POSKeyError
That is the reason why I did not / could not narrow down the function bodies to a dummy function which only keeps the original function signature. The same goes for the plone-logged-in-compiled.min.js which I had to include as full JavaScript file.

If anyone can shed a little light on this, I'd be a little more happier about this.

mtoepfl · December 23, 2021, 7:29am

Hey Thet,

only a first shot written in my mobile phone, but perhaps it helps.

Perhaps you are only misleaded by the ZODB.POSException.POSKeyError. I think it should be an AttributeError. In Zope5 the RequestContainer seems to be the root object in Acquisition. So adapters is no attribute of the context object in your test setup.

File "/home/_thet/repos-config/dotfiles-thet/dot.buildout/eggs/zope.interface-5.4.0-py3.9-linux-x86_64.egg/zope/interface/registry.py", line 448, in subscribers
return self.adapters.subscribers(objects, provided),,

As we migrated our codebase to Zope5 I noticed that there is thrown a AttributeError at some places where there was a KeyError in Zope2.

As I sayed only a first shot, but maybe it helps.

Thanks for your persistent work on this topic,

Michael

yurj · December 23, 2021, 7:30am

Isn't the resource_overrides folder in the ZMI under portal_resources? Importing the resource maybe will recreata that folder structure and test will need them?

The first commit that fix will lead to:
https://github.com/plone/Products.CMFPlone/blob/09c33640325941250486392bb892258efcc74609/Products/CMFPlone/resources/browser/combine.py#L152 (combine_bundles)

thus recreating that dirs.

The registry commit will make this code go above, then creating the folders in portal_resources:

def combine(context):
    logger = context.getLogger("bundles")
    registry = queryUtility(IRegistry)

    if registry is None:
        logger.info("Cannot find registry")
        return

https://github.com/plone/Products.CMFPlone/blob/09c33640325941250486392bb892258efcc74609/Products/CMFPlone/resources/exportimport/bundles.py#L6

The poskeyerror can be because the zodb does not commit, so maybe the object created is not found later. This is my 'wild' guess. @dieter, what do you think?.