Details
-
Bug
-
Status: Resolved
-
Major
-
Resolution: Auto Closed
-
0.8.2.1
-
None
-
None
-
zk version 3.4.6,
CentOS 6, 2.6.32-504.1.3.el6.x86_64
Description
On several occasions, we've seen our process enter a cycle of: zk session expiry; new session creation; rebalancing activity; pause during which nothing is heard from the zk server. Sometimes, the reconnections are successful, elements are pulled from Kafka, but then disconnection and reconnection occurs shortly thereafter, causing OOMs when new elements are pulled in (although OOMs were not seen in the two cases attached as examples). Restarting the process that uses the zk client resolved the problems in both cases.
This behavior was seen on 09/08 and 09/11 – the attached 'full' logs show all logs entries minus entries particular to our application. For 09/08, the time span is 2015-09-08T12:52:06.069-04:00 to 2015-09-08T13:14:48.250-04:00; for 11/08, the time span is between 2015-09-11T01:38:17.000-04:00 to 2015-09-11T07:44:47.124-04:00. The digest logs are the result of retaining only error and warning entries, and entries containing any of: "begin rebalancing", "end rebalancing", "timed", and "zookeeper state". For the 09/11 digest logs, entries from the kafka.network.Processor logger are also excised for clarity. Unfortunately, debug logging was not enabled during these events.
The 09/11 case shows repeated cycles of session expiry, followed by rebalancing activity, followed by a pause during which nothing is heard from the zk server, followed by a session timeout. A stable session seems to have been established at 2015-09-11T04:13:47.140-04:00, but messages of the form "I wrote this conflicted ephemeral node [{"version":1,"subscription":
{"binlogs_mailchimp_us2":100},"pattern":"static","timestamp":"1441959227564"}] at /consumers/prologue-second-stage_prod_us2/ids/prologue-second-stage_prod_us2_app01.c1.prologue.prod.atl01.rsglab.com-1441812334972-b967b718 a while back in a different session, hence I will backoff for this node to be deleted by Zookeeper and retry" were logged out repeatedly until we restarted the process after 2015-09-11T07:44:47.124-04:00, which marks the final entry in the log.
The 09/08 case is a little more straightforward than the 09/11 case, in that a stable session was not established prior to our restarting the process.
It's perhaps also noteworthy that in the 09/08 case, two timeouts for the same session are seen during a single rebalance, at 2015-09-08T12:52:19.107-04:00 and 2015-09-08T12:52:31.639-04:00. The rebalance in question begins at 2015-09-08T12:52:06.667-04:00.
The connection to ZK expires and is restablished multiple times before the process is killed after 2015-09-08T13:13:41.655-04:00, which marks the last entry in the logs for this day.