help debugging a "can't pickle" error deep within a catalog reindex
hi, i'm trying to perform a ZCatalog.refreshCatalog() on a catalog with over 29,000 indexed objects. it churns for a good long time, and eventually fails with a long set of tracebacks, of which i've included a sample at the end of this message. i think i understand the gist of the issue... it's trying to write an object (probably a CatalogBrain) to the database, but this object's __dict__ contains a value that is of type instancemethod, which isn't allowed for persistent objects. the problem is that i can't figure out which specific objects are causing the problem. i've used pdb.post_mortem to get a debug prompt way down in the traceback, but the code goes in and out of C modules, so i'm missing a lot of what's happening. and when i interactively peek at the objects that are being indexed when the error happens, there doesn't seem to be anything wrong, and i can index the objects w/ no problem. i've even tried dropping the subtransaction threshold down to 1, so it will try to commit a savepoint after every object, but none of the objects being indexed seemed to have any problems. i CAN verify that the instancemethod that is causing the problem renders like this: <bound method SessionDataManager.getSessionData of <SessionDataManager at /session_data_manager>> even that hasn't proven enough for me to concretely identify the source of the problem, though. i've been working on this for a full day already, and am not sure how to proceed. does anyone have any debugging tips that might help me figure out what, exactly, is causing the reindex attempts to blow up? thanks! -r Traceback (most recent call last): File "/home/rob/topp/14000/builds/20080611/opencore/lib/zope/lib/python/Products/ZCatalog/ZCatalog.py", line 296, in refreshCatalog self.catalog_object(obj, p, pghandler=pghandler) File "/home/rob/topp/14000/builds/20080611/opencore/zope/Products/CMFPlone/CatalogTool.py", line 367, in catalog_object self._increment_counter() File "/home/rob/topp/14000/builds/20080611/opencore/zope/Products/CMFPlone/CatalogTool.py", line 395, in _increment_counter self._counter.change(1) File "/home/rob/topp/14000/builds/20080611/opencore/lib/zope/lib/python/BTrees/Length.py", line 55, in change self.value += delta File "/home/rob/topp/14000/builds/20080611/opencore/lib/zope/lib/python/ZODB/Connection.py", line 890, in register self._register(obj) File "/home/rob/topp/14000/builds/20080611/opencore/lib/zope/lib/python/ZODB/Connection.py", line 900, in _register self.transaction_manager.get().join(self) File "/home/rob/topp/14000/builds/20080611/opencore/lib/zope/lib/python/transaction/_transaction.py", line 273, in join self._prior_operation_failed() # doesn't return File "/home/rob/topp/14000/builds/20080611/opencore/lib/zope/lib/python/transaction/_transaction.py", line 267, in _prior_operation_failed raise TransactionFailedError("An operation previously failed, " TransactionFailedError: An operation previously failed, with traceback: File "/home/rob/topp/14000/builds/20080611/opencore/lib/zope/lib/python/ZServer/PubCore/ZServerPublisher.py", line 25, in __init__ response=b) File "/home/rob/topp/14000/builds/20080611/opencore/lib/zope/lib/python/ZPublisher/Publish.py", line 401, in publish_module environ, debug, request, response) File "/home/rob/topp/14000/builds/20080611/opencore/lib/zope/lib/python/ZPublisher/Publish.py", line 202, in publish_module_standard response = publish(request, module_name, after_list, debug=debug) File "/home/rob/topp/14000/builds/20080611/opencore/lib/zope/lib/python/ZPublisher/Publish.py", line 119, in publish request, bind=1) File "/home/rob/topp/14000/builds/20080611/opencore/lib/zope/lib/python/ZPublisher/mapply.py", line 88, in mapply if debug is not None: return debug(object,args,context) File "/home/rob/topp/14000/builds/20080611/opencore/lib/zope/lib/python/ZPublisher/Publish.py", line 42, in call_object result=apply(object,args) # Type s<cr> to step into published object. File "/home/rob/topp/14000/builds/20080611/opencore/lib/zope/lib/python/Products/ZCatalog/ZCatalog.py", line 260, in manage_catalogReindex self.refreshCatalog(clear=1, pghandler=handler) File "/home/rob/topp/14000/builds/20080611/opencore/lib/zope/lib/python/Products/ZCatalog/ZCatalog.py", line 296, in refreshCatalog self.catalog_object(obj, p, pghandler=pghandler) File "/home/rob/topp/14000/builds/20080611/opencore/zope/Products/CMFPlone/CatalogTool.py", line 385, in catalog_object update_metadata, pghandler=pghandler) File "/home/rob/topp/14000/builds/20080611/opencore/zope/Products/CacheSetup/patch.py", line 96, in catalog_object uid, idxs, update_metadata, pghandler) File "/home/rob/topp/14000/builds/20080611/opencore/zope/Products/CacheSetup/patch_utils.py", line 6, in call return getattr(self, PATTERN % __name__)(*args, **kw) File "/home/rob/topp/14000/builds/20080611/opencore/lib/zope/lib/python/Products/ZCatalog/ZCatalog.py", line 560, in catalog_object transaction.savepoint(optimistic=True) File "/home/rob/topp/14000/builds/20080611/opencore/lib/zope/lib/python/transaction/_manager.py", line 110, in savepoint return self.get().savepoint(optimistic) File "/home/rob/topp/14000/builds/20080611/opencore/lib/zope/lib/python/transaction/_transaction.py", line 312, in savepoint self._saveAndRaiseCommitishError() # reraises! File "/home/rob/topp/14000/builds/20080611/opencore/lib/zope/lib/python/transaction/_transaction.py", line 422, in _saveAndRaiseCommitishError t, v, tb = self._saveAndGetCommitishError() File "/home/rob/topp/14000/builds/20080611/opencore/lib/zope/lib/python/transaction/_transaction.py", line 309, in savepoint savepoint = Savepoint(self, optimistic, *self._resources) File "/home/rob/topp/14000/builds/20080611/opencore/lib/zope/lib/python/transaction/_transaction.py", line 737, in __init__ savepoint = savepoint() File "/home/rob/topp/14000/builds/20080611/opencore/lib/zope/lib/python/ZODB/Connection.py", line 1046, in savepoint self._commit(None) File "/home/rob/topp/14000/builds/20080611/opencore/lib/zope/lib/python/ZODB/Connection.py", line 555, in _commit self._store_objects(ObjectWriter(obj), transaction) File "/home/rob/topp/14000/builds/20080611/opencore/lib/zope/lib/python/ZODB/Connection.py", line 582, in _store_objects p = writer.serialize(obj) # This calls __getstate__ of obj File "/home/rob/topp/14000/builds/20080611/opencore/lib/zope/lib/python/ZODB/serialize.py", line 407, in serialize return self._dump(meta, obj.__getstate__()) File "/home/rob/topp/14000/builds/20080611/opencore/lib/zope/lib/python/ZODB/serialize.py", line 416, in _dump self._p.dump(state) File "copy_reg.py", line 69, in _reduce_ex raise TypeError, "can't pickle %s objects" % base.__name__ TypeError: can't pickle instancemethod objects
Rob Miller <ra@burningman.com> writes:
hi,
i'm trying to perform a ZCatalog.refreshCatalog() on a catalog with over 29,000 indexed objects. it churns for a good long time, and eventually fails with a long set of tracebacks, of which i've included a sample at the end of this message.
i think i understand the gist of the issue... it's trying to write an object (probably a CatalogBrain) to the database, but this object's __dict__ contains a value that is of type instancemethod, which isn't allowed for persistent objects.
the problem is that i can't figure out which specific objects are causing the problem. i've used pdb.post_mortem to get a debug prompt way down in the traceback, but the code goes in and out of C modules, so i'm missing a lot of what's happening. and when i interactively peek at the objects that are being indexed when the error happens, there doesn't seem to be anything wrong, and i can index the objects w/ no problem. i've even tried dropping the subtransaction threshold down to 1, so it will try to commit a savepoint after every object, but none of the objects being indexed seemed to have any problems.
i CAN verify that the instancemethod that is causing the problem renders like this:
<bound method SessionDataManager.getSessionData of <SessionDataManager at /session_data_manager>>
even that hasn't proven enough for me to concretely identify the source of the problem, though.
i've been working on this for a full day already, and am not sure how to proceed. does anyone have any debugging tips that might help me figure out what, exactly, is causing the reindex attempts to blow up?
thanks!
Can you get a pdb.post_mortem prompt at the actual ZODB/serialize.py:416 error or only at transaction/_transaction.py:267 where some sort of previous error is handled? If the former, I often find it informative to step up to ZODB/serialize.py:407 where obj.__getstate__() is called and find out what obj is. Is it the same object every time? If not, is it of the same type every time? A next step can also be to put a pdb.set_trace() at transaction/_transaction.py:340 in the register() method such that it's is only called when the offending object is added to the transaction. Hope some of that helps, Ross
Traceback (most recent call last): File "/home/rob/topp/14000/builds/20080611/opencore/lib/zope/lib/python/Products/ZCatalog/ZCatalog.py", line 296, in refreshCatalog self.catalog_object(obj, p, pghandler=pghandler) File "/home/rob/topp/14000/builds/20080611/opencore/zope/Products/CMFPlone/CatalogTool.py", line 367, in catalog_object self._increment_counter() File "/home/rob/topp/14000/builds/20080611/opencore/zope/Products/CMFPlone/CatalogTool.py", line 395, in _increment_counter self._counter.change(1) File "/home/rob/topp/14000/builds/20080611/opencore/lib/zope/lib/python/BTrees/Length.py", line 55, in change self.value += delta File "/home/rob/topp/14000/builds/20080611/opencore/lib/zope/lib/python/ZODB/Connection.py", line 890, in register self._register(obj) File "/home/rob/topp/14000/builds/20080611/opencore/lib/zope/lib/python/ZODB/Connection.py", line 900, in _register self.transaction_manager.get().join(self) File "/home/rob/topp/14000/builds/20080611/opencore/lib/zope/lib/python/transaction/_transaction.py", line 273, in join self._prior_operation_failed() # doesn't return File "/home/rob/topp/14000/builds/20080611/opencore/lib/zope/lib/python/transaction/_transaction.py", line 267, in _prior_operation_failed raise TransactionFailedError("An operation previously failed, " TransactionFailedError: An operation previously failed, with traceback:
File "/home/rob/topp/14000/builds/20080611/opencore/lib/zope/lib/python/ZServer/PubCore/ZServerPublisher.py", line 25, in __init__ response=b) File "/home/rob/topp/14000/builds/20080611/opencore/lib/zope/lib/python/ZPublisher/Publish.py", line 401, in publish_module environ, debug, request, response) File "/home/rob/topp/14000/builds/20080611/opencore/lib/zope/lib/python/ZPublisher/Publish.py", line 202, in publish_module_standard response = publish(request, module_name, after_list, debug=debug) File "/home/rob/topp/14000/builds/20080611/opencore/lib/zope/lib/python/ZPublisher/Publish.py", line 119, in publish request, bind=1) File "/home/rob/topp/14000/builds/20080611/opencore/lib/zope/lib/python/ZPublisher/mapply.py", line 88, in mapply if debug is not None: return debug(object,args,context) File "/home/rob/topp/14000/builds/20080611/opencore/lib/zope/lib/python/ZPublisher/Publish.py", line 42, in call_object result=apply(object,args) # Type s<cr> to step into published object. File "/home/rob/topp/14000/builds/20080611/opencore/lib/zope/lib/python/Products/ZCatalog/ZCatalog.py", line 260, in manage_catalogReindex self.refreshCatalog(clear=1, pghandler=handler) File "/home/rob/topp/14000/builds/20080611/opencore/lib/zope/lib/python/Products/ZCatalog/ZCatalog.py", line 296, in refreshCatalog self.catalog_object(obj, p, pghandler=pghandler) File "/home/rob/topp/14000/builds/20080611/opencore/zope/Products/CMFPlone/CatalogTool.py", line 385, in catalog_object update_metadata, pghandler=pghandler) File "/home/rob/topp/14000/builds/20080611/opencore/zope/Products/CacheSetup/patch.py", line 96, in catalog_object uid, idxs, update_metadata, pghandler) File "/home/rob/topp/14000/builds/20080611/opencore/zope/Products/CacheSetup/patch_utils.py", line 6, in call return getattr(self, PATTERN % __name__)(*args, **kw) File "/home/rob/topp/14000/builds/20080611/opencore/lib/zope/lib/python/Products/ZCatalog/ZCatalog.py", line 560, in catalog_object transaction.savepoint(optimistic=True) File "/home/rob/topp/14000/builds/20080611/opencore/lib/zope/lib/python/transaction/_manager.py", line 110, in savepoint return self.get().savepoint(optimistic) File "/home/rob/topp/14000/builds/20080611/opencore/lib/zope/lib/python/transaction/_transaction.py", line 312, in savepoint self._saveAndRaiseCommitishError() # reraises! File "/home/rob/topp/14000/builds/20080611/opencore/lib/zope/lib/python/transaction/_transaction.py", line 422, in _saveAndRaiseCommitishError t, v, tb = self._saveAndGetCommitishError() File "/home/rob/topp/14000/builds/20080611/opencore/lib/zope/lib/python/transaction/_transaction.py", line 309, in savepoint savepoint = Savepoint(self, optimistic, *self._resources) File "/home/rob/topp/14000/builds/20080611/opencore/lib/zope/lib/python/transaction/_transaction.py", line 737, in __init__ savepoint = savepoint() File "/home/rob/topp/14000/builds/20080611/opencore/lib/zope/lib/python/ZODB/Connection.py", line 1046, in savepoint self._commit(None) File "/home/rob/topp/14000/builds/20080611/opencore/lib/zope/lib/python/ZODB/Connection.py", line 555, in _commit self._store_objects(ObjectWriter(obj), transaction) File "/home/rob/topp/14000/builds/20080611/opencore/lib/zope/lib/python/ZODB/Connection.py", line 582, in _store_objects p = writer.serialize(obj) # This calls __getstate__ of obj File "/home/rob/topp/14000/builds/20080611/opencore/lib/zope/lib/python/ZODB/serialize.py", line 407, in serialize return self._dump(meta, obj.__getstate__()) File "/home/rob/topp/14000/builds/20080611/opencore/lib/zope/lib/python/ZODB/serialize.py", line 416, in _dump self._p.dump(state) File "copy_reg.py", line 69, in _reduce_ex raise TypeError, "can't pickle %s objects" % base.__name__ TypeError: can't pickle instancemethod objects
_______________________________________________ Zope maillist - Zope@zope.org http://mail.zope.org/mailman/listinfo/zope** No cross posts or HTML encoding! ** (Related lists - http://mail.zope.org/mailman/listinfo/zope-announcehttp://mail.zope.org/mail... )
Ross Patterson wrote:
Rob Miller <ra@burningman.com> writes:
hi,
i'm trying to perform a ZCatalog.refreshCatalog() on a catalog with over 29,000 indexed objects. it churns for a good long time, and eventually fails with a long set of tracebacks, of which i've included a sample at the end of this message.
i think i understand the gist of the issue... it's trying to write an object (probably a CatalogBrain) to the database, but this object's __dict__ contains a value that is of type instancemethod, which isn't allowed for persistent objects.
the problem is that i can't figure out which specific objects are causing the problem. i've used pdb.post_mortem to get a debug prompt way down in the traceback, but the code goes in and out of C modules, so i'm missing a lot of what's happening. and when i interactively peek at the objects that are being indexed when the error happens, there doesn't seem to be anything wrong, and i can index the objects w/ no problem. i've even tried dropping the subtransaction threshold down to 1, so it will try to commit a savepoint after every object, but none of the objects being indexed seemed to have any problems.
i CAN verify that the instancemethod that is causing the problem renders like this:
<bound method SessionDataManager.getSessionData of <SessionDataManager at /session_data_manager>>
even that hasn't proven enough for me to concretely identify the source of the problem, though.
i've been working on this for a full day already, and am not sure how to proceed. does anyone have any debugging tips that might help me figure out what, exactly, is causing the reindex attempts to blow up?
thanks!
Can you get a pdb.post_mortem prompt at the actual ZODB/serialize.py:416 error or only at transaction/_transaction.py:267 where some sort of previous error is handled?
yes, i put the post_mortem around the "transaction.savepoint" call at line 559 of Products/ZCatalog/ZCatalog.py. this is the place where the error is happening, but it's where the subtransaction threshold has been reached, so IIUC the error could be caused by any of the objects in the subtransaction.
If the former, I often find it informative to step up to ZODB/serialize.py:407 where obj.__getstate__() is called and find out what obj is. Is it the same object every time? If not, is it of the same type every time?
right. as long as the subtxn threshold number is the same, then the object is the same. but if i change the subtxn threshold, then the object will be different. as i said, i even tried reducing the subtxn threshold to '1', so, assuming my understanding is correct, this would be triggered after every object. it took many hours to get to my debug prompt; when i did, the obj was FileAttachment object that didn't seem to have any problems. i was able to interactively index the object from the pdb prompt, and even commit the transaction, w/ no problems.
A next step can also be to put a pdb.set_trace() at transaction/_transaction.py:340 in the register() method such that it's is only called when the offending object is added to the transaction.
i'll give this a shot, thx.
Hope some of that helps,
even just having someone to discuss it with is helpful, for my sanity at least... ;-) thx. -r
Rob Miller <ra@burningman.com> writes:
Ross Patterson wrote:
Rob Miller <ra@burningman.com> writes:
hi,
i'm trying to perform a ZCatalog.refreshCatalog() on a catalog with over 29,000 indexed objects. it churns for a good long time, and eventually fails with a long set of tracebacks, of which i've included a sample at the end of this message.
i think i understand the gist of the issue... it's trying to write an object (probably a CatalogBrain) to the database, but this object's __dict__ contains a value that is of type instancemethod, which isn't allowed for persistent objects.
the problem is that i can't figure out which specific objects are causing the problem. i've used pdb.post_mortem to get a debug prompt way down in the traceback, but the code goes in and out of C modules, so i'm missing a lot of what's happening. and when i interactively peek at the objects that are being indexed when the error happens, there doesn't seem to be anything wrong, and i can index the objects w/ no problem. i've even tried dropping the subtransaction threshold down to 1, so it will try to commit a savepoint after every object, but none of the objects being indexed seemed to have any problems.
i CAN verify that the instancemethod that is causing the problem renders like this:
<bound method SessionDataManager.getSessionData of <SessionDataManager at /session_data_manager>>
even that hasn't proven enough for me to concretely identify the source of the problem, though.
i've been working on this for a full day already, and am not sure how to proceed. does anyone have any debugging tips that might help me figure out what, exactly, is causing the reindex attempts to blow up?
thanks!
Can you get a pdb.post_mortem prompt at the actual ZODB/serialize.py:416 error or only at transaction/_transaction.py:267 where some sort of previous error is handled?
yes, i put the post_mortem around the "transaction.savepoint" call at line 559 of Products/ZCatalog/ZCatalog.py. this is the place where the error is happening, but it's where the subtransaction threshold has been reached, so IIUC the error could be caused by any of the objects in the subtransaction.
Then it seems like you're not getting at the actual pickle error and thus aren't looking at the object whose __getstate__ returns the offending instance method. If you have enough memory, try running the refreshCatalog with subtransactions disabled to get the *actual* pickle error.
If the former, I often find it informative to step up to ZODB/serialize.py:407 where obj.__getstate__() is called and find out what obj is. Is it the same object every time? If not, is it of the same type every time?
right. as long as the subtxn threshold number is the same, then the object is the same. but if i change the subtxn threshold, then the object will be different. as i said, i even tried reducing the subtxn threshold to '1', so, assuming my understanding is correct, this would be triggered after every object. it took many hours to get to my debug prompt; when i did, the obj was FileAttachment object that didn't seem to have any problems. i was able to interactively index the object from the pdb prompt, and even commit the transaction, w/ no problems.
The actual error of your TB is the error that savepoint raises when a previous error has occurred. So changing the subtransaction threshold just changes which object is being indexed when the savepoint *happens* to be run and notices that an error has been raised for a previous object in the savepoint. At least, that's my read of it.
A next step can also be to put a pdb.set_trace() at transaction/_transaction.py:340 in the register() method such that it's is only called when the offending object is added to the transaction.
i'll give this a shot, thx.
Hope some of that helps,
even just having someone to discuss it with is helpful, for my sanity at least... ;-)
Well, then I'll have to enjoy your sanity vicariously. :) Ross
Rob Miller wrote at 2008-6-17 15:47 -0700:
... Traceback (most recent call last): .... "/home/rob/topp/14000/builds/20080611/opencore/lib/zope/lib/python/ZODB/serialize.py", line 407, in serialize return self._dump(meta, obj.__getstate__()) File "/home/rob/topp/14000/builds/20080611/opencore/lib/zope/lib/python/ZODB/serialize.py", line 416, in _dump self._p.dump(state) File "copy_reg.py", line 69, in _reduce_ex raise TypeError, "can't pickle %s objects" % base.__name__ TypeError: can't pickle instancemethod objects
Reproduce the problem in an interactive Python interpreter ("bin/zopectl debug" on *nix; alternatives for Win*). Call "pdb.pm()" (or probably better "dm.pdb.zpdb.pm()" ("dm.pdb" can be found on PyPI)) and go up two call frames. Look at "obj". With a bit of looks, you see which objects this is and where it comes from. -- Dieter
Rob Miller wrote:
hi,
i'm trying to perform a ZCatalog.refreshCatalog() on a catalog with over 29,000 indexed objects. it churns for a good long time, and eventually fails with a long set of tracebacks, of which i've included a sample at the end of this message.
i think i understand the gist of the issue... it's trying to write an object (probably a CatalogBrain) to the database, but this object's __dict__ contains a value that is of type instancemethod, which isn't allowed for persistent objects.
the problem is that i can't figure out which specific objects are causing the problem. i've used pdb.post_mortem to get a debug prompt way down in the traceback, but the code goes in and out of C modules, so i'm missing a lot of what's happening. and when i interactively peek at the objects that are being indexed when the error happens, there doesn't seem to be anything wrong, and i can index the objects w/ no problem. i've even tried dropping the subtransaction threshold down to 1, so it will try to commit a savepoint after every object, but none of the objects being indexed seemed to have any problems.
okay, after leaving this for a few days, i came back to it and managed to work it out. for posterity's sake, what ended up working was that i added an explicit transaction.commit() after every object reindex, wrapped in a try: except, like so: --- src/Zope/lib/python/Products/ZCatalog/ZCatalog.py 2007-10-29 06:09:30.000000000 -0700 +++ lib/zope/lib/python/Products/ZCatalog/ZCatalog.py 2008-06-24 10:47:49.000000000 -0700 @@ -294,6 +294,11 @@ if obj is not None: try: self.catalog_object(obj, p, pghandler=pghandler) + try: + transaction.commit() + except: + import sys, pdb + pdb.post_mortem(sys.exc_info()[2]) except ConflictError: raise except: this made the reindex take a ridiculously long time, and it leaves the catalog in an inconsistent state (i.e. it should only be done on a copy of the database, one that you can throw away), but it did in the end reveal to me which record was causing the problem. the problematic record ended up being a ghosted catalog entry that happened to share the same name as a view. when the catalog tried to look up the object by its path (via unrestrictedTraverse), the view object was returned. thanks for the help! -r
participants (3)
-
Dieter Maurer -
Rob Miller -
Ross Patterson