apache / apache/pulsar-client-python

[2.8.0] Python client instances emit logs for every client instance ever constructed with a `logger` argument

Abierto
#40 9 comentarios 0 reacciones 1 asignado Reclamado por @BewareMyPower Ver en GitHub
Lenguaje dominante
Python
Estrellas
75
Forks
53
Métricas de merge de PR
Sin PR fusionados en 30 d

Descripción

**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
```

Guía de contribución

Abrir la guía de contribución

Evaluación

Este issue todavía no se ha evaluado.

Recibe los nuevos issues en tu correo

Un resumen breve de issues de GitHub para principiantes.