Spark Engine on K8s not shutdown when session timeout

[tgravescs]

Hello,

I'm running kyuubi with spark on k8s and I'm seeing a problem where the spark driver pod is stuck when trying to shutdown due to idle timeout. I think the problem is the SparkTBinaryFrontendHandler is still there (though I'm not positive on this).
Note Kyuubi thinks the engine is gone at this point. Although it still shows a session for it.

spark driver log has:

23/07/21 18:19:04 INFO SparkSQLSessionManager: Closing session 1226d019-d39f-4973-95d3-c1df387e6db8 that has been idle for more than 60000 ms
23/07/21 18:19:04 INFO SparkSQLSessionManager: user1's session with SessionHandle [1226d019-d39f-4973-95d3-c1df387e6db8]/batch-5cef6739-51e0-469b-b039-8ec0ec6a883e i
s closed, current opening sessions 0
23/07/21 18:19:04 ERROR ExecutePython: python worker exit
23/07/21 18:19:04 WARN ExecutePython: Process has been interrupted
Exception in thread "session[1226d019-d39f-4973-95d3-c1df387e6db8] process stderr thread" java.io.IOException: Stream closed
        at java.io.BufferedInputStream.getBufIfOpen(BufferedInputStream.java:170)
        at java.io.BufferedInputStream.read(BufferedInputStream.java:336)
        at sun.nio.cs.StreamDecoder.readBytes(StreamDecoder.java:284)
        at sun.nio.cs.StreamDecoder.implRead(StreamDecoder.java:326)
        at sun.nio.cs.StreamDecoder.read(StreamDecoder.java:178)
        at java.io.InputStreamReader.read(InputStreamReader.java:184)
        at java.io.BufferedReader.fill(BufferedReader.java:161)
        at java.io.BufferedReader.readLine(BufferedReader.java:324)
        at java.io.BufferedReader.readLine(BufferedReader.java:389)
        at scala.io.BufferedSource$BufferedLineIterator.hasNext(BufferedSource.scala:74)
        at scala.collection.Iterator$$anon$12.hasNext(Iterator.scala:513)
        at scala.collection.Iterator.foreach(Iterator.scala:943)
        at scala.collection.Iterator.foreach$(Iterator.scala:943)
        at scala.collection.AbstractIterator.foreach(Iterator.scala:1431)
        at org.apache.kyuubi.engine.spark.operation.ExecutePython$$anon$2.run(ExecutePython.scala:347)
23/07/21 18:24:04 INFO SparkSQLSessionManager: Idled for more than 300000 ms, terminating
23/07/21 18:24:04 INFO SparkSQLEngine: Service: [SparkTBinaryFrontend] is stopping.
23/07/21 18:24:04 INFO SparkTBinaryFrontendService: Service: [EngineServiceDiscovery] is stopping.
23/07/21 18:24:04 WARN ZookeeperDiscoveryClient: This Kyuubi instance 192.XXX.XX.XX:33895 is now de-registered from ZooKeeper. The server will be shut down after th
e last client session completes.
23/07/21 18:24:04 INFO CuratorFrameworkImpl: backgroundOperationsLoop exiting
23/07/21 18:24:04 INFO ZooKeeper: Session: 0x1000619d028003d closed
23/07/21 18:24:04 INFO EngineServiceDiscovery: Service[EngineServiceDiscovery] is stopped.
23/07/21 18:24:04 INFO SparkTBinaryFrontendService: Service[SparkTBinaryFrontend] is stopped.
23/07/21 18:24:04 INFO ClientCnxn: EventThread shut down for session: 0x1000619d028003d
23/07/21 18:24:04 INFO SparkTBinaryFrontendService: SparkTBinaryFrontend has stopped
23/07/21 18:24:04 INFO SparkSQLEngine: Service: [SparkSQLBackendService] is stopping.
23/07/21 18:24:04 INFO SparkSQLBackendService: Service: [SparkSQLSessionManager] is stopping.
23/07/21 18:24:04 INFO SparkSQLSessionManager: Service: [SparkSQLOperationManager] is stopping.
23/07/21 18:24:04 INFO SparkSQLOperationManager: Service[SparkSQLOperationManager] is stopped.
23/07/21 18:24:04 INFO SparkSQLSessionManager: Service[SparkSQLSessionManager] is stopped.
23/07/21 18:24:14 INFO KyuubiPythonGatewayServer: shutting down the python gateway server.
23/07/21 18:24:14 INFO SparkSQLBackendService: Service[SparkSQLBackendService] is stopped.
23/07/21 18:24:14 INFO SparkSQLEngine: Service[SparkSQLEngine] is stopped.
23/07/21 18:24:14 INFO SparkUI: Stopped Spark web UI at http://spark-b3dd9d8979aa2a0f-driver-svc.default.svc:4040
23/07/21 18:24:14 INFO KubernetesClusterSchedulerBackend: Shutting down all executors
23/07/21 18:24:14 INFO KubernetesClusterSchedulerBackend$KubernetesDriverEndpoint: Asking each executor to shut down
23/07/21 18:24:14 WARN ExecutorPodsWatchSnapshotSource: Kubernetes client has been closed.
23/07/21 18:24:14 INFO MapOutputTrackerMasterEndpoint: MapOutputTrackerMasterEndpoint stopped!
23/07/21 18:24:14 INFO MemoryStore: MemoryStore cleared
23/07/21 18:24:14 INFO BlockManager: BlockManager stopped
23/07/21 18:24:14 INFO BlockManagerMaster: BlockManagerMaster stopped
23/07/21 18:24:14 INFO OutputCommitCoordinator$OutputCommitCoordinatorEndpoint: OutputCommitCoordinator stopped!
23/07/21 18:24:14 INFO SparkContext: Successfully stopped SparkContext

as you can see the spark context is gone. Looking at the threads still up in the driver I noticed the SparkTBinaryFrontendHandler and was wondering if that might be causing an issue?

"SparkTBinaryFrontendHandler-Pool: Thread-127" #127 prio=5 os_prio=0 tid=0x00007f5220003000 nid=0xa7 runnable [0x00007f5236dfa000]                                   |
   java.lang.Thread.State: RUNNABLE                                                                                                                                  |
        at java.net.SocketInputStream.socketRead0(Native Method)                                                                                                     |
        at java.net.SocketInputStream.socketRead(SocketInputStream.java:116)                                                                                         |
        at java.net.SocketInputStream.read(SocketInputStream.java:171)                                                                                               |
        at java.net.SocketInputStream.read(SocketInputStream.java:141)                                                                                               |
        at java.io.BufferedInputStream.fill(BufferedInputStream.java:246)                                                                                            |
        at java.io.BufferedInputStream.read1(BufferedInputStream.java:286)                                                                                           |
        at java.io.BufferedInputStream.read(BufferedInputStream.java:345)                                                                                            |
        - locked <0x00000000d8f247f0> (a java.io.BufferedInputStream)                                                                                                |
        at org.apache.kyuubi.shade.org.apache.thrift.transport.TIOStreamTransport.read(TIOStreamTransport.java:127)                                                  |
        at org.apache.kyuubi.shade.org.apache.thrift.transport.TTransport.readAll(TTransport.java:86)                                                                |
        at org.apache.kyuubi.shade.org.apache.thrift.transport.TSaslTransport.readLength(TSaslTransport.java:376)                                                    |
        at org.apache.kyuubi.shade.org.apache.thrift.transport.TSaslTransport.readFrame(TSaslTransport.java:453)                                                     |
        at org.apache.kyuubi.shade.org.apache.thrift.transport.TSaslTransport.read(TSaslTransport.java:435)                                                          |
        at org.apache.kyuubi.shade.org.apache.thrift.transport.TSaslServerTransport.read(TSaslServerTransport.java:41)                                               |
        at org.apache.kyuubi.shade.org.apache.thrift.transport.TTransport.readAll(TTransport.java:86)                                                                |
        at org.apache.kyuubi.shade.org.apache.thrift.protocol.TBinaryProtocol.readAll(TBinaryProtocol.java:429)                                                      |
        at org.apache.kyuubi.shade.org.apache.thrift.protocol.TBinaryProtocol.readI32(TBinaryProtocol.java:318)                                                      |
        at org.apache.kyuubi.shade.org.apache.thrift.protocol.TBinaryProtocol.readMessageBegin(TBinaryProtocol.java:219)                                             |
        at org.apache.kyuubi.shade.org.apache.thrift.TBaseProcessor.process(TBaseProcessor.java:27)                                                                  |
        at org.apache.kyuubi.service.authentication.TSetIpAddressProcessor.process(TSetIpAddressProcessor.scala:36)                                                  |
        at org.apache.kyuubi.shade.org.apache.thrift.server.TThreadPoolServer$WorkerProcess.run(TThreadPoolServer.java:286)                                          |
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)                                                                           |
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)                                                                           |
        at java.lang.Thread.run(Thread.java:750)

anyone seen this or know what might be the problem?

[yaooqinn]

Did it hang for a prolonged period or for 60 seconds?

[HaoYang670]

Hi @tgravescs , please take a look at #5060.

[HaoYang670]

I also find that sometimes the spark cluster will be removed before sessions.

[HaoYang670]

But I can't reproduce it each time

[zwangsheng]

Provide the version of kyuubi server and spark sql engine, of course if build from master branch, it is best to provide commit hash.

It is very helpful to analyze the issue.

[HaoYang670]

This commit: huangzhir@ae47042