Cut and Paste in same folder

krissik commented 6 years ago

What I did:

On folder_contents I select an item and click "Cut" button
I click "Paste" button on same folder

What I expect to happen:

Selected item is still in folder.

What actually happened:

The selected item disappears after clicking "Paste" and "Successfully pasted items" message is shown. I can still paste the item to another folder so it is not lost but this is very confusing for users.

What version of Plone/ Addons I am using:

Version 5.1.2 (I could reproduce it on demo.plone.org)

sunew commented 6 years ago

Could be related to https://github.com/plone/mockup/issues/857 Possibly fixed in 5.1.4-pending - @krissik would it possuble for you to test that case on 5.1.4-pending?

krissik commented 6 years ago

Possibly fixed in 5.1.4-pending - @krissik would it possuble for you to test that case on 5.1.4-pending?

The problem still exists in 5.1.4-pending.

cdw9 commented 5 years ago

I have seen this happen in Plone 5.1.2 and 5.1.4. It only happens with empty folders. Steps to reproduce:

Create four folders at the same level
Add content into two of the folders
From folder_contents, select the four folders
Cut
Paste

Only the two folders with content are saved, the two empty folders disappear. As @krissik mentioned, all folders do show up if pasted into a new location.

davisagli commented 5 years ago

@cdw9 are the folders actually gone, or did they just get removed from the catalog? (Check if they show up in the ZMI.)

cdw9 commented 5 years ago

They are showing up in the ZMI

cekk commented 4 years ago

Updates on this thread: i have the same problem on a 5.1.5 and only in production. Locally and in staging environment i can cut/paste in the same folder without problems.

The same installation on a production machine generates this same problem: the item disappears from catalog but it's still visible in ZMI.

The problem could be in how notified events are intercepted (and in which order)? The focus point could be here.

I noticed that if i wake up the catalog (a simple search for example) before notifying these two events, the item is correctly indexed. Otherwise not.

vincentfretin commented 4 years ago

Still an issue in Plone 5.2.2 I reproduce the issue locally. I cut an image, then paste in the same folder, the image disappear, but I can see it in ZMI. I paste again, I have this message in the console [Zope.ZCatalog:407][waitress-0] uncatalogObject unsuccessfully attempted to uncatalog an object with a uid of /Plone/dossier/myimage.jpg. So yeah it seems to unindex the item, commit, then try to paste the item and fails silently? Then if I paste it in a different folder, the item now has really moved and is reindexed.

The view @@fc-paste is taking care of that, see src/plone.app.content/plone/app/content/browser/contents/paste.py it seems to just do self.dest.manage_pasteObjects(self.request['__cp']) and this goes to CopySupport.py like @cekk said.

vincentfretin commented 4 years ago

I put a pdb in _pasteObjects https://github.com/zopefoundation/Zope/blob/master/src/OFS/CopySupport.py#L166

I'm looking to where it's unindexed when I have the error uncatalogObject unsuccessfully attempted to uncatalog an object with a uid of /Plone/dossier/myimage.jpg.

If I put a import pdb; pdb.set_trace() line 405 in Products.ZCatalog-5.0.4-py2.7.egg/Products/ZCatalog/Catalog.py where there is the unsuccessfully attempted message.

The unindex seems to be in the ObjectMovedEvent event:

