Zodbpack UnicodeDecodeError on migrated zodb

Plone Support
, ,
1

I have several dbs migrated from python 2 to python 3, Plone 5.2. One of them is giving me an error when packing the database

Traceback (most recent call last):
  File "/plone/plone5.2/buildout/bin/zeopack", line 42, in <module>
    sys.exit(plone.recipe.zeoserver.pack.main(host, port, unix, days, username, password, realm, blb_dir, storage))
  File "/plone/eggs/plone.recipe.zeoserver-2.0.1-py3.6.egg/plon/recipe/zeoserver/pack.py", line 65, in main
    _main(*args, **kw)
  File "/plone/eggs/plone.recipe.zeoserver-2.0.1-py3.6.egg/plon/recipe/zeoserver/pack.py", line 46, in _main
    cs.pack(wait=True, days=int(days))
  File "/plone/eggs/ZEO-5.2.1-py3.6.egg/ZEO/ClientStorage.py", ine 562, in pack
    return self._call('pack', t, wait)
  File "/plone/eggs/ZEO-5.2.1-py3.6.egg/ZEO/asyncio/client.py",line 764, in call
    return self.__call(self.call_threadsafe, method, args, **kw)
  File "/plone/eggs/ZEO-5.2.1-py3.6.egg/ZEO/asyncio/client.py",line 743, in call
    return self.wait_for_result(result, timeout)
  File "/plone/eggs/ZEO-5.2.1-py3.6.egg/ZEO/asyncio/client.py",line 756, in wait_for_result
    return future.result(timeout)
  File "/usr/lib64/python3.6/concurrent/futures/_base.py", line 432, in result
    return self.__get_result()
  File "/usr/lib64/python3.6/concurrent/futures/_base.py", line 384, in __get_result
    raise self._exception
ZEO.Exceptions.ServerException: ('builtins.UnicodeDecodeError', ('ascii', b'\x00\x00\x00\x00\x00\x0\xeb$', 6, 7, 'ordinal not in range(128)'))

Everything should have been converted with zodbupdate with command ./bin/zodbupdate --convert-py3 --file=$path_to_db --encoding-fallback latin1. I'm not sure if the update had an error that went unnoticed when I migrated a couple months ago or if this is new. The site appears to functional normally and I can create backups, I just can't pack.

I tried copying this to a dev environment and rerunning the conversion in python 3 as described by documention for zodbupdate. It fails at the packing stage.

Packing storage ...
Traceback (most recent call last):
  File "./bin/zodbupdate", line 322, in <module>
    sys.exit(zodbupdate.main.main())
  File "/plone/eggs/zodbupdate-1.4-py3.6.egg/zodbupdate/main.py", line 239, in main
    storage.pack(time.time(), ZODB.serialize.referencesf)
  File "/plone/eggs/ZODB-5.5.1-py3.6.egg/ZODB/FileStorage/FileStorage.py", line 1231, in pack
    pack_result = self.packer(self, referencesf, stop, gc)
  File "/plone/eggs/ZODB-5.5.1-py3.6.egg/ZODB/FileStorage/FileStorage.py", line 1184, in packer
    opos = p.pack()
  File "/plone/eggs/ZODB-5.5.1-py3.6.egg/ZODB/FileStorage/fspack.py", line 405, in pack
    self.gc.findReachable()
  File "/plone/eggs/ZODB-5.5.1-py3.6.egg/ZODB/FileStorage/fspack.py", line 191, in findReachable
    self.findReachableAtPacktime([z64])
  File "/plone/eggs/ZODB-5.5.1-py3.6.egg/ZODB/FileStorage/fspack.py", line 276, in findReachableAtPacktime
    for oid in self.findrefs(pos):
  File "/plone/eggs/ZODB-5.5.1-py3.6.egg/ZODB/FileStorage/fspack.py", line 329, in findrefs
    return self.referencesf(self._file.read(dh.plen))
  File "/plone/eggs/ZODB-5.5.1-py3.6.egg/ZODB/serialize.py", line 650, in referencesf
    u.noload()
UnicodeDecodeError: 'ascii' codec can't decode byte 0xeb in position 6: ordinal not in range(128)

What's my recourse here? Is there a way to find these objects and remove them?

2

I think this is the same issue that @pbauer mentions here: https://github.com/zopefoundation/ZODB/issues/285

I got the oid from running zodbupdate -v and simply tried to load it in debug mode:

