Spark-on-k8s-operator: Spark executors won't start : spark-operator:v1beta2-1.2.0-3.0.0

[kocham]

@liyinan926

when I run demo spark-pi on spark-operator:v1beta2-1.2.0-3.0.0，Spark executors won't start， The driver logs showed no logs from the SparkContext and the KubernetesSchedulerBackend. Anyone know what might be causing this issue?
I have read issue 133， almost the same situation, but i just run a demo spark-pi 。

env:
k8s：client/server v1.15.5
docker：18.09.7
chart：sparkoperator-0.8.2
image：spark-operator:v1beta2-1.2.0-3.0.0

here are logs and configs:

spark-pi-driver pod events:

spark-driver configmap：
root@spark-pi-driver:/opt/spark/conf# cat spark.properties

Java properties built from Kubernetes config map with name: spark-pi-86f682744282e0c0-driver-conf-map

Mon Aug 31 03:15:08 UTC 2020

spark.kubernetes.executor.label.version=3.0.0
spark.executor.memory=1024m
spark.driver.host=spark-pi-86f682744282e0c0-driver-svc.spark-job.svc
spark.driver.blockManager.port=7079
spark.kubernetes.executor.label.sparkoperator.k8s.io/app-name=spark-pi
spark.kubernetes.container.image=reg.hrlyit.com/common/spark-operator\:v1beta2-1.2.0-3.0.0
spark.jars=local\:///opt/spark/examples/jars/spark-examples_2.12-3.0.0.jar
spark.kubernetes.driver.limit.cores=1000m
spark.kubernetes.submitInDriver=true
spark.driver.memory=1024m
spark.kubernetes.container.image.pullPolicy=Always
spark.kubernetes.executor.label.sparkoperator.k8s.io/launched-by-spark-operator=true
spark.submit.deployMode=cluster
spark.kubernetes.memoryOverheadFactor=0.1
spark.kubernetes.executor.label.sparkoperator.k8s.io/submission-id=3ba91ce2-31c1-453b-9414-34af382589bc
spark.kubernetes.submission.waitAppCompletion=false
spark.kubernetes.driver.label.sparkoperator.k8s.io/launched-by-spark-operator=true
spark.kubernetes.resource.type=java
spark.master=k8s\://https\://100.0.0.1\:443
spark.executor.cores=1
spark.kubernetes.authenticate.driver.serviceAccountName=sparkjob
spark.submit.pyFiles=
spark.kubernetes.driver.pod.name=spark-pi-driver
spark.kubernetes.driver.label.sparkoperator.k8s.io/app-name=spark-pi
spark.executor.instances=1
spark.kubernetes.namespace=spark-job
spark.app.id=spark-20ef0cb82c8a4ed28b88cff5c896c9a3
spark.kubernetes.driver.label.sparkoperator.k8s.io/submission-id=3ba91ce2-31c1-453b-9414-34af382589bc
spark.app.name=spark-pi
spark.kubernetes.driver.label.version=3.0.0
spark.driver.cores=1
spark.driver.port=7078