[15] > /home/vincentfretin/.buildout/eggs/Zope-4.4.4-py2.7.egg/OFS/CopySupport.py(194)_pasteObjects()
-> if cp is None:
(Pdb++) c
[33] > /home/vincentfretin/.buildout/eggs/Products.ZCatalog-5.0.4-py2.7.egg/Products/ZCatalog/Catalog.py(406)uncatalogObject()
-> LOG.error('uncatalogObject unsuccessfully '
(Pdb++) l
401                 del uids[uid]
402                 self._length.change(-1)
403     
404             else:
405                 import pdb; pdb.set_trace()
406  ->             LOG.error('uncatalogObject unsuccessfully '
407                           'attempted to uncatalog an object '
408                           'with a uid of %s. ', str(uid))
409     
410         def uniqueValuesFor(self, name):
411             """ return unique values for FieldIndex name """
(Pdb++) u
[32] > /home/vincentfretin/.buildout/eggs/Products.ZCatalog-5.0.4-py2.7.egg/Products/ZCatalog/ZCatalog.py(513)uncatalog_object()
-> self._catalog.uncatalogObject(uid)
(Pdb++) u
[31] > /home/vincentfretin/workspace/buildout.coredev-5.2/src/Products.CMFPlone/Products/CMFPlone/CatalogTool.py(362)uncatalog_object()
-> return BaseTool.uncatalog_object(self, *args, **kwargs)
(Pdb++) u
[30] > /home/vincentfretin/.buildout/eggs/Products.CMFCore-2.4.7-py2.7.egg/Products/CMFCore/CatalogTool.py(347)_unindexObject()
-> self.uncatalog_object(url)
(Pdb++) u
[29] > /home/vincentfretin/.buildout/eggs/Products.CMFCore-2.4.7-py2.7.egg/Products/CMFCore/indexing.py(56)unindex()
-> catalog._unindexObject(obj)
(Pdb++) u
[28] > /home/vincentfretin/.buildout/eggs/Products.CMFCore-2.4.7-py2.7.egg/Products/CMFCore/indexing.py(225)process()
-> util.unindex(obj)
(Pdb++) u
[27] > /home/vincentfretin/.buildout/eggs/Products.CMFCore-2.4.7-py2.7.egg/Products/CMFCore/indexing.py(96)processQueue()
-> processed = queue.process()
(Pdb++) u
[26] > /home/vincentfretin/workspace/buildout.coredev-5.2/src/Products.CMFPlone/Products/CMFPlone/CatalogTool.py(435)searchResults()
-> processQueue()
(Pdb++) u
[25] > /home/vincentfretin/workspace/buildout.coredev-5.2/src/plone.app.discussion/plone/app/discussion/comment.py(297)notify_content_object_moved()
-> portal_type='Discussion Item',
(Pdb++) u
[24] > /home/vincentfretin/.buildout/eggs/zope.interface-5.0.2-py2.7-linux-x86_64.egg/zope/interface/adapter.py(619)subscribers()
-> subscription(*objects)
(Pdb++) u
[23] > /home/vincentfretin/.buildout/eggs/zope.interface-5.0.2-py2.7-linux-x86_64.egg/zope/interface/registry.py(448)subscribers()
-> return self.adapters.subscribers(objects, provided)
(Pdb++) u
[22] > /home/vincentfretin/.buildout/eggs/zope.component-4.6.1-py2.7.egg/zope/component/_api.py(124)subscribers()
-> return sitemanager.subscribers(objects, interface)
(Pdb++) u
[21] > /home/vincentfretin/.buildout/eggs/zope.component-4.6.1-py2.7.egg/zope/component/event.py(36)objectEventNotify()
-> component_subscribers((event.object, event), None)
(Pdb++) u
[20] > /home/vincentfretin/.buildout/eggs/zope.interface-5.0.2-py2.7-linux-x86_64.egg/zope/interface/adapter.py(619)subscribers()
-> subscription(*objects)
(Pdb++) u
[19] > /home/vincentfretin/.buildout/eggs/zope.interface-5.0.2-py2.7-linux-x86_64.egg/zope/interface/registry.py(448)subscribers()
-> return self.adapters.subscribers(objects, provided)
(Pdb++) u
[18] > /home/vincentfretin/.buildout/eggs/zope.component-4.6.1-py2.7.egg/zope/component/_api.py(124)subscribers()
-> return sitemanager.subscribers(objects, interface)
(Pdb++) u
[17] > /home/vincentfretin/.buildout/eggs/zope.component-4.6.1-py2.7.egg/zope/component/event.py(27)dispatch()
-> component_subscribers(event, None)
(Pdb++) u
[16] > /home/vincentfretin/.buildout/eggs/zope.event-4.4-py2.7.egg/zope/event/__init__.py(32)notify()
-> subscriber(event)
(Pdb++) u
[15] > /home/vincentfretin/.buildout/eggs/Zope-4.4.4-py2.7.egg/OFS/CopySupport.py(194)_pasteObjects()
-> if cp is None:
(Pdb++) n
2020-07-03 13:43:25,854 ERROR   [Zope.ZCatalog:408][waitress-1] uncatalogObject unsuccessfully attempted to uncatalog an object with a uid of /Plone/dossier/dossier-2/myimage.jpg. 
[15] > /home/vincentfretin/.buildout/eggs/Zope-4.4.4-py2.7.egg/OFS/CopySupport.py(300)_pasteObjects()
-> notifyContainerModified(orig_container)
(Pdb++) l
200                 six.raise_from(CopyError('Clipboard Error'), e)
201     
202             oblist = []
203             app = self.getPhysicalRoot()
204             for mdata in mdatas:
205                 m = loadMoniker(mdata)
206                 try:
207                     ob = m.bind(app)
208                 except ConflictError:
209                     raise
210                 except Exception:
(Pdb++) u
[14] > /home/vincentfretin/.buildout/eggs/Zope-4.4.4-py2.7.egg/OFS/CopySupport.py(327)manage_pasteObjects()
-> op, result = self._pasteObjects(cb_copy_data, cb_maxsize=8192)
(Pdb++) d
[15] > /home/vincentfretin/.buildout/eggs/Zope-4.4.4-py2.7.egg/OFS/CopySupport.py(300)_pasteObjects()
-> notifyContainerModified(orig_container)
(Pdb++) l
295                             "%s._setObject without suppress_events is discouraged."
296                             % self.__class__.__name__, DeprecationWarning)
297                     ob = self._getOb(id)
298     
299                     notify(ObjectMovedEvent(ob, orig_container, orig_id, self, id))
300  ->                 notifyContainerModified(orig_container)
301                     if aq_base(orig_container) is not aq_base(self):
302                         notifyContainerModified(self)
303     
304                     ob._postCopy(self, op=1)
305                     # try to make ownership implicit if possible
(Pdb++)

vincentfretin commented 4 years ago

But I actually never have an exception in this pasteObjects code... so it's hard to find the root cause of the issue, why it's not reindexed afterwards.

I confirm the item is unindex, the container is reindexed, but the item is never reindexed.

Serving on http://0.0.0.0:8080
[15] > /home/vincentfretin/.buildout/eggs/Zope-4.4.4-py2.7.egg/OFS/CopySupport.py(194)_pasteObjects()
-> if cp is None:
(Pdb++) c
[29] > /home/vincentfretin/.buildout/eggs/Products.CMFCore-2.4.7-py2.7.egg/Products/CMFCore/indexing.py(57)unindex()
-> catalog = getToolByName(obj, 'portal_catalog', None)
(Pdb++) l
 52                     idxs=attributes,
 53                     update_metadata=update_metadata)
 54     
 55         def unindex(self, obj):
 56             import pdb; pdb.set_trace()
 57  ->         catalog = getToolByName(obj, 'portal_catalog', None)
 58             if catalog is not None:
 59                 catalog._unindexObject(obj)
 60     
 61         def begin(self):
 62             pass
(Pdb++) obj
<Image at /Plone/dossier/myimage.jpg>
(Pdb++) c
[19] > /home/vincentfretin/.buildout/eggs/Products.CMFCore-2.4.7-py2.7.egg/Products/CMFCore/indexing.py(48)reindex()
-> catalog = getToolByName(obj, 'portal_catalog', None)
(Pdb++) obj
<Folder at /Plone/dossier>

