kyuubi icon indicating copy to clipboard operation
kyuubi copied to clipboard

Published 20 hours ago • verified publisher icon apache

[Improvement] Spark engine: java.io.IOException: Unknown version of delegation token 8

Open MLikeWater opened this issue 2 years ago • 3 comments

Code of Conduct

Search before asking

  • [X] I have searched in the issues and found no similar issues.

What would you like to be improved?

Use Kyuubi master (commit 024fa2db70cec76c40756930af2c09f363451d5b) compile the installation package, use k8s deployment, Spark client way to submit a job, engine appears the following information:

22/08/11 20:02:48 INFO SparkTBinaryFrontendService: Client protocol version: HIVE_CLI_SERVICE_PROTOCOL_V10
22/08/11 20:02:48 INFO SparkSQLSessionManager: Opening session for [email protected]
22/08/11 20:02:48 WARN SQLConf: The SQL config 'spark.sql.adaptive.coalescePartitions.minPartitionNum' has been deprecated in Spark v3.2 and may be removed in the future. Use 'spark.sql.adaptive.coalescePartitions.minPartitionSize' instead.
22/08/11 20:02:48 WARN SQLConf: The SQL config 'spark.sql.adaptive.coalescePartitions.minPartitionNum' has been deprecated in Spark v3.2 and may be removed in the future. Use 'spark.sql.adaptive.coalescePartitions.minPartitionSize' instead.
22/08/11 20:02:48 WARN SQLConf: The SQL config 'spark.sql.adaptive.coalescePartitions.minPartitionNum' has been deprecated in Spark v3.2 and may be removed in the future. Use 'spark.sql.adaptive.coalescePartitions.minPartitionSize' instead.
22/08/11 20:02:48 INFO SparkSQLSessionManager: hive's session with SessionHandle [d81bb7e3-ff03-4c4c-9cd4-de465b00cf7a] is opened, current opening sessions 1
22/08/11 20:02:48 WARN SparkTBinaryFrontendService: No matching Hive token found for engine metastore uris thrift://hive-metastore01:9083,thrift://hive-metastore02:9083
22/08/11 20:02:48 WARN SparkTBinaryFrontendService: Error renew delegation tokens:
java.io.IOException: Unknown version of delegation token 8
        at org.apache.hadoop.security.token.delegation.AbstractDelegationTokenIdentifier.readFields(AbstractDelegationTokenIdentifier.java:193)
        at org.apache.kyuubi.util.KyuubiHadoopUtils$.getTokenIssueDate(KyuubiHadoopUtils.scala:94)
        at org.apache.kyuubi.engine.spark.SparkTBinaryFrontendService$.$anonfun$addOtherTokens$1(SparkTBinaryFrontendService.scala:169)
        at org.apache.kyuubi.engine.spark.SparkTBinaryFrontendService$.$anonfun$addOtherTokens$1$adapted(SparkTBinaryFrontendService.scala:166)
        at scala.collection.immutable.Map$Map1.foreach(Map.scala:193)
        at org.apache.kyuubi.engine.spark.SparkTBinaryFrontendService$.addOtherTokens(SparkTBinaryFrontendService.scala:166)
        at org.apache.kyuubi.engine.spark.SparkTBinaryFrontendService$.renewDelegationToken(SparkTBinaryFrontendService.scala:105)
        at org.apache.kyuubi.engine.spark.SparkTBinaryFrontendService.RenewDelegationToken(SparkTBinaryFrontendService.scala:48)
        at org.apache.kyuubi.shade.org.apache.hive.service.rpc.thrift.TCLIService$Processor$RenewDelegationToken.getResult(TCLIService.java:1897)
        at org.apache.kyuubi.shade.org.apache.hive.service.rpc.thrift.TCLIService$Processor$RenewDelegationToken.getResult(TCLIService.java:1882)
        at org.apache.kyuubi.shade.org.apache.thrift.ProcessFunction.process(ProcessFunction.java:39)
        at org.apache.kyuubi.shade.org.apache.thrift.TBaseProcessor.process(TBaseProcessor.java:39)
        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:748)
22/08/11 20:02:48 INFO OperationLog: Creating operation log file /opt/kyuubi/work/engine_operation_logs/d81bb7e3-ff03-4c4c-9cd4-de465b00cf7a/d436905a-8d41-4564-b86d-9709b922ce9d
22/08/11 20:02:48 INFO ExecuteStatement: Processing hive's query[d436905a-8d41-4564-b86d-9709b922ce9d]: INITIALIZED_STATE -> PENDING_STATE, statement: show databases
22/08/11 20:02:48 INFO ExecuteStatement: Processing hive's query[d436905a-8d41-4564-b86d-9709b922ce9d]: PENDING_STATE -> RUNNING_STATE, statement: show databases

