OpenTSDB Kerberos - Failed: No common layer of protection

[Michael Sanders]

I have installed the new version of opentsdb and testing against a kerberized cluster. I have created the configuration for the jaas.conf file. I am using a keytab that we generated. We successfully login. The cluster is a 30 node cluster. hbase shell works on all the nodes, and I can successfully connect using other tools. With OpenTSDB, I have it installed on one node, and everything for the opentsdb configuration and keytab file are located in /etc/opentsdb/conf directory on that one node. 

Relevant opentsdb.conf

hbase.security.auth.enable=true

hbase.security.authentication=kerberos

hbase.kerberos.regionserver.principal=hbase/_HO...@WD.LRD.CAT.COM

java.security.auth.login.config=/etc/opentsdb/conf/jaas.conf

hbase.sasl.clientconfig=Client

jaas.conf

Client {

 com.sun.security.auth.module.Krb5LoginModule required debug=true

 useKeyTab=true

 keyTab="/etc/opentsdb/conf/hbase.keytab"

 storeKey=true

 useTicketCache=true

 principal="hbase/URL...@URL.COM";

};

Relevant Logs
10:29:49.174 [main] INFO  net.opentsdb.utils.Config - Successfully loaded configuration file: /etc/opentsdb/conf/opentsdb.conf

ey [tsd.core.meta.enable_tsuid_tracking]  Value [false]

Key [tsd.http.request.cors_domains]  Value []

Key [tsd.http.request.cors_headers]  Value [Authorization, Content-Type, Accept, Origin, User-Agent, DNT, Cache-Control, X-Mx-ReqToken, Keep-Alive, X-Requested-With, If-Modified-Since]

Key [tsd.storage.hbase.meta_table]  Value [tsdb-meta]

Key [tsd.search.enable]  Value [false]

Key [java.security.auth.login.config]  Value [/etc/opentsdb/conf/jaas.conf]

Key [tsd.core.tree.enable_processing]  Value [false]

Key [tsd.http.cachedir]  Value [/tmp/opentsdb]

Key [tsd.http.request.max_chunk]  Value [4096]

Key [tsd.http.show_stack_trace]  Value [true]

Key [tsd.http.show_stack_trace]  Value [true]

Key [tsd.query.allow_simultaneous_duplicates]  Value [true]

Key [tsd.storage.compaction.flush_speed]  Value [2]

Key [tsd.core.uid.random_metrics]  Value [false]

Key [tsd.core.meta.enable_realtime_uid]  Value [false]

Key [tsd.core.preload_uid_cache]  Value [false]

Key [tsd.query.filter.expansion_limit]  Value [4096]

Key [tsd.storage.hbase.uid_table]  Value [vims-tsdb-uid]

Key [tsd.storage.repair_appends]  Value [false]

Key [tsd.storage.hbase.zk_basedir]  Value [/hbase]

Key [tsd.storage.compaction.flush_interval]  Value [10]

Key [tsd.query.skip_unresolved_tagvs]  Value [false]

Key [hbase.kerberos.regionserver.principal]  Value [hbase/_HO...@WD.LRD.CAT.COM]

Key [tsd.no_diediedie]  Value [false]

Key [tsd.core.meta.enable_realtime_ts]  Value [false]

Key [tsd.http.query.allow_delete]  Value [false]

Key [tsd.network.bind]  Value [0.0.0.0]

Key [tsd.network.worker_threads]  Value []

Key [hbase.security.auth.enable]  Value [true]

Key [tsd.query.timeout]  Value [0]

Debug is  true storeKey true useTicketCache true useKeyTab true doNotPrompt false ticketCache is null isInitiator true KeyTab is /etc/opentsdb/conf/hbase.keytab refreshKrb5Config is false principal is

hbase/hdtmaster2.lrd.cat.com@URLCOM tryFirstPass is false useFirstPass is false storePass

is false clearPass is false

Acquire TGT from Cache

Principal is hbase/URL.com@URLCOM

null credentials from Ticket Cache

principal is hbase/url...@URL.COM

Will use keytab

Commit Succeeded

