This week, we saw a potential bug with zookeeper 3.3.4. In an attempt toadding a separate disk for zookeeper transaction logs, our SysOps teamthrew new disks at all the zookeeper servers in our production cluster ataround the same time. Right after this, we saw degraded performance on ourzookeeper cluster. And yes, I agree that this degraded behavior is expectedand we could've done a better job and upgraded one server at a time. Although, the observed impact was that ephemeral nodes got deleted withoutsession expiration on the zookeeper clients.

Let me try and describe what I've observed from the Kafka and ZK serverlogs -

Kafka client has a session established with ZK, say Session A, that it hasbeen using successfully. At the time of the degraded ZK performance issue,Session A expires. Kafka's ZkClient tries to establish another session withZK. After 9 seconds, it establishes a session, say Session B and tries touse it for creating a znode. This operation fails with a NodeExists errorsince another session, say session C, has created that znode. This isconsidered OK since ZkClient retries an operation transparently if it gets disconnected and sometimes you can get NodeExists. But then later, sessionC expires and hence the ephemeral node is deleted from ZK. This leads tounexpected errors in Kafka since its session, Session B, is still valid andhence it expects the znode to be there. The issue is that session C wasestablished, created the znode and expired, without the zookeeper client onKafka ever knowing about it.

I've attempted to serialize the sequence of events according to relevantdata from txn and log4j logs below.

On Thu, Apr 26, 2012 at 11:17 AM, Neha Narkhede <[EMAIL PROTECTED]> wrote:> Hi,>> This week, we saw a potential bug with zookeeper 3.3.4. In an attempt to> adding a separate disk for zookeeper transaction logs, our SysOps team> threw new disks at all the zookeeper servers in our production cluster at> around the same time. Right after this, we saw degraded performance on our> zookeeper cluster. And yes, I agree that this degraded behavior is expected> and we could've done a better job and upgraded one server at a time. Al> though, the observed impact was that ephemeral nodes got deleted without> session expiration on the zookeeper clients.>> Let me try and describe what I've observed from the Kafka and ZK server> logs ->> Kafka client has a session established with ZK, say Session A, that it has> been using successfully. At the time of the degraded ZK performance issue,> Session A expires. Kafka's ZkClient tries to establish another session with> ZK. After 9 seconds, it establishes a session, say Session B and tries to> use it for creating a znode. This operation fails with a NodeExists error> since another session, say session C, has created that znode. This is> considered OK since ZkClient retries an operation transparently if it gets> disconnected and sometimes you can get NodeExists. But then later, session> C expires and hence the ephemeral node is deleted from ZK. This leads to> unexpected errors in Kafka since its session, Session B, is still valid and> hence it expects the znode to be there. The issue is that session C was> established, created the znode and expired, without the zookeeper client on> Kafka ever knowing about it.>> I've attempted to serialize the sequence of events according to relevant> data from txn and log4j logs below.>> Leader zookeeper is srvr-90.prod>> Session A = 0x9367a5bd54c9078> Session B = 0x8367a5bd75ea01b> Session C = 0x8367a5bd75e9dd5> The znode being created > /consumers/kafka-DR/ids/kafka-DR_srvr-0193.prod-1334094226781-6a7f1b76> zookeeper session timeout is 6 seconds>>> 1.>> Original session A, 0x9367a5bd54c9078 expired at 20:33:09 with zxid> 0x31189e02d8 on the leader.> 2.>> Leader processed session termination for 0x9367a5bd54c9078 at> 20:33.09.000.> 3.>> Leader realizes client has closed socket, so it closes NIOServerCnxn for> 0x9367a5bd54c9078 at 20:33:09.009> 4.>> Kafka client gets Expired state at 20:33:09.161> 5.>> Kafka client starts re-registering its node in ZK at 20:33.09.209 with> socket connection established to srvr-89.prod> 6.>> Client session 0x0 times out several times, reconnects to another server> and repeats session establishment request.> 7.>> On the leader's txn log, session B 0x8367a5bd75ea01b is created at> 20:33.17-> 1.>> time:4/23/12 20:33:17 PM PDT session:0x8367a5bd75ea01b cxid:0x0> zxid:0x31189e1985 type:createSession timeOut:6000> 8.>> On zk server srvr-89, session B 0x8367a5bd75ea01b is established -> 1.>> zk.log4j.2012-04-23-srvr-89.gz:> 1.>> 2012-04-23 20:33:17,987 - INFO> [CommitProcessor:8:NIOServerCnxn@1580] - Established session> 0x8367a5bd75ea01b with negotiated timeout 6000 for client /> 172.17.87.173:52865> 2.>> 2012/04/23 20:33:18.022 INFO [ZkClient] [main-EventThread] [kafka]> zookeeper state changed (SyncConnected)> 9.>> At 20:33:18.022 on Kafka client, session is established with session id> 0x8367a5bd75ea01b> 1.>> 2012/04/23 20:33:18.022 INFO [ClientCnxn]> [main-SendThread(srvr-89.prod:12913)] [kafka] Session establishment> complete on server srvr-89.prod/172.17.229.105:12913, sessionid > 0x8367a5bd75ea01b, negotiated timeout = 6000> 10.>> Kafka zookeeper client fails to create znode at 20

+

Patrick Hunt 2012-04-26, 18:21

NEW: Monitor These Apps!

All projects made searchable here are trademarks of the Apache Software Foundation.
Service operated by Sematext