search

streamnative / pulsar-archived

Apache Pulsar - distributed pub-sub messaging system
https://pulsar.apache.org
Apache License 2.0
72 stars 25 forks source link

ISSUE-5099: "ConnectException: Connection refused: /127.0.0.1:49695" when running python example function #443

Open sijie opened 4 years ago

sijie commented 4 years ago

Original Issue: apache/pulsar#5099

Describe the bug "ConnectException: Connection refused: /127.0.0.1:49695" when running python example function...the function got failed.....

To Reproduce

  1. start a standalone Pulsar on my MAC
  2. run a python function example - "ExclamationFunction" of built-in examples bin/pulsar-admin functions localrun --py /examples/python-examples/exclamation_function.py --classname ExclamationFunction --inputs persistent://public/default/exclamation-input --output persistent://public/default/exclamation-output --name exclamation

btw: the same problem occurs in cluster mode...just replace "localrun" with "create"

  1. the exception logs as follows: 
    13:18:37.355 [main] INFO  org.apache.pulsar.functions.runtime.ProcessRuntime - Started process successfully
13:18:37.689 [main] INFO  org.apache.pulsar.functions.LocalRunner - RuntimeSpawner quit because of
13:19:08.111 [function-timer-thread-3-1] ERROR org.apache.pulsar.functions.runtime.ProcessRuntime - Health check failed for exclamation-0
java.util.concurrent.ExecutionException: io.grpc.StatusRuntimeException: UNAVAILABLE: io exception
    at java.util.concurrent.CompletableFuture.reportGet(CompletableFuture.java:357) ~[?:1.8.0_211]
    at java.util.concurrent.CompletableFuture.get(CompletableFuture.java:1895) ~[?:1.8.0_211]
    at org.apache.pulsar.functions.runtime.ProcessRuntime.lambda$start$1(ProcessRuntime.java:164) ~[org.apache.pulsar-pulsar-functions-runtime-2.4.0.jar:2.4.0]
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [?:1.8.0_211]
    at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308) [?:1.8.0_211]
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180) [?:1.8.0_211]
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294) [?:1.8.0_211]
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_211]
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_211]
    at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) [io.netty-netty-all-4.1.32.Final.jar:4.1.32.Final]
    at java.lang.Thread.run(Thread.java:748) [?:1.8.0_211]
Caused by: io.grpc.StatusRuntimeException: UNAVAILABLE: io exception
    at io.grpc.Status.asRuntimeException(Status.java:530) ~[io.grpc-grpc-core-1.18.0.jar:1.18.0]
    at io.grpc.stub.ClientCalls$UnaryStreamToFuture.onClose(ClientCalls.java:482) ~[io.grpc-grpc-stub-1.18.0.jar:1.18.0]
    at io.grpc.PartialForwardingClientCallListener.onClose(PartialForwardingClientCallListener.java:39) ~[io.grpc-grpc-core-1.18.0.jar:1.18.0]
    at io.grpc.ForwardingClientCallListener.onClose(ForwardingClientCallListener.java:23) ~[io.grpc-grpc-core-1.18.0.jar:1.18.0]
    at io.grpc.ForwardingClientCallListener$SimpleForwardingClientCallListener.onClose(ForwardingClientCallListener.java:40) ~[io.grpc-grpc-core-1.18.0.jar:1.18.0]
    at io.grpc.internal.CensusStatsModule$StatsClientInterceptor$1$1.onClose(CensusStatsModule.java:699) ~[io.grpc-grpc-core-1.18.0.jar:1.18.0]
    at io.grpc.PartialForwardingClientCallListener.onClose(PartialForwardingClientCallListener.java:39) ~[io.grpc-grpc-core-1.18.0.jar:1.18.0]
    at io.grpc.ForwardingClientCallListener.onClose(ForwardingClientCallListener.java:23) ~[io.grpc-grpc-core-1.18.0.jar:1.18.0]
    at io.grpc.ForwardingClientCallListener$SimpleForwardingClientCallListener.onClose(ForwardingClientCallListener.java:40) ~[io.grpc-grpc-core-1.18.0.jar:1.18.0]
    at io.grpc.internal.CensusTracingModule$TracingClientInterceptor$1$1.onClose(CensusTracingModule.java:397) ~[io.grpc-grpc-core-1.18.0.jar:1.18.0]
    at io.grpc.internal.ClientCallImpl.closeObserver(ClientCallImpl.java:459) ~[io.grpc-grpc-core-1.18.0.jar:1.18.0]
    at io.grpc.internal.ClientCallImpl.access$300(ClientCallImpl.java:63) ~[io.grpc-grpc-core-1.18.0.jar:1.18.0]
    at io.grpc.internal.ClientCallImpl$ClientStreamListenerImpl.close(ClientCallImpl.java:546) ~[io.grpc-grpc-core-1.18.0.jar:1.18.0]
    at io.grpc.internal.ClientCallImpl$ClientStreamListenerImpl.access$600(ClientCallImpl.java:467) ~[io.grpc-grpc-core-1.18.0.jar:1.18.0]
    at io.grpc.internal.ClientCallImpl$ClientStreamListenerImpl$1StreamClosed.runInContext(ClientCallImpl.java:584) ~[io.grpc-grpc-core-1.18.0.jar:1.18.0]
    at io.grpc.internal.ContextRunnable.run(ContextRunnable.java:37) ~[io.grpc-grpc-core-1.18.0.jar:1.18.0]
    at io.grpc.internal.SerializingExecutor.run(SerializingExecutor.java:123) ~[io.grpc-grpc-core-1.18.0.jar:1.18.0]
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) ~[?:1.8.0_211]
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) ~[?:1.8.0_211]
    ... 1 more
