search

plone / plone.testing

Provides tools for writing unit and integration tests in a Zope and Plone environment. It is not tied to Plone, and it does not depend on Zope 2 (although it has some optional Zope 2-only features)
https://pypi.org/project/plone.testing/
3 stars 9 forks source link

Browser tests crash opening not found URL #83

Open ale-rt opened 1 year ago

ale-rt commented 1 year ago

I have this patch:

diff --git a/Products/CMFPlone/tests/test_redirect_after_login.py b/Products/CMFPlone/tests/test_redirect_after_login.py
index 4552a508d..ab33a7a91 100644
--- a/Products/CMFPlone/tests/test_redirect_after_login.py
+++ b/Products/CMFPlone/tests/test_redirect_after_login.py
@@ -205,6 +205,10 @@ class TestRedirectAfterLogin(unittest.TestCase):
             "Logout status message not displayed.",
         )

+    def test_zzzz(self):
+        breakpoint()
+        self.browser.open('http://nohost/plone/bogus')
+
     def test_password_reset_uses_all_adapters(self):
         # By default, when you reset your password, you are directly logged in.
         # An initial login adapter should be active.

When I run the silly test_zzzz with buildout.coredev I see:

(Pdb++) self.browser
<plone.testing._z2_testbrowser.Browser object at 0x7ff86590aa90>
(Pdb++) self.browser.open('http://nohost/plone/bogus')
*** ZODB.POSException.ConnectionStateError: Shouldn't load state for persistent.list.PersistentList 0x3b676fdf706dc1a7 when the connection is closed
Traceback (most recent call last):
  File "/home/ale/.buildout/eggs/cp311/zope.testbrowser-5.6.1-py3.11.egg/zope/testbrowser/browser.py", line 256, in open
    self._processRequest(url, make_request)
  File "/home/ale/.buildout/eggs/cp311/zope.testbrowser-5.6.1-py3.11.egg/zope/testbrowser/browser.py", line 282, in _processRequest
    resp = make_request(reqargs)
  File "/home/ale/.buildout/eggs/cp311/zope.testbrowser-5.6.1-py3.11.egg/zope/testbrowser/browser.py", line 253, in make_request
    return self.testapp.get(url, **args)
  File "/home/ale/.buildout/eggs/cp311/WebTest-3.0.0-py3.11.egg/webtest/app.py", line 324, in get
    return self.do_request(req, status=status,
  File "/home/ale/.buildout/eggs/cp311/zope.testbrowser-5.6.1-py3.11.egg/zope/testbrowser/browser.py", line 93, in do_request
    response = super(TestbrowserApp, self).do_request(req, status,
  File "/home/ale/.buildout/eggs/cp311/WebTest-3.0.0-py3.11.egg/webtest/app.py", line 620, in do_request
    res = req.get_response(app, catch_exc_info=True)
  File "/home/ale/.buildout/eggs/cp311/WebOb-1.8.7-py3.11.egg/webob/request.py", line 1309, in send
    status, headers, app_iter, exc_info = self.call_application(
  File "/home/ale/.buildout/eggs/cp311/WebOb-1.8.7-py3.11.egg/webob/request.py", line 1278, in call_application
    app_iter = application(self.environ, start_response)
  File "/home/ale/.buildout/eggs/cp311/WebTest-3.0.0-py3.11.egg/webtest/lint.py", line 196, in lint_app
    iterator = application(environ, start_response_wrapper)
  File "/home/ale/.buildout/eggs/cp311/plone.testing-8.0.3-py3.11.egg/plone/testing/_z2_testbrowser.py", line 39, in wrapped_func
    return func(*args, **kw)
  File "/home/ale/.buildout/eggs/cp311/plone.testing-8.0.3-py3.11.egg/plone/testing/_z2_testbrowser.py", line 66, in __call__
    wsgi_result = publish(environ, start_response)
  File "/home/ale/Code/plone/projects/coredev/6.1/src/Zope/src/ZPublisher/WSGIPublisher.py", line 405, in publish_module
    request.close()
  File "/home/ale/Code/plone/projects/coredev/6.1/src/Zope/src/ZPublisher/BaseRequest.py", line 215, in close
    notify(EndRequestEvent(None, self))
  File "/home/ale/.buildout/eggs/cp311/zope.event-4.6-py3.11.egg/zope/event/__init__.py", line 33, in notify
    subscriber(event)
  File "/home/ale/.buildout/eggs/cp311/zope.component-5.1.0-py3.11.egg/zope/component/event.py", line 27, in dispatch
    component_subscribers(event, None)
  File "/home/ale/.buildout/eggs/cp311/zope.component-5.1.0-py3.11.egg/zope/component/_api.py", line 134, in subscribers
    return sitemanager.subscribers(objects, interface)
  File "/home/ale/.buildout/eggs/cp311/zope.interface-6.0-py3.11-linux-x86_64.egg/zope/interface/registry.py", line 445, in subscribers
    return self.adapters.subscribers(objects, provided)
  File "/home/ale/.buildout/eggs/cp311/zope.interface-6.0-py3.11-linux-x86_64.egg/zope/interface/adapter.py", line 892, in subscribers
    subscriptions = self.subscriptions([providedBy(o) for o in objects], provided)
  File "/home/ale/.buildout/eggs/cp311/zope.interface-6.0-py3.11-linux-x86_64.egg/zope/interface/adapter.py", line 874, in _uncached_subscriptions
    if order >= len(byorder):
  File "/usr/lib/python3.11/collections/__init__.py", line 1235, in __len__
    return len(self.data)
  File "/home/ale/.buildout/eggs/cp311/ZODB-5.8.0-py3.11.egg/ZODB/Connection.py", line 782, in setstate
    raise ConnectionStateError(msg)
davisagli commented 1 year ago

In general this error happens when something tries to read the state of a persistent object whose connection was already closed. It might have something to do with the ordering of subscribers to the EndRequestEvent (or the ordering of that event relative to other cleanup that happens at the end of the request)

ale-rt commented 1 year ago

Thanks for you brilliant insight! It seems to me the issue happens with the connection cache. It should be cleaned out but it is not :) You are probably right about the end request subscribers. I will dig a little bit more on that

ale-rt commented 1 year ago

FTR there is just one IEndRequestEvent subscriber:

[25] > /home/ale/.buildout/eggs/cp311/zope.interface-6.0-py3.11-linux-x86_64.egg/zope/interface/adapter.py(892)subscribers()
-> subscriptions = self.subscriptions([providedBy(o) for o in objects], provided)
(Pdb++) objects
(<zope.publisher.interfaces.EndRequestEvent object at 0x7f7871db4dd0>,)
ale-rt commented 1 year ago

This is the (proper) traceback for the same test in Plone 5.2

Error in test test_zzzz (Products.CMFPlone.tests.test_redirect_after_login.TestRedirectAfterLogin)
Traceback (most recent call last):
  File "/home/ale/.pyenv/versions/3.8.15/lib/python3.8/unittest/case.py", line 60, in testPartExecutor
    yield
  File "/home/ale/.pyenv/versions/3.8.15/lib/python3.8/unittest/case.py", line 676, in run
    self._callTestMethod(testMethod)
  File "/home/ale/.pyenv/versions/3.8.15/lib/python3.8/unittest/case.py", line 633, in _callTestMethod
    method()
  File "/home/ale/Code/plone/projects/coredev/5.2/src/Products.CMFPlone/Products/CMFPlone/tests/test_redirect_after_login.py", line 200, in test_zzzz
    self.browser.open('http://nohost/plone/bogus')
  File "/home/ale/.buildout/eggs/cp38/zope.testbrowser-5.6.1-py3.8.egg/zope/testbrowser/browser.py", line 256, in open
    self._processRequest(url, make_request)
  File "/home/ale/.buildout/eggs/cp38/zope.testbrowser-5.6.1-py3.8.egg/zope/testbrowser/browser.py", line 282, in _processRequest
    resp = make_request(reqargs)
  File "/home/ale/.buildout/eggs/cp38/zope.testbrowser-5.6.1-py3.8.egg/zope/testbrowser/browser.py", line 253, in make_request
    return self.testapp.get(url, **args)
  File "/home/ale/.buildout/eggs/cp38/WebTest-3.0.0-py3.8.egg/webtest/app.py", line 324, in get
    return self.do_request(req, status=status,
  File "/home/ale/.buildout/eggs/cp38/zope.testbrowser-5.6.1-py3.8.egg/zope/testbrowser/browser.py", line 93, in do_request
    response = super(TestbrowserApp, self).do_request(req, status,
  File "/home/ale/.buildout/eggs/cp38/WebTest-3.0.0-py3.8.egg/webtest/app.py", line 620, in do_request
    res = req.get_response(app, catch_exc_info=True)
  File "/home/ale/.buildout/eggs/cp38/WebOb-1.8.7-py3.8.egg/webob/request.py", line 1309, in send
    status, headers, app_iter, exc_info = self.call_application(
  File "/home/ale/.buildout/eggs/cp38/WebOb-1.8.7-py3.8.egg/webob/request.py", line 1278, in call_application
    app_iter = application(self.environ, start_response)
  File "/home/ale/.buildout/eggs/cp38/WebTest-3.0.0-py3.8.egg/webtest/lint.py", line 196, in lint_app
    iterator = application(environ, start_response_wrapper)
  File "/home/ale/.buildout/eggs/cp38/plone.testing-8.0.3-py3.8.egg/plone/testing/_z2_testbrowser.py", line 39, in wrapped_func
    return func(*args, **kw)
  File "/home/ale/.buildout/eggs/cp38/plone.testing-8.0.3-py3.8.egg/plone/testing/_z2_testbrowser.py", line 66, in __call__
    wsgi_result = publish(environ, start_response)
  File "/home/ale/.buildout/eggs/cp38/Zope-4.8.7-py3.8.egg/ZPublisher/WSGIPublisher.py", line 385, in publish_module
    response = _publish(request, new_mod_info)
  File "/home/ale/.buildout/eggs/cp38/Zope-4.8.7-py3.8.egg/ZPublisher/WSGIPublisher.py", line 264, in publish
    obj = request.traverse(path, validated_hook=validate_user)
  File "/home/ale/.buildout/eggs/cp38/Zope-4.8.7-py3.8.egg/ZPublisher/BaseRequest.py", line 535, in traverse
    return response.notFoundError(URL)
  File "/home/ale/.buildout/eggs/cp38/Zope-4.8.7-py3.8.egg/ZPublisher/HTTPResponse.py", line 999, in notFoundError
    raise exc
zExceptions.NotFound: http://nohost/plone/bogus
ale-rt commented 1 year ago

It seems that in Plone 6 we are trying to call request.close after the connection is closed:

  File "/home/ale/.buildout/eggs/cp311/Zope-5.8.2-py3.11.egg/ZPublisher/WSGIPublisher.py", line 405, in publish_module
    request.close()
  File "/home/ale/.buildout/eggs/cp311/Zope-5.8.2-py3.11.egg/ZPublisher/BaseRequest.py", line 215, in close
    notify(EndRequestEvent(None, self))

This should not be the case, given that the subscribers are stored in a site manager persistent list. This is a well known fact reading the comment to this code: https://github.com/zopefoundation/Zope/blob/5128b943df76d5fb557245eedd841c85ad7ba1c0/src/ZPublisher/BaseRequest.py#L213-L219

ale-rt commented 1 year ago

The problem is in zope.component that since version 5 stores the subscribers in a PersistentList.

Here what we have in Plone6.1:

[26] > /home/ale/.buildout/eggs/cp311/zope.interface-6.0-py3.11-linux-x86_64.egg/zope/interface/adapter.py(878)_uncached_subscriptions()
-> continue
(Pdb++) self._registry.ro[0]
<zope.component.persistentregistry.PersistentAdapterRegistry object at 0x7fcbd097b3f0 oid 0x969d3f9388a51b2 in <Connection at 7fcbd22f1010>>
(Pdb++) self._registry.ro[0]._subscribers.__class__
<class 'persistent.list.PersistentList'>

Here what we have in Plone 5.2:

[26] > /home/ale/.buildout/eggs/cp38/zope.interface-5.5.2-py3.8-linux-x86_64.egg/zope/interface/adapter.py(879)_uncached_subscriptions()
-> breakpoint()
(Pdb++) self._registry.ro[0]
<zope.component.persistentregistry.PersistentAdapterRegistry object at 0x7f912ddda040 oid 0x24c06c6911bc3788 in <Connection at 7f912ddaab20>>
(Pdb++) self._registry.ro[0]._subscribers.__class__
<class 'list'>