zookeeper-user mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Patrick Hunt <ph...@apache.org>
Subject Re: Ephemeral node deleted for unexpired sessions in Zookeeper 3.3.4
Date Thu, 26 Apr 2012 18:21:25 GMT
Please create a jira for this, attach the logs, config, etc... Thanks.

Patrick

On Thu, Apr 26, 2012 at 11:17 AM, Neha Narkhede <neha.narkhede@gmail.com> 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:33.18.358 with
>   Session B due to NodeExists exception
>   1.
>
>      2012/04/23 20:33:18.358 INFO [ZkUtils$]
>      [ZkClient-EventThread-81-srvr-85.prod:12913,srvr-88.prod:12913,srvr-84.prod:12913,srvr-89.prod:12913,srvr-90.prod:12913/kafka]
>      [kafka]
>      /consumers/kafka-DR/ids/kafka-DR_srvr-0193.prod-1334094226781-6a7f1b76
>      exists with value { "firehoseActivity": 1,"firehoseUpdates":
>      1,"GenericSearchEvent": 1,"firehoseShares": 1,"ProfileViewEvent": 1 }
>      during connection loss; this is ok
>       11.
>
>   Kafka client gets Disconnected and SyncConnected with session B at
>   20:33:26
>   1.
>
>      2012/04/23 20:33:26.669 INFO [ClientCnxn]
>      [main-SendThread(srvr-89.prod:12913)] [kafka] Client session timed out,
>      have not heard from server in 4000ms for sessionid 0x8367a5bd75ea01b,
>      closing socket connection and attempting reconnect
>      2.
>
>      2012/04/23 20:33:26.769 INFO [ZkClient] [main-EventThread] [kafka]
>      zookeeper state changed (Disconnected)
>      3.
>
>      2012/04/23 20:33:27.471 INFO [ClientCnxn]
>      [main-SendThread(srvr-89.prod:12913)] [kafka] Opening socket
> connection to
>      server srvr-88.prod/172.17.229.104:12913
>      4.
>
>      2012/04/23 20:33:27.531 INFO [ClientCnxn]
>      [main-SendThread(srvr-88.prod:12913)] [kafka] Socket connection
> established
>      to srvr-88.prod/172.17.229.104:12913, initiating session
>      5.
>
>      2012/04/23 20:33:28.419 INFO [ClientCnxn]
>      [main-SendThread(srvr-88.prod:12913)] [kafka] Session establishment
>      complete on server srvr-88.prod/172.17.229.104:12913, sessionid =
>      0x8367a5bd75ea01b, negotiated timeout = 6000
>       12.
>
>   Kafka client runs into NoNode exception at 20:33:30
>   2012/04/23 20:33:30.538 INFO [ZookeeperConsumerConnector]
>   [kafka-DR_srvr-0193.prod-1334094226781-6a7f1b76_watcher_executor] [kafka]
>   exception during rebalance
>
> At around the same time, the session C (0x8367a5bd75e9dd5) gets established
> and also creates the node and later expires.
>
>   1.
>
>   On leader srvr-90, session C gets created
>   1.
>
>      time:4/23/12 20:33:09 PM PDT session:0x8367a5bd75e9dd5 cxid:0x0
>      zxid:0x31189e0709 type:createSession timeOut:6000
>       2.
>
>   On server srvr-89, session gets created at 20:33.13.930
>   1.
>
>      zk.log4j.2012-04-23-srvr-89.gz:2012-04-23 20:33:13,930 - INFO
>       [CommitProcessor:8:NIOServerCnxn@1580] - Established session
>      0x8367a5bd75e9dd5 with negotiated timeout 6000 for client /
>      172.17.87.173:52802
>      2.
>
>      zk.log4j.2012-04-23-srvr-89.gz:2012-04-23 20:33:17,667 - WARN
>       [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:12913:NIOServerCnxn@634] -
>      EndOfStreamException: Unable to read additional data from client
> sessionid
>      0x8367a5bd75e9dd5, likely client has closed socket
>      3.
>
>      zk.log4j.2012-04-23-srvr-89.gz:2012-04-23 20:33:17,668 - INFO
>       [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:12913:NIOServerCnxn@1435] -
>      Closed socket connection for client /172.17.87.173:52802 which had
>      sessionid 0x8367a5bd75e9dd5
>       3.
>
>   3. Session B creates the znode -
>   1.
>
>      time:4/23/12 20:33:17 PM PDT session:0x8367a5bd75e9dd5 cxid:0x1
>      zxid:0x31189e1464 type:create acl:[31,s{'world,'anyone}] ephemeral:true
>      path:/kafka/consumers/kafka-DR/ids/kafka-DR_ech3-app0193.prod-1334094226781-6a7f1b76
>      data:7B202266697265686F73654163746976697479223A20312C2266697265686F736555706461746573223A20312C2247656E657269635365617263684576656E74223A20312C2266697265686F7365536861726573223A20312C2250726F66696C65566965774576656E74223A2031207D
>
>      2.
>
>      Session B gets closed on the leader
>       4.
>
>   Session C expires on leader
>   1.
>
>      time:4/23/12 20:33:29 PM PDT session:0x8367a5bd75e9dd5 cxid:0x0
>      zxid:0x31189e27d0 type:closeSession
>
>
> Since the leader processes create session and create znode for Session C
> first, shouldn't it be the session id that gets returned to the client as
> create session response ?
> Does this sound like a bug ?
>
> *TL;DR*
>
> Ephemeral nodes got deleted for unexpired sessions on ZK 3.3.4.
> The kafka and zookeeper server log4j logs (timestamps are in UTC) as well
> as the leader's txn log are
> here.<http://people.apache.org/%7Enehanarkhede/kafka-misc/zookeeper-outage-2012-04-23/kafka-zk-bug-2012-04-23.tar.gz>
>
> Will appreciate any help with debugging this.
>
> Thanks,
> Neha

Mime
View raw message