thlautenschlaeger opened a new issue #5912: "UNAVAILABLE: io exception" pulsar functions URL: https://github.com/apache/pulsar/issues/5912 Pulsar functions keeps crashing in localrun and in cluster mode. I'm trying to execute a simple word count python [function](https://github.com/apache/pulsar/blob/master/pulsar-functions/python-examples/wordcount_function.py) but it never successfully executes. **Execution command** ./pulsar-admin functions localrun --py /home/vagrant/python_scripts/example_function.py --classname WordCountFunction --tenant test --namespace test --name excfunc --inputs persistent://test/test/test1 --output persistent://test/test/test2 **Log from functions status** { "numInstances" : 1, "numRunning" : 0, "instances" : [ { "instanceId" : 0, "status" : { "running" : false, "error" : "UNAVAILABLE: io exception", "numRestarts" : 0, "numReceived" : 0, "numSuccessfullyProcessed" : 0, "numUserExceptions" : 0, "latestUserExceptions" : [ ], "numSystemExceptions" : 0, "latestSystemExceptions" : [ ], "averageLatency" : 0.0, "lastInvocationTime" : 0, "workerId" : "c-standalone-fw-localhost-8080" } } ] } **Log from localrun** 23:10:47.895 [function-timer-thread-3-1] INFO org.apache.pulsar.functions.runtime.ProcessRuntime - Started process successfully 23:10:47.903 [Timer-0] INFO org.apache.pulsar.functions.LocalRunner - { "numRestarts": "4", "instanceId": "0" } 2019-12-20 23:10:48.127 INFO ConnectionPool:85 | Created connection for pulsar://localhost:6650 2019-12-20 23:10:48.128 INFO ClientConnection:324 | [127.0.0.1:39360 -> 127.0.0.1:6650] Connected to broker 2019-12-20 23:10:48.131 INFO BatchMessageContainer:43 | { BatchContainer [size = 0] [batchSizeInBytes_ = 0] [maxAllowedMessageBatchSizeInBytes_ = 131072] [maxAllowedNumMessagesInBatch_ = 1000] [topicName = persistent://test/test/log] [producerName_ = ] [batchSizeInBytes_ = 0] [numberOfBatchesSent = 0] [averageBatchSize = 0]} BatchMessageContainer constructed 2019-12-20 23:10:48.131 INFO HandlerBase:53 | [persistent://test/test/log, ] Getting connection from pool 2019-12-20 23:10:48.134 INFO ProducerImpl:151 | [persistent://test/test/log, ] Created producer on broker [127.0.0.1:39360 -> 127.0.0.1:6650] 2019-12-20 23:10:48.136 INFO Client:88 | Subscribing on Topic :persistent://test/test/test1 2019-12-20 23:10:48.138 INFO HandlerBase:53 | [persistent://test/test/test1, test/test/excfunc, 0] Getting connection from pool 2019-12-20 23:10:48.143 INFO ConsumerImpl:170 | [persistent://test/test/test1, test/test/excfunc, 0] Created consumer on broker [127.0.0.1:39360 -> 127.0.0.1:6650] ^C23:11:07.717 [Thread-1] INFO org.apache.pulsar.functions.LocalRunner - Shutting down the localrun runtimeSpawner ... [vagrant@localhost bin]$ clear [vagrant@localhost bin]$ ./pulsar-admin functions localrun --py /home/vagrant/python_scripts/example_function.py --classname WordCountFunction --tenant test --namespace test --name excfunc --inputs persistent://test/test/test1 --output persistent://test/test/test2 --log-topic persistent://test/test/log 23:11:14.305 [main] INFO org.apache.pulsar.functions.runtime.ProcessRuntimeFactory - Java instance jar location is not defined, using the location defined in system environment : /home/vagrant/apache-pulsar-2.4.2/instances/java-instance.jar 23:11:14.309 [main] INFO org.apache.pulsar.functions.runtime.ProcessRuntimeFactory - Python instance file location is not defined using the location defined in system environment : /home/vagrant/apache-pulsar-2.4.2/instances/python-instance/python_instance_main.py 23:11:14.310 [main] INFO org.apache.pulsar.functions.runtime.ProcessRuntimeFactory - No extra dependencies location is defined in either function worker config or system environment 23:11:14.463 [main] INFO org.apache.pulsar.functions.runtime.RuntimeSpawner - test/test/excfunc-0 RuntimeSpawner starting function 23:11:14.464 [main] INFO org.apache.pulsar.functions.runtime.ProcessRuntime - Creating function log directory /home/vagrant/apache-pulsar-2.4.2/logs/functions/test/test/excfunc 23:11:14.466 [main] INFO org.apache.pulsar.functions.runtime.ProcessRuntime - Created or found function log directory /home/vagrant/apache-pulsar-2.4.2/logs/functions/test/test/excfunc 23:11:14.466 [main] INFO org.apache.pulsar.functions.runtime.ProcessRuntime - ProcessBuilder starting the process with args python /home/vagrant/apache-pulsar-2.4.2/instances/python-instance/python_instance_main.py --py /home/vagrant/python_scripts/example_function.py --logging_directory /home/vagrant/apache-pulsar-2.4.2/logs/functions --logging_file excfunc --logging_config_file /home/vagrant/apache-pulsar-2.4.2/conf/functions-logging/logging_config.ini --instance_id 0 --function_id bda8a6b3-7cb2-4d79-9602-7c164eb0aaef --function_version 683af9f6-4c2e-4e5b-888f-6bc5787cdb5e --function_details '{"tenant":"test","namespace":"test","name":"excfunc","className":"WordCountFunction","logTopic":"persistent://test/test/log","runtime":"PYTHON","autoAck":true,"parallelism":1,"source":{"inputSpecs":{"persistent://test/test/test1":{}},"cleanupSubscription":true},"sink":{"topic":"persistent://test/test/test2"},"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 33446 --metrics_port 32789 --expected_healthcheck_interval 30 --secrets_provider secretsprovider.ClearTextSecretsProvider --cluster_name local 23:11:14.486 [main] INFO org.apache.pulsar.functions.runtime.ProcessRuntime - Started process successfully 2019-12-20 23:11:14.957 INFO ConnectionPool:85 | Created connection for pulsar://localhost:6650 2019-12-20 23:11:14.958 INFO ClientConnection:324 | [127.0.0.1:39378 -> 127.0.0.1:6650] Connected to broker 2019-12-20 23:11:14.962 INFO BatchMessageContainer:43 | { BatchContainer [size = 0] [batchSizeInBytes_ = 0] [maxAllowedMessageBatchSizeInBytes_ = 131072] [maxAllowedNumMessagesInBatch_ = 1000] [topicName = persistent://test/test/log] [producerName_ = ] [batchSizeInBytes_ = 0] [numberOfBatchesSent = 0] [averageBatchSize = 0]} BatchMessageContainer constructed 2019-12-20 23:11:14.962 INFO HandlerBase:53 | [persistent://test/test/log, ] Getting connection from pool 2019-12-20 23:11:14.965 INFO ProducerImpl:151 | [persistent://test/test/log, ] Created producer on broker [127.0.0.1:39378 -> 127.0.0.1:6650] 2019-12-20 23:11:14.967 INFO Client:88 | Subscribing on Topic :persistent://test/test/test1 2019-12-20 23:11:14.969 INFO HandlerBase:53 | [persistent://test/test/test1, test/test/excfunc, 0] Getting connection from pool 2019-12-20 23:11:14.971 INFO ConsumerImpl:170 | [persistent://test/test/test1, test/test/excfunc, 0] Created consumer on broker [127.0.0.1:39378 -> 127.0.0.1:6650] 23:11:15.046 [main] INFO org.apache.pulsar.functions.LocalRunner - RuntimeSpawner quit because of 23:11:17.879 [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:381) ~[org.apache.pulsar-pulsar-functions-runtime-2.4.2.jar:2.4.2] at org.apache.pulsar.functions.runtime.ProcessRuntime.isAlive(ProcessRuntime.java:368) ~[org.apache.pulsar-pulsar-functions-runtime-2.4.2.jar:2.4.2] at org.apache.pulsar.functions.runtime.RuntimeSpawner.lambda$start$0(RuntimeSpawner.java:88) ~[org.apache.pulsar-pulsar-functions-runtime-2.4.2.jar:2.4.2] at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [?:1.8.0_232] at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308) [?:1.8.0_232] at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180) [?:1.8.0_232] at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294) [?:1.8.0_232] at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_232] at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_232] 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_232] 23:11:17.880 [function-timer-thread-3-1] ERROR org.apache.pulsar.functions.runtime.RuntimeSpawner - test/test/excfunc-java.lang.RuntimeException: Function Container is dead with exception.. restarting 23:11:17.880 [function-timer-thread-3-1] INFO org.apache.pulsar.functions.runtime.ProcessRuntime - Creating function log directory /home/vagrant/apache-pulsar-2.4.2/logs/functions/test/test/excfunc 23:11:17.881 [function-timer-thread-3-1] INFO org.apache.pulsar.functions.runtime.ProcessRuntime - Created or found function log directory /home/vagrant/apache-pulsar-2.4.2/logs/functions/test/test/excfunc 23:11:17.881 [function-timer-thread-3-1] INFO org.apache.pulsar.functions.runtime.ProcessRuntime - ProcessBuilder starting the process with args python /home/vagrant/apache-pulsar-2.4.2/instances/python-instance/python_instance_main.py --py /home/vagrant/python_scripts/example_function.py --logging_directory /home/vagrant/apache-pulsar-2.4.2/logs/functions --logging_file excfunc --logging_config_file /home/vagrant/apache-pulsar-2.4.2/conf/functions-logging/logging_config.ini --instance_id 0 --function_id bfd51266-09ad-40e5-84a1-1f77b6626935 --function_version a717f725-3164-4a1b-b88b-1415b6288af2 --function_details '{"tenant":"test","namespace":"test","name":"excfunc","className":"WordCountFunction","logTopic":"persistent://test/test/log","runtime":"PYTHON","autoAck":true,"parallelism":1,"source":{"inputSpecs":{"persistent://test/test/test1":{}},"cleanupSubscription":true},"sink":{"topic":"persistent://test/test/test2"},"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 44478 --metrics_port 40031 --expected_healthcheck_interval 30 --secrets_provider secretsprovider.ClearTextSecretsProvider --cluster_name local 23:11:17.897 [function-timer-thread-3-1] INFO org.apache.pulsar.functions.runtime.ProcessRuntime - Started process successfully 23:11:17.904 [Timer-0] INFO org.apache.pulsar.functions.LocalRunner - { "numRestarts": "5", "instanceId": "0" } 2019-12-20 23:11:18.113 INFO ConnectionPool:85 | Created connection for pulsar://localhost:6650 2019-12-20 23:11:18.114 INFO ClientConnection:324 | [127.0.0.1:39386 -> 127.0.0.1:6650] Connected to broker 2019-12-20 23:11:18.117 INFO BatchMessageContainer:43 | { BatchContainer [size = 0] [batchSizeInBytes_ = 0] [maxAllowedMessageBatchSizeInBytes_ = 131072] [maxAllowedNumMessagesInBatch_ = 1000] [topicName = persistent://test/test/log] [producerName_ = ] [batchSizeInBytes_ = 0] [numberOfBatchesSent = 0] [averageBatchSize = 0]} BatchMessageContainer constructed 2019-12-20 23:11:18.117 INFO HandlerBase:53 | [persistent://test/test/log, ] Getting connection from pool 2019-12-20 23:11:18.121 INFO ProducerImpl:151 | [persistent://test/test/log, ] Created producer on broker [127.0.0.1:39386 -> 127.0.0.1:6650] 2019-12-20 23:11:18.122 INFO Client:88 | Subscribing on Topic :persistent://test/test/test1 2019-12-20 23:11:18.124 INFO HandlerBase:53 | [persistent://test/test/test1, test/test/excfunc, 0] Getting connection from pool 2019-12-20 23:11:18.127 INFO ConsumerImpl:170 | [persistent://test/test/test1, test/test/excfunc, 0] Created consumer on broker [127.0.0.1:39386 -> 127.0.0.1:6650] **Machine** - OS: CentOS 7 - Python: 3.7.4 - Openjdk: 1.8.0_232 - Pulsar: 2.4.2.jar
---------------------------------------------------------------- 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. For queries about this service, please contact Infrastructure at: [email protected] With regards, Apache Git Services
