Launcher not stopping when pod moves to Succeeded status

[ash211]

...
2017/02/15 08:35:19.780 INFO LoggingPodStatusWatcher: Application status for org-apache-spark-examples-sparkpi-1487176453511 (phase: Running)
2017/02/15 08:35:20.781 INFO LoggingPodStatusWatcher: Application status for org-apache-spark-examples-sparkpi-1487176453511 (phase: Running)
2017/02/15 08:35:21.781 INFO LoggingPodStatusWatcher: Application status for org-apache-spark-examples-sparkpi-1487176453511 (phase: Running)
2017/02/15 08:35:22.782 INFO LoggingPodStatusWatcher: Application status for org-apache-spark-examples-sparkpi-1487176453511 (phase: Running)
2017/02/15 08:35:23.782 INFO LoggingPodStatusWatcher: Application status for org-apache-spark-examples-sparkpi-1487176453511 (phase: Running)
2017/02/15 08:35:23.922 INFO LoggingPodStatusWatcher: Application status for org-apache-spark-examples-sparkpi-1487176453511 (phase: Succeeded)
2017/02/15 08:35:23.922 INFO LoggingPodStatusWatcher: Phase changed, new state:
	 pod name: org-apache-spark-examples-sparkpi-1487176453511
	 namespace: default
	 labels: spark-app-id -> org-apache-spark-examples-sparkpi-1487176453511, spark-app-name -> org.apache.spark.examples.SparkPi, spark-driver -> org-apache-spark-examples-sparkpi-1487176453511
	 pod uid: 970400ae-f39c-11e6-ae50-0e0cecaa76e2
	 creation time: 2017-02-15T16:34:15Z
	 service account name: default
	 volumes: spark-submission-secret-volume, default-token-fvqq7
	 node name: REDACTED
	 start time: 2017-02-15T16:34:15Z
	 container images: ash211/testrepo:driver-latest7
	 phase: Succeeded
2017/02/15 08:35:23.923 INFO Client: Application org-apache-spark-examples-sparkpi-1487176453511 finished.
2017/02/15 08:35:23.925 INFO WatchConnectionManager: WebSocket close received. code: 1000, reason:
2017/02/15 08:35:23.925 WARN WatchConnectionManager: Ignoring onClose for already closed/closing websocket
2017/02/15 08:35:24.783 INFO LoggingPodStatusWatcher: Application status for org-apache-spark-examples-sparkpi-1487176453511 (phase: Succeeded)
2017/02/15 08:35:25.783 INFO LoggingPodStatusWatcher: Application status for org-apache-spark-examples-sparkpi-1487176453511 (phase: Succeeded)
2017/02/15 08:35:26.784 INFO LoggingPodStatusWatcher: Application status for org-apache-spark-examples-sparkpi-1487176453511 (phase: Succeeded)
2017/02/15 08:35:27.784 INFO LoggingPodStatusWatcher: Application status for org-apache-spark-examples-sparkpi-1487176453511 (phase: Succeeded)
2017/02/15 08:35:28.784 INFO LoggingPodStatusWatcher: Application status for org-apache-spark-examples-sparkpi-1487176453511 (phase: Succeeded)
2017/02/15 08:35:29.785 INFO LoggingPodStatusWatcher: Application status for org-apache-spark-examples-sparkpi-1487176453511 (phase: Succeeded)
2017/02/15 08:35:30.785 INFO LoggingPodStatusWatcher: Application status for org-apache-spark-examples-sparkpi-1487176453511 (phase: Succeeded)
2017/02/15 08:35:31.786 INFO LoggingPodStatusWatcher: Application status for org-apache-spark-examples-sparkpi-1487176453511 (phase: Succeeded)
2017/02/15 08:35:32.786 INFO LoggingPodStatusWatcher: Application status for org-apache-spark-examples-sparkpi-1487176453511 (phase: Succeeded)
...
repeats forever
...

[varunkatta]

