We were able to reproduce it. A "stat" on all three servers looks identical:

[zk: <ip:port>(CONNECTED) 0] stat /zkrsm
cZxid = 9
ctime = Mon Nov 01 13:01:57 PDT 2010
mZxid = 9
mtime = Mon Nov 01 13:01:57 PDT 2010
pZxid = 12884902218
cversion = 177
dataVersion = 0
aclVersion = 0
ephemeralOwner = 0
dataLength = 0
numChildren = 177

Creating a sequential node through the command line also fails:

[zk: <ip:port>(CONNECTED) 1] create -s /zkrsm/0000000000000000_record testdata
Node already exists: /zkrsm/0000000000000000_record

One potentially interesting thing is that numChildren above is 177, though I have sequence numbers on that record prefix up to 214 or so. There seem to be some gaps though -- I thin "ls /zkrsm" only shows about 177. Not sure if that's relevant or not.

Thanks,

Jeremy

On 11/01/2010 12:06 PM, Jeremy Stribling wrote:
Thanks for the reply. It happened every time we called create, not just once. More than that, we tried restarting each of the nodes in the system (one-by-one), including the new master, and the problem continued.

Unfortunately we cleaned everything up, and it's not in that state anymore. We haven't yet tried to reproduce, but I will try and report back if I can get any "cversion" info.

Jeremy

On 11/01/2010 11:33 AM, Patrick Hunt wrote:
Hi Jeremy, this sounds like a bug to me, I don't think you should be
getting the nodeexists when the sequence flag is set.

Looking at the code briefly we use the parent's "cversion"
(incremented each time the child list is changed, added/removed).

Did you see this error each time you called create, or just once? If
you look at the cversion in the Stat of the znode "/zkrsm" on each of
the servers what does it show? You can use the java CLI to connect to
each of your servers and access this information. It would be
interesting to see if the data was out of sync only for a short period
of time, or forever. Is this repeatable?

Ben/Flavio do you see anything here?

Patrick

On Thu, Oct 28, 2010 at 6:06 PM, Jeremy Stribling<st...@nicira.com> wrote:
HI everyone,

Is there any situation in which creating a new ZK node with the SEQUENCE
flag should result in a "node exists" error?  I'm seeing this happening
after a failure of a ZK node that appeared to have been the master; when the new master takes over, my app is unable to create a new SEQUENCE node under
an existing parent node.  I'm using Zookeeper 3.2.2.

Here's a representative log snippet:

--------------------------
3050756 [ProcessThread:-1] TRACE
org.apache.zookeeper.server.PrepRequestProcessor  -
:Psessionid:0x12bf518350f0001 type:create cxid:0x4cca0691
zxid:0xfffffffffffffffe txntype:unknown /zkrsm/0000000000000000_record
3050756 [ProcessThread:-1] WARN
org.apache.zookeeper.server.PrepRequestProcessor  - Got exception when
processing sessionid:0x12bf518350f0001 type:create cxid:0x4cca0691
zxid:0xfffffffffffffffe txntype:unknown n/a
org.apache.zookeeper.KeeperException$NodeExistsException: KeeperErrorCode =
NodeExists
        at
org.apache.zookeeper.server.PrepRequestProcessor.pRequest(PrepRequestProcessor.java:245)
        at
org.apache.zookeeper.server.PrepRequestProcessor.run(PrepRequestProcessor.java:114)
3050756 [ProcessThread:-1] DEBUG
org.apache.zookeeper.server.quorum.CommitProcessor - Processing request:: sessionid:0x12bf518350f0001 type:create cxid:0x4cca0691 zxid:0x50000027e
txntype:-1 n/a
3050756 [ProcessThread:-1] DEBUG org.apache.zookeeper.server.quorum.Leader
  - Proposing:: sessionid:0x12bf518350f0001 type:create cxid:0x4cca0691
zxid:0x50000027e txntype:-1 n/a
3050756 [SyncThread:0] TRACE org.apache.zookeeper.server.quorum.Leader -
Ack zxid: 0x50000027e
3050757 [SyncThread:0] TRACE org.apache.zookeeper.server.quorum.Leader -
outstanding proposal: 0x50000027e
3050757 [SyncThread:0] TRACE org.apache.zookeeper.server.quorum.Leader -
outstanding proposals all
3050757 [SyncThread:0] DEBUG org.apache.zookeeper.server.quorum.Leader -
Count for zxid: 0x50000027e is 1
3050757 [FollowerHandler-/172.16.0.28:48776] TRACE
org.apache.zookeeper.server.quorum.Leader  - Ack zxid: 0x50000027e
3050757 [FollowerHandler-/172.16.0.28:48776] TRACE
org.apache.zookeeper.server.quorum.Leader  - outstanding proposal:
0x50000027e
3050757 [FollowerHandler-/172.16.0.28:48776] TRACE
org.apache.zookeeper.server.quorum.Leader  - outstanding proposals all
3050757 [FollowerHandler-/172.16.0.28:48776] DEBUG
org.apache.zookeeper.server.quorum.Leader - Count for zxid: 0x50000027e is
2
3050757 [FollowerHandler-/172.16.0.28:48776] DEBUG
org.apache.zookeeper.server.quorum.CommitProcessor - Committing request:: sessionid:0x12bf518350f0001 type:create cxid:0x4cca0691 zxid:0x50000027e
txntype:-1 n/a
3050757 [CommitProcessor:0] DEBUG
org.apache.zookeeper.server.FinalRequestProcessor - Processing request:: sessionid:0x12bf518350f0001 type:create cxid:0x4cca0691 zxid:0x50000027e
txntype:-1 n/a
3050757 [CommitProcessor:0] TRACE
org.apache.zookeeper.server.FinalRequestProcessor  -
:Esessionid:0x12bf518350f0001 type:create cxid:0x4cca0691 zxid:0x50000027e
txntype:-1 n/a
3050757 [FollowerHandler-/172.16.0.28:41062] TRACE
org.apache.zookeeper.server.quorum.Leader  - Ack zxid: 0x50000027e
3050757 [FollowerHandler-/172.16.0.28:41062] TRACE
org.apache.zookeeper.server.quorum.Leader  - outstanding proposals all
3050757 [FollowerHandler-/172.16.0.28:41062] DEBUG
org.apache.zookeeper.server.quorum.Leader  - outstanding is 0
--------------------------

I'm still a n00b at understanding ZK log messages, so maybe there's
something obvious going on. I looked in the JIRA and did my best to search the mailing list archives, but couldn't find anything related to this. Any
ideas?  Thanks very much,

Jeremy

Reply via email to