10:29:50.086 [AsyncHBase I/O Worker #1] DEBUG org.hbase.async.auth.Login - Found tgt Ticket (hex)

=Forwardable Ticket true

Forwarded Ticket false

Proxiable Ticket false

Proxy Ticket false

Postdated Ticket false

Renewable Ticket false

Initial Ticket false

Auth Time = Thu Feb 25 10:29:50 CST 2016

Start Time = Thu Feb 25 10:29:50 CST 2016

End Time = Thu Feb 25 20:29:50 CST 2016

Renew Till = null

Client Addresses  Null .

10:29:50.089 [AsyncHBase I/O Worker #1] DEBUG o.h.a.a.KerberosClientAuthProvider - Creating sasl client: client=hbase/url...@URL.COM, service=hbase, serviceHostname=hdtdata24.com

10:29:50.104 [AsyncHBase I/O Worker #1] DEBUG org.hbase.async.RegionClient - handleUpstream [id: 0x9efdf4af, /172.22.168.12:51178 => /172.22.168.39:60020] WRITTEN_AMOUNT: 6

10:29:50.117 [AsyncHBase I/O Worker #1] DEBUG org.hbase.async.RegionClient - handleUpstream [id: 0x9efdf4af, /172.22.168.12:51178 => /172.22.168.39:60020] WRITTEN_AMOUNT: 1385

10:29:50.117 [AsyncHBase I/O Worker #1] INFO  org.hbase.async.RegionClient - Initialized security

helper: org.hbase.async.SecureRpcHelper96@435e331b for region client: RegionClient@1400264902(chan=null, #pending_rpcs=2, #batched=0, #rpcs_inflight=0)

10:29:50.124 [AsyncHBase I/O Worker #1] DEBUG org.hbase.async.RegionClient - handleUpstream [id: 0x9efdf4af, /172.22.168.12:51178 => /172.22.168.39:60020] RECEIVED: BigEndianHeapChannelBuffer(ridx=0, widx=112, cap=112)

10:29:50.124 [AsyncHBase I/O Worker #1] DEBUG org.hbase.async.RegionClient - ------------------>>

ENTERING DECODE >>------------------

10:29:50.125 [AsyncHBase I/O Worker #1] DEBUG org.hbase.async.RegionClient - handleUpstream [id: 0x9efdf4af, /172.22.168.12:51178 => /172.22.168.39:60020] WRITTEN_AMOUNT: 4

10:29:50.126 [AsyncHBase I/O Worker #1] DEBUG org.hbase.async.RegionClient - handleUpstream [id: 0x9efdf4af, /172.22.168.12:51178 => /172.22.168.39:60020] RECEIVED: BigEndianHeapChannelBuffer(ridx=0, widx=58, cap=58)

10:29:50.126 [AsyncHBase I/O Worker #1] DEBUG org.hbase.async.RegionClient - ------------------>>

ENTERING DECODE >>------------------

10:29:50.136 [AsyncHBase I/O Worker #1] ERROR org.hbase.async.SecureRpcHelper - Failed Sasl challenge

javax.security.sasl.SaslException: No common protection layer between client and server

        at com.sun.security.sasl.gsskerb.GssKrb5Client.doFinalHandshake(GssKrb5Client.java:252) ~[na:1.7.0_67]

        at com.sun.security.sasl.gsskerb.GssKrb5Client.evaluateChallenge(GssKrb5Client.java:187) ~[na:1.7.0_67]

        at org.hbase.async.SecureRpcHelper$1PrivilegedAction.run(SecureRpcHelper.java:286) [asynchbase-1.7.1.jar:na]

        at org.hbase.async.SecureRpcHelper$1PrivilegedAction.run(SecureRpcHelper.java:282) [asynchbase-1.7.1.jar:na]

        at java.security.AccessController.doPrivileged(Native Method) [na:1.7.0_67]

[ManOLamancha]

On Thursday, February 25, 2016 at 8:41:22 AM UTC-8, Michael Sanders wrote:

10:29:50.089 [AsyncHBase I/O Worker #1] DEBUG o.h.a.a.KerberosClientAuthProvider - Creating sasl client: client=hbase/url...@URL.COM, service=hbase, serviceHostname=hdtdata24.com

10:29:50.104 [AsyncHBase I/O Worker #1] DEBUG org.hbase.async.RegionClient - handleUpstream [id: 0x9efdf4af, /172.22.168.12:51178 => /172.22.168.39:60020] WRITTEN_AMOUNT: 6

10:29:50.117 [AsyncHBase I/O Worker #1] DEBUG org.hbase.async.RegionClient - handleUpstream [id: 0x9efdf4af, /172.22.168.12:51178 => /172.22.168.39:60020] WRITTEN_AMOUNT: 1385

10:29:50.117 [AsyncHBase I/O Worker #1] INFO  org.hbase.async.RegionClient - Initialized security

helper: org.hbase.async.SecureRpcHelper96@435e331b for region client: RegionClient@1400264902(chan=null, #pending_rpcs=2, #batched=0, #rpcs_inflight=0)

10:29:50.124 [AsyncHBase I/O Worker #1] DEBUG org.hbase.async.RegionClient - handleUpstream [id: 0x9efdf4af, /172.22.168.12:51178 => /172.22.168.39:60020] RECEIVED: BigEndianHeapChannelBuffer(ridx=0, widx=112, cap=112)

10:29:50.124 [AsyncHBase I/O Worker #1] DEBUG org.hbase.async.RegionClient - ------------------>>

ENTERING DECODE >>------------------

10:29:50.125 [AsyncHBase I/O Worker #1] DEBUG org.hbase.async.RegionClient - handleUpstream [id: 0x9efdf4af, /172.22.168.12:51178 => /172.22.168.39:60020] WRITTEN_AMOUNT: 4

10:29:50.126 [AsyncHBase I/O Worker #1] DEBUG org.hbase.async.RegionClient - handleUpstream [id: 0x9efdf4af, /172.22.168.12:51178 => /172.22.168.39:60020] RECEIVED: BigEndianHeapChannelBuffer(ridx=0, widx=58, cap=58)

10:29:50.126 [AsyncHBase I/O Worker #1] DEBUG org.hbase.async.RegionClient - ------------------>>

ENTERING DECODE >>------------------

10:29:50.136 [AsyncHBase I/O Worker #1] ERROR org.hbase.async.SecureRpcHelper - Failed Sasl challenge

javax.security.sasl.SaslException: No common protection layer between client and server

        at com.sun.security.sasl.gsskerb.GssKrb5Client.doFinalHandshake(GssKrb5Client.java:252) ~[na:1.7.0_67]

        at com.sun.security.sasl.gsskerb.GssKrb5Client.evaluateChallenge(GssKrb5Client.java:187) ~[na:1.7.0_67]

        at org.hbase.async.SecureRpcHelper$1PrivilegedAction.run(SecureRpcHelper.java:286) [asynchbase-1.7.1.jar:na]

        at org.hbase.async.SecureRpcHelper$1PrivilegedAction.run(SecureRpcHelper.java:282) [asynchbase-1.7.1.jar:na]

        at java.security.AccessController.doPrivileged(Native Method) [na:1.7.0_67]

It looks like you set everything up properly. What version of HBase are you using?

[Michael Sanders]

We are using CDH 5.3.8

Which uses hbase-0.98.6  +cdh5.3.8+126.

Thanks for any feedback that you give.

[ManOLamancha]

On Thursday, February 25, 2016 at 10:01:48 AM UTC-8, Michael Sanders wrote:

We are using CDH 5.3.8

Which uses hbase-0.98.6  +cdh5.3.8+126.

Thanks for any feedback that you give.

Got it. Looking at: https://support.pivotal.io/hc/en-us/articles/202175358-Hadoop-daemons-reports-an-ERROR-No-common-protection-layer-between-client-and-server-

it may be that you're servers have a different protection level. Check their configs for something like

<property>
<name>hadoop.rpc.protection</name>
<value>authentication</value>

</property>

And if it's different  set "hbase.rpc.protection" to be the same.

[Michael Sanders]

ManOLamancha,

I am no longer getting that error. I checked our core-site.xml and the setting for hadoop.rpc.protection was at privacy. In the opentsdb.conf file I put the following:

12:41:30.287 [AsyncHBase I/O Worker #2] DEBUG org.hbase.async.auth.Login - Already logged in

12:41:30.287 [AsyncHBase Timer HBaseClient #1-SendThread(URL.com:2181)] DEBUG org.apache.zookeeper.ClientCnxn - Session establishment request sent on URL.com/172.22.168.12:2181

12:41:30.288 [AsyncHBase I/O Worker #2] INFO  o.h.a.a.KerberosClientAuthProvider - Connecting to hbase/URL...@WD.URL.COM

12:41:30.288 [AsyncHBase Timer HBaseClient #1-SendThread(URL.com:2181)] DEBUG o.a.zookeeper.ClientCnxnSocketNIO - deferring non-priming packet: clientPath:null serverPath:null finished:false header:: 0,-11  replyHeader:: 0,0,0  request:: null response:: nulluntil SASL authentication completes.

12:41:30.288 [AsyncHBase I/O Worker #2] INFO  o.h.a.a.KerberosClientAuthProvider - Client will use GSSAPI as SASL mechanism.

12:41:30.288 [AsyncHBase I/O Worker #2] DEBUG o.h.a.a.KerberosClientAuthProvider - Creating sasl client: client=hb...@WD.URL.COM, service=hbase, serviceHostname=URL.com

12:41:30.288 [AsyncHBase Timer HBaseClient #1-SendThread(URL.com:2181)] DEBUG o.a.zookeeper.ClientCnxnSocketNIO - deferring non-priming packet: clientPath:null serverPath:null finished:false header:: 0,-11  replyHeader:: 0,0,0  request:: null response:: nulluntil SASL authentication completes.

12:41:30.289 [AsyncHBase Timer HBaseClient #1-SendThread(URL.com:2181)] DEBUG o.a.zookeeper.ClientCnxnSocketNIO - deferring non-priming packet: clientPath:null serverPath:null finished:false header:: 0,-11  replyHeader:: 0,0,0  request:: null response:: nulluntil SASL authentication completes.

12:41:30.289 [AsyncHBase Timer HBaseClient #1-SendThread(URL.com:2181)] DEBUG o.a.zookeeper.ClientCnxnSocketNIO - deferring non-priming packet: clientPath:null serverPath:null finished:false header:: 0,-11  replyHeader:: 0,0,0  request:: null response:: nulluntil SASL authentication completes.

12:41:30.289 [AsyncHBase Timer HBaseClient #1-SendThread(URL.com:2181)] INFO  org.apache.zookeeper.ClientCnxn - Session establishment complete on server URL.com/172.22.168.12:2181, sessionid = 0x252ae596a4b8a31, negotiated timeout = 5000

12:41:30.289 [AsyncHBase I/O Worker #2] DEBUG org.hbase.async.RegionClient - handleUpstream [id: 0x2d538a7e, /172.22.168.12:47396 => /172.22.168.39:60020] WRITTEN_AMOUNT: 6

12:41:30.290 [AsyncHBase Timer HBaseClient #1-EventThread] DEBUG org.hbase.async.HBaseClient - Got ZooKeeper event: WatchedEvent state:SyncConnected type:None path:null

12:43:56.043 [AsyncHBase Timer HBaseClient #1-SendThread(URL.com:2181)] DEBUG o.a.zookeeper.ClientCnxnSocketNIO - deferring non-priming packet: clientPath:null serverPath:null finished:false header:: 0,-11  replyHeader:: 0,0,0  request:: null response:: nulluntil SASL authentication completes.

12:43:56.043 [AsyncHBase I/O Worker #5] DEBUG org.hbase.async.RegionClient - handleUpstream [id: 0x2abf7782, /172.22.168.12:47983 => /172.22.168.39:60020] RECEIVED: BigEndianHeapChannelBuffer(ridx=0, widx=58, cap=58)

12:43:56.043 [AsyncHBase I/O Worker #5] DEBUG org.hbase.async.RegionClient - ------------------>> ENTERING DECODE >>------------------

12:43:56.044 [AsyncHBase Timer HBaseClient #1-SendThread(URL.com:2181)] DEBUG o.a.zookeeper.ClientCnxnSocketNIO - deferring non-priming packet: clientPath:null serverPath:null finished:false header:: 0,-11  replyHeader:: 0,0,0  request:: null response:: nulluntil SASL authentication completes.

12:43:56.044 [AsyncHBase Timer HBaseClient #1-SendThread(URL.com:2181)] DEBUG o.a.zookeeper.ClientCnxnSocketNIO - deferring non-priming packet: clientPath:null serverPath:null finished:false header:: 0,-11  replyHeader:: 0,0,0  request:: null response:: nulluntil SASL authentication completes.

12:43:56.044 [AsyncHBase Timer HBaseClient #1-SendThread(URL.com:2181)] DEBUG o.a.z.client.ZooKeeperSaslClient - saslClient.evaluateChallenge(len=50)

12:43:56.045 [AsyncHBase I/O Worker #5] DEBUG org.hbase.async.RegionClient - handleUpstream [id: 0x2abf7782, /172.22.168.12:47983 => /172.22.168.39:60020] WRITTEN_AMOUNT: 54

12:43:56.045 [AsyncHBase I/O Worker #5] INFO  org.hbase.async.SecureRpcHelper96 - SASL client context established. Negotiated QoP: auth-conf on for: RegionClient@2056015074(chan=null, #pending_rpcs=1, #batched=0, #rpcs_inflight=0)

12:43:56.045 [AsyncHBase Timer HBaseClient #1-SendThread(URL.com:2181)] DEBUG o.a.z.client.ZooKeeperSaslClient - ClientCnxn:sendSaslPacket:length=78

12:43:56.045 [AsyncHBase I/O Worker #5] DEBUG org.hbase.async.RegionClient - handleUpstream [id: 0x2abf7782, /172.22.168.12:47983 => /172.22.168.39:60020] WRITTEN_AMOUNT: 96

12:43:56.045 [AsyncHBase Timer HBaseClient #1-SendThread(URL.com:2181)] DEBUG o.a.zookeeper.ClientCnxnSocketNIO - deferring non-priming packet: clientPath:null serverPath:null finished:false header:: 0,-11  replyHeader:: 0,0,0  request:: null response:: nulluntil SASL authentication completes.

12:43:56.045 [AsyncHBase Timer HBaseClient #1-SendThread(URL.com:2181)] DEBUG o.a.zookeeper.ClientCnxnSocketNIO - deferring non-priming packet: clientPath:null serverPath:null finished:false header:: 0,-11  replyHeader:: 0,0,0  request:: null response:: nulluntil SASL authentication completes.

12:43:56.045 [AsyncHBase I/O Worker #5] DEBUG org.hbase.async.RegionClient - [id: 0x2abf7782, /172.22.168.12:47983 => /172.22.168.39:60020] Sending RPC #0, payload=BigEndianHeapChannelBuffer(ridx=12, widx=196, cap=196) [0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, -76, 9, 8, 0, 26, 3, 71, 101, 116, 32, 1, -88, 1, 10, 17, 8, 1, 18, 13, 104, 98, 97, 115, 101,

58, 109, 101, 116, 97, 44, 44, 49, 18, -110, 1, 10, -115, 1, 118, 105, 109, 115, 45, 116, 115, 100, 98, 44, 0, 0, 0, 0,

0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 58, 65, 115, 121, 110, 99, 72, 66, 97, 115, 101, 126, 112, 114, 111, 98, 101, 126, 60, 59, 95, 60, 44, 58, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 58, 65, 115, 121, 110, 99, 72, 66, 97, 115, 101, 126, 112, 114, 111, 98, 101, 126, 60, 59, 95, 60, 80, 1]

12:43:56.045 [AsyncHBase Timer HBaseClient #1-SendThread(URL.com:2181)] DEBUG o.a.zookeeper.ClientCnxnSocketNIO - deferring non-priming packet: clientPath:null serverPath:null finished:false header:: 0,-11  replyHeader:: 0,0,0  request:: null response:: nulluntil SASL authentication completes.

12:43:56.045 [AsyncHBase Timer HBaseClient #1-SendThread(URL.com:2181)] DEBUG o.a.zookeeper.ClientCnxnSocketNIO - deferring non-priming packet: clientPath:null serverPath:null finished:false header:: 0,-11  replyHeader:: 0,0,0  request:: null response:: nulluntil SASL authentication completes.

12:43:56.045 [AsyncHBase I/O Worker #5] DEBUG org.hbase.async.RegionClient - handleUpstream [id: 0x2abf7782, /172.22.168.12:47983 => /172.22.168.39:60020] EXCEPTION: java.lang.IndexOutOfBoundsException: Not enough readable bytes - Need 196, maximum is 184

12:43:56.046 [AsyncHBase Timer HBaseClient #1-SendThread(URL.com:2181)] DEBUG o.a.zookeeper.ClientCnxnSocketNIO - deferring non-priming packet: clientPath:null serverPath:null finished:false header:: 0,-11  replyHeader:: 0,0,0  request:: null response:: nulluntil SASL authentication completes.

12:43:56.046 [AsyncHBase Timer HBaseClient #1-SendThread(URL.com:2181)] DEBUG o.a.zookeeper.ClientCnxnSocketNIO - deferring non-priming packet: clientPath:null serverPath:null finished:false header:: 0,-11  replyHeader:: 0,0,0  request:: null response:: nulluntil SASL authentication completes.

12:43:56.046 [AsyncHBase Timer HBaseClient #1-SendThread(URL.com:2181)] DEBUG o.a.zookeeper.ClientCnxnSocketNIO - deferring non-priming packet: clientPath:null serverPath:null finished:false header:: 0,-11  replyHeader:: 0,0,0  request:: null response:: nulluntil SASL authentication completes.

 DEBUG org.hbase.async.RegionClient - handleUpstream [id: 0x2d538a7e, /172.22.168.12:47396 => /172.22.168.39:60020] RECEIVED: BigEndianHeapChannelBuffer(ridx=0, widx=58, cap=58)

12:43:52.046 [AsyncHBase I/O Worker #2] ERROR org.hbase.async.RegionClient - Unexpected exception from downstream on [id: 0xdabbfe38, /172.22.168.12:47971 => /172.22.168.39:60020]

java.lang.IndexOutOfBoundsException: Not enough readable bytes - Need 196, maximum is 184

        at org.jboss.netty.buffer.AbstractChannelBuffer.checkReadableBytes(AbstractChannelBuffer.java:668) ~[netty-3.9.4.Final.jar:na]

        at org.jboss.netty.buffer.AbstractChannelBuffer.readBytes(AbstractChannelBuffer.java:338) ~[netty-3.9.4.Final.jar:na]

        at org.jboss.netty.buffer.AbstractChannelBuffer.readBytes(AbstractChannelBuffer.java:344) ~[netty-3.9.4.Final.jar:na]

        at org.hbase.async.SecureRpcHelper.wrap(SecureRpcHelper.java:235) ~[asynchbase-1.7.1.jar:na]

        at org.hbase.async.RegionClient.encode(RegionClient.java:1368) ~[asynchbase-1.7.1.jar:na]

        at org.hbase.async.RegionClient.sendRpc(RegionClient.java:981) ~[asynchbase-1.7.1.jar:na]

        at org.hbase.async.RegionClient.sendQueuedRpcs(RegionClient.java:1124) ~[asynchbase-1.7.1.jar:na]

        at org.hbase.async.RegionClient.becomeReady(RegionClient.java:656) ~[asynchbase-1.7.1.jar:na]

        at org.hbase.async.SecureRpcHelper96.sendRPCHeader(SecureRpcHelper96.java:190) ~[asynchbase-1.7.1.jar:na]

        at org.hbase.async.SecureRpcHelper96.handleResponse(SecureRpcHelper96.java:148) ~[asynchbase-1.7.1.jar:na]

        at org.hbase.async.RegionClient.decode(RegionClient.java:1399) ~[asynchbase-1.7.1.jar:na]

        at org.hbase.async.RegionClient.decode(RegionClient.java:88) ~[asynchbase-1.7.1.jar:na]

        at org.jboss.netty.handler.codec.replay.ReplayingDecoder.callDecode(ReplayingDecoder.java:500) ~[netty-3.9.4.Final.jar:na]

        at org.jboss.netty.handler.codec.replay.ReplayingDecoder.messageReceived(ReplayingDecoder.java:435) ~[netty-3.9.4.Final.jar:na]

        at org.jboss.netty.channel.SimpleChannelUpstreamHandler.handleUpstream(SimpleChannelUpstreamHandler.java:70) [netty-3.9.4.Final.jar:na]

        at org.hbase.async.RegionClient.handleUpstream(RegionClient.java:1206) ~[asynchbase-1.7.1.jar:na]

        at org.jboss.netty.channel.DefaultChannelPipeline.sendUpstream(DefaultChannelPipeline.java:564) [netty-3.9.4.Final.jar:na]

        at org.jboss.netty.channel.DefaultChannelPipeline$DefaultChannelHandlerContext.sendUpstream(DefaultChannelPipeline.java:791) [netty-3.9.4.Final.jar:na]

        at org.jboss.netty.channel.SimpleChannelHandler.messageReceived(SimpleChannelHandler.java:142) [netty-3.9.4.Final.jar:na]

--

12:43:53.208 [AsyncHBase I/O Worker #3] ERROR org.hbase.async.RegionClient - Unexpected exception from downstream on [id: 0x642a0927, /172.22.168.12:47976 => /172.22.168.39:60020]

java.lang.IndexOutOfBoundsException: Not enough readable bytes - Need 196, maximum is 184

        at org.jboss.netty.buffer.AbstractChannelBuffer.checkReadableBytes(AbstractChannelBuffer.java:668) ~[netty-3.9.4.Final.jar:na]

        at org.jboss.netty.buffer.AbstractChannelBuffer.readBytes(AbstractChannelBuffer.java:338) ~[netty-3.9.4.Final.jar:na]

        at org.jboss.netty.buffer.AbstractChannelBuffer.readBytes(AbstractChannelBuffer.java:344) ~[netty-3.9.4.Final.jar:na]

        at org.hbase.async.SecureRpcHelper.wrap(SecureRpcHelper.java:235) ~[asynchbase-1.7.1.jar:na]

        at org.hbase.async.RegionClient.encode(RegionClient.java:1368) ~[asynchbase-1.7.1.jar:na]

        at org.hbase.async.RegionClient.sendRpc(RegionClient.java:981) ~[asynchbase-1.7.1.jar:na]

        at org.hbase.async.RegionClient.sendQueuedRpcs(RegionClient.java:1124) ~[asynchbase-1.7.1.jar:na]

        at org.hbase.async.RegionClient.becomeReady(RegionClient.java:656) ~[asynchbase-1.7.1.jar:na]

        at org.hbase.async.SecureRpcHelper96.sendRPCHeader(SecureRpcHelper96.java:190) ~[asynchbase-1.7.1.jar:na]

        at org.hbase.async.SecureRpcHelper96.handleResponse(SecureRpcHelper96.java:148) ~[asynchbase-1.7.1.jar:na]

        at org.hbase.async.RegionClient.decode(RegionClient.java:1399) ~[asynchbase-1.7.1.jar:na]

        at org.hbase.async.RegionClient.decode(RegionClient.java:88) ~[asynchbase-1.7.1.jar:na]

        at org.jboss.netty.handler.codec.replay.ReplayingDecoder.callDecode(ReplayingDecoder.java:500) ~[netty-3.9.4.Final.jar:na]

        at org.jboss.netty.handler.codec.replay.ReplayingDecoder.messageReceived(ReplayingDecoder.java:435) ~[netty-3.9.4.Final.jar:na]

        at org.jboss.netty.channel.SimpleChannelUpstreamHandler.handleUpstream(SimpleChannelUpstreamHandler.java:70) [netty-3.9.4.Final.jar:na]

        at org.hbase.async.RegionClient.handleUpstream(RegionClient.java:1206) ~[asynchbase-1.7.1.jar:na]

        at org.jboss.netty.channel.DefaultChannelPipeline.sendUpstream(DefaultChannelPipeline.java:564) [netty-3.9.4.Final.jar:na]

        at org.jboss.netty.channel.DefaultChannelPipeline$DefaultChannelHandlerContext.sendUpstream(DefaultChannelPipeline.java:791) [netty-3.9.4.Final.jar:na]

        at org.jboss.netty.channel.SimpleChannelHandler.messageReceived(SimpleChannelHandler.java:142) [netty-3.9.4.Final.jar:na]

Thanks,

[Michael Sanders]

In the core-site.xml the protection was set to

hadoop.rpc.protection=privacy

So in the opentsdb.conf I changed the setting to: 

hbase.rpc.protection=privacy.

[ManOLamancha]

On Saturday, February 27, 2016 at 12:30:30 PM UTC-8, Michael Sanders wrote:

12:43:56.046 [AsyncHBase Timer HBaseClient #1-SendThread(URL.com:2181)] DEBUG o.a.zookeeper.ClientCnxnSocketNIO - deferring non-priming packet: clientPath:null serverPath:null finished:false header:: 0,-11  replyHeader:: 0,0,0  request:: null response:: nulluntil SASL authentication completes.

 DEBUG org.hbase.async.RegionClient - handleUpstream [id: 0x2d538a7e, /172.22.168.12:47396 => /172.22.168.39:60020] RECEIVED: BigEndianHeapChannelBuffer(ridx=0, widx=58, cap=58)

12:43:52.046 [AsyncHBase I/O Worker #2] ERROR org.hbase.async.RegionClient - Unexpected exception from downstream on [id: 0xdabbfe38, /172.22.168.12:47971 => /172.22.168.39:60020]

java.lang.IndexOutOfBoundsException: Not enough readable bytes - Need 196, maximum is 184

Great, I'm glad that solved the issue. But do you keep seeing this error? If so there's something else going on with the SASL authentication.

[Michael Sanders]

Yeah, every time I try to start opentsdb it fails due to "RegionClient - Unexpected exception from downstream on" Do you know a good place to start looking? I had never developed any application that required SASL, we just upgraded to kerberos.

Thanks again,

[ManOLamancha]

On Saturday, February 27, 2016 at 5:32:36 PM UTC-8, Michael Sanders wrote:

Yeah, every time I try to start opentsdb it fails due to "RegionClient - Unexpected exception from downstream on" Do you know a good place to start looking? I had never developed any application that required SASL, we just upgraded to kerberos.

It could be a bug in the parsing code here: https://github.com/OpenTSDB/asynchbase/blob/master/src/SecureRpcHelper.java#L234  The channel buffer read/write index is a finicky thing. Are you able to tweak and compile the code a bit to see if you can get it to read the proper amount of data from the buffer? If not I could try messing around with a few jars for you to try.

[Muhammad Hammad Ali]

Hi Guys,

I face a similar kind of problem, I have setup opentsdb 2.2.0 version on hortonworks 2.3.2 cluster with Kerberos installed, I made the required settings for Kerberos and hadoop rpc, but i still face the error of downstream and it seems like error occurs when it tries to read the hbase:meta table, which exists already in hbase. I tried to find help but I could not find much about it. Would be great if anybody can guide in the proper way. I face the below error. Thanks in advance.

Its a bit old post now but lets try my luck :) I tried to setup opentsdb 2.2.0 service with hortonworks kerberized cluster, i tried the kerberos settings provided in this post but still it does not seem to work, i am not able to start opentsdb service as it always fails to read the hbase:meta table, which already exists in the hbase and then it gives downstream and broken pipe error in the end, does anybody faced similar issue with opentsdb. I face the below error, any help will be appreciated.

10:19:59.756 DEBUG [HBaseClient.handleDisconnect] - Channel [id: 0x301ad776]'s state changed: [id: 0x301ad776] CONNECT :16020
10:19:59.756 WARN [HBaseClient.call] - Probe Exists(table="hbase:meta", key=[100, 105, 115, 97, 103, 103, 114, 101, 103, 97, 116, 105, 111, 110, 46, 103, 101, 114, 109, 97, 110, 121, 44, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 58, 65, 115, 121, 110, 99, 72, 66, 97, 115, 101, 126, 112, 114, 111, 98, 101, 126, 60, 59, 95, 60, 44, 58, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 58, 65, 115, 121, 110, 99, 72, 66, 97, 115, 101, 126, 112, 114, 111, 98, 101, 126, 60, 59, 95, 60], family=null, qualifiers=null, attempt=0, region=RegionInfo(table="hbase:meta", region_name="hbase:meta,,1", stop_key="")) failed
org.hbase.async.NonRecoverableException: Too many attempts: Exists(table="hbase:meta", key=[100, 105, 115, 97, 103, 103, 114, 101, 103, 97, 116, 105, 111, 110, 46, 103, 101, 114, 109, 97, 110, 121, 44, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 58, 65, 115, 121, 110, 99, 72, 66, 97, 115, 101, 126, 112, 114, 111, 98, 101, 126, 60, 59, 95, 60, 44, 58, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 58, 65, 115, 121, 110, 99, 72, 66, 97, 115, 101, 126, 112, 114, 111, 98, 101, 126, 60, 59, 95, 60], family=null, qualifiers=null, attempt=11, region=RegionInfo(table="hbase:meta", region_name="hbase:meta,,1", stop_key=""))
at org.hbase.async.HBaseClient.tooManyAttempts(HBaseClient.java:2056) [asynchbase-1.7.1.jar:na]
at org.hbase.async.HBaseClient.sendRpcToRegion(HBaseClient.java:1920) [asynchbase-1.7.1.jar:na]
at org.hbase.async.HBaseClient$1RetryRpc.call(HBaseClient.java:1944) [asynchbase-1.7.1.jar:na]
at org.hbase.async.HBaseClient$1RetryRpc.call(HBaseClient.java:1927) [asynchbase-1.7.1.jar:na]
at com.stumbleupon.async.Deferred.doCall(Deferred.java:1278) [async-1.4.0.jar:na]
at com.stumbleupon.async.Deferred.runCallbacks(Deferred.java:1257) [async-1.4.0.jar:na]
at com.stumbleupon.async.Deferred.callback(Deferred.java:1005) [async-1.4.0.jar:na]
at org.hbase.async.HBaseClient$ZKClient$ZKCallback.processResult(HBaseClient.java:3632) [asynchbase-1.7.1.jar:na]
at org.apache.zookeeper.ClientCnxn$EventThread.processEvent(ClientCnxn.java:573) [zookeeper-3.4.6.2.3.4.0-3485.jar:3.4.6-3485--1]
at org.apache.zookeeper.ClientCnxn$EventThread.run(ClientCnxn.java:510) [zookeeper-3.4.6.2.3.4.0-3485.jar:3.4.6-3485--1]
10:19:59.756 DEBUG [HBaseClient.call] - Retrying 3 RPCs on NSREd region "hbase:meta,,1"
10:19:59.757 DEBUG [RegionClient.sendRpc] - RPC queued: HBaseRpc(method=getClosestRowBefore, table="hbase:meta", key="mytable,\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00:AsyncHBase~probe~<;<,:", region=RegionInfo(table="hbase:meta", region_name="hbase:meta,,1", stop_key=""), attempt=11, timeout=-1, hasTimedout=false)
10:19:59.757 DEBUG [RegionClient.sendRpc] - RPC queued: HBaseRpc(method=getClosestRowBefore, table="hbase:meta", key="mytable-uid,\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00:AsyncHBase~probe~<;<,:", region=RegionInfo(table="hbase:meta", region_name="hbase:meta,,1", stop_key=""), attempt=11, timeout=-1, hasTimedout=false)
10:19:59.757 INFO [ClientCnxn.primeConnection] - Socket connection established to :2181, initiating session
10:19:59.757 DEBUG [HBaseClient.disconnectZK] - Ignore any DEBUG exception from ZooKeeper
10:19:59.757 DEBUG [ClientCnxn.primeConnection] - Session establishment request sent on :2181
10:19:59.757 DEBUG [ZooKeeper.close] - Closing session: 0x0
10:19:59.757 DEBUG [ClientCnxn.close] - Closing client for session: 0x0
10:19:59.757 DEBUG [HBaseClient.handleDisconnect] - Channel [id: 0x301ad776, 
10:19:59.757 DEBUG [RegionClient.handleUpstream] - handleUpstream [id: 0x301ad776, 
10:19:59.757 DEBUG [HBaseClient.handleDisconnect] - Channel [id: 0x301ad776, CONNECTED: 
10:19:59.757 DEBUG [RegionClient.handleUpstream] - handleUpstream [id: 0x301ad776, 
10:19:59.757 DEBUG [Login.initUserIfNeeded] - Already logged in
10:19:59.758 INFO [KerberosClientAuthProvider.newSaslClient] - Connecting to hbase/no...@example.com
10:19:59.758 INFO [KerberosClientAuthProvider.run] - Client will use GSSAPI as SASL mechanism.
10:19:59.758 DEBUG [KerberosClientAuthProvider.run] - Creating sasl client: client=
10:19:59.758 DEBUG [RegionClient.handleUpstream] - handleUpstream [id: 0x301ad776, /10.66.48.100:53332 => /] WRITTEN_AMOUNT: 6
10:19:59.759 DEBUG [RegionClient.handleUpstream] - handleUpstream [id: 0x301ad776, /10.66.48.100:53332 => /10.66.48.102:16020] EXCEPTION: java.io.IOException: Broken pipe
10:19:59.760 ERROR [RegionClient.exceptionCaught] - Unexpected exception from downstream on 
java.io.IOException: Broken pipe

Regards,

Hammad

[ManOLamancha]

On Sunday, July 3, 2016 at 7:26:06 AM UTC-7, Muhammad Hammad Ali wrote:

10:19:59.757 DEBUG [HBaseClient.handleDisconnect] - Channel [id: 0x301ad776, CONNECTED: 
10:19:59.757 DEBUG [RegionClient.handleUpstream] - handleUpstream [id: 0x301ad776, 
10:19:59.757 DEBUG [Login.initUserIfNeeded] - Already logged in
10:19:59.758 INFO [KerberosClientAuthProvider.newSaslClient] - Connecting to hbase/no...@example.com
10:19:59.758 INFO [KerberosClientAuthProvider.run] - Client will use GSSAPI as SASL mechanism.
10:19:59.758 DEBUG [KerberosClientAuthProvider.run] - Creating sasl client: client=
10:19:59.758 DEBUG [RegionClient.handleUpstream] - handleUpstream [id: 0x301ad776, /10.66.48.100:53332 => /] WRITTEN_AMOUNT: 6
10:19:59.759 DEBUG [RegionClient.handleUpstream] - handleUpstream [id: 0x301ad776, /10.66.48.100:53332 => /10.66.48.102:16020] EXCEPTION: java.io.IOException: Broken pipe
10:19:59.760 ERROR [RegionClient.exceptionCaught] - Unexpected exception from downstream on 
java.io.IOException: Broken pipe

Hmm, what user are you running the TSDB under? Is i the same user as your Kerberos config? That could potentially be part of it. And if anyone has a Kerberos configured VM image or Docker image or something I could play with I'd be happy to try out some debugging. 

[sagonfor7]

Did these issues get tracked down to root cause/solved?

I'm using OpenTSDB 2.3 against a Kerberized CDH 5.9 cluster and I see something similar - 

14:48:55.541 INFO  [SecureRpcHelper96.handleResponse] - SASL client context established. Negotiated QoP: auth-conf on for: RegionClient@662104194(chan=null, #pending_rpcs=1, #batched=0, #rpcs_inflight=0)

14:48:55.543 ERROR [RegionClient.exceptionCaught] - Unexpected exception from downstream on [id: 0x6c24ad29, /10.0.1.53:43986 => /10.0.1.67:60020]

java.lang.IndexOutOfBoundsException: Not enough readable bytes - Need 191, maximum is 179

[sagonfor7]

I looked into this, having the same problem, and came to the same conclusion - I've posted my findings on the GitHub. The change I made was to use readableBytes for the array dimension, which then keeps netty happy.

That makes the SASL stuff work and things progress much further. However, I run into the same problem others are reporting later on with respect to "Broken Pipe" exceptions. 

I'm happy to contribute code here to make this work but I'd like to know where I'm starting from - does this work against any Kerberized Hadoop cluster and if so, which one?

/s7

[ManOLamancha]

On Sunday, January 29, 2017 at 1:22:20 PM UTC-8, sagonfor7 wrote:

I looked into this, having the same problem, and came to the same conclusion - I've posted my findings on the GitHub. The change I made was to use readableBytes for the array dimension, which then keeps netty happy.

That makes the SASL stuff work and things progress much further. However, I run into the same problem others are reporting later on with respect to "Broken Pipe" exceptions. 

I'm happy to contribute code here to make this work but I'd like to know where I'm starting from - does this work against any Kerberized Hadoop cluster and if so, which one?

Thanks for looking at it. I commented on the issue and would love to have your patch. We haven't tested it against an encrypted HBase cluster, just Kerberos authentication gated cluster, so we definitely need some work there.