[
https://issues.apache.org/jira/browse/HIVE-14090?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=15348497#comment-15348497
]
Sahil Takiar edited comment on HIVE-14090 at 6/24/16 4:17 PM:
--------------------------------------------------------------
The root cause of this issue is in {{RetryingHMSHandler.invokeInternal}}
method, specifically the following lines:
{code}
if (retryCount >= retryLimit) {
LOG.error("HMSHandler Fatal error: " +
ExceptionUtils.getStackTrace(caughtException));
// Since returning exceptions with a nested "cause" can be a problem in
// Thrift, we are stuffing the stack trace into the message itself.
throw new MetaException(ExceptionUtils.getStackTrace(caughtException));
}
{code}
Some context: this code is run on the Hive Metastore server (clients
communicate with the remote Hive Metastore instance via a Thrift API).
The {{caughtException}} variable is a {{JDOFatalUserException}}. So the entire
stack-trace of {{JDOFatalUserException}} gets stuffed into the message of a
{{MetaException}}, which then gets returned to the client (HiveServer2
usually), via the Hive Metastore Thrift API. This only happens for
{{JDOException}}s due to some other logic in the class, which is why it is not
a very common complaint. So when HiveServer2 sees an exception is thrown by the
Metastore, it displays the exception message to the user, which in this case
contains the full stack-trace of the exception.
Note that the comments in the code mention that the stack-trace is stuffed into
the message due to some problems with Thrift not sending the entire stack-trace
back to the client. This comment was added in HIVE-3400 - there is a
Phabricator review linked to the Hive JIRA (https://reviews.facebook.net/D4791)
which contains a relevant conversation about this choice, I copied it below:
{code}
Actually the RetryingHMSHandler is currently putting the stacktrace into the
"message" of the MetaException and not its "cause". In the Thrift generated
MetaException.java, there is no constructor taking the cause so I stuffed it
into the message. Now that I think of it, I can call initCause(jdoexception)
after constructing the MetaException. Then I can make the change you suggested.
Do you want me to do that?
...
Yes, please do that. Type comparison is much better than regex matching.
...
Unfortunately, things break with that change. In direct db mode things are
fine. But when we go through Thrift, the MetaException received by Hive client
from the Thrift server has null as its cause. Even though the cause is being
set properly on the Thrift side. This might be happening because Thrift does
not "know" about JDOExceptions. Or it may even be a limitation of Thrift
exception handling. Not sure. I'm satisfied with the way it was. The two key
requirements of letting the client know about the JDOException and shipping the
entire stack trace back were being met. What do you think?
...
Yeah, lets keep it this way then. If, thrift can't transport exception trace
correctly. I will suggest to leave a comment there saying why we have to do
regex matching of exception message instead of checking type of exception.
{code}
I modified the code to stop stuffing the stack-trace into the exception
message, and I tested the change locally. The change works. The full exception
is still shipped to the client (HiveServer2), who prints the full exception
stack trace in its log files, and only the exception message is displayed to
the user. I was sure to run the Hive Metastore as a Thrift Server in order to
check if Thrift had any issues transporting the stack trace of the exception,
and I saw no issues.
was (Author: stakiar):
The root cause of this issue is in {{RetryingHMSHandler.invokeInternal}}
method, specifically the following lines:
{code}
if (retryCount >= retryLimit) {
LOG.error("HMSHandler Fatal error: " +
ExceptionUtils.getStackTrace(caughtException));
// Since returning exceptions with a nested "cause" can be a problem in
// Thrift, we are stuffing the stack trace into the message itself.
throw new MetaException(ExceptionUtils.getStackTrace(caughtException));
}
{code}
Some context: this code is run on the Hive Metastore server (clients
communicate with the remote Hive Metastore instance via a Thrift API).
The {{caughtException}} variable is a {{JDOFatalUserException}}. So the entire
stack-trace of {{JDOFatalUserException}} gets stuffed into the message of a
{{MetaException}}, which then gets returned to the client (HiveServer2
usually), via the Hive Metastore Thrift API. This only happens for
{{JDOException}}s due to some other logic in the class, which is why it is not
a very common complaint. So when HiveServer2 sees an exception is thrown by the
Metastore, it displays the exception message to the user, which in this case
contains the full stack-trace of the exception.
Note that the comments in the code mention that the stack-trace is stuffed into
the message due to some problems with Thrift not sending the entire stack-trace
back to the client. This comment was added in
https://issues.apache.org/jira/browse/HIVE-3400 - there is a Phabricator review
linked to the Hive JIRA (https://reviews.facebook.net/D4791) which contains a
relevant conversation about this choice, I copied it below:
{code}
Actually the RetryingHMSHandler is currently putting the stacktrace into the
"message" of the MetaException and not its "cause". In the Thrift generated
MetaException.java, there is no constructor taking the cause so I stuffed it
into the message. Now that I think of it, I can call initCause(jdoexception)
after constructing the MetaException. Then I can make the change you suggested.
Do you want me to do that?
...
Yes, please do that. Type comparison is much better than regex matching.
...
Unfortunately, things break with that change. In direct db mode things are
fine. But when we go through Thrift, the MetaException received by Hive client
from the Thrift server has null as its cause. Even though the cause is being
set properly on the Thrift side. This might be happening because Thrift does
not "know" about JDOExceptions. Or it may even be a limitation of Thrift
exception handling. Not sure. I'm satisfied with the way it was. The two key
requirements of letting the client know about the JDOException and shipping the
entire stack trace back were being met. What do you think?
...
Yeah, lets keep it this way then. If, thrift can't transport exception trace
correctly. I will suggest to leave a comment there saying why we have to do
regex matching of exception message instead of checking type of exception.
{code}
I modified the code to stop stuffing the stack-trace into the exception
message, and I tested the change locally. The change works. The full exception
is still shipped to the client (HiveServer2), who prints the full exception
stack trace in its log files, and only the exception message is displayed to
the user. I was sure to run the Hive Metastore as a Thrift Server in order to
check if Thrift had any issues transporting the stack trace of the exception,
and I saw no issues.
> JDOException's thrown by the Metastore have their full stack trace returned
> to clients
> --------------------------------------------------------------------------------------
>
> Key: HIVE-14090
> URL: https://issues.apache.org/jira/browse/HIVE-14090
> Project: Hive
> Issue Type: Bug
> Affects Versions: 1.1.0, 2.1.0
> Reporter: Sahil Takiar
> Assignee: Sahil Takiar
>
> When user try to create any database or table with a name longer than 128
> characters:
> {code}
> create database
> test_longname_looooooonglooooooonglooooooonglooooooonglooooooonglooooooonglooooooonglooooooonglooooooonglooooooonglooooooongNametableFAIL;
> {code}
> It dumps the full exception stack-trace in a non-user-friendly message. The
> lends to relatively negative user-experience for Beeline users who hit this
> exception, they are generally not interested in the full stack-trace.
> The formatted stack-trace is below:
> {code}
> Error while processing statement: FAILED: Execution Error, return code 1 from
> org.apache.hadoop.hive.ql.exec.DDLTask.
> MetaException(message:javax.jdo.JDOFatalUserException: Attempt to store value
> "test_longname_looooooonglooooooonglooooooonglooooooonglooooooonglooooooonglooooooonglooooooonglooooooonglooooooonglooooooongnametablefail2"
> in column "`NAME`" that has maximum length of 128. Please correct your data!
> at
> org.datanucleus.api.jdo.NucleusJDOHelper.getJDOExceptionForNucleusException(NucleusJDOHelper.java:528)
> at
> org.datanucleus.api.jdo.JDOPersistenceManager.jdoMakePersistent(JDOPersistenceManager.java:732)
> at
> org.datanucleus.api.jdo.JDOPersistenceManager.makePersistent(JDOPersistenceManager.java:752)
> at
> org.apache.hadoop.hive.metastore.ObjectStore.createDatabase(ObjectStore.java:569)
> at sun.reflect.GeneratedMethodAccessor31.invoke(Unknown Source)
> at
> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
> at java.lang.reflect.Method.invoke(Method.java:606)
> at
> org.apache.hadoop.hive.metastore.RawStoreProxy.invoke(RawStoreProxy.java:114)
> at com.sun.proxy.$Proxy10.createDatabase(Unknown Source)
> at
> org.apache.hadoop.hive.metastore.HiveMetaStore$HMSHandler.create_database_core(HiveMetaStore.java:923)
> at
> org.apache.hadoop.hive.metastore.HiveMetaStore$HMSHandler.create_database(HiveMetaStore.java:962)
> at sun.reflect.GeneratedMethodAccessor30.invoke(Unknown Source)
> at
> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
> at java.lang.reflect.Method.invoke(Method.java:606)
> at
> org.apache.hadoop.hive.metastore.RetryingHMSHandler.invokeInternal(RetryingHMSHandler.java:138)
> at
> org.apache.hadoop.hive.metastore.RetryingHMSHandler.invoke(RetryingHMSHandler.java:99)
> at com.sun.proxy.$Proxy12.create_database(Unknown Source)
> at
> org.apache.hadoop.hive.metastore.api.ThriftHiveMetastore$Processor$create_database.getResult(ThriftHiveMetastore.java:8863)
> at
> org.apache.hadoop.hive.metastore.api.ThriftHiveMetastore$Processor$create_database.getResult(ThriftHiveMetastore.java:8847)
> at org.apache.thrift.ProcessFunction.process(ProcessFunction.java:39)
> at org.apache.thrift.TBaseProcessor.process(TBaseProcessor.java:39)
> at
> org.apache.hadoop.hive.thrift.HadoopThriftAuthBridge$Server$TUGIAssumingProcessor$1.run(HadoopThriftAuthBridge.java:707)
> at
> org.apache.hadoop.hive.thrift.HadoopThriftAuthBridge$Server$TUGIAssumingProcessor$1.run(HadoopThriftAuthBridge.java:702)
> at java.security.AccessController.doPrivileged(Native Method)
> at javax.security.auth.Subject.doAs(Subject.java:415)
> at
> org.apache.hadoop.security.UserGroupInformation.doAs(UserGroupInformation.java:1693)
> at
> org.apache.hadoop.hive.thrift.HadoopThriftAuthBridge$Server$TUGIAssumingProcessor.process(HadoopThriftAuthBridge.java:702)
> at
> org.apache.thrift.server.TThreadPoolServer$WorkerProcess.run(TThreadPoolServer.java:286)
> at
> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
> at
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
> at java.lang.Thread.run(Thread.java:745) NestedThrowablesStackTrace: Attempt
> to store value
> "test_longname_looooooonglooooooonglooooooonglooooooonglooooooonglooooooonglooooooonglooooooonglooooooonglooooooonglooooooongnametablefail2"
> in column "`NAME`" that has maximum length of 128. Please correct your data!
> org.datanucleus.exceptions.NucleusUserException: Attempt to store value
> "test_longname_looooooonglooooooonglooooooonglooooooonglooooooonglooooooonglooooooonglooooooonglooooooonglooooooonglooooooongnametablefail2"
> in column "`NAME`" that has maximum length of 128. Please correct your data!
> at
> org.datanucleus.store.rdbms.mapping.datastore.CharRDBMSMapping.setString(CharRDBMSMapping.java:263)
> at
> org.datanucleus.store.rdbms.mapping.java.SingleFieldMapping.setString(SingleFieldMapping.java:201)
> at
> org.datanucleus.store.rdbms.fieldmanager.ParameterSetter.storeStringField(ParameterSetter.java:159)
> at
> org.datanucleus.state.JDOStateManager.providedStringField(JDOStateManager.java:1256)
> at
> org.apache.hadoop.hive.metastore.model.MDatabase.jdoProvideField(MDatabase.java)
> at
> org.apache.hadoop.hive.metastore.model.MDatabase.jdoProvideFields(MDatabase.java)
> at
> org.datanucleus.state.JDOStateManager.provideFields(JDOStateManager.java:1346)
> at
> org.datanucleus.store.rdbms.request.InsertRequest.execute(InsertRequest.java:289)
> at
> org.datanucleus.store.rdbms.RDBMSPersistenceHandler.insertTable(RDBMSPersistenceHandler.java:167)
> at
> org.datanucleus.store.rdbms.RDBMSPersistenceHandler.insertObject(RDBMSPersistenceHandler.java:143)
> at
> org.datanucleus.state.JDOStateManager.internalMakePersistent(JDOStateManager.java:3784)
> at
> org.datanucleus.state.JDOStateManager.makePersistent(JDOStateManager.java:3760)
> at
> org.datanucleus.ExecutionContextImpl.persistObjectInternal(ExecutionContextImpl.java:2219)
> at
> org.datanucleus.ExecutionContextImpl.persistObjectWork(ExecutionContextImpl.java:2065)
> at
> org.datanucleus.ExecutionContextImpl.persistObject(ExecutionContextImpl.java:1913)
> at
> org.datanucleus.ExecutionContextThreadedImpl.persistObject(ExecutionContextThreadedImpl.java:217)
> at
> org.datanucleus.api.jdo.JDOPersistenceManager.jdoMakePersistent(JDOPersistenceManager.java:727)
> at
> org.datanucleus.api.jdo.JDOPersistenceManager.makePersistent(JDOPersistenceManager.java:752)
> at
> org.apache.hadoop.hive.metastore.ObjectStore.createDatabase(ObjectStore.java:569)
> at sun.reflect.GeneratedMethodAccessor31.invoke(Unknown Source)
> at
> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
> at java.lang.reflect.Method.invoke(Method.java:606)
> at
> org.apache.hadoop.hive.metastore.RawStoreProxy.invoke(RawStoreProxy.java:114)
> at com.sun.proxy.$Proxy10.createDatabase(Unknown Source)
> at
> org.apache.hadoop.hive.metastore.HiveMetaStore$HMSHandler.create_database_core(HiveMetaStore.java:923)
> at
> org.apache.hadoop.hive.metastore.HiveMetaStore$HMSHandler.create_database(HiveMetaStore.java:962)
> at sun.reflect.GeneratedMethodAccessor30.invoke(Unknown Source)
> at
> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
> at java.lang.reflect.Method.invoke(Method.java:606)
> at
> org.apache.hadoop.hive.metastore.RetryingHMSHandler.invokeInternal(RetryingHMSHandler.java:138)
> at
> org.apache.hadoop.hive.metastore.RetryingHMSHandler.invoke(RetryingHMSHandler.java:99)
> at com.sun.proxy.$Proxy12.create_database(Unknown Source)
> at
> org.apache.hadoop.hive.metastore.api.ThriftHiveMetastore$Processor$create_database.getResult(ThriftHiveMetastore.java:8863)
> at
> org.apache.hadoop.hive.metastore.api.ThriftHiveMetastore$Processor$create_database.getResult(ThriftHiveMetastore.java:8847)
> at org.apache.thrift.ProcessFunction.process(ProcessFunction.java:39)
> at org.apache.thrift.TBaseProcessor.process(TBaseProcessor.java:39)
> at
> org.apache.hadoop.hive.thrift.HadoopThriftAuthBridge$Server$TUGIAssumingProcessor$1.run(HadoopThriftAuthBridge.java:707)
> at
> org.apache.hadoop.hive.thrift.HadoopThriftAuthBridge$Server$TUGIAssumingProcessor$1.run(HadoopThriftAuthBridge.java:702)
> at java.security.AccessController.doPrivileged(Native Method)
> at javax.security.auth.Subject.doAs(Subject.java:415)
> at
> org.apache.hadoop.security.UserGroupInformation.doAs(UserGroupInformation.java:1693)
> at
> org.apache.hadoop.hive.thrift.HadoopThriftAuthBridge$Server$TUGIAssumingProcessor.process(HadoopThriftAuthBridge.java:702)
> at
> org.apache.thrift.server.TThreadPoolServer$WorkerProcess.run(TThreadPoolServer.java:286)
> at
> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
> at
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
> at java.lang.Thread.run(Thread.java:745) )
> {code}
> The ideal situation would be to just return the following message to Beeline
> users:
> {code}
> Error while processing statement: FAILED: Execution Error, return code 1 from
> org.apache.hadoop.hive.ql.exec.DDLTask.
> MetaException(message:javax.jdo.JDOFatalUserException: Attempt to store value
> "test_longname_looooooonglooooooonglooooooonglooooooonglooooooonglooooooonglooooooonglooooooonglooooooonglooooooonglooooooongnametablefail2"
> in column "`NAME`" that has maximum length of 128. Please correct your data!)
> {code}
> And have the full stack trace should up in the HiveServer2 logs.
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
