You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@pulsar.apache.org by GitBox <gi...@apache.org> on 2021/08/27 23:11:52 UTC
[GitHub] [pulsar] zbentley opened a new issue #11823: Using the Python pulsar client with a logger can cause arbitrary/unrelated `async` Python functions to return `None`
zbentley opened a new issue #11823:
URL: https://github.com/apache/pulsar/issues/11823
If a `logger` object (any logger object) is supplied to `pulsar.Client` objects in Python, its presence can cause arbitrary `async` Python functions to return `None` incorrectly.
# Steps to reproduce
To reproduce, run the following:
```
import asyncio
import logging
from pulsar import Client
async def async_func(client, rv):
consumer = client.subscribe('sometopic', 'somesub')
consumer.close()
print("async returning", rv)
return rv
if __name__ == '__main__':
client = Client(
service_url='pulsar://localhost:6650/',
logger=logging.getLogger("foo")
)
print("returned:", asyncio.run(async_func(client, "bar")))
```
# Test setup
Python: 3.9
OS: MacOS 10.11
Arch: x86_64
Pulsar broker: 2.8.0 standalone, running locally
Client: `2.8.0.post0`
# Pathology/root cause
This appears to be due to a Boost-python issue (and, in my opinion, a pretty bad one) I found while trying to track down this behavior: https://github.com/boostorg/python/issues/374
Unless there is a way to fix that, it looks like **any** invocation of `pulsar-client`'s Python logger by the C++ code can, in the right circumstances, corrupt the Python interpreter state and cause the calling `async` function to return `None` incorrectly.
--
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: commits-unsubscribe@pulsar.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [pulsar] BewareMyPower commented on issue #11823: Using the Python pulsar client with a logger can cause arbitrary/unrelated `async` Python functions to return `None`
Posted by GitBox <gi...@apache.org>.
BewareMyPower commented on issue #11823:
URL: https://github.com/apache/pulsar/issues/11823#issuecomment-909407548
> I think this means that source artifacts are not published to PyPi, which may be a separate issue. Do you think I should open one?
You can open an issue or send an email for this issue. I'm not familiar with how Python client was published but someone else might know.
> very sorry for wasting your time with the back-and-forth.
Never mind, glad to hear it works for you :)
--
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: commits-unsubscribe@pulsar.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [pulsar] BewareMyPower commented on issue #11823: Using the Python pulsar client with a logger can cause arbitrary/unrelated `async` Python functions to return `None`
Posted by GitBox <gi...@apache.org>.
BewareMyPower commented on issue #11823:
URL: https://github.com/apache/pulsar/issues/11823#issuecomment-908420128
--
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: commits-unsubscribe@pulsar.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [pulsar] zbentley commented on issue #11823: Using the Python pulsar client with a logger can cause arbitrary/unrelated `async` Python functions to return `None`
Posted by GitBox <gi...@apache.org>.
zbentley commented on issue #11823:
URL: https://github.com/apache/pulsar/issues/11823#issuecomment-908533263
Unfortunately I am able to reproduce the bug on your branch:
```
∴ python tests/benchmark/scratch.py
async returning bar
StopIteration: bar
returned: None
```
--
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: commits-unsubscribe@pulsar.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [pulsar] BewareMyPower commented on issue #11823: Using the Python pulsar client with a logger can cause arbitrary/unrelated `async` Python functions to return `None`
Posted by GitBox <gi...@apache.org>.
BewareMyPower commented on issue #11823:
URL: https://github.com/apache/pulsar/issues/11823#issuecomment-909826703
It should only be published to PyPi for stable versions. For master branch, you need to build from source.
If the related PR was already cherry-picked to branch of last stable version (branch-2.8 currently), the wheel file would be included in StreamNative's weekly release, like https://github.com/streamnative/pulsar/releases/tag/v2.8.0.15.
--
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: commits-unsubscribe@pulsar.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [pulsar] BewareMyPower closed issue #11823: Using the Python pulsar client with a logger can cause arbitrary/unrelated `async` Python functions to return `None`
Posted by GitBox <gi...@apache.org>.
BewareMyPower closed issue #11823:
URL: https://github.com/apache/pulsar/issues/11823
--
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: commits-unsubscribe@pulsar.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [pulsar] zbentley commented on issue #11823: Using the Python pulsar client with a logger can cause arbitrary/unrelated `async` Python functions to return `None`
Posted by GitBox <gi...@apache.org>.
zbentley commented on issue #11823:
URL: https://github.com/apache/pulsar/issues/11823#issuecomment-909262051
The contents of my `scratch.py` were the snippet in the description of the bug.
When I run your code exactly as written, I get this output:
```
INFO:foo:Subscribing on Topic :sometopic
INFO:foo:Created connection for pulsar://localhost:6650/
INFO:foo:[127.0.0.1:61188 -> 127.0.0.1:6650] Connected to broker
INFO:foo:[persistent://public/default/sometopic, somesub, 0] Getting connection from pool
INFO:foo:Created connection for pulsar://localhost:6650
INFO:foo:[127.0.0.1:61189 -> 127.0.0.1:6650] Connected to broker through proxy. Logical broker: pulsar://localhost:6650
INFO:foo:[persistent://public/default/sometopic, somesub, 0] Created consumer on broker [127.0.0.1:61189 -> 127.0.0.1:6650]
INFO:foo:[persistent://public/default/sometopic, somesub, 0] Closing consumer for topic persistent://public/default/sometopic
INFO:foo:[persistent://public/default/sometopic, somesub, 0] Closed consumer 0
async returning bar
StopIteration: bar
returned: None
INFO:foo:Closing Pulsar client
INFO:foo:[127.0.0.1:61189 -> 127.0.0.1:6650] Connection closed
INFO:foo:[127.0.0.1:61188 -> 127.0.0.1:6650] Connection closed
```
...after which the code hangs (per the other bug linked).
I'm using python 3.9.6 installed via `brew`, in a clean virtual environment; the only commands I've issued other than venv creation are `pip install pulsar-client` and `pip install fastavro`.
--
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: commits-unsubscribe@pulsar.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [pulsar] zbentley commented on issue #11823: Using the Python pulsar client with a logger can cause arbitrary/unrelated `async` Python functions to return `None`
Posted by GitBox <gi...@apache.org>.
zbentley commented on issue #11823:
URL: https://github.com/apache/pulsar/issues/11823#issuecomment-908458813
@BewareMyPower testing now.
--
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: commits-unsubscribe@pulsar.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [pulsar] zbentley commented on issue #11823: Using the Python pulsar client with a logger can cause arbitrary/unrelated `async` Python functions to return `None`
Posted by GitBox <gi...@apache.org>.
zbentley commented on issue #11823:
URL: https://github.com/apache/pulsar/issues/11823#issuecomment-907623129
> Does removing the call of PyErr_Print really work?
I believe so, though that only solves part of the issue. Without the call to PyErr_Print, return values aren't altered. However, the logger won't work in those situations (destruction after an async return) even without the call to PyErr_Print, as boost::python::call fails before invoking the requested function in that context.
> a temporary solution is to avoid C++ object's destructor in async functions
That does indeed work. However, because the Pulsar client is heavily asynchronous, I don't think that workaround is practical. Consider a big python prorgram with lots of async code that instantiates a Pulsar client globally. Any time that client logs for any reason (not just destructors), there's a chance that the logging action happens while the interpreter is returning from an async function, in which case this bug will occur--even if the async functions running have nothing to do with Pulsar in any way. The case with a destructor is just the most reliable way to encounter this bug, not the only way.
I'm less sure about this, but I think that chance might not be as small as it sounds; it is possible that if the event loop is blocked by something (anything), pending futures whose results have not yet been consumed stay in the StopIteration-exception-pending state until a routine comes along to check on them. If that is the case, then the "coincidence" window where this bug could occur is much wider.
--
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: commits-unsubscribe@pulsar.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [pulsar] BewareMyPower commented on issue #11823: Using the Python pulsar client with a logger can cause arbitrary/unrelated `async` Python functions to return `None`
Posted by GitBox <gi...@apache.org>.
BewareMyPower commented on issue #11823:
URL: https://github.com/apache/pulsar/issues/11823#issuecomment-907569265
@lbenc135 Could you help take a look?
--
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: commits-unsubscribe@pulsar.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [pulsar] zbentley commented on issue #11823: Using the Python pulsar client with a logger can cause arbitrary/unrelated `async` Python functions to return `None`
Posted by GitBox <gi...@apache.org>.
zbentley commented on issue #11823:
URL: https://github.com/apache/pulsar/issues/11823#issuecomment-907522329
Actually, after thinking about it a bit, this may be possible for the Pulsar client to mitigate (though it still seems like a Boost problem fundamentally).
Since `PyErr_Print` mutates interpreter state (clears the global exception bit), calling it in the C++ python bindings is making this bug worse. Without that call, any logger interactions during C++ object destruction would still fail, and some Python internal interpreter errors would be emitted, but things would still generally work.
However, with the call to `PyErr_Print`, other state gets corrupted and return values get messed up.
--
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: commits-unsubscribe@pulsar.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [pulsar] BewareMyPower commented on issue #11823: Using the Python pulsar client with a logger can cause arbitrary/unrelated `async` Python functions to return `None`
Posted by GitBox <gi...@apache.org>.
BewareMyPower commented on issue #11823:
URL: https://github.com/apache/pulsar/issues/11823#issuecomment-908420128
Yeah, I just opened a PR #11840 to fix this issue, PTAL. Since the test cannot be verified in current Python2 based CI, you can verify it in your local env.
--
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: commits-unsubscribe@pulsar.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [pulsar] zbentley commented on issue #11823: Using the Python pulsar client with a logger can cause arbitrary/unrelated `async` Python functions to return `None`
Posted by GitBox <gi...@apache.org>.
zbentley commented on issue #11823:
URL: https://github.com/apache/pulsar/issues/11823#issuecomment-910843883
I did not know about the weekly releases, thanks!
--
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: commits-unsubscribe@pulsar.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [pulsar] BewareMyPower commented on issue #11823: Using the Python pulsar client with a logger can cause arbitrary/unrelated `async` Python functions to return `None`
Posted by GitBox <gi...@apache.org>.
BewareMyPower commented on issue #11823:
URL: https://github.com/apache/pulsar/issues/11823#issuecomment-909320468
--
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: commits-unsubscribe@pulsar.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [pulsar] BewareMyPower commented on issue #11823: Using the Python pulsar client with a logger can cause arbitrary/unrelated `async` Python functions to return `None`
Posted by GitBox <gi...@apache.org>.
BewareMyPower commented on issue #11823:
URL: https://github.com/apache/pulsar/issues/11823#issuecomment-907610190
It's weird that somehow I can reproduce this bug now, the output is
```
async returning bar
StopIteration: bar
returned: None
2021-08-28 19:00:00.107 ERROR [0x700004d1c000] ClientConnection:581 | [127.0.0.1:56560 -> 127.0.0.1:6650] Read failed: Operation canceled
```
--
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: commits-unsubscribe@pulsar.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [pulsar] zbentley commented on issue #11823: Using the Python pulsar client with a logger can cause arbitrary/unrelated `async` Python functions to return `None`
Posted by GitBox <gi...@apache.org>.
zbentley commented on issue #11823:
URL: https://github.com/apache/pulsar/issues/11823#issuecomment-908358590
Confirmed that #10981 does not resolve this issue. That's because the root cause is pretty broad (any time C++ code calls back into Python during a C++ destructor, not just during global finalization, the call fails--and worse, if you then call the standard "print why this failed" python utility function, it corrupts the interpreter frame).
--
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: commits-unsubscribe@pulsar.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [pulsar] BewareMyPower closed issue #11823: Using the Python pulsar client with a logger can cause arbitrary/unrelated `async` Python functions to return `None`
Posted by GitBox <gi...@apache.org>.
BewareMyPower closed issue #11823:
URL: https://github.com/apache/pulsar/issues/11823
--
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: commits-unsubscribe@pulsar.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [pulsar] zbentley commented on issue #11823: Using the Python pulsar client with a logger can cause arbitrary/unrelated `async` Python functions to return `None`
Posted by GitBox <gi...@apache.org>.
zbentley commented on issue #11823:
URL: https://github.com/apache/pulsar/issues/11823#issuecomment-908358590
--
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: commits-unsubscribe@pulsar.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [pulsar] BewareMyPower commented on issue #11823: Using the Python pulsar client with a logger can cause arbitrary/unrelated `async` Python functions to return `None`
Posted by GitBox <gi...@apache.org>.
BewareMyPower commented on issue #11823:
URL: https://github.com/apache/pulsar/issues/11823#issuecomment-907612758
I think a temporary solution is to avoid C++ object's destructor in `async` functions, like
```python
consumer = None
async def async_func(client, rv):
global consumer # use the global variable
consumer = client.subscribe('sometopic', 'somesub')
consumer.close()
print("async returning", rv)
return rv
```
--
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: commits-unsubscribe@pulsar.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [pulsar] zbentley commented on issue #11823: Using the Python pulsar client with a logger can cause arbitrary/unrelated `async` Python functions to return `None`
Posted by GitBox <gi...@apache.org>.
zbentley commented on issue #11823:
URL: https://github.com/apache/pulsar/issues/11823#issuecomment-909421877
Thanks again for the fix!
What's the Pulsar policy on cutting new client releases? Should your bugfix cause publication of updated Python client packages to PyPi, or should that wait until the next main Pulsar release?
Either one is fine, I just want to know whether I should publish a hand-built version of the Python client to my organization's internal package mirror or wait for PyPi to have it.
--
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: commits-unsubscribe@pulsar.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [pulsar] BewareMyPower commented on issue #11823: Using the Python pulsar client with a logger can cause arbitrary/unrelated `async` Python functions to return `None`
Posted by GitBox <gi...@apache.org>.
BewareMyPower commented on issue #11823:
URL: https://github.com/apache/pulsar/issues/11823#issuecomment-907571524
I cannot reproduce this bug in my local env (macOS Big Sur 11.2, Boost-python 1.74). Here's my output:
```
async returning bar
returned: bar
```
I also noticed `PyErr_Print` is only called when exceptions are caught. Does removing the call of `PyErr_Print` really work?
----
BTW, I found https://github.com/apache/pulsar/pull/10981 might fix this issue because the Python client I used was compiled from latest master. Could you also try it?
--
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: commits-unsubscribe@pulsar.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [pulsar] zbentley commented on issue #11823: Using the Python pulsar client with a logger can cause arbitrary/unrelated `async` Python functions to return `None`
Posted by GitBox <gi...@apache.org>.
zbentley commented on issue #11823:
URL: https://github.com/apache/pulsar/issues/11823#issuecomment-909262051
--
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: commits-unsubscribe@pulsar.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [pulsar] BewareMyPower commented on issue #11823: Using the Python pulsar client with a logger can cause arbitrary/unrelated `async` Python functions to return `None`
Posted by GitBox <gi...@apache.org>.
BewareMyPower commented on issue #11823:
URL: https://github.com/apache/pulsar/issues/11823#issuecomment-907940772
Yeah, I tried in my local env that removing `PyErr_Print` works. It's because when the `LoggerWrapper` is constructed in a destructor, `py::call_method` for `logger.getEffectiveLevel` failed and `PyErr_Print` is triggered. I'll push a PR soon.
--
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: commits-unsubscribe@pulsar.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [pulsar] zbentley commented on issue #11823: Using the Python pulsar client with a logger can cause arbitrary/unrelated `async` Python functions to return `None`
Posted by GitBox <gi...@apache.org>.
zbentley commented on issue #11823:
URL: https://github.com/apache/pulsar/issues/11823#issuecomment-909266177
On Python 3.7.10, the bug still occurs, but I get a lot more output, which may be useful:
```
DEBUG:foo:Using Binary Lookup
DEBUG:asyncio:Using selector: KqueueSelector
INFO:foo:Subscribing on Topic :sometopic
INFO:foo:Created connection for pulsar://localhost:6650/
DEBUG:foo:[<none> -> pulsar://localhost:6650/] Connecting to localhost:6650
DEBUG:foo:[<none> -> pulsar://localhost:6650/] Resolved hostname localhost to 127.0.0.1:6650
INFO:foo:[127.0.0.1:61246 -> 127.0.0.1:6650] Connected to broker
DEBUG:foo:[127.0.0.1:61246 -> 127.0.0.1:6650] Handling incoming command: CONNECTED
DEBUG:foo:Connection has max message size setting: 5242880
DEBUG:foo:Current max message size is: 5242880
DEBUG:foo:[127.0.0.1:61246 -> 127.0.0.1:6650] Handling incoming command: PARTITIONED_METADATA_RESPONSE
DEBUG:foo:[127.0.0.1:61246 -> 127.0.0.1:6650] Received partition-metadata response from server. req_id: 1
DEBUG:foo:PartitionMetadataLookup response for persistent://public/default/sometopic, lookup-broker-url
DEBUG:foo:BatchAcknowledgementTracker for [persistent://public/default/sometopic, somesub, 0] Constructed BatchAcknowledgementTracker
DEBUG:foo:Created negative ack tracker with delay: 60000 ms - Timer interval: 00:00:20
INFO:foo:[persistent://public/default/sometopic, somesub, 0] Getting connection from pool
DEBUG:foo:Got connection from pool for pulsar://localhost:6650/ use_count: 4 @ 0x7fdffc820200
DEBUG:foo:ACK grouping is enabled, grouping time 100ms, grouping max size 1000
DEBUG:foo:[127.0.0.1:61246 -> 127.0.0.1:6650] Handling incoming command: LOOKUP_RESPONSE
DEBUG:foo:[127.0.0.1:61246 -> 127.0.0.1:6650] Received lookup response from server. req_id: 2
DEBUG:foo:[127.0.0.1:61246 -> 127.0.0.1:6650] Received lookup response from server. req_id: 2 -- broker-url: pulsar://localhost:6650 -- broker-tls-url: authoritative: 1 redirect: 1
DEBUG:foo:Lookup response for persistent://public/default/sometopic, lookup-broker-url pulsar://localhost:6650
DEBUG:foo:Getting connection to broker: pulsar://localhost:6650
INFO:foo:Created connection for pulsar://localhost:6650
DEBUG:foo:[<none> -> pulsar://localhost:6650/] Connecting to localhost:6650
DEBUG:foo:[<none> -> pulsar://localhost:6650/] Resolved hostname localhost to 127.0.0.1:6650
INFO:foo:[127.0.0.1:61247 -> 127.0.0.1:6650] Connected to broker through proxy. Logical broker: pulsar://localhost:6650
DEBUG:foo:[127.0.0.1:61247 -> 127.0.0.1:6650] Handling incoming command: CONNECTED
DEBUG:foo:Connection has max message size setting: 5242880
DEBUG:foo:Current max message size is: 5242880
DEBUG:foo:[persistent://public/default/sometopic, somesub, 0] Connected to broker: [127.0.0.1:61247 -> 127.0.0.1:6650]
DEBUG:foo:[127.0.0.1:61247 -> 127.0.0.1:6650] Handling incoming command: SUCCESS
DEBUG:foo:[127.0.0.1:61247 -> 127.0.0.1:6650] Received success response from server. req_id: 0
INFO:foo:[persistent://public/default/sometopic, somesub, 0] Created consumer on broker [127.0.0.1:61247 -> 127.0.0.1:6650]
DEBUG:foo:[persistent://public/default/sometopic, somesub, 0] Send initial flow permits: 1000
DEBUG:foo:[persistent://public/default/sometopic, somesub, 0] Send more permits: 1000
INFO:foo:[persistent://public/default/sometopic, somesub, 0] Closing consumer for topic persistent://public/default/sometopic
DEBUG:foo:[127.0.0.1:61247 -> 127.0.0.1:6650] Handling incoming command: SUCCESS
DEBUG:foo:[127.0.0.1:61247 -> 127.0.0.1:6650] Received success response from server. req_id: 1
INFO:foo:[persistent://public/default/sometopic, somesub, 0] Closed consumer 0
async returning bar
StopIteration: bar
The above exception was the direct cause of the following exception:
Traceback (most recent call last):
File "/Users/zac.bentley/.pyenv/versions/3.7.10/lib/python3.7/logging/__init__.py", line 1365, in debug
if self.isEnabledFor(DEBUG):
SystemError: PyEval_EvalFrameEx returned a result with an error set
DEBUG:foo:Reference to the HandlerBase is not valid.
DEBUG:foo:Ignoring timer cancelled event, code[system:89]
returned: None
INFO:foo:Closing Pulsar client
INFO:foo:[127.0.0.1:61247 -> 127.0.0.1:6650] Connection closed
INFO:foo:[127.0.0.1:61246 -> 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: commits-unsubscribe@pulsar.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [pulsar] zbentley commented on issue #11823: Using the Python pulsar client with a logger can cause arbitrary/unrelated `async` Python functions to return `None`
Posted by GitBox <gi...@apache.org>.
zbentley commented on issue #11823:
URL: https://github.com/apache/pulsar/issues/11823#issuecomment-908700292
Additionally, in the process of debugging this issue, I found a couple more issues related to the `logger` argument in Python.
- Annoying/potentially damages logging integrity (medium/low severity for me, unsure about others): https://github.com/apache/pulsar/issues/11845
- Extremely problematic for any affected code (high severity for me, likely others too unless there is something about my installation that is very unique): https://github.com/apache/pulsar/issues/11847
--
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: commits-unsubscribe@pulsar.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [pulsar] BewareMyPower commented on issue #11823: Using the Python pulsar client with a logger can cause arbitrary/unrelated `async` Python functions to return `None`
Posted by GitBox <gi...@apache.org>.
BewareMyPower commented on issue #11823:
URL: https://github.com/apache/pulsar/issues/11823#issuecomment-909320468
--
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: commits-unsubscribe@pulsar.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [pulsar] BewareMyPower commented on issue #11823: Using the Python pulsar client with a logger can cause arbitrary/unrelated `async` Python functions to return `None`
Posted by GitBox <gi...@apache.org>.
BewareMyPower commented on issue #11823:
URL: https://github.com/apache/pulsar/issues/11823#issuecomment-908841015
I found the second issue as well. We can take a look at these two issues later.
Regarding to this issue, could you upload you code `scratch.py` to reproduce? In my local env, `custom_logger_test.py` and the code in this PR work well. Here's my code with debug level logging.
```python
import faulthandler
import asyncio
import logging
from pulsar import Client
def test():
client = Client(
service_url='pulsar://localhost:6650/',
logger=logging.getLogger("foo")
)
async def async_func(rv):
consumer = client.subscribe('sometopic', 'somesub')
consumer.close()
print("async returning", rv)
return rv
print("returned:", asyncio.run(async_func("bar")))
client.close()
if __name__ == '__main__':
faulthandler.enable()
logging.basicConfig(encoding='utf-8', level=logging.DEBUG)
test()
```
When I ran it, the output was like
```
async returning bar
2021-08-31 10:10:38.706 DEBUG [0x10afd1e00] ConsumerImpl:106 | [persistent://public/default/sometopic, somesub, 0] ~ConsumerImpl
2021-08-31 10:10:38.706 DEBUG [0x10afd1e00] AckGroupingTrackerEnabled:100 | Reference to the HandlerBase is not valid.
DEBUG:foo:Ignoring timer cancelled event, code[system:89]
returned: bar
```
You can see there're two lines that use the default logger.
In your output, we can still see `StopIteration: bar` that should be printed by `PyErr_Print`. I didn't remove all `PyErr_Print` calls because I think they won't happen in some destructors. If you can provide code to reproduce, I can debug deeper for the cause.
--
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: commits-unsubscribe@pulsar.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [pulsar] zbentley commented on issue #11823: Using the Python pulsar client with a logger can cause arbitrary/unrelated `async` Python functions to return `None`
Posted by GitBox <gi...@apache.org>.
zbentley commented on issue #11823:
URL: https://github.com/apache/pulsar/issues/11823#issuecomment-909399309
> How did you build the C++ library?
I didn't; `pip install pulsar-client` does not by default invoke the compiler. Instead, it downloads [wheels](https://packaging.python.org/guides/distributing-packages-using-setuptools/#wheels) of precompiled artifacts that were submitted by project maintainers.
However, the usual means of overriding this (`pip install pulsar-client --no-binary :all:`) does not work for me:
```
∴ pip install pulsar-client --no-binary :all:
ERROR: Could not find a version that satisfies the requirement pulsar-client (from versions: none)
ERROR: No matching distribution found for pulsar-client
```
I think this means that source artifacts are not published to PyPi, which may be a separate issue. Do you think I should open one?
Anyway, I installed protoc and googletest via Homebrew and ran your build instructions (I didn't have to set `DCMAKE_PREFIX_PATH`, but otherwise I did everything else the same).
Both tests passed on your branch! I feel very stupid for not fixing up my pathing to use my client compiled against your branch; very sorry for wasting your time with the back-and-forth.
--
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: commits-unsubscribe@pulsar.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [pulsar] zbentley commented on issue #11823: Using the Python pulsar client with a logger can cause arbitrary/unrelated `async` Python functions to return `None`
Posted by GitBox <gi...@apache.org>.
zbentley commented on issue #11823:
URL: https://github.com/apache/pulsar/issues/11823#issuecomment-907520647
Since this is a reasonably subtle and silent bug when it occurs, I suggest removing client support for a user-supplied `logger`.
That breaks backwards compatibility, and is not to be undertaken lightly, but the risk otherwise seems pretty significant: the bug surface is the intersection of "a custom logger is in use", "any `async` python function is running in my program, anywhere" and "any pulsar C++ object is destructed anywhere in the program". That's not good.
--
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: commits-unsubscribe@pulsar.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org