Caused by: io.netty.channel.AbstractChannel$AnnotatedConnectException: Connection refused: /127.0.0.1:49695
    at sun.nio.ch.SocketChannelImpl.checkConnect(Native Method) ~[?:1.8.0_211]
    at sun.nio.ch.SocketChannelImpl.finishConnect(SocketChannelImpl.java:717) ~[?:1.8.0_211]
    at io.netty.channel.socket.nio.NioSocketChannel.doFinishConnect(NioSocketChannel.java:327) ~[io.netty-netty-all-4.1.32.Final.jar:4.1.32.Final]
    at io.netty.channel.nio.AbstractNioChannel$AbstractNioUnsafe.finishConnect(AbstractNioChannel.java:340) ~[io.netty-netty-all-4.1.32.Final.jar:4.1.32.Final]
    at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:644) ~[io.netty-netty-all-4.1.32.Final.jar:4.1.32.Final]
    at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:591) ~[io.netty-netty-all-4.1.32.Final.jar:4.1.32.Final]
    at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:508) ~[io.netty-netty-all-4.1.32.Final.jar:4.1.32.Final]
    at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:470) ~[io.netty-netty-all-4.1.32.Final.jar:4.1.32.Final]
    at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:909) ~[io.netty-netty-all-4.1.32.Final.jar:4.1.32.Final]
    ... 2 more
Caused by: java.net.ConnectException: Connection refused
    at sun.nio.ch.SocketChannelImpl.checkConnect(Native Method) ~[?:1.8.0_211]
    at sun.nio.ch.SocketChannelImpl.finishConnect(SocketChannelImpl.java:717) ~[?:1.8.0_211]
    at io.netty.channel.socket.nio.NioSocketChannel.doFinishConnect(NioSocketChannel.java:327) ~[io.netty-netty-all-4.1.32.Final.jar:4.1.32.Final]
    at io.netty.channel.nio.AbstractNioChannel$AbstractNioUnsafe.finishConnect(AbstractNioChannel.java:340) ~[io.netty-netty-all-4.1.32.Final.jar:4.1.32.Final]
    at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:644) ~[io.netty-netty-all-4.1.32.Final.jar:4.1.32.Final]
    at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:591) ~[io.netty-netty-all-4.1.32.Final.jar:4.1.32.Final]
    at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:508) ~[io.netty-netty-all-4.1.32.Final.jar:4.1.32.Final]
    at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:470) ~[io.netty-netty-all-4.1.32.Final.jar:4.1.32.Final]
    at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:909) ~[io.netty-netty-all-4.1.32.Final.jar:4.1.32.Final]
    ... 2 more
