| *** Jan_Garaj3_ has joined #zope | 00:16 | |
| *** J1m_ has quit IRC | 00:17 | |
| *** Jan_Garaj3 has quit IRC | 00:17 | |
| *** Jan_Garaj3_ is now known as Jan_Garaj3 | 00:17 | |
| *** J1m_ has joined #zope | 00:18 | |
| *** TresEquis has joined #zope | 00:31 | |
| *** TresEquis has quit IRC | 00:51 | |
| *** menesis has quit IRC | 01:05 | |
| *** J1m_ has quit IRC | 01:08 | |
| *** Jan_Garaj3 has quit IRC | 01:52 | |
| *** nueces has quit IRC | 02:12 | |
| *** menesis has joined #zope | 06:12 | |
| *** menesis has quit IRC | 06:34 | |
| *** bosim has joined #zope | 08:01 | |
| *** bosim has quit IRC | 08:02 | |
| *** bosim has joined #zope | 08:03 | |
| *** __mac__ has joined #zope | 08:17 | |
| *** __mac__ has quit IRC | 08:26 | |
| *** __mac__ has joined #zope | 08:33 | |
| *** yvl has joined #zope | 09:00 | |
| *** agroszer has joined #zope | 09:23 | |
| *** alecm has quit IRC | 09:46 | |
| *** Jan_Garaj3 has joined #zope | 09:48 | |
| *** tisto has joined #zope | 09:58 | |
| *** River_Rat is now known as RiverRat | 10:09 | |
| *** MrTango has joined #zope | 10:58 | |
| *** maurits has joined #zope | 12:02 | |
| *** Jan_Garaj3 has quit IRC | 12:05 | |
| *** jakke has joined #zope | 12:28 | |
| jakke | Hi Guys, anyone has input on this question: https://mail.zope.org/pipermail/zope-dev/2014-December/046517.html ? | 12:29 |
|---|---|---|
| jakke | about 2 different versions of _zope_proxy_proxy.c files being used in zope? | 12:29 |
| jakke | thx! | 12:29 |
| mgedmin | it's probably an oversight | 12:39 |
| mgedmin | I'd be tempted to look at the histories of the files and contact the contributors with this questionh | 12:40 |
| mgedmin | ha ha https://github.com/zopefoundation/zope.proxy/blob/master/src/zope/proxy/_zope_proxy_proxy.c#L15-L25 | 12:40 |
| mgedmin | yes they're supposed to be synchronized | 12:41 |
| mgedmin | do you want to file a bug? | 12:43 |
| mgedmin | jakke: ^ | 12:43 |
| mgedmin | incidentally, zope.container has one fix (pypy support) that didn't make it to zope.proxy, not the other way around, AFAICS | 12:44 |
| jakke | mgedmin, don't know, still digging into a very strange error | 12:49 |
| jakke | loading an object returns an empty object instead of object with data | 12:49 |
| mgedmin | are you accessing __dict__ directly? | 12:50 |
| jakke | and during the diving into that issue, we found this mismatch | 12:50 |
| jakke | no, it's all standard zope code | 12:50 |
| jakke | objects stored in __annotations__, which is a BTree | 12:50 |
| mgedmin | hmm... are you storing LocationProxy/ContainedProxy wrappers in the ZODB? | 12:51 |
| jakke | apparently that's what happening with plone portlets yes | 12:52 |
| jakke | they inherit in their chain from zope.contained | 12:53 |
| mgedmin | I remember having some trouble when we tried to store unicode strings in a container | 12:54 |
| mgedmin | they got wrapped in a ContainedProxy, which then got wrapped in a SecurityProxy | 12:54 |
| mgedmin | and in a new transaction when we loaded those and tried to construct form fields dynamically we ended up having to removeSecurityProxy() from the string before we could actually use it as a field title | 12:55 |
| do3cc | the zope-cmf mailing list just exploded in activity ;-) | 12:55 |
| mgedmin | which was a bit of a wtf until we figured out where those security-proxied strings came from | 12:55 |
| jakke | that's an interesting track, check wether the previous version contained unicode :) | 12:57 |
| mgedmin | the wtf was because normally strings are rocks and have no proxies, and therefore they have no security declarations and therefore if you get a security-proxied string somehow you can't do anything with it | 12:58 |
| mgedmin | which is probably different from your problem | 12:58 |
| mgedmin | when you say "an empty object", what do you mean, exactly? | 12:59 |
| mgedmin | what's the class/type of the object? | 12:59 |
| mgedmin | is it wrapped in any proxies? | 12:59 |
| mgedmin | what does the pickle data look like? | 12:59 |
| jakke | well, it's plone code, we've seen in now in portlets and collections | 13:00 |
| mgedmin | zodbbrowser might or might not be helpful here -- I'd use it | 13:00 |
| mgedmin | (assuming it works with plone) | 13:00 |
| jakke | so we get __annotations__, wich are a BTrees.OOBTree.OOBTree | 13:01 |
| jakke | and one of the objects stored in that BTree, is a valid object, but it contains no attributes | 13:02 |
| jakke | pickle looks healthy, bin/instance debug I can access the objects as well | 13:02 |
| jakke | compared the pickle of a "broken" portlet of that with a 'functional portlet', and they look the same, except for the attributes in one object | 13:03 |
| mgedmin | what's the class of the object? does it differ from type(obj)? what does it inherit? | 13:03 |
| mgedmin | are all attributes missing? some of them? what are their names? | 13:04 |
| jakke | all are missing | 13:04 |
| jakke | checking for class and type now | 13:04 |
| mgedmin | when you say "missing", do you mean you get AttributeError? | 13:05 |
| mgedmin | default values from class-level attributes? | 13:05 |
| mgedmin | empty-looking __dict__ in a REPL prompt? | 13:05 |
| jakke | last thing: empty looking __dict__ | 13:05 |
| jakke | and you get the default class attribute values if you try to acces these | 13:06 |
| mgedmin | have you called obj._p_activate() before looking at obj.__dict__? | 13:06 |
| mgedmin | ah, ok, you have | 13:06 |
| jakke | not explicitly | 13:06 |
| mgedmin | right | 13:06 |
| mgedmin | so the state pickle is missing attributes? interesting | 13:06 |
| mgedmin | I'd definitely want to see the history of that particular object with zodbbrowser | 13:07 |
| jakke | yups, and only for 1 object as far as we've seen | 13:07 |
| jakke | not that much of a history, depends on when the packing has been done | 13:07 |
| jakke | some only have 1 history object, being the "new state" itself, which is weird in itself | 13:07 |
| mgedmin | well, if they've been packed, that's what you'd see | 13:08 |
| jakke | cause if it's a new state, I'd expect the previous state to be there as well | 13:08 |
| mgedmin | is there DC metadata? | 13:08 |
| jakke | DC as in Dublin Core? | 13:08 |
| mgedmin | yes | 13:08 |
| mgedmin | I'm just wondering if the timestamp of the oldest (the only) transaction touching this object matches its creation time in DC metadata | 13:09 |
| mgedmin | if yes, we know something | 13:09 |
| mgedmin | if no, older states got lost during packing | 13:09 |
| jakke | apparently there is | 13:09 |
| mgedmin | "new state" in zodbbrowser's history doesn't mean much; iirc I'm diffing the unpickled state against an empty dict to show the very first revision | 13:10 |
| mgedmin | don't read too much into the wording (or, alternatively, send me patches to improve it ;) | 13:10 |
| jakke | not using zodbbrowser, I load it from instance/debug and db.history calls :) | 13:11 |
| mgedmin | ah, cool | 13:11 |
| mgedmin | I used to know how to do that | 13:11 |
| mgedmin | (and then got tired of the manularity and convinced a junior programmer to write zodbbrowser for me) | 13:11 |
| jakke | :D, I know it now, because I'm diving way deeper than I wanted too, probably forget about it when this task is finished ;-) | 13:12 |
| jakke | we compared a "new empty state" with an brand new object of the same type, empty, and it's the same | 13:13 |
| mgedmin | is this related to the _zope_proxy_proxy.c thing or something unrelated? | 13:14 |
| jakke | related | 13:14 |
| jakke | the object that gets "initialized empty" is a zope.contained object, that's how we boiled it down to the _zope_proxy_proxy.c | 13:15 |
| jakke | don't know if the cause is there, we've just noticed the mismatch | 13:15 |
| mgedmin | are you running on pypy? | 13:16 |
| jakke | no, standard python2.7 | 13:17 |
| mgedmin | then there are no meaningful differences between the two .c files | 13:17 |
| jakke | good to know, thanks :) | 13:17 |
| mgedmin | is the state dict complex? does it have mutable non-persistent subobjects? | 13:18 |
| jakke | no, everything should be persisted | 13:19 |
| jakke | ok mgedmin, I gatherd some context for you | 13:37 |
| jakke | http://pastebin.com/XPrtxkqz | 13:37 |
| jakke | the blc is the broken one, the wlc is the working one | 13:37 |
| jakke | as you can see is type() and __class__ the same, but one has an address, the odther doesn't | 13:37 |
| mgedmin | and type(blc_data['navigation'].__annotations__['plone.portlets.assignmentsettings'].data) is ...? | 13:38 |
| jakke | and the broken one has an empty dict, compared to a "working one" | 13:38 |
| jakke | >>> type(blc_data['navigation'].__annotations__) | 13:38 |
| jakke | <type 'BTrees.OOBTree.OOBTree'> | 13:38 |
| mgedmin | that's not what I asked about | 13:39 |
| jakke | right, sec | 13:39 |
| jakke | <class 'persistent.mapping.PersistentMapping'> | 13:40 |
| jakke | same goes for the working | 13:40 |
| mgedmin | hmmm | 13:40 |
| mgedmin | type(blc_data['navigation']) versus type(wlcdata['navigation']) ? | 13:41 |
| *** J1m has joined #zope | 13:41 | |
| jakke | both the same: <class 'plone.app.portlets.portlets.navigation.Assignment'> | 13:42 |
| mgedmin | how can they have different repr()s? | 13:42 |
| jakke | beacuse the wlcdata['navigation'].id has a value: u'navigation' | 13:43 |
| jakke | and the blc_data['navigation'].id is '' | 13:44 |
| mgedmin | oh, there's an if in the __repr__? | 13:44 |
| jakke | it's been some time since I've checked there | 13:44 |
| *** LeoRochael has joined #zope | 13:45 | |
| jakke | but id is a wrapper for __name__, and repr uses __name__ | 13:45 |
| jakke | I suppose there is kind of a lookup based upon the __name__ or its presence, but I don't remember exactly anymore | 13:45 |
| mgedmin | I see: https://github.com/zopefoundation/Zope/blob/master/src/OFS/SimpleItem.py#L351 | 13:46 |
| jakke | but that's quite normal behavior for objects that lost their __name__ or id, I've seen that with other objects too | 13:46 |
| mgedmin | I'm not used to debugging Zope 2 :) | 13:46 |
| jakke | we're kind of stuck to it with plone ;-) | 13:47 |
| mgedmin | so you've narrowed it down to broken data in the zodb | 13:47 |
| jakke | well, yes and no | 13:48 |
| jakke | it's stored broken in zodb, that much is for sure | 13:48 |
| jakke | we still don't know yet why it gets broken | 13:48 |
| mgedmin | right, the question is: what code breaks it | 13:48 |
| mgedmin | is it the initial transaction that adds it? a subsequent packing? | 13:48 |
| mgedmin | is this filestorage? relstorage? | 13:48 |
| mgedmin | do you have a way to reproduce the issue (i.e. add a new working portlet and make it break)? | 13:49 |
| jakke | what we're thinking of now, is that the loading of the object goes bad, and a "backup path" loads an empty object, instead of a data packed object, and that the transaction machinery detects a "change in object" and stores the new one | 13:49 |
| jakke | no, we cannot reproduce it, that's a major issue, we just "wait and see" and do post mortem analysis | 13:49 |
| jakke | and it goes together with a "document_view by None" in the undo log, but that doesn't add much info either | 13:50 |
| jakke | packing is not related | 13:50 |
| mgedmin | document_view, interesting | 13:50 |
| jakke | it's relstorage | 13:50 |
| mgedmin | I'd really like to see this with zodbbrowser | 13:50 |
| mgedmin | like look at the oid of blc_data['navigation'].__annotations__['plone.portlets.assignmentsettings'] | 13:51 |
| mgedmin | does it change? | 13:51 |
| mgedmin | between the working version and the broken version, I mean | 13:51 |
| mgedmin | (first you'd have to find an object that used to work and then broke, but has all the history) | 13:51 |
| jakke | often I only have 1 version in the history, which I think is fairly change | 13:51 |
| jakke | but I'll doublecheck | 13:52 |
| jakke | so it could be a new object as well, point is that portlets aren't changed that often | 13:52 |
| mgedmin | well, actually, track the entire chain from the topmost thing | 13:52 |
| jakke | so it could be packed as well, but if it's an update, at least 2 versions should be visible in the history | 13:52 |
| mgedmin | also, the empty __name__, is that a bug? | 13:52 |
| jakke | it's a symptom, don't know what causes it | 13:53 |
| jakke | a colleague assumed it's because loading objects from zodb is not done via the constructor but via new() and then add the data to the object | 13:54 |
| jakke | haven't touched that bit of code yet though | 13:55 |
| mgedmin | that's how most pickles work anyway | 13:55 |
| jakke | but if you do a new() and fail to add data to it, it could explain the loss of __name__ too | 13:55 |
| mgedmin | a failure in __setstate__ would show up in the logs, though | 13:55 |
| jakke | grepping the logs, but I don't think we've seen an error there | 13:58 |
| mgedmin | does zodbbrowser even work with relstorage? | 13:58 |
| jakke | I have an export on filestorage, so no problem :) | 13:59 |
| mgedmin | does it include history? :) | 13:59 |
| jakke | should yes, it's supposed to be a full export | 13:59 |
| mgedmin | "full" is nicely non-specific | 14:00 |
| jakke | :D | 14:00 |
| jakke | I'll have a look, adding it to buildout now | 14:00 |
| *** LeoRochael has quit IRC | 14:04 | |
| jakke | according to my logs about the issue, the export seems to contain history, since I've been querying it | 14:06 |
| mgedmin | cool | 14:07 |
| jakke | but still I haven't check if it's a new object or not, have to have a look | 14:08 |
| jakke | see if there is a previous version of the containing object available | 14:08 |
| jakke | and then check the _p_oid for both "broken objects" | 14:08 |
| jakke | both versions of the broken in the end object I mean | 14:09 |
| jakke | packed, darn | 14:10 |
| mgedmin | maybe it was broken from the beginning? | 14:13 |
| jakke | no, for sure not | 14:17 |
| jakke | users complained when their navigation "all of a sudden" was broken | 14:17 |
| mgedmin | any correlation with server restarts? | 14:18 |
| jakke | maybe, if I'm lucky, I can find it back in an old old old backup, but I doubt that | 14:19 |
| jakke | no, seems to be a correlation with number of visits though | 14:19 |
| jakke | the start of the academic year always causes more visits, and this year also more broken portlets, | 14:19 |
| jakke | now everything is back to normal, and the frequency is down | 14:19 |
| mgedmin | hmmm | 14:19 |
| mgedmin | broken conflict resolution code? | 14:20 |
| jakke | servers have a standard restart cycle every month or so | 14:20 |
| jakke | mgedmin, I like your thinking! | 14:21 |
| mgedmin | still, that means portlets get modified during a view operation | 14:22 |
| jakke | yes | 14:22 |
| mgedmin | which would be inefficient, if not outright wrong | 14:22 |
| jakke | I'll get you a log pastebin | 14:22 |
| jakke | http://pastebin.com/J1WAK7vh | 14:23 |
| jakke | it's not a realated log, but it seems a good point to look into | 14:24 |
| mgedmin | iirc oobtrees have some interesting conflict resolution code | 14:24 |
| mgedmin | that might be wrong for some application semantics | 14:24 |
| jakke | it goes fine in 90+ % of the cases | 14:25 |
| mgedmin | http://docs.zope.org/zope3/Code/ZODB/ConflictResolution.txt/index.html mentions some dangers with situations where you have multiple persistent objects that have to be kept in sync | 14:26 |
| jakke | btrees in zodb is, according to some document I read some time ago, also not always the better choice | 14:29 |
| jakke | zodbbrowser does not want to cooperate | 14:31 |
| mgedmin | :( | 14:31 |
| jakke | ttributeError: class MultiHook has no attribute '__repr__' | 14:31 |
| mgedmin | mind pasting the traceback to https://github.com/mgedmin/zodbbrowser/issues? | 14:32 |
| mgedmin | I thought I wrapped all repr() calls with try/except, but apparently missed some :/ | 14:32 |
| jakke | what name do you want me to give it? | 14:33 |
| mgedmin | "AttributeError: class MultiHook has no attribute '__repr__'" is a fine issue title | 14:33 |
| *** menesis has joined #zope | 14:35 | |
| jakke | there you are :) | 14:36 |
| jakke | it used to work though, I've used zodbbrowser before | 14:36 |
| jakke | ok, I'll look into those conflict errors at the time of the messy transaction, could give us some more clues | 14:39 |
| jakke | would be awesome | 14:39 |
| jakke | no luck, no conflict resolution logs for that timeframe :( | 14:55 |
| *** giacomos has joined #zope | 15:06 | |
| *** J1m has quit IRC | 15:24 | |
| *** J1m has joined #zope | 15:47 | |
| *** J1m has quit IRC | 15:51 | |
| *** J1m_ has joined #zope | 15:57 | |
| *** J1m has joined #zope | 16:07 | |
| *** J1m_ has quit IRC | 16:10 | |
| *** agroszer has quit IRC | 16:29 | |
| mgedmin | jakke, zodbbrowser 0.11.2 fixes that AttributeError | 16:35 |
| *** bosim has quit IRC | 17:15 | |
| *** alecm has joined #zope | 17:17 | |
| *** __mac__ has quit IRC | 17:38 | |
| *** __mac__ has joined #zope | 17:51 | |
| kiorky | 7.98.178.82 | 18:14 |
| jakke | awesome mgedmin!, I'll try after the weekend, now is time to go home :) | 18:18 |
| jakke | started buildout already, so it's waiting for me on monday morning | 18:19 |
| *** yvl has quit IRC | 18:51 | |
| *** giacomos has quit IRC | 19:15 | |
| *** __mac__ has quit IRC | 19:49 | |
| *** Jan_Garaj3 has joined #zope | 20:01 | |
| *** nueces has joined #zope | 20:10 | |
| *** Jan_Garaj3 has quit IRC | 20:20 | |
| *** tisto has quit IRC | 20:22 | |
| *** __mac__ has joined #zope | 20:23 | |
| *** __mac__ has quit IRC | 20:47 | |
| *** __mac__ has joined #zope | 21:15 | |
| *** __mac__ has quit IRC | 21:26 | |
| *** maurits has quit IRC | 21:30 | |
| *** __mac__ has joined #zope | 21:34 | |
| *** __mac__ has quit IRC | 21:41 | |
| *** __mac__ has joined #zope | 21:52 | |
| *** __mac__ has quit IRC | 21:53 | |
| *** J1m has quit IRC | 21:54 | |
| *** J1m has joined #zope | 22:44 | |
| *** Jan_Garaj3 has joined #zope | 22:48 | |
| *** MrTango has quit IRC | 22:59 | |
| *** kiorky has quit IRC | 23:32 | |
| *** kiorky has joined #zope | 23:33 | |
| *** kiorky has quit IRC | 23:44 | |
| *** kiorky has joined #zope | 23:44 | |
Generated by irclog2html.py 2.15.1 by Marius Gedminas - find it at mg.pov.lt!