spark operation cluster logs:
Mon, Aug 31 2020 11:15:11 amI0831 03:15:11.221554 9 spark_pod_eventhandler.go:58] Pod spark-pi-driver updated in namespace spark-job.
Mon, Aug 31 2020 11:15:11 amI0831 03:15:11.221592 9 spark_pod_eventhandler.go:95] Enqueuing SparkApplication spark-job/spark-pi for app update processing.
Mon, Aug 31 2020 11:15:11 amI0831 03:15:11.221629 9 controller.go:258] Starting processing key: "spark-job/spark-pi"
Mon, Aug 31 2020 11:15:11 amI0831 03:15:11.221802 9 event.go:274] Event(v1.ObjectReference{Kind:"SparkApplication", Namespace:"spark-job", Name:"spark-pi", UID:"41ed2c8a-d257-4a21-8a87-e17048b900a2", APIVersion:"sparkoperator.k8s.io/v1beta2", ResourceVersion:"821065", FieldPath:""}): type: 'Normal' reason: 'SparkDriverRunning' Driver spark-pi-driver is running
Mon, Aug 31 2020 11:15:11 amI0831 03:15:11.221841 9 controller.go:773] Update the status of SparkApplication spark-job/spark-pi from:
Mon, Aug 31 2020 11:15:11 am{
Mon, Aug 31 2020 11:15:11 am"sparkApplicationId": "spark-20ef0cb82c8a4ed28b88cff5c896c9a3",
Mon, Aug 31 2020 11:15:11 am"submissionID": "3ba91ce2-31c1-453b-9414-34af382589bc",
Mon, Aug 31 2020 11:15:11 am"lastSubmissionAttemptTime": "2020-08-31T03:15:09Z",
Mon, Aug 31 2020 11:15:11 am"terminationTime": null,
Mon, Aug 31 2020 11:15:11 am"driverInfo": {
Mon, Aug 31 2020 11:15:11 am"webUIServiceName": "spark-pi-ui-svc",
Mon, Aug 31 2020 11:15:11 am"webUIPort": 4040,
Mon, Aug 31 2020 11:15:11 am"webUIAddress": "100.0.161.117:4040",
Mon, Aug 31 2020 11:15:11 am"podName": "spark-pi-driver"
Mon, Aug 31 2020 11:15:11 am},
Mon, Aug 31 2020 11:15:11 am"applicationState": {
Mon, Aug 31 2020 11:15:11 am"state": "SUBMITTED"
Mon, Aug 31 2020 11:15:11 am},
Mon, Aug 31 2020 11:15:11 am"executionAttempts": 1,
Mon, Aug 31 2020 11:15:11 am"submissionAttempts": 1
Mon, Aug 31 2020 11:15:11 am}
Mon, Aug 31 2020 11:15:11 amto:
Mon, Aug 31 2020 11:15:11 am{
Mon, Aug 31 2020 11:15:11 am"sparkApplicationId": "spark-20ef0cb82c8a4ed28b88cff5c896c9a3",
Mon, Aug 31 2020 11:15:11 am"submissionID": "3ba91ce2-31c1-453b-9414-34af382589bc",
Mon, Aug 31 2020 11:15:11 am"lastSubmissionAttemptTime": "2020-08-31T03:15:09Z",
Mon, Aug 31 2020 11:15:11 am"terminationTime": null,
Mon, Aug 31 2020 11:15:11 am"driverInfo": {
Mon, Aug 31 2020 11:15:11 am"webUIServiceName": "spark-pi-ui-svc",
Mon, Aug 31 2020 11:15:11 am"webUIPort": 4040,
Mon, Aug 31 2020 11:15:11 am"webUIAddress": "100.0.161.117:4040",
Mon, Aug 31 2020 11:15:11 am"podName": "spark-pi-driver"
Mon, Aug 31 2020 11:15:11 am},
Mon, Aug 31 2020 11:15:11 am"applicationState": {
Mon, Aug 31 2020 11:15:11 am"state": "RUNNING"
Mon, Aug 31 2020 11:15:11 am},
Mon, Aug 31 2020 11:15:11 am"executionAttempts": 1,
Mon, Aug 31 2020 11:15:11 am"submissionAttempts": 1
Mon, Aug 31 2020 11:15:11 am}
Mon, Aug 31 2020 11:15:11 amI0831 03:15:11.233601 9 metrics.go:112] Incrementing spark_app_running_count with labels map[app_type:Unknown]
Mon, Aug 31 2020 11:15:11 amI0831 03:15:11.233623 9 controller.go:218] SparkApplication spark-job/spark-pi was updated, enqueueing it
Mon, Aug 31 2020 11:15:11 amI0831 03:15:11.233659 9 controller.go:265] Ending processing key: "spark-job/spark-pi"
Mon, Aug 31 2020 11:15:11 amI0831 03:15:11.233691 9 controller.go:258] Starting processing key: "spark-job/spark-pi"
Mon, Aug 31 2020 11:15:11 amI0831 03:15:11.233772 9 controller.go:265] Ending processing key: "spark-job/spark-pi"

by the way, chart：sparkoperator-0.8.2 seems has a problem, spark job serviceaccount have not right to list sparkapplication resouces on cluster scope by default, so i have to create a custerrolebinds to bind spark job serviceaccount and spark clusterrole manually. could this be added for the next version?

