Re: Creating ephemeral nodes: First time returns ZNODEEXISTS

Patrick Hunt Mon, 31 Aug 2009 21:16:44 -0700

Hi Leonard,

Between 00:43:23,035 and 00:43:23,157 I see client session0x123730dbe6e0001 get 15 "node exists" exceptions in a row. Are youexpecting this? (ie are you attempting to create this node 15 times in arow or is this unexpected? I can't tell from the client snippet youincluded)

Are you using the multithreaded version of the client or the singlethreaded version? It would be useful if you could create a JIRA andattach the following:

https://issues.apache.org/jira/browse/ZOOKEEPER

1) create the jira and attach the client & server logs
2) attach zoo.cfg file
3) if you can attach a copy of your client code that would
be interesting as well. In your email we see the create, however it
would be interesting to see the session creation call you are doing
and how the client is initialized.

I would also suggest that you examine the cli_mt or cli_st client that'sincluded with the release (build cli.c in src/c/src).

Use this client to connect to your server and examine the node that yourcreate_ephemeral_znode is operating on. For example try an get (create,etc...) call and check the stat information (if ephemeralOwner is zerothen it's not an ephemeral node for example). You can also take a lookat the code for cli.c (or the tests) for some examples of how toinitialize/run a mt/st client process and compare it to your own. Btw,we suggest that users use the multi-threaded client whenever possible,unless ST is specifically required.


Patrick

Leonard Cuff wrote:

I've just upgraded to ZooKeeper 3.2.0, testing the fix for ephemeral nodes
disappearing correctly when the client process dies. I'm seeing some
unexpected behavior:

The first time I call zoo_create() to create an ephemeral node, it returns
ZNODEEXISTS, even if the node didn't previously exist. It successfully
creates the znode, and the znode is then available to write to. If I delete
the node and call zoo_create() a second time, it correctly returns ZOK.

I'm wondering if anyone else is seeing the same thing. I've spent quite a
bit of time checking my client code, and I'm pretty convinced this is
happening as described.

I see lots of exceptions in the log file. I'll append my client code, and
the log file.

Thanks for any and all input.

Leonard

create_ephemeral_znode ( char *znode ) {

    int         result;

    result = zoo_create ( zh, znode, NULL, 0, &ZOO_OPEN_ACL_UNSAFE,
ZOO_EPHEMERAL , NULL, 0 );

    if ( result == ZOK  ) {
        vcm_log_info ( logger, "ephemeral status node '%s' created
successfuly", znode);
        return SUCCESS;

}

    if ( result == ZNODEEXISTS ) {

        vcm_log_debug ( logger, "ephemeral status node '%s' already exists.
Will delete and recreate", znode);


        result = zoo_delete  (zh, znode, ANY_VERSION );
        vcm_log_info ( logger, "delete ephemeral node '%s' returned %d
(%s)", znode, result, zerror ( result ) );

        if ( result != ZOK && result != ZNONODE ) {
            vcm_log_error ( logger, "Couldn't delete ephemeral node '%s'
because %d (%s) %s at %d",
                    znode, result, zerror ( result ) , __FILE__, __LINE__);

}result = zoo_create ( zh, znode, NULL, 0, &ZOO_OPEN_ACL_UNSAFE,

ZOO_EPHEMERAL , NULL, 0 );

        if ( result == ZOK  ) {
            vcm_log_info ( logger, "ephemeral status node '%s' created
successfuly", znode);
            return SUCCESS;

}vcm_log_warn ( logger, "Can't create '%s' (err: %d : %s), %s at %d",

                znode, result  , zerror ( result ), __FILE__, __LINE__);

        return ZOO_PATH_CREATION_FAILED;

}

    vcm_log_warn ( logger, "Can't create '%s' (err: %d : %s), %s at %d",
                znode, result  , zerror ( result ), __FILE__, __LINE__);

    return ZOO_PATH_CREATION_FAILED;

}


--------------------------------------


JMX enabled by default
Starting zookeeper ...
zoopid file is /vcm/home/zoo/zookeeper-3.2.0/snap/zookeeper_server.pid
STARTED
2009-09-01 00:42:43,535 - INFO  [main:quorumpeercon...@80] - Reading
configuration from:
/vcm/home/sandbox/ticket_161758-1/vcm/apps/zookeeper-3.2.0/bin/../conf/zoo.c
fg
2009-09-01 00:42:43,539 - WARN  [main:quorumpeerm...@104] - Either no config
or no quorum defined in config, running  in standalone mode
2009-09-01 00:42:43,560 - INFO  [main:quorumpeercon...@80] - Reading
configuration from:
/vcm/home/sandbox/ticket_161758-1/vcm/apps/zookeeper-3.2.0/bin/../conf/zoo.c
fg
2009-09-01 00:42:43,562 - INFO  [main:zookeeperserverm...@94] - Starting
server
2009-09-01 00:42:43,573 - INFO  [main:environm...@97] - Server
environment:zookeeper.version=3.2.0-790261, built on 07/01/2009 16:49 GMT
2009-09-01 00:42:43,574 - INFO  [main:environm...@97] - Server
environment:host.name=ind104.an.dev.fastclick.net
2009-09-01 00:42:43,574 - INFO  [main:environm...@97] - Server
environment:java.version=1.6.0_14
2009-09-01 00:42:43,575 - INFO  [main:environm...@97] - Server
environment:java.vendor=Sun Microsystems Inc.
2009-09-01 00:42:43,576 - INFO  [main:environm...@97] - Server
environment:java.home=/home/lcuff/java/jre1.6.0_14
2009-09-01 00:42:43,577 - INFO  [main:environm...@97] - Server
environment:java.class.path=/vcm/home/sandbox/ticket_161758-1/vcm/apps/zooke
eper-3.2.0/bin/../conf::/vcm/home/sandbox/ticket_161758-1/vcm/apps/zookeeper
-3.2.0/bin/../zookeeper-3.2.0.jar:/vcm/home/sandbox/ticket_161758-1/vcm/apps
/zookeeper-3.2.0/bin/../lib/jdiff-1.0.9.jar:/vcm/home/sandbox/ticket_161758-
1/vcm/apps/zookeeper-3.2.0/bin/../lib/jline-0.9.94.jar:/vcm/home/sandbox/tic
ket_161758-1/vcm/apps/zookeeper-3.2.0/bin/../lib/junit-4.4.jar:/vcm/home/san
dbox/ticket_161758-1/vcm/apps/zookeeper-3.2.0/bin/../lib/log4j-1.2.15.jar:/v
cm/home/sandbox/ticket_161758-1/vcm/apps/zookeeper-3.2.0/bin/../lib/xerces-1
.4.4.jar:/vcm/home/sandbox/ticket_161758-1/vcm/apps/zookeeper-3.2.0/bin/../s
rc/java/lib/jdiff-1.0.9.jar:/vcm/home/sandbox/ticket_161758-1/vcm/apps/zooke
eper-3.2.0/bin/../src/java/lib/jline-0.9.94.jar:/vcm/home/sandbox/ticket_161
758-1/vcm/apps/zookeeper-3.2.0/bin/../src/java/lib/junit-4.4.jar:/vcm/home/s
andbox/ticket_161758-1/vcm/apps/zookeeper-3.2.0/bin/../src/java/lib/log4j-1.
2.15.jar:/vcm/home/sandbox/ticket_161758-1/vcm/apps/zookeeper-3.2.0/bin/../s
rc/java/lib/xerces-1.4.4.jar
2009-09-01 00:42:43,577 - INFO  [main:environm...@97] - Server
environment:java.library.path=/home/lcuff/java/jre1.6.0_14/lib/amd64/server:
/home/lcuff/java/jre1.6.0_14/lib/amd64:/home/lcuff/java/jre1.6.0_14/../lib/a
md64:/vcm/home/zoo/zookeeper-3.1.1/src/c/.libs:/vcm/home/zoo/zookeeper-3.1.1
/src/c/.libs:/vcm/home/zoo/zookeeper-3.1.1/src/c/.libs:/vcm/home/zoo/zookeep
er-3.1.1/src/c/.libs:/vcm/home/zoo/zookeeper-3.1.1/src/c/.libs:/vcm/home/zoo
/zookeeper-3.1.1/src/c/.libs:/vcm/home/zoo/zookeeper-3.1.1/src/c/.libs:/vcm/
home/zoo/zookeeper-3.1.1/src/c/.libs:/vcm/home/zoo/zookeeper-3.1.1/src/c/.li
bs:/vcm/home/zoo/zookeeper-3.1.1/src/c/.libs:/vcm/home/sandbox/ticket_161758
-1/vcm/apps/apr-util/lib:/vcm/home/sandbox/ticket_161758-1/vcm/apps/apr/lib:
/vcm/home/sandbox/ticket_161758-1/vcm/apps/cunit/lib:/vcm/home/sandbox/ticke
t_161758-1/vcm/apps/curl-7.18.0/lib:/vcm/home/sandbox/ticket_161758-1/vcm/ap
ps/libevent/lib:/vcm/home/sandbox/ticket_161758-1/vcm/apps/libmemcached/lib:
/vcm/home/sandbox/ticket_161758-1/vcm/apps/spread/lib:/vcm/home/sandbox/tick
et_161758-1/vcm/apps/python/lib:/usr/java/packages/lib/amd64:/lib:/usr/lib
2009-09-01 00:42:43,578 - INFO  [main:environm...@97] - Server
environment:java.io.tmpdir=/tmp
2009-09-01 00:42:43,579 - INFO  [main:environm...@97] - Server
environment:java.compiler=<NA>
2009-09-01 00:42:43,580 - INFO  [main:environm...@97] - Server
environment:os.name=Linux
2009-09-01 00:42:43,580 - INFO  [main:environm...@97] - Server
environment:os.arch=amd64
2009-09-01 00:42:43,581 - INFO  [main:environm...@97] - Server
environment:os.version=2.6.9-55.ELsmp
2009-09-01 00:42:43,582 - INFO  [main:environm...@97] - Server
environment:user.name=vcm
2009-09-01 00:42:43,585 - INFO  [main:environm...@97] - Server
environment:user.home=/vcm/home
2009-09-01 00:42:43,586 - INFO  [main:environm...@97] - Server
environment:user.dir=/vcm/home/sandbox/ticket_161758-1/vcm/apps/zookeeper-3.
2.0/bin
2009-09-01 00:42:43,642 - INFO  [main:files...@81] - Reading snapshot
/vcm/home/zoo/zookeeper-3.2.0/snap/version-2/snapshot.23d
2009-09-01 00:42:43,687 - INFO  [main:filetxnsnap...@208] - Snapshotting:
2a2
2009-09-01 00:43:04,609 - INFO
[NIOServerCxn.Factory:2181:nioserverc...@586] - Connected to
/192.168.68.107:50461 lastZxid 0
2009-09-01 00:43:04,611 - INFO
[NIOServerCxn.Factory:2181:nioserverc...@618] - Creating new session
0x123730dbe6e0000
2009-09-01 00:43:04,667 - INFO  [SyncThread:0:nioserverc...@967] - Finished
init of 0x123730dbe6e0000 valid:true
2009-09-01 00:43:10,540 - WARN
[NIOServerCxn.Factory:2181:nioserverc...@497] - Exception causing close of
session 0x123730dbe6e0000 due to java.io.IOException: Read error
2009-09-01 00:43:10,541 - INFO
[NIOServerCxn.Factory:2181:nioserverc...@836] - closing
session:0x123730dbe6e0000 NIOServerCnxn:
java.nio.channels.SocketChannel[connected local=/192.168.68.107:2181
remote=/192.168.68.107:50461]
2009-09-01 00:43:18,025 - INFO
[NIOServerCxn.Factory:2181:nioserverc...@586] - Connected to
/192.168.68.107:50463 lastZxid 0
2009-09-01 00:43:18,026 - INFO
[NIOServerCxn.Factory:2181:nioserverc...@618] - Creating new session
0x123730dbe6e0001
2009-09-01 00:43:18,056 - INFO  [SyncThread:0:nioserverc...@967] - Finished
init of 0x123730dbe6e0001 valid:true
2009-09-01 00:43:20,002 - INFO  [SessionTracker:sessiontrackeri...@133] -
Expiring session 0x123730dbe6e0000
2009-09-01 00:43:20,003 - INFO  [SessionTracker:zookeeperser...@325] -
Expiring session 0x123730dbe6e0000
2009-09-01 00:43:20,003 - INFO  [ProcessThread:-1:preprequestproces...@384]
- Processed session termination request for id: 0x123730dbe6e0000
2009-09-01 00:43:23,035 - WARN  [ProcessThread:-1:preprequestproces...@402]
- Got exception when processing sessionid:0x123730dbe6e0001 type:create
cxid:0x4a9c6e27 zxid:0xfffffffffffffffe txntype:unknown n/a
org.apache.zookeeper.KeeperException$NodeExistsException: KeeperErrorCode =
NodeExists

atorg.apache.zookeeper.server.PrepRequestProcessor.pRequest(PrepRequestProcess

or.java:245)