packing a db fails on python3.7 with '_pickle.UnpicklingError: odd number of items for SETITEMS'

[dwt]

I'm not sure what info I can best provide here, as I can't share the database this happens on.

What I can share though is that I have a DB that we update from python2 to python3 with https://github.com/zopefoundation/zodbupdate (which seems to work well, even if it is black magic) but when I also pack it while updating it does throw this error on python 3.7.3 (Mac) while it does not on python3.6.8 (Mac and CentOS).

I'm a bit of a noob concerning ZODB so I'd like some pointers how to best provide info on this bug.

The error and traceback look a bit like this:

1 (venv) ~/some/path/zope4/instances/test/var % zodbupdate -f Data_cmstest3.fs --pack --encoding utf8 --encoding-fallback latin1 --convert-py3
Updating magic marker for Data_cmstest3.fs
Loaded 1 rename rules from OFS:renames
Loaded 2 decode rules from AccessControl:decodes
Loaded 2 decode rules from Products.PythonScripts:decodes
Loaded 13 decode rules from OFS:decodes
Warning: Missing factory for App.Product ProductFolder
Warning: Missing factory for Products.LDAPMultiPlugins.LDAPMultiPlugin LDAPMultiPlugin
Warning: Missing factory for Products.LDAPUserFolder.LDAPUserFolder LDAPUserFolder
Warning: Missing factory for Products.LDAPUserFolder.LDAPDelegate LDAPDelegate
Committing changes (#1).
Committing changes (#2).
Committing changes (#3).
Committing changes (#4).
Committing changes (#5).
Committing changes (#6).
Committing changes (#7).
Committing changes (#8).
Committing changes (#9).
Committing changes (#10).
Committing changes (#11).
Committing changes (#12).
Committing changes (#13).
Committing changes (#14).
Committing changes (#15).
Committing changes (#16).
Committing changes (#17).
Committing changes (#18).
Committing changes (#19).
Committing changes (#20).
Packing storage ...
Traceback (most recent call last):
  File "/some/path/bin/zodbupdate", line 11, in <module>
    load_entry_point('zodbupdate', 'console_scripts', 'zodbupdate')()
  File "/some/path/zodbupdate/src/zodbupdate/main.py", line 232, in main
    storage.pack(time.time(), ZODB.serialize.referencesf)
  File "/some/path/ZODB/FileStorage/FileStorage.py", line 1231, in pack
    pack_result = self.packer(self, referencesf, stop, gc)
  File "/some/path/ZODB/FileStorage/FileStorage.py", line 1184, in packer
    opos = p.pack()
  File "/some/path/ZODB/FileStorage/fspack.py", line 405, in pack
    self.gc.findReachable()
  File "/some/path/ZODB/FileStorage/fspack.py", line 191, in findReachable
    self.findReachableAtPacktime([z64])
  File "/some/path/ZODB/FileStorage/fspack.py", line 276, in findReachableAtPacktime
    for oid in self.findrefs(pos):
  File "/some/path/ZODB/FileStorage/fspack.py", line 329, in findrefs
    return self.referencesf(self._file.read(dh.plen))
  File "/some/path/ZODB/serialize.py", line 650, in referencesf
    u.noload()
_pickle.UnpicklingError: odd number of items for SETITEMS
zodbupdate -f Data_cmstest3.fs --pack --encoding utf8 --encoding-fallback    402,58s user 25,04s system 95% cpu 7:26,78 total

Looking at where I think this error originates from on 3.6 and 3.7 there doesn't seem to be an obvious difference. But maybe I'm missing something?

Also of course this could be a problem of https://github.com/zopefoundation/zodbupdate, but I'm filing it here first as it seems to happen during pack deep in ZODB code and also didn't happen on the previous python version.

[jamadden]

ZODB uses a fork of pickle called zodbpickle. The code in zodbpickle is the same for all Python 3.x versions, so it's not obvious to me how you could get different behaviour depending on the Python version.

It might help to see the pickle in question; you could get that by adding a try/except around line 650 in ZODB/serialize.py and printing it.

[dwt]

I'm not quite comfortable to link this pickle in the public bug, but I think I can send it to you privately. Can you give me an email where I can send this to?

[mgedmin]

I saw zopefoundation/zodbpickle#47 today talking about random pickle corruption and remembered this bug. Could it be the cause of your problem? (How could we ascertain that?)

[dwt]

I can try the conversion again with that patch - as the bug is completely reproducible for me, this might help. I'll have a look soon.

[dwt]

Indeed that seems to be the same bug, or at least something with the same underlaying reason. Lets seem what the discussion there turns up.

Thanks @mgedmin for the tip!

[dwt]

Closing this now, as I cannot reproduce this any longer with the patch from zopefoundation/zodbpickle#47 applied.