However, the query is normal.

The environment information is as follows:

Kyuubi version: master
Spark: 3.2.1
Hive metastore: 3.1.2

How should we improve?

No response

Are you willing to submit PR?

  • [ ] Yes I am willing to submit a PR!

MLikeWater avatar Aug 12 '22 03:08 MLikeWater

cc @zhouyifan279

yaooqinn avatar Aug 12 '22 03:08 yaooqinn

@zhouyifan279 Thanks for support. Ozone inherits the parent Hadoop class and implements: https://github.com/apache/ozone/blob/master/hadoop-ozone/common/src/main/java/org/apache/hadoop/ozone/security/OzoneTokenIdentifier.java

MLikeWater avatar Aug 12 '22 06:08 MLikeWater

In addition to engine logs, Kyuubi Server logs are as follows:

20:05:11.197 INFO org.apache.kyuubi.credentials.HadoopFsDelegationTokenProvider: getting token owned by scm for: ofs://cluster1/
20:05:11.208 INFO org.apache.kyuubi.credentials.HadoopCredentialsManager: Scheduling renewal in 3600000 ms.
20:05:11.208 INFO org.apache.kyuubi.credentials.HadoopCredentialsManager: Send new credentials with epoch 0 to SQL engine through session 48eabdf4-6620-4259-8bea-4bbc2c1674e2
20:05:11.254 WARN org.apache.kyuubi.client.KyuubiSyncThriftClient: TRenewDelegationTokenReq(sessionHandle:TSessionHandle(sessionId:THandleIdentifier(guid:BF 45 A5 6B C8 CB 4C 88 A3 0C 8E 9D 95 36 92 7B, secret:C2 EE 5B 97 3E A0 41 FC AC 16 9B D7 08 ED 8F 38)), delegationToken:SERUUwABNDEwLjczLjE0NS4yNDE6OTg2MiwxMC44NC43My41Mzo5ODYyLDEwLjg5LjY2LjIwOjk4^M
......
OTg2MgA=) failed on engine side
org.apache.kyuubi.KyuubiSQLException: Unknown version of delegation token 8
        at org.apache.kyuubi.KyuubiSQLException$.apply(KyuubiSQLException.scala:69) ~[kyuubi-common_2.12-1.6.0-SNAPSHOT.jar:1.6.0-SNAPSHOT]
        at org.apache.kyuubi.KyuubiSQLException$.apply(KyuubiSQLException.scala:81) ~[kyuubi-common_2.12-1.6.0-SNAPSHOT.jar:1.6.0-SNAPSHOT]
        at org.apache.kyuubi.client.KyuubiSyncThriftClient.sendCredentials(KyuubiSyncThriftClient.scala:371) ~[kyuubi-server_2.12-1.6.0-SNAPSHOT.jar:1.6.0-SNAPSHOT]
        at org.apache.kyuubi.operation.LaunchEngine.$anonfun$renewEngineCredentials$1(LaunchEngine.scala:70) ~[kyuubi-server_2.12-1.6.0-SNAPSHOT.jar:1.6.0-SNAPSHOT]
        at org.apache.kyuubi.operation.LaunchEngine.$anonfun$renewEngineCredentials$1$adapted(LaunchEngine.scala:70) ~[kyuubi-server_2.12-1.6.0-SNAPSHOT.jar:1.6.0-SNAPSHOT]
        at org.apache.kyuubi.credentials.HadoopCredentialsManager.$anonfun$sendCredentialsIfNeeded$2(HadoopCredentialsManager.scala:178) ~[kyuubi-server_2.12-1.6.0-SNAPSHOT.jar:1.6.0-SNAPSHOT]
        at scala.runtime.java8.JFunction0$mcV$sp.apply(JFunction0$mcV$sp.java:23) ~[scala-library-2.12.15.jar:?]
        at scala.util.Try$.apply(Try.scala:213) ~[scala-library-2.12.15.jar:?]
        at org.apache.kyuubi.credentials.HadoopCredentialsManager.sendCredentialsIfNeeded(HadoopCredentialsManager.scala:178) ~[kyuubi-server_2.12-1.6.0-SNAPSHOT.jar:1.6.0-SNAPSHOT]
        at org.apache.kyuubi.operation.LaunchEngine.renewEngineCredentials(LaunchEngine.scala:71) ~[kyuubi-server_2.12-1.6.0-SNAPSHOT.jar:1.6.0-SNAPSHOT]
        at org.apache.kyuubi.operation.LaunchEngine.$anonfun$runInternal$1(LaunchEngine.scala:52) ~[kyuubi-server_2.12-1.6.0-SNAPSHOT.jar:1.6.0-SNAPSHOT]
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) ~[?:1.8.0_311]
        at java.util.concurrent.FutureTask.run(FutureTask.java:266) ~[?:1.8.0_311]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) ~[?:1.8.0_311]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) ~[?:1.8.0_311]
        at java.lang.Thread.run(Thread.java:748) ~[?:1.8.0_311]