vincentfretin commented 4 years ago

When it works, it should do the following sequence:

[29] > /home/vincentfretin/.buildout/eggs/Products.CMFCore-2.4.7-py2.7.egg/Products/CMFCore/indexing.py(57)unindex()
-> catalog = getToolByName(obj, 'portal_catalog', None)
(Pdb++) obj
<Image at /Plone/dossier/myimage.jpg>
(Pdb++) c
[29] > /home/vincentfretin/.buildout/eggs/Products.CMFCore-2.4.7-py2.7.egg/Products/CMFCore/indexing.py(48)reindex()
-> catalog = getToolByName(obj, 'portal_catalog', None)
(Pdb++) obj
<Image at /Plone/dossier2/myimage.jpg>
(Pdb++) c
[19] > /home/vincentfretin/.buildout/eggs/Products.CMFCore-2.4.7-py2.7.egg/Products/CMFCore/indexing.py(48)reindex()
-> catalog = getToolByName(obj, 'portal_catalog', None)
(Pdb++) obj
<Folder at /Plone/dossier>
(Pdb++) c
[19] > /home/vincentfretin/.buildout/eggs/Products.CMFCore-2.4.7-py2.7.egg/Products/CMFCore/indexing.py(48)reindex()
-> catalog = getToolByName(obj, 'portal_catalog', None)
(Pdb++) obj
<Folder at /Plone/dossier2>

vincentfretin commented 4 years ago

The bug is in IndexQueue.optimize Products.CMFCore-2.4.7-py2.7.egg/Products/CMFCore/indexing.py An UNINDEX (-1) followed by REINDEX (0) will optimize as a unindex only apparently.

Cut myimage.jpg from dossier to dossier2

<zope.lifecycleevent.ObjectCopiedEvent object at 0x7fa2d1daa590> <Image at myimage.jpg>
<OFS.event.ObjectWillBeAddedEvent object at 0x7fa2d1d37450> <Image at myimage.jpg>
<zope.lifecycleevent.ObjectAddedEvent object at 0x7fa2d1d37450> <Image at myimage.jpg>
QUEUE REINDEX <Image at myimage.jpg>
PROCESS QUEUE
QUEUE OPTIMIZE, BEFORE [(0, <Image at /Plone/dossier/dossier-2/myimage.jpg>, [], 1)]
QUEUE OPTIMIZE, AFTER [(0, <Image at /Plone/dossier/dossier-2/myimage.jpg>, [], 1)]
really reindex <Image at myimage.jpg>
QUEUE REINDEX <Image at myimage.jpg>
QUEUE REINDEX <Image at myimage.jpg>
<zope.container.contained.ContainerModifiedEvent object at 0x7fa2dd1bf0d0> <Folder at dossier-2>
QUEUE REINDEX <Folder at dossier-2>
<OFS.event.ObjectClonedEvent object at 0x7fa2dd1bf0d0> <Image at myimage.jpg>
PROCESS QUEUE
QUEUE OPTIMIZE, BEFORE [(0, <Image at /Plone/dossier/dossier-2/myimage.jpg>, ('allowedRolesAndUsers',), 1), (0, <Image at /Plone/dossier/dossier-2/myimage.jpg>, [], 1), (0, <Folder at /Plone/dossier-2>, [], 1)]
QUEUE OPTIMIZE, AFTER [(0, <Image at /Plone/dossier/dossier-2/myimage.jpg>, [], 1), (0, <Folder at /Plone/dossier/dossier-2>, [], 1)]
really reindex <Image at myimage.jpg>
really reindex <Folder at dossier-2>
PROCESS QUEUE
QUEUE OPTIMIZE, BEFORE []
QUEUE OPTIMIZE, AFTER []

Cut myimage.jpg from dossier to same folder dossier:

