Unable to connect to apache phoenix remotely using squirrel

[#1]

Dear community,

I am experiencing problems when connecting to phoenix using squirrel client. The problem comes when I am connecting remotely. Local connection works good.

Client throws exception:

java.util.concurrent.TimeoutException
at java.util.concurrent.FutureTask.get(FutureTask.java:201)
at net.sourceforge.squirrel_sql.client.mainframe.action.OpenConnectionCommand.awaitConnection(OpenConnectionCommand.java:132)
at net.sourceforge.squirrel_sql.client.mainframe.action.OpenConnectionCommand.access$100(OpenConnectionCommand.java:45)
at net.sourceforge.squirrel_sql.client.mainframe.action.OpenConnectionCommand$2.run(OpenConnectionCommand.java:115)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
at java.util.concurrent.FutureTask.run(FutureTask.java:262)
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)

Zookeeper log:

2016-12-22 23:48:32,854 INFO org.apache.zookeeper.server.NIOServerCnxnFactory: Accepted socket connection from /192.168.56.2:16551
2016-12-22 23:48:32,859 INFO org.apache.zookeeper.server.ZooKeeperServer: Client attempting to establish new session at /192.168.56.2:16551
2016-12-22 23:48:32,861 INFO org.apache.zookeeper.server.ZooKeeperServer: Established session 0x159287d6c210110 with negotiated timeout 60000 for client /192.168.56.2:16551
2016-12-22 23:50:19,131 INFO org.apache.zookeeper.server.NIOServerCnxn: Closed socket connection for client /192.168.56.2:16551 which had sessionid 0x159287d6c210110
2016-12-22 23:50:38,959 INFO org.apache.zookeeper.server.NIOServerCnxnFactory: Accepted socket connection from /192.168.56.2:16560
2016-12-22 23:50:38,968 INFO org.apache.zookeeper.server.ZooKeeperServer: Client attempting to establish new session at /192.168.56.2:16560
2016-12-22 23:50:38,973 INFO org.apache.zookeeper.server.ZooKeeperServer: Established session 0x159287d6c210119 with negotiated timeout 60000 for client /192.168.56.2:16560
2016-12-22 23:55:52,641 INFO org.apache.zookeeper.server.NIOServerCnxnFactory: Accepted socket connection from /192.168.56.2:16640
2016-12-22 23:55:53,683 INFO org.apache.zookeeper.server.NIOServerCnxn: Closed socket connection for client /192.168.56.2:16640 (no session established for client)
2016-12-22 23:59:37,436 INFO org.apache.zookeeper.server.NIOServerCnxnFactory: Accepted socket connection from /192.168.56.2:16696
2016-12-22 23:59:37,438 INFO org.apache.zookeeper.server.ZooKeeperServer: Client attempting to renew session 0x159287d6c210119 at /192.168.56.2:16696
2016-12-22 23:59:37,440 INFO org.apache.zookeeper.server.ZooKeeperServer: Established session 0x159287d6c210119 with negotiated timeout 60000 for client /192.168.56.2:16696
2016-12-23 00:02:46,660 INFO org.apache.zookeeper.server.NIOServerCnxnFactory: Accepted socket connection from /192.168.56.2:16768
2016-12-23 00:02:46,661 INFO org.apache.zookeeper.server.ZooKeeperServer: Client attempting to establish new session at /192.168.56.2:16768
2016-12-23 00:02:46,666 INFO org.apache.zookeeper.server.ZooKeeperServer: Established session 0x15928c2dfb30012 with negotiated timeout 60000 for client /192.168.56.2:16768
2016-12-23 00:04:57,929 INFO org.apache.zookeeper.server.NIOServerCnxn: Closed socket connection for client /192.168.56.2:16696 which had sessionid 0x159287d6c210119
2016-12-23 00:04:57,930 INFO org.apache.zookeeper.server.NIOServerCnxn: Closed socket connection for client /192.168.56.2:16768 which had sessionid 0x15928c2dfb30012
2016-12-24 08:22:45,304 INFO org.apache.zookeeper.server.NIOServerCnxnFactory: Accepted socket connection from /192.168.56.2:2933
2016-12-24 08:22:45,314 INFO org.apache.zookeeper.server.ZooKeeperServer: Client attempting to establish new session at /192.168.56.2:2933
2016-12-24 08:22:45,318 INFO org.apache.zookeeper.server.ZooKeeperServer: Established session 0x15928c2dfb30086 with negotiated timeout 60000 for client /192.168.56.2:2933

I am using following connection string:

jdbc:phoenix:192.168.56.102:2181:/hbase

The port 2181 on 192.168.56.102 is accessible via telnet.

