diff --git a/news/3987.bugfix.1.rst b/news/3987.bugfix.1.rst new file mode 100644 index 000000000..b86924c94 --- /dev/null +++ b/news/3987.bugfix.1.rst @@ -0,0 +1 @@ +Add upgrade step to fix inconsistencies in UID index. [maurits] diff --git a/src/euphorie/upgrade/deployment/v19/20251010123200_fix_uid_index/__init__.py b/src/euphorie/upgrade/deployment/v19/20251010123200_fix_uid_index/__init__.py new file mode 100644 index 000000000..e69de29bb diff --git a/src/euphorie/upgrade/deployment/v19/20251010123200_fix_uid_index/upgrade.py b/src/euphorie/upgrade/deployment/v19/20251010123200_fix_uid_index/upgrade.py new file mode 100644 index 000000000..eee3814d2 --- /dev/null +++ b/src/euphorie/upgrade/deployment/v19/20251010123200_fix_uid_index/upgrade.py @@ -0,0 +1,243 @@ +from ftw.upgrade import UpgradeStep +from plone import api +from plone.app.upgrade.utils import update_catalog_metadata +from plone.uuid.handlers import addAttributeUUID +from plone.uuid.interfaces import ATTRIBUTE_NAME +from plone.uuid.interfaces import IUUID +from Products.ZCatalog.ProgressHandler import ZLogHandler +from zope.globalrequest import getRequest + +import logging +import os +import transaction + + +logger = logging.getLogger(__name__) +# By default we do intermediate commits, to have less chance of ConflictErrors. +# Set the environment variable EUPHORIE_DISABLE_INTERMEDIATE_COMMITS=1 +# to disable intermediate commits. +EUPHORIE_DISABLE_INTERMEDIATE_COMMITS = bool( + int(os.environ.get("EUPHORIE_DISABLE_INTERMEDIATE_COMMITS", 0)) +) + + +class FixUidIndex(UpgradeStep): + """Fix UID index inconsistencies. + + The 20251006201600_ensure_uid upgrade step ensured that all content + has a UID assigned to it. But that was not enough to fix all problems. + So we need to take over some more code from this script: + https://github.com/zestsoftware/plonescripts/blob/master/fix_uid_index.py + + That script first checks paths in actual_catalog.uids.keys(), but that did + not surface any problems in our case, so we skip that part here. + + Then it really checks the UID index. This has two internal BTrees + that can get out of sync: + + 1) _index: UID -> doc id + 2) _unindex: doc id -> UID + + And indeed we see problems there in a test site: + + Number of _index uid keys: 198801, unique: 198801 + Number of _index doc id values: 198801, unique: 198801 + Number of _unindex doc id keys: 419339, unique: 419339 + Number of _unindex uid values: 419339, unique: 245707 + + Normally, all these numbers should all be the same. + This is not the case for us. + + The script tries to register intids for all objects that are missing them, + but we don't have that problem. So we skip that part. + """ + + def is_uid_index_consistent(self): + """Check if the UID index is consistent. + + Returns True if consistent, False if not. + """ + catalog = api.portal.get_tool("portal_catalog") + index = catalog.Indexes["UID"] + _index_keys = index._index.keys() + _index_values = index._index.values() + _unindex_keys = index._unindex.keys() + _unindex_values = index._unindex.values() + logger.info( + "Number of _index uid keys: %d, unique: %d", + len(_index_keys), + len(set(_index_keys)), + ) + logger.info( + "Number of _index doc id values: %d, unique: %d", + len(_index_values), + len(set(_index_values)), + ) + logger.info( + "Number of _unindex doc id keys: %d, unique: %d", + len(_unindex_keys), + len(set(_unindex_keys)), + ) + logger.info( + "Number of _unindex uid values: %d, unique: %d", + len(_unindex_values), + len(set(_unindex_values)), + ) + + # Both index and unindex should have the same number of entries. + # And keys and values should be unique. + if not ( + len(_index_keys) + == len(set(_index_keys)) + == len(_index_values) + == len(set(_index_values)) + == len(_unindex_keys) + == len(set(_unindex_keys)) + == len(_unindex_values) + == len(set(_unindex_values)) + ): + logger.error( + "The numbers of keys and values in the UID index are NOT consistent." + ) + return False + + logger.info("The numbers of keys and values in the UID index are consistent.") + # Are the matching sets the same? + if set(_index_keys) != set(_unindex_values) or set(_index_values) != set( + _unindex_keys + ): + logger.error( + "The sets are NOT the same. Inconsistencies found in UID index." + ) + return False + logger.info("No inconsistencies found in UID index.") + return True + + def _commit(self, note=""): + """Commit the current transaction with an optional note.""" + if EUPHORIE_DISABLE_INTERMEDIATE_COMMITS: + return + tx = transaction.get() + if note: + tx.note(note) + tx.commit() + logger.info("Committed transaction: %s", note) + + def __call__(self): + """Upgrade step to fix inconsistencies in the UID index. + + I will add some inline comments about how long this took on a test + site with about 420k items and a messed up UID index. + """ + logger.info("Checking inconsistencies in UID index.") + if self.is_uid_index_consistent(): + logger.info("The UID index is consistent. Nothing to do.") + return + + # Gather paths for which we will create a new uuid. + recreate = set() + catalog = api.portal.get_tool("portal_catalog") + index = catalog.Indexes["UID"] + # Get the values once to speed up the loop below. Without this, the + # first full run took over an hour, gathering 220k paths to recreate. + # Make it a set for faster 'in' checks. This reduces the time insanely. + index_index_values = set(index._index.values()) + logger.info("Checking _unindex items.") + for docid, uid in index._unindex.items(): + if docid not in index_index_values: + path = catalog.getpath(docid) + logger.debug( + "Doc id %s is missing from _index values. UID %s, path %s", + docid, + uid, + path, + ) + recreate.add(path) + if len(recreate) % 10000 == 0: + logger.info("Found %d paths to recreate so far.", len(recreate)) + + logger.info("Done checking _unindex items.") + if not recreate: + logger.info("No paths need to have their UID recreated.") + return + if recreate: + logger.info( + "We will recreate %d UIDs/UUIDs that are currently duplicate.", + len(recreate), + ) + logger.info( + "You might need to manually fix some links.\n" + "We have no way of knowing if a link should use " + "resolveuid/old_uid or resolveuid/new_uid.\n" + "Perhaps we could query the relation catalog to see " + "which relations an item has." + ) + + # Now recreate UIDs for the gathered paths. + # This took about 6 minutes on the test site. + app = self.portal.getPhysicalRoot() + for num, path in enumerate(recreate, 1): + try: + obj = app.unrestrictedTraverse(path) + except KeyError: + logger.info("Ignoring unreachable path to recreate UID: %s", path) + continue + # obj.UID() would return the UID of the parent in case + # obj is a Discussion Item. + old_uuid = IUUID(obj) + # This might find an item by acquisition. + # migration-law/migration-law/migration-law/research.htm + # may actually be migration-law/research.htm + actual_path = "/".join(obj.getPhysicalPath()) + if actual_path != path: + logger.warning( + "Wanted to recreate UID for path %s, but this leads to " + "other path %s. Ignoring.", + path, + actual_path, + ) + continue + delattr(obj, ATTRIBUTE_NAME) + # Call the event handler that adds a UUID: + addAttributeUUID(obj, None) + new_uuid = IUUID(obj) + logger.debug("Changed UID from %s to %s for %s", old_uuid, new_uuid, path) + if num % 10000 == 0: + note = f"Created fresh UID for {num}/{len(recreate)} paths so far." + logger.info(note) + if num % 50000 == 0: + self._commit(note=note) + + note = f"Created fresh UID for all {len(recreate)} paths." + logger.info(note) + self._commit(note=note) + + # Update catalog metadata to reflect new UIDs. + # On the test site this took about 13 minutes. + note = "Updating catalog metadata for UIDs." + logger.info(note) + logger.info("This can take a long time...") + update_catalog_metadata(self.portal, "UID") + self._commit(note=note) + + # Now we need to clear and reindex the UID index. + logger.info("Clearing UID index...") + index.clear() + # Reindexing took about 10 minutes on the test site. + # So let's add a progress logger. + logger.info("Reindexing UID index...") + catalog._catalog.reindexIndex( + "UID", + getRequest(), + pghandler=ZLogHandler(10000), + ) + note = "Reindexed UID index." + logger.info(note) + self._commit(note=note) + + logger.info("The UID index should be fine again. Checking...") + if not self.is_uid_index_consistent(): + raise ValueError( + "After all fixes and reindexing, the UID index is still inconsistent." + ) + logger.info("Yes, the UID index is consistent. All done.")