[HIVE-23425] HS2 disconnect should not affect DDL operation status

• Type: Bug
• Status: Open
• Priority: Minor
• Resolution: Unresolved
• Component/s: HiveServer2
• Assignee: Sam An
• Reporter: Sam An
• Created: 08/May/20 21:24
• Updated: 08/May/20 21:32

Description

I observe in a cluster that HS2 connection to HMS was timed out. 

// code placeholder

2020-05-07 19:28:46,718 WARN org.apache.hadoop.hive.metastore.RetryingMetaStoreClient: [HiveServer2-Background-Pool: Thread-21790]: MetaStoreClient lost connection. Attempting to reconnect (1 of 1) after 1s. dropTable org.apache.thrift.transport.TTransportException: java.net.SocketTimeoutException: Read timed out at org.apache.thrift.transport.TIOStreamTransport.read(TIOStreamTransport.java:129) ~[hive-exec-3.1.3000.7.1.0.0-714.jar:3.1.3000.7.1.0.0-714] at org.apache.thrift.transport.TTransport.readAll(TTransport.java:86) ~[hive-exec-3.1.3000.7.1.0.0-714.jar:3.1.3000.7.1.0.0-714] at org.apache.thrift.transport.TSaslTransport.readLength(TSaslTransport.java:374) ~[hive-exec-3.1.3000.7.1.0.0-714.jar:3.1.3000.7.1.0.0-714] at org.apache.thrift.transport.TSaslTransport.readFrame(TSaslTransport.java:451) ~[hive-exec-3.1.3000.7.1.0.0-714.jar:3.1.3000.7.1.0.0-714] at org.apache.thrift.transport.TSaslTransport.read(TSaslTransport.java:433) ~[hive-exec-3.1.3000.7.1.0.0-714.jar:3.1.3000.7.1.0.0-714] at org.apache.thrift.transport.TSaslClientTransport.read(TSaslClientTransport.java:37) ~[hive-exec-3.1.3000.7.1.0.0-714.jar:3.1.3000.7.1.0.0-714]

2020-05-07 19:28:47,718 INFO org.apache.hadoop.hive.metastore.RetryingMetaStoreClient: [HiveServer2-Background-Pool: Thread-21790]: RetryingMetaStoreClient trying reconnect as hive/[e-mail] (auth:KERBEROS)
2020-05-07 19:28:47,719 INFO org.apache.hadoop.hive.metastore.HiveMetaStoreClient: [HiveServer2-Background-Pool: Thread-21790]: Closed a connection to metastore, current connections: 29
2020-05-07 19:28:47,719 INFO org.apache.hadoop.hive.metastore.HiveMetaStoreClient: [HiveServer2-Background-Pool: Thread-21790]: Trying to connect to metastore with URI thrift://ascend-px-master4.ascend-p.a8du-8mgv.cloudera.site:9083
2020-05-07 19:28:47,719 INFO org.apache.hadoop.hive.metastore.HiveMetaStoreClient: [HiveServer2-Background-Pool: Thread-21790]: HMSC::open(): Could not find delegation token. Creating KERBEROS-based thrift connection.
2020-05-07 19:28:47,724 INFO org.apache.hadoop.hive.metastore.HiveMetaStoreClient: [HiveServer2-Background-Pool: Thread-21790]: Opened a connection to metastore, current connections: 30
2020-05-07 19:28:47,725 INFO org.apache.hadoop.hive.metastore.HiveMetaStoreClient: [HiveServer2-Background-Pool: Thread-21790]: Connected to metastore.
2020-05-07 19:28:47,730 INFO org.apache.hadoop.hive.ql.hooks.HiveProtoLoggingHook: [HiveServer2-Background-Pool: Thread-21790]: Received post-hook notification for: hive_20200507192346_a1a0bad2-ca4f-4cd0-a0e7-22415c7050f0
2020-05-07 19:28:47,731 INFO org.apache.hive.service.cli.operation.OperationManager: [d900945d-9eb5-4b63-8ce9-c1166bc2474a HiveServer2-HttpHandler-Pool: Thread-19285]: Adding operation: OperationHandle [opType=EXECUTE_STATEMENT, getHandleIdentifier()=db40b2c8-d291-4f34-9809-24b6300ee45c]
2020-05-07 19:28:47,731 INFO org.apache.hadoop.hive.common.LogUtils: [d900945d-9eb5-4b63-8ce9-c1166bc2474a HiveServer2-HttpHandler-Pool: Thread-19285]: Thread context registration is done.
2020-05-07 19:28:47,731 INFO org.apache.hive.service.cli.operation.Operation: [d900945d-9eb5-4b63-8ce9-c1166bc2474a HiveServer2-HttpHandler-Pool: Thread-19285]: [opType=EXECUTE_STATEMENT, queryId=hive_20200507192847_08dbb746-b38f-405c-a92c-f6d2dd02b6f8, startTime=1588879727730, sessionId=d900945d-9eb5-4b63-8ce9-c1166bc2474a, createTime=1588879461427, userName=hive, ipAddress=10.28.140.56]
2020-05-07 19:28:47,732 INFO org.apache.hadoop.hive.ql.Driver: [d900945d-9eb5-4b63-8ce9-c1166bc2474a HiveServer2-HttpHandler-Pool: Thread-19285]: Compiling command(queryId=hive_20200507192847_08dbb746-b38f-405c-a92c-f6d2dd02b6f8): repl dump `*` from 1501982 with ('hive.repl.dump.metadata.only'='true', 'hive.repl.dump.include.acid.tables'='true')
2020-05-07 19:28:47,732 INFO org.apache.hadoop.hive.ql.Driver: [HiveServer2-Background-Pool: Thread-21790]: Completed executing command(queryId=hive_20200507192346_a1a0bad2-ca4f-4cd0-a0e7-22415c7050f0); Time taken: 301.177 seconds
2020-05-07 19:28:47,732 INFO org.apache.hadoop.hive.ql.Driver: [HiveServer2-Background-Pool: Thread-21790]: OK
2020-05-07 19:28:47,732 INFO org.apache.hadoop.hive.ql.lockmgr.DbTxnManager: [HiveServer2-Background-Pool: Thread-21790]: Stopped heartbeat for query: hive_20200507192346_a1a0bad2-ca4f-4cd0-a0e7-22415c7050f0
2020-05-07 19:28:47,738 INFO org.apache.hadoop.hive.common.LogUtils: [HiveServer2-Background-Pool: Thread-21790]: Unregistered logging context.

However, on HMS, the drop table operation has not been completed till 5 minutes later.