Page MenuHomePhabricator
Create Task
Maniphest T142430

Ensure no dropped messages in eventlogging producers when stopping broker
Closed, ResolvedPublic13 Estimated Story Points
Actions

Description

Now that we've switched to kafka-python, we no longer see eventlogging processes die during broker restarts. That's good! But it seems that kafka-python does drop a few number of messages when a broker restarts.

I tested increasing both retries and retry_backoff_ms for the Kafka producer, but I still saw a few retrying (0 attempts left). Error: <class 'kafka.errors.NotLeaderForPartitionError'> during a broker restart. kafka-python doesn't seem to log the final failed produce itself, but it does increase some internal metrics.

  1. kafka-python should log something here! Submit a fix upstream to do so.
  2. See if we can reproduce this outside of production. We might have to pipe quite a few messages through a processor to see this.
  3. If we can reproduce, find a solution. The fix could just be more producer tuning, but this also could be a bug in kafka-python.

Details

SubjectRepoBranchLines +/-
Revert "Add python-confluent-kafka to eventlogging::dependencies"operations/puppetproduction+0 -1
Add python-confluent-kafka to eventlogging::dependenciesoperations/puppetproduction+1 -0
Set kafka_producer_scheme to kafka-confluent for analytics eventlogging processoroperations/puppetproduction+3 -2
Add hiera lookup for kafka_producer_scheme so we can try out kafka-confluent producer for analytics eventlogging processoroperations/puppetproduction+44 -40
Increase sync_timeout=10.0 for eventbus service kafka produceroperations/puppetproduction+7 -1
Revert min.insync.replicas to 1, set api_version for eventbus Kafka produceroperations/puppetproduction+8 -9
Set api_version for eventlogging kafka consumers as well as producersoperations/puppetproduction+25 -13
Manually specify Kafka api_version in kafka_clusters configoperations/puppetproduction+30 -2
Customize query in gerrit

Related Objects

Event Timeline

Ottomata created this task.Aug 8 2016, 7:37 PM
Restricted Application added a subscriber: Aklapper. · View Herald TranscriptAug 8 2016, 7:37 PM
Ottomata triaged this task as Medium priority.Aug 9 2016, 3:11 PM
Ottomata added a subscriber: elukey.
Ottomata added a comment.Aug 9 2016, 4:24 PM

Am testing high volume production for eventbus in labs. Created this upstream issue: https://github.com/dpkp/kafka-python/issues/801

Ottomata added a comment.Aug 9 2016, 5:55 PM

kafka-python 1.3.1 was released yesterday. This fixed a bug I found when running sync producer in labs and stopping a broker. I don't lose messages in sync mode during broker stops. However, the situation described above still happens in production analytics eventlogging async producer with retries=6 and retry_backoff_ms=200.

• Nuria moved this task from Incoming to Backlog (Later) on the Analytics board.Aug 15 2016, 3:35 PM
• Nuria assigned this task to Ottomata.Oct 10 2016, 3:37 PM
Ottomata moved this task from Backlog (Later) to Operational Excellence Future on the Analytics board.Nov 14 2016, 4:36 PM
Ottomata edited projects, added Analytics-Kanban; removed Analytics.Nov 14 2016, 7:31 PM
Ottomata added a comment.Nov 14 2016, 7:35 PM

I can't reproduce this in labs. A quick look at logs on eventlog1001 make it clear that this is still happening. It seems that produce requests in flight exhaust their configured retries sending to the disconnected (and no longer leader) broker. Subsequent produce requests succeed find because the metadata has been updated for those.

Not totally sure how to fix since I can't reproduce. I'd like to suggest trying out a newer version of confluent-kafka-python for analytics eventlogging async kafka producer. Been trying this in labs, and I see a small performance boost out of using confluent. I generally trust librdkafka, so hopefully using this for async produce won't fail us during broker restarts.

Thoughts?

gerritbot subscribed.Dec 1 2016, 4:33 PM

Change 324745 had a related patch set uploaded (by Ottomata):
Manually specify Kafka api_version in kafka_clusters config

https://gerrit.wikimedia.org/r/324745

gerritbot added a project: Patch-For-Review.Dec 1 2016, 4:33 PM
• Nuria moved this task from Next Up to In Progress on the Analytics-Kanban board.Dec 1 2016, 5:14 PM
gerritbot added a comment.Dec 1 2016, 7:43 PM

Change 324745 merged by Ottomata:
Manually specify Kafka api_version in kafka_clusters config

https://gerrit.wikimedia.org/r/324745

gerritbot added a comment.Dec 1 2016, 8:16 PM

Change 324790 had a related patch set uploaded (by Ottomata):
Set api_version for eventlogging kafka consumers as well as producers

https://gerrit.wikimedia.org/r/324790

gerritbot added a comment.Dec 1 2016, 8:23 PM

Change 324790 merged by Ottomata:
Set api_version for eventlogging kafka consumers as well as producers

https://gerrit.wikimedia.org/r/324790

Ottomata renamed this task from Ensure no dropped messages in analytics eventlogging processors when stopping broker to Ensure no dropped messages in eventlogging producers when stopping broker.Dec 1 2016, 8:30 PM

I added api_version as a param to avoid possible dropped messages due to https://issues.apache.org/jira/browse/KAFKA-3547 for analytics async kafka-python producers. I didn't expect this to actually help the analytics async use, and it didn't. Will try it for the eventbus 'sync' use case and see how it goes. The problems of dropped messages are different in both of these cases.

gerritbot added a comment.Dec 1 2016, 9:06 PM

Change 324801 had a related patch set uploaded (by Ottomata):
Revert min.insync.replicas to 1, set api_version for eventbus Kafka producer

https://gerrit.wikimedia.org/r/324801

