Skip to content

Pulsar client with custom logger may not terminate gracefully when a producer is created #256

Open

Description

@tzvi-shir-vaknin

When providing a custom logger to the Pulsar client and creating a producer, intermittent terminations occur with the following error:

terminate called without an active exception
Aborted (core dumped)

This doesn't happen consistently; I'd estimate it occurs in about 1 out of 20 runs. The other executions complete gracefully as expected. As the setup here is almost exactly as in #194, I've tried adding the del statements suggested there, but that hasn't resolved the issue for me.

Here is the Python script I'm using:

import logging
import pulsar


def open_and_close():
    pulsar_logger = logging.getLogger("pulsarDummyLogger")
    client = pulsar.Client("pulsar://localhost:6650", logger=pulsar_logger)
    producer = client.create_producer("A")
    producer.close()
    client.close()
    del producer
    del client


if __name__ == "__main__":
    open_and_close()

I'm running it using the following bash command (as it doesn't happen all the time, I must run it a few times to encounter it):

for i in {1..20}; do env/bin/python python_script.py || break; done

I tried it on python 3.11.3 and on 3.13.3, as well as with pulsar-client 3.5.0, 3.6.0, 3.6.1, 3.7.0.

Any insights or suggestions would be greatly appreciated

Activity

  1. BewareMyPower commented on May 22, 2025

    @BewareMyPower
    Contributor

    I cannot reproduce it on macOS or Ubuntu 22.04 docker container (localhost is changed to host.docker.internal).

    (venv) root@bdbb571df90b:~# for i in {1..100}; do python3 python_script.py || break; done
    (venv) root@bdbb571df90b:~# python3 --version
    Python 3.12.3
    (venv) root@bdbb571df90b:~# python3 -c 'import pulsar; print(pulsar.__version__)'
    3.7.0
  2. BewareMyPower commented on May 22, 2025

    @BewareMyPower
    Contributor

    Oh I can reproduced it with another round of tests with the INFO log enabled:

        logging.basicConfig(level=logging.INFO)
    INFO:pulsarDummyLogger:[<none> -> pulsar://host.docker.internal:6650] Create ClientConnection, timeout=10000
    INFO:pulsarDummyLogger:Created connection for pulsar://host.docker.internal:6650-pulsar://host.docker.internal:6650-0
    INFO:pulsarDummyLogger:[172.17.0.2:45444 -> 192.168.65.254:6650] Connected to broker
    INFO:pulsarDummyLogger:[persistent://public/default/A, ] Getting connection from pool
    INFO:pulsarDummyLogger:Lookup response for persistent://public/default/A, lookup-broker-url pulsar://localhost:6650, from [172.17.0.2:45444 -> 192.168.65.254:6650] 
    INFO:pulsarDummyLogger:[<none> -> pulsar://host.docker.internal:6650] Create ClientConnection, timeout=10000
    INFO:pulsarDummyLogger:Created connection for pulsar://localhost:6650-pulsar://host.docker.internal:6650-0
    INFO:pulsarDummyLogger:[172.17.0.2:45458 -> 192.168.65.254:6650] Connected to broker through proxy. Logical broker: pulsar://localhost:6650, proxy: , physical address:pulsar://host.docker.internal:6650
    INFO:pulsarDummyLogger:Creating producer for topic:persistent://public/default/A, producerName: on [172.17.0.2:45458 -> 192.168.65.254:6650] 
    INFO:pulsarDummyLogger:[persistent://public/default/A, ] Created producer on broker [172.17.0.2:45458 -> 192.168.65.254:6650] 
    INFO:pulsarDummyLogger:Finished connecting to broker after 3 ms
    INFO:pulsarDummyLogger:[persistent://public/default/A, standalone-0-479] Closing producer for topic persistent://public/default/A
    INFO:pulsarDummyLogger:[persistent://public/default/A, standalone-0-479] Closed producer 0
    INFO:pulsarDummyLogger:Closing Pulsar client with 0 producers and 0 consumers
    INFO:pulsarDummyLogger:[172.17.0.2:45444 -> 192.168.65.254:6650] Connection disconnected (refCnt: 1)
    INFO:pulsarDummyLogger:[172.17.0.2:45458 -> 192.168.65.254:6650] Connection disconnected (refCnt: 1)
    INFO:pulsarDummyLogger:[172.17.0.2:45444 -> 192.168.65.254:6650] Destroyed connection to pulsar://host.docker.internal:6650-0
    INFO:pulsarDummyLogger:[172.17.0.2:45458 -> 192.168.65.254:6650] Destroyed connection to pulsar://localhost:6650-0
    INFO:pulsarDummyLogger:Producer - [persistent://public/default/A, standalone-0-479] , [batching  = off]
    terminate called without an active exception
    1.sh: line 1:  6356 Aborted                 python3 python_script.py
    

    Let me assign it to myself

  3. BewareMyPower commented on May 22, 2025

    @BewareMyPower
    Contributor

    It seems that there is a rare chance that the shutdown thread failed to exit.

    [New Thread 0xfffff4c0f180 (LWP 6877)]
    INFO:pulsarDummyLogger:[172.17.0.2:39146 -> 192.168.65.254:6650] Connection disconnected (refCnt: 1)
    INFO:pulsarDummyLogger:[172.17.0.2:39152 -> 192.168.65.254:6650] Connection disconnected (refCnt: 2)
    INFO:pulsarDummyLogger:[172.17.0.2:39146 -> 192.168.65.254:6650] Destroyed connection to pulsar://host.docker.internal:6650-0
    INFO:pulsarDummyLogger:Producer - [persistent://public/default/A, standalone-0-522] , [batching  = off]
    [Thread 0xfffff600f180 (LWP 6875) exited]
    INFO:pulsarDummyLogger:[172.17.0.2:39152 -> 192.168.65.254:6650] Destroyed connection to pulsar://localhost:6650-0
    [Thread 0xfffff560f180 (LWP 6876) exited]
    terminate called without an active exception
    

    From the logs above from GDB, LWP 6877, which is the shutdown thread introduced in apache/pulsar#15316, didn't exit when the exception was thrown.

            std::thread shutdownTask{[this, self, callback] {
                shutdown();
                // ...

    I added a log after client.close() and enabled debug level logs:

        print('client is closed')
        del producer
        del client
    DEBUG:pulsarDummyLogger:ioExecutorProvider_ is closed
    DEBUG:pulsarDummyLogger:listenerExecutorProvider_ is closed
    DEBUG:pulsarDummyLogger:partitionListenerExecutorProvider_ is closed
    client is closed
    DEBUG:pulsarDummyLogger:[persistent://public/default/A, standalone-0-631] ~ProducerImpl
    INFO:pulsarDummyLogger:Producer - [persistent://public/default/A, standalone-0-631] , [batching  = off]
    terminate called without an active exception
    

    The most possible reason is that the shutdown thread didn't exit when the Python interpreter exited. It might need a fix from the C++ client side.


    While I might need more time to figure out a fix and verify if it works, I thought of a more tricky workaround and found it worked.

        client.close()
        time.sleep(0.01) # The trick is here that wait for some time until the shutdown thread is finished
        del producer # This line is actually not necessary
        del client

    Could you verify it?

  4. tzvi-shir-vaknin commented on May 22, 2025

    @tzvi-shir-vaknin
    Author

    Thanks for looking into this and suggesting a temporary solution! Your time and effort are greatly appreciated.

    Yes, adding the timeout does resolve the immediate issue. Thank you!

    For my specific use case, I'd prefer to stick with the default Pulsar logger at the ERROR level. This would keep logs minimal, appearing only in rare error scenarios, rather than implementing a timeout each time I close the client.

    I hope you'll be able to address the root cause of this issue soon.

    Thanks again!

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

Labels

No labels
No labels

Type

No type

Projects

No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions