ZODB ConnectionStateError with BTrees - shouldn't load state when connection is closed

1

Plone 6.0.13 Classic UI.
This topic has come up a few times on this forum and here plone - What are the possible causes of a ConnectionStateError? - Stack Overflow. From that, I'm led to believe that the problem may be due to RAM caching (plone.memoize) persistent objects across threads. I am using ZEO and get this error when running a single waitress.

Two separate tracebacks here, note that it is when rendering the related_projects field but the ConnectionStateError manifests in a different place. I am having a hard time consistently reproducing this error. The content type here is Project - I've tried to create a Project as user, then edit a Project as another user and sometimes this will produce this error. But not always.

Exception Value
    ZODB.POSException.ConnectionStateError: Shouldn't load state for BTrees.IIBTree.IITreeSet 0x1e38f4 when the connection is closed - Expression: "python:widget.render()" - Filename: ... ources/ims.project/ims/webdev/browser/templates/widget.pt - Location: (line 49: col 32) - Source: ... al:replace="structure python:widget.render()" ^^^^^^^^^^^^^^^^^^^^^^ - Expression: "widget/@@ploneform-render-widget" - Filename: ... ims.project/ims/webdev/browser/templates/subgroup_form.pt - Location: (line 153: col 73) - Source: ... place="structure widget/@@ploneform-render-widget" /> ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ - Expression: "context/main_template/macros/master" - Filename: ... /ims.project/ims/webdev/browser/templates/project_edit.pt - Location: (line 6: col 23) - Source: ... etal:use-macro="context/main_template/macros/master"> ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ - Arguments: template: <Products.Five.browser.pagetemplatefile.ViewPageTemplateFile object at 0x7f9a16dafe10> options: {} args: () nothing: None modules: <Products.PageTemplates.ZRPythonExpr._SecureModuleImporter object at 0x7f9a67577fd0> request: <WSGIRequest, URL=https://[redacted dev site]/software-projects/bsi/@@edit> view: <Products.Five.browser.metaconfigure.RenderWidget object at 0x7f9a033941d0> context: <SelectWidget 'form.widgets.related_projects'> views: <Products.Five.browser.pagetemplatefile.ViewMapper object at 0x7f9a03719e10> here: <SelectWidget 'form.widgets.related_projects'> container: <SelectWidget 'form.widgets.related_projects'> root: None traverse_subpath: [] user: <PloneUser 'carterg@adfs.omni.imsweb.com'> default: <DEFAULT> repeat: <Products.PageTemplates.engine.RepeatDictWrapper object at 0x7f9a0326a170> loop: {} target_language: None translate: <function BaseTemplate.render.<locals>.translate at 0x7f9a02e31080>