Launcher also doesn't stop on job failures. I have seen launcher repeat forever as shown below

2017-02-15 09:56:30 INFO  LoggingPodStatusWatcher:54 - Application status for spark-pi-1487181293571 (phase: Running)
2017-02-15 09:56:31 INFO  LoggingPodStatusWatcher:54 - Application status for spark-pi-1487181293571 (phase: Running)
2017-02-15 09:56:32 INFO  LoggingPodStatusWatcher:54 - Application status for spark-pi-1487181293571 (phase: Running)
2017-02-15 09:56:33 INFO  LoggingPodStatusWatcher:54 - Application status for spark-pi-1487181293571 (phase: Running)

Steps to repro

• Start Sparkpi
• Wait till the executors launch
• Kill all spark-pi pods
• See the launch repeat forever in job 'running' state

[varunkatta]

This is Varun Katta from Pepperdata Inc. I quickly poked around the code to see what might be causing this behavior.

I was able to fix the issue making a simple change to LoggingPodStatusWatcher. This will at least fix the succeeds phase - repeats forever issue. I can send a pull request, if it is OK.

[ash211]

Hi @varunkatta welcome to the project!

Since you have a fix already coded up maybe you can send it in as a PR? I'd be happy to code review, test, and soon merge. Thank you!

[ash211]

@foxish I think this is a regression introduced by the bump you made to kubernetes-client in PR #105

I'm seeing these new log lines from WatchConnectionManager introduced in this diff: https://github.com/fabric8io/kubernetes-client/pull/652/files#diff-82d7fbf23850dc5eb044f65a616bb245R164

2017/02/15 08:45:36.136 INFO Client: Application org-apache-spark-examples-sparkpi-1487177056890 finished.
2017/02/15 08:45:36.137 INFO WatchConnectionManager: WebSocket close received. code: 1000, reason:
2017/02/15 08:45:36.137 WARN WatchConnectionManager: Ignoring onClose for already closed/closing websocket
2017/02/15 08:45:37.097 INFO LoggingPodStatusWatcher: Application status for org-apache-spark-examples-sparkpi-1487177056890 (phase: Succeeded)
2017/02/15 08:45:38.098 INFO LoggingPodStatusWatcher: Application status for org-apache-spark-examples-sparkpi-1487177056890 (phase: Succeeded)
2017/02/15 08:45:39.098 INFO LoggingPodStatusWatcher: Application status for org-apache-spark-examples-sparkpi-1487177056890 (phase: Succeeded)

What does code: 1000 mean? It looks like the watch isn't getting closed now so the scheduler doesn't get shut down so the logging runs forever. The linked PR fixes this by shutting down the thread scheduler directly in response to an event, rather than relying on the watch's onClose method to be called which no longer happens.

Here's the WatchConnectionManager-only logs from a recent run:

2017-02-15 16:06:22 INFO  WatchConnectionManager:158 - WebSocket successfully opened
2017-02-15 16:06:22 INFO  WatchConnectionManager:158 - WebSocket successfully opened
2017-02-15 16:06:22 INFO  WatchConnectionManager:158 - WebSocket successfully opened
2017-02-15 16:06:22 INFO  WatchConnectionManager:158 - WebSocket successfully opened
2017-02-15 16:06:29 INFO  WatchConnectionManager:296 - WebSocket close received. code: 1000, reason:
2017-02-15 16:06:29 WARN  WatchConnectionManager:298 - Ignoring onClose for already closed/closing websocket
2017-02-15 16:06:29 INFO  WatchConnectionManager:296 - WebSocket close received. code: 1000, reason:
2017-02-15 16:06:29 WARN  WatchConnectionManager:298 - Ignoring onClose for already closed/closing websocket
2017-02-15 16:06:29 INFO  WatchConnectionManager:296 - WebSocket close received. code: 1000, reason:
2017-02-15 16:06:29 WARN  WatchConnectionManager:298 - Ignoring onClose for already closed/closing websocket
2017-02-15 16:07:16 INFO  WatchConnectionManager:296 - WebSocket close received. code: 1000, reason:
2017-02-15 16:07:16 WARN  WatchConnectionManager:298 - Ignoring onClose for already closed/closing websocket

