zombie connections are lurking in some places -- 8

[paregorios]

Place view for Tiberis (river) works for logged-in admin user, but unauthenticated users see an error message.

[paregorios]

Here's the traceback:

2018-02-20T09:05:33 ERROR Zope.SiteErrorLog 1519135533.160.548246354376 https://pleiades.stoa.org/places/423080/base_view
Traceback (innermost last):
  Module ZPublisher.Publish, line 138, in publish
  Module ZPublisher.mapply, line 77, in mapply
  Module ZPublisher.Publish, line 48, in call_object
  Module Shared.DC.Scripts.Bindings, line 322, in __call__
  Module Shared.DC.Scripts.Bindings, line 359, in _bindAndExec
  Module Products.CMFCore.FSPageTemplate, line 237, in _exec
  Module Products.CMFCore.FSPageTemplate, line 177, in pt_render
  Module Products.PageTemplates.PageTemplate, line 87, in pt_render
  Module zope.pagetemplate.pagetemplate, line 132, in pt_render
   - Warning: Macro expansion failed
   - Warning: <type 'exceptions.KeyError'>: 'macro'
  Module zope.pagetemplate.pagetemplate, line 240, in __call__
  Module collective.newrelic.patches.talinterpreter, line 17, in monkeypatch
  Module newrelic.api.function_trace, line 110, in literal_wrapper
  Module zope.tal.talinterpreter, line 271, in __call__
  Module zope.tal.talinterpreter, line 343, in interpret
  Module zope.tal.talinterpreter, line 888, in do_useMacro
  Module zope.tal.talinterpreter, line 343, in interpret
  Module zope.tal.talinterpreter, line 533, in do_optTag_tal
  Module zope.tal.talinterpreter, line 518, in do_optTag
  Module zope.tal.talinterpreter, line 513, in no_tag
  Module zope.tal.talinterpreter, line 343, in interpret
  Module zope.tal.talinterpreter, line 954, in do_defineSlot
  Module zope.tal.talinterpreter, line 343, in interpret
  Module zope.tal.talinterpreter, line 533, in do_optTag_tal
  Module zope.tal.talinterpreter, line 518, in do_optTag
  Module zope.tal.talinterpreter, line 513, in no_tag
  Module zope.tal.talinterpreter, line 343, in interpret
  Module zope.tal.talinterpreter, line 858, in do_defineMacro
  Module zope.tal.talinterpreter, line 343, in interpret
  Module zope.tal.talinterpreter, line 954, in do_defineSlot
  Module zope.tal.talinterpreter, line 343, in interpret
  Module zope.tal.talinterpreter, line 533, in do_optTag_tal
  Module zope.tal.talinterpreter, line 518, in do_optTag
  Module zope.tal.talinterpreter, line 513, in no_tag
  Module zope.tal.talinterpreter, line 343, in interpret
  Module zope.tal.talinterpreter, line 954, in do_defineSlot
  Module zope.tal.talinterpreter, line 343, in interpret
  Module zope.tal.talinterpreter, line 533, in do_optTag_tal
  Module zope.tal.talinterpreter, line 518, in do_optTag
  Module zope.tal.talinterpreter, line 513, in no_tag
  Module zope.tal.talinterpreter, line 343, in interpret
  Module zope.tal.talinterpreter, line 946, in do_defineSlot
  Module zope.tal.talinterpreter, line 343, in interpret
  Module zope.tal.talinterpreter, line 533, in do_optTag_tal
  Module zope.tal.talinterpreter, line 518, in do_optTag
  Module zope.tal.talinterpreter, line 513, in no_tag
  Module zope.tal.talinterpreter, line 343, in interpret
  Module zope.tal.talinterpreter, line 858, in do_defineMacro
  Module zope.tal.talinterpreter, line 343, in interpret
  Module zope.tal.talinterpreter, line 533, in do_optTag_tal
  Module zope.tal.talinterpreter, line 518, in do_optTag
  Module zope.tal.talinterpreter, line 513, in no_tag
  Module zope.tal.talinterpreter, line 343, in interpret
  Module zope.tal.talinterpreter, line 888, in do_useMacro
  Module zope.tal.talinterpreter, line 343, in interpret
  Module zope.tal.talinterpreter, line 533, in do_optTag_tal
  Module zope.tal.talinterpreter, line 518, in do_optTag
  Module zope.tal.talinterpreter, line 513, in no_tag
  Module zope.tal.talinterpreter, line 343, in interpret
  Module zope.tal.talinterpreter, line 852, in do_condition
  Module zope.tal.talinterpreter, line 343, in interpret
  Module zope.tal.talinterpreter, line 531, in do_optTag_tal
  Module zope.tal.talinterpreter, line 513, in no_tag
  Module zope.tal.talinterpreter, line 343, in interpret
  Module zope.tal.talinterpreter, line 742, in do_insertStructure_tal
  Module Products.PageTemplates.Expressions, line 218, in evaluateStructure
  Module zope.tales.tales, line 696, in evaluate
   - URL: file:/srv/python27-apps/pleiades4/src/Products.PleiadesEntity/Products/PleiadesEntity/skins/PleiadesEntity/place_view.pt
   - Line 185, Column 12
   - Expression: <PathExpr standard:u'context/@@connections-listing|nothing'>
   - Names:
      {'container': <Place at /plone/places/423080>,
       'context': <Place at /plone/places/423080>,
       'default': <object object at 0x7f33bc987bc0>,
       'here': <Place at /plone/places/423080>,
       'loop': {},
       'nothing': None,
       'options': {'args': ()},
       'repeat': <Products.PageTemplates.Expressions.SafeMapping object at 0x7f333ee7f310>,
       'request': <HTTPRequest, URL=https://pleiades.stoa.org/places/423080/base_view>,
       'root': <Application at >,
       'template': <FSPageTemplate at /plone/places/423080/base_view>,
       'traverse_subpath': [],
       'user': <SpecialUser 'Anonymous User'>}
  Module zope.tales.expressions, line 217, in __call__
  Module Products.PageTemplates.Expressions, line 155, in _eval
  Module Products.PageTemplates.Expressions, line 117, in render
  Module Products.PleiadesEntity.browser.attestations, line 127, in __call__
  Module Products.PleiadesEntity.browser.attestations, line 467, in rows
  Module Products.CMFCore.WorkflowTool, line 263, in getInfoFor
WorkflowException: No workflow provides '${name}' information.

[paregorios]

In work in https://github.com/isawnyu/PleiadesEntity/tree/issue337

[paregorios]

This is somehow related to #336. The error here is occurring when trying to deal with certain "zombie" connections, which seem to be derelict working copies(?).

[paregorios]

Said zombie copies show up in the ZMI:

and in the place view:

but not in the folder listing:

nor in the ZMI portal_catalog, even after reindexing

They are returned by all the apparatus associated with processing the view template, going back to the getSubConnections() method on the Named schema mixin, which is used by the Place content object in PleiadesEntity.

The zombie copies (with ids like "copy_of_salinae") are missing workflow aspects,

[paregorios]

Near term: we should be able to ignore these objects in constructing the list of connections for viewing; however, we need to find out how/where they are getting created and fix that. I will pursue the near-term cosmetic fix sub #336 and leave this ticket open for finding and fixing the underlying problem.

[paregorios]

Still seeing these. I'm at a loss as to see where they are coming from.

[paregorios]

once this ticket is resolved we need to review and reassess the blocked ticket #336

[MatthewWilkes]

There are a large number of content items affected throughout the site, with modification dates between 2012 and 2019. This does not appear to be a one-off error.

I'm defining this error as there being a child of a place that contains 'copyof' in its id within the folder, but has a mismatching id field on the object itself. The object does not reference the same ZODB level object as the one it's a copy of.

On places with multiple copy_of_ children, they always have modification dates within a few milliseconds of eachother. They are not catalogued.

The difference between objects of one such item is:

-  '__ac_local_roles__': {'sgillies': ['Owner']},
?                           ^^^^^^

+  '__ac_local_roles__': {'scosta': ['Owner']},
?                           ^^ ++

-  '_at_uid': '97fb36eaaf53724626851f2ff48d598a',
+  '_at_uid': '8377e3563749ed51b9dc64047bcc34cc',

'_owner': (['plone',
            'acl_users'],
-             'jbecker'),
+             'sgillies'),

-  'modification_date': DateTime('2017/08/05 18:32:13.882425 GMT-4'),
?                                                     ^^ ---

+  'modification_date': DateTime('2017/08/05 18:32:13.633092 GMT-4'),
?                                                     ^^^^^

-  'referenceCitations|referenceCitations:000|access_uri': u'http://darmc.harvard.edu',
+  'referenceCitations|referenceCitations:000|access_uri': u'https://darmc.harvard.edu/',
?                                                                +                    +

'referenceCitations|referenceCitations:000|alternate_uri': u'',
-  'referenceCitations|referenceCitations:000|bibliographic_uri': u'',
+  'referenceCitations|referenceCitations:000|bibliographic_uri': u'https://www.zotero.org/groups/2533/pleiades/items/itemKey/9UD9W75C',