[kocham]

spark app description：
[root@bigdata-k8s-master-90-50 spark]# kubectl -n spark-job describe sparkapp spark-pi
Name: spark-pi
Namespace: spark-job
Labels:
Annotations: API Version: sparkoperator.k8s.io/v1beta2
Kind: SparkApplication
Metadata:
Creation Timestamp: 2020-09-14T09:49:23Z
Generation: 1
Managed Fields:
API Version: sparkoperator.k8s.io/v1beta2
Fields Type: FieldsV1
...
Manager: kubectl
Operation: Update
Time: 2020-09-14T09:49:23Z
API Version: sparkoperator.k8s.io/v1beta2
Fields Type: FieldsV1
...
Manager: spark-operator
Operation: Update
Time: 2020-09-14T09:49:29Z
Resource Version: 4005331
Self Link: /apis/sparkoperator.k8s.io/v1beta2/namespaces/spark-job/sparkapplications/spark-pi
UID: 172cd309-42ea-4dc7-a86b-30db43e930f3
Spec:
Driver:
Core Limit: 1000m
Cores: 1
Labels:
Version: 3.0.0
Memory: 1024m
Service Account: sparkjob
Volume Mounts:
Mount Path: /tmp
Name: test-volume
Executor:
Cores: 1
Instances: 1
Labels:
Version: 3.0.0
Memory: 1024m
Service Account: sparkjob
Volume Mounts:
Mount Path: /tmp
Name: test-volume
Image: reg.hrlyit.com/common/spark-operator:v1beta2-1.2.0-3.0.0
Image Pull Policy: Always
Main Application File: local:///opt/spark/examples/jars/spark-examples_2.12-3.0.0.jar
Main Class: org.apache.spark.examples.SparkPi
Mode: cluster
Restart Policy:
Type: Never
Spark Version: 3.0.0
Type: Scala
Volumes:
Host Path:
Path: /tmp
Type: Directory
Name: test-volume
Status:
Application State:
State: RUNNING
Driver Info:
Pod Name: spark-pi-driver
Web UI Address: 100.0.53.184:4040
Web UI Port: 4040
Web UI Service Name: spark-pi-ui-svc
Execution Attempts: 1
Last Submission Attempt Time: 2020-09-14T09:49:26Z
Spark Application Id: spark-9b8cef55212a4a55b856d5b60d62f640
Submission Attempts: 1
Submission ID: 094d194f-8020-4404-89ee-331e5f224cc9
Termination Time:
Events:
Type Reason Age From Message
---- ------ ---- ---- -------
Normal SparkApplicationAdded 31s spark-operator SparkApplication spark-pi was added, enqueuing it for submission
Normal SparkApplicationSubmitted 28s spark-operator SparkApplication spark-pi was submitted successfully
Normal SparkDriverRunning 25s spark-operator Driver spark-pi-driver is running
Normal SparkDriverRunning 25s spark-operator Driver spark-pi-driver is running

[kocham]

this confused me for more than two weeks，could anybody help me？

[vislante]

I am facing with same issue, but the pyspark version. Could someone help here.

@kocham are you able to fix this?

[kocham]

I tried many ways, it still not worked, maybe we have to wait some time to use sparkoperator in product env.

------------------ 原始邮件 ------------------
发件人: "GoogleCloudPlatform/spark-on-k8s-operator" <[email protected]>;
发送时间: 2020年10月28日(星期三) 晚上8:43
收件人: "GoogleCloudPlatform/spark-on-k8s-operator"<[email protected]>;
抄送: "兵临城下"<[email protected]>;"Mention"<[email protected]>;
主题: Re: [GoogleCloudPlatform/spark-on-k8s-operator] Spark executors won't start : spark-operator:v1beta2-1.2.0-3.0.0 (#1010)

I am facing with same issue, but the pyspark version. Could someone help here.

@kocham are you able to fix this?

—
You are receiving this because you were mentioned.
Reply to this email directly, view it on GitHub, or unsubscribe.

[mmhhss]

I am facing with same issue on pyspark version.
describe sparkapplication everything is fine and it starts the driver.

