apache / apache/pulsar

[Bug] function Interrupted for unknown reasons

Open
#21,803 1 comment 0 reactions 0 assignees View on GitHub
type/bug
Dominant language
Java
Stars
15.3k
Forks
3.8k
Avg merge
1d 14h
Merged PRs (30d)
160

Description

### Search before asking

- [X] I searched in the [issues](https://github.com/apache/pulsar/issues) and found nothing similar.

### Version

Pulsar & Function 3.1.1

### Minimal reproduce step

running with effectively once

### What did you expect to see?

function can handle InterruptedException

### What did you see instead?

When function is running, the following exception will occasionally occur, and function reading and writing are stuck.

```java
023-12-19T23:55:03,134+0800 [pulsar-external-listener-6-1] ERROR org.apache.pulsar.client.impl.ConsumerBase - [persistent://pulsar/log_Production/alltables-partition-13][sink-v2] Message listener error in processing message: 777380:54372:13
java.lang.RuntimeException: java.lang.InterruptedException
at org.apache.pulsar.functions.source.PushPulsarSource.consume(PushPulsarSource.java:64) ~[io.streamnative-pulsar-functions-instance-3.0.1.3.jar:3.0.1.3]
at org.apache.pulsar.functions.source.MultiConsumerPulsarSource.received(MultiConsumerPulsarSource.java:81) ~[io.streamnative-pulsar-functions-instance-3.0.1.3.jar:3.0.1.3]
at org.apache.pulsar.client.impl.ConsumerBase.callMessageListener(ConsumerBase.java:1153) ~[io.streamnative-pulsar-client-original-3.0.1.3.jar:3.0.1.3]
at org.apache.pulsar.client.impl.ConsumerBase.lambda$triggerListener$10(ConsumerBase.java:1119) ~[io.streamnative-pulsar-client-original-3.0.1.3.jar:3.0.1.3]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136) ~[?:?]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635) ~[?:?]
at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) ~[io.netty-netty-common-4.1.94.Final.jar:4.1.94.Final]
at java.lang.Thread.run(Thread.java:833) ~[?:?]
Caused by: java.lang.InterruptedException
at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:1638) ~[?:?]
at java.util.concurrent.LinkedBlockingQueue.put(LinkedBlockingQueue.java:343) ~[?:?]
at org.apache.pulsar.functions.source.PushPulsarSource.consume(PushPulsarSource.java:62) ~[io.streamnative-pulsar-functions-instance-3.0.1.3.jar:3.0.1.3]
... 7 more
```

According to the log, the close interface was called and the client was closed.
```java
2023-12-27T10:01:14,985+0800 [Thread-3] INFO function-functions-pro - start to close all the producers
2023-12-27T10:01:14,988+0800 [Thread-3] INFO function-functions-pro - finish to close all the producers
2023-12-27T10:01:14,988+0800 [Thread-3] INFO org.apache.pulsar.client.impl.PulsarClientImpl - Client closing. URL: pulsar://21.24.16.111:6650
2023-12-27T10:01:14,988+0800 [pulsar/log_Production/functions-pro-0] INFO org.apache.pulsar.functions.instance.JavaInstanceRunnable - Encountered exception in sink write:
org.apache.pulsar.client.api.PulsarClientException: java.lang.InterruptedException
org.apache.pulsar.client.api.PulsarClientException.unwrap(PulsarClientException.java:1031) ~[java-instance.jar:?]
org.apache.pulsar.client.impl.ProducerBuilderImpl.create(ProducerBuilderImpl.java:89) ~[io.streamnative-pulsar-client-original-3.0.1.3.jar:3.0.1.3]
com.tencent.DynamicTopicSink.getProducer(DynamicTopicSink.java:164) ~[8Ia5QqpY9lE3mwskma2zRA/:?]
com.tencent.DynamicTopicSink.write(DynamicTopicSink.java:142) ~[8Ia5QqpY9lE3mwskma2zRA/:?]
org.apache.pulsar.functions.instance.JavaInstanceRunnable.sendOutputMessage(JavaInstanceRunnable.java:429) ~[io.streamnative-pulsar-functions-instance-3.0.1.3.jar:?]
org.apache.pulsar.functions.instance.JavaInstanceRunnable.handleResult(JavaInstanceRunnable.java:391) ~[io.streamnative-pulsar-functions-instance-3.0.1.3.jar:?]
org.apache.pulsar.functions.instance.JavaInstanceRunnable.run(JavaInstanceRunnable.java:331) ~[io.streamnative-pulsar-functions-instance-3.0.1.3.jar:?]
java.lang.Thread.run(Thread.java:833) ~[?:?]
Caused by: java.lang.InterruptedException
java.util.concurrent.CompletableFuture.reportGet(CompletableFuture.java:386) ~[?:?]
java.util.concurrent.CompletableFuture.get(CompletableFuture.java:2073) ~[?:?]
org.apache.pulsar.client.impl.ProducerBuilderImpl.create(ProducerBuilderImpl.java:87) ~[io.streamnative-pulsar-client-original-3.0.1.3.jar:3.0.1.3]
\t... 6 more
2023-12-27T10:01:14,989+0800 [pulsar-client-io-17-5] INFO org.apache.pulsar.client.impl.ProducerImpl - [persistent://pulsar/log_Production/EquipInfo-partition-3] [sink-EquipInfo] Closed Producer
2023-12-27T10:01:14,989+0800 [Thread-3] INFO org.apache.pulsar.client.impl.ProducerImpl - [persistent://pulsar/log_Production/CombatEffectivenessFlow-partition-4] [sink-CombatEffectivenessFlow] Closed Producer (not connected)
2023-12-27T10:01:14,990+0800 [Thread-3] INFO org.apache.pulsar.client.impl.ProducerImpl - [persistent://pulsar/log_Production/CombatEffectivenessFlow-partition-1] [sink-CombatEffectivenessFlow] Closed Producer (not connected)
2023-12-27T10:01:14,990+0800 [Thread-3] INFO org.apache.pulsar.client.impl.ProducerImpl - [persistent://pulsar/log_Production/CombatEffectivenessFlow-partition-3] [sink-CombatEffectivenessFlow] Closed Producer (not connected)
2023-12-27T10:01:14,990+0800 [Thread-3] INFO org.apache.pulsar.client.impl.ProducerImpl - [persistent://pulsar/log_Production/CombatEffectivenessFlow-partition-2] [sink-CombatEffectivenessFlow] Closed Producer (not connected)
2023-12-27T10:01:14,990+0800 [pulsar-client-io-17-5] INFO org.apache.pulsar.client.impl.ProducerImpl - [persistent://pulsar/log_Production/shenqibianhua-partition-4] [sink-shenqibianhua] Closed Producer
2023-12-27T10:01:14,990+0800 [pulsar-client-io-17-5] INFO org.apache.pulsar.client.impl.ProducerImpl - [persistent://pulsar/log_Production/shenqibianhua-partition-1] [sink-shenqibianhua] Closed Producer
....
2023-12-27T10:01:14,991+0800 [pulsar-client-io-17-9] INFO org.apache.pulsar.client.impl.ProducerImpl - [persistent://pulsar/log_Production/EquipInfo-partition-0] [sink-EquipInfo] Closed Producer
2023-12-27T10:01:14,991+0800 [pulsar-client-io-17-7] INFO org.apache.pulsar.client.impl.PartitionedProducerImpl - [persistent://pulsar/log_Production/shenqibianhua] Closed Partitioned Producer
2023-12-27T10:01:14,991+0800 [pulsar-client-io-17-9] INFO org.apache.pulsar.client.impl.PartitionedProducerImpl - [persistent://pulsar/log_Production/EquipInfo] Closed Partitioned Producer
2023-12-27T10:01:14,991+0800 [pulsar/log_Production/functions-pro-0] ERROR org.apache.pulsar.functions.instance.JavaInstanceRunnable - [pulsar/log_Production/functions-pro:0] Uncaught exception in Java Instance
java.lang.RuntimeException: Failed to process message: 1306487:441847:0
org.apache.pulsar.functions.source.PulsarSource.lambda$buildRecord$6(PulsarSource.java:155) ~[io.streamnative-pulsar-functions-instance-3.0.1.3.jar:3.0.1.3]
org.apache.pulsar.functions.source.PulsarRecord.fail(PulsarRecord.java:133) ~[io.streamnative-pulsar-functions-instance-3.0.1.3.jar:3.0.1.3]
org.apache.pulsar.functions.instance.JavaInstanceRunnable.sendOutputMessage(JavaInstanceRunnable.java:434) ~[io.streamnative-pulsar-functions-instance-3.0.1.3.jar:?]
org.apache.pulsar.functions.instance.JavaInstanceRunnable.handleResult(JavaInstanceRunnable.java:391) ~[io.streamnative-pulsar-functions-instance-3.0.1.3.jar:?]
org.apache.pulsar.functions.instance.JavaInstanceRunnable.run(JavaInstanceRunnable.java:331) ~[io.streamnative-pulsar-functions-instance-3.0.1.3.jar:?]
java.lang.Thread.run(Thread.java:833) ~[?:?]
2023-12-27T10:01:14,991+0800 [pulsar-client-io-17-7] INFO org.apache.pulsar.client.impl.ProducerImpl - [persistent://pulsar/log_Production/ShiMenMission-partition-3] [sink-ShiMenMission] Closed Producer
```
I override the close interface

```java
@Override
public void close() throws Exception {
logger.info("start to close all the producers");
closeProducer();
closeClient();
}

public void closeProducer() {
List> closeFutures = new ArrayList<>(producerMap.size());
try {
for (Map.Entry> entry : producerMap.entrySet()) {
Producer producer = entry.getValue();
closeFutures.add(producer.closeAsync());
producerMap.clear();
}
org.apache.pulsar.common.util.FutureUtil.waitForAll(closeFutures);
logger.info("finish to close all the producers");
} catch (Exception e) {
logger.warn("Failed to close all the producers", e);
}
}

public void closeClient() {
List> closeFutures = new ArrayList<>(10);
try {
closeFutures.add(pulsarClient.closeAsync());
org.apache.pulsar.common.util.FutureUtil.waitForAll(closeFutures);
logger.info("finish to close all the client");
} catch (Exception e) {
logger.warn("Failed to close all the producers", e);
}
}
```

### Anything else?

_No response_

### Are you willing to submit a PR?

- [ ] I'm willing to submit a PR!

[error.log](https://github.com/apache/pulsar/files/13792035/error.log)

Contributor guide

Open the contributing guide

Research direction

Start with the reported stack traces in PushPulsarSource.java, MultiConsumerPulsarSource.java, and JavaInstanceRunnable.java, then compare them with the shutdown sequence in the custom close methods. Reproduce the interruption while running an effectively-once function and determine how shutdown affects function reads and writes; done means the interruption behavior is understood and the stuck-processing failure is addressed.

Written by the indexing model from the issue text.

Assessment

Tech stack
java
Domain
backend, distributed-systems, stream-processing
Issue type
Bug
Difficulty
4/5
Estimated time
3-5 days
Activity status
Stale
Clarity
Needs clarification
Newbie friendliness
25/100

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.