[ZODB-Dev] cPickle: state is not a directory/Upgrade to Zope 2.7failing

Tim Peters tim at zope.com
Tue Nov 4 11:17:24 EST 2003


Recap:  Andreas has a Zope 2.6.2 site (Python 2.2.3, CMF 1.4), and is trying to
migrate it to Zope 2.7 with Python 2.3.2.  He gets exceptions upon startup,
coming out of _set_ghost_state, with cPickle complaining:

    cPickle.UnpicklingError: state is not a dictionary

[Tim]
>> So we need more info.  Two things:
>>
>> 1. Fiddle _set_ghost_state to output repr(p) when this fails.
>>    That is, I need to see the actual pickle, in all its gory glory.
>>    All we can deduce from the above is that the state object is
>>    neither None nor a dict (the error message told us it's not a
>>    dict, and it wouldn't have gotten to that check if it were None).

[Andreas Jung]

"""
repr(p):

'((U\x0fHelpSys.HelpSysq\x01U\x0bProductHelpq\x02tq\x03Nt.}q\x04(U\x07catal
ogq\x05(U\x08\x00\x00\x00\x00\x00\x01FSq\x06(U\x1aProducts.ZCatalog.ZCatalo
gq\x07U\x08ZCatalogq\x08ttQU\x0elastRegisteredq\t(cDateTime.DateTime\nDateT
ime\nq\nNoq\x0b(GA\xcf\xb7\xf0\xe4\x94\x18\x93U\x05GMT+2q\x0ctbU\x05titleq\
rU\x14CMF CollectorNG
Helpq\x0eU\x08_objectsq\x0f(}q\x10(U\tmeta_typeq\x11U\nHelp
Topicq\x12U\x02idq\x13U\x0fplaceholder.txtq\x14uth\x13U\x04Helpq\x15U\x0fpl
aceholder.txtq\x16(U\x08\x00\x00\x00\x00\x00\x01FTq\x17(U\x11HelpSys.HelpTo
picq\x18U\x08STXTopicq\x19ttQu.'
"""

That obviously <wink> explains it, but I'm not sure what we can do about it --
it is indeed a bad pickle.  The difference is that, before Python 2.3, cPickle
skipped a crucial type check and ended up simply ignoring the offending part of
the pickle; several holes "like that" were fixed in 2.3 cPickle, and it
properly complains.  So that's the first point to take away:  this pickle is
bad, and never should have worked.

2.3 has a new pickletools module, with a handy dis() function for doing a
symbolic dump of pickles.  That pickle contains two things, and
_set_ghost_state complains during the second.  Here's a dump of the first
thing:

    0: (    MARK
    1: (        MARK
    2: U            SHORT_BINSTRING 'HelpSys.HelpSys'
   19: q            BINPUT     1
   21: U            SHORT_BINSTRING 'ProductHelp'
   34: q            BINPUT     2
   36: t            TUPLE      (MARK at 1)
   37: q        BINPUT     3
   39: N        NONE
   40: t        TUPLE      (MARK at 0)
   41: .    STOP

That's identifying the module and class of an object.  It looks fine.  The
second thing in the pickle is trying to record that object's state:

    0: }    EMPTY_DICT
    1: q    BINPUT     4
    3: (    MARK
    4: U        SHORT_BINSTRING 'catalog'
   13: q        BINPUT     5
   15: (        MARK
   16: U            SHORT_BINSTRING '\x00\x00\x00\x00\x00\x01FS'
   26: q            BINPUT     6
   28: (            MARK
   29: U                SHORT_BINSTRING 'Products.ZCatalog.ZCatalog'
   57: q                BINPUT     7
   59: U                SHORT_BINSTRING 'ZCatalog'
   69: q                BINPUT     8
   71: t                TUPLE      (MARK at 28)
   72: t            TUPLE      (MARK at 15)
   73: Q        BINPERSID
   74: U        SHORT_BINSTRING 'lastRegistered'
   90: q        BINPUT     9
   92: (        MARK
   93: c            GLOBAL     'DateTime.DateTime DateTime'
  121: q            BINPUT     10
  123: N            NONE
  124: o            OBJ        (MARK at 92)
  125: q        BINPUT     11
  127: (        MARK
  128: G            BINFLOAT   1064296905.1569999
  137: U            SHORT_BINSTRING 'GMT+2'
  144: q            BINPUT     12
  146: t            TUPLE      (MARK at 127)
  147: b        BUILD
  148: U        SHORT_BINSTRING 'title'
  155: q        BINPUT     13
  157: U        SHORT_BINSTRING 'CMF CollectorNG Help'
  179: q        BINPUT     14
  181: U        SHORT_BINSTRING '_objects'
  191: q        BINPUT     15
  193: (        MARK
  194: }            EMPTY_DICT
  195: q            BINPUT     16
  197: (            MARK
  198: U                SHORT_BINSTRING 'meta_type'
  209: q                BINPUT     17
  211: U                SHORT_BINSTRING 'Help Topic'
  223: q                BINPUT     18
  225: U                SHORT_BINSTRING 'id'
  229: q                BINPUT     19
  231: U                SHORT_BINSTRING 'placeholder.txt'
  248: q                BINPUT     20
  250: u                SETITEMS   (MARK at 197)
  251: t            TUPLE      (MARK at 193)
  252: h        BINGET     19
  254: U        SHORT_BINSTRING 'Help'
  260: q        BINPUT     21
  262: U        SHORT_BINSTRING 'placeholder.txt'
  279: q        BINPUT     22
  281: (        MARK
  282: U            SHORT_BINSTRING '\x00\x00\x00\x00\x00\x01FT'
  292: q            BINPUT     23
  294: (            MARK
  295: U                SHORT_BINSTRING 'HelpSys.HelpTopic'
  314: q                BINPUT     24
  316: U                SHORT_BINSTRING 'STXTopic'
  326: q                BINPUT     25
  328: t                TUPLE      (MARK at 294)
  329: t            TUPLE      (MARK at 281)
  330: Q        BINPERSID
  331: u        SETITEMS   (MARK at 3)
  332: .    STOP

The offending "subpickle" has repr

(cDateTime.DateTime\nDateTime\nq\nNoq\x0b(GA\xcf\xb7\xf0\xe4\x94\x18\x93Ux05GMT
+2q\x0ctb.

and corresponds to the second dump above starting with

   92: (        MARK

and ending with

  147: b        BUILD

It's the BUILD opcode that's complaining in 2.3.  I created a binary file
"pick" with just this part of the pickle (with a STOP opcode appended), and
I'll attach that.  Here's a full dump of the attached pickle:

    0: (    MARK
    1: c        GLOBAL     'DateTime.DateTime DateTime'
   29: q        BINPUT     10
   31: N        NONE
   32: o        OBJ        (MARK at 0)
   33: q    BINPUT     11
   35: (    MARK
   36: G        BINFLOAT   1064296905.1569999
   45: U        SHORT_BINSTRING 'GMT+2'
   52: q        BINPUT     12
   54: t        TUPLE      (MARK at 35)
   55: b    BUILD
   56: .    STOP

This pickle creates a DateTime object, and then *tries* to set its state from a
tuple.  That's not legal -- a tuple makes no sense here.  Before Python 2.3,
cPickle silently ignored the tuple, seemingly by accident.  2.2.3's cPickle's
load_build() contains:

        i = 0;
        while (PyDict_Next(value, &i, &d_key, &d_value)) {
            if (PyObject_SetItem(instdict, d_key, d_value) < 0) {
                r=-1;
                break;
            }
        }

where "value" is the tuple.  Alas, PyDict_Next just returns 0, without setting
an exception, if the thing passed to it isn't an instance of a dict subclass.
So, in 2.2.3, this loop ends unexceptionally on the the first PyDict_Next call,
and the "state tuple" is plain ignored.

It's more complicated in 2.3, because a tuple of (exactly) length 2 actually
*is* legal here in 2.3.  It expects the 2-tuple to contain a state dict, and a
slot state dict (before 2.3, objects with slots couldn't be pickled reliably).
So, under 2.3, the float 1064296905.1569999 gets unpacked into "the state
dict", and the string 'GMT+2' gets unpacked into "the slotstate dict".  Float
isn't a dict subclass, so 2.3's load_build() properly gripes with "state is not
a dictionary".

>> 2. You might try fiddling _set_ghost_state to use pickle.py instead
>>    of the cPickle module.  Sometimes there's a bug in one that's not
>>    in the other, and even if not pickle.py sometimes produces
>>    error messages that are more informative.

[Andreas]
"""
Using pickle.py:


------
2003-11-04T08:16:50 INFO(0) ZServer HTTP server started at Tue Nov  4
08:16:50 2003
	Hostname: sentinel
	Port: 20080
------
2003-11-04T08:16:50 INFO(0) ZServer FTP server started at Tue Nov  4
08:16:50 2003
	Hostname: localhost.localdomain
	Port: 20021
------
2003-11-04T08:16:51 DEBUG(-200) Localizer Unicode patching for Zope 2.6b1+
------
2003-11-04T08:16:51 DEBUG(-200) FileStorage create storage
/develop/sandboxes/tracker/instance/var/Data.fs
------
2003-11-04T08:16:51 INFO(0) ZODB Opening database for mounting:
'145966912_1035475459.685228'
------
2003-11-04T08:16:51 DEBUG(-200) TemporaryStorage create storage
TemporaryStorage
------
2003-11-04T08:16:51 INFO(0) ZODB Mounted database
'145966912_1035475459.685228' at /temp_folder
------
2003-11-04T08:16:51 ERROR(200) ZODB Couldn't load state for 0000000000014652
Traceback (most recent call last):
  File "/develop/sandboxes/tracker/Zope/lib/python/ZODB/Connection.py",
line 564, in setstate
    self._set_ghost_state(obj, p)
  File "/develop/sandboxes/tracker/Zope/lib/python/ZODB/Connection.py",
line 606, in _set_ghost_state
    state = unpickler.load()
  File "/opt/python-2.3.2/lib/python2.3/pickle.py", line 872, in load
    dispatch[key](self)
  File "/opt/python-2.3.2/lib/python2.3/pickle.py", line 1244, in load_build
    inst.__dict__.update(state)
AttributeError: keys
------
2003-11-04T08:16:51 ERROR(200) Zope Couldn't install CMFCollectorNG
Traceback (most recent call last):
  File "/develop/sandboxes/tracker/Zope/lib/python/OFS/Application.py",
line 642, in install_product
    initmethod(context)
  File
"/develop/sandboxes/tracker/instance/Products/CMFCollectorNG/__init__.py",
line 52, in initialize
    context.registerHelp(directory='help')
  File "/develop/sandboxes/tracker/Zope/lib/python/App/ProductContext.py",
line 302, in registerHelp
    if help.lastRegistered is not None and \
AttributeError: lastRegistered
Traceback (most recent call last):
  File "/develop/sandboxes/tracker/Zope/lib/python/Zope/Startup/run.py",
line 27, in ?
    run()
  File "/develop/sandboxes/tracker/Zope/lib/python/Zope/Startup/run.py",
line 24, in run
    start_zope(opts.configroot)
  File
"/develop/sandboxes/tracker/Zope/lib/python/Zope/Startup/__init__.py", line
50, in start_zope
    starter.startZope()
  File
"/develop/sandboxes/tracker/Zope/lib/python/Zope/Startup/__init__.py", line
221, in startZope
    Zope.startup()
  File "/develop/sandboxes/tracker/Zope/lib/python/Zope/__init__.py", line
46, in startup
    _startup()
  File "/develop/sandboxes/tracker/Zope/lib/python/Zope/App/startup.py",
line 95, in startup
    OFS.Application.initialize(application)
  File "/develop/sandboxes/tracker/Zope/lib/python/OFS/Application.py",
line 421, in initialize
    install_products(app)
  File "/develop/sandboxes/tracker/Zope/lib/python/OFS/Application.py",
line 580, in install_products
    folder_permissions, raise_exc=debug_mode)
  File "/develop/sandboxes/tracker/Zope/lib/python/OFS/Application.py",
line 642, in install_product
    initmethod(context)
  File
"/develop/sandboxes/tracker/instance/Products/CMFCollectorNG/__init__.py",
line 52, in initialize
    context.registerHelp(directory='help')
  File "/develop/sandboxes/tracker/Zope/lib/python/App/ProductContext.py",
line 302, in registerHelp
    if help.lastRegistered is not None and \
AttributeError: lastRegistered
"""

I expect you'd get much the same if you tried this using pickle.py under 2.2.3
too.  The

    AttributeError: keys

you're getting from pickle.py's load_build() is its way of spelling "hey, the
state isn't a dict or subclass of dict".

Using the binary pickle attached, here under 2.3.2:

>>> f = open('/code/pick', 'rb')
>>> guts = f.read()
>>> import cPickle
>>> cPickle.loads(guts)   # this is the same error you originally reported
Traceback (most recent call last):
  File "<stdin>", line 1, in ?
cPickle.UnpicklingError: state is not a dictionary

>>> import pickle
>>> pickle.loads(guts)    # this is the same error you showed from pickle.py
Traceback (most recent call last):
  File "<stdin>", line 1, in ?
  File "C:\PYTHON23\lib\pickle.py", line 1394, in loads
    return Unpickler(file).load()
  File "C:\PYTHON23\lib\pickle.py", line 872, in load
    dispatch[key](self)
  File "C:\PYTHON23\lib\pickle.py", line 1244, in load_build
    inst.__dict__.update(state)
AttributeError: keys
>>>

The same thing under 2.2.3:

>>> f = open('/code/pick', 'rb')
>>> guts = f.read()
>>> import cPickle
>>> cPickle.loads(guts)
DateTime('2003/11/04 10:22:44.270 US/Eastern')

Note that while the loads() didn't complain, it didn't create the intended
object either:  that's *current* date and time, as of the time I ran that
example.  The time recorded in the bogus "state tuple" was ignored.

So the crucial question is who produces DateTime pickles of this form?  All
such pickles will silently do a wrong thing when loaded with a Python before
2.3 (they'll all load as current date and time), and will raise an exception
when loaded under 2.3+.

>>> import pickle
>>> pickle.loads(guts)
Traceback (most recent call last):
  File "<stdin>", line 1, in ?
  File "C:\PYTHON22\lib\pickle.py", line 986, in loads
    return Unpickler(file).load()
  File "C:\PYTHON22\lib\pickle.py", line 597, in load
    dispatch[key](self)
  File "C:\PYTHON22\lib\pickle.py", line 939, in load_build
    inst.__dict__.update(value)
AttributeError: keys
>>>

So pickle.py dies the same way under 2.2.3 and 2.3.2.
-------------- next part --------------
A non-text attachment was scrubbed...
Name: pick
Type: application/octet-stream
Size: 57 bytes
Desc: not available
Url : http://lists.zope.org/pipermail/zodb-dev/attachments/20031104/a67e8df9/pick-0001.obj


More information about the ZODB-Dev mailing list