>>> oid=0x02eb03
>>> from ZODB.utils import p64
>>> app._p_jar.get(p64(oid))
ERROR:ZODB.Connection:Couldn't load state for BTrees.OIBTree.OISet 0x02eb03
Traceback (most recent call last):
  File "/sprj/btp_zope_plone5/plone-btp-dev-02/buildouts/eggs/ZODB-5.5.1-py3.6.egg/ZODB/Connection.py", line 795, in setstate
    self._reader.setGhostState(obj, p)
  File "/sprj/btp_zope_plone5/plone-btp-dev-02/buildouts/eggs/ZODB-5.5.1-py3.6.egg/ZODB/serialize.py", line 633, in setGhostState
    state = self.getState(pickle)
  File "/sprj/btp_zope_plone5/plone-btp-dev-02/buildouts/eggs/ZODB-5.5.1-py3.6.egg/ZODB/serialize.py", line 626, in getState
    return unpickler.load()
UnicodeDecodeError: 'ascii' codec can't decode byte 0xeb in position 6: ordinal not in range(128)
Traceback (most recent call last):
  File "<console>", line 1, in <module>
  File "/sprj/btp_zope_plone5/plone-btp-dev-02/buildouts/eggs/ZODB-5.5.1-py3.6.egg/ZODB/Connection.py", line 795, in setstate
    self._reader.setGhostState(obj, p)
  File "/sprj/btp_zope_plone5/plone-btp-dev-02/buildouts/eggs/ZODB-5.5.1-py3.6.egg/ZODB/serialize.py", line 633, in setGhostState
    state = self.getState(pickle)
  File "/sprj/btp_zope_plone5/plone-btp-dev-02/buildouts/eggs/ZODB-5.5.1-py3.6.egg/ZODB/serialize.py", line 626, in getState
    return unpickler.load()
UnicodeDecodeError: 'ascii' codec can't decode byte 0xeb in position 6: ordinal not in range(128)

I have no idea what this is other than an instance of OISet. Unfortunately I can't use pbauer's solution of clearing the obj in python 2 first since I've already committed to the python 3 version before realizing it was a problem. Attempting to call clear() triggers the same problem. Is there some other way to remove an object by oid?

3

This looks like an "oid" (= Object ID). Nothing should try to convert it into an str (at least not with the ascii encoding). I assume that the latin1` fallback may have caused a misinterpretation.

In your followup post, you show that a load fails with a similar error in an unpickle. You could use Python's pickletoolsto look into the corresponding pickle. This might show what zodbupdate did wrong.

4

It is definitely an oid: running zodbupdate with the "-v" flag originally showed that it was 0x02eb03

>>> p64(0x02eb03)
b'\x00\x00\x00\x00\x00\x02\xeb\x03'

Slightly different ending but possibly just a display difference. I tried removing it with a method similar to one outlined here https://www.nathanvangheem.com/posts/2011/05/25/fixing-broken-zodb-object-references.html but this led to a ValueError and I am loathe to seriously attempt fixing the DB with this black magic.

Maybe the best course of action at this point is to cut my losses and keep "pack-gc = false" set for the future for this DB.

5

I also ran into the same error when I tried to pack an already converted ZODB (relstorage in my case).

DISCLAIMER: This is NOT a recommendation!

I packed the ZODB (about 2gb of Data.fs and 18gb of blobs) to zero days and converted it to py3.
There were some warnings pointing to some leftovers of addons but didn't put much attention to it, since they were already removed or not in use for long.

Moving it to relstorage with zodbconvert worked without any issues and I also couldn't find any issues while testing the migrated site, besides I had to setup some caching settings by reimporting the profile.

Days later, without any other issues, I wanted to setup a cron job for automatic packing of the DB and ran into the mentioned error.

Since everything else worked I searched for a way to get rid of the old and no longer in use objects in a bulk way and not one by one not knowing how many there would be and stumbled over Zope ZODB Pack error - Stack Overflow

It basically ignores objects that are no longer readable, while zodbpack is evaluating which object should be moved into the packed ZODB.

In serialize.py of ZOBD-5.6.0 I changed #637 to

def referencesf(p, oids=None):
    """Return a list of object ids found in a pickle

    A list may be passed in, in which case, information is
    appended to it.

    Only ordinary internal references are included.
    Weak and multi-database references are not included.
    """

    refs = []
    u = PersistentUnpickler(None, refs.append, BytesIO(p))
    u.noload()
    try:
        u.noload()
    except Exception:
        print(f"Ignoring AttributeError during garbage collection unpickling. {Exception}")
        pass

I did put that in a separate buildout to not have to alter the existing deployment.

Data.fs and blobs before packing 26gb / 32gb in Postgres.

Packing worked with the try/except but resulted as 53gb in Postgres. And didn't get smaller with additional zodbpack calls.

Looked like ZODB/zodbpack had no reference whatsoever for the old/ignored "trash data".

What finally helped to reduce the size, back to the actual data was to do a ./bin/zodbconvert relstorage-backup.cfg out of relstorage, where only the known/active objects get exported, resulting in 17gb of Data on the filesystem.

I then started a fresh import with ./bin/zodbconvert --clear relstorage-restore.cfg where the size of Postgres went finally down to 27gb.

AND ONCE AGAIN... DISCLAIMER: This is NOT a recommendation!