-  'referenceCitations|referenceCitations:000|citation_detail': u'',
+  'referenceCitations|referenceCitations:000|citation_detail': u'972',
?                                                                 +++

-  'referenceCitations|referenceCitations:000|formatted_citation': u'Michael McCormick, Guoping Huang, Kelly Gibson et al. (ed.), Digital Atlas of Roman and Medieval Civilizations, Harvard University Center for Geographic Analysis',
+  'referenceCitations|referenceCitations:000|formatted_citation': u'Michael McCormick, Giovanni Zambotti, Leland Grigoli, and Kelly Gibson, eds., The Digital Atlas of Roman and Medieval Civilizations (Cambridge (Massachusetts): Harvard University, 2007-), 972.',

-  'referenceCitations|referenceCitations:000|short_title': u'',
+  'referenceCitations|referenceCitations:000|short_title': u'DARMC',
?                                                             +++++

-  'referenceCitations|referenceCitations:000|type': u'cites',
+  'referenceCitations|referenceCitations:000|type': u'citesAsDataSource',
?                                                           ++++++++++++

-  'version_id': 1,
?                ^

+  'version_id': 0,
?                ^

-  'workflow_history': {'pleiades_entity_workflow': ({'action': None, 'review_state': 'drafting', 'comments': '', 'actor': 'sgillies', 'time': DateTime('2011/03/09 13:38:2.508000 US/Eastern')}, {'action': 'submit', 'review_state': 'pending', 'comments': '', 'actor': 'sgillies', 'time': DateTime('2011/03/09 13:38:3.286000 US/Eastern')}, {'action': 'publish', 'review_state': 'published', 'actor': 'thomase', 'comments': '', 'time': DateTime('2011/03/09 23:54:20.239000 US/Eastern')})}}
+  'workflow_history': {'pleiades_entity_workflow': ({'action': None, 'review_state': 'drafting', 'comments': '', 'actor': 'sgillies', 'time': DateTime('2011/03/09 13:38:2.508000 US/Eastern')}, {'action': 'submit', 'review_state': 'pending', 'comments': '', 'actor': 'sgillies', 'time': DateTime('2011/03/09 13:38:3.286000 US/Eastern')}, {'action': 'publish', 'review_state': 'published', 'actor': 'thomase', 'comments': '', 'time': DateTime('2011/03/09 23:54:20.239000 US/Eastern')}, {'action': None, 'review_state': 'drafting', 'actor': 'scosta', 'comments': '', 'time': DateTime('2011/12/17 02:17:39.405000 US/Eastern')}, {'action': 'submit', 'review_state': 'pending', 'actor': 'scosta', 'comments': '', 'time': DateTime('2011/12/17 02:17:40.521000 US/Eastern')}, {'action': 'publish', 'review_state': 'published', 'actor': 'scosta', 'comments': '', 'time': DateTime('2011/12/17 02:17:40.599000 US/Eastern')})}}

where the from state is the copy and the to state is the canonical one. The version_id parameter is higher in the copy than the canonical one, but the modified dates are only 200ms apart and have different owners.

There are differences in the workflow_history, but they're all many years away from the modification date. This leads me to believe the modification date is not trustworthy and could be an artifact of changes to the parent.

In some examples the copy has a higher version_id, in others the canonical item has a higher version_id. Sometimes the version_id is the same. In all cases, it seems the last workflow transition is always newer in the canonical version.

For example:

432336962/copy_of_janiculum 2018/08/01 09:28:56.813536 GMT-4 [0] -> 2018/07/30 14:08:11.824258 GMT-4 [3] 

and

501359/copy_of_arisbe 2014/01/20 17:59:7.842000 US/Eastern [1] -> 2010/06/24 09:29:41.263000 GMT-4 [0] 

I wonder if this is a symptom of multiple conflicting iterate operations at the same time?

[alecpm]

Could this be related to the fact that a number of content types do a full commit in the middle of their custom _renameAfterCreation methods, instead of a savepoint? If some later part of the transaction failed, the user would get an error but the artifact would remain from the point just before the auto-rename.

[MatthewWilkes]

I've developed a script to iterate over the places and fix any of the broken connections, which I've been able to run on my local instance with positive results. I think running this on staging and testing it before applying to live is a good way of proceeding to clear the existing errors, considering the zombie connections aren't indexed anyway.

[MatthewWilkes]

