[
https://issues.apache.org/jira/browse/ZOOKEEPER-634?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=12792942#action_12792942
]
Andrew Reynhout commented on ZOOKEEPER-634:
-------------------------------------------
Epilogue: I spoke too soon, I guess I had been staring at the data for too long.
Some parts of the Stat struct were getting repointed or overwritten by the time
the values were shuttled into the Ruby glue. Aside from the variation between
32b and 64b, the variations were repeatable (always the same changes, always
the same wrong data), so I thought I saw something that wasn't there.
Properly duping the struct before passing to the Ruby thread resolved it.
> some elements of struct Stat have incorrect values when returned
> asynchronously
> -------------------------------------------------------------------------------
>
> Key: ZOOKEEPER-634
> URL: https://issues.apache.org/jira/browse/ZOOKEEPER-634
> Project: Zookeeper
> Issue Type: Bug
> Components: c client
> Affects Versions: 3.2.1
> Environment: OSX 10.5, 10.6 (32b and 64b, respectively)
> Reporter: Andrew Reynhout
> Priority: Minor
>
> I'm working on Ruby bindings for ZK (3.2.2) via the C API. This involves
> some painful kludgery due to MRI Ruby's threading model, but I believe this
> bug report is valid:
> Some of the elements of Stat structs, when returned via the C client, have
> values inconsistent with the synchronous call, zkCli output, and
> expectations. E.g.:
> {noformat:title=zkCli command line}
> $ zk/bin/zkCli.sh -server localhost:2182 set /lala lala234
> Connecting to localhost:2182
> WATCHER::
> WatchedEvent: Server state change. New state: SyncConnected
> cZxid = 3
> ctime = Sat Dec 19 14:32:03 EST 2009
> mZxid = 69
> mtime = Sat Dec 19 15:31:46 EST 2009
> pZxid = 3
> cversion = 0
> dataVersion = 4
> aclVersion = 0
> ephemeralOwner = 0
> dataLength = 7
> numChildren = 0
> {noformat}
> {noformat:title=Ruby script + verbose ZK log output}
> 2009-12-19 15:31:48,952:45753(0x751000):zoo_de...@process_completions@1902:
> Switching on cptr->completion_type (async)
> 2009-12-19 15:31:48,952:45753(0x751000):zoo_de...@process_completions@1916:
> Calling COMPLETION_STAT for xid=4b2d3837 rc=0
> 2009-12-19 15:31:48,952:45753(0x751000):zoo_de...@process_completions@1949:
> --- PRE ruby callback.
> -----------------------
> &res.stat 0x00750e30
> .czxid 3
> .mzxid 69
> .ctime 1261251123149
> .mtime 1261254706180
> .version 4
> .cversion 0
> .aversion 0
> .ephemeralOwner 0
> .dataLength 7
> .numChildren 0
> .pzxid 3
> =======================
> 2009-12-19
> 15:31:48,952:45753(0x751000):zoo_de...@ruby_stat_completion_wrapper@1702: ---
> creating ruby thread.
> 2009-12-19
> 15:31:48,952:45753(0x7ee000):zoo_de...@ruby_stat_completion_wrapper_2@1685:
> --- invoking ruby callback.
> -----------------------
> cb->dc 0x002fe000
> cb->rc 0
> cb->ctx 0x01a03870
> cb->stat 0x00750e30
> ->czxid 3
> ->mzxid 69
> ->ctime 1261251123149
> ->mtime 140735387442616
> ->version 0
> ->cversion 0
> ->aversion 27264392
> ->ephemeralOwner 4302638816
> ->dataLength -2100901903
> ->numChildren 32767
> ->pzxid 3
> =======================
> 2009-12-19
> 15:31:48,952:45753(0x7ee000):zoo_de...@ruby_stat_completion_wrapper_2@1687:
> --- callback returned, freeing struct.
> 2009-12-19
> 15:31:48,952:45753(0x7ee000):zoo_de...@ruby_stat_completion_wrapper_2@1689:
> --- struct freed.
> sync returned #<ZooKeeperFFI::Stat:0x000001013783d0>
> async callback.return_code 0
> attr ?? sync async
> ---- -- ---- -----
> czxid OK 3 3
> mzxid OK 69 69
> ctime OK 1261251123149 1261251123149
> mtime -- 1261254706180 140735387442616
> version -- 4 0
> cversion OK 0 0
> aversion -- 0 27264392
> ephemeralOwner -- 0 4302638816
> dataLength -- 7 -2100901903
> numChildren -- 0 32767
> pzxid OK 3 3
> 2009-12-19 15:31:49,052:45753(0x6ce000):zoo_de...@do_io@316: IO thread
> terminated
> 2009-12-19 15:31:49,052:45753(0x751000):zoo_de...@do_completion@335:
> completion thread terminated
> 2009-12-19 15:31:49,052:45753(0x705f3be0):zoo_i...@zookeeper_close@2407:
> Closing zookeeper session 125a86bdc640020 to [127.0.0.1:2182]
> {noformat}
> The last set of lines, above, are output from my Ruby code, comparing the
> differences between sync and async calls. I added the LOG_DEBUG in
> zookeeper.c to dump the contents of res.stat before it gets shipped off to
> Ruby...as you can see, the LOG_DEBUG values match the values in the async
> Ruby call, but they're wrong.
> I've currently only tested on OSX 10.5 (32bit) and 10.6 (64bit), but
> sometimes different elements are wrong on each. I can get a comprehensive
> list if it's useful, but as examples:
> {noformat:title=data variation examples}
> ## aexists
> # ctime (int64_t):
> # 32b OK
> # 64b OK
> # dataLength (int32_t):
> # 32b OK
> # 64b NG (== -2100901903 instead of 10)
> ## aget
> # ctime (int64_t):
> # 32b OK
> # 64b NG (== 0 instead of something unixtimey e.g. 1261251123149)
> # dataLength (int32_t):
> # 32b NG (== -1856148083 instead of 10)
> # 64b OK
> ## aset
> # ctime (int64_t):
> # 32b OK
> # 64b OK
> # dataLength (int32_t):
> # 32b OK
> # 64b NG (== -2100901903 instead of 10)
> {noformat}
> Lastly, a snippet of my changes to zookeeper.c, hopefully showing that I
> haven't done any harm to the data. Note that I'm also seeing similar data
> variations for COMPLETION_DATA, which also returns a Stat struct. I haven't
> finished the Ruby code for COMPLETION_ACLLIST (again, returns a Stat), so the
> same issue might arise there as well.
> I realize that hacking the ZK C API is not a great way to build a foreign
> binding. :(
> {code:title=src/c/src/zookeeper.c}
> case COMPLETION_STAT:
> LOG_DEBUG(("Calling COMPLETION_STAT for xid=%x
> rc=%d",cptr->xid,rc));
> if (rc) {
> //cptr->c.stat_result(rc, 0, cptr->data);
> ruby_stat_completion_wrapper(cptr->c.stat_result, rc, 0,
> (void *)cptr->data);
> } else {
> struct SetDataResponse res;
> deserialize_SetDataResponse(ia, "reply", &res);
> LOG_DEBUG(("--- PRE ruby callback.\n\
> -----------------------\n\
> &res.stat 0x%08x\n\
> .czxid %ld\n\
> .mzxid %ld\n\
> .ctime %ld\n\
> .mtime %ld\n\
> .version %d\n\
> .cversion %d\n\
> .aversion %d\n\
> .ephemeralOwner %ld\n\
> .dataLength %d\n\
> .numChildren %d\n\
> .pzxid %ld\n\
> =======================",
> &res.stat,
> res.stat.czxid, res.stat.mzxid, res.stat.ctime, res.stat.mtime,
> res.stat.version, res.stat.cversion, res.stat.aversion,
> res.stat.ephemeralOwner, res.stat.dataLength, res.stat.numChildren,
> res.stat.pzxid ));
> //cptr->c.stat_result(rc, &res.stat, cptr->data);
> ruby_stat_completion_wrapper(cptr->c.stat_result, rc,
> &res.stat, (void *)cptr->data);
> deallocate_SetDataResponse(&res);
> }
> break;
> {code}
--
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.
