Segmentation fault sometimes happens when running unit tests

[BewareMyPower]

Segmentation fault sometimes happens when running unit tests

[BewareMyPower]

2024-03-12 02:35:31.040 INFO  [140455429797440] RetryableOperation:114 | Reschedule get-partition-metadata-persistent://public/default/partitioned_topic_name_test for 100 ms, remaining time: 29900 ms
2024-03-12 02:35:31.040 DEBUG [140455429797440] ExecutorService:44 | Event loop of ExecutorService exits successfully
2024-03-12 02:35:31.040 DEBUG [140457878760320] ClientImpl:775 | listenerExecutorProvider_ is closed
2024-03-12 02:35:31.040 DEBUG [140457878760320] ClientImpl:780 | partitionListenerExecutorProvider_ is closed
2024-03-12 02:35:31.041 DEBUG [140457878760320] ProducerImpl:117 | [persistent://public/default/partitioned_topic_name_test-partition-0, standalone-0-53] ~ProducerImpl
2024-03-12 02:35:31.041 INFO  [140457878760320] ProducerImpl:757 | Producer - [persistent://public/default/partitioned_topic_name_test-partition-0, standalone-0-53] , [batching  = off]
2024-03-12 02:35:31.041 DEBUG [140457878760320] ProducerImpl:117 | [persistent://public/default/partitioned_topic_name_test-partition-1, standalone-0-54] ~ProducerImpl
2024-03-12 02:35:31.041 INFO  [140457878760320] ProducerImpl:757 | Producer - [persistent://public/default/partitioned_topic_name_test-partition-1, standalone-0-54] , [batching  = off]
2024-03-12 02:35:31.041 DEBUG [140457878760320] ProducerImpl:117 | [persistent://public/default/partitioned_topic_name_test-partition-2, standalone-0-55] ~ProducerImpl
2024-03-12 02:35:31.041 INFO  [140457878760320] ProducerImpl:757 | Producer - [persistent://public/default/partitioned_topic_name_test-partition-2, standalone-0-55] , [batching  = off]
# another test...
2024-03-12 02:35:31.140 DEBUG [140455413016128] RetryableOperation:129 | Run operation get-partition-metadata-persistent://public/default/partitioned_topic_name_test, remaining time: 29900 ms

It seems that the RetryableOperation is still scheduled after client.close() is called.

[BewareMyPower]

The root cause might be an incorrect implementation of the shutdown of a partitioned producer.

Here are the output when I ran PulsarTest.test_shutdown_client with debug level logs:

2024-03-12 15:09:35.278 DEBUG [0x1e4d42100] ClientImpl:699 | 1 producers and 0 consumers have been shutdown.
2024-03-12 15:09:35.278 DEBUG [0x16df5f000] ConnectionPool:86 | Got connection from pool for pulsar://localhost:6650-0 use_count: 2 @ 0x15ca15e00
2024-03-12 15:09:35.278 INFO  [0x1e4d42100] ClientConnection:1325 | [127.0.0.1:63468 -> 127.0.0.1:6650] Connection disconnected (refCnt: 2)
2024-03-12 15:09:35.278 DEBUG [0x16de47000] ClientConnection:1262 | [127.0.0.1:63468 -> 127.0.0.1:6650]  Ignoring timer cancelled event, code[system:89]
2024-03-12 15:09:35.278 INFO  [0x1e4d42100] HandlerBase:150 | [persistent://public/default/partitioned_topic_name_test-partition-0, standalone-155-58] Schedule reconnection in 0.1 s
2024-03-12 15:09:35.279 INFO  [0x1e4d42100] HandlerBase:150 | [persistent://public/default/partitioned_topic_name_test-partition-1, standalone-155-59] Schedule reconnection in 0.1 s
2024-03-12 15:09:35.279 DEBUG [0x16df5f000] BinaryProtoLookupService:148 | PartitionMetadataLookup failed for persistent://public/default/partitioned_topic_name_test, result NotConnected
2024-03-12 15:09:35.279 INFO  [0x1e4d42100] HandlerBase:150 | [persistent://public/default/partitioned_topic_name_test-partition-2, standalone-155-60] Schedule reconnection in 0.1 s

As you can see the internal producers still scheduled reconnections after shutdown.

After using another topic name in test_shutdown_client, no reconnection happened:

024-03-12 15:20:36.796 DEBUG [0x1e4d42100] ClientImpl:699 | 1 producers and 0 consumers have been shutdown.
2024-03-12 15:20:36.796 INFO  [0x1e4d42100] ClientConnection:1325 | [127.0.0.1:63850 -> 127.0.0.1:6650] Connection disconnected (refCnt: 1)
2024-03-12 15:20:36.796 DEBUG [0x1e4d42100] ClientImpl:705 | ConnectionPool is closed
2024-03-12 15:20:36.796 DEBUG [0x16fd93000] ClientConnection:1262 | [127.0.0.1:63850 -> 127.0.0.1:6650]  Ignoring timer cancelled event, code[system:89]
2024-03-12 15:20:36.796 INFO  [0x16fd93000] ClientConnection:274 | [127.0.0.1:63850 -> 127.0.0.1:6650] Destroyed connection to pulsar://localhost:6650-0
2024-03-12 15:20:36.796 DEBUG [0x16fd93000] ExecutorService:44 | Event loop of ExecutorService exits successfully
2024-03-12 15:20:36.796 DEBUG [0x1e4d42100] ClientImpl:715 | ioExecutorProvider_ is closed
2024-03-12 15:20:36.796 DEBUG [0x1e4d42100] ClientImpl:720 | listenerExecutorProvider_ is closed
2024-03-12 15:20:36.796 DEBUG [0x1e4d42100] ClientImpl:725 | partitionListenerExecutorProvider_ is closed