You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@zookeeper.apache.org by "Andrew Reynhout (JIRA)" <ji...@apache.org> on 2009/12/19 23:14:18 UTC
[jira] Created: (ZOOKEEPER-634) some elements of struct Stat have
incorrect values when returned asynchronously
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_DEBUG@process_completions@1902: Switching on cptr->completion_type (async)
2009-12-19 15:31:48,952:45753(0x751000):ZOO_DEBUG@process_completions@1916: Calling COMPLETION_STAT for xid=4b2d3837 rc=0
2009-12-19 15:31:48,952:45753(0x751000):ZOO_DEBUG@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_DEBUG@ruby_stat_completion_wrapper@1702: --- creating ruby thread.
2009-12-19 15:31:48,952:45753(0x7ee000):ZOO_DEBUG@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_DEBUG@ruby_stat_completion_wrapper_2@1687: --- callback returned, freeing struct.
2009-12-19 15:31:48,952:45753(0x7ee000):ZOO_DEBUG@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_DEBUG@do_io@316: IO thread terminated
2009-12-19 15:31:49,052:45753(0x751000):ZOO_DEBUG@do_completion@335: completion thread terminated
2009-12-19 15:31:49,052:45753(0x705f3be0):ZOO_INFO@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.
[jira] Resolved: (ZOOKEEPER-634) some elements of struct Stat have
incorrect values when returned asynchronously
Posted by "Andrew Reynhout (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/ZOOKEEPER-634?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Andrew Reynhout resolved ZOOKEEPER-634.
---------------------------------------
Resolution: Invalid
Sorry, some of the data included is invalid. I'll repost when confirmed, if necessary. :-/
> 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_DEBUG@process_completions@1902: Switching on cptr->completion_type (async)
> 2009-12-19 15:31:48,952:45753(0x751000):ZOO_DEBUG@process_completions@1916: Calling COMPLETION_STAT for xid=4b2d3837 rc=0
> 2009-12-19 15:31:48,952:45753(0x751000):ZOO_DEBUG@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_DEBUG@ruby_stat_completion_wrapper@1702: --- creating ruby thread.
> 2009-12-19 15:31:48,952:45753(0x7ee000):ZOO_DEBUG@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_DEBUG@ruby_stat_completion_wrapper_2@1687: --- callback returned, freeing struct.
> 2009-12-19 15:31:48,952:45753(0x7ee000):ZOO_DEBUG@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_DEBUG@do_io@316: IO thread terminated
> 2009-12-19 15:31:49,052:45753(0x751000):ZOO_DEBUG@do_completion@335: completion thread terminated
> 2009-12-19 15:31:49,052:45753(0x705f3be0):ZOO_INFO@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.
[jira] Commented: (ZOOKEEPER-634) some elements of struct Stat have
incorrect values when returned asynchronously
Posted by "Andrew Reynhout (JIRA)" <ji...@apache.org>.
[ 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_DEBUG@process_completions@1902: Switching on cptr->completion_type (async)
> 2009-12-19 15:31:48,952:45753(0x751000):ZOO_DEBUG@process_completions@1916: Calling COMPLETION_STAT for xid=4b2d3837 rc=0
> 2009-12-19 15:31:48,952:45753(0x751000):ZOO_DEBUG@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_DEBUG@ruby_stat_completion_wrapper@1702: --- creating ruby thread.
> 2009-12-19 15:31:48,952:45753(0x7ee000):ZOO_DEBUG@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_DEBUG@ruby_stat_completion_wrapper_2@1687: --- callback returned, freeing struct.
> 2009-12-19 15:31:48,952:45753(0x7ee000):ZOO_DEBUG@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_DEBUG@do_io@316: IO thread terminated
> 2009-12-19 15:31:49,052:45753(0x751000):ZOO_DEBUG@do_completion@335: completion thread terminated
> 2009-12-19 15:31:49,052:45753(0x705f3be0):ZOO_INFO@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.
[jira] Commented: (ZOOKEEPER-634) some elements of struct Stat have
incorrect values when returned asynchronously
Posted by "Patrick Hunt (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/ZOOKEEPER-634?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=12796840#action_12796840 ]
Patrick Hunt commented on ZOOKEEPER-634:
----------------------------------------
Please consider contributing your ruby binding, we'd love to include it in the release along with python, perl, etc...
> 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_DEBUG@process_completions@1902: Switching on cptr->completion_type (async)
> 2009-12-19 15:31:48,952:45753(0x751000):ZOO_DEBUG@process_completions@1916: Calling COMPLETION_STAT for xid=4b2d3837 rc=0
> 2009-12-19 15:31:48,952:45753(0x751000):ZOO_DEBUG@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_DEBUG@ruby_stat_completion_wrapper@1702: --- creating ruby thread.
> 2009-12-19 15:31:48,952:45753(0x7ee000):ZOO_DEBUG@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_DEBUG@ruby_stat_completion_wrapper_2@1687: --- callback returned, freeing struct.
> 2009-12-19 15:31:48,952:45753(0x7ee000):ZOO_DEBUG@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_DEBUG@do_io@316: IO thread terminated
> 2009-12-19 15:31:49,052:45753(0x751000):ZOO_DEBUG@do_completion@335: completion thread terminated
> 2009-12-19 15:31:49,052:45753(0x705f3be0):ZOO_INFO@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.