apache / pulsar-client-python

Apache Pulsar Python client library
https://pulsar.apache.org/
Apache License 2.0
51 stars 40 forks source link

Multi Topic consumer not using client provided logger - MultiTopicsConsumerImpl:526 | Received Message from one of the topic #216

Open Vincouux opened 2 months ago

Vincouux commented 2 months ago

Instantiating a multi topic consumer, using a client with provided logger, result undesired debug logging, which logs the a dump of the message. This can result in extremely high logging storage cost.

Here is how to reproduce :

...
pulsar_logger = logging.getLogger("pulsar")
pulsar_logger.setLevel(logging.INFO)
client = Client("your_pulsar_url", logger=pulsar_logger)
topics = ["topic1", "topic2", "topic3"]
consumer = client.subscribe(
    topics,
    subscription_name="subscription_name",
    consumer_type=ConsumerType.KeyShared,
)
# generate some message using a producer
...

What I expected to see : No logging with log level lower than INFO

What I see : Dump of every single message received by the consumer:

2024-07-10 16:13:22.773 DEBUG [137957839206144] MultiTopicsConsumerImpl:526 | Received Message from one of the topic - DUMP_OF_THE_MESSAGE

Environment :

pulsar-client==3.5.0 (python)
apachepulsar/pulsar-all:3.0.2 (docker image)
python3.9
BewareMyPower commented 2 months ago

It seems that you need to set logging.basicConfig first.

In my local env, the following code print no logs:

pulsar_logger = logging.getLogger("pulsar")
pulsar_logger.setLevel(logging.INFO)
client = pulsar.Client('pulsar://localhost:6650', logger=pulsar_logger)
# ...

However, after adding logging.basicConfig(level=logging.INFO) before the 1st line, it worked.

INFO:pulsar:[<none> -> pulsar://localhost:6650] Create ClientConnection, timeout=10000
INFO:pulsar:Created connection for pulsar://localhost:6650-pulsar://localhost:6650-0

And I can also change the log level to bug with pulsar_logger.setLevel(logging.DEBUG):

DEBUG:pulsar:Using Binary Lookup
DEBUG:pulsar:Run io_service in a single thread

But after removing the basicConfig call, the debug logs disappeared.

Vincouux commented 2 months ago

Thank you for your answer ! Passing a logger to Pulsar Client has always seem to work fine, and the associated level was always respected.

But for some reason, using a Multi Topic Consumer is not working as it should, and is logging this very specific DEBUG logging for every single message (MultiTopicsConsumerImpl:526 | Received Message from one of the topic).

Also, this is the only DEBUG statement being printed. That is why I was suspecting a bug in Pulsar Client. Another strange observation is that replacing this Multi Topic Consumer by a Single Topic Consumer (replacing the list of topics with a simple string), immediately remove this particular DEBUG statement.

I'm still not sure if it's a bug, a dependency race condition or simply an implementation issue on my end. For the time being, I'm replacing the Multi Topic Consumer with a home-made multi-threaded (multiple) Single Topic Consumers..