[
https://issues.apache.org/jira/browse/HIVE-20209?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16561954#comment-16561954
]
Hive QA commented on HIVE-20209:
--------------------------------
Here are the results of testing the latest attachment:
https://issues.apache.org/jira/secure/attachment/12933581/HIVE-20209.01-branch-3.patch
{color:green}SUCCESS:{color} +1 due to 1 test(s) being added or modified.
{color:red}ERROR:{color} -1 due to 100 failed/errored test(s), 14412 tests
executed
*Failed tests:*
{noformat}
TestAddPartitions - did not produce a TEST-*.xml file (likely timed out)
(batchId=226)
TestAddPartitionsFromPartSpec - did not produce a TEST-*.xml file (likely timed
out) (batchId=228)
TestAdminUser - did not produce a TEST-*.xml file (likely timed out)
(batchId=234)
TestAggregateStatsCache - did not produce a TEST-*.xml file (likely timed out)
(batchId=228)
TestAlterPartitions - did not produce a TEST-*.xml file (likely timed out)
(batchId=228)
TestAppendPartitions - did not produce a TEST-*.xml file (likely timed out)
(batchId=228)
TestBeeLineDriver - did not produce a TEST-*.xml file (likely timed out)
(batchId=271)
TestCachedStore - did not produce a TEST-*.xml file (likely timed out)
(batchId=234)
TestCatalogCaching - did not produce a TEST-*.xml file (likely timed out)
(batchId=234)
TestCatalogNonDefaultClient - did not produce a TEST-*.xml file (likely timed
out) (batchId=226)
TestCatalogNonDefaultSvr - did not produce a TEST-*.xml file (likely timed out)
(batchId=234)
TestCatalogOldClient - did not produce a TEST-*.xml file (likely timed out)
(batchId=226)
TestCatalogs - did not produce a TEST-*.xml file (likely timed out)
(batchId=228)
TestCheckConstraint - did not produce a TEST-*.xml file (likely timed out)
(batchId=226)
TestDataSourceProviderFactory - did not produce a TEST-*.xml file (likely timed
out) (batchId=236)
TestDatabases - did not produce a TEST-*.xml file (likely timed out)
(batchId=228)
TestDeadline - did not produce a TEST-*.xml file (likely timed out)
(batchId=234)
TestDefaultConstraint - did not produce a TEST-*.xml file (likely timed out)
(batchId=228)
TestDropPartitions - did not produce a TEST-*.xml file (likely timed out)
(batchId=226)
TestDummy - did not produce a TEST-*.xml file (likely timed out) (batchId=271)
TestEmbeddedHiveMetaStore - did not produce a TEST-*.xml file (likely timed
out) (batchId=229)
TestExchangePartitions - did not produce a TEST-*.xml file (likely timed out)
(batchId=228)
TestFMSketchSerialization - did not produce a TEST-*.xml file (likely timed
out) (batchId=236)
TestFilterHooks - did not produce a TEST-*.xml file (likely timed out)
(batchId=226)
TestForeignKey - did not produce a TEST-*.xml file (likely timed out)
(batchId=228)
TestFunctions - did not produce a TEST-*.xml file (likely timed out)
(batchId=226)
TestGetPartitions - did not produce a TEST-*.xml file (likely timed out)
(batchId=226)
TestGetTableMeta - did not produce a TEST-*.xml file (likely timed out)
(batchId=226)
TestHLLNoBias - did not produce a TEST-*.xml file (likely timed out)
(batchId=236)
TestHLLSerialization - did not produce a TEST-*.xml file (likely timed out)
(batchId=236)
TestHdfsUtils - did not produce a TEST-*.xml file (likely timed out)
(batchId=234)
TestHiveAlterHandler - did not produce a TEST-*.xml file (likely timed out)
(batchId=226)
TestHiveMetaStoreGetMetaConf - did not produce a TEST-*.xml file (likely timed
out) (batchId=234)
TestHiveMetaStorePartitionSpecs - did not produce a TEST-*.xml file (likely
timed out) (batchId=228)
TestHiveMetaStoreSchemaMethods - did not produce a TEST-*.xml file (likely
timed out) (batchId=234)
TestHiveMetaStoreTimeout - did not produce a TEST-*.xml file (likely timed out)
(batchId=236)
TestHiveMetaStoreTxns - did not produce a TEST-*.xml file (likely timed out)
(batchId=236)
TestHiveMetaStoreWithEnvironmentContext - did not produce a TEST-*.xml file
(likely timed out) (batchId=231)
TestHiveMetastoreCli - did not produce a TEST-*.xml file (likely timed out)
(batchId=226)
TestHyperLogLog - did not produce a TEST-*.xml file (likely timed out)
(batchId=236)
TestHyperLogLogDense - did not produce a TEST-*.xml file (likely timed out)
(batchId=236)
TestHyperLogLogMerge - did not produce a TEST-*.xml file (likely timed out)
(batchId=236)
TestHyperLogLogSparse - did not produce a TEST-*.xml file (likely timed out)
(batchId=236)
TestJSONMessageDeserializer - did not produce a TEST-*.xml file (likely timed
out) (batchId=234)
TestListPartitions - did not produce a TEST-*.xml file (likely timed out)
(batchId=226)
TestLockRequestBuilder - did not produce a TEST-*.xml file (likely timed out)
(batchId=226)
TestMarkPartition - did not produce a TEST-*.xml file (likely timed out)
(batchId=234)
TestMarkPartitionRemote - did not produce a TEST-*.xml file (likely timed out)
(batchId=236)
TestMetaStoreConnectionUrlHook - did not produce a TEST-*.xml file (likely
timed out) (batchId=228)
TestMetaStoreEndFunctionListener - did not produce a TEST-*.xml file (likely
timed out) (batchId=228)
TestMetaStoreEventListener - did not produce a TEST-*.xml file (likely timed
out) (batchId=232)
TestMetaStoreEventListenerOnlyOnCommit - did not produce a TEST-*.xml file
(likely timed out) (batchId=234)
TestMetaStoreEventListenerWithOldConf - did not produce a TEST-*.xml file
(likely timed out) (batchId=236)
TestMetaStoreInitListener - did not produce a TEST-*.xml file (likely timed
out) (batchId=234)
TestMetaStoreListenersError - did not produce a TEST-*.xml file (likely timed
out) (batchId=234)
TestMetaStoreSchemaFactory - did not produce a TEST-*.xml file (likely timed
out) (batchId=234)
TestMetaStoreSchemaInfo - did not produce a TEST-*.xml file (likely timed out)
(batchId=234)
TestMetaStoreUtils - did not produce a TEST-*.xml file (likely timed out)
(batchId=234)
TestMetastoreConf - did not produce a TEST-*.xml file (likely timed out)
(batchId=228)
TestMetastoreSchemaTool - did not produce a TEST-*.xml file (likely timed out)
(batchId=234)
TestMetrics - did not produce a TEST-*.xml file (likely timed out) (batchId=228)
TestMiniDruidCliDriver - did not produce a TEST-*.xml file (likely timed out)
(batchId=271)
TestMiniDruidKafkaCliDriver - did not produce a TEST-*.xml file (likely timed
out) (batchId=271)
TestNotNullConstraint - did not produce a TEST-*.xml file (likely timed out)
(batchId=228)
TestObjectStore - did not produce a TEST-*.xml file (likely timed out)
(batchId=236)
TestObjectStoreInitRetry - did not produce a TEST-*.xml file (likely timed out)
(batchId=234)
TestObjectStoreSchemaMethods - did not produce a TEST-*.xml file (likely timed
out) (batchId=236)
TestOldSchema - did not produce a TEST-*.xml file (likely timed out)
(batchId=234)
TestPartitionNameWhitelistValidation - did not produce a TEST-*.xml file
(likely timed out) (batchId=228)
TestPrimaryKey - did not produce a TEST-*.xml file (likely timed out)
(batchId=228)
TestRawStoreProxy - did not produce a TEST-*.xml file (likely timed out)
(batchId=226)
TestRemoteHiveMetaStore - did not produce a TEST-*.xml file (likely timed out)
(batchId=230)
TestRemoteHiveMetaStoreIpAddress - did not produce a TEST-*.xml file (likely
timed out) (batchId=224)
TestRemoteUGIHiveMetaStoreIpAddress - did not produce a TEST-*.xml file (likely
timed out) (batchId=233)
TestRetriesInRetryingHMSHandler - did not produce a TEST-*.xml file (likely
timed out) (batchId=236)
TestRetryingHMSHandler - did not produce a TEST-*.xml file (likely timed out)
(batchId=234)
TestRuntimeStats - did not produce a TEST-*.xml file (likely timed out)
(batchId=226)
TestSchemaToolForMetastore - did not produce a TEST-*.xml file (likely timed
out) (batchId=228)
TestSetUGIOnBothClientServer - did not produce a TEST-*.xml file (likely timed
out) (batchId=227)
TestSetUGIOnOnlyClient - did not produce a TEST-*.xml file (likely timed out)
(batchId=225)
TestSetUGIOnOnlyServer - did not produce a TEST-*.xml file (likely timed out)
(batchId=235)
TestSparseEncodeHash - did not produce a TEST-*.xml file (likely timed out)
(batchId=236)
TestStats - did not produce a TEST-*.xml file (likely timed out) (batchId=228)
TestStatsSetupConst - did not produce a TEST-*.xml file (likely timed out)
(batchId=236)
TestTableIterable - did not produce a TEST-*.xml file (likely timed out)
(batchId=236)
TestTablesCreateDropAlterTruncate - did not produce a TEST-*.xml file (likely
timed out) (batchId=226)
TestTablesGetExists - did not produce a TEST-*.xml file (likely timed out)
(batchId=228)
TestTablesList - did not produce a TEST-*.xml file (likely timed out)
(batchId=226)
TestTezPerfCliDriver - did not produce a TEST-*.xml file (likely timed out)
(batchId=271)
TestTxnHandlerNegative - did not produce a TEST-*.xml file (likely timed out)
(batchId=226)
TestTxnUtils - did not produce a TEST-*.xml file (likely timed out)
(batchId=226)
TestUniqueConstraint - did not produce a TEST-*.xml file (likely timed out)
(batchId=226)
org.apache.hadoop.hive.cli.TestCliDriver.testCliDriver[mm_all] (batchId=70)
org.apache.hadoop.hive.cli.TestMiniLlapCliDriver.testCliDriver[mm_all]
(batchId=153)
org.apache.hadoop.hive.cli.TestMiniLlapLocalCliDriver.testCliDriver[results_cache_with_masking]
(batchId=174)
org.apache.hadoop.hive.cli.TestMiniSparkOnYarnCliDriver.testCliDriver[constprog_semijoin]
(batchId=187)
org.apache.hadoop.hive.metastore.client.TestRuntimeStats.testCleanup[Embedded]
(batchId=213)
org.apache.hadoop.hive.ql.TestWarehouseExternalDir.testManagedPaths
(batchId=248)
org.apache.hive.service.TestHS2ImpersonationWithRemoteMS.testImpersonation
(batchId=256)
org.apache.hive.spark.client.rpc.TestRpc.testServerPort (batchId=323)
{noformat}
Test results:
https://builds.apache.org/job/PreCommit-HIVE-Build/12943/testReport
Console output: https://builds.apache.org/job/PreCommit-HIVE-Build/12943/console
Test logs: http://104.198.109.242/logs/PreCommit-HIVE-Build-12943/
Messages:
{noformat}
Executing org.apache.hive.ptest.execution.TestCheckPhase
Executing org.apache.hive.ptest.execution.PrepPhase
Executing org.apache.hive.ptest.execution.YetusPhase
Executing org.apache.hive.ptest.execution.ExecutionPhase
Executing org.apache.hive.ptest.execution.ReportingPhase
Tests exited with: TestsFailedException: 100 tests failed
{noformat}
This message is automatically generated.
ATTACHMENT ID: 12933581 - PreCommit-HIVE-Build
> Metastore connection fails for first attempt in repl dump.
> ----------------------------------------------------------
>
> Key: HIVE-20209
> URL: https://issues.apache.org/jira/browse/HIVE-20209
> Project: Hive
> Issue Type: Bug
> Components: HiveServer2, repl
> Affects Versions: 3.0.0, 3.1.0, 4.0.0
> Reporter: Sankar Hariappan
> Assignee: Sankar Hariappan
> Priority: Major
> Labels: DR, pull-request-available, replication
> Fix For: 4.0.0
>
> Attachments: HIVE-20209.01-branch-3.patch, HIVE-20209.01.patch
>
>
> Run the following command:
> {code:java}
> repl dump `*` from 60758 with ('hive.repl.dump.metadata.only'='true',
> 'hive.repl.dump.include.acid.tables'='true');
> {code}
> See this in hs2.log:
> {code:java}
> 2018-07-10T18:07:32,308 INFO [HiveServer2-Handler-Pool: Thread-14380]:
> conf.HiveConf (HiveConf.java:getLogIdVar(5061)) - Using the default value
> passed in for log id: f1e13736-3f10-4abf-a29b-683b534dfa4c
> 2018-07-10T18:07:32,309 INFO [HiveServer2-Handler-Pool: Thread-14380]:
> session.SessionState (:()) - Updating thread name to
> f1e13736-3f10-4abf-a29b-683b534dfa4c HiveServer2-Handler-Pool: Thread-14380
> 2018-07-10T18:07:32,311 INFO [f1e13736-3f10-4abf-a29b-683b534dfa4c
> HiveServer2-Handler-Pool: Thread-14380]: operation.OperationManager (:()) -
> Adding operation: OperationHandle [opType=EXECUTE_STATEMENT,
> getHandleIdentifier()=16eb1d07-e125-490c-8ab8-90192bfd459b]
> 2018-07-10T18:07:32,314 INFO [f1e13736-3f10-4abf-a29b-683b534dfa4c
> HiveServer2-Handler-Pool: Thread-14380]: ql.Driver (:()) - Compiling
> command(queryId=hive_20180710180732_7dcc20db-90db-486d-a825-e6fa91dc092b):
> repl dump `*` from 60758 with ('hive.repl.dump.metadata.only'='true',
> 'hive.repl.dump.include.acid.tables'='true')
> 2018-07-10T18:07:32,317 INFO [f1e13736-3f10-4abf-a29b-683b534dfa4c
> HiveServer2-Handler-Pool: Thread-14380]: metastore.HiveMetaStoreClient (:())
> - Trying to connect to metastore with URI
> thrift://hwx-demo-2.field.hortonworks.com:9083
> 2018-07-10T18:07:32,317 INFO [f1e13736-3f10-4abf-a29b-683b534dfa4c
> HiveServer2-Handler-Pool: Thread-14380]: metastore.HiveMetaStoreClient (:())
> - Opened a connection to metastore, current connections: 19
> 2018-07-10T18:07:32,319 INFO [f1e13736-3f10-4abf-a29b-683b534dfa4c
> HiveServer2-Handler-Pool: Thread-14380]: metastore.HiveMetaStoreClient (:())
> - Connected to metastore.
> 2018-07-10T18:07:32,319 INFO [f1e13736-3f10-4abf-a29b-683b534dfa4c
> HiveServer2-Handler-Pool: Thread-14380]: metastore.RetryingMetaStoreClient
> (:()) - RetryingMetaStoreClient proxy=class
> org.apache.hadoop.hive.ql.metadata.SessionHiveMetaStoreClient ugi=hive
> (auth:SIMPLE) retries=24 delay=5 lifetime=0
> 2018-07-10T18:07:32,439 INFO [f1e13736-3f10-4abf-a29b-683b534dfa4c
> HiveServer2-Handler-Pool: Thread-14380]: ql.Driver (:()) - Semantic Analysis
> Completed (retrial = false)
> 2018-07-10T18:07:32,440 INFO [f1e13736-3f10-4abf-a29b-683b534dfa4c
> HiveServer2-Handler-Pool: Thread-14380]: ql.Driver (:()) - Returning Hive
> schema: Schema(fieldSchemas:[FieldSchema(name:dump_dir, type:string,
> comment:from deserializer), FieldSchema(name:last_repl_id, type:string,
> comment:from deserializer)], properties:null)
> 2018-07-10T18:07:32,443 INFO [f1e13736-3f10-4abf-a29b-683b534dfa4c
> HiveServer2-Handler-Pool: Thread-14380]: exec.ListSinkOperator (:()) -
> Initializing operator LIST_SINK[0]
> 2018-07-10T18:07:32,446 INFO [f1e13736-3f10-4abf-a29b-683b534dfa4c
> HiveServer2-Handler-Pool: Thread-14380]: ql.Driver (:()) - Completed
> compiling
> command(queryId=hive_20180710180732_7dcc20db-90db-486d-a825-e6fa91dc092b);
> Time taken: 0.132 seconds
> 2018-07-10T18:07:32,447 INFO [f1e13736-3f10-4abf-a29b-683b534dfa4c
> HiveServer2-Handler-Pool: Thread-14380]: conf.HiveConf
> (HiveConf.java:getLogIdVar(5061)) - Using the default value passed in for log
> id: f1e13736-3f10-4abf-a29b-683b534dfa4c
> 2018-07-10T18:07:32,448 INFO [f1e13736-3f10-4abf-a29b-683b534dfa4c
> HiveServer2-Handler-Pool: Thread-14380]: session.SessionState (:()) -
> Resetting thread name to HiveServer2-Handler-Pool: Thread-14380
> 2018-07-10T18:07:32,451 INFO [HiveServer2-Background-Pool: Thread-15161]:
> reexec.ReExecDriver (:()) - Execution #1 of query
> 2018-07-10T18:07:32,452 INFO [HiveServer2-Background-Pool: Thread-15161]:
> lockmgr.DbTxnManager (:()) - Setting lock request transaction to txnid:30327
> for queryId=hive_20180710180732_7dcc20db-90db-486d-a825-e6fa91dc092b
> 2018-07-10T18:07:32,454 INFO [HiveServer2-Background-Pool: Thread-15161]:
> lockmgr.DbLockManager (:()) - Requesting:
> queryId=hive_20180710180732_7dcc20db-90db-486d-a825-e6fa91dc092b
> LockRequest(component:[LockComponent(type:SHARED_READ, level:DB,
> dbname:default, operationType:SELECT), LockComponent(type:SHARED_READ,
> level:DB, dbname:hwxdemo, operationType:SELECT),
> LockComponent(type:SHARED_READ, level:DB, dbname:information_schema,
> operationType:SELECT), LockComponent(type:SHARED_READ, level:DB, dbname:sys,
> operationType:SELECT)], txnid:30327, user:hive,
> hostname:hwx-demo-2.field.hortonworks.com,
> agentInfo:hive_20180710180732_7dcc20db-90db-486d-a825-e6fa91dc092b)
> 2018-07-10T18:07:32,497 INFO [HiveServer2-Background-Pool: Thread-15161]:
> lockmgr.DbLockManager (:()) - Response to
> queryId=hive_20180710180732_7dcc20db-90db-486d-a825-e6fa91dc092b
> LockResponse(lockid:30305, state:ACQUIRED)
> 2018-07-10T18:07:32,501 INFO [HiveServer2-Background-Pool: Thread-15161]:
> ql.Driver (:()) - Executing
> command(queryId=hive_20180710180732_7dcc20db-90db-486d-a825-e6fa91dc092b):
> repl dump `*` from 60758 with ('hive.repl.dump.metadata.only'='true',
> 'hive.repl.dump.include.acid.tables'='true')
> 2018-07-10T18:07:32,503 INFO [HiveServer2-Background-Pool: Thread-15161]:
> ql.Driver (:()) - Starting task [Stage-0:REPL_DUMP] in serial mode
> 2018-07-10T18:07:32,506 INFO [HiveServer2-Background-Pool: Thread-15161]:
> metastore.HiveMetaStoreClient (:()) - Closed a connection to metastore,
> current connections: 18
> 2018-07-10T18:07:32,509 INFO [HiveServer2-Background-Pool: Thread-15161]:
> metastore.HiveMetaStoreClient (:()) - Trying to connect to metastore with URI
> thrift://hwx-demo-2.field.hortonworks.com:9083
> 2018-07-10T18:07:32,509 INFO [HiveServer2-Background-Pool: Thread-15161]:
> metastore.HiveMetaStoreClient (:()) - Opened a connection to metastore,
> current connections: 19
> 2018-07-10T18:07:32,510 INFO [HiveServer2-Background-Pool: Thread-15161]:
> metastore.HiveMetaStoreClient (:()) - Connected to metastore.
> 2018-07-10T18:07:32,510 INFO [HiveServer2-Background-Pool: Thread-15161]:
> metastore.RetryingMetaStoreClient (:()) - RetryingMetaStoreClient proxy=class
> org.apache.hadoop.hive.ql.metadata.SessionHiveMetaStoreClient ugi=hive
> (auth:SIMPLE) retries=24 delay=5 lifetime=0
> 2018-07-10T18:07:32,536 INFO [HiveServer2-Background-Pool: Thread-15161]:
> metastore.HiveMetaStoreClient (:()) - Closed a connection to metastore,
> current connections: 18
> 2018-07-10T18:07:32,538 INFO [HiveServer2-Background-Pool: Thread-15161]:
> metastore.HiveMetaStoreClient (:()) - Trying to connect to metastore with URI
> thrift://hwx-demo-2.field.hortonworks.com:9083
> 2018-07-10T18:07:32,539 INFO [HiveServer2-Background-Pool: Thread-15161]:
> metastore.HiveMetaStoreClient (:()) - Opened a connection to metastore,
> current connections: 19
> 2018-07-10T18:07:32,542 INFO [HiveServer2-Background-Pool: Thread-15161]:
> metastore.HiveMetaStoreClient (:()) - Connected to metastore.
> 2018-07-10T18:07:32,542 INFO [HiveServer2-Background-Pool: Thread-15161]:
> metastore.RetryingMetaStoreClient (:()) - RetryingMetaStoreClient proxy=class
> org.apache.hadoop.hive.ql.metadata.SessionHiveMetaStoreClient ugi=hive
> (auth:SIMPLE) retries=24 delay=5 lifetime=0
> 2018-07-10T18:07:32,565 INFO [HiveServer2-Background-Pool: Thread-15161]:
> ReplState (:()) - REPL::START:
> \{"dbName":"*","dumpType":"INCREMENTAL","estimatedNumEvents":0,"dumpStartTime":1531246052}
> 2018-07-10T18:07:32,577 INFO [HiveServer2-Background-Pool: Thread-15161]:
> metastore.HiveMetaStoreClient (:()) - Closed a connection to metastore,
> current connections: 18
> 2018-07-10T18:07:32,578 INFO [HiveServer2-Background-Pool: Thread-15161]:
> events.AbstractEventHandler (:()) - Processing#60759 COMMIT_TXN message :
> \{"txnid":30321,"timestamp":1531246017,"server":"thrift://hwx-demo-2.field.hortonworks.com:9083","servicePrincipal":"hive/[email protected]"}
> 2018-07-10T18:07:32,603 INFO [HiveServer2-Background-Pool: Thread-15161]:
> ReplState (:()) - REPL::EVENT_DUMP:
> \{"dbName":"*","eventId":"60759","eventType":"EVENT_COMMIT_TXN","eventsDumpProgress":"1/0","dumpTime":1531246052}
> 2018-07-10T18:07:32,604 INFO [HiveServer2-Background-Pool: Thread-15161]:
> events.AbstractEventHandler (:()) - Processing#60760 COMMIT_TXN message :
> \{"txnid":30322,"timestamp":1531246021,"server":"thrift://hwx-demo-2.field.hortonworks.com:9083","servicePrincipal":"hive/[email protected]"}
> 2018-07-10T18:07:32,628 INFO [HiveServer2-Background-Pool: Thread-15161]:
> ReplState (:()) - REPL::EVENT_DUMP:
> \{"dbName":"*","eventId":"60760","eventType":"EVENT_COMMIT_TXN","eventsDumpProgress":"2/0","dumpTime":1531246052}
> 2018-07-10T18:07:32,629 INFO [HiveServer2-Background-Pool: Thread-15161]:
> events.AbstractEventHandler (:()) - Processing#60761 OPEN_TXN message :
> \{"txnIds":null,"timestamp":1531246022,"fromTxnId":30323,"toTxnId":30323,"server":"thrift://hwx-demo-2.field.hortonworks.com:9083","servicePrincipal":"hive/[email protected]"}
> 2018-07-10T18:07:32,653 INFO [HiveServer2-Background-Pool: Thread-15161]:
> ReplState (:()) - REPL::EVENT_DUMP:
> \{"dbName":"*","eventId":"60761","eventType":"EVENT_OPEN_TXN","eventsDumpProgress":"3/0","dumpTime":1531246052}
> 2018-07-10T18:07:32,654 INFO [HiveServer2-Background-Pool: Thread-15161]:
> events.AbstractEventHandler (:()) - Processing#60762 COMMIT_TXN message :
> \{"txnid":30323,"timestamp":1531246028,"server":"thrift://hwx-demo-2.field.hortonworks.com:9083","servicePrincipal":"hive/[email protected]"}
> 2018-07-10T18:07:32,679 INFO [HiveServer2-Background-Pool: Thread-15161]:
> ReplState (:()) - REPL::EVENT_DUMP:
> \{"dbName":"*","eventId":"60762","eventType":"EVENT_COMMIT_TXN","eventsDumpProgress":"4/0","dumpTime":1531246052}
> 2018-07-10T18:07:32,680 INFO [HiveServer2-Background-Pool: Thread-15161]:
> events.AbstractEventHandler (:()) - Processing#60763 OPEN_TXN message :
> \{"txnIds":null,"timestamp":1531246033,"fromTxnId":30324,"toTxnId":30324,"server":"thrift://hwx-demo-2.field.hortonworks.com:9083","servicePrincipal":"hive/[email protected]"}
> 2018-07-10T18:07:32,702 INFO [HiveServer2-Background-Pool: Thread-15161]:
> ReplState (:()) - REPL::EVENT_DUMP:
> \{"dbName":"*","eventId":"60763","eventType":"EVENT_OPEN_TXN","eventsDumpProgress":"5/0","dumpTime":1531246052}
> 2018-07-10T18:07:32,702 INFO [HiveServer2-Background-Pool: Thread-15161]:
> events.AbstractEventHandler (:()) - Processing#60764 OPEN_TXN message :
> \{"txnIds":null,"timestamp":1531246038,"fromTxnId":30325,"toTxnId":30325,"server":"thrift://hwx-demo-2.field.hortonworks.com:9083","servicePrincipal":"hive/[email protected]"}
> 2018-07-10T18:07:32,724 INFO [HiveServer2-Background-Pool: Thread-15161]:
> ReplState (:()) - REPL::EVENT_DUMP:
> \{"dbName":"*","eventId":"60764","eventType":"EVENT_OPEN_TXN","eventsDumpProgress":"6/0","dumpTime":1531246052}
> 2018-07-10T18:07:32,725 INFO [HiveServer2-Background-Pool: Thread-15161]:
> events.AbstractEventHandler (:()) - Processing#60765 COMMIT_TXN message :
> \{"txnid":30324,"timestamp":1531246038,"server":"thrift://hwx-demo-2.field.hortonworks.com:9083","servicePrincipal":"hive/[email protected]"}
> 2018-07-10T18:07:32,747 INFO [HiveServer2-Background-Pool: Thread-15161]:
> ReplState (:()) - REPL::EVENT_DUMP:
> \{"dbName":"*","eventId":"60765","eventType":"EVENT_COMMIT_TXN","eventsDumpProgress":"7/0","dumpTime":1531246052}
> 2018-07-10T18:07:32,748 INFO [HiveServer2-Background-Pool: Thread-15161]:
> events.AbstractEventHandler (:()) - Processing#60766 COMMIT_TXN message :
> \{"txnid":30325,"timestamp":1531246043,"server":"thrift://hwx-demo-2.field.hortonworks.com:9083","servicePrincipal":"hive/[email protected]"}
> 2018-07-10T18:07:32,768 INFO [HiveServer2-Background-Pool: Thread-15161]:
> ReplState (:()) - REPL::EVENT_DUMP:
> \{"dbName":"*","eventId":"60766","eventType":"EVENT_COMMIT_TXN","eventsDumpProgress":"8/0","dumpTime":1531246052}
> 2018-07-10T18:07:32,769 INFO [HiveServer2-Background-Pool: Thread-15161]:
> events.AbstractEventHandler (:()) - Processing#60767 OPEN_TXN message :
> \{"txnIds":null,"timestamp":1531246043,"fromTxnId":30326,"toTxnId":30326,"server":"thrift://hwx-demo-2.field.hortonworks.com:9083","servicePrincipal":"hive/[email protected]"}
> 2018-07-10T18:07:32,791 INFO [HiveServer2-Background-Pool: Thread-15161]:
> ReplState (:()) - REPL::EVENT_DUMP:
> \{"dbName":"*","eventId":"60767","eventType":"EVENT_OPEN_TXN","eventsDumpProgress":"9/0","dumpTime":1531246052}
> 2018-07-10T18:07:32,791 INFO [HiveServer2-Background-Pool: Thread-15161]:
> events.AbstractEventHandler (:()) - Processing#60768 COMMIT_TXN message :
> \{"txnid":30326,"timestamp":1531246049,"server":"thrift://hwx-demo-2.field.hortonworks.com:9083","servicePrincipal":"hive/[email protected]"}
> 2018-07-10T18:07:32,816 INFO [HiveServer2-Background-Pool: Thread-15161]:
> ReplState (:()) - REPL::EVENT_DUMP:
> \{"dbName":"*","eventId":"60768","eventType":"EVENT_COMMIT_TXN","eventsDumpProgress":"10/0","dumpTime":1531246052}
> 2018-07-10T18:07:32,817 INFO [HiveServer2-Background-Pool: Thread-15161]:
> events.AbstractEventHandler (:()) - Processing#60769 OPEN_TXN message :
> \{"txnIds":null,"timestamp":1531246052,"fromTxnId":30327,"toTxnId":30327,"server":"thrift://hwx-demo-2.field.hortonworks.com:9083","servicePrincipal":"hive/[email protected]"}
> 2018-07-10T18:07:32,841 INFO [HiveServer2-Background-Pool: Thread-15161]:
> ReplState (:()) - REPL::EVENT_DUMP:
> \{"dbName":"*","eventId":"60769","eventType":"EVENT_OPEN_TXN","eventsDumpProgress":"11/0","dumpTime":1531246052}
> 2018-07-10T18:07:32,841 WARN [HiveServer2-Background-Pool: Thread-15161]:
> metastore.RetryingMetaStoreClient (:()) - MetaStoreClient lost connection.
> Attempting to reconnect (1 of 24) after 5s. getNextNotification
> org.apache.thrift.transport.TTransportException: Cannot write to null
> outputStream
> at
> org.apache.thrift.transport.TIOStreamTransport.write(TIOStreamTransport.java:142)
> ~[hive-exec-3.1.0.3.0.0.0-1605.jar:3.1.0.3.0.0.0-1605]
> at
> org.apache.thrift.protocol.TBinaryProtocol.writeI32(TBinaryProtocol.java:178)
> ~[hive-exec-3.1.0.3.0.0.0-1605.jar:3.1.0.3.0.0.0-1605]
> at
> org.apache.thrift.protocol.TBinaryProtocol.writeMessageBegin(TBinaryProtocol.java:106)
> ~[hive-exec-3.1.0.3.0.0.0-1605.jar:3.1.0.3.0.0.0-1605]
> at org.apache.thrift.TServiceClient.sendBase(TServiceClient.java:70)
> ~[hive-exec-3.1.0.3.0.0.0-1605.jar:3.1.0.3.0.0.0-1605]
> at org.apache.thrift.TServiceClient.sendBase(TServiceClient.java:62)
> ~[hive-exec-3.1.0.3.0.0.0-1605.jar:3.1.0.3.0.0.0-1605]
> at
> org.apache.hadoop.hive.metastore.api.ThriftHiveMetastore$Client.send_get_next_notification(ThriftHiveMetastore.java:5547)
> ~[hive-exec-3.1.0.3.0.0.0-1605.jar:3.1.0.3.0.0.0-1605]
> at
> org.apache.hadoop.hive.metastore.api.ThriftHiveMetastore$Client.get_next_notification(ThriftHiveMetastore.java:5539)
> ~[hive-exec-3.1.0.3.0.0.0-1605.jar:3.1.0.3.0.0.0-1605]
> at
> org.apache.hadoop.hive.metastore.HiveMetaStoreClient.getNextNotification(HiveMetaStoreClient.java:2697)
> ~[hive-exec-3.1.0.3.0.0.0-1605.jar:3.1.0.3.0.0.0-1605]
> at sun.reflect.GeneratedMethodAccessor24.invoke(Unknown Source) ~[?:?]
> at
> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
> ~[?:1.8.0_112]
> at java.lang.reflect.Method.invoke(Method.java:498) ~[?:1.8.0_112]
> at
> org.apache.hadoop.hive.metastore.RetryingMetaStoreClient.invoke(RetryingMetaStoreClient.java:212)
> ~[hive-exec-3.1.0.3.0.0.0-1605.jar:3.1.0.3.0.0.0-1605]
> at com.sun.proxy.$Proxy60.getNextNotification(Unknown Source) ~[?:?]
> at sun.reflect.GeneratedMethodAccessor24.invoke(Unknown Source) ~[?:?]
> at
> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
> ~[?:1.8.0_112]
> at java.lang.reflect.Method.invoke(Method.java:498) ~[?:1.8.0_112]
> at
> org.apache.hadoop.hive.metastore.HiveMetaStoreClient$SynchronizedHandler.invoke(HiveMetaStoreClient.java:2773)
> ~[hive-exec-3.1.0.3.0.0.0-1605.jar:3.1.0.3.0.0.0-1605]
> at com.sun.proxy.$Proxy60.getNextNotification(Unknown Source) ~[?:?]
> at
> org.apache.hadoop.hive.metastore.messaging.EventUtils$MSClientNotificationFetcher.getNextNotificationEvents(EventUtils.java:94)
> ~[hive-exec-3.1.0.3.0.0.0-1605.jar:3.1.0.3.0.0.0-1605]
> at
> org.apache.hadoop.hive.metastore.messaging.EventUtils$NotificationEventIterator.fetchNextBatch(EventUtils.java:146)
> ~[hive-exec-3.1.0.3.0.0.0-1605.jar:3.1.0.3.0.0.0-1605]
> at
> org.apache.hadoop.hive.metastore.messaging.EventUtils$NotificationEventIterator.hasNext(EventUtils.java:176)
> ~[hive-exec-3.1.0.3.0.0.0-1605.jar:3.1.0.3.0.0.0-1605]
> at
> org.apache.hadoop.hive.ql.exec.repl.ReplDumpTask.incrementalDump(ReplDumpTask.java:170)
> ~[hive-exec-3.1.0.3.0.0.0-1605.jar:3.1.0.3.0.0.0-1605]
> at
> org.apache.hadoop.hive.ql.exec.repl.ReplDumpTask.execute(ReplDumpTask.java:121)
> ~[hive-exec-3.1.0.3.0.0.0-1605.jar:3.1.0.3.0.0.0-1605]
> at org.apache.hadoop.hive.ql.exec.Task.executeTask(Task.java:205)
> ~[hive-exec-3.1.0.3.0.0.0-1605.jar:3.1.0.3.0.0.0-1605]
> at
> org.apache.hadoop.hive.ql.exec.TaskRunner.runSequential(TaskRunner.java:97)
> ~[hive-exec-3.1.0.3.0.0.0-1605.jar:3.1.0.3.0.0.0-1605]
> at org.apache.hadoop.hive.ql.Driver.launchTask(Driver.java:2668)
> ~[hive-exec-3.1.0.3.0.0.0-1605.jar:3.1.0.3.0.0.0-1605]
> at org.apache.hadoop.hive.ql.Driver.execute(Driver.java:2339)
> ~[hive-exec-3.1.0.3.0.0.0-1605.jar:3.1.0.3.0.0.0-1605]
> at org.apache.hadoop.hive.ql.Driver.runInternal(Driver.java:2015)
> ~[hive-exec-3.1.0.3.0.0.0-1605.jar:3.1.0.3.0.0.0-1605]
> at org.apache.hadoop.hive.ql.Driver.run(Driver.java:1713)
> ~[hive-exec-3.1.0.3.0.0.0-1605.jar:3.1.0.3.0.0.0-1605]
> at org.apache.hadoop.hive.ql.Driver.run(Driver.java:1707)
> ~[hive-exec-3.1.0.3.0.0.0-1605.jar:3.1.0.3.0.0.0-1605]
> at org.apache.hadoop.hive.ql.reexec.ReExecDriver.run(ReExecDriver.java:157)
> ~[hive-exec-3.1.0.3.0.0.0-1605.jar:3.1.0.3.0.0.0-1605]
> at
> org.apache.hive.service.cli.operation.SQLOperation.runQuery(SQLOperation.java:224)
> ~[hive-service-3.1.0.3.0.0.0-1605.jar:3.1.0.3.0.0.0-1605]
> at
> org.apache.hive.service.cli.operation.SQLOperation.access$700(SQLOperation.java:87)
> ~[hive-service-3.1.0.3.0.0.0-1605.jar:3.1.0.3.0.0.0-1605]
> at
> org.apache.hive.service.cli.operation.SQLOperation$BackgroundWork$1.run(SQLOperation.java:316)
> ~[hive-service-3.1.0.3.0.0.0-1605.jar:3.1.0.3.0.0.0-1605]
> at java.security.AccessController.doPrivileged(Native Method) ~[?:1.8.0_112]
> at javax.security.auth.Subject.doAs(Subject.java:422) ~[?:1.8.0_112]
> at
> org.apache.hadoop.security.UserGroupInformation.doAs(UserGroupInformation.java:1688)
> ~[hadoop-common-3.1.0.3.0.0.0-1605.jar:?]
> at
> org.apache.hive.service.cli.operation.SQLOperation$BackgroundWork.run(SQLOperation.java:329)
> ~[hive-service-3.1.0.3.0.0.0-1605.jar:3.1.0.3.0.0.0-1605]
> at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
> ~[?:1.8.0_112]
> at java.util.concurrent.FutureTask.run(FutureTask.java:266) ~[?:1.8.0_112]
> at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
> ~[?:1.8.0_112]
> at java.util.concurrent.FutureTask.run(FutureTask.java:266) ~[?:1.8.0_112]
> at
> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
> ~[?:1.8.0_112]
> at
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
> ~[?:1.8.0_112]
> at java.lang.Thread.run(Thread.java:745) [?:1.8.0_112]
> 2018-07-10T18:07:33,157 INFO
> [org.apache.ranger.audit.queue.AuditBatchQueue1]:
> destination.HDFSAuditDestination (:()) - Flushing HDFS audit. Event Size:4
> 2018-07-10T18:07:37,842 INFO [HiveServer2-Background-Pool: Thread-15161]:
> metastore.RetryingMetaStoreClient (:()) - RetryingMetaStoreClient trying
> reconnect as hive (auth:SIMPLE)
> 2018-07-10T18:07:37,842 INFO [HiveServer2-Background-Pool: Thread-15161]:
> metastore.HiveMetaStoreClient (:()) - Trying to connect to metastore with URI
> thrift://hwx-demo-2.field.hortonworks.com:9083
> 2018-07-10T18:07:37,842 INFO [HiveServer2-Background-Pool: Thread-15161]:
> metastore.HiveMetaStoreClient (:()) - Opened a connection to metastore,
> current connections: 19
> 2018-07-10T18:07:37,843 INFO [HiveServer2-Background-Pool: Thread-15161]:
> metastore.HiveMetaStoreClient (:()) - Connected to metastore.
> 2018-07-10T18:07:37,864 INFO [HiveServer2-Background-Pool: Thread-15161]:
> ReplState (:()) - REPL::END:
> \{"dbName":"*","dumpType":"INCREMENTAL","actualNumEvents":11,"dumpEndTime":1531246057,"dumpDir":"/user/hive/repl/c72dc152-c252-4454-9b0e-cf8c335ab07c","lastReplId":"60769"}
> 2018-07-10T18:07:37,864 INFO [HiveServer2-Background-Pool: Thread-15161]:
> repl.ReplDumpTask (:()) - Done dumping events, preparing to return
> /user/hive/repl/c72dc152-c252-4454-9b0e-cf8c335ab07c,60769
> 2018-07-10T18:07:37,919 INFO [HiveServer2-Background-Pool: Thread-15161]:
> ql.Driver (:()) - Completed executing
> command(queryId=hive_20180710180732_7dcc20db-90db-486d-a825-e6fa91dc092b);
> Time taken: 5.419 seconds
> 2018-07-10T18:07:37,919 INFO [HiveServer2-Background-Pool: Thread-15161]:
> ql.Driver (:()) - OK
> {code}
> Metastore connection failed 1st attempt, but success after reconnect. That
> adds 5s for every repl dump command and likely to leak connection.
> Similarly, Hive.close() also causes
> {code:java}
> org.apache.thrift.transport.TTransportException: Cannot write to null
> outputStream{code}
>
--
This message was sent by Atlassian JIRA
(v7.6.3#76005)
