MLikeWater commented on issue #2855:
URL:
https://github.com/apache/incubator-kyuubi/issues/2855#issuecomment-1152385586
Post the main logs of the three classes:
HiveDelegationTokenProvider:
```
21:39:13.890 DEBUG org.apache.thrift.transport.TSaslTransport: CLIENT:
Received message with status COMPLETE and payload length 0
21:39:13.890 INFO hive.metastore: Opened a connection to metastore, current
connections: 1
21:39:13.890 INFO hive.metastore: Connected to metastore.
21:39:13.948 INFO org.apache.kyuubi.credentials.HiveDelegationTokenProvider:
Created HiveMetaStoreClient with metastore uris thrift://10.2.1.3:9083
21:39:13.951 INFO org.apache.kyuubi.credentials.HadoopCredentialsManager:
Using the following builtin delegation token providers: hadoopfs, hive.
21:39:13.951 INFO org.apache.kyuubi.credentials.HadoopCredentialsManager:
Service[HadoopCredentialsManager] is initialized.
21:39:13.956 INFO org.apache.kyuubi.operation.KyuubiOperationManager:
Service[KyuubiOperationManager] is initialized.
21:39:13.957 INFO org.apache.kyuubi.session.KyuubiSessionManager:
Service[KyuubiSessionManager] is initialized.
21:39:13.957 INFO org.apache.kyuubi.server.KyuubiServer:
Service[KyuubiBackendService] is initialized.
21:39:13.975 INFO org.apache.kyuubi.server.KyuubiTBinaryFrontendService:
Initializing KyuubiTBinaryFrontend on xxxx:10011 with [200, 999] worker threads
21:39:14.023 INFO org.apache.curator.framework.imps.CuratorFrameworkImpl:
Starting
21:39:14.024 DEBUG org.apache.curator.CuratorZookeeperClient: Starting
21:39:14.024 DEBUG org.apache.curator.ConnectionState: Starting
21:39:14.024 DEBUG org.apache.curator.ConnectionState: reset
21:39:14.028 INFO org.apache.zookeeper.ZooKeeper: Client
environment:zookeeper.version=3.4.14-4c25d480e66aadd371de8bd2fd8da255ac140bcf,
built on 03/06/2019 16:18 GMT
21:39:14.028 INFO org.apache.zookeeper.ZooKeeper: Client
environment:host.name=xxxxx
21:39:14.028 INFO org.apache.zookeeper.ZooKeeper: Client
environment:java.version=1.8.0_311
21:39:14.028 INFO org.apache.zookeeper.ZooKeeper: Client
environment:java.vendor=Oracle Corporation
21:39:14.028 INFO org.apache.zookeeper.ZooKeeper: Client
environment:java.home=/usr/java/jdk1.8.0_311-amd64/jre
...
21:40:16.203 INFO org.apache.kyuubi.credentials.HiveDelegationTokenProvider:
Getting Hive delegation token for meimei against hive/xxxx@xxxx
21:40:16.205 DEBUG org.apache.thrift.transport.TSaslTransport: writing data
length: 97
21:40:16.207 DEBUG org.apache.thrift.transport.TSaslTransport: CLIENT:
reading data length: 164
21:40:17.857 DEBUG org.apache.kyuubi.server.KyuubiServer: OperationHandle
[type=UNKNOWN_OPERATION, identifier: 14f7175c-b1bc-4058-8c21-eb34b2cd8519]:
Long polling timed out, null
21:40:17.857 DEBUG org.apache.thrift.transport.TSaslTransport: writing data
length: 79
21:40:17.858 DEBUG org.apache.thrift.transport.TSaslTransport: SERVER:
reading data length: 117
21:40:17.858 DEBUG org.apache.kyuubi.server.KyuubiTBinaryFrontendService:
TFetchResultsReq(operationHandle:TOperationHandle(operationId:THandleIdentifier(guid:14
F7 17 5C B1 BC 40 58 8C 21 EB 34 B2 CD 85 19, secret:4B DE EA 3D 64 24 41 69
90 7D 25 46 42 F6 41 DF), operationType:UNKNOWN, hasResultSet:false),
orientation:FETCH_NEXT, maxRows:1000, fetchType:1)
21:40:17.861 DEBUG org.apache.thrift.transport.TSaslTransport: writing data
length: 583664
21:40:17.867 DEBUG org.apache.thrift.transport.TSaslTransport: SERVER:
reading data length: 100
21:40:17.867 DEBUG org.apache.kyuubi.server.KyuubiTBinaryFrontendService:
TGetOperationStatusReq(operationHandle:TOperationHandle(operationId:THandleIdentifier(guid:14
F7 17 5C B1 BC 40 58 8C 21 EB 34 B2 CD 85 19, secret:4B DE EA 3D 64 24 41 69
90 7D 25 46 42 F6 41 DF), operationType:UNKNOWN, hasResultSet:false))
21:40:20.244 DEBUG org.apache.thrift.transport.TSaslServerTransport:
transport map does not contain key
21:40:20.244 DEBUG org.apache.thrift.transport.TSaslTransport: opening
transport org.apache.thrift.transport.TSaslServerTransport@3dcfaa6b
21:40:20.244 DEBUG org.apache.thrift.transport.TSaslTransport: No data or no
sasl data in the stream
21:40:20.245 DEBUG org.apache.thrift.transport.TSaslServerTransport: failed
to open server transport
org.apache.thrift.transport.TSaslTransportException: No data or no sasl data
in the stream
at
org.apache.thrift.transport.TSaslTransport.open(TSaslTransport.java:328)
~[libthrift-0.9.3.jar:0.9.3]
at
org.apache.thrift.transport.TSaslServerTransport.open(TSaslServerTransport.java:41)
~[libthrift-0.9.3.jar:0.9.3]
at
org.apache.thrift.transport.TSaslServerTransport$Factory.getTransport(TSaslServerTransport.java:216)
~[libthrift-0.9.3.jar:0.9.3]
at
org.apache.thrift.server.TThreadPoolServer$WorkerProcess.run(TThreadPoolServer.java:269)
~[libthrift-0.9.3.jar:0.9.3]
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]
21:40:20.801 DEBUG org.apache.zookeeper.ClientCnxn: Got ping response for
sessionid: 0x20165086c3b0008 after 0ms
```
```
21:40:16.160 INFO org.apache.kyuubi.credentials.HadoopCredentialsManager:
Scheduling renewal in 0 ms.
21:40:16.160 INFO org.apache.kyuubi.credentials.HadoopCredentialsManager:
Created CredentialsRef for user meimei and scheduled a renewal task
21:40:16.162 DEBUG org.apache.hadoop.security.UserGroupInformation:
PrivilegedAction as:meimei (auth:PROXY) via scm/scm@xxxxx (auth:KERBEROS)
from:org.apache.kyuubi.credentials.HadoopFsDelegationTokenProvider$.doAsProxyUser(HadoopFsDelegationTokenProvider.scala:115)
21:40:16.163 DEBUG org.apache.hadoop.fs.FileSystem: Bypassing cache to
create filesystem ofs://cluster1/
21:40:16.163 DEBUG org.apache.hadoop.fs.FileSystem: Looking for FS
supporting ofs
21:40:16.163 DEBUG org.apache.hadoop.fs.FileSystem: looking for
configuration option fs.ofs.impl
21:40:16.163 DEBUG org.apache.hadoop.fs.FileSystem: Filesystem ofs defined
in configuration option
21:40:16.163 DEBUG org.apache.hadoop.fs.FileSystem: FS for ofs is class
org.apache.hadoop.fs.ozone.RootedOzoneFileSystem
21:40:16.171 DEBUG org.apache.hadoop.ipc.Client: getting client out of
cache: Client-3c4d5755c6544c8fa54cb7980bca9bf2
21:40:16.171 DEBUG org.apache.hadoop.ipc.Client: The ping interval is 60000
ms.
21:40:16.171 DEBUG org.apache.hadoop.ipc.Client: Connecting to /10.2.1.5:9862
21:40:16.181 DEBUG org.apache.hadoop.security.UserGroupInformation:
PrivilegedAction as:scm/scm@xxxxx (auth:KERBEROS)
from:org.apache.hadoop.ipc.Client$Connection.setupIOstreams(Client.java:818)
21:40:16.181 DEBUG org.apache.hadoop.security.SaslRpcClient: Sending sasl
message state: NEGOTIATE
21:40:16.181 DEBUG org.apache.hadoop.security.SaslRpcClient: Get token info
proto:interface org.apache.hadoop.ozone.om.protocolPB.OzoneManagerProtocolPB
info:@org.apache.hadoop.security.token.TokenInfo(value=class
org.apache.hadoop.ozone.security.OzoneDelegationTokenSelector)
21:40:16.181 DEBUG
org.apache.hadoop.ozone.security.OzoneDelegationTokenSelector: Got tokens: null
for service 10.2.1.5:9862
21:40:16.182 DEBUG org.apache.hadoop.security.SaslRpcClient: tokens aren't
supported for this protocol or user doesn't have one
21:40:16.182 DEBUG org.apache.hadoop.security.SaslRpcClient: Get kerberos
info proto:interface
org.apache.hadoop.ozone.om.protocolPB.OzoneManagerProtocolPB
info:@org.apache.hadoop.security.KerberosInfo(clientPrincipal=,
serverPrincipal=ozone.om.kerberos.principal)
21:40:16.184 DEBUG org.apache.hadoop.security.SaslRpcClient: RPC Server's
Kerberos principal name for
protocol=org.apache.hadoop.ozone.om.protocolPB.OzoneManagerProtocolPB is
om/om@xxxxx
21:40:16.184 DEBUG org.apache.hadoop.security.SaslRpcClient: Creating SASL
GSSAPI(KERBEROS) client to authenticate to service at om
21:40:16.185 DEBUG org.apache.hadoop.security.SaslRpcClient: Use KERBEROS
authentication for protocol OzoneManagerProtocolPB
....
21:40:16.191 DEBUG org.apache.hadoop.ipc.Client: IPC Client (1298557761)
connection to /10.2.1.5:9862 from meimei: starting, having connections 1
21:40:16.192 DEBUG org.apache.hadoop.ipc.Client: IPC Client (1298557761)
connection to /10.2.1.5:9862 from meimei sending #1
org.apache.hadoop.ozone.om.protocol.OzoneManagerProtocol.submitRequest
21:40:16.194 DEBUG org.apache.hadoop.ipc.Client: IPC Client (1298557761)
connection to /10.2.1.5:9862 from meimei got value #1
21:40:16.194 DEBUG org.apache.hadoop.ipc.ProtobufRpcEngine: Call:
submitRequest took 23ms
21:40:16.198 INFO
org.apache.kyuubi.credentials.HadoopFsDelegationTokenProvider: getting token
owned by meimei for: ofs://cluster1/
21:40:16.202 DEBUG org.apache.hadoop.ipc.Client: stopping client from cache:
Client-3c4d5755c6544c8fa54cb7980bca9bf2
21:40:16.203 INFO org.apache.kyuubi.credentials.HiveDelegationTokenProvider:
Getting Hive delegation token for meimei against hive/xx@xxxxx
21:40:16.205 DEBUG org.apache.thrift.transport.TSaslTransport: writing data
length: 97
21:40:16.207 DEBUG org.apache.thrift.transport.TSaslTransport: CLIENT:
reading data length: 164
21:40:17.857 DEBUG org.apache.kyuubi.server.KyuubiServer: OperationHandle
[type=UNKNOWN_OPERATION, identifier: 14f7175c-b1bc-4058-8c21-eb34b2cd8519]:
Long polling timed out, null
21:40:17.857 DEBUG org.apache.thrift.transport.TSaslTransport: writing data
length: 79
21:40:17.858 DEBUG org.apache.thrift.transport.TSaslTransport: SERVER:
reading data length: 117
```
HadoopCredentialsManager:
```
21:39:13.890 INFO hive.metastore: Connected to metastore.
21:39:13.948 INFO org.apache.kyuubi.credentials.HiveDelegationTokenProvider:
Created HiveMetaStoreClient with metastore uris thrift://10.2.1.3:9083
21:39:13.951 INFO org.apache.kyuubi.credentials.HadoopCredentialsManager:
Using the following builtin delegation token providers: hadoopfs, hive.
21:39:13.951 INFO org.apache.kyuubi.credentials.HadoopCredentialsManager:
Service[HadoopCredentialsManager] is initialized.
21:39:13.956 INFO org.apache.kyuubi.operation.KyuubiOperationManager:
Service[KyuubiOperationManager] is initialized.
21:39:13.957 INFO org.apache.kyuubi.session.KyuubiSessionManager:
Service[KyuubiSessionManager] is initialized.
21:39:13.957 INFO org.apache.kyuubi.server.KyuubiServer:
Service[KyuubiBackendService] is initialized.
21:39:13.975 INFO org.apache.kyuubi.server.KyuubiTBinaryFrontendService:
Initializing KyuubiTBinaryFrontend on xxxxx:10011 with [200, 999] worker threads
21:39:14.023 INFO org.apache.curator.framework.imps.CuratorFrameworkImpl:
Starting
21:39:14.024 DEBUG org.apache.curator.CuratorZookeeperClient: Starting
21:39:14.024 DEBUG org.apache.curator.ConnectionState: Starting
21:39:14.024 DEBUG org.apache.curator.ConnectionState: reset
...
21:39:14.047 INFO org.apache.kyuubi.operation.KyuubiOperationManager:
Service[KyuubiOperationManager] is started.
21:39:14.047 INFO org.apache.kyuubi.session.KyuubiSessionManager:
Service[KyuubiSessionManager] is started.
21:39:14.047 INFO org.apache.kyuubi.server.KyuubiServer:
Service[KyuubiBackendService] is started.
21:40:16.160 INFO org.apache.kyuubi.credentials.HadoopCredentialsManager:
Scheduling renewal in 0 ms.
21:40:16.160 INFO org.apache.kyuubi.credentials.HadoopCredentialsManager:
Created CredentialsRef for user meimei and scheduled a renewal task
21:40:16.162 DEBUG org.apache.hadoop.security.UserGroupInformation:
PrivilegedAction as:meimei (auth:PROXY) via scm/scm@xxx (auth:KERBEROS)
from:org.apache.kyuubi.credentials.HadoopFsDelegationTokenProvider$.doAsProxyUser(HadoopFsDelegationTokenProvider.scala:115)
21:40:16.163 DEBUG org.apache.hadoop.fs.FileSystem: Bypassing cache to
create filesystem ofs://cluster1/
21:40:16.163 DEBUG org.apache.hadoop.fs.FileSystem: Looking for FS
supporting ofs
21:40:16.163 DEBUG org.apache.hadoop.fs.FileSystem: looking for
configuration option fs.ofs.impl
21:40:16.163 DEBUG org.apache.hadoop.fs.FileSystem: Filesystem ofs defined
in configuration option
21:40:16.163 DEBUG org.apache.hadoop.fs.FileSystem: FS for ofs is class
org.apache.hadoop.fs.ozone.RootedOzoneFileSystem
21:40:16.171 DEBUG org.apache.hadoop.ipc.Client: getting client out of
cache: Client-3c4d5755c6544c8fa54cb7980bca9bf2
21:40:16.171 DEBUG org.apache.hadoop.ipc.Client: The ping interval is 60000
ms.
21:40:16.171 DEBUG org.apache.hadoop.ipc.Client: Connecting to /10.2.1.5:9862
...
1:41:12.902 DEBUG org.apache.kyuubi.server.KyuubiTBinaryFrontendService:
TGetOperationStatusReq(operationHandle:TOperationHandle(operationId:THandleIdentifier(guid:14
F7 17 5C B1 BC 40 58 8C 21 EB 34 B2 CD 85 19, secret:4B DE EA 3D 64 24 41 69
90 7D 25 46 42 F6 41 DF), operationType:UNKNOWN, hasResultSet:false))
21:41:13.111 DEBUG org.apache.thrift.transport.TSaslServerTransport:
transport map does not contain key
21:41:13.111 DEBUG org.apache.thrift.transport.TSaslTransport: opening
transport org.apache.thrift.transport.TSaslServerTransport@5300a8c4
21:41:13.112 DEBUG org.apache.thrift.transport.TSaslTransport: No data or no
sasl data in the stream
21:41:13.112 DEBUG org.apache.thrift.transport.TSaslServerTransport: failed
to open server transport
org.apache.thrift.transport.TSaslTransportException: No data or no sasl data
in the stream
at
org.apache.thrift.transport.TSaslTransport.open(TSaslTransport.java:328)
~[libthrift-0.9.3.jar:0.9.3]
at
org.apache.thrift.transport.TSaslServerTransport.open(TSaslServerTransport.java:41)
~[libthrift-0.9.3.jar:0.9.3]
at
org.apache.thrift.transport.TSaslServerTransport$Factory.getTransport(TSaslServerTransport.java:216)
~[libthrift-0.9.3.jar:0.9.3]
at
org.apache.thrift.server.TThreadPoolServer$WorkerProcess.run(TThreadPoolServer.java:269)
~[libthrift-0.9.3.jar:0.9.3]
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]
21:41:14.172 DEBUG org.apache.zookeeper.ClientCnxn: Got ping response for
sessionid: 0x20165086c3b0008 after 0ms
21:41:16.175 ERROR org.apache.kyuubi.operation.LaunchEngine: Failed to renew
engine credentials when launching engine
org.apache.kyuubi.KyuubiException: Exception thrown in awaitResult:
at
org.apache.kyuubi.util.ThreadUtils$.awaitResult(ThreadUtils.scala:64)
~[kyuubi-common_2.12-1.6.0-SNAPSHOT.jar:1.6.0-SNAPSHOT]
at
org.apache.kyuubi.credentials.CredentialsRef.$anonfun$waitUntilReady$1(CredentialsRef.scala:66)
~[kyuubi-server_2.12-1.6.0-SNAPSHOT.jar:1.6.0-SNAPSHOT]
at
org.apache.kyuubi.credentials.CredentialsRef.$anonfun$waitUntilReady$1$adapted(CredentialsRef.scala:66)
~[kyuubi-server_2.12-1.6.0-SNAPSHOT.jar:1.6.0-SNAPSHOT]
at scala.Option.foreach(Option.scala:407)
~[scala-library-2.12.15.jar:?]
at
org.apache.kyuubi.credentials.CredentialsRef.waitUntilReady(CredentialsRef.scala:66)
~[kyuubi-server_2.12-1.6.0-SNAPSHOT.jar:1.6.0-SNAPSHOT]
at
org.apache.kyuubi.credentials.HadoopCredentialsManager.getOrCreateUserCredentialsRef(HadoopCredentialsManager.scala:215)
~[kyuubi-server_2.12-1.6.0-SNAPSHOT.jar:1.6.0-SNAPSHOT]
at
org.apache.kyuubi.credentials.HadoopCredentialsManager.sendCredentialsIfNeeded(HadoopCredentialsManager.scala:170)
~[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.util.concurrent.TimeoutException: Futures timed out after
[60000 milliseconds]
at
scala.concurrent.impl.Promise$DefaultPromise.ready(Promise.scala:259)
~[scala-library-2.12.15.jar:?]
at
scala.concurrent.impl.Promise$DefaultPromise.result(Promise.scala:263)
~[scala-library-2.12.15.jar:?]
at
org.apache.kyuubi.util.ThreadUtils$.awaitResult(ThreadUtils.scala:61)
~[kyuubi-common_2.12-1.6.0-SNAPSHOT.jar:1.6.0-SNAPSHOT]
... 13 more
21:41:16.176 INFO org.apache.kyuubi.operation.LaunchEngine: Processing
meimei's query[14f7175c-b1bc-4058-8c21-eb34b2cd8519]: RUNNING_STATE ->
FINISHED_STATE, statement: LAUNCH_ENGINE, time taken: 78.428 seconds
21:41:16.177 DEBUG org.apache.thrift.transport.TSaslTransport: writing data
length: 79
21:41:16.178 DEBUG org.apache.thrift.transport.TSaslTransport: SERVER:
reading data length: 117
21:41:16.178 DEBUG org.apache.kyuubi.server.KyuubiTBinaryFrontendService:
TFetchResultsReq(operationHandle:TOperationHandle(operationId:THandleIdentifier(guid:14
F7 17 5C B1 BC 40 58 8C 21 EB 34 B2 CD 85 19, secret:4B DE EA 3D 64 24 41 69
90 7D 25 46 42 F6 41 DF), operationType:UNKNOWN, hasResultSet:false),
orientation:FETCH_NEXT, maxRows:1000, fetchType:1)
```
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: [email protected]
For queries about this service, please contact Infrastructure at:
[email protected]
---------------------------------------------------------------------
To unsubscribe, e-mail: [email protected]
For additional commands, e-mail: [email protected]
