[
https://issues.apache.org/jira/browse/HIVE-20819?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16699562#comment-16699562
]
Roohi Syeda commented on HIVE-20819:
------------------------------------
Logs
2018-10-23 10:52:58,516 DEBUG hive.ql.parse.ParseDriver:
[HiveServer2-Handler-Pool: Thread-54]: Parsing command: drop table empdata
2018-10-23 10:52:58,516 DEBUG hive.ql.parse.ParseDriver:
[HiveServer2-Handler-Pool: Thread-54]: Parse Completed
2018-10-23 10:52:58,566 INFO hive.metastore: [HiveServer2-Handler-Pool:
Thread-54]: Trying to connect to metastore with URI thrift://XXXXX:9083
*2018-10-23 10:52:58,567 INFO hive.metastore: [**HiveServer2-Handler-Pool**:
Thread-54]: Opened a connection to metastore, current connections: 4*
2018-10-23 10:52:58,569 INFO hive.metastore: [HiveServer2-Handler-Pool:
Thread-54]: Connected to metastore.
2018-10-23 10:52:58,698 INFO org.apache.hadoop.hive.ql.Driver:
[HiveServer2-Handler-Pool: Thread-54]: Semantic Analysis Completed
2018-10-23 10:52:58,699 INFO hive.ql.metadata.Hive: [HiveServer2-Handler-Pool:
Thread-54]: Dumping metastore api call timing information for : compilation
phase
2018-10-23 10:52:58,699 DEBUG hive.ql.metadata.Hive: [HiveServer2-Handler-Pool:
Thread-54]: Total time spent in each metastore function (ms):
\{getTable_(String, String, )=129}
2018-10-23 10:52:58,699 INFO org.apache.hadoop.hive.ql.Driver:
[HiveServer2-Handler-Pool: Thread-54]: Completed compiling
command(queryId=hive_20181023105252_d3247a1c-e343-470b-aa46-a692b5ade414); Time
taken: 0.183 seconds
2018-10-23 10:52:58,699 DEBUG org.apache.hadoop.security.UserGroupInformation:
*[HiveServer2-**Handler-Pool**: Thread-54]:* *PrivilegedAction as:hive
(auth:SIMPLE)*
*from:org.apache.hive.service.cli.session.HiveSessionProxy.invoke(HiveSessionProxy.java:59)*
2018-10-23 10:52:58,699 DEBUG org.apache.hive.service.cli.CLIService:
[HiveServer2-Handler-Pool: Thread-54]: SessionHandle
[44f74bd9-1a71-458e-9992-e9d8afc3a958]: executeStatementAsync()
2018-10-23 10:52:58,700 DEBUG org.apache.hadoop.security.UserGroupInformation:
[HiveServer2-Background-Pool: Thread-56]: PrivilegedAction as:hive (auth:PROXY)
via hive (auth:SIMPLE)
from:org.apache.hive.service.cli.operation.SQLOperation$3.run(SQLOperation.java:314)
2018-10-23 10:52:58,700 DEBUG org.apache.thrift.transport.TSaslTransport:
[HiveServer2-Handler-Pool: Thread-54]: writing data length: 109
*2018-10-23 10:52:58,715 DEBUG hive.ql.metadata.Hive:
[HiveServer2-Background-Pool: Thread-56]: Creating new db.
db.isCurrentUserOwner = false*
*2018-10-23 10:52:58,715 DEBUG hive.ql.metadata.Hive:
[HiveServer2-Background-Pool: Thread-56]: Closing current thread's connection
to Hive Metastore.*
*2018-10-23 10:52:58,715 INFO hive.metastore: [HiveServer2-Background-Pool:
Thread-56]: Closed a connection to metastore, current connections: 3*
2018-10-23 10:52:58,716 INFO org.apache.hadoop.hive.ql.log.PerfLogger:
[HiveServer2-Background-Pool: Thread-56]: </PERFLOG method=TimeToSubmit
start=1540317178702 end=1540317178716 duration=14
from=org.apache.hadoop.hive.ql.Driver>
2018-10-23 10:52:58,716 INFO org.apache.hadoop.hive.ql.log.PerfLogger:
[HiveServer2-Background-Pool: Thread-56]: <PERFLOG method=runTasks
from=org.apache.hadoop.hive.ql.Driver>
2018-10-23 10:52:58,716 INFO org.apache.hadoop.hive.ql.Driver:
[HiveServer2-Background-Pool: Thread-56]: Starting task [Stage-0:DDL] in serial
mode
2018-10-23 10:52:58,717 INFO hive.metastore: [HiveServer2-Background-Pool:
Thread-56]: Trying to connect to metastore with URI thrift://XXXX:9083
*2018-10-23 10:52:58,717 INFO hive.metastore:
[HiveServer2-**Background-Pool**: Thread-56]: Opened a connection to metastore,
current connections: 4*
2018-10-23 10:52:58,720 INFO hive.metastore: [HiveServer2-Background-Pool:
Thread-56]: Connected to metastore.
> Leaking Metastore connections when HADOOP_USER_NAME environmental variable is
> set
> ---------------------------------------------------------------------------------
>
> Key: HIVE-20819
> URL: https://issues.apache.org/jira/browse/HIVE-20819
> Project: Hive
> Issue Type: Bug
> Components: HiveServer2
> Reporter: Roohi Syeda
> Assignee: Roohi Syeda
> Priority: Minor
> Attachments: HIVE-20819.1.patch
>
>
> Leaking Metastore connections when HADOOP_USER_NAME environmental variable is
> set.
> The connections created are in ESTABLISHED state and never closed
>
> *More Details :*
> When a new query is executed for a new session
>
> The handler thread, calls line 66 HiveSessionImplwithUGI
> (UserGroupInformation.createProxyUser(
> owner, UserGroupInformation.getLoginUser());
>
> At *query compile time*, this sessionUgi is used to open MS connection by
> *handler* thread
> Later at *query run time*, line 277 of SQLOperation
> Runnable work =
> new BackgroundWork(getCurrentUGI(), parentSession.getSessionHive(),
> SessionState.get(),
> asyncPrepare);
>
> getCurrentUGI(); is used to create a new proxy user, which in turn calls
> Utils.getUGI (see below) and passed to the *Background* thread
>
> public static UserGroupInformation *getUGI*() throws LoginException,
> IOException {
> String doAs = System.getenv("HADOOP_USER_NAME");
> if(doAs != null && doAs.length() > 0) {
> /*
> * this allows doAs (proxy user) to be passed along across process
> boundary where
> * delegation tokens are not supported. For example, a DDL stmt via
> WebHCat with
> * a doAs parameter, forks to 'hcat' which needs to start a Session that
> * proxies the end user
> */
> return UserGroupInformation.createProxyUser(doAs,
> UserGroupInformation.getLoginUser());
> }
> return UserGroupInformation.getCurrentUser();
> }
>
>
> currentUGI creates a *new* proxyuser instance. This ugi is being set on the
> background thread
> And when it is trying to get the Hive db in subsequent calls, we see that
> since the ugi’s are not equal (See the equals code below), a new connection
> is opened, which is never closed, by background thread.
> Line 318 in Hive.java
>
> private static Hive getInternal(HiveConf c, boolean needsRefresh, boolean
> isFastCheck,
> boolean doRegisterAllFns) throws HiveException {
> Hive db = hiveDB.get();
> if (db == null || !db.*isCurrentUserOwner*() || needsRefresh
> || (c != null && !isCompatible(db, c, isFastCheck))) {
> db = create(c, false, db, doRegisterAllFns);
> }
> if (c != null) {
> db.conf = c;
> }
> return db;
> }
>
> private boolean isCurrentUserOwner() throws HiveException {
> try {
> return owner == null ||
> owner.equals(UserGroupInformation.getCurrentUser());
> } catch(IOException e) {
> throw new HiveException("Error getting current user: " +
> e.getMessage(), e);
> }
> }
> /**
> * Compare the subjects to see if they are equal to each other.
> */
> @Override
> public boolean *equals*(Object o) {
> if (o == this) {
> return true;
> } else if (o == null || getClass() != o.getClass()) {
> return false;
> } else {
> return subject == ((UserGroupInformation) o).subject;
> }
> }
>
> Solution:
> When we assign *currentUGI* to the bg thread, we should call
> UserGroupInformation.getCurrentUser() (see below) instead of calling *getUGI*
> method listed above (which creates a new instance of proxy user and subject
> and will always return isCurrentUserOwner as false, since both subject and
> ugi instances are different and hence creates a new MS connection)
>
> /**
> * Return the current user, including any doAs in the current stack.
>
> */
>
> public synchronized
> static UserGroupInformation getCurrentUser() throws IOException {
> AccessControlContext context = AccessController.getContext();
> Subject subject = Subject.getSubject(context);
> if (subject == null || subject.getPrincipals(User.class).isEmpty()) {
> return getLoginUser();
> } else {
> return new UserGroupInformation(subject);
> }
> }
>
>
--
This message was sent by Atlassian JIRA
(v7.6.3#76005)
