[jira] [Created] (KAFKA-3921) Periodic refresh of metadata causes spurious log messages

["Steven Schlansker (JIRA)" <ji...@apache.org>]

Steven Schlansker created KAFKA-3921:
----------------------------------------

             Summary: Periodic refresh of metadata causes spurious log messages
                 Key: KAFKA-3921
                 URL: https://issues.apache.org/jira/browse/KAFKA-3921
             Project: Kafka
          Issue Type: Improvement
          Components: clients
    Affects Versions: 0.9.0.1
            Reporter: Steven Schlansker


Kafka cluster metadata has a configurable expiry period.  (I don't understand why this is -- cluster updates can happen at any time, and we have to pick those up quicker than every 10 minutes?  But this ticket isn't about that.)

When this interval expires, the ClientUtils class spins up a SyncProducer, which sends a special message to retrieve metadata.  The producer is then closed immediately after processing this message.

This causes the SyncProducer to log both a connection open and close at INFO level:

{code}
2016-06-30T17:50:19.408Z INFO <> [ProducerSendThread-central-buzzsaw-1-myhost] kafka.client.ClientUtils$ - Fetching metadata from broker BrokerEndPoint(2,broker-3.mycorp.com,9092) with correlation id 17188 for 1 topic(s) Set(logstash)
2016-06-30T17:50:19.410Z INFO <> [ProducerSendThread-central-buzzsaw-1-myhost] kafka.producer.SyncProducer - Connected to broker-3.mycorp.com:9092 for producing
2016-06-30T17:50:19.411Z INFO <> [ProducerSendThread-central-buzzsaw-1-myhost] kafka.producer.SyncProducer - Disconnecting from broker-3.mycorp.com:9092
2016-06-30T17:50:19.411Z INFO <> [ProducerSendThread-central-buzzsaw-1-myhost] kafka.producer.SyncProducer - Disconnecting from broker-14.mycorp.com:9092
2016-06-30T17:50:19.411Z INFO <> [ProducerSendThread-central-buzzsaw-1-myhost] kafka.producer.SyncProducer - Disconnecting from broker-logkafka-13.mycorp.com:9092
2016-06-30T17:50:19.411Z INFO <> [ProducerSendThread-central-buzzsaw-1-myhost] kafka.producer.SyncProducer - Disconnecting from broker-12.mycorp.com:9092
2016-06-30T17:50:19.413Z INFO <> [ProducerSendThread-central-buzzsaw-1-myhost] kafka.producer.SyncProducer - Connected to broker-12.mycorp.com:9092 for producing
{code}

When you are reading the logs, this appears periodically.  We've had more than one administrator then think that the cluster is unhealthy, and client connections are getting dropped -- it's disconnecting from the broker so frequently!  What is wrong???  But in reality, it is just this harmless / expected metadata update.

Can we tweak the log levels so that the periodic background refresh does not log unless something goes wrong?  The log messages are misleading and easy to misinterpret.  I had to read the code pretty thoroughly to convince myself that these messages are actually harmless.



--
This message was sent by Atlassian JIRA
(v6.3.4#6332)