Uploaded image for project: 'Hive'
  1. Hive
  2. HIVE-6852

JDBC client connections hang at TSaslTransport

    Details

    • Type: Bug
    • Status: Open
    • Priority: Major
    • Resolution: Unresolved
    • Affects Version/s: None
    • Fix Version/s: None
    • Component/s: JDBC
    • Labels:
      None

      Description

      I've noticed that when there is an underlying issue in connecting a client to the JDBC interface of the HiveServer2 to run queries, you get a hang after the thrift portion, at least in certain scenarios:

      Turning log4j to DEBUG, you can see the following when trying to get a connection using:

              Connection jdbc = DriverManager.getConnection(this.con,"hive","password");
              "jdbc:hive2://localhost:10000/default",
      

      The logs get to here before the hang :

      0    [main] DEBUG org.apache.thrift.transport.TSaslTransport  - opening transport org.apache.thrift.transport.TSaslClientTransport@219ba640
      0 [main] DEBUG org.apache.thrift.transport.TSaslTransport  - opening transport org.apache.thrift.transport.TSaslClientTransport@219ba640
      3    [main] DEBUG org.apache.thrift.transport.TSaslClientTransport  - Sending mechanism name PLAIN and initial response of length 14
      3 [main] DEBUG org.apache.thrift.transport.TSaslClientTransport  - Sending mechanism name PLAIN and initial response of length 14
      5    [main] DEBUG org.apache.thrift.transport.TSaslTransport  - CLIENT: Writing message with status START and payload length 5
      5 [main] DEBUG org.apache.thrift.transport.TSaslTransport  - CLIENT: Writing message with status START and payload length 5
      5    [main] DEBUG org.apache.thrift.transport.TSaslTransport  - CLIENT: Writing message with status COMPLETE and payload length 14
      5 [main] DEBUG org.apache.thrift.transport.TSaslTransport  - CLIENT: Writing message with status COMPLETE and payload length 14
      5    [main] DEBUG org.apache.thrift.transport.TSaslTransport  - CLIENT: Start message handled
      5 [main] DEBUG org.apache.thrift.transport.TSaslTransport  - CLIENT: Start message handled
      5    [main] DEBUG org.apache.thrift.transport.TSaslTransport  - CLIENT: Main negotiation loop complete
      5 [main] DEBUG org.apache.thrift.transport.TSaslTransport  - CLIENT: Main negotiation loop complete
      6    [main] DEBUG org.apache.thrift.transport.TSaslTransport  - CLIENT: SASL Client receiving last message
      6 [main] DEBUG org.apache.thrift.transport.TSaslTransport  - CLIENT: SASL Client receiving last message
      

        Activity

        Hide
        szehon Szehon Ho added a comment -

        Can you check the jstack of the hanging client to see what its waiting for?

        Show
        szehon Szehon Ho added a comment - Can you check the jstack of the hanging client to see what its waiting for?
        Hide
        vkovalchuk Vladimir Kovalchuk added a comment -

        100% reproducible.
        ...
        "main" #1 prio=5 os_prio=0 tid=0x0000000001e78000 nid=0x255c runnable [0x0000000002bee000]
        java.lang.Thread.State: RUNNABLE
        at java.net.SocketInputStream.socketRead0(Native Method)
        at java.net.SocketInputStream.socketRead(SocketInputStream.java:116)
        at java.net.SocketInputStream.read(SocketInputStream.java:170)
        at java.net.SocketInputStream.read(SocketInputStream.java:141)
        at java.io.BufferedInputStream.fill(BufferedInputStream.java:246)
        at java.io.BufferedInputStream.read1(BufferedInputStream.java:286)
        at java.io.BufferedInputStream.read(BufferedInputStream.java:345)

        • locked <0x00000000d63658d8> (a java.io.BufferedInputStream)
          at org.apache.thrift.transport.TIOStreamTransport.read(TIOStreamTransport.java:127)
          at org.apache.thrift.transport.TTransport.readAll(TTransport.java:84)
          at org.apache.thrift.transport.TSaslTransport.receiveSaslMessage(TSaslTransport.java:178)
          at org.apache.thrift.transport.TSaslTransport.open(TSaslTransport.java:288)
          at org.apache.thrift.transport.TSaslClientTransport.open(TSaslClientTransport.java:37)
          at org.apache.hive.jdbc.HiveConnection.openTransport(HiveConnection.java:190)
          at org.apache.hive.jdbc.HiveConnection.<init>(HiveConnection.java:163)
          at org.apache.hive.jdbc.HiveDriver.connect(HiveDriver.java:105)
          at java.sql.DriverManager.getConnection(DriverManager.java:664)
          at java.sql.DriverManager.getConnection(DriverManager.java:247)
          ...
        Show
        vkovalchuk Vladimir Kovalchuk added a comment - 100% reproducible. ... "main" #1 prio=5 os_prio=0 tid=0x0000000001e78000 nid=0x255c runnable [0x0000000002bee000] java.lang.Thread.State: RUNNABLE at java.net.SocketInputStream.socketRead0(Native Method) at java.net.SocketInputStream.socketRead(SocketInputStream.java:116) at java.net.SocketInputStream.read(SocketInputStream.java:170) at java.net.SocketInputStream.read(SocketInputStream.java:141) at java.io.BufferedInputStream.fill(BufferedInputStream.java:246) at java.io.BufferedInputStream.read1(BufferedInputStream.java:286) at java.io.BufferedInputStream.read(BufferedInputStream.java:345) locked <0x00000000d63658d8> (a java.io.BufferedInputStream) at org.apache.thrift.transport.TIOStreamTransport.read(TIOStreamTransport.java:127) at org.apache.thrift.transport.TTransport.readAll(TTransport.java:84) at org.apache.thrift.transport.TSaslTransport.receiveSaslMessage(TSaslTransport.java:178) at org.apache.thrift.transport.TSaslTransport.open(TSaslTransport.java:288) at org.apache.thrift.transport.TSaslClientTransport.open(TSaslClientTransport.java:37) at org.apache.hive.jdbc.HiveConnection.openTransport(HiveConnection.java:190) at org.apache.hive.jdbc.HiveConnection.<init>(HiveConnection.java:163) at org.apache.hive.jdbc.HiveDriver.connect(HiveDriver.java:105) at java.sql.DriverManager.getConnection(DriverManager.java:664) at java.sql.DriverManager.getConnection(DriverManager.java:247) ...
        Hide
        vkovalchuk Vladimir Kovalchuk added a comment -

        The problem was that HiveServer2 conf file had authentication = NOSASL, but the client was not prepared for this situation. Workaround is to add ";auth=noSasl" to JDBC URL.
        I would say it's definitely a bug (at protocol specification level I am afraid, needs some re-design), and at least needs to be documentation.

        Show
        vkovalchuk Vladimir Kovalchuk added a comment - The problem was that HiveServer2 conf file had authentication = NOSASL, but the client was not prepared for this situation. Workaround is to add ";auth=noSasl" to JDBC URL. I would say it's definitely a bug (at protocol specification level I am afraid, needs some re-design), and at least needs to be documentation.
        Hide
        azeroth2b Shawn Lavelle added a comment - - edited

        This workaround doesn't work with authentication set to CUSTOM. Client still hangs.

        Show
        azeroth2b Shawn Lavelle added a comment - - edited This workaround doesn't work with authentication set to CUSTOM. Client still hangs.
        Hide
        azeroth2b Shawn Lavelle added a comment - - edited

        Any thoughts on this being a known JDK issue?
        http://bugs.java.com/bugdatabase/view_bug.do?bug_id=8075484
        (https://bugs.openjdk.java.net/browse/JDK-8049846)
        (https://bugs.openjdk.java.net/browse/JDK-8075484)

        Here's my stack trace using CUSTOM authentication on Hive 0.11:

        Debug Output
        16/09/08 09:36:48 DEBUG TSaslTransport: opening transport org.apache.thrift.transpor58
        16/09/08 09:36:48 DEBUG TSaslClientTransport: Sending mechanism name PLAIN and initi
        16/09/08 09:36:48 DEBUG TSaslTransport: CLIENT: Writing message with status START an
        16/09/08 09:36:48 DEBUG TSaslTransport: CLIENT: Writing message with status COMPLETE
        16/09/08 09:36:48 DEBUG TSaslTransport: CLIENT: Start message handled
        16/09/08 09:36:48 DEBUG TSaslTransport: CLIENT: Main negotiation loop complete
        16/09/08 09:36:48 DEBUG TSaslTransport: CLIENT: SASL Client receiving last message
        
        Partial Stack Trace
        "main" #1 prio=5 os_prio=0 tid=0x000000000049f800 nid=0x409c runnable [0x000000000024d000]
           java.lang.Thread.State: RUNNABLE
                at java.net.SocketInputStream.socketRead0(Native Method)
                at java.net.SocketInputStream.socketRead(SocketInputStream.java:116)
                at java.net.SocketInputStream.read(SocketInputStream.java:170)
                at java.net.SocketInputStream.read(SocketInputStream.java:141)
                at java.io.BufferedInputStream.fill(BufferedInputStream.java:246)
                at java.io.BufferedInputStream.read1(BufferedInputStream.java:286)
                at java.io.BufferedInputStream.read(BufferedInputStream.java:345)
                - locked <0x0000000716426228> (a java.io.BufferedInputStream)
                at org.apache.thrift.transport.TIOStreamTransport.read(TIOStreamTransport.java:127)
                at org.apache.thrift.transport.TTransport.readAll(TTransport.java:84)
                at org.apache.thrift.transport.TSaslTransport.receiveSaslMessage(TSaslTransport.java:178)
                at org.apache.thrift.transport.TSaslTransport.open(TSaslTransport.java:288)
                at org.apache.thrift.transport.TSaslClientTransport.open(TSaslClientTransport.java:37)
                at org.apache.hive.jdbc.HiveConnection.openTransport(HiveConnection.java:157)
        
        Show
        azeroth2b Shawn Lavelle added a comment - - edited Any thoughts on this being a known JDK issue? http://bugs.java.com/bugdatabase/view_bug.do?bug_id=8075484 ( https://bugs.openjdk.java.net/browse/JDK-8049846 ) ( https://bugs.openjdk.java.net/browse/JDK-8075484 ) Here's my stack trace using CUSTOM authentication on Hive 0.11: Debug Output 16/09/08 09:36:48 DEBUG TSaslTransport: opening transport org.apache.thrift.transpor58 16/09/08 09:36:48 DEBUG TSaslClientTransport: Sending mechanism name PLAIN and initi 16/09/08 09:36:48 DEBUG TSaslTransport: CLIENT: Writing message with status START an 16/09/08 09:36:48 DEBUG TSaslTransport: CLIENT: Writing message with status COMPLETE 16/09/08 09:36:48 DEBUG TSaslTransport: CLIENT: Start message handled 16/09/08 09:36:48 DEBUG TSaslTransport: CLIENT: Main negotiation loop complete 16/09/08 09:36:48 DEBUG TSaslTransport: CLIENT: SASL Client receiving last message Partial Stack Trace "main" #1 prio=5 os_prio=0 tid=0x000000000049f800 nid=0x409c runnable [0x000000000024d000] java.lang. Thread .State: RUNNABLE at java.net.SocketInputStream.socketRead0(Native Method) at java.net.SocketInputStream.socketRead(SocketInputStream.java:116) at java.net.SocketInputStream.read(SocketInputStream.java:170) at java.net.SocketInputStream.read(SocketInputStream.java:141) at java.io.BufferedInputStream.fill(BufferedInputStream.java:246) at java.io.BufferedInputStream.read1(BufferedInputStream.java:286) at java.io.BufferedInputStream.read(BufferedInputStream.java:345) - locked <0x0000000716426228> (a java.io.BufferedInputStream) at org.apache.thrift.transport.TIOStreamTransport.read(TIOStreamTransport.java:127) at org.apache.thrift.transport.TTransport.readAll(TTransport.java:84) at org.apache.thrift.transport.TSaslTransport.receiveSaslMessage(TSaslTransport.java:178) at org.apache.thrift.transport.TSaslTransport.open(TSaslTransport.java:288) at org.apache.thrift.transport.TSaslClientTransport.open(TSaslClientTransport.java:37) at org.apache.hive.jdbc.HiveConnection.openTransport(HiveConnection.java:157)

          People

          • Assignee:
            Unassigned
            Reporter:
            jayunit100 jay vyas
          • Votes:
            4 Vote for this issue
            Watchers:
            10 Start watching this issue

            Dates

            • Created:
              Updated:

              Development