[#2]

I would guess the problem does not lie in your client and ZooKeeper, but your client and HBase. Remember that one use of ZooKeeper is for discovering HBase servers.

I would verify that the service ports for HBase (e.g. 16000, 16020) are bound to an external network interface (*not* lo or 127.0.0.1) using netstat and that you can connect to these ports remotely using telnet as you did. 16000 is the RPC port for the Master and 16020 is the RPC for the RegionServer.

Another option to get more debug information is to increase the log verbosity to DEBUG via log4j in your client for the org.apache.hadoop.hbase and org.apache.phoenix packages. This should give you more information about what actions the client is taking and why they are failing.

[#3]

Thanks for fast reply.

Hbase ports are binded to host interface and can be reached via telnet from other machines in network.

I`ve increased log verbosity to DEBUG of hbase and phoenix, but receive almost the same as before:

2016-12-25 09:19:08,001 INFO  [SessionTracker] server.ZooKeeperServer: Expiring session 0x159350a18720009, timeout of 40000ms exceeded
2016-12-25 09:19:08,002 INFO  [ProcessThread(sid:0 cport:-1):] server.PrepRequestProcessor: Processed session termination for sessionid: 0x159350a18720009
2016-12-25 09:19:13,549 INFO  [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181] server.NIOServerCnxnFactory: Accepted socket connection from /192.168.56.2:5916
2016-12-25 09:19:13,558 INFO  [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181] server.ZooKeeperServer: Client attempting to establish new session at /192.168.56.2:5916
2016-12-25 09:19:13,562 INFO  [SyncThread:0] server.ZooKeeperServer: Established session 0x159350f38570009 with negotiated timeout 40000 for client /192.168.56.2:5916
2016-12-25 09:19:31,985 DEBUG [ubuntu-dev,45751,1482653908596_ChoreService_1] master.ReplicationLogCleaner: Didn't find this log in ZK, deleting: ubuntu-dev%2C37691%2C1482653082873.default.1482653085286
2016-12-25 09:19:31,985 DEBUG [ubuntu-dev,45751,1482653908596_ChoreService_1] master.ReplicationLogCleaner: Didn't find this log in ZK, deleting: ubuntu-dev%2C45415%2C1482653262902..meta.1482653269511.meta
2016-12-25 09:19:31,986 DEBUG [ubuntu-dev,45751,1482653908596_ChoreService_1] master.ReplicationLogCleaner: Didn't find this log in ZK, deleting: ubuntu-dev%2C37691%2C1482653082873..meta.1482653089699.meta
2016-12-25 09:19:31,986 DEBUG [ubuntu-dev,45751,1482653908596_ChoreService_1] master.ReplicationLogCleaner: Didn't find this log in ZK, deleting: ubuntu-dev%2C44016%2C1482653169692..meta.1482653176455.meta
2016-12-25 09:19:31,986 DEBUG [ubuntu-dev,45751,1482653908596_ChoreService_1] master.ReplicationLogCleaner: Didn't find this log in ZK, deleting: ubuntu-dev%2C45415%2C1482653262902.default.1482653265020
2016-12-25 09:19:31,986 DEBUG [ubuntu-dev,45751,1482653908596_ChoreService_1] master.ReplicationLogCleaner: Didn't find this log in ZK, deleting: ubuntu-dev%2C44016%2C1482653169692.default.1482653172062
2016-12-25 09:19:31,988 DEBUG [ubuntu-dev,45751,1482653908596_ChoreService_1] cleaner.CleanerChore: Removing: file:/opt/hbase/hbase-1.2.4/data/oldWALs/ubuntu-dev%2C37691%2C1482653082873.default.1482653085286 from archive
2016-12-25 09:19:31,988 DEBUG [ubuntu-dev,45751,1482653908596_ChoreService_1] cleaner.CleanerChore: Removing: file:/opt/hbase/hbase-1.2.4/data/oldWALs/ubuntu-dev%2C45415%2C1482653262902..meta.1482653269511.meta from archive
2016-12-25 09:19:31,989 DEBUG [ubuntu-dev,45751,1482653908596_ChoreService_1] cleaner.CleanerChore: Removing: file:/opt/hbase/hbase-1.2.4/data/oldWALs/ubuntu-dev%2C37691%2C1482653082873..meta.1482653089699.meta from archive
2016-12-25 09:19:31,990 DEBUG [ubuntu-dev,45751,1482653908596_ChoreService_1] cleaner.CleanerChore: Removing: file:/opt/hbase/hbase-1.2.4/data/oldWALs/ubuntu-dev%2C44016%2C1482653169692..meta.1482653176455.meta from archive
2016-12-25 09:19:31,991 DEBUG [ubuntu-dev,45751,1482653908596_ChoreService_1] cleaner.CleanerChore: Removing: file:/opt/hbase/hbase-1.2.4/data/oldWALs/ubuntu-dev%2C45415%2C1482653262902.default.1482653265020 from archive
2016-12-25 09:19:31,997 DEBUG [ubuntu-dev,45751,1482653908596_ChoreService_1] cleaner.CleanerChore: Removing: file:/opt/hbase/hbase-1.2.4/data/oldWALs/ubuntu-dev%2C44016%2C1482653169692.default.1482653172062 from archive
2016-12-25 09:19:32,028 DEBUG [ubuntu-dev,45751,1482653908596_ChoreService_1] cleaner.CleanerChore: Removing: file:/opt/hbase/hbase-1.2.4/data/archive/data/hbase/meta/1588230740/info/c4846c81d545457da46dd0e5a648fba4 from archive
2016-12-25 09:19:32,029 DEBUG [ubuntu-dev,45751,1482653908596_ChoreService_1] cleaner.CleanerChore: Removing: file:/opt/hbase/hbase-1.2.4/data/archive/data/hbase/meta/1588230740/info/53cc0a8971704b799d887e79118d36dc from archive
2016-12-25 09:19:32,030 DEBUG [ubuntu-dev,45751,1482653908596_ChoreService_1] cleaner.CleanerChore: Removing: file:/opt/hbase/hbase-1.2.4/data/archive/data/hbase/meta/1588230740/info/e3e3cd0fa27b43aa8f68292dd94963d8 from archive

[#4]

Did you inspect the extra logging at the client side? It looks like you have only copied the HBase master server logs.

Also, what ports did you verify via telnet?

[#5]

Checked hostname resolve. Hostname resolves to host ip.

[#6 · Accepted solution]

Solution found. When hbase is started in standalone(non-distributed) mode zookeeper takes hostname as hbase master and places it in /hbase/master. This value is returned to remote host when it tries to connect. If hostname is not resolved from remote host, then connection fails.

[#7]

So I guess you didn't have hostname resolution set up correctly as you said below? 🙂

But in general, yes, all host advertisements done by HBase are done using hostnames and not IP addresses. This is essentially a prerequisite to get Kerberos authentication working.