apache / apache/pulsar-client-python
[2.8.0] Python client instances emit logs for every client instance ever constructed with a `logger` argument
- Ngôn ngữ chính
- Python
- Star
- 75
- Fork
- 53
- Chỉ số merge pull request
- Không có pull request nào được merge trong 30 ngày
Mô tả
**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
```
Hướng dẫn đóng góp
Đánh giá
Issue này chưa được đánh giá.