[THRIFT-4805] Suppress excessive logging of SASL TTransportExceptions in case of END_OF_FILE - ASF JIRA

Voters

Watch issue

Watchers

Link

Clone

Update Comment Author

Replace String in Comment

Update Comment Visibility

Delete Comments

XML

Word

Printable

JSON

Details

Type: Bug
Status: Closed
Priority: Major
Resolution: Fixed
Affects Version/s: 0.12.0
Fix Version/s: 0.13.0
Component/s: Java - Library
Labels:
- Breaking-Change

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():

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 {...}

The logic here is solid for RuntimeExceptions that wrap TTansportExceptions. But it slips up on handling the condition being checked for at line#323, i.e.:

TThreadPoolServer.java

            || (x instanceof TTransportException)) {

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:

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)

The fix is simple. I'll upload it shortly, for review.