{"action":"created","issue":{"url":"https://api.github.com/repos/edenhill/librdkafka/issues/777","repository_url":"https://api.github.com/repos/edenhill/librdkafka","labels_url":"https://api.github.com/repos/edenhill/librdkafka/issues/777/labels{/name}","comments_url":"https://api.github.com/repos/edenhill/librdkafka/issues/777/comments","events_url":"https://api.github.com/repos/edenhill/librdkafka/issues/777/events","html_url":"https://github.com/edenhill/librdkafka/issues/777","id":174804508,"number":777,"title":"Problems recovering after broker down","user":{"login":"mhyllander","id":3501939,"avatar_url":"https://avatars.githubusercontent.com/u/3501939?v=3","gravatar_id":"","url":"https://api.github.com/users/mhyllander","html_url":"https://github.com/mhyllander","followers_url":"https://api.github.com/users/mhyllander/followers","following_url":"https://api.github.com/users/mhyllander/following{/other_user}","gists_url":"https://api.github.com/users/mhyllander/gists{/gist_id}","starred_url":"https://api.github.com/users/mhyllander/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/mhyllander/subscriptions","organizations_url":"https://api.github.com/users/mhyllander/orgs","repos_url":"https://api.github.com/users/mhyllander/repos","events_url":"https://api.github.com/users/mhyllander/events{/privacy}","received_events_url":"https://api.github.com/users/mhyllander/received_events","type":"User","site_admin":false},"labels":[{"url":"https://api.github.com/repos/edenhill/librdkafka/labels/producer","name":"producer","color":"5319e7"}],"state":"open","locked":false,"assignee":null,"assignees":[],"milestone":null,"comments":2,"created_at":"2016-09-02T16:58:06Z","updated_at":"2016-09-05T10:24:31Z","closed_at":null,"body":"I'm having a problem with recovery when a broker has been down and comes up again. I'm using rsyslog 8.20 with librdkafka 0.9.1 to send logs to a kafka 0.8.2.1 cluster with two brokers.\r\n\r\nWhen one of the brokers (A) goes down for some reason, the other (B) assumes leadership of all partitions. librdkafka on the hosts detects this and sends all Produce requests to B. After a while when A has completed recovery of all local partitions and has caught up with B, it comes online again and resumes leadership of half the partitions.\r\n\r\nThis is where I'm having problems. Lots of nodes keep sending produce requests to B, they don't seem to detect that A has become leader again. In the kafka server log on B there are large amounts of messages like this (broker 0=A, broker 1=B):\r\n\r\n```\r\n[2016-09-02 16:54:00,933] WARN [KafkaApi-1] Produce request with correlation id 598054 from client rdkafka-hive-prod-euw-readmin-re1-o4pavq on partition [logs2,48] failed due to Leader not local for partition [logs2,48] on broker 1 (kafka.server.KafkaApis)\r\n[2016-09-02 16:54:00,933] WARN [KafkaApi-1] Produce request with correlation id 280093 from client rdkafka-hive-prod-euw-hivejs-hj1-h6jn1c on partition [logs2,34] failed due to Leader not local for partition [logs2,34] on broker 1 (kafka.server.KafkaApis)\r\n[2016-09-02 16:54:00,933] WARN [KafkaApi-1] Produce request with correlation id 2108417 from client rdkafka-hive-prod-euw-repeer-re2-cgqjpo on partition [logs2,46] failed due to Leader not local for partition [logs2,46] on broker 1 (kafka.server.KafkaApis)\r\n[2016-09-02 16:54:00,933] WARN [KafkaApi-1] Produce request with correlation id 366881 from client rdkafka-hive-prod-euw-logger2-lg4-d5 on partition [logs2,34] failed due to Leader not local for partition [logs2,34] on broker 1 (kafka.server.KafkaApis)\r\n[2016-09-02 16:54:00,933] WARN [KafkaApi-1] Produce request with correlation id 2123807 from client rdkafka-hive-prod-euw-frontend-fe1-95n70w on partition [logs2,18] failed due to Leader not local for partition [logs2,18] on broker 1 (kafka.server.KafkaApis)\r\n[2016-09-02 16:54:00,933] WARN [KafkaApi-1] Produce request with correlation id 794621 from client rdkafka-hive-prod-euw-zk-zk1-2 on partition [logs2,52] failed due to Leader not local for partition [logs2,52] on broker 1 (kafka.server.KafkaApis)\r\n[2016-09-02 16:54:00,933] WARN [KafkaApi-1] Produce request with correlation id 1962590 from client rdkafka-hive-prod-use-hivecdn-hc1-ifts62 on partition [logs2,18] failed due to Leader not local for partition [logs2,18] on broker 1 (kafka.server.KafkaApis)\r\n[2016-09-02 16:54:00,933] WARN [KafkaApi-1] Produce request with correlation id 1852380 from client rdkafka-hive-prod-euw-hivepx-hp1-tajiv6 on partition [logs2,58] failed due to Leader not local for partition [logs2,58] on broker 1 (kafka.server.KafkaApis)\r\n[2016-09-02 16:54:00,933] WARN [KafkaApi-1] Produce request with correlation id 890436 from client rdkafka-hive-prod-use-hivecdn-hc1-ecaud6 on partition [logs2,22] failed due to Leader not local for partition [logs2,22] on broker 1 (kafka.server.KafkaApis)\r\n[2016-09-02 16:54:00,933] WARN [KafkaApi-1] Produce request with correlation id 2023478 from client rdkafka-hive-prod-euw-relay-ry1-0 on partition [logs2,52] failed due to Leader not local for partition [logs2,52] on broker 1 (kafka.server.KafkaApis)\r\n[2016-09-02 16:54:00,933] WARN [KafkaApi-1] Produce request with correlation id 2157767 from client rdkafka-hive-prod-euw-service-svc-d0 on partition [logs2,36] failed due to Leader not local for partition [logs2,36] on broker 1 (kafka.server.KafkaApis)\r\n[2016-09-02 16:54:00,933] WARN [KafkaApi-1] Produce request with correlation id 112178 from client rdkafka-hive-prod-euw-logx2-lg5-tgu8j6 on partition [logs2,56] failed due to Leader not local for partition [logs2,56] on broker 1 (kafka.server.KafkaApis)\r\n[2016-09-02 16:54:00,933] WARN [KafkaApi-1] Produce request with correlation id 115353 from client rdkafka-hive-prod-euw-spark-sp2-m2 on partition [logs2,36] failed due to Leader not local for partition [logs2,36] on broker 1 (kafka.server.KafkaApis)\r\n[2016-09-02 16:54:00,933] WARN [KafkaApi-1] Produce request with correlation id 114844 from client rdkafka-hive-prod-euw-logger2-lg4-d1 on partition [logs2,0] failed due to Leader not local for partition [logs2,0] on broker 1 (kafka.server.KafkaApis)\r\n[2016-09-02 16:54:00,933] WARN [KafkaApi-1] Produce request with correlation id 277827 from client rdkafka-hive-prod-euw-zk-zk1-1 on partition [logs2,40] failed due to Leader not local for partition [logs2,40] on broker 1 (kafka.server.KafkaApis)\r\n[2016-09-02 16:54:00,934] WARN [KafkaApi-1] Produce request with correlation id 272411 from client rdkafka-hive-prod-euw-bandwidth-bw1-0 on partition [logs2,36] failed due to Leader not local for partition [logs2,36] on broker 1 (kafka.server.KafkaApis)\r\n[2016-09-02 16:54:00,934] WARN [KafkaApi-1] Produce request with correlation id 284752 from client rdkafka-hive-prod-euw-spark-sp2-w1 on partition [logs2,18] failed due to Leader not local for partition [logs2,18] on broker 1 (kafka.server.KafkaApis)\r\n[2016-09-02 16:54:00,934] WARN [KafkaApi-1] Produce request with correlation id 287579 from client rdkafka-hive-prod-euw-kafka-lg6-1 on partition [logs2,58] failed due to Leader not local for partition [logs2,58] on broker 1 (kafka.server.KafkaApis)\r\n[2016-09-02 16:54:00,934] WARN [KafkaApi-1] Produce request with correlation id 2234140 from client rdkafka-hive-prod-euw-ipserv-ip1-z80gp6 on partition [logs2,8] failed due to Leader not local for partition [logs2,8] on broker 1 (kafka.server.KafkaApis)\r\n[2016-09-02 16:54:00,934] WARN [KafkaApi-1] Produce request with correlation id 2231654 from client rdkafka-hive-prod-euw-ipserv-ip1-b0wrjx on partition [logs2,40] failed due to Leader not local for partition [logs2,40] on broker 1 (kafka.server.KafkaApis)\r\n[2016-09-02 16:54:00,934] WARN [KafkaApi-1] Produce request with correlation id 2190908 from client rdkafka-hive-prod-euw-frontend-fe1-couwxt on partition [logs2,36] failed due to Leader not local for partition [logs2,36] on broker 1 (kafka.server.KafkaApis)\r\n[2016-09-02 16:54:00,934] WARN [KafkaApi-1] Produce request with correlation id 2154151 from client rdkafka-hive-prod-euw-ipserv-ip1-b9mgk3 on partition [logs2,48] failed due to Leader not local for partition [logs2,48] on broker 1 (kafka.server.KafkaApis)\r\n[2016-09-02 16:54:00,934] WARN [KafkaApi-1] Produce request with correlation id 2085390 from client rdkafka-hive-prod-euw-frontend-fe1-6r7x4j on partition [logs2,48] failed due to Leader not local for partition [logs2,48] on broker 1 (kafka.server.KafkaApis)\r\n[2016-09-02 16:54:00,934] WARN [KafkaApi-1] Produce request with correlation id 2113946 from client rdkafka-hive-prod-euw-frontend-fe1-hkzwag on partition [logs2,8] failed due to Leader not local for partition [logs2,8] on broker 1 (kafka.server.KafkaApis)\r\n[2016-09-02 16:54:00,934] WARN [KafkaApi-1] Produce request with correlation id 2076737 from client rdkafka-hive-prod-euw-frontend-fe1-m14chu on partition [logs2,10] failed due to Leader not local for partition [logs2,10] on broker 1 (kafka.server.KafkaApis)\r\n[2016-09-02 16:54:00,934] WARN [KafkaApi-1] Produce request with correlation id 2039076 from client rdkafka-hive-prod-euw-ipserv-ip1-3fd1uw on partition [logs2,4] failed due to Leader not local for partition [logs2,4] on broker 1 (kafka.server.KafkaApis)\r\n[2016-09-02 16:54:00,934] WARN [KafkaApi-1] Produce request with correlation id 1997910 from client rdkafka-hive-prod-euw-frontend-fe1-4ekfxw on partition [logs2,30] failed due to Leader not local for partition [logs2,30] on broker 1 (kafka.server.KafkaApis)\r\n[2016-09-02 16:54:00,934] WARN [KafkaApi-1] Produce request with correlation id 1979461 from client rdkafka-hive-prod-euw-frontend-fe1-fox2sc on partition [logs2,20] failed due to Leader not local for partition [logs2,20] on broker 1 (kafka.server.KafkaApis)\r\n[2016-09-02 16:54:00,934] WARN [KafkaApi-1] Produce request with correlation id 1876978 from client rdkafka-hive-prod-euw-repeer-re2-ecik7m on partition [logs2,30] failed due to Leader not local for partition [logs2,30] on broker 1 (kafka.server.KafkaApis)\r\n[2016-09-02 16:54:00,934] WARN [KafkaApi-1] Produce request with correlation id 1068428 from client rdkafka-hive-prod-euw-hivecdn-hc1-kjoawp on partition [logs2,14] failed due to Leader not local for partition [logs2,14] on broker 1 (kafka.server.KafkaApis)\r\n[2016-09-02 16:54:00,934] WARN [KafkaApi-1] Produce request with correlation id 2157768 from client rdkafka-hive-prod-euw-service-svc-d0 on partition [logs2,8] failed due to Leader not local for partition [logs2,8] on broker 1 (kafka.server.KafkaApis)\r\n```\r\n\r\nI'm having this issue right now, but it's hard to turn on debugging in librdkafka and rsyslog without restarting rsyslog.\r\n\r\nThis is the librdkafka configuration:\r\n\r\n```\r\n    confParam=[\r\n      \"client.id=rdkafka-hive-prod-euw-kafka-lg6-1\",\r\n      \"broker.version.fallback=0.8.2\",\r\n      \"queue.buffering.max.messages=10000\",\r\n      # https://github.com/edenhill/librdkafka/blob/master/INTRODUCTION.md#high-throughput\r\n      \"batch.num.messages=1000\",\r\n      \"queue.buffering.max.ms=1000\",\r\n      # retry failed sends as many times as possible\r\n      \"message.send.max.retries=10000000\",\r\n      # metata refresh interval (every 2m)\r\n      \"topic.metadata.refresh.interval.ms=120000\",\r\n      # refresh metadata when a broker goes down or restarts (try every 2s for 20 minutes)\r\n      \"topic.metadata.refresh.fast.cnt=600\",\r\n      \"topic.metadata.refresh.fast.interval.ms=2000\",\r\n      # use compression\r\n      \"compression.codec=snappy\"\r\n    ]\r\n    topicConfParam=[\r\n      # keep messages in queue forever\r\n      \"message.timeout.ms=0\"\r\n    ]\r\n```\r\n\r\nI've been experimenting with the metadata refresh settings, without much luck it seems. Any help would be greatly appreciated.\r\n\r\nMagnus"},"comment":{"url":"https://api.github.com/repos/edenhill/librdkafka/issues/comments/244713595","html_url":"https://github.com/edenhill/librdkafka/issues/777#issuecomment-244713595","issue_url":"https://api.github.com/repos/edenhill/librdkafka/issues/777","id":244713595,"user":{"login":"edenhill","id":524990,"avatar_url":"https://avatars.githubusercontent.com/u/524990?v=3","gravatar_id":"","url":"https://api.github.com/users/edenhill","html_url":"https://github.com/edenhill","followers_url":"https://api.github.com/users/edenhill/followers","following_url":"https://api.github.com/users/edenhill/following{/other_user}","gists_url":"https://api.github.com/users/edenhill/gists{/gist_id}","starred_url":"https://api.github.com/users/edenhill/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/edenhill/subscriptions","organizations_url":"https://api.github.com/users/edenhill/orgs","repos_url":"https://api.github.com/users/edenhill/repos","events_url":"https://api.github.com/users/edenhill/events{/privacy}","received_events_url":"https://api.github.com/users/edenhill/received_events","type":"User","site_admin":false},"created_at":"2016-09-05T10:24:31Z","updated_at":"2016-09-05T10:24:31Z","body":"13 hours! Not bad, patience is the key..\r\n\r\nWhat should be happening is when librdkafka tries to produce to the broker it thinks is the leader (but no longer isnt), that broker should respond with an error (NotLeaderForPartition) and librdkafka will issue new MetadataRequests to find out the new leader and migrate the partitions over to the new leader broker.\r\n\r\nI think the issue here is your monstrous message.send.max.retries value - the retry code is run before the NotLeaderForPartition error handling code is. That is clearly a bug, retries should only be performed on transient errors, I'll fix that.\r\n"}}
{"actor":{"display_login":"edenhill"}}