Traceback (innermost last):

    Module ZPublisher.WSGIPublisher, line 181, in transaction_pubevents
    Module ZPublisher.WSGIPublisher, line 391, in publish_module
    Module ZPublisher.WSGIPublisher, line 285, in publish
    Module ZPublisher.mapply, line 98, in mapply
    Module ZPublisher.WSGIPublisher, line 68, in call_object
    Module z3c.form.form, line 239, in __call__
    Module ims.project.browser.project, line 176, in render
    Module z3c.form.form, line 163, in render
    Module Products.Five.browser.pagetemplatefile, line 126, in __call__
    Module Products.Five.browser.pagetemplatefile, line 58, in __call__
    Module zope.pagetemplate.pagetemplate, line 134, in pt_render
    Module Products.PageTemplates.engine, line 365, in __call__
    Module z3c.pt.pagetemplate, line 174, in render
    Module chameleon.zpt.template, line 331, in render
    Module chameleon.template, line 193, in render
    Module 87a0bf8f6568ce5e04142488a04cf6d8.py, line 197, in render
    Module 095cbc6011f24e96a7cca502a87c6443.py, line 929, in render_master
    Module 095cbc6011f24e96a7cca502a87c6443.py, line 1589, in render_content
    Module 87a0bf8f6568ce5e04142488a04cf6d8.py, line 178, in __fill_main
    Module 7d6d102cb71cb377b09666a913f2848d.py, line 961, in render_titlelessform
    Module 7d6d102cb71cb377b09666a913f2848d.py, line 1284, in render_fields
    Module 7d6d102cb71cb377b09666a913f2848d.py, line 1956, in render_widget_rendering
    Module 7d6d102cb71cb377b09666a913f2848d.py, line 2079, in render_field
    Module zope.tales.expressions, line 248, in __call__
    Module Products.PageTemplates.Expressions, line 224, in _eval
    Module Products.PageTemplates.Expressions, line 155, in render
    Module zope.browserpage.simpleviewclass, line 44, in __call__
    Module Products.Five.browser.pagetemplatefile, line 126, in __call__
    Module Products.Five.browser.pagetemplatefile, line 58, in __call__
    Module zope.pagetemplate.pagetemplate, line 134, in pt_render
    Module Products.PageTemplates.engine, line 365, in __call__
    Module z3c.pt.pagetemplate, line 174, in render
    Module chameleon.zpt.template, line 331, in render
    Module chameleon.template, line 217, in render
    Module chameleon.utils, line 20, in raise_with_traceback
    Module chameleon.template, line 193, in render
    Module ef0d272d90666d38d7c756e206775706.py, line 725, in render
    Module ef0d272d90666d38d7c756e206775706.py, line 564, in render_widget_wrapper
    Module zope.tales.pythonexpr, line 73, in __call__
    __traceback_info__: (widget.render())
    Module <string>, line 1, in <module>
    Module plone.app.z3cform.widgets.base, line 47, in render
    Module plone.app.z3cform.widgets.select, line 106, in _base_args
    Module plone.app.z3cform.widgets.select, line 68, in items
    Module z3c.form.browser.select, line 85, in items
    Module plone.app.vocabularies.catalog, line 571, in __iter__
    Module plone.memoize.volatile, line 73, in replacement
    Module plone.app.vocabularies.catalog, line 763, in brains
    Module wildcard.hps.patches, line 25, in safeSearchResults
    Module ims.opensearch.patches, line 142, in searchResults
    Module Products.CMFPlone.CatalogTool, line 425, in searchResults
    Module Products.ZCatalog.ZCatalog, line 615, in searchResults
    Module Products.ZCatalog.Catalog, line 1084, in searchResults
    Module Products.ZCatalog.Catalog, line 627, in search
    Module Products.ZCatalog.Catalog, line 557, in _search_index
    Module Products.PluginIndexes.DateRangeIndex.DateRangeIndex, line 286, in query_index
    Module ZODB.Connection, line 781, in setstate

ZODB.POSException.ConnectionStateError: ZODB.POSException.ConnectionStateError: Shouldn't load state for BTrees.IIBTree.IITreeSet 0x1e38f4 when the connection is closed - Expression: "python:widget.render()" - Filename: ... ources/ims.project/ims/webdev/browser/templates/widget.pt - Location: (line 49: col 32) - Source: ... al:replace="structure python:widget.render()" ^^^^^^^^^^^^^^^^^^^^^^ - Expression: "widget/@@ploneform-render-widget" - Filename: ... ims.project/ims/webdev/browser/templates/subgroup_form.pt - Location: (line 153: col 73) - Source: ... place="structure widget/@@ploneform-render-widget" /> ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ - Expression: "context/main_template/macros/master" - Filename: ... /ims.project/ims/webdev/browser/templates/project_edit.pt - Location: (line 6: col 23) - Source: ... etal:use-macro="context/main_template/macros/master"> ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ - Arguments: template: <Products.Five.browser.pagetemplatefile.ViewPageTemplateFile object at 0x7f9a16dafe10> options: {} args: () nothing: None modules: <Products.PageTemplates.ZRPythonExpr._SecureModuleImporter object at 0x7f9a67577fd0> request: <WSGIRequest, URL=https://[redacted dev site]/software-projects/bsi/@@edit> view: <Products.Five.browser.metaconfigure.RenderWidget object at 0x7f9a033941d0> context: <SelectWidget 'form.widgets.related_projects'> views: <Products.Five.browser.pagetemplatefile.ViewMapper object at 0x7f9a03719e10> here: <SelectWidget 'form.widgets.related_projects'> container: <SelectWidget 'form.widgets.related_projects'> root: None traverse_subpath: [] user: <PloneUser 'carterg@adfs.omni.imsweb.com'> default: <DEFAULT> repeat: <Products.PageTemplates.engine.RepeatDictWrapper object at 0x7f9a0326a170> loop: {} target_language: None translate: <function BaseTemplate.render.<locals>.translate at 0x7f9a02e31080>