That's a very interesting suggestion, @alecpm! Yes, that sounds quite possible. I don't think they should be using a full commit, maybe we should also switch those over to savepoints and see if that fixes the issue? I could also add a manual error throw in there to emulate this, but I'm still not sure what user interactions would cause the rename after creation to trigger.

[MatthewWilkes]

@paregorios I've deployed the change @alecpm suggested to staging and run the fixup script. https://pleiades.jazkarta.com/places/462204 appears to be displaying correctly, but I do think we need to consider the different places that the autorename happens to make sure we've not broken any of them. All I've tested there so far is creating a new association, as some of the comments around the commits said it was there to placate the portal_factory.

[alecpm]

In general, if you try to change the id an object after creating it you'll get an error unless a savepoint (formerly sub-transaction commit) is created. The rename method will be called on new object creation via the AT add form, and also explicitly here when "promoting" a Location to a Place using the "Promote to Place" action menu on a Location.

[paregorios]

So, what's the current thinking on this one? Wait until the next iteration to complete?

[MatthewWilkes]

@paregorios That's a very good question. I've deployed the script to fix the issue to the development server but ran out of time before being able to run it. I think for this that code review is probably the most effective way of reviewing. I'm also a bit concerned that #392 interacts with this in some way, but I didn't grok exactly what was found there well enough to say for sure. I'd personally value @alecpm's opinion.

[skleinfeldt]

Next step is to test by running on staging.

[MatthewWilkes]

Okay, I've run this on staging:

If you compare https://pleiades.stoa.org/places/462204 and https://pleiades.jazkarta.com/places/462204

you'll see the error is no longer present on the staging server.

[paregorios]

Looks good. Let's deploy to production and run. Maybe stash a copy of the production database somewhere before we do?

[skleinfeldt]

Maybe stash a copy of the production database somewhere before we do?

Good idea!!

[MatthewWilkes]

These are the entities that were fixed