But driver logs hang after "exec /usr/bin/tini -s -- /usr/bin/spark-operator driver --properties-file /opt/spark/conf/spark.properties --class org.apache.spark.deploy.PythonRunner local:///opt/spark/examples/src/main/python/kmeans.py"

Maybe set wrong image.
Original image is gcr.io/spark-operator/spark:v3.0.0.
Git clone this project and build new image using the Dockerfile in this project named is spark:v4.0.0
start the spark-operator using spark:v4.0.0.
Run spark-pi.yaml using v3.0.0 is ok but using v4.0.0 it will hang after this comand "exec /usr/bin/tini -s -- /usr/bin/spark-operator......"
From v3.0.0 install python and pip install pyspark, named as v3.1.0. Run python script using v3.1.0 image, the problem will disappear.

[kz33]

@kocham Can you share your driver logs?

[kz33]

@mmhhss I think you built the spark:v4.0.0 image by mistake.
The following is the correct way:

$ pwd
../spark-on-k8s-operator
$ cd spark-docker
$ docker build -t spark:v4.0.0 -f Dockerfile .

and You use this image gcr.io/spark-operator/spark-py:v3.0.0 if you want to run pyspark

[vislante]

@kz33 we used v3.0.0 image and driver is up and running without any issues. I checked with UI and see that deploymode as client even when i am changing it to cluster in the yaml file.

Am i doing anything wrong here

[kz33]

Hi @vislante , You did nothing wrong and this link will answer your doubts.

[vislante]

@kz33 thank you... any idea why executors are not launched?

[kz33]

@vislante Can you share your driver logs?
Did you run this demo （expamles/spark-pi.yaml）? If not, can you share your yaml ？

[vislante]

@kz33 Here are the logs from driver

++ id -u

• myuid=185
  ++ id -g
• mygid=0
• set +e
  ++ getent passwd 185
• uidentry=
• set -e
• '[' -z '' ']'
• '[' -w /etc/passwd ']'
• echo '185:x:185:0:anonymous uid:/opt/spark:/bin/false'
• SPARK_CLASSPATH=':/opt/spark/jars/*'
• env
• sed 's/[^=]=(.)/\1/g'
• grep SPARK_JAVA_OPT_
• sort -t_ -k4 -n
• readarray -t SPARK_EXECUTOR_JAVA_OPTS
• '[' -n '' ']'
• '[' 3 == 2 ']'
• '[' 3 == 3 ']'
  ++ python3 -V
• pyv3='Python 3.7.3'
• export PYTHON_VERSION=3.7.3
• PYTHON_VERSION=3.7.3
• export PYSPARK_PYTHON=python3
• PYSPARK_PYTHON=python3
• export PYSPARK_DRIVER_PYTHON=python3
• PYSPARK_DRIVER_PYTHON=python3
• '[' -n '' ']'
• '[' -z ']'
• case "$1" in
• shift 1
• CMD=("$SPARK_HOME/bin/spark-submit" --conf "spark.driver.bindAddress=$SPARK_DRIVER_BIND_ADDRESS" --deploy-mode client "$@")
• exec /usr/bin/tini -s -- /opt/spark/bin/spark-submit --conf spark.driver.bindAddress=10.192.21.206 --deploy-mode client --properties-file /opt/spark/conf/spark.properties --class org.apache.spark.deploy.PythonRunner local:///opt/spark/spark_single_file.py
  20/11/21 12:37:11 WARN NativeCodeLoader: Unable to load native-hadoop library for your platform... using builtin-java classes where applicable
  Using Spark's default log4j profile: org/apache/spark/log4j-defaults.properties
  20/11/21 12:37:12 INFO SparkContext: Running Spark version 3.0.0
  20/11/21 12:37:12 INFO ResourceUtils: ==============================================================
  20/11/21 12:37:12 INFO ResourceUtils: Resources for spark.driver:

20/11/21 12:37:12 INFO ResourceUtils: ==============================================================
20/11/21 12:37:12 INFO SparkContext: Submitted application: word_count
20/11/21 12:37:12 INFO SecurityManager: Changing view acls to: 185,root
20/11/21 12:37:12 INFO SecurityManager: Changing modify acls to: 185,root
20/11/21 12:37:12 INFO SecurityManager: Changing view acls groups to:
20/11/21 12:37:12 INFO SecurityManager: Changing modify acls groups to:
20/11/21 12:37:12 INFO SecurityManager: SecurityManager: authentication disabled; ui acls disabled; users with view permissions: Set(185, root); groups with view permissions: Set(); users with modify permissions: Set(185, root); groups with modify permissions: Set()
20/11/21 12:37:12 INFO Utils: Successfully started service 'sparkDriver' on port 7078.
20/11/21 12:37:12 INFO SparkEnv: Registering MapOutputTracker
20/11/21 12:37:12 INFO SparkEnv: Registering BlockManagerMaster
20/11/21 12:37:13 INFO BlockManagerMasterEndpoint: Using org.apache.spark.storage.DefaultTopologyMapper for getting topology information
20/11/21 12:37:13 INFO BlockManagerMasterEndpoint: BlockManagerMasterEndpoint up
20/11/21 12:37:13 INFO SparkEnv: Registering BlockManagerMasterHeartbeat
20/11/21 12:37:13 INFO DiskBlockManager: Created local directory at /var/data/spark-1b928580-024d-4fa2-bb41-75033fe08c10/blockmgr-d62ee677-aee2-4387-a243-f4b2b576c634
20/11/21 12:37:13 INFO MemoryStore: MemoryStore started with capacity 413.9 MiB
20/11/21 12:37:13 INFO SparkEnv: Registering OutputCommitCoordinator
20/11/21 12:37:13 INFO Utils: Successfully started service 'SparkUI' on port 4040.
20/11/21 12:37:13 INFO SparkUI: Bound SparkUI to 0.0.0.0, and started at http://pyspark-pi-9f064775eaced99c-driver-svc.spark-jobs.svc:4040
20/11/21 12:37:13 INFO Executor: Starting executor ID driver on host pyspark-pi-driver
20/11/21 12:37:13 INFO Utils: Successfully started service 'org.apache.spark.network.netty.NettyBlockTransferService' on port 7079.
20/11/21 12:37:13 INFO NettyBlockTransferService: Server created on pyspark-pi-9f064775eaced99c-driver-svc.spark-jobs.svc:7079
20/11/21 12:37:13 INFO BlockManager: Using org.apache.spark.storage.RandomBlockReplicationPolicy for block replication policy
20/11/21 12:37:13 INFO BlockManagerMaster: Registering BlockManager BlockManagerId(driver, pyspark-pi-9f064775eaced99c-driver-svc.spark-jobs.svc, 7079, None)
20/11/21 12:37:13 INFO BlockManagerMasterEndpoint: Registering block manager pyspark-pi-9f064775eaced99c-driver-svc.spark-jobs.svc:7079 with 413.9 MiB RAM, BlockManagerId(driver, pyspark-pi-9f064775eaced99c-driver-svc.spark-jobs.svc, 7079, None)
20/11/21 12:37:13 INFO BlockManagerMaster: Registered BlockManager BlockManagerId(driver, pyspark-pi-9f064775eaced99c-driver-svc.spark-jobs.svc, 7079, None)
20/11/21 12:37:13 INFO BlockManager: Initialized BlockManager: BlockManagerId(driver, pyspark-pi-9f064775eaced99c-driver-svc.spark-jobs.svc, 7079, None)
20/11/21 12:37:14 INFO SharedState: Setting hive.metastore.warehouse.dir ('null') to the value of spark.sql.warehouse.dir ('file:/opt/spark/work-dir/spark-warehouse').
20/11/21 12:37:14 INFO SharedState: Warehouse path is 'file:/opt/spark/work-dir/spark-warehouse'.

[kz33]

Hi, @vislante , thank you for your driver logs
but I did not see any errors log.

My idea is that we can find some error logs from your operator log for analysis together, and you can see if the executor pod is created and if there is any useful error information for us to analyze.

you can see operator logs by running the following command:

kubectl -n spark-operator logs -f {spark-operator-pod-name}

If you want, you can share your yaml file. I hope to reproduce this problem and help you solve it.

[vislante]

Hi @kz33

Apologies for the late reply, actually we figured out the issue. We have a master configuration set while initialising spark context. Once we removed that I can see the exec pods getting launched.