search

plone / volto

React-based frontend for the Plone Content Management System
https://demo.plone.org/
MIT License
453 stars 612 forks source link

Plone 6 Cypress tests - "Shouldn't load state for Products.CMFPlone.Portal.PloneSite 0x25deef56568b1865 when the connection is closed" #3294

Closed sneridagh closed 2 years ago

sneridagh commented 2 years ago

https://github.com/plone/volto/runs/6253883271?check_suite_focus=true

I already talked about this with @datakurre . I think that the teardown happens in the middle of the server doing something (like creating images scales, or other unfinished task), then you tear it down (via the xmlrpc call) then it complains hard.

With @datakurre we saw that maybe the Layers in the RobotFramework fixture should be reordered so they are tore down correctly... but this scapes to my knowledge of this matter.

/cc @ericof @davisagli @tisto

I can see a lot of these:

Method: POST
[2120](https://github.com/plone/volto/runs/6253883271?check_suite_focus=true#step:7:2120)
URL: http://localhost:55001/plone/my-folder/my-document
[2121](https://github.com/plone/volto/runs/6253883271?check_suite_focus=true#step:7:2121)
Headers: {
[2122](https://github.com/plone/volto/runs/6253883271?check_suite_focus=true#step:7:2122)
  "Connection": "keep-alive",
[2123](https://github.com/plone/volto/runs/6253883271?check_suite_focus=true#step:7:2123)
  "user-agent": "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/100.0.4896.127 Safari/537.36",
[2124](https://github.com/plone/volto/runs/6253883271?check_suite_focus=true#step:7:2124)
  "accept": "application/json",
[2125](https://github.com/plone/volto/runs/6253883271?check_suite_focus=true#step:7:2125)
  "cookie": "I18N_LANGUAGE=en; auth_token=***; __ac=NjE2NDZkNjk2ZTo%253D",
[2126](https://github.com/plone/volto/runs/6253883271?check_suite_focus=true#step:7:2126)
  "authorization": "Basic YWRtaW46c2VjcmV0",
[2127](https://github.com/plone/volto/runs/6253883271?check_suite_focus=true#step:7:2127)
  "accept-encoding": "gzip, deflate",
[2128](https://github.com/plone/volto/runs/6253883271?check_suite_focus=true#step:7:2128)
  "content-type": "application/json",
[2129](https://github.com/plone/volto/runs/6253883271?check_suite_focus=true#step:7:2129)
  "content-length": 307
[2130](https://github.com/plone/volto/runs/6253883271?check_suite_focus=true#step:7:2130)
}
[2131](https://github.com/plone/volto/runs/6253883271?check_suite_focus=true#step:7:2131)
Body: {"@type":"Document","id":"child","title":"My Child","blocks":{"d3f1c443-583f-4e8e-a682-3bf25752a300":{"@type":"title"},"7624cf59-05d0-4055-8f55-5fd6597d84b0":{"@type":"text"}},"blocks_layout":{"items":["d3f1c443-583f-4e8e-a682-3bf25752a300","7624cf59-05d0-4055-8f55-5fd6597d84b0"]},"allow_discussion":false}
[2132](https://github.com/plone/volto/runs/6253883271?check_suite_focus=true#step:7:2132)

[2133](https://github.com/plone/volto/runs/6253883271?check_suite_focus=true#step:7:2133)
-----------------------------------------------------------
[2134](https://github.com/plone/volto/runs/6253883271?check_suite_focus=true#step:7:2134)

[2135](https://github.com/plone/volto/runs/6253883271?check_suite_focus=true#step:7:2135)
The response we got was:
[2136](https://github.com/plone/volto/runs/6253883271?check_suite_focus=true#step:7:2136)

[2137](https://github.com/plone/volto/runs/6253883271?check_suite_focus=true#step:7:2137)
Status: 500 - Internal Server Error
[2138](https://github.com/plone/volto/runs/6253883271?check_suite_focus=true#step:7:2138)
Headers: {
[2139](https://github.com/plone/volto/runs/6253883271?check_suite_focus=true#step:7:2139)
  "content-length": "4925",
[2140](https://github.com/plone/volto/runs/6253883271?check_suite_focus=true#step:7:2140)
  "content-type": "application/json",
[2141](https://github.com/plone/volto/runs/6253883271?check_suite_focus=true#step:7:2141)
  "date": "Mon, 02 May 2022 07:51:36 GMT",
[2142](https://github.com/plone/volto/runs/6253883271?check_suite_focus=true#step:7:2142)
  "server": "waitress",
[2143](https://github.com/plone/volto/runs/6253883271?check_suite_focus=true#step:7:2143)
  "via": "waitress",
[2144](https://github.com/plone/volto/runs/6253883271?check_suite_focus=true#step:7:2144)
  "x-frame-options": "SAMEORIGIN",
[2145](https://github.com/plone/volto/runs/6253883271?check_suite_focus=true#step:7:2145)
  "x-powered-by": "Zope (www.zope.dev), Python (www.python.org)"
[2146](https://github.com/plone/volto/runs/6253883271?check_suite_focus=true#step:7:2146)
}
[2147](https://github.com/plone/volto/runs/6253883271?check_suite_focus=true#step:7:2147)
Body: {
[2148](https://github.com/plone/volto/runs/6253883271?check_suite_focus=true#step:7:2148)
  "message": "Shouldn't load state for Products.CMFPlone.Portal.PloneSite 0x25deef56568b1865 when the connection is closed",
[2149](https://github.com/plone/volto/runs/6253883271?check_suite_focus=true#step:7:2149)
  "traceback": [
[2150](https://github.com/plone/volto/runs/6253883271?check_suite_focus=true#step:7:2150)
    "File \"/app/lib/python3.9/site-packages/ZPublisher/WSGIPublisher.py\", line 167, in transaction_pubevents",
[2151](https://github.com/plone/volto/runs/6253883271?check_suite_focus=true#step:7:2151)
    "    yield",
[2152](https://github.com/plone/volto/runs/6253883271?check_suite_focus=true#step:7:2152)
    "",
[2153](https://github.com/plone/volto/runs/6253883271?check_suite_focus=true#step:7:2153)
    "  File \"/app/lib/python3.9/site-packages/ZPublisher/WSGIPublisher.py\", line 376, in publish_module",
[2154](https://github.com/plone/volto/runs/6253883271?check_suite_focus=true#step:7:2154)
    "    response = _publish(request, new_mod_info)",
[2155](https://github.com/plone/volto/runs/6253883271?check_suite_focus=true#step:7:2155)
    "",
[2156](https://github.com/plone/volto/runs/6253883271?check_suite_focus=true#step:7:2156)
    "  File \"/app/lib/python3.9/site-packages/ZPublisher/WSGIPublisher.py\", line 271, in publish",
[2157](https://github.com/plone/volto/runs/6253883271?check_suite_focus=true#step:7:2157)
    "    result = mapply(obj,",
[2158](https://github.com/plone/volto/runs/6253883271?check_suite_focus=true#step:7:2158)
    "",
[2159](https://github.com/plone/volto/runs/6253883271?check_suite_focus=true#step:7:2159)
    "  File \"/app/lib/python3.9/site-packages/ZPublisher/mapply.py\", line 85, in mapply",
[2160](https://github.com/plone/volto/runs/6253883271?check_suite_focus=true#step:7:2160)
    "    return debug(object, args, context)",
[2161](https://github.com/plone/volto/runs/6253883271?check_suite_focus=true#step:7:2161)
    "",
[2162](https://github.com/plone/volto/runs/6253883271?check_suite_focus=true#step:7:2162)
    "  File \"/app/lib/python3.9/site-packages/ZPublisher/WSGIPublisher.py\", line 68, in call_object",
[2163](https://github.com/plone/volto/runs/6253883271?check_suite_focus=true#step:7:2163)
    "    return obj(*args)",
[2164](https://github.com/plone/volto/runs/6253883271?check_suite_focus=true#step:7:2164)
    "",
[2165](https://github.com/plone/volto/runs/6253883271?check_suite_focus=true#step:7:2165)
    "  File \"/app/lib/python3.9/site-packages/plone/rest/service.py\", line 22, in __call__",
[2166](https://github.com/plone/volto/runs/6253883271?check_suite_focus=true#step:7:2166)
    "    return self.render()",
[2167](https://github.com/plone/volto/runs/6253883271?check_suite_focus=true#step:7:2167)
    "",
[2168](https://github.com/plone/volto/runs/6253883271?check_suite_focus=true#step:7:2168)
    "  File \"/app/lib/python3.9/site-packages/plone/restapi/services/__init__.py\", line 19, in render",
[2169](https://github.com/plone/volto/runs/6253883271?check_suite_focus=true#step:7:2169)
    "    content = self.reply()",
[2170](https://github.com/plone/volto/runs/6253883271?check_suite_focus=true#step:7:2170)
    "",
[2171](https://github.com/plone/volto/runs/6253883271?check_suite_focus=true#step:7:2171)
    "  File \"/app/lib/python3.9/site-packages/plone/restapi/services/content/add.py\", line 93, in reply",
[2172](https://github.com/plone/volto/runs/6253883271?check_suite_focus=true#step:7:2172)
    "    obj = add(self.context, obj, rename=not bool(id_))",
[2173](https://github.com/plone/volto/runs/6253883271?check_suite_focus=true#step:7:2173)
    "",
[2174](https://github.com/plone/volto/runs/6253883271?check_suite_focus=true#step:7:2174)
    "  File \"/app/lib/python3.9/site-packages/plone/restapi/services/content/utils.py\", line 95, in add",
[2175](https://github.com/plone/volto/runs/6253883271?check_suite_focus=true#step:7:2175)
    "    new_id = container._setObject(id_, obj)",
[2176](https://github.com/plone/volto/runs/6253883271?check_suite_focus=true#step:7:2176)
    "",
[2177](https://github.com/plone/volto/runs/6253883271?check_suite_focus=true#step:7:2177)
    "  File \"/app/lib/python3.9/site-packages/Products/BTreeFolder2/BTreeFolder2.py\", line 465, in _setObject",
[2178](https://github.com/plone/volto/runs/6253883271?check_suite_focus=true#step:7:2178)
    "    notify(ObjectAddedEvent(ob, self, id))",
[2179](https://github.com/plone/volto/runs/6253883271?check_suite_focus=true#step:7:2179)
    "",
[2180](https://github.com/plone/volto/runs/6253883271?check_suite_focus=true#step:7:2180)
    "  File \"/app/lib/python3.9/site-packages/zope/event/__init__.py\", line 32, in notify",
[2181](https://github.com/plone/volto/runs/6253883271?check_suite_focus=true#step:7:2181)
    "    subscriber(event)",
[2182](https://github.com/plone/volto/runs/6253883271?check_suite_focus=true#step:7:2182)
    "",
[2183](https://github.com/plone/volto/runs/6253883271?check_suite_focus=true#step:7:2183)
    "  File \"/app/lib/python3.9/site-packages/zope/component/event.py\", line 27, in dispatch",
[2184](https://github.com/plone/volto/runs/6253883271?check_suite_focus=true#step:7:2184)
    "    component_subscribers(event, None)",
[2185](https://github.com/plone/volto/runs/6253883271?check_suite_focus=true#step:7:2185)
    "",
[2186](https://github.com/plone/volto/runs/6253883271?check_suite_focus=true#step:7:2186)
    "  File \"/app/lib/python3.9/site-packages/zope/component/_api.py\", line 134, in subscribers",
[2187](https://github.com/plone/volto/runs/6253883271?check_suite_focus=true#step:7:2187)
    "    return sitemanager.subscribers(objects, interface)",
[2188](https://github.com/plone/volto/runs/6253883271?check_suite_focus=true#step:7:2188)
    "",
[2189](https://github.com/plone/volto/runs/6253883271?check_suite_focus=true#step:7:2189)
    "  File \"/app/lib/python3.9/site-packages/zope/interface/registry.py\", line 448, in subscribers",
[2190](https://github.com/plone/volto/runs/6253883271?check_suite_focus=true#step:7:2190)
    "    return self.adapters.subscribers(objects, provided)",
[2191](https://github.com/plone/volto/runs/6253883271?check_suite_focus=true#step:7:2191)
    "",
[2192](https://github.com/plone/volto/runs/6253883271?check_suite_focus=true#step:7:2192)
    "  File \"/app/lib/python3.9/site-packages/zope/interface/adapter.py\", line 899, in subscribers",
[2193](https://github.com/plone/volto/runs/6253883271?check_suite_focus=true#step:7:2193)
    "    subscription(*objects)",
[2194](https://github.com/plone/volto/runs/6253883271?check_suite_focus=true#step:7:2194)
    "",
[2195](https://github.com/plone/volto/runs/6253883271?check_suite_focus=true#step:7:2195)
    "  File \"/app/lib/python3.9/site-packages/zope/component/event.py\", line 36, in objectEventNotify",
[2196](https://github.com/plone/volto/runs/6253883271?check_suite_focus=true#step:7:2196)
    "    component_subscribers((event.object, event), None)",
[2197](https://github.com/plone/volto/runs/6253883271?check_suite_focus=true#step:7:2197)
    "",
[2198](https://github.com/plone/volto/runs/6253883271?check_suite_focus=true#step:7:2198)
    "  File \"/app/lib/python3.9/site-packages/zope/component/_api.py\", line 134, in subscribers",
[2199](https://github.com/plone/volto/runs/6253883271?check_suite_focus=true#step:7:2199)
    "    return sitemanager.subscribers(objects, interface)",
[2200](https://github.com/plone/volto/runs/6253883271?check_suite_focus=true#step:7:2200)
    "",
[2201](https://github.com/plone/volto/runs/6253883271?check_suite_focus=true#step:7:2201)
    "  File \"/app/lib/python3.9/site-packages/zope/interface/registry.py\", line 448, in subscribers",
[2202](https://github.com/plone/volto/runs/6253883271?check_suite_focus=true#step:7:2202)
    "    return self.adapters.subscribers(objects, provided)",
[2203](https://github.com/plone/volto/runs/6253883271?check_suite_focus=true#step:7:2203)
    "",
[2204](https://github.com/plone/volto/runs/6253883271?check_suite_focus=true#step:7:2204)
    "  File \"/app/lib/python3.9/site-packages/zope/interface/adapter.py\", line 899, in subscribers",
[2205](https://github.com/plone/volto/runs/6253883271?check_suite_focus=true#step:7:2205)
    "    subscription(*objects)",
[2206](https://github.com/plone/volto/runs/6253883271?check_suite_focus=true#step:7:2206)
    "",
[2207](https://github.com/plone/volto/runs/6253883271?check_suite_focus=true#step:7:2207)
    "  File \"/app/lib/python3.9/site-packages/Products/CMFCore/CMFCatalogAware.py\", line 274, in handleContentishEvent",
[2208](https://github.com/plone/volto/runs/6253883271?check_suite_focus=true#step:7:2208)
    "    wfaware.notifyWorkflowCreated()",
[2209](https://github.com/plone/volto/runs/6253883271?check_suite_focus=true#step:7:2209)
    "",
[2210](https://github.com/plone/volto/runs/6253883271?check_suite_focus=true#step:7:2210)
    "  File \"/app/lib/python3.9/site-packages/Products/CMFCore/CMFCatalogAware.py\", line 197, in notifyWorkflowCreated",
[2211](https://github.com/plone/volto/runs/6253883271?check_suite_focus=true#step:7:2211)
    "    wtool.notifyCreated(self)",
[2212](https://github.com/plone/volto/runs/6253883271?check_suite_focus=true#step:7:2212)
    "",
[2213](https://github.com/plone/volto/runs/6253883271?check_suite_focus=true#step:7:2213)
    "  File \"/app/lib/python3.9/site-packages/Products/CMFCore/WorkflowTool.py\", line 300, in notifyCreated",
[2214](https://github.com/plone/volto/runs/6253883271?check_suite_focus=true#step:7:2214)
    "    self._reindexWorkflowVariables(ob)",
[2215](https://github.com/plone/volto/runs/6253883271?check_suite_focus=true#step:7:2215)
    "",
[2216](https://github.com/plone/volto/runs/6253883271?check_suite_focus=true#step:7:2216)
    "  File \"/app/lib/python3.9/site-packages/Products/CMFCore/WorkflowTool.py\", line 610, in _reindexWorkflowVariables",
[2217](https://github.com/plone/volto/runs/6253883271?check_suite_focus=true#step:7:2217)
    "    ob.reindexObjectSecurity()",
[2218](https://github.com/plone/volto/runs/6253883271?check_suite_focus=true#step:7:2218)
    "",
[2219](https://github.com/plone/volto/runs/6253883271?check_suite_focus=true#step:7:2219)
    "  File \"/app/lib/python3.9/site-packages/Products/CMFCore/CMFCatalogAware.py\", line 110, in reindexObjectSecurity",
[2220](https://github.com/plone/volto/runs/6253883271?check_suite_focus=true#step:7:2220)
    "    for brain in catalog.unrestrictedSearchResults(path=path):",
[2221](https://github.com/plone/volto/runs/6253883271?check_suite_focus=true#step:7:2221)
    "",
[2222](https://github.com/plone/volto/runs/6253883271?check_suite_focus=true#step:7:2222)
    "  File \"/app/lib/python3.9/site-packages/Products/CMFCore/CatalogTool.py\", line 272, in unrestrictedSearchResults",
[2223](https://github.com/plone/volto/runs/6253883271?check_suite_focus=true#step:7:2223)
    "    processQueue()",
[2224](https://github.com/plone/volto/runs/6253883271?check_suite_focus=true#step:7:2224)
    "",
[2225](https://github.com/plone/volto/runs/6253883271?check_suite_focus=true#step:7:2225)
    "  File \"/app/lib/python3.9/site-packages/Products/CMFCore/indexing.py\", line 97, in processQueue",
[2226](https://github.com/plone/volto/runs/6253883271?check_suite_focus=true#step:7:2226)
    "    processed = queue.process()",
[2227](https://github.com/plone/volto/runs/6253883271?check_suite_focus=true#step:7:2227)
    "",
[2228](https://github.com/plone/volto/runs/6253883271?check_suite_focus=true#step:7:2228)
    "  File \"/app/lib/python3.9/site-packages/Products/CMFCore/indexing.py\", line 213, in process",
[2229](https://github.com/plone/volto/runs/6253883271?check_suite_focus=true#step:7:2229)
    "    self.optimize()",
[2230](https://github.com/plone/volto/runs/6253883271?check_suite_focus=true#step:7:2230)
    "",
[2231](https://github.com/plone/volto/runs/6253883271?check_suite_focus=true#step:7:2231)
    "  File \"/app/lib/python3.9/site-packages/Products/CMFCore/indexing.py\", line 179, in optimize",
[2232](https://github.com/plone/volto/runs/6253883271?check_suite_focus=true#step:7:2232)
    "    hash_id = hash_id, func()",
[2233](https://github.com/plone/volto/runs/6253883271?check_suite_focus=true#step:7:2233)
    "",
[2234](https://github.com/plone/volto/runs/6253883271?check_suite_focus=true#step:7:2234)
    "  File \"/app/lib/python3.9/site-packages/OFS/Traversable.py\", line 134, in getPhysicalPath",
[2235](https://github.com/plone/volto/runs/6253883271?check_suite_focus=true#step:7:2235)
    "    if func is p.getPhysicalPath.__func__:",
[2236](https://github.com/plone/volto/runs/6253883271?check_suite_focus=true#step:7:2236)
    "",
[2237](https://github.com/plone/volto/runs/6253883271?check_suite_focus=true#step:7:2237)
    "  File \"/app/lib/python3.9/site-packages/ZODB/Connection.py\", line 770, in setstate",
[2238](https://github.com/plone/volto/runs/6253883271?check_suite_focus=true#step:7:2238)
    "    raise ConnectionStateError(msg)"
[2239](https://github.com/plone/volto/runs/6253883271?check_suite_focus=true#step:7:2239)
  ],
[2240](https://github.com/plone/volto/runs/6253883271?check_suite_focus=true#step:7:2240)
  "type": "ConnectionStateError"
[2241](https://github.com/plone/volto/runs/6253883271?check_suite_focus=true#step:7:2241)
}
[2242](https://github.com/plone/volto/runs/6253883271?check_suite_focus=true#step:7:2242)
datakurre commented 2 years ago

I recall my final guess was that, because WSGI server layer does not stop listening to HTTP port between tests, it will keep handling requests between tests, independently rom the other layers, leading to unexpected DB state. And, if so, the fix would be to customize WSGI server layer to only start the server on testSetup, and also stop in on testTeardown.

datakurre commented 2 years ago

The notes I passed to Victor:

WSGI server layer would be called on testTearDown before Plone sandbox layer, because is the last one alphabetically https://github.com/zopefoundation/zope.testrunner/blob/9ee7fdf1cb56003571ad24ebc33b66ebb25ec299/src/zope/testrunner/runner.py#L1107

But it implements no testTearDown or testSetup. So WSGI server is only setup and teardown once, and therefore it is definitely listening for cyprus between tests and passing calls to Plone WSGI app.

Quick idea: Inherit a custom WSGI server layer from https://github.com/plone/plone.testing/blob/1756b024612763b8c84115ecaf4de9d0c48c8f59/src/plone/testing/zope.py#L883 and change the implementation there to only start the server in testSetup and stop it in testTearDown. Then ensure with robot server verbose logging that on testTearDown WSGI goes down before database teardown.

But even if you had your own WSGI layer, which would call shutdown on the testTearDown, it would be small possibility for similar race conditions, because the server is running in a thread and it probably could not stop currently handled request. But it should be single threaded and stop the queued request. And probably fix the issue. If not, one could probably sleep & wait for the server thread to stop, but that could be another bag of worms.

sneridagh commented 2 years ago

Related: https://github.com/plone/plone.app.robotframework/pull/131