thrift-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Mithun Radhakrishnan (JIRA)" <j...@apache.org>
Subject [jira] [Updated] (THRIFT-4805) Fix logic of THRIFT-3769
Date Mon, 18 Feb 2019 20:56:00 GMT

     [ https://issues.apache.org/jira/browse/THRIFT-4805?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]

Mithun Radhakrishnan updated THRIFT-4805:
-----------------------------------------
    Description: 
This has to do with the fix checked in for THRIFT-3769 and THRIFT-2268, which was to mute
the noise from {{TSaslTransportExceptions}} raised from load-balancer health-checks for Thrift
services, such as the Hive metastore. Please consider [the code in TThreadPoolServer::run()|https://github.com/apache/thrift/blob/master/lib/java/src/org/apache/thrift/server/TThreadPoolServer.java#L322]:
{code:java|title=TThreadPoolServer.java}
      } catch (TException tx) {
        LOGGER.error("Thrift error occurred during processing of message.", tx);
      } catch (Exception x) {
        // We'll usually receive RuntimeException types here
        // Need to unwrap to ascertain real causing exception before we choose to ignore
        Throwable realCause = x.getCause();
        // Ignore err-logging all transport-level/type exceptions
        if ((realCause != null && realCause instanceof TTransportException)
            || (x instanceof TTransportException)) {
          LOGGER.debug(
              "Received TTransportException during processing of message. Ignoring.",
              x);
        } else {
          // Log the exception at error level and continue
          LOGGER.error("Error occurred during processing of message.", x);
        }
      } finally {...}
{code}
The logic here is solid for {{RuntimeExceptions}} that wrap {{TTansportExceptions}}. But it
slips up on handling the condition being checked for at [line#323|https://github.com/apache/thrift/blob/master/lib/java/src/org/apache/thrift/server/TThreadPoolServer.java#L323],
i.e.:
{code:java|title=TThreadPoolServer.java}
            || (x instanceof TTransportException)) {
{code}
The {{catch (Exception x)}} comes *after* the {{catch (TException tx)}}, so it's a guarantee
that {{!(x instanceof TTransportException)}}. When a {{TTransportException}} (or {{TSaslTransportException}})
is thrown, it will be caught in the first catch block, and logged. This rather defeats the
purpose of the fix. The error manifests with the following stack-trace filling up my logs:
{noformat}
org.apache.thrift.transport.TTransportException
        at org.apache.thrift.transport.TIOStreamTransport.read(TIOStreamTransport.java:132)
        at org.apache.thrift.transport.TTransport.readAll(TTransport.java:86)
        at org.apache.thrift.transport.TSaslTransport.readLength(TSaslTransport.java:374)
        at org.apache.thrift.transport.TSaslTransport.readFrame(TSaslTransport.java:451)
        at org.apache.thrift.transport.TSaslTransport.read(TSaslTransport.java:433)
        at org.apache.thrift.transport.TSaslServerTransport.read(TSaslServerTransport.java:43)
        at org.apache.thrift.transport.TTransport.readAll(TTransport.java:86)
        at org.apache.thrift.protocol.TBinaryProtocol.readAll(TBinaryProtocol.java:425)
        at org.apache.thrift.protocol.TBinaryProtocol.readI32(TBinaryProtocol.java:321)
        at org.apache.thrift.protocol.TBinaryProtocol.readMessageBegin(TBinaryProtocol.java:225)
        at org.apache.thrift.TBaseProcessor.process(TBaseProcessor.java:27)
        at org.apache.hive.service.cli.thrift.ThriftCLIMetricsProcessor.process(ThriftCLIMetricsProcessor.java:63)
        at org.apache.hadoop.hive.thrift.HadoopThriftAuthBridge$Server$TUGIAssumingProcessor$2.run(HadoopThriftAuthBridge.java:777)
        at org.apache.hadoop.hive.thrift.HadoopThriftAuthBridge$Server$TUGIAssumingProcessor$2.run(HadoopThriftAuthBridge.java:773)
        at java.security.AccessController.doPrivileged(Native Method)
        at javax.security.auth.Subject.doAs(Subject.java:422)
        at org.apache.hadoop.security.UserGroupInformation.doAs(UserGroupInformation.java:1953)
        at org.apache.hadoop.hive.thrift.HadoopThriftAuthBridge$Server$TUGIAssumingProcessor.process(HadoopThriftAuthBridge.java:773)
        at org.apache.thrift.server.TThreadPoolServer$WorkerProcess.run(TThreadPoolServer.java:310)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
        at java.lang.Thread.run(Thread.java:748)
{noformat}
The fix is simple. I'll upload it shortly, for review.

  was:
This has to do with the fix checked in for THRIFT-3769 and THRIFT-2268, which was to mute
the noise from \{{TSaslTransportException}}s raised from load-balancer health-checks for
Thrift services, such as the Hive metastore. Please consider [the code in TThreadPoolServer::run()|https://github.com/apache/thrift/blob/master/lib/java/src/org/apache/thrift/server/TThreadPoolServer.java#L322]:
{code:java|title=TThreadPoolServer.java}
      } catch (TException tx) {
        LOGGER.error("Thrift error occurred during processing of message.", tx);
      } catch (Exception x) {
        // We'll usually receive RuntimeException types here
        // Need to unwrap to ascertain real causing exception before we choose to ignore
        Throwable realCause = x.getCause();
        // Ignore err-logging all transport-level/type exceptions
        if ((realCause != null && realCause instanceof TTransportException)
            || (x instanceof TTransportException)) {
          LOGGER.debug(
              "Received TTransportException during processing of message. Ignoring.",
              x);
        } else {
          // Log the exception at error level and continue
          LOGGER.error("Error occurred during processing of message.", x);
        }
      } finally {...}
{code}
The logic here is solid for {{RuntimeExceptions}} that wrap {{TTansportExceptions}}. But it
slips up on handling the condition being checked for at [line#323|https://github.com/apache/thrift/blob/master/lib/java/src/org/apache/thrift/server/TThreadPoolServer.java#L323],
i.e.:
{code:java|title=TThreadPoolServer.java}
            || (x instanceof TTransportException)) {
{code}
The {{catch (Exception x)}} comes *after* the {{catch (TException tx)}}, so it's a guarantee
that {{!(x instanceof TTransportException)}}. When a {{TTransportException}} (or {{TSaslTransportException}})
is thrown, it will be caught in the first catch block, and logged. This rather defeats the
purpose of the fix. The error manifests with the following stack-trace filling up my logs:
{noformat}
org.apache.thrift.transport.TTransportException
        at org.apache.thrift.transport.TIOStreamTransport.read(TIOStreamTransport.java:132)
        at org.apache.thrift.transport.TTransport.readAll(TTransport.java:86)
        at org.apache.thrift.transport.TSaslTransport.readLength(TSaslTransport.java:374)
        at org.apache.thrift.transport.TSaslTransport.readFrame(TSaslTransport.java:451)
        at org.apache.thrift.transport.TSaslTransport.read(TSaslTransport.java:433)
        at org.apache.thrift.transport.TSaslServerTransport.read(TSaslServerTransport.java:43)
        at org.apache.thrift.transport.TTransport.readAll(TTransport.java:86)
        at org.apache.thrift.protocol.TBinaryProtocol.readAll(TBinaryProtocol.java:425)
        at org.apache.thrift.protocol.TBinaryProtocol.readI32(TBinaryProtocol.java:321)
        at org.apache.thrift.protocol.TBinaryProtocol.readMessageBegin(TBinaryProtocol.java:225)
        at org.apache.thrift.TBaseProcessor.process(TBaseProcessor.java:27)
        at org.apache.hive.service.cli.thrift.ThriftCLIMetricsProcessor.process(ThriftCLIMetricsProcessor.java:63)
        at org.apache.hadoop.hive.thrift.HadoopThriftAuthBridge$Server$TUGIAssumingProcessor$2.run(HadoopThriftAuthBridge.java:777)
        at org.apache.hadoop.hive.thrift.HadoopThriftAuthBridge$Server$TUGIAssumingProcessor$2.run(HadoopThriftAuthBridge.java:773)
        at java.security.AccessController.doPrivileged(Native Method)
        at javax.security.auth.Subject.doAs(Subject.java:422)
        at org.apache.hadoop.security.UserGroupInformation.doAs(UserGroupInformation.java:1953)
        at org.apache.hadoop.hive.thrift.HadoopThriftAuthBridge$Server$TUGIAssumingProcessor.process(HadoopThriftAuthBridge.java:773)
        at org.apache.thrift.server.TThreadPoolServer$WorkerProcess.run(TThreadPoolServer.java:310)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
        at java.lang.Thread.run(Thread.java:748)
{noformat}
The fix is simple. I'll upload it shortly, for review.


> Fix logic of THRIFT-3769
> ------------------------
>
>                 Key: THRIFT-4805
>                 URL: https://issues.apache.org/jira/browse/THRIFT-4805
>             Project: Thrift
>          Issue Type: Bug
>          Components: Java - Library
>    Affects Versions: 0.12.0
>            Reporter: Mithun Radhakrishnan
>            Assignee: Mithun Radhakrishnan
>            Priority: Major
>         Attachments: THRIFT-4805.1.patch, THRIFT-4805.bonus.patch
>
>
> This has to do with the fix checked in for THRIFT-3769 and THRIFT-2268, which was to
mute the noise from {{TSaslTransportExceptions}} raised from load-balancer health-checks
for Thrift services, such as the Hive metastore. Please consider [the code in TThreadPoolServer::run()|https://github.com/apache/thrift/blob/master/lib/java/src/org/apache/thrift/server/TThreadPoolServer.java#L322]:
> {code:java|title=TThreadPoolServer.java}
>       } catch (TException tx) {
>         LOGGER.error("Thrift error occurred during processing of message.", tx);
>       } catch (Exception x) {
>         // We'll usually receive RuntimeException types here
>         // Need to unwrap to ascertain real causing exception before we choose to ignore
>         Throwable realCause = x.getCause();
>         // Ignore err-logging all transport-level/type exceptions
>         if ((realCause != null && realCause instanceof TTransportException)
>             || (x instanceof TTransportException)) {
>           LOGGER.debug(
>               "Received TTransportException during processing of message. Ignoring.",
>               x);
>         } else {
>           // Log the exception at error level and continue
>           LOGGER.error("Error occurred during processing of message.", x);
>         }
>       } finally {...}
> {code}
> The logic here is solid for {{RuntimeExceptions}} that wrap {{TTansportExceptions}}.
But it slips up on handling the condition being checked for at [line#323|https://github.com/apache/thrift/blob/master/lib/java/src/org/apache/thrift/server/TThreadPoolServer.java#L323],
i.e.:
> {code:java|title=TThreadPoolServer.java}
>             || (x instanceof TTransportException)) {
> {code}
> The {{catch (Exception x)}} comes *after* the {{catch (TException tx)}}, so it's a guarantee
that {{!(x instanceof TTransportException)}}. When a {{TTransportException}} (or {{TSaslTransportException}})
is thrown, it will be caught in the first catch block, and logged. This rather defeats the
purpose of the fix. The error manifests with the following stack-trace filling up my logs:
> {noformat}
> org.apache.thrift.transport.TTransportException
>         at org.apache.thrift.transport.TIOStreamTransport.read(TIOStreamTransport.java:132)
>         at org.apache.thrift.transport.TTransport.readAll(TTransport.java:86)
>         at org.apache.thrift.transport.TSaslTransport.readLength(TSaslTransport.java:374)
>         at org.apache.thrift.transport.TSaslTransport.readFrame(TSaslTransport.java:451)
>         at org.apache.thrift.transport.TSaslTransport.read(TSaslTransport.java:433)
>         at org.apache.thrift.transport.TSaslServerTransport.read(TSaslServerTransport.java:43)
>         at org.apache.thrift.transport.TTransport.readAll(TTransport.java:86)
>         at org.apache.thrift.protocol.TBinaryProtocol.readAll(TBinaryProtocol.java:425)
>         at org.apache.thrift.protocol.TBinaryProtocol.readI32(TBinaryProtocol.java:321)
>         at org.apache.thrift.protocol.TBinaryProtocol.readMessageBegin(TBinaryProtocol.java:225)
>         at org.apache.thrift.TBaseProcessor.process(TBaseProcessor.java:27)
>         at org.apache.hive.service.cli.thrift.ThriftCLIMetricsProcessor.process(ThriftCLIMetricsProcessor.java:63)
>         at org.apache.hadoop.hive.thrift.HadoopThriftAuthBridge$Server$TUGIAssumingProcessor$2.run(HadoopThriftAuthBridge.java:777)
>         at org.apache.hadoop.hive.thrift.HadoopThriftAuthBridge$Server$TUGIAssumingProcessor$2.run(HadoopThriftAuthBridge.java:773)
>         at java.security.AccessController.doPrivileged(Native Method)
>         at javax.security.auth.Subject.doAs(Subject.java:422)
>         at org.apache.hadoop.security.UserGroupInformation.doAs(UserGroupInformation.java:1953)
>         at org.apache.hadoop.hive.thrift.HadoopThriftAuthBridge$Server$TUGIAssumingProcessor.process(HadoopThriftAuthBridge.java:773)
>         at org.apache.thrift.server.TThreadPoolServer$WorkerProcess.run(TThreadPoolServer.java:310)
>         at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
>         at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
>         at java.lang.Thread.run(Thread.java:748)
> {noformat}
> The fix is simple. I'll upload it shortly, for review.



--
This message was sent by Atlassian JIRA
(v7.6.3#76005)

Mime
View raw message