13:19:08.130 [function-timer-thread-3-1] ERROR org.apache.pulsar.functions.runtime.ProcessRuntime - Extracted Process death exception
java.lang.RuntimeException: 
    at org.apache.pulsar.functions.runtime.ProcessRuntime.tryExtractingDeathException(ProcessRuntime.java:380) ~[org.apache.pulsar-pulsar-functions-runtime-2.4.0.jar:2.4.0]
    at org.apache.pulsar.functions.runtime.ProcessRuntime.isAlive(ProcessRuntime.java:367) ~[org.apache.pulsar-pulsar-functions-runtime-2.4.0.jar:2.4.0]
    at org.apache.pulsar.functions.runtime.RuntimeSpawner.lambda$start$0(RuntimeSpawner.java:88) ~[org.apache.pulsar-pulsar-functions-runtime-2.4.0.jar:2.4.0]
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [?:1.8.0_211]
    at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308) [?:1.8.0_211]
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180) [?:1.8.0_211]
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294) [?:1.8.0_211]
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_211]
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_211]
    at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) [io.netty-netty-all-4.1.32.Final.jar:4.1.32.Final]
    at java.lang.Thread.run(Thread.java:748) [?:1.8.0_211]
13:19:08.131 [function-timer-thread-3-1] ERROR org.apache.pulsar.functions.runtime.RuntimeSpawner - public/default/exclamation-java.lang.RuntimeException:  Function Container is dead with exception.. restarting
13:19:08.136 [function-timer-thread-3-1] INFO  org.apache.pulsar.functions.runtime.ProcessRuntime - Creating function log directory /Users/frank/bigdata/pulsar/apache-pulsar-2.4.0/logs/functions/public/default/exclamation
13:19:08.137 [function-timer-thread-3-1] INFO  org.apache.pulsar.functions.runtime.ProcessRuntime - Created or found function log directory /Users/frank/bigdata/pulsar/apache-pulsar-2.4.0/logs/functions/public/default/exclamation
13:19:08.137 [function-timer-thread-3-1] INFO  org.apache.pulsar.functions.runtime.ProcessRuntime - ProcessBuilder starting the process with args python /Users/frank/bigdata/pulsar/apache-pulsar-2.4.0/instances/python-instance/python_instance_main.py --py /Users/frank/bigdata/pulsar/apache-pulsar-2.4.0/examples/python-examples/exclamation_function.py --logging_directory /Users/frank/bigdata/pulsar/apache-pulsar-2.4.0/logs/functions --logging_file exclamation --logging_config_file /Users/frank/bigdata/pulsar/apache-pulsar-2.4.0/conf/functions-logging/logging_config.ini --instance_id 0 --function_id bc8d75e3-9c28-4104-93da-51237dce0efb --function_version 4a5207a8-e009-47ec-b7c9-5c658f12eda7 --function_details '{"tenant":"public","namespace":"default","name":"exclamation","className":"ExclamationFunction","runtime":"PYTHON","autoAck":true,"parallelism":1,"source":{"inputSpecs":{"persistent://public/default/exclamation-input":{}},"cleanupSubscription":true},"sink":{"topic":"persistent://public/default/exclamation-output"},"resources":{"cpu":1.0,"ram":"1073741824","disk":"10737418240"},"componentType":"FUNCTION"}' --pulsar_serviceurl pulsar://localhost:6650 --use_tls false --tls_allow_insecure false --hostname_verification_enabled false --max_buffered_tuples 1024 --port 49695 --metrics_port 49696 --expected_healthcheck_interval 30 --secrets_provider secretsprovider.ClearTextSecretsProvider --cluster_name local
13:19:08.145 [function-timer-thread-3-1] INFO  org.apache.pulsar.functions.runtime.ProcessRuntime - Started process successfully
13:19:08.165 [Timer-0] INFO  org.apache.pulsar.functions.LocalRunner - {
"failureException": "UNAVAILABLE: io exception",
"instanceId": "0"
}
13:19:37.694 [function-timer-thread-3-1] ERROR org.apache.pulsar.functions.runtime.ProcessRuntime - Extracted Process death exception
java.lang.RuntimeException: 
    at org.apache.pulsar.functions.runtime.ProcessRuntime.tryExtractingDeathException(ProcessRuntime.java:380) ~[org.apache.pulsar-pulsar-functions-runtime-2.4.0.jar:2.4.0]
    at org.apache.pulsar.functions.runtime.ProcessRuntime.isAlive(ProcessRuntime.java:367) ~[org.apache.pulsar-pulsar-functions-runtime-2.4.0.jar:2.4.0]
    at org.apache.pulsar.functions.runtime.RuntimeSpawner.lambda$start$0(RuntimeSpawner.java:88) ~[org.apache.pulsar-pulsar-functions-runtime-2.4.0.jar:2.4.0]
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [?:1.8.0_211]
    at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308) [?:1.8.0_211]
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180) [?:1.8.0_211]
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294) [?:1.8.0_211]
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_211]
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_211]
    at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) [io.netty-netty-all-4.1.32.Final.jar:4.1.32.Final]
    at java.lang.Thread.run(Thread.java:748) [?:1.8.0_211]
