sarama icon indicating copy to clipboard operation
sarama copied to clipboard

Lots of logs spamming with RefreshMetadata when sarama logger is enabled.

Open AmiKotia opened this issue 1 year ago • 8 comments

Versions

Please specify real version numbers or git SHAs, not just "Latest" since that changes fairly regularly.

Sarama Kafka Go
1.34.1 3.3.1 1.16
Configuration

What configuration values are you using for Sarama and Kafka?

Logs

When filing an issue please provide logs from Sarama and Kafka if at all possible. You can set sarama.Logger to a log.Logger to capture Sarama debug output.

logs: CLICK ME

"} {"level":"info","msg":"client/metadata fetching metadata for all topics from broker kafka:9092\n","time":"2023-08-15T22:33:14Z"} {"level":"info","msg":"client/metadata fetching metadata for all topics from broker kafka:9092\n","time":"2023-08-15T22:33:14Z"} {"level":"info","msg":"client/metadata fetching metadata for all topics from broker kafka:9092\n","time":"2023-08-15T22:33:14Z"} {"level":"info","msg":"client/metadata fetching metadata for all topics from broker kafka:9092\n","time":"2023-08-15T22:33:15Z"} {"level":"info","msg":"client/metadata fetching metadata for all topics from broker kafka:9092\n","time":"2023-08-15T22:33:15Z"} {"level":"info","msg":"client/metadata fetching metadata for all topics from broker kafka:9092\n","time":"2023-08-15T22:33:15Z"} {"level":"info","msg":"client/metadata fetching metadata for all topics from broker kafka:9092\n","time":"2023-08-15T22:33:15Z"} {"level":"info","msg":"client/metadata fetching metadata for all topics from broker kafka:9092\n","time":"2023-08-15T22:33:15Z"} {"level":"info","msg":"client/metadata fetching metadata for all topics from broker kafka:9092\n","time":"2023-08-15T22:33:15Z"} {"level":"info","msg":"client/metadata fetching metadata for all topics from broker kafka:9092\n","time":"2023-08-15T22:33:15Z"} {"

Problem Description

Hi,

We are using sarama health check for our application and it is being called for every producer and consumer that our application creates. Currently, the default retry interval that we have configured is of 250 milliseconds and we are seeing a lot of logs of the level Info getting logged every 250 ms which is generated from the line err := hs.client.RefreshMetadata()

Due to this constant spamming of Info level logs, we aren't able to enable sarama logs in our production environment.

Is there a suggestion that you can provide so that we can continue to use this healthcheck with retry frequency of 250 ms and at the same time not log these Info level logs {"level":"info","msg":"client/metadata fetching metadata for all topics from broker kafka:9092\n","time":"2023-08-15T22:33:15Z"}? Is it possible that these logs can be changed to debug level?

AmiKotia avatar Aug 18 '23 18:08 AmiKotia

@AmiKotia this message is attached to the DebugLogger rather than the main Logger https://github.com/IBM/sarama/blob/86816212a7aca81d7d64c5603bb1aeb7f8248a7a/client.go#L1036

So as long as you configure DebugLogger separately (by default it sends its output to Logger if you haven't overridden the default) then you should be OK?

dnwe avatar Aug 18 '23 20:08 dnwe

@dnwe We have overridden the default logger. I wonder why we still see it at Info level? sarama.Logger = config.Logger

AmiKotia avatar Aug 18 '23 22:08 AmiKotia

@AmiKotia the sarama logger isn’t levelled, we have two separate loggers that just write to whatever you provide, so it must be your logger impl that’s setting info level

dnwe avatar Aug 18 '23 23:08 dnwe

@dnwe Could you provide a level based logger?

ForeverSRC avatar Aug 25 '23 02:08 ForeverSRC

@ForeverSRC it is always tricky providing a logging framework in a Go module library that will work for everyone. The existing pair of loggers provide a simple “Debug” and “Everything Info and above” and have been an easy way for people to turn on/off logging.

In v2 we could move to using slog from the stdlib as the interface, but it would require application changes to move to the new module version

dnwe avatar Aug 25 '23 07:08 dnwe

@dnwe Then how about provide an "Error" logger. Just like the options in github.com/olivere/elastic/[email protected]/client.go:690

Our scenario is, we monitor every error log and send them to the alert system, as most of the error logs are logged by the Logger, we always have some false positive alert, for example, when a broker shut down and a partition select a new broker, we want to monitor the event of a broker shutting down, but not a partition select a new broker and a broker start up.

ForeverSRC avatar Aug 29 '23 01:08 ForeverSRC

Thank you for taking the time to raise this issue. However, it has not had any activity on it in the past 90 days and will be closed in 30 days if no updates occur. Please check if the main branch has already resolved the issue since it was raised. If you believe the issue is still valid and you would like input from the maintainers then please comment to ask for it to be reviewed.

github-actions[bot] avatar Jan 25 '24 18:01 github-actions[bot]

Thank you for taking the time to raise this issue. However, it has not had any activity on it in the past 90 days and will be closed in 30 days if no updates occur. Please check if the main branch has already resolved the issue since it was raised. If you believe the issue is still valid and you would like input from the maintainers then please comment to ask for it to be reviewed.

github-actions[bot] avatar Apr 24 '24 20:04 github-actions[bot]