Skip to content

Instantly share code, notes, and snippets.

@karenc

karenc/cnx-legacy-workspace-error.md

Last active January 1, 2020 21:30
Show Gist options
  • Save karenc/3beceaaa14ca1a066e0d111fb369dbf3 to your computer and use it in GitHub Desktop.
Save karenc/3beceaaa14ca1a066e0d111fb369dbf3 to your computer and use it in GitHub Desktop.
Download ZIP
Raw
cnx-legacy-workspace-error.md

(taken from https://github.com/openstax/cnx/issues/757)

Investigation

The servers running legacy are prod04 and prod05. This can be found on cnx-deploy:

[zclient:children]
prod04
prod05

From the first screenshot, you can see the url https://legacy.cnx.org/Members/mcantrall, so I would look for /Members/mcantrall in the logs. Legacy logs are in /var/lib/cnx/cnx-buildout/var/log/. ssh into prod04 and prod05 and look for the error. I use less and search within the file. I suggest going to the bottom of the file (less shortcut: G) and then do a reverse search (less shortcut: ?) and I found this:

2019-11-06T10:27:01 ERROR Zope.SiteErrorLog https://legacy.cnx.org/Members/mcantrall/workspace_contents
Traceback (innermost last):
  Module ZPublisher.Publish, line 115, in publish
  Module ZPublisher.mapply, line 88, in mapply
  Module ZPublisher.Publish, line 41, in call_object
  Module Shared.DC.Scripts.Bindings, line 311, in __call__
  Module Products.PloneHotfix20110531, line 106, in _patched_bindAndExec
  Module Products.PloneHotfix20130618.spamProtect, line 35, in _patched_bindAndExec
  Module Products.PloneHotfix20121106.python_scripts, line 63, in _patched_bindAndExec
  Module Shared.DC.Scripts.Bindings, line 348, in _bindAndExec
  Module Products.CMFCore.FSPageTemplate, line 195, in _exec
  Module Products.CacheSetup.patch_cmf, line 29, in FSPT_pt_render
  Module Products.CacheSetup.patch_utils, line 9, in call_pattern
  Module Products.CMFCore.FSPageTemplate, line 134, in pt_render
  Module Products.CacheSetup.patch_cmf, line 77, in PT_pt_render
  Module Products.CacheSetup.patch_utils, line 9, in call_pattern
  Module Products.PageTemplates.PageTemplate, line 104, in pt_render
   - <FSPageTemplate at /plone/workspace_contents used for /plone/Members/mcantrall>
  Module TAL.TALInterpreter, line 238, in __call__
  Module TAL.TALInterpreter, line 281, in interpret
  Module TAL.TALInterpreter, line 749, in do_useMacro
  Module TAL.TALInterpreter, line 281, in interpret
  Module TAL.TALInterpreter, line 457, in do_optTag_tal
  Module TAL.TALInterpreter, line 442, in do_optTag
  Module TAL.TALInterpreter, line 437, in no_tag
  Module TAL.TALInterpreter, line 281, in interpret
  Module TAL.TALInterpreter, line 780, in do_defineSlot
  Module TAL.TALInterpreter, line 281, in interpret
  Module TAL.TALInterpreter, line 457, in do_optTag_tal
  Module TAL.TALInterpreter, line 442, in do_optTag
  Module TAL.TALInterpreter, line 437, in no_tag
  ...
  Module TAL.TALInterpreter, line 281, in interpret
  Module TAL.TALInterpreter, line 507, in do_setLocal_tal
  Module Products.PageTemplates.TALES, line 221, in evaluate
   - URL: file:RhaptosSite/skins/rhaptos_site/workspace_contents.pt
   - Line 282, Column 20
   - Expression: standard:'item/getObject | nothing'
   - Names:
      {'container': <PloneSite at /plone>,
       'context': <PloneFolder at /plone/Members/mcantrall>,
       'default': <Products.PageTemplates.TALES.Default instance at 0x7f2e235b5cf8>,
       'here': <PloneFolder at /plone/Members/mcantrall>,
       'loop': <Products.PageTemplates.TALES.SafeMapping object at 0x7f2e0e9b0e60>,
       'modules': <Products.PageTemplates.ZRPythonExpr._SecureModuleImporter instance at 0x7f2e235b8488>,
       'nothing': None,
       'options': {'args': ()},
       'repeat': <Products.PageTemplates.TALES.SafeMapping object at 0x7f2e0e9b0e60>,
       'request': <HTTPRequest, URL=https://legacy.cnx.org/Members/mcantrall/workspace_contents>,
       'root': <Application at >,
       'template': <FSPageTemplate at /plone/workspace_contents used for /plone/Members/mcantrall>,
       'traverse_subpath': [],
       'user': <PloneUser 'sanura'>}
  Module Products.PageTemplates.Expressions, line 185, in __call__
  Module Products.PageTemplates.Expressions, line 180, in _eval
  Module Products.PageTemplates.Expressions, line 85, in render
  Module Products.ZCatalog.CatalogBrains, line 86, in getObject
  Module OFS.Traversable, line 250, in restrictedTraverse
  Module OFS.Traversable, line 187, in unrestrictedTraverse
   - __traceback_info__: ([], '2019-11-04.8137449132')
  Module Products.Five.traversable, line 126, in __bobo_traverse__
AttributeError: 2019-11-04.8137449132

This bit in the traceback gives you the filename:

   - URL: file:RhaptosSite/skins/rhaptos_site/workspace_contents.pt
   - Line 282, Column 20
   - Expression: standard:'item/getObject | nothing'

In the /var/lib/cnx/cnx-buildout, do

find -name workspace_contents.pt

You'd get something like this:

./eggs/Products.RhaptosSite-1.47-py2.4.egg/Products/RhaptosSite/skins/rhaptos_site/workspace_contents.pt
./eggs/Products.RhaptosSite-1.49-py2.4.egg/Products/RhaptosSite/skins/rhaptos_site/workspace_contents.pt
./eggs/Products.RhaptosSite-1.46-py2.4.egg/Products/RhaptosSite/skins/rhaptos_site/workspace_contents.pt
./eggs/Products.RhaptosSite-1.48-py2.4.egg/Products/RhaptosSite/skins/rhaptos_site/workspace_contents.pt

Older eggs are often not deleted, the file we need is the latest one

./eggs/Products.RhaptosSite-1.49-py2.4.egg/Products/RhaptosSite/skins/rhaptos_site/workspace_contents.pt

I'm not sure what the line number in the traceback (Line 282, Column 20) refers to because the file only has 200 lines.

But we can look for the expression item/getObject, and it's on line 149:

        <metal:item_slot metal:fill-slot="item_display" i18n:domain="plone"
                         tal:define="obj item/getObject | nothing">

This is the current plone documentation for the zope page template language: https://docs.plone.org/adapt-and-extend/theming/templates_css/template_basics.html

Plone uses Zope Page Templates, consisting of the three related standards:

  • Template Attribute Language (TAL)
  • TAL Expression Syntax (TALES)
  • Macro Expansion TAL (METAL).

Note: we are using plone version 2.5, and the current version of plone at the time of writing is 5.2, so a lot of the documentation probably doesn't apply.

tal:define=obj item/getObject | nothing means something like:

try:
    obj = item.getObject()  # or item.getObject
except:
    obj = None

But item isn't actually defined in this file. Look further up the file, you'll see on line 127:

<metal:contentsmacro use-macro="context/folder_contents/macros/contents">

This means use the macro called "contents" in a file called folder_contents.*.

find -name 'folder_contents.*'

./parts/plone/GroupUserFolder/doc/folder_contents.png
./parts/plone/CMFPlone/skins/plone_templates/folder_contents.pt.metadata
./parts/plone/CMFPlone/skins/plone_templates/folder_contents.pt
./parts/plone/CMFDefault/skins/generic/folder_contents.dtml
./parts/plone/CMFDefault/skins/zpt_generic/folder_contents.py
./eggs/Products.RhaptosSite-1.47-py2.4.egg/Products/RhaptosSite/skins/rhaptos_overrides/folder_contents.pt.metadata
./eggs/Products.RhaptosSite-1.47-py2.4.egg/Products/RhaptosSite/skins/rhaptos_overrides/folder_contents.pt
./eggs/Products.RhaptosSite-1.49-py2.4.egg/Products/RhaptosSite/skins/rhaptos_overrides/folder_contents.pt.metadata
./eggs/Products.RhaptosSite-1.49-py2.4.egg/Products/RhaptosSite/skins/rhaptos_overrides/folder_contents.pt
./eggs/Products.RhaptosSite-1.46-py2.4.egg/Products/RhaptosSite/skins/rhaptos_overrides/folder_contents.pt.metadata
./eggs/Products.RhaptosSite-1.46-py2.4.egg/Products/RhaptosSite/skins/rhaptos_overrides/folder_contents.pt
./eggs/Products.RhaptosSite-1.48-py2.4.egg/Products/RhaptosSite/skins/rhaptos_overrides/folder_contents.pt.metadata
./eggs/Products.RhaptosSite-1.48-py2.4.egg/Products/RhaptosSite/skins/rhaptos_overrides/folder_contents.pt

This time there are results from parts/, it contains some plone and zope packages and some third party packages. Our packages are in eggs/, but there are other third party packages in eggs/ as well.

Since Products.RhaptosSite is one of our packages, it's most likely to be overriding the default zope and plone ones.

So open ./eggs/Products.RhaptosSite-1.49-py2.4.egg/Products/RhaptosSite/skins/rhaptos_overrides/folder_contents.pt.

Searching for item, I found on line 241:

<tal:items tal:repeat="item batch">

This is like:

for item in batch:

Next, we need to look for the definition of batch, on line 46 - 54:

    <metal:contentsmacro define-macro="contents"
         tal:define="standalone python:1;
                     contentTypes here/getAllowedTypes;
                     contentFilter contentFilter|request/contentFilter|nothing;
                     b_size b_size|request/b_size|python:100;
                     view_title view_title|request/view_title|string:;
                     contentsMethod python:test(here.portal_type=='Topic', here.queryCatalog, here.getFolderContents);
                     batch batch|python:contentsMethod(contentFilter,batch=True, b_size=b_size);
                     full_view full_view|request/full_view|python:True;">

batch is contentsMethod(contentFilter, batch=True, b_size=b_size), contentsMethod is here.queryCatalog if here.portal_type == 'Topic' else here.getFolderContents. contentFilter is None unless there is a post or get request parameter called contentFilter, b_size is 100 unless there is a post or get request parameter called b_size.

Next, it's time to get a python shell with the zope application:

./bin/instance debug

The first line (among lots of warnings) is:

Starting debugger (the name "app" is bound to the top-level Zope object)

You can see it by doing:

>>> app
<Application at >

ZODB (Zope Object Database) is an object oriented database for storing python objects.

For example, you can use objectValues() to find all the child objects of app.

>>> app.objectValues()
[<ApplicationManager at /Control_Panel>, <DTMLMethod at /standard_html_header>, <DTMLMethod at /standard_html_footer>, <DTMLMethod at /standard_error_message>, <Folder at /QuickStart>, <VirtualHostMonster at /risaRemap>, <Folder at /developers>, <ZSyncer at /broken>, <Image at /favicon.ico>, <DTMLMethod at /index_html>, <BrowserIdManager at /browser_id_manager>, <SessionDataManager at /session_data_manager>, <Folder at /Examples>, <SiteErrorLog at /error_log>, <ZopePageTemplate at /standard_template.pt>, <Connection at /devrep>, <PythonScript at /convertUsers>, <SQL at /sqlListUsers>, <PythonScript at /usListUsers>, <Folder at /tmp>, <PloneSite at /plone>, <PythonScript at /migrate_contents>, <PythonScript at /migrate_workgroups>, <ExternalMethod at /loggit>, <LocalFS at /logs>, <LocalFS at /oldlogs>, <PythonScript at /request>, <ExternalMethod at /html2cnxml>, <LocalFS at /rerunlogs>, <LocalFS at /stats>, <SimpleTemporaryContainer at /temp_folder>, <PluggableAuthService at /acl_users>, <File at /robots.txt>]

The url that had the error is /plone/Members/mcantrall, which can be accessed by doing app.plone.Members.mcantrall.

>>> app.plone.Members.mcantrall
<PloneFolder at /plone/Members/mcantrall>
>>> app.plone.Members.mcantrall.objectIds()
['col28320', 'Module.2019-11-01.2903', 'm79822', 'm79926', 'Module.2019-11-01.3346', 'Module.2019-11-01.3513', 'Module.2019-11-01.5839', 'Module.2019-11-01.0059', 'Module.2019-11-01.0304', 'Module.2019-11-01.0503', 'Module.2019-11-01.0645', 'Module.2019-11-01.0840', 'Module.2019-11-04.5029', 'Module.2019-11-04.5400', 'Module.2019-11-04.5609', 'Module.2019-11-04.5759', 'Module.2019-11-04.0035', 'Module.2019-11-04.0237', 'Module.2019-11-04.0350', 'Module.2019-11-04.4815']
>>> app.plone.Members.mcantrall.portal_type
'Workspace'

To reproduce the error when the user goes to their workspace, we follow the paths that the code took:

  1. getFolderContents:
karen@qa00:/var/lib/cnx/cnx-buildout$ find -name 'getFolderContents.*'
./parts/plone/CMFPlone/skins/plone_scripts/getFolderContents.py

contents = context.portal_catalog.queryCatalog(contentFilter, show_all=1,
  1. queryCatalog:
karen@qa00:/var/lib/cnx/cnx-buildout$ find -name 'queryCatalog.*'
./parts/plone/CMFPlone/skins/plone_scripts/queryCatalog.py
./eggs/Products.PloneHotfix20121106-1.2-py2.4.egg/Products/PloneHotfix20121106/queryCatalog.pyo
./eggs/Products.PloneHotfix20121106-1.2-py2.4.egg/Products/PloneHotfix20121106/queryCatalog.pyc
./eggs/Products.PloneHotfix20121106-1.2-py2.4.egg/Products/PloneHotfix20121106/queryCatalog.py

results = catalog(**query)

The query includes the location to search from, which is the current path /plone/Members/mcantrall. By default, the portal catalog only returns objects that can be viewed by the current user. Since we are not logged in in the python shell, we need to use unrestrictedSearchResults in order to see what the user is seeing:

>>> app.plone.portal_catalog.unrestrictedSearchResults({'path': {'query': '/plone/Members/mcantrall', 'depth': 1}})
[<Products.ZCatalog.Catalog.mybrains object at 0x7123a48>, <Products.ZCatalog.Catalog.mybrains object at 0x7123c58>, <Products.ZCatalog.Catalog.mybrains object at 0x7123cb0>, <Products.ZCatalog.Catalog.mybrains object at 0x750e050>, <Products.ZCatalog.Catalog.mybrains object at 0x750e8e8>, <Products.ZCatalog.Catalog.mybrains object at 0x753d310>, <Products.ZCatalog.Catalog.mybrains object at 0x753d998>, <Products.ZCatalog.Catalog.mybrains object at 0x7557310>, <Products.ZCatalog.Catalog.mybrains object at 0x7557998>, <Products.ZCatalog.Catalog.mybrains object at 0x7557b50>, <Products.ZCatalog.Catalog.mybrains object at 0x78cf0a8>, <Products.ZCatalog.Catalog.mybrains object at 0x78cf100>, <Products.ZCatalog.Catalog.mybrains object at 0x78cf158>, <Products.ZCatalog.Catalog.mybrains object at 0x78cf260>, <Products.ZCatalog.Catalog.mybrains object at 0x78cf2b8>, <Products.ZCatalog.Catalog.mybrains object at 0x78cf310>, <Products.ZCatalog.Catalog.mybrains object at 0x78cf680>, <Products.ZCatalog.Catalog.mybrains object at 0x78cf8e8>, <Products.ZCatalog.Catalog.mybrains object at 0x78cfa48>, <Products.ZCatalog.Catalog.mybrains object at 0x78cfec0>, <Products.ZCatalog.Catalog.mybrains object at 0x7a1e730>, <Products.ZCatalog.Catalog.mybrains object at 0x7a1ef18>]

The portal catalog returns these objects called brains, they contain some basic information about the objects like id and path, but doesn't contain everything. To get the object, we can call .getObject().

>>> items = app.plone.portal_catalog.unrestrictedSearchResults({'path': {'query': '/plone/Members/mcantrall', 'depth': 1}})
>>> [i.getObject() for i in items]
Traceback (most recent call last):
  File "<stdin>", line 1, in ?
  File "/var/lib/cnx/cnx-buildout/parts/zope2/lib/python/Products/ZCatalog/CatalogBrains.py", line 86, in getObject
    target = parent.restrictedTraverse(path[-1])
  File "/var/lib/cnx/cnx-buildout/parts/zope2/lib/python/OFS/Traversable.py", line 250, in restrictedTraverse
    return self.unrestrictedTraverse(path, default, restricted=1)
  File "/var/lib/cnx/cnx-buildout/parts/zope2/lib/python/OFS/Traversable.py", line 187, in unrestrictedTraverse
    next = bobo_traverse(REQUEST, name)
  File "/var/lib/cnx/cnx-buildout/eggs/Products.Five-1.4.5_rhaptosdev_r32037-py2.4.egg/Products/Five/traversable.py", line 126, in __bobo_traverse__
    return getattr(self, name)
AttributeError: 2019-11-04.0519911123

This is exactly the kind of error we are seeing in the traceback!

>>> brains = set([i.getId for i in items])
>>> objects = set(app.plone.Members.mcantrall.objectIds())
>>> brains.difference(objects)
set(['2019-11-04.8137449132', '2019-11-04.0519911123'])

There is a difference between the objects in the database and the brains returned by the portal catalog.

Probably some objects didn't create or delete cleanly, causing the objects to be indexed but do not actually exist in the database.

Next, try to unindex the object so the portal catalog doesn't return the object:

>>> app.plone.portal_catalog.unindexObject(app.plone.Members.mcantrall['2019-11-04.8137449132']
... )
Traceback (most recent call last):
  File "<stdin>", line 1, in ?
  File "/var/lib/cnx/cnx-buildout/eggs/Products.PloneHotfix20130618-1.1-py2.4.egg/Products/PloneHotfix20130618/get.py", line 38, in __getitem__
    raise KeyError, key
KeyError: '2019-11-04.8137449132'
>>> app.plone.portal_catalog.unindexObject.func_code
<code object unindexObject at 0x7f7d12eb49d0, file "/var/lib/cnx/cnx-buildout/parts/plone/CMFCore/CatalogTool.py", line 368>
>>> app.plone.portal_catalog.uncatalog_object('/plone/Members/mcantrall/2019-11-04.8137449132')
Traceback (most recent call last):
  File "<stdin>", line 1, in ?
  File "/var/lib/cnx/cnx-buildout/eggs/Products.CacheSetup-1.2.1-py2.4.egg/Products/CacheSetup/patch.py", line 109, in uncatalog_object
    return call(self, 'uncatalog_object', uid)
  File "/var/lib/cnx/cnx-buildout/eggs/Products.CacheSetup-1.2.1-py2.4.egg/Products/CacheSetup/patch_utils.py", line 6, in call
    return getattr(self, PATTERN % __name__)(*args, **kw)
  File "/var/lib/cnx/cnx-buildout/parts/zope2/lib/python/Products/ZCatalog/ZCatalog.py", line 599, in uncatalog_object
    self._catalog.uncatalogObject(uid)
  File "/var/lib/cnx/cnx-buildout/parts/zope2/lib/python/Products/ZCatalog/Catalog.py", line 389, in uncatalogObject
    x.unindex_object(rid)
  File "/var/lib/cnx/cnx-buildout/parts/zope2/lib/python/Products/PluginIndexes/DateRangeIndex/DateRangeIndex.py", line 192, in unindex_object
    self._removeForwardIndexEntry( since, until, documentId )
  File "/var/lib/cnx/cnx-buildout/parts/zope2/lib/python/Products/PluginIndexes/DateRangeIndex/DateRangeIndex.py", line 384, in _removeForwardIndexEntry
    set.remove( documentId )
KeyError: -1455954524

Unindexing the object returned a KeyError returned by a DateRangeIndex. Let's have a look at the indexes available:

>>> app.plone.portal_catalog.index_objects()
[<DateIndex at created>, <FieldIndex at orig_id>, <FieldIndex at Creator>, <DateIndex at modified>, <DateRangeIndex at effectiveRange>, <FieldIndex at sortable_title>, <KeywordIndex at allowedRolesAndUsers>, <FieldIndex at getObjPositionInParent>, <DateIndex at Date>, <ExtendedPathIndex at path>, <FieldIndex at review_state>, <FieldIndex at portal_type>]

The only DateRangeIndex is effectiveRange so that's where the problem is.

Solution

I've written a script to fix this problem: https://github.com/openstax/devops/blob/master/scripts/legacy/fix_legacy_user_workspace.py

Usage: fix_legacy_user_workspace.py [username] ...
Usage: fix_legacy_user_workspace.py --test | --help | --fix-all

Attempts to fix the AttributeError raised when a user goes to their workspace.

Options:
  --fix-all    fix all broken workspaces
  --commit     commit transaction (save all changes)
  --test       run unit tests
  -h, --help   display help message and exit

I tested this on staging and it appears to work for user davidnvn (because mcantrall's workspace wasn't broken). On production, I expect the script to be run like this:

./fix_legacy_user_workspace.py mcantrall

  1. Download the script:

    wget -O fix_legacy_user_workspace.py 'https://raw.githubusercontent.com/openstax/devops/master/scripts/legacy/fix_legacy_user_workspace.py?token=AABFOCPNDDG4X77UDQ2AEVK54TORK'
chmod +x fix_legacy_user_workspace.py

  2. Run the script:

    ./fix_legacy_user_workspace.py --commit mcantrall
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment