zbentley opened a new issue #11845:
URL: https://github.com/apache/pulsar/issues/11845
**Describe the bug**
When `Client` instances are constructed with the Python driver, they seem to
accumulate the value of the `logger` argument as global state. This means two
things:
1. If a Client is constructed *without* a `logger`, all subsequent clients
constructed with a `logger` will not use it.
2. If a Client is constructed *with* a logger, and another client is
constructed with a different logger, the second client will emit all logs
twice: once to the first client's logger, and once to its own logger.
These behaviors both occur whether or not previously-constructed clients
still exist--even if previous clients have been disconnected and garbage
collected, issues still occur.
**To Reproduce**
1. Ensure a broker is running (I tested against 2.8.0) on `localhost:6650`.
2. Run this Python snippet:
```python
import logging
from pulsar import Client
def logger_with_prefix(prefix):
logger = logging.getLogger('test')
ch = logging.StreamHandler()
formatter = logging.Formatter('{}: %(message)s'.format(prefix))
ch.setFormatter(formatter)
logger.addHandler(ch)
return logger
if __name__ == '__main__':
print("Creating first")
first = Client(service_url='pulsar://localhost:6650/')
print("Destroying first")
del first
print("Creating second")
second = Client(
service_url='pulsar://localhost:6650/',
logger=logger_with_prefix("FOO"),
)
consumer = second.subscribe('sometopic', 'somesub')
consumer.close()
```
3. Observe that the Python logger is not used when logging consumer
creation/destruction (sample output below).
4. Run this Python snippet:
```python
import logging
from pulsar import Client
def logger_with_prefix(prefix):
logger = logging.getLogger('test')
ch = logging.StreamHandler()
formatter = logging.Formatter('{}: %(message)s'.format(prefix))
ch.setFormatter(formatter)
logger.addHandler(ch)
return logger
if __name__ == '__main__':
print("Creating first")
first = Client(
service_url='pulsar://localhost:6650/',
logger = logger_with_prefix("FOO"),
)
print("Destroying first")
del first
print("Creating second")
second = Client(
service_url='pulsar://localhost:6650/',
logger=logger_with_prefix("BAR"),
)
consumer = second.subscribe('sometopic', 'somesub')
consumer.close()
```
5. Observe that logs for the consumer operations are emitted twice, once on
the `FOO` logger and once on the `BAR` logger.
6. Run this python snippet:
```python
import logging
from pulsar import Client
def logger_with_prefix(prefix):
logger = logging.getLogger('test')
ch = logging.StreamHandler()
formatter = logging.Formatter('{}: %(message)s'.format(prefix))
ch.setFormatter(formatter)
logger.addHandler(ch)
return logger
if __name__ == '__main__':
print("Creating first")
first = Client(
service_url='pulsar://localhost:6650/',
logger = logger_with_prefix("FOO"),
)
print("Destroying first")
del first
print("Creating second")
second = Client(
service_url='pulsar://localhost:6650/',
)
consumer = second.subscribe('sometopic', 'somesub')
consumer.close()
```
7. Observe that logs are emitted with the `FOO` prefix.
**Expected behavior**
1. In the first snippet, all logs should be emitted with the `FOO` prefix.
2. In the second snippet, all logs should be emitted with the `BAR` prefix.
3. In the third snippet, all logs should be emitted with no prefix/using the
internal log4cxx logger.
**Desktop (please complete the following information):**
- OS: MacOS 10.11
Erroneous output of snippet 1:
```
∴ python tests/benchmark/scratch.py
Creating first
Destroying first
Creating second
2021-08-30 16:44:35.805 INFO [0x1178f2e00] Client:88 | Subscribing on Topic
:sometopic
2021-08-30 16:44:35.806 INFO [0x1178f2e00] ConnectionPool:84 | Created
connection for pulsar://localhost:6650/
2021-08-30 16:44:35.808 INFO [0x70000c911000] ClientConnection:372 |
[127.0.0.1:57417 -> 127.0.0.1:6650] Connected to broker
2021-08-30 16:44:35.821 INFO [0x70000c911000] HandlerBase:55 |
[persistent://public/default/sometopic, somesub, 0] Getting connection from pool
2021-08-30 16:44:35.822 INFO [0x70000c911000] ConnectionPool:84 | Created
connection for pulsar://localhost:6650
2021-08-30 16:44:35.823 INFO [0x70000c911000] ClientConnection:374 |
[127.0.0.1:57418 -> 127.0.0.1:6650] Connected to broker through proxy. Logical
broker: pulsar://localhost:6650
2021-08-30 16:44:35.839 INFO [0x70000c911000] ConsumerImpl:220 |
[persistent://public/default/sometopic, somesub, 0] Created consumer on broker
[127.0.0.1:57418 -> 127.0.0.1:6650]
2021-08-30 16:44:35.839 INFO [0x1178f2e00] ConsumerImpl:874 |
[persistent://public/default/sometopic, somesub, 0] Closing consumer for topic
persistent://public/default/sometopic
2021-08-30 16:44:35.840 INFO [0x70000c911000] ConsumerImpl:930 |
[persistent://public/default/sometopic, somesub, 0] Closed consumer 0
2021-08-30 16:44:35.848 INFO [0x1178f2e00] ClientConnection:1446 |
[127.0.0.1:57418 -> 127.0.0.1:6650] Connection closed
2021-08-30 16:44:35.848 ERROR [0x70000c911000] ClientConnection:531 |
[127.0.0.1:57418 -> 127.0.0.1:6650] Read failed: Operation canceled
2021-08-30 16:44:35.849 INFO [0x1178f2e00] ClientConnection:261 |
[127.0.0.1:57418 -> 127.0.0.1:6650] Destroyed connection
2021-08-30 16:44:35.849 ERROR [0x70000c911000] ClientConnection:531 |
[127.0.0.1:57417 -> 127.0.0.1:6650] Read failed: Operation canceled
2021-08-30 16:44:35.849 INFO [0x1178f2e00] ClientConnection:1446 |
[127.0.0.1:57417 -> 127.0.0.1:6650] Connection closed
2021-08-30 16:44:35.849 INFO [0x1178f2e00] ClientConnection:261 |
[127.0.0.1:57417 -> 127.0.0.1:6650] Destroyed connection
```
Erroneous output of snippet 2:
```
import logging
from pulsar import Client
def logger_with_prefix(prefix):
logger = logging.getLogger('test')
ch = logging.StreamHandler()
formatter = logging.Formatter('{}: %(message)s'.format(prefix))
ch.setFormatter(formatter)
logger.addHandler(ch)
return logger
if __name__ == '__main__':
print("Creating first")
first = Client(
service_url='pulsar://localhost:6650/',
logger = logger_with_prefix("FOO"),
)
print("Destroying first")
del first
print("Creating second")
second = Client(
service_url='pulsar://localhost:6650/',
logger=logger_with_prefix("BAR"),
)
consumer = second.subscribe('sometopic', 'somesub')
consumer.close()
```
Erroneous output of snippet 3:
```
∴ python tests/benchmark/scratch.py
Creating first
Destroying first
Creating second
FOO: Subscribing on Topic :sometopic
FOO: Created connection for pulsar://localhost:6650/
FOO: [127.0.0.1:57427 -> 127.0.0.1:6650] Connected to broker
FOO: [persistent://public/default/sometopic, somesub, 0] Getting connection
from pool
FOO: Created connection for pulsar://localhost:6650
FOO: [127.0.0.1:57428 -> 127.0.0.1:6650] Connected to broker through proxy.
Logical broker: pulsar://localhost:6650
FOO: [persistent://public/default/sometopic, somesub, 0] Created consumer on
broker [127.0.0.1:57428 -> 127.0.0.1:6650]
FOO: [persistent://public/default/sometopic, somesub, 0] Closing consumer
for topic persistent://public/default/sometopic
FOO: [persistent://public/default/sometopic, somesub, 0] Closed consumer 0
FOO: [127.0.0.1:57428 -> 127.0.0.1:6650] Connection closed
FOO: [127.0.0.1:57427 -> 127.0.0.1:6650] Connection closed
```
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: [email protected]
For queries about this service, please contact Infrastructure at:
[email protected]