Originjal id	Duplicate id	Original last modified	Original version id	Copy last modified	Copy version id
darmc-location-2381	copy_of_darmc-location-2381	2011/12/09 16:43:22.261000 US/Eastern	0	2011/03/09 23:55:58.927000 US/Eastern	2
246730	copy_of_246730	2016/07/13 09:32:6.144068 GMT-4	7	2016/07/13 10:02:40.592618 GMT-4	7
502042016	copy_of_502042016	2016/07/13 09:37:50.145519 GMT-4	6	2016/07/13 09:33:24.592894 GMT-4	6
507729266	copy_of_507729266	2016/07/13 09:37:50.278108 GMT-4	6	2016/07/13 09:33:24.711562 GMT-4	6
falesia	copy_of_falesia	2011/12/17 02:17:40.446000 US/Eastern	0	2010/11/15 14:06:14.666000 US/Eastern	0
batlas-location	copy_of_batlas-location	2017/08/05 18:32:31.472758 GMT-4	0	2011/03/09 13:38:2.056000 US/Eastern	0
darmc-location-972	copy_of_darmc-location-972	2011/12/17 02:17:40.599000 US/Eastern	0	2011/03/09 23:54:20.239000 US/Eastern	1
darmc-location-7041	copy_of_darmc-location-7041	2017/09/29 13:47:55.549028 GMT-4	0	2011/03/09 23:54:20.976000 US/Eastern	1
413122	copy_of_413122	2016/07/13 09:53:5.923125 GMT-4	0	2016/07/13 10:00:56.345497 GMT-4	19
356966898	copy_of_356966898	2016/07/13 09:53:6.189949 GMT-4	9	2016/07/13 10:01:52.922032 GMT-4	9
423025	copy_of_423025	2016/07/13 09:53:6.356469 GMT-4	9	2016/07/13 10:01:53.047795 GMT-4	9
janiculum	copy_of_janiculum	2018/08/01 09:28:56.813536 GMT-4	0	2018/07/30 14:08:11.824258 GMT-4	3
462492	copy_of_462492	2016/07/13 09:37:55.919646 GMT-4	13	2016/07/13 09:47:43.110946 GMT-4	13
462492	copy_of_462492	2016/07/13 09:53:36.012434 GMT-4	8	2016/07/13 09:47:51.729657 GMT-4	8
462492	copy_of_462492	2016/07/13 09:47:11.914405 GMT-4	10	2016/07/13 09:51:8.842964 GMT-4	10
462503	copy_of_462503	2016/07/13 09:47:11.670391 GMT-4	10	2016/07/13 09:51:8.971888 GMT-4	10
462492	copy_of_462492	2016/07/13 09:47:15.306237 GMT-4	8	2016/07/13 09:45:47.662386 GMT-4	8
462492	copy_of_462492	2016/07/13 09:47:8.535728 GMT-4	14	2016/07/13 09:45:55.531178 GMT-4	14
462193	copy_of_462193	2016/07/13 09:47:8.905930 GMT-4	14	2016/07/13 09:45:55.675254 GMT-4	14
462492	copy_of_462492	2016/07/13 09:46:40.821393 GMT-4	10	2016/07/13 09:45:55.941375 GMT-4	10
462492	copy_of_462492	2016/07/13 09:50:58.435036 GMT-4	19	2016/07/13 09:46:10.373800 GMT-4	19
991353	copy_of_991353	2016/07/13 09:50:58.870123 GMT-4	19	2016/07/13 09:46:10.601721 GMT-4	19
981549	copy_of_981549	2016/07/13 09:50:59.237637 GMT-4	19	2016/07/13 09:46:10.735419 GMT-4	19
462492	copy_of_462492	2016/07/13 09:46:41.194866 GMT-4	8	2016/07/13 09:46:11.691327 GMT-4	8
462492	copy_of_462492	2016/07/13 09:59:16.291315 GMT-4	10	2016/07/13 09:46:14.326268 GMT-4	10
arisbe	copy_of_arisbe	2014/01/20 17:59:7.842000 US/Eastern	1	2010/06/24 09:29:41.263000 GMT-4	0
aeolis	copy_of_aeolis	2017/06/01 10:49:24.609549 GMT-4	1	2009/10/15 13:52:2.797000 GMT-4	0
735295266	copy_of_735295266	2016/07/13 10:04:27.324500 GMT-4	10	2016/07/13 09:41:35.679673 GMT-4	10
isthmia	copy_of_isthmia	2017/06/05 09:49:49.807209 GMT-4	0	2010/09/22 14:38:2.514000 GMT-4	0
isthmos	copy_of_isthmos	2017/06/05 09:49:33.288257 GMT-4	0	2010/09/22 14:38:2.546000 GMT-4	1
batlas-location	copy_of_batlas-location	2017/06/05 09:47:43.042962 GMT-4	0	2011/01/25 13:31:17.307000 US/Eastern	0
darmc-location-24254	copy_of_darmc-location-24254	2017/06/05 09:47:59.418170 GMT-4	0	2011/01/25 14:01:0.376000 US/Eastern	1
570577	copy_of_570577	2016/07/13 09:56:18.804622 GMT-4	9	2016/07/13 09:50:30.833299 GMT-4	9
athenae	copy_of_athenae	2018/10/15 20:06:0.916166 GMT-4	1	2016/08/21 00:11:44.441109 GMT-4	2
442241741	copy_of_442241741	2016/07/13 09:52:46.173462 GMT-4	0	2016/07/13 09:41:3.075997 GMT-4	7
991381	copy_of_991381	2016/07/13 10:04:24.658116 GMT-4	25	2016/07/13 09:35:48.114638 GMT-4	25
658560	copy_of_658560	2016/07/13 09:53:31.794146 GMT-4	13	2016/07/13 09:46:58.730635 GMT-4	13
661388	copy_of_661388	2016/07/13 09:53:31.935827 GMT-4	13	2016/07/13 09:46:58.890904 GMT-4	13
karkemish	copy_of_karkemish	2017/06/06 21:43:59.267547 GMT-4	11	2012/10/12 11:03:59.194000 GMT-4	0
727172	copy_of_727172	2016/07/13 09:32:54.846667 GMT-4	8	2016/07/13 09:39:2.645778 GMT-4	8
pelousion	copy_of_pelousion	2019/03/14 11:15:18.031116 GMT-4	1	2013/08/22 11:14:23.102000 GMT-4	3
nineveh	copy_of_nineveh	2018/02/02 06:18:6.120160 US/Eastern	1	2010/10/05 14:28:23.163000 GMT-4	2
victoria	copy_of_victoria	2012/02/17 22:45:44.282000 US/Eastern	5	2009/11/23 17:42:46.266000 US/Eastern	0
undetermined	copy_of_undetermined	2012/02/17 22:45:43.880000 US/Eastern	5	2011/01/21 00:45:21.712000 US/Eastern	0
darmc-location-19220	copy_of_darmc-location-19220	2012/02/17 22:45:44.423000 US/Eastern	5	2011/01/21 08:41:53.536000 US/Eastern	1

[paregorios]

It turns out this is not resolved after all: https://github.com/isawnyu/pleiades-gazetteer/issues/336#issuecomment-536301972

[paregorios]

Still a problem. See #428