<OFS.event.ObjectWillBeMovedEvent object at 0x7fa2d1cfead0> <Image at myimage.jpg>
QUEUE UNINDEX <Image at myimage.jpg>
<zope.lifecycleevent.ObjectMovedEvent object at 0x7fa2d1cfe990> <Image at myimage.jpg>
QUEUE REINDEX <Image at myimage.jpg>
notify_content_object_moved in plone.app.discussion forces the queue to process
PROCESS QUEUE
QUEUE OPTIMIZE, BEFORE [(-1, <Image at /Plone/dossier/myimage.jpg>, None, None), (0, <Image at /Plone/dossier/myimage.jpg>, [], 1)]
QUEUE OPTIMIZE, AFTER [(-1, <Image at /Plone/dossier/myimage.jpg>, [], 1)]
really unindex <Image at myimage.jpg>
<z3c.caching.purge.Purge object at 0x7fa2dd978c50> <Image at myimage.jpg>
<z3c.caching.purge.Purge object at 0x7fa2dd978c50> <Folder at dossier>
<zope.container.contained.ContainerModifiedEvent object at 0x7fa2dd978c50> <Folder at dossier>
QUEUE REINDEX <Folder at dossier>
PROCESS QUEUE
QUEUE OPTIMIZE, BEFORE [(0, <Folder at /Plone/dossier>, [], 1)]
QUEUE OPTIMIZE, AFTER [(0, <Folder at /Plone/dossier>, [], 1)]
really reindex <Folder at dossier>
PROCESS QUEUE
QUEUE OPTIMIZE, BEFORE []
QUEUE OPTIMIZE, AFTER []

vincentfretin commented 4 years ago

[(-1, <Image at /Plone/dossier/myimage.jpg>, None, None), (0, <Image at /Plone/dossier/myimage.jpg>, [], 1)]

optimize to:

[(-1, <Image at /Plone/dossier/myimage.jpg>, [], 1)]

I think it should be:

[(0, <Image at /Plone/dossier/myimage.jpg>, [], 1)]

The line that may be wrong is https://github.com/zopefoundation/Products.CMFCore/blob/master/Products/CMFCore/indexing.py#L189

op = min(max(op, UNINDEX), INDEX)

vincentfretin commented 4 years ago

same issue was in https://github.com/plone/collective.indexing/blob/master/src/collective/indexing/queue.py#L136

Helge Tesdal @tesdal (cc Andreas Zeidler @witsch) I think you wrote this code like 12 years ago https://github.com/plone/collective.indexing/commit/49331cbea31948ff95ad407a9d87a058ceed13a2

Now collective.indexing is integrated in Products.CMFCore. I don't see the case UNINDEX followed my REINDEX in the tests https://github.com/zopefoundation/Products.CMFCore/blob/master/Products/CMFCore/tests/test_CatalogIndexing.py#L249-L265

vincentfretin commented 4 years ago

From buildout.coredev 5.2 I added Products.CMFCore in tests.cfg and added the following test in testOptimizeQueuexx

          queue.setState([(UNINDEX, 'A', None, None), (REINDEX, 'A', [], 1)])        
          queue.optimize()                                                        
          self.assertEqual(queue.getState(), [(REINDEX, 'A', [], 1)])

and run with bin/test -s Products.CMFCore -t testOptimizeQueuexx this fails, it gives (UNINDEX, 'A', [], 1)] instead of (REINDEX, 'A', [], 1)]

vincentfretin commented 4 years ago

I created the failing test here: https://github.com/zopefoundation/Products.CMFCore/pull/96

vincentfretin commented 4 years ago

I understood the code, the line that has the issue is op += iop See the issue description and the fix in https://github.com/zopefoundation/Products.CMFCore/pull/96

vincentfretin commented 4 years ago

And I just verified in Plone for real, the item doesn't disappear anymore. :+1:

vincentfretin commented 4 years ago

The fix is released in Products.CMFCore 2.4.8 (Plone 5.2.2)

plone / Products.CMFPlone