13:19:37.695 [function-timer-thread-3-1] ERROR org.apache.pulsar.functions.runtime.RuntimeSpawner - public/default/exclamation-java.lang.RuntimeException:  Function Container is dead with exception.. restarting
13:19:37.696 [function-timer-thread-3-1] INFO  org.apache.pulsar.functions.runtime.ProcessRuntime - Creating function log directory /Users/frank/bigdata/pulsar/apache-pulsar-2.4.0/logs/functions/public/default/exclamation
13:19:37.696 [function-timer-thread-3-1] INFO  org.apache.pulsar.functions.runtime.ProcessRuntime - Created or found function log directory /Users/frank/bigdata/pulsar/apache-pulsar-2.4.0/logs/functions/public/default/exclamation
13:19:37.696 [function-timer-thread-3-1] INFO  org.apache.pulsar.functions.runtime.ProcessRuntime - ProcessBuilder starting the process with args python /Users/frank/bigdata/pulsar/apache-pulsar-2.4.0/instances/python-instance/python_instance_main.py --py /Users/frank/bigdata/pulsar/apache-pulsar-2.4.0/examples/python-examples/exclamation_function.py --logging_directory /Users/frank/bigdata/pulsar/apache-pulsar-2.4.0/logs/functions --logging_file exclamation --logging_config_file /Users/frank/bigdata/pulsar/apache-pulsar-2.4.0/conf/functions-logging/logging_config.ini --instance_id 0 --function_id bc8d75e3-9c28-4104-93da-51237dce0efb --function_version 4a5207a8-e009-47ec-b7c9-5c658f12eda7 --function_details '{"tenant":"public","namespace":"default","name":"exclamation","className":"ExclamationFunction","runtime":"PYTHON","autoAck":true,"parallelism":1,"source":{"inputSpecs":{"persistent://public/default/exclamation-input":{}},"cleanupSubscription":true},"sink":{"topic":"persistent://public/default/exclamation-output"},"resources":{"cpu":1.0,"ram":"1073741824","disk":"10737418240"},"componentType":"FUNCTION"}' --pulsar_serviceurl pulsar://localhost:6650 --use_tls false --tls_allow_insecure false --hostname_verification_enabled false --max_buffered_tuples 1024 --port 49695 --metrics_port 49696 --expected_healthcheck_interval 30 --secrets_provider secretsprovider.ClearTextSecretsProvider --cluster_name local
13:19:37.701 [Timer-0] INFO  org.apache.pulsar.functions.LocalRunner - {
"numRestarts": "1",
"instanceId": "0"
}
13:19:37.704 [function-timer-thread-3-1] INFO  org.apache.pulsar.functions.runtime.ProcessRuntime - Started process successfully
13:20:07.695 [function-timer-thread-3-1] ERROR org.apache.pulsar.functions.runtime.ProcessRuntime - Extracted Process death exception
java.lang.RuntimeException: 
    at org.apache.pulsar.functions.runtime.ProcessRuntime.tryExtractingDeathException(ProcessRuntime.java:380) ~[org.apache.pulsar-pulsar-functions-runtime-2.4.0.jar:2.4.0]
    at org.apache.pulsar.functions.runtime.ProcessRuntime.isAlive(ProcessRuntime.java:367) ~[org.apache.pulsar-pulsar-functions-runtime-2.4.0.jar:2.4.0]
    at org.apache.pulsar.functions.runtime.RuntimeSpawner.lambda$start$0(RuntimeSpawner.java:88) ~[org.apache.pulsar-pulsar-functions-runtime-2.4.0.jar:2.4.0]
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [?:1.8.0_211]
    at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308) [?:1.8.0_211]
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180) [?:1.8.0_211]
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294) [?:1.8.0_211]
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_211]
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_211]
    at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) [io.netty-netty-all-4.1.32.Final.jar:4.1.32.Final]
    at java.lang.Thread.run(Thread.java:748) [?:1.8.0_211]