Exception Value
    ZODB.POSException.ConnectionStateError: Shouldn't load state for BTrees.Length.Length 0x0f49cb when the connection is closed - Expression: "python:widget.render()" - Filename: ... ources/ims.project/ims/webdev/browser/templates/widget.pt - Location: (line 49: col 32) - Source: ... al:replace="structure python:widget.render()" ^^^^^^^^^^^^^^^^^^^^^^ - Expression: "widget/@@ploneform-render-widget" - Filename: ... ims.project/ims/webdev/browser/templates/subgroup_form.pt - Location: (line 153: col 73) - Source: ... place="structure widget/@@ploneform-render-widget" /> ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ - Expression: "context/main_template/macros/master" - Filename: ... /ims.project/ims/webdev/browser/templates/project_edit.pt - Location: (line 6: col 23) - Source: ... etal:use-macro="context/main_template/macros/master"> ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ - Arguments: template: <Products.Five.browser.pagetemplatefile.ViewPageTemplateFile object at 0x7f0f1826e490> options: {} args: () nothing: None modules: <Products.PageTemplates.ZRPythonExpr._SecureModuleImporter object at 0x7f0f407572d0> request: <WSGIRequest, URL=https://[redacted dev site]/software-projects/bsi/@@edit> view: <Products.Five.browser.metaconfigure.RenderWidget object at 0x7f0edc1b7450> context: <SelectWidget 'form.widgets.related_projects'> views: <Products.Five.browser.pagetemplatefile.ViewMapper object at 0x7f0edc165d10> here: <SelectWidget 'form.widgets.related_projects'> container: <SelectWidget 'form.widgets.related_projects'> root: None traverse_subpath: [] user: <PloneUser 'ploneadmin@adfs.omni.imsweb.com'> default: <DEFAULT> repeat: <Products.PageTemplates.engine.RepeatDictWrapper object at 0x7f0edb839a40> loop: {} target_language: None translate: <function BaseTemplate.render.<locals>.translate at 0x7f0edb27fd80>

Traceback (innermost last):

    Module ZPublisher.WSGIPublisher, line 181, in transaction_pubevents
    Module ZPublisher.WSGIPublisher, line 391, in publish_module
    Module ZPublisher.WSGIPublisher, line 285, in publish
    Module ZPublisher.mapply, line 98, in mapply
    Module ZPublisher.WSGIPublisher, line 68, in call_object
    Module z3c.form.form, line 239, in __call__
    Module ims.project.browser.project, line 176, in render
    Module z3c.form.form, line 163, in render
    Module Products.Five.browser.pagetemplatefile, line 126, in __call__
    Module Products.Five.browser.pagetemplatefile, line 58, in __call__
    Module zope.pagetemplate.pagetemplate, line 134, in pt_render
    Module Products.PageTemplates.engine, line 365, in __call__
    Module z3c.pt.pagetemplate, line 174, in render
    Module chameleon.zpt.template, line 331, in render
    Module chameleon.template, line 193, in render
    Module 87a0bf8f6568ce5e04142488a04cf6d8.py, line 197, in render
    Module 095cbc6011f24e96a7cca502a87c6443.py, line 929, in render_master
    Module 095cbc6011f24e96a7cca502a87c6443.py, line 1589, in render_content
    Module 87a0bf8f6568ce5e04142488a04cf6d8.py, line 178, in __fill_main
    Module 7d6d102cb71cb377b09666a913f2848d.py, line 961, in render_titlelessform
    Module 7d6d102cb71cb377b09666a913f2848d.py, line 1284, in render_fields
    Module 7d6d102cb71cb377b09666a913f2848d.py, line 1956, in render_widget_rendering
    Module 7d6d102cb71cb377b09666a913f2848d.py, line 2079, in render_field
    Module zope.tales.expressions, line 248, in __call__
    Module Products.PageTemplates.Expressions, line 224, in _eval
    Module Products.PageTemplates.Expressions, line 155, in render
    Module zope.browserpage.simpleviewclass, line 44, in __call__
    Module Products.Five.browser.pagetemplatefile, line 126, in __call__
    Module Products.Five.browser.pagetemplatefile, line 58, in __call__
    Module zope.pagetemplate.pagetemplate, line 134, in pt_render
    Module Products.PageTemplates.engine, line 365, in __call__
    Module z3c.pt.pagetemplate, line 174, in render
    Module chameleon.zpt.template, line 331, in render
    Module chameleon.template, line 217, in render
    Module chameleon.utils, line 20, in raise_with_traceback
    Module chameleon.template, line 193, in render
    Module ef0d272d90666d38d7c756e206775706.py, line 725, in render
    Module ef0d272d90666d38d7c756e206775706.py, line 564, in render_widget_wrapper
    Module zope.tales.pythonexpr, line 73, in __call__
    __traceback_info__: (widget.render())
    Module <string>, line 1, in <module>
    Module plone.app.z3cform.widgets.base, line 47, in render
    Module plone.app.z3cform.widgets.select, line 106, in _base_args
    Module plone.app.z3cform.widgets.select, line 68, in items
    Module z3c.form.browser.select, line 85, in items
    Module plone.app.vocabularies.catalog, line 571, in __iter__
    Module plone.memoize.volatile, line 73, in replacement
    Module plone.app.vocabularies.catalog, line 763, in brains
    Module wildcard.hps.patches, line 25, in safeSearchResults
    Module ims.opensearch.patches, line 142, in searchResults
    Module Products.CMFPlone.CatalogTool, line 425, in searchResults
    Module Products.ZCatalog.ZCatalog, line 615, in searchResults
    Module Products.ZCatalog.Catalog, line 1084, in searchResults
    Module Products.ZCatalog.Catalog, line 627, in search
    Module Products.ZCatalog.Catalog, line 557, in _search_index
    Module Products.PluginIndexes.unindex, line 453, in query_index
    Module Products.PluginIndexes.unindex, line 412, in getRequestCacheKey
    Module Products.PluginIndexes.unindex, line 308, in getCounter
    Module BTrees.Length, line 58, in __call__
    Module ZODB.Connection, line 781, in setstate

Some notable things here:

  • the patches in wildcard.hps and ims.opensearch appear to be simply passing on to their base classes, so I don't suspect them to be a factor
  • plone.memoize is used by plone.app.vocabularies.catalog

This is the related_projects field in the schema

   directives.order_after(related_projects='billing')
    directives.widget(
        'related_projects',
        SelectFieldWidget
    )
    # need to move all of these down because of IJamisField.jamis
    directives.write_permission(related_projects='zope2.View')
    related_projects = RelationList(
        title=_('Related Projects'),
        default=[],
        required=False,
        value_type=RelationChoice(title=_('Project'),
                                  vocabulary=StaticCatalogVocabulary(
                                      {
                                          "object_provides": "ims.project.interfaces.project.IProject",
                                      },
                                      title_template="{brain.Title}"
                                  ))
    )

StaticCatalogVocabulary uses plone.memoize for some things. Is this a bug with Plone, or should I not be using StaticCatalogVocabulary this way? It is also very difficult to test if any fix has any effect - just a guess but perhaps sometimes when I make the request it makes a new thread and sometimes it doesn't? Can I make this consistently make a new thread somehow?

2

I put a tracepoint in DateRangeIndex and, at least for that case, it is the effectiveRange field. Products.CMFPlone.CatalogTool adds this key and allowedRolesAndUsers to most queries. It's just a DateTime object, which I would think is not a persistent object, but in any case if I remove that key and call ZCatalog.searchResults it works without this ConnectionStateError.

StaticCatalogVocabulary has caching on a few methods, for example the "brains" function. If the brains results add persistent objects in it this error would make sense to me, but again, I don't see how that would be the case. This may be a wild idea, but is it possible to inspect those brains and see if there is a persistent object in there?

3

I don't think caching is related to the problem after all. It's finding that there is no cache, and erroring on the original func call. Indeed, commenting out @ram.cache doesn't work.

What would be causing the connection to close?

4

Can anyone give some insight on how threading works in Zope? I tried setting the max threads to 1 and my team could not reproduce the problem (with the big caveat that the problem is not easily reproducible, so we can't be 100% sure this worked).

On rarer occasions, I will see the error in the logs but it does not get presented anywhere to the user. I don't know where that request came from - a new thread?

5

In general, this error happens if a persistent object tries to load its state from the ZODB after the connection that was used to access it is closed. You were right to expect it could be related to caching persistent objects, because that's where I've seen this before. But, as you figured out, this was a cache miss for StaticCatalogVocabulary.brains and the error happened while calling the original function, so caching doesn't seem to be implicated there.

StaticCatalogVocabulary.brains uses StaticCatalogVocabulary.catalog which is inherited from CatalogVocabulary.catalog, which is also cached, with a different caching decorator. This one is stored on the StaticCatalogVocabulary instance instead of on the request. So I think this error could happen if the same StaticCatalogVocabulary instance is used across multiple requests. (But only if those requests use different ZODB connections, which is why it doesn't happen if you have a single thread.)

I think if you create a named vocabulary factory (see plone.app.vocabularies/plone/app/vocabularies/catalog.py at master · plone/plone.app.vocabularies · GitHub) that will avoid this problem, since there will be a new instance of StaticCatalogVocabulary each time it is used.

But probably this should also be fixed in plone.app.vocabularies by removing the problematic caching of the catalog tool.