Caused by: java.io.IOException: Unknown version of delegation token 8
        at org.apache.hadoop.security.token.delegation.AbstractDelegationTokenIdentifier.readFields(AbstractDelegationTokenIdentifier.java:193) ~[hadoop-common-3.2.2.jar:?]
        at org.apache.kyuubi.util.KyuubiHadoopUtils$.getTokenIssueDate(KyuubiHadoopUtils.scala:94) ~[kyuubi-common_2.12-1.6.0-SNAPSHOT.jar:1.6.0-SNAPSHOT]
        at org.apache.kyuubi.engine.spark.SparkTBinaryFrontendService$.$anonfun$addOtherTokens$1(SparkTBinaryFrontendService.scala:169) ~[?:?]
        at org.apache.kyuubi.engine.spark.SparkTBinaryFrontendService$.$anonfun$addOtherTokens$1$adapted(SparkTBinaryFrontendService.scala:166) ~[?:?]
        at scala.collection.immutable.Map$Map1.foreach(Map.scala:193) ~[scala-library-2.12.15.jar:?]
        at org.apache.kyuubi.engine.spark.SparkTBinaryFrontendService$.addOtherTokens(SparkTBinaryFrontendService.scala:166) ~[?:?]
        at org.apache.kyuubi.engine.spark.SparkTBinaryFrontendService$.renewDelegationToken(SparkTBinaryFrontendService.scala:105) ~[?:?]
        at org.apache.kyuubi.engine.spark.SparkTBinaryFrontendService.RenewDelegationToken(SparkTBinaryFrontendService.scala:48) ~[?:?]
        at org.apache.kyuubi.shade.org.apache.hive.service.rpc.thrift.TCLIService$Processor$RenewDelegationToken.getResult(TCLIService.java:1897) ~[?:?]
        at org.apache.kyuubi.shade.org.apache.hive.service.rpc.thrift.TCLIService$Processor$RenewDelegationToken.getResult(TCLIService.java:1882) ~[?:?]
        at org.apache.kyuubi.shade.org.apache.thrift.ProcessFunction.process(ProcessFunction.java:39) ~[?:?]
        at org.apache.kyuubi.shade.org.apache.thrift.TBaseProcessor.process(TBaseProcessor.java:39) ~[?:?]
        at org.apache.kyuubi.service.authentication.TSetIpAddressProcessor.process(TSetIpAddressProcessor.scala:36) ~[kyuubi-common_2.12-1.6.0-SNAPSHOT.jar:1.6.0-SNAPSHOT]
        at org.apache.kyuubi.shade.org.apache.thrift.server.TThreadPoolServer$WorkerProcess.run(TThreadPoolServer.java:286) ~[?:?]
        ... 3 more
20:05:11.260 INFO org.apache.kyuubi.credentials.HadoopCredentialsManager: Update session credentials epoch from -1 to 0
20:05:11.260 INFO org.apache.kyuubi.operation.LaunchEngine: Processing scm's query[7c02605b-7a5b-4fca-98a7-2e89d1d94f9d]: RUNNING_STATE -> FINISHED_STATE, statement: LAUNCH_ENGINE, time taken: 23.649 seconds
20:05:26.177 INFO org.apache.kyuubi.server.KyuubiTBinaryFrontendService: Received request of closing SessionHandle [48eabdf4-6620-4259-8bea-4bbc2c1674e2]
20:05:26.178 INFO org.apache.kyuubi.session.KyuubiSessionManager: SessionHandle [48eabdf4-6620-4259-8bea-4bbc2c1674e2] is closed, current opening sessions 0
20:05:26.178 INFO org.apache.kyuubi.operation.LaunchEngine: Processing scm's query[7c02605b-7a5b-4fca-98a7-2e89d1d94f9d]: FINISHED_STATE -> CLOSED_STATE, statement: LAUNCH_ENGINE
20:05:26.210 INFO org.apache.kyuubi.server.KyuubiTBinaryFrontendService: Finished closing SessionHandle [48eabdf4-6620-4259-8bea-4bbc2c1674e2]
20:59:46.848 INFO org.apache.kyuubi.server.KinitAuxiliaryService: Successfully kinit -kt /opt/kyuubi/scm.keytab scm/[email protected]

MLikeWater avatar Aug 12 '22 06:08 MLikeWater

@zhouyifan279 Great 👍

MLikeWater avatar Aug 15 '22 07:08 MLikeWater