13:20:07.696 [function-timer-thread-3-1] ERROR org.apache.pulsar.functions.runtime.RuntimeSpawner - public/default/exclamation-java.lang.RuntimeException:  Function Container is dead with exception.. restarting
13:20:07.697 [function-timer-thread-3-1] INFO  org.apache.pulsar.functions.runtime.ProcessRuntime - Creating function log directory /Users/frank/bigdata/pulsar/apache-pulsar-2.4.0/logs/functions/public/default/exclamation
13:20:07.697 [function-timer-thread-3-1] INFO  org.apache.pulsar.functions.runtime.ProcessRuntime - Created or found function log directory /Users/frank/bigdata/pulsar/apache-pulsar-2.4.0/logs/functions/public/default/exclamation
13:20:07.698 [function-timer-thread-3-1] INFO  org.apache.pulsar.functions.runtime.ProcessRuntime - ProcessBuilder starting the process with args python /Users/frank/bigdata/pulsar/apache-pulsar-2.4.0/instances/python-instance/python_instance_main.py --py /Users/frank/bigdata/pulsar/apache-pulsar-2.4.0/examples/python-examples/exclamation_function.py --logging_directory /Users/frank/bigdata/pulsar/apache-pulsar-2.4.0/logs/functions --logging_file exclamation --logging_config_file /Users/frank/bigdata/pulsar/apache-pulsar-2.4.0/conf/functions-logging/logging_config.ini --instance_id 0 --function_id bc8d75e3-9c28-4104-93da-51237dce0efb --function_version 4a5207a8-e009-47ec-b7c9-5c658f12eda7 --function_details '{"tenant":"public","namespace":"default","name":"exclamation","className":"ExclamationFunction","runtime":"PYTHON","autoAck":true,"parallelism":1,"source":{"inputSpecs":{"persistent://public/default/exclamation-input":{}},"cleanupSubscription":true},"sink":{"topic":"persistent://public/default/exclamation-output"},"resources":{"cpu":1.0,"ram":"1073741824","disk":"10737418240"},"componentType":"FUNCTION"}' --pulsar_serviceurl pulsar://localhost:6650 --use_tls false --tls_allow_insecure false --hostname_verification_enabled false --max_buffered_tuples 1024 --port 49695 --metrics_port 49696 --expected_healthcheck_interval 30 --secrets_provider secretsprovider.ClearTextSecretsProvider --cluster_name local
13:20:07.701 [Timer-0] INFO  org.apache.pulsar.functions.LocalRunner - {
"numRestarts": "2",
"instanceId": "0"
}
13:20:07.706 [function-timer-thread-3-1] INFO  org.apache.pulsar.functions.runtime.ProcessRuntime - Started process successfully
JarrodJ83 commented 4 years ago

Is this specific to the example code in the python example or just all python functions? I am trying to learn functions and running into this following the guides. Is there any recommended workaround?