gerritbot added a comment.Dec 1 2016, 9:13 PM

Change 324801 merged by Ottomata:
Revert min.insync.replicas to 1, set api_version for eventbus Kafka producer

https://gerrit.wikimedia.org/r/324801

Ottomata added a comment.EditedDec 1 2016, 9:45 PM

I just applied the api_version change for the eventbus kafka-python producer. Good news: this eliminated the ArrayIndexOutOfBoundsException caused by https://issues.apache.org/jira/browse/KAFKA-3547. Bad news: it did nothing to help our dropped produce requests problem.

I'm currently seeing KafkaTimeoutError: Timeout after waiting for 2.0 secs. for several eventbus produce requests when I restart main Kafka brokers.

Ottomata edited projects, added Event-Platform; removed Patch-For-Review.Dec 1 2016, 9:45 PM
Ottomata added a comment.EditedDec 1 2016, 10:06 PM

We could try increasing sync_timeout, maybe 2 is just too short.

Or we could try https://gerrit.wikimedia.org/r/#/c/302372/ and async. Grasping at straws here :/

Stashbot subscribed.Dec 7 2016, 6:10 PM

Mentioned in SAL (#wikimedia-operations) [2016-12-07T18:10:21Z] <ottomata> will be bouncing some main-eqiad kafka brokers to try to troubleshoot T142430

gerritbot added a comment.Dec 7 2016, 6:23 PM

Change 325813 had a related patch set uploaded (by Ottomata):
Increase sync_timeout=10.0 for eventbus service kafka producer

https://gerrit.wikimedia.org/r/325813

gerritbot added a project: Patch-For-Review.Dec 7 2016, 6:23 PM
gerritbot added a comment.Dec 7 2016, 6:29 PM

Change 325813 merged by Ottomata:
Increase sync_timeout=10.0 for eventbus service kafka producer

https://gerrit.wikimedia.org/r/325813

Ottomata added a comment.Dec 7 2016, 6:36 PM

! Ah! Increasing sync_timeout to 10.0 worked! The default of 2.0 was too little. I also tried 5.0 and saw the KafkaTimeoutErrors. When all services at 10.0, I saw 0 dropped messages during a broker restart. I believe this gives the kafka-python client enough time to refresh leadership metadata and actually submit a retry to the new leader.

Phew, this is looking WAY better.

• Nuria subscribed.Dec 7 2016, 7:12 PM

Nice!

Ottomata added a comment.EditedDec 7 2016, 8:03 PM

I've just been trying out the confluent kafka producer for async analytics purposes. Looking pretty good too! I'll merge a few puppet changes (once gerrit comes back up), and if all goes well we may be able to close this ticket...

gerritbot added a comment.Dec 7 2016, 9:38 PM

Change 325837 had a related patch set uploaded (by Ottomata):
Add hiera lookup for kafka_producer_scheme so we can try out kafka-confluent producer for analytics eventlogging processor

https://gerrit.wikimedia.org/r/325837

gerritbot added a comment.Dec 7 2016, 9:50 PM

Change 325837 merged by Ottomata:
Add hiera lookup for kafka_producer_scheme so we can try out kafka-confluent producer for analytics eventlogging processor

https://gerrit.wikimedia.org/r/325837

gerritbot added a comment.Dec 7 2016, 9:53 PM

Change 325845 had a related patch set uploaded (by Ottomata):
Set kafka_producer_scheme to kafka-confluent for analytics eventlogging processor

https://gerrit.wikimedia.org/r/325845

gerritbot added a comment.Dec 7 2016, 9:56 PM

Change 325845 merged by Ottomata:
Set kafka_producer_scheme to kafka-confluent for analytics eventlogging processor

https://gerrit.wikimedia.org/r/325845

Ottomata added a comment.Dec 7 2016, 10:04 PM

Great. I feel good about this! I think the async kafka-confluent is gonna do us better for analytics, and the sync kafka-python for eventbus with a bigger sync timeout is good.

Ottomata set the point value for this task to 13.Dec 7 2016, 10:04 PM
Ottomata moved this task from In Progress to Done on the Analytics-Kanban board.
gerritbot added a comment.Dec 7 2016, 10:05 PM

Change 325846 had a related patch set uploaded (by Ottomata):
Add python-confluent-kafka to eventlogging::dependencies

https://gerrit.wikimedia.org/r/325846

gerritbot added a comment.Dec 7 2016, 10:06 PM

Change 325846 merged by Ottomata:
Add python-confluent-kafka to eventlogging::dependencies

https://gerrit.wikimedia.org/r/325846

Volans mentioned this in T152771: python-confluent-kafka conflict with snakebite on stat1002.Dec 9 2016, 3:04 PM
gerritbot added a comment.Dec 9 2016, 6:03 PM

Change 326148 had a related patch set uploaded (by Volans):
Revert "Add python-confluent-kafka to eventlogging::dependencies"

https://gerrit.wikimedia.org/r/326148

gerritbot added a comment.Dec 9 2016, 6:19 PM

Change 326148 merged by Volans:
Revert "Add python-confluent-kafka to eventlogging::dependencies"

https://gerrit.wikimedia.org/r/326148

Volans subscribed.Dec 9 2016, 6:26 PM

Please see T152771, we had to revert this last change to unbreak Puppet on stat1002.

• Nuria closed this task as Resolved.Dec 16 2016, 6:01 PM
Content licensed under Creative Commons Attribution-ShareAlike (CC BY-SA) 4.0 unless otherwise noted; code licensed under GNU General Public License (GPL) 2.0 or later and other open source licenses. By using this site, you agree to the Terms of Use, Privacy Policy, and Code of Conduct. · Wikimedia Foundation · Privacy Policy · Code of Conduct · Terms of Use · Disclaimer · CC-BY-SA · GPL