Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Fixed tests when run with zope.component 5+. #107

Merged
merged 1 commit into from
Mar 16, 2022

Conversation

mauritsvanrees
Copy link
Member

Sample test failure:

File "/Users/maurits/community/plone-coredev/6.0/src/plone.app.users/plone/app/users/tests/password.rst", line 27, in password.rst
Failed example:
    browser.open('http://nohost/plone/' + view_name)
Expected:
    Traceback (most recent call last):
    ...
    zExceptions.unauthorized.Unauthorized: ...You are not authorized to access this resource...
Got:
    Traceback (most recent call last):
      File "/Users/maurits/.pyenv/versions/3.9.9/lib/python3.9/doctest.py", line 1334, in __run
        exec(compile(example.source, filename, "single",
      File "<doctest password.rst[8]>", line 1, in <module>
        browser.open('http://nohost/plone/' + view_name)
      File "/Users/maurits/shared-eggs/cp39/zope.testbrowser-5.5.1-py3.9.egg/zope/testbrowser/browser.py", line 256, in open
        self._processRequest(url, make_request)
      File "/Users/maurits/shared-eggs/cp39/zope.testbrowser-5.5.1-py3.9.egg/zope/testbrowser/browser.py", line 282, in _processRequest
        resp = make_request(reqargs)
      File "/Users/maurits/shared-eggs/cp39/zope.testbrowser-5.5.1-py3.9.egg/zope/testbrowser/browser.py", line 253, in make_request
        return self.testapp.get(url, **args)
      File "/Users/maurits/shared-eggs/cp39/WebTest-3.0.0-py3.9.egg/webtest/app.py", line 324, in get
        return self.do_request(req, status=status,
      File "/Users/maurits/shared-eggs/cp39/zope.testbrowser-5.5.1-py3.9.egg/zope/testbrowser/browser.py", line 93, in do_request
        response = super(TestbrowserApp, self).do_request(req, status,
      File "/Users/maurits/shared-eggs/cp39/WebTest-3.0.0-py3.9.egg/webtest/app.py", line 620, in do_request
        res = req.get_response(app, catch_exc_info=True)
      File "/Users/maurits/shared-eggs/cp39/WebOb-1.8.7-py3.9.egg/webob/request.py", line 1309, in send
        status, headers, app_iter, exc_info = self.call_application(
      File "/Users/maurits/shared-eggs/cp39/WebOb-1.8.7-py3.9.egg/webob/request.py", line 1278, in call_application
        app_iter = application(self.environ, start_response)
      File "/Users/maurits/shared-eggs/cp39/WebTest-3.0.0-py3.9.egg/webtest/lint.py", line 196, in lint_app
        iterator = application(environ, start_response_wrapper)
      File "/Users/maurits/shared-eggs/cp39/plone.testing-8.0.3-py3.9.egg/plone/testing/_z2_testbrowser.py", line 39, in wrapped_func
        return func(*args, **kw)
      File "/Users/maurits/shared-eggs/cp39/plone.testing-8.0.3-py3.9.egg/plone/testing/_z2_testbrowser.py", line 66, in __call__
        wsgi_result = publish(environ, start_response)
      File "/Users/maurits/community/plone-coredev/6.0/src/Zope/src/ZPublisher/WSGIPublisher.py", line 391, in publish_module
        request.close()
      File "/Users/maurits/community/plone-coredev/6.0/src/Zope/src/ZPublisher/BaseRequest.py", line 215, in close
        notify(EndRequestEvent(None, self))
      File "/Users/maurits/shared-eggs/cp39/zope.event-4.5.0-py3.9.egg/zope/event/__init__.py", line 32, in notify
        subscriber(event)
      File "/Users/maurits/shared-eggs/cp39/zope.component-5.0.1-py3.9.egg/zope/component/event.py", line 27, in dispatch
        component_subscribers(event, None)
      File "/Users/maurits/shared-eggs/cp39/zope.component-5.0.1-py3.9.egg/zope/component/_api.py", line 134, in subscribers
        return sitemanager.subscribers(objects, interface)
      File "/Users/maurits/shared-eggs/cp39/zope.interface-5.4.0-py3.9-macosx-10.15-x86_64.egg/zope/interface/registry.py", line 448, in subscribers
        return self.adapters.subscribers(objects, provided)
      File "/Users/maurits/shared-eggs/cp39/zope.interface-5.4.0-py3.9-macosx-10.15-x86_64.egg/zope/interface/adapter.py", line 895, in subscribers
        subscriptions = self.subscriptions([providedBy(o) for o in objects], provided)
      File "/Users/maurits/shared-eggs/cp39/zope.interface-5.4.0-py3.9-macosx-10.15-x86_64.egg/zope/interface/adapter.py", line 877, in _uncached_subscriptions
        if order >= len(byorder):
      File "/Users/maurits/.pyenv/versions/3.9.9/lib/python3.9/collections/__init__.py", line 1169, in __len__
        return len(self.data)
      File "/Users/maurits/shared-eggs/cp39/ZODB-5.6.0-py3.9.egg/ZODB/Connection.py", line 785, in setstate
        raise ConnectionStateError(msg)
    ZODB.POSException.ConnectionStateError: Shouldn't load state for persistent.list.PersistentList 0x3953f62e87808eb2 when the connection is closed

Should be somehow caused by this zope.component PR:
zopefoundation/zope.component#51

From what I can follow from the traceback and running around in the pdb, it goes wrong in this part of ZPublisher/BaseRequest.py:

    def close(self):
        try:
            notify(EndRequestEvent(None, self))
        finally:
            # subscribers might need the zodb, so `clear` must come afterwards
            # (since `self._held=None` might close the connection, see above)
            self.clear()

The notify fails, even when I comment out the two subscribers that I found (Products.Five and plone.app.contentrules).
Probably some other code has already called self.clear() before this.
A reason for this can be that several subrequests are made for the Diazo theme, and this seems to call self.clear() directly.
Whatever the reason, the comment is true: subscribers might need the zodb.
In fact, with zope.component 5, the list of subscribers itself, even when it is empty, is something that we get from the zodb.
So it fails here.

When I run bin/instance fg and visit the same page anonymously (@@change-password) it works fine:
I am Unauthorized and get redirected, which is also what the test expects.
So in practice all seems fine.

So what somehow triggers the ZODB error, is that this is a test, and the first browser visit is to a page that raises an Unauthorized.
The fix/workaround is to first visit the root of the site. Then somehow all is well.

Note: last time I tried this, most tests in most packages passed just fine.
plone.app.users was an exception, and there were about two other packages I think.
I will follow up with more PRs, but this one should be fine, also for use with our current outdated zope.component 4.6.2.

Sample test failure:

```
File "/Users/maurits/community/plone-coredev/6.0/src/plone.app.users/plone/app/users/tests/password.rst", line 27, in password.rst
Failed example:
    browser.open('http://nohost/plone/' + view_name)
Expected:
    Traceback (most recent call last):
    ...
    zExceptions.unauthorized.Unauthorized: ...You are not authorized to access this resource...
Got:
    Traceback (most recent call last):
      File "/Users/maurits/.pyenv/versions/3.9.9/lib/python3.9/doctest.py", line 1334, in __run
        exec(compile(example.source, filename, "single",
      File "<doctest password.rst[8]>", line 1, in <module>
        browser.open('http://nohost/plone/' + view_name)
      File "/Users/maurits/shared-eggs/cp39/zope.testbrowser-5.5.1-py3.9.egg/zope/testbrowser/browser.py", line 256, in open
        self._processRequest(url, make_request)
      File "/Users/maurits/shared-eggs/cp39/zope.testbrowser-5.5.1-py3.9.egg/zope/testbrowser/browser.py", line 282, in _processRequest
        resp = make_request(reqargs)
      File "/Users/maurits/shared-eggs/cp39/zope.testbrowser-5.5.1-py3.9.egg/zope/testbrowser/browser.py", line 253, in make_request
        return self.testapp.get(url, **args)
      File "/Users/maurits/shared-eggs/cp39/WebTest-3.0.0-py3.9.egg/webtest/app.py", line 324, in get
        return self.do_request(req, status=status,
      File "/Users/maurits/shared-eggs/cp39/zope.testbrowser-5.5.1-py3.9.egg/zope/testbrowser/browser.py", line 93, in do_request
        response = super(TestbrowserApp, self).do_request(req, status,
      File "/Users/maurits/shared-eggs/cp39/WebTest-3.0.0-py3.9.egg/webtest/app.py", line 620, in do_request
        res = req.get_response(app, catch_exc_info=True)
      File "/Users/maurits/shared-eggs/cp39/WebOb-1.8.7-py3.9.egg/webob/request.py", line 1309, in send
        status, headers, app_iter, exc_info = self.call_application(
      File "/Users/maurits/shared-eggs/cp39/WebOb-1.8.7-py3.9.egg/webob/request.py", line 1278, in call_application
        app_iter = application(self.environ, start_response)
      File "/Users/maurits/shared-eggs/cp39/WebTest-3.0.0-py3.9.egg/webtest/lint.py", line 196, in lint_app
        iterator = application(environ, start_response_wrapper)
      File "/Users/maurits/shared-eggs/cp39/plone.testing-8.0.3-py3.9.egg/plone/testing/_z2_testbrowser.py", line 39, in wrapped_func
        return func(*args, **kw)
      File "/Users/maurits/shared-eggs/cp39/plone.testing-8.0.3-py3.9.egg/plone/testing/_z2_testbrowser.py", line 66, in __call__
        wsgi_result = publish(environ, start_response)
      File "/Users/maurits/community/plone-coredev/6.0/src/Zope/src/ZPublisher/WSGIPublisher.py", line 391, in publish_module
        request.close()
      File "/Users/maurits/community/plone-coredev/6.0/src/Zope/src/ZPublisher/BaseRequest.py", line 215, in close
        notify(EndRequestEvent(None, self))
      File "/Users/maurits/shared-eggs/cp39/zope.event-4.5.0-py3.9.egg/zope/event/__init__.py", line 32, in notify
        subscriber(event)
      File "/Users/maurits/shared-eggs/cp39/zope.component-5.0.1-py3.9.egg/zope/component/event.py", line 27, in dispatch
        component_subscribers(event, None)
      File "/Users/maurits/shared-eggs/cp39/zope.component-5.0.1-py3.9.egg/zope/component/_api.py", line 134, in subscribers
        return sitemanager.subscribers(objects, interface)
      File "/Users/maurits/shared-eggs/cp39/zope.interface-5.4.0-py3.9-macosx-10.15-x86_64.egg/zope/interface/registry.py", line 448, in subscribers
        return self.adapters.subscribers(objects, provided)
      File "/Users/maurits/shared-eggs/cp39/zope.interface-5.4.0-py3.9-macosx-10.15-x86_64.egg/zope/interface/adapter.py", line 895, in subscribers
        subscriptions = self.subscriptions([providedBy(o) for o in objects], provided)
      File "/Users/maurits/shared-eggs/cp39/zope.interface-5.4.0-py3.9-macosx-10.15-x86_64.egg/zope/interface/adapter.py", line 877, in _uncached_subscriptions
        if order >= len(byorder):
      File "/Users/maurits/.pyenv/versions/3.9.9/lib/python3.9/collections/__init__.py", line 1169, in __len__
        return len(self.data)
      File "/Users/maurits/shared-eggs/cp39/ZODB-5.6.0-py3.9.egg/ZODB/Connection.py", line 785, in setstate
        raise ConnectionStateError(msg)
    ZODB.POSException.ConnectionStateError: Shouldn't load state for persistent.list.PersistentList 0x3953f62e87808eb2 when the connection is closed
```

Should be somehow caused by this zope.component PR:
zopefoundation/zope.component#51

From what I can follow from the traceback and running around in the pdb, it goes wrong in this part of `ZPublisher/BaseRequest.py`:

```
    def close(self):
        try:
            notify(EndRequestEvent(None, self))
        finally:
            # subscribers might need the zodb, so `clear` must come afterwards
            # (since `self._held=None` might close the connection, see above)
            self.clear()
```

The notify fails, even when I comment out the two subscribers that I found (`Products.Five` and `plone.app.contentrules`).
Probably some other code has already called `self.clear()` before this.
A reason for this can be that several subrequests are made for the Diazo theme, and this seems to call `self.clear()` directly.
Whatever the reason, the comment is true: subscribers might need the zodb.
In fact, with zope.component 5, the list of subscribers itself, even when it is empty, is something that we get from the zodb.
So it fails here.

When I run `bin/instance fg` and visit the same page anonymously (`@@change-password`) it works fine:
I am Unauthorized and get redirected, which is also what the test expects.
So in practice all seems fine.

So what somehow triggers the ZODB error, is that this is a test, and the first browser visit is to a page that raises an Unauthorized.
The fix/workaround is to first visit the root of the site.  Then somehow all is well.

Note: last time I tried this, most tests in most packages passed just fine.
`plone.app.users` was an exception, and there were about two other packages I think.
I will follow up with more PRs, but this one should be fine, also for use with our current outdated zope.component 4.6.2.
@mister-roboto
Copy link

@mauritsvanrees thanks for creating this Pull Request and helping to improve Plone!

TL;DR: Finish pushing changes, pass all other checks, then paste a comment:

@jenkins-plone-org please run jobs

To ensure that these changes do not break other parts of Plone, the Plone test suite matrix needs to pass, but it takes 30-60 min. Other CI checks are usually much faster and the Plone Jenkins resources are limited, so when done pushing changes and all other checks pass either start all Jenkins PR jobs yourself, or simply add the comment above in this PR to start all the jobs automatically.

Happy hacking!

@mauritsvanrees
Copy link
Member Author

@jenkins-plone-org please run jobs

@mauritsvanrees
Copy link
Member Author

BTW, a possible alternative way to attack and solve this problem, is described here by Jason Madden. But I am not sure how to pick that up. Also, that comment is about "errors caused by test hygiene issues" and that does not seem to be the case here.

@mauritsvanrees
Copy link
Member Author

I have run all coredev tests locally with zope.component 5.0.1, except the robot tests, and that resulted in 3 failures in plone.app.users, fixed in this PR, one in plone.app.customerize, fixed in plone/plone.app.customerize#20, and two in Products.CMFPlone, fixed in plone/Products.CMFPlone#3451.

Once green and merged, I will make a PR for coredev to use latest zope.component as pinned by Zope.

@mauritsvanrees
Copy link
Member Author

Note: all tests with failures were the same:

  • using zope.testbrowser
  • first visit results in an Unauthorized or other exception

mauritsvanrees added a commit to plone/Products.CMFPlone that referenced this pull request Mar 16, 2022
mister-roboto pushed a commit to plone/buildout.coredev that referenced this pull request Mar 16, 2022
Branch: refs/heads/master
Date: 2022-03-16T09:25:47+01:00
Author: Maurits van Rees (mauritsvanrees) <maurits@vanrees.org>
Commit: plone/Products.CMFPlone@3061816

Fixed tests when run with zope.component 5+.

See plone/plone.app.users#107

Files changed:
A news/500.bugfix
M Products/CMFPlone/tests/testSecurity.py
mister-roboto pushed a commit to plone/buildout.coredev that referenced this pull request Mar 16, 2022
Branch: refs/heads/master
Date: 2022-03-08T20:59:56+01:00
Author: Maurits van Rees (mauritsvanrees) <maurits@vanrees.org>
Commit: plone/plone.app.customerize@dd92054

Fixed tests when run with zope.component 5+.

See plone/plone.app.users#107

Files changed:
A news/500.bugfix
M plone/app/customerize/tests/testBrowserLayers.txt
Repository: plone.app.customerize

Branch: refs/heads/master
Date: 2022-03-16T09:25:59+01:00
Author: Maurits van Rees (mauritsvanrees) <maurits@vanrees.org>
Commit: plone/plone.app.customerize@71f66fb

Merge pull request #20 from plone/maurits-zope-component-5

Fixed tests when run with zope.component 5+.

Files changed:
A news/500.bugfix
M plone/app/customerize/tests/testBrowserLayers.txt
mister-roboto pushed a commit to plone/buildout.coredev that referenced this pull request Mar 16, 2022
Branch: refs/heads/master
Date: 2022-03-08T20:59:56+01:00
Author: Maurits van Rees (mauritsvanrees) <maurits@vanrees.org>
Commit: plone/plone.app.customerize@dd92054

Fixed tests when run with zope.component 5+.

See plone/plone.app.users#107

Files changed:
A news/500.bugfix
M plone/app/customerize/tests/testBrowserLayers.txt
Repository: plone.app.customerize

Branch: refs/heads/master
Date: 2022-03-16T09:25:59+01:00
Author: Maurits van Rees (mauritsvanrees) <maurits@vanrees.org>
Commit: plone/plone.app.customerize@71f66fb

Merge pull request #20 from plone/maurits-zope-component-5

Fixed tests when run with zope.component 5+.

Files changed:
A news/500.bugfix
M plone/app/customerize/tests/testBrowserLayers.txt
@mauritsvanrees mauritsvanrees merged commit eb12ba1 into master Mar 16, 2022
@mauritsvanrees mauritsvanrees deleted the maurits-zope-component-5 branch March 16, 2022 08:26
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

2 participants