Spark-on-k8s-operator: [bug] failed executor pod provisioned via gcp autoscale

[chenqin]

Have been running a cluster with node pool size equals 1 (4 vcpu host auto scale turns on), run spark pi demanding two executors with 3 cores each. What I expected is new node (executor) will be added on demand and register to to k8s app with auto scale on. What I observed was node get provisioned but executor state FAILED

`
driver:
cores: 0.1
coreLimit: "200m"
memory: "512m"
labels:
version: 2.4.0
serviceAccount: spark
volumeMounts:
- name: "test-volume"
mountPath: "/tmp"
executor:
cores: 3
instances: 2
memory: "512m"
labels:
version: 2.4.0
volumeMounts:
- name: "test-volume"
mountPath: "/tmp"

cq:~/golang/src/github.com/GoogleCloudPlatform/spark-on-k8s-operator/examples$ sparkctl event spark-pi
+------------+--------+----------------------------------------------------+
| TYPE | AGE | MESSAGE |
+------------+--------+----------------------------------------------------+
| Normal | 12m | SparkApplication spark-pi |
| | | was added, Enqueuing it for |
| | | submission |
| Normal | 12m | SparkApplication spark-pi was |
| | | submitted successfully |
| Normal | 11m | Driver spark-pi-driver is |
| | | running |
| Normal | 11m | Executor |
| | | spark-pi-1549663845342-exec-1 |
| | | is pending |
| Normal | 11m | Executor |
| | | spark-pi-1549663845342-exec-2 |
| | | is pending |
| Normal | 11m | Executor |
| | | spark-pi-1549663845342-exec-1 |
| | | is running |
+------------+--------+----------------------------------------------------+

cq@:~/golang/src/github.com/GoogleCloudPlatform/spark-on-k8s-operator/examples$ sparkctl status spark-pi
application state:
+-----------+----------------+----------------+-----------------+---------------------+--------------------+-------------------+
| STATE | SUBMISSION AGE | COMPLETION AGE | DRIVER POD | DRIVER UI | SUBMISSIONATTEMPTS | EXECUTIONATTEMPTS |
+-----------+----------------+----------------+-----------------+---------------------+--------------------+-------------------+
| COMPLETED | 13m | 11m | spark-pi-driver | xxxx:31258 | 1 | 1 |
+-----------+----------------+----------------+-----------------+---------------------+--------------------+-------------------+
executor state:
+-------------------------------+-----------+
| EXECUTOR POD | STATE |
+-------------------------------+-----------+
| spark-pi-1549663845342-exec-1 | COMPLETED |
| spark-pi-1549663845342-exec-2 | FAILED |
+-------------------------------+-----------+
`

[liyinan926]

What does the driver logs say?

[chenqin]

Updated with longer maxRegisteredResourcesWaitingTime and still reproducible issue.

`
apiVersion: "sparkoperator.k8s.io/v1beta1"
kind: SparkApplication
metadata:
name: spark-pi
namespace: default
spec:
SparkConf:
"spark.scheduler.maxRegisteredResourcesWaitingTime": 120s
type: Scala
mode: cluster
image: "gcr.io/spark-operator/spark:v2.4.0"
imagePullPolicy: Always
mainClass: org.apache.spark.examples.SparkPi
mainApplicationFile: "local:///opt/spark/examples/jars/spark-examples_2.11-2.4.0.jar"
sparkVersion: "2.4.0"
restartPolicy:
type: Never
volumes:
- name: "test-volume"
hostPath:
path: "/tmp"
type: Directory
driver:
cores: 0.1
coreLimit: "200m"
memory: "512m"
labels:
version: 2.4.0
serviceAccount: spark
volumeMounts:
- name: "test-volume"
mountPath: "/tmp"
executor:
cores: 3
instances: 2
memory: "512m"
labels:
version: 2.4.0

2019-02-08 23:40:51 INFO SparkContext:54 - Added JAR file:///opt/spark/examples/jars/spark-examples_2.11-2.4.0.jar at spark://spark-pi-1549669214064-driver-svc.default.svc:7078/jars/spark-examples_2.11-2.4.0.jar with timestamp 1549669251557
2019-02-08 23:41:06 INFO ExecutorPodsAllocator:54 - Going to request 2 executors from Kubernetes.
2019-02-08 23:41:07 INFO Utils:54 - Successfully started service 'org.apache.spark.network.netty.NettyBlockTransferService' on port 7079.
2019-02-08 23:41:07 INFO NettyBlockTransferService:54 - Server created on spark-pi-1549669214064-driver-svc.default.svc:7079
2019-02-08 23:41:07 INFO BlockManager:54 - Using org.apache.spark.storage.RandomBlockReplicationPolicy for block replication policy
2019-02-08 23:41:07 INFO BlockManagerMaster:54 - Registering BlockManager BlockManagerId(driver, spark-pi-1549669214064-driver-svc.default.svc, 7079, None)
2019-02-08 23:41:07 INFO BlockManagerMasterEndpoint:54 - Registering block manager spark-pi-1549669214064-driver-svc.default.svc:7079 with 117.0 MB RAM, BlockManagerId(driver, spark-pi-1549669214064-driver-svc.default.svc, 7079, None)
2019-02-08 23:41:07 INFO BlockManagerMaster:54 - Registered BlockManager BlockManagerId(driver, spark-pi-1549669214064-driver-svc.default.svc, 7079, None)
2019-02-08 23:41:07 INFO BlockManager:54 - Initialized BlockManager: BlockManagerId(driver, spark-pi-1549669214064-driver-svc.default.svc, 7079, None)
2019-02-08 23:41:08 INFO ContextHandler:781 - Started o.s.j.s.ServletContextHandler@288ca5f0{/metrics/json,null,AVAILABLE,@Spark}
2019-02-08 23:41:17 INFO KubernetesClusterSchedulerBackend$KubernetesDriverEndpoint:54 - Registered executor NettyRpcEndpointRef(spark-client://Executor) (172.16.3.6:50738) with ID 1
2019-02-08 23:41:17 INFO BlockManagerMasterEndpoint:54 - Registering block manager 172.16.3.6:38237 with 117.0 MB RAM, BlockManagerId(1, 172.16.3.6, 38237, None)
2019-02-08 23:43:05 INFO KubernetesClusterSchedulerBackend:54 - SchedulerBackend is ready for scheduling beginning after waiting maxRegisteredResourcesWaitingTime: 120000(ms)
2019-02-08 23:43:08 INFO SparkContext:54 - Starting job: reduce at SparkPi.scala:38

+------------+--------+----------------------------------------------------+
| TYPE | AGE | MESSAGE |
+------------+--------+----------------------------------------------------+
| Normal | 4m | SparkApplication spark-pi |
| | | was added, Enqueuing it for |
| | | submission |
| Normal | 4m | SparkApplication spark-pi was |
| | | submitted successfully |
| Normal | 4m | Driver spark-pi-driver is |
| | | pending |
| Normal | 3m | Driver spark-pi-driver is |
| | | running |
| Normal | 3m | Executor |
| | | spark-pi-1549669214064-exec-1 |
| | | is pending |
| Normal | 3m | Executor |
| | | spark-pi-1549669214064-exec-2 |
| | | is pending |
| Normal | 3m | Executor |
| | | spark-pi-1549669214064-exec-1 |
| | | is running |
+------------+--------+----------------------------------------------------+
`

[liyinan926]

Interesting, still only one executor registered with the driver. Looks like the pending second executor did not get scheduled even with the newly available node, right? Will look into this.