-
Ephemeral node deleted for unexpired sessions in Zookeeper 3.3.4Neha Narkhede 2012-04-26, 18:17
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-sr
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-sr
+
Patrick Hunt 2012-04-26, 18:21