We should make some of those DEBUG rather than INFO

[foxish]

I'll send a PR upstream to fix the logging behavior in both watchers.
I think the change in behavior you see is due to a different PR: fabric8io/kubernetes-client#634
I did not make any behavioral changes to WatchConnectionManager.java. I will investigate and send a fix upstream.

[ash211]

Sounds good -- thank you for the quick response! I'll propose a patch with my desired change in the logging behavior upstream and we can discuss there.

[ash211]

fabric8io/kubernetes-client#663

[kimoonkim]

Found another case Launcher did not stop. My k8s cluster uses an overlay network, which was broken because the overlay daemons crashed. This prevented the launcher from uploading local jars. The good news is that our Client code correctly recognized this and shut down the pod and service:

Exception in thread "main" org.apache.spark.SparkException: Failed to submit the application to the driver pod.
	at org.apache.spark.deploy.kubernetes.Client$$anonfun$run$7$$anonfun$apply$6.apply(Client.scala:169)
	at org.apache.spark.deploy.kubernetes.Client$$anonfun$run$7$$anonfun$apply$6.apply(Client.scala:131)
	at org.apache.spark.util.Utils$.tryWithResource(Utils.scala:2530)
	at org.apache.spark.deploy.kubernetes.Client$$anonfun$run$7.apply(Client.scala:131)
	at org.apache.spark.deploy.kubernetes.Client$$anonfun$run$7.apply(Client.scala:109)
	at org.apache.spark.util.Utils$.tryWithResource(Utils.scala:2530)
	at org.apache.spark.deploy.kubernetes.Client.run(Client.scala:109)
	at org.apache.spark.deploy.kubernetes.Client$.main(Client.scala:812)
	at org.apache.spark.deploy.kubernetes.Client.main(Client.scala)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:497)
	at org.apache.spark.deploy.SparkSubmit$.org$apache$spark$deploy$SparkSubmit$$runMain(SparkSubmit.scala:747)
	at org.apache.spark.deploy.SparkSubmit$.doRunMain$1(SparkSubmit.scala:178)
	at org.apache.spark.deploy.SparkSubmit$.submit(SparkSubmit.scala:203)
	at org.apache.spark.deploy.SparkSubmit$.main(SparkSubmit.scala:117)
	at org.apache.spark.deploy.SparkSubmit.main(SparkSubmit.scala)

However, LoggingPodStatusWatcher was not informed of this and kept going:

2017-02-23 13:00:06 INFO  LoggingPodStatusWatcher:54 - Application status for spark-pi-1487883497166 (phase: Running)
2017-02-23 13:00:07 INFO  LoggingPodStatusWatcher:54 - Application status for spark-pi-1487883497166 (phase: Running)
2017-02-23 13:00:08 INFO  LoggingPodStatusWatcher:54 - Application status for spark-pi-1487883497166 (phase: Running)
2017-02-23 13:00:09 INFO  LoggingPodStatusWatcher:54 - Application status for spark-pi-1487883497166 (phase: Running)
2017-02-23 13:00:10 INFO  LoggingPodStatusWatcher:54 - Application status for spark-pi-1487883497166 (phase: Running)
2017-02-23 13:00:11 INFO  LoggingPodStatusWatcher:54 - Application status for spark-pi-1487883497166 (phase: Running)
2017-02-23 13:00:12 INFO  LoggingPodStatusWatcher:54 - Application status for spark-pi-1487883497166 (phase: Running)
2017-02-23 13:00:13 INFO  LoggingPodStatusWatcher:54 - Application status for spark-pi-1487883497166 (phase: Running)
...

Hopefully #142 fixes this too.

[ash211]

@kimoonkim I filed the above linked ticket for that. I think the underlying cause is the missing onClose call from the upstream library.