I'm having some trouble with the 3.4.4 Java client on Linux (openjdk 6
or 7, debian or ubuntu). It doesn't seem to successfully connect to a
server -- this goes for zkCli as well as custom code that uses the
client jar. On OSX, it *does* connect.
I've collected the DEBUG-level log output for the process of
connecting to my development Zookeeper node (also running 3.4.4),
waiting until a Connected event arrives, and sending getChildren("/").
The Linux version logs that it will not use SASL and then keeps
deferring the getChildren request "until SASL authentication
completes". The exact same (fat) jar running on OSX complains a few
times about being "unable to locate a login configuration" but doesn't
wait.
Using the 3.4.3 client library or earlier does successfully connect,
logging only the one message about JAAS that was changed as a result
of ZOOKEEPER-1510.
On Linux, the output of the 3.4.4 client is:
INFO [main] 2012-09-25 14:02:24,521 org.apache.zookeeper.ZooKeeper Client
environment:zookeeper.version=3.4.4-1386507, built on 09/17/2012 08:33 GMT
INFO [main] 2012-09-25 14:02:24,521 org.apache.zookeeper.ZooKeeper Client
environment:host.name=robert.corp.socrata.com
INFO [main] 2012-09-25 14:02:24,521 org.apache.zookeeper.ZooKeeper Client
environment:java.version=1.6.0_24
INFO [main] 2012-09-25 14:02:24,521 org.apache.zookeeper.ZooKeeper Client
environment:java.vendor=Sun Microsystems Inc.
INFO [main] 2012-09-25 14:02:24,521 org.apache.zookeeper.ZooKeeper Client
environment:java.home=/usr/lib/jvm/java-6-openjdk-amd64/jre
INFO [main] 2012-09-25 14:02:24,521 org.apache.zookeeper.ZooKeeper Client
environment:java.class.path=socrata-zookeeper-assembly-0.0.1.jar
INFO [main] 2012-09-25 14:02:24,522 org.apache.zookeeper.ZooKeeper Client
environment:java.library.path=/usr/lib/jvm/java-6-openjdk-amd64/jre/lib/amd64/server:/usr/lib/jvm/java-6-openjdk-amd64/jre/lib/amd64:/usr/lib/jvm/java-6-openjdk-amd64/jre/../lib/amd64:/usr/java/packages/lib/amd64:/usr/lib/x86_64-linux-gnu/jni:/lib/x86_64-linux-gnu:/usr/lib/x86_64-linux-gnu:/usr/lib/jni:/lib:/usr/lib
INFO [main] 2012-09-25 14:02:24,522 org.apache.zookeeper.ZooKeeper Client
environment:java.io.tmpdir=/tmp
INFO [main] 2012-09-25 14:02:24,522 org.apache.zookeeper.ZooKeeper Client
environment:java.compiler=<NA>
INFO [main] 2012-09-25 14:02:24,522 org.apache.zookeeper.ZooKeeper Client
environment:os.name=Linux
INFO [main] 2012-09-25 14:02:24,522 org.apache.zookeeper.ZooKeeper Client
environment:os.arch=amd64
INFO [main] 2012-09-25 14:02:24,522 org.apache.zookeeper.ZooKeeper Client
environment:os.version=3.2.0-3-amd64
INFO [main] 2012-09-25 14:02:24,522 org.apache.zookeeper.ZooKeeper Client
environment:user.name=robertm
INFO [main] 2012-09-25 14:02:24,522 org.apache.zookeeper.ZooKeeper Client
environment:user.home=/home/robertm
INFO [main] 2012-09-25 14:02:24,522 org.apache.zookeeper.ZooKeeper Client
environment:user.dir=/home/robertm/socrata/jvm/socrata-zookeeper
INFO [main] 2012-09-25 14:02:24,523 org.apache.zookeeper.ZooKeeper Initiating
client connection, connectString=10.0.2.106:2181 sessionTimeout=40000
watcher=com.socrata.zookeeper.ZooKeeperProvider$ZKWatcher@165973ea
DEBUG [main] 2012-09-25 14:02:24,527 org.apache.zookeeper.ClientCnxn
zookeeper.disableAutoWatchReset is false
INFO [main] 2012-09-25 14:02:24,545 com.socrata.Main Waiting for connection...
DEBUG [main] 2012-09-25 14:02:24,548 com.socrata.zookeeper.ZooKeeperProvider
Waiting for connected-state...
INFO [main-SendThread(mike.local:2181)] 2012-09-25 14:02:24,576
org.apache.zookeeper.ClientCnxn Opening socket connection to server
mike.local/10.0.2.106:2181. Will not attempt to authenticate using SASL
(unknown error)
INFO [main-SendThread(mike.local:2181)] 2012-09-25 14:02:24,584
org.apache.zookeeper.ClientCnxn Socket connection established to
mike.local/10.0.2.106:2181, initiating session
DEBUG [main-SendThread(mike.local:2181)] 2012-09-25 14:02:24,586
org.apache.zookeeper.ClientCnxn Session establishment request sent on
mike.local/10.0.2.106:2181
INFO [main-SendThread(mike.local:2181)] 2012-09-25 14:02:24,600
org.apache.zookeeper.ClientCnxn Session establishment complete on server
mike.local/10.0.2.106:2181, sessionid = 0x139ff2e85b60005, negotiated timeout =
40000
DEBUG [main-EventThread] 2012-09-25 14:02:24,614
com.socrata.zookeeper.ZooKeeperProvider ConnectionStateChanged(Connected)
DEBUG [main-SendThread(mike.local:2181)] 2012-09-25 14:02:24,636
org.apache.zookeeper.ClientCnxnSocketNIO deferring non-priming packet:
clientPath:/ serverPath:/ finished:false header:: 0,12 replyHeader:: 0,0,0
request:: '/,F response:: v{} until SASL authentication completes.
DEBUG [main-SendThread(mike.local:2181)] 2012-09-25 14:02:37,923
org.apache.zookeeper.ClientCnxnSocketNIO deferring non-priming packet:
clientPath:/ serverPath:/ finished:false header:: 0,12 replyHeader:: 0,0,0
request:: '/,F response:: v{} until SASL authentication completes.
DEBUG [main-SendThread(mike.local:2181)] 2012-09-25 14:02:37,924
org.apache.zookeeper.ClientCnxnSocketNIO deferring non-priming packet:
clientPath:/ serverPath:/ finished:false header:: 0,12 replyHeader:: 0,0,0
request:: '/,F response:: v{} until SASL authentication completes.
DEBUG [main-SendThread(mike.local:2181)] 2012-09-25 14:02:37,924
org.apache.zookeeper.ClientCnxnSocketNIO deferring non-priming packet:
clientPath:null serverPath:null finished:false header:: -2,11 replyHeader::
null request:: null response:: nulluntil SASL authentication completes.
DEBUG [main-SendThread(mike.local:2181)] 2012-09-25 14:02:51,260
org.apache.zookeeper.ClientCnxnSocketNIO deferring non-priming packet:
clientPath:/ serverPath:/ finished:false header:: 0,12 replyHeader:: 0,0,0
request:: '/,F response:: v{} until SASL authentication completes.
DEBUG [main-SendThread(mike.local:2181)] 2012-09-25 14:02:51,260
org.apache.zookeeper.ClientCnxnSocketNIO deferring non-priming packet:
clientPath:null serverPath:null finished:false header:: -2,11 replyHeader::
null request:: null response:: nulluntil SASL authentication completes.
DEBUG [main-SendThread(mike.local:2181)] 2012-09-25 14:02:51,261
org.apache.zookeeper.ClientCnxnSocketNIO deferring non-priming packet:
clientPath:/ serverPath:/ finished:false header:: 0,12 replyHeader:: 0,0,0
request:: '/,F response:: v{} until SASL authentication completes.
DEBUG [main-SendThread(mike.local:2181)] 2012-09-25 14:02:51,261
org.apache.zookeeper.ClientCnxnSocketNIO deferring non-priming packet:
clientPath:null serverPath:null finished:false header:: -2,11 replyHeader::
null request:: null response:: nulluntil SASL authentication completes.
DEBUG [main-SendThread(mike.local:2181)] 2012-09-25 14:02:51,261
org.apache.zookeeper.ClientCnxnSocketNIO deferring non-priming packet:
clientPath:null serverPath:null finished:false header:: -2,11 replyHeader::
null request:: null response:: nulluntil SASL authentication completes.
DEBUG [main-SendThread(mike.local:2181)] 2012-09-25 14:02:51,265
org.apache.zookeeper.ClientCnxnSocketNIO deferring non-priming packet:
clientPath:/ serverPath:/ finished:false header:: 0,12 replyHeader:: 0,0,0
request:: '/,F response:: v{} until SASL authentication completes.
DEBUG [main-SendThread(mike.local:2181)] 2012-09-25 14:02:51,265
org.apache.zookeeper.ClientCnxnSocketNIO deferring non-priming packet:
clientPath:null serverPath:null finished:false header:: -2,11 replyHeader::
null request:: null response:: nulluntil SASL authentication completes.
DEBUG [main-SendThread(mike.local:2181)] 2012-09-25 14:02:51,266
org.apache.zookeeper.ClientCnxnSocketNIO deferring non-priming packet:
clientPath:null serverPath:null finished:false header:: -2,11 replyHeader::
null request:: null response:: nulluntil SASL authentication completes.
INFO [main-SendThread(mike.local:2181)] 2012-09-25 14:02:51,266
org.apache.zookeeper.ClientCnxn Client session timed out, have not heard from
server in 26668ms for sessionid 0x139ff2e85b60005, closing socket connection
and attempting reconnect
DEBUG [main-EventThread] 2012-09-25 14:02:51,377
com.socrata.zookeeper.ZooKeeperProvider ConnectionStateChanged(Disconnected)
ConnectionLost
On OSX, here is the output:
INFO [main] 2012-09-25 14:03:16,286 org.apache.zookeeper.ZooKeeper Client
environment:zookeeper.version=3.4.4-1386507, built on 09/17/2012 08:33 GMT
INFO [main] 2012-09-25 14:03:16,287 org.apache.zookeeper.ZooKeeper Client
environment:host.name=hydra.engr.corp.socrata.com
INFO [main] 2012-09-25 14:03:16,288 org.apache.zookeeper.ZooKeeper Client
environment:java.version=1.6.0_35
INFO [main] 2012-09-25 14:03:16,288 org.apache.zookeeper.ZooKeeper Client
environment:java.vendor=Apple Inc.
INFO [main] 2012-09-25 14:03:16,288 org.apache.zookeeper.ZooKeeper Client
environment:java.home=/System/Library/Java/JavaVirtualMachines/1.6.0.jdk/Contents/Home
INFO [main] 2012-09-25 14:03:16,288 org.apache.zookeeper.ZooKeeper Client
environment:java.class.path=socrata-zookeeper-assembly-0.0.1.jar
INFO [main] 2012-09-25 14:03:16,288 org.apache.zookeeper.ZooKeeper Client
environment:java.library.path=.:/Library/Java/Extensions:/System/Library/Java/Extensions:/usr/lib/java
INFO [main] 2012-09-25 14:03:16,288 org.apache.zookeeper.ZooKeeper Client
environment:java.io.tmpdir=/var/folders/zh/884zqwg14033gkv3bm2ylb6h0000gn/T/
INFO [main] 2012-09-25 14:03:16,288 org.apache.zookeeper.ZooKeeper Client
environment:java.compiler=<NA>
INFO [main] 2012-09-25 14:03:16,288 org.apache.zookeeper.ZooKeeper Client
environment:os.name=Mac OS X
INFO [main] 2012-09-25 14:03:16,288 org.apache.zookeeper.ZooKeeper Client
environment:os.arch=x86_64
INFO [main] 2012-09-25 14:03:16,288 org.apache.zookeeper.ZooKeeper Client
environment:os.version=10.7.4
INFO [main] 2012-09-25 14:03:16,288 org.apache.zookeeper.ZooKeeper Client
environment:user.name=paradise
INFO [main] 2012-09-25 14:03:16,288 org.apache.zookeeper.ZooKeeper Client
environment:user.home=/Users/paradise
INFO [main] 2012-09-25 14:03:16,288 org.apache.zookeeper.ZooKeeper Client
environment:user.dir=/Users/paradise/tmp
INFO [main] 2012-09-25 14:03:16,289 org.apache.zookeeper.ZooKeeper Initiating
client connection, connectString=10.0.2.106:2181 sessionTimeout=40000
watcher=com.socrata.zookeeper.ZooKeeperProvider$ZKWatcher@5e785d65
DEBUG [main] 2012-09-25 14:03:16,293 org.apache.zookeeper.ClientCnxn
zookeeper.disableAutoWatchReset is false
INFO [main] 2012-09-25 14:03:16,315 com.socrata.Main Waiting for connection...
DEBUG [main] 2012-09-25 14:03:16,319 com.socrata.zookeeper.ZooKeeperProvider
Waiting for connected-state...
INFO [main-SendThread(10.0.2.106:2181)] 2012-09-25 14:03:16,335
org.apache.zookeeper.ClientCnxn Opening socket connection to server
10.0.2.106/10.0.2.106:2181. Will not attempt to authenticate using SASL (Unable
to locate a login configuration)
INFO [main-SendThread(10.0.2.106:2181)] 2012-09-25 14:03:16,344
org.apache.zookeeper.ClientCnxn Socket connection established to
10.0.2.106/10.0.2.106:2181, initiating session
DEBUG [main-SendThread(10.0.2.106:2181)] 2012-09-25 14:03:16,346
org.apache.zookeeper.ClientCnxn Session establishment request sent on
10.0.2.106/10.0.2.106:2181
DEBUG [main-SendThread(10.0.2.106:2181)] 2012-09-25 14:03:16,347
org.apache.zookeeper.client.ZooKeeperSaslClient Could not retrieve login
configuration: java.lang.SecurityException: Unable to locate a login
configuration
DEBUG [main-SendThread(10.0.2.106:2181)] 2012-09-25 14:03:16,351
org.apache.zookeeper.client.ZooKeeperSaslClient Could not retrieve login
configuration: java.lang.SecurityException: Unable to locate a login
configuration
INFO [main-SendThread(10.0.2.106:2181)] 2012-09-25 14:03:16,368
org.apache.zookeeper.ClientCnxn Session establishment complete on server
10.0.2.106/10.0.2.106:2181, sessionid = 0x139ff2e85b60006, negotiated timeout =
40000
DEBUG [main-SendThread(10.0.2.106:2181)] 2012-09-25 14:03:16,371
org.apache.zookeeper.client.ZooKeeperSaslClient Could not retrieve login
configuration: java.lang.SecurityException: Unable to locate a login
configuration
DEBUG [main-SendThread(10.0.2.106:2181)] 2012-09-25 14:03:16,371
org.apache.zookeeper.client.ZooKeeperSaslClient Could not retrieve login
configuration: java.lang.SecurityException: Unable to locate a login
configuration
DEBUG [main-EventThread] 2012-09-25 14:03:16,385
com.socrata.zookeeper.ZooKeeperProvider ConnectionStateChanged(Connected)
DEBUG [main-SendThread(10.0.2.106:2181)] 2012-09-25 14:03:16,417
org.apache.zookeeper.client.ZooKeeperSaslClient Could not retrieve login
configuration: java.lang.SecurityException: Unable to locate a login
configuration
DEBUG [main-SendThread(10.0.2.106:2181)] 2012-09-25 14:03:16,417
org.apache.zookeeper.client.ZooKeeperSaslClient Could not retrieve login
configuration: java.lang.SecurityException: Unable to locate a login
configuration
DEBUG [main-SendThread(10.0.2.106:2181)] 2012-09-25 14:03:16,417
org.apache.zookeeper.client.ZooKeeperSaslClient Could not retrieve login
configuration: java.lang.SecurityException: Unable to locate a login
configuration
DEBUG [main-SendThread(10.0.2.106:2181)] 2012-09-25 14:03:16,418
org.apache.zookeeper.client.ZooKeeperSaslClient Could not retrieve login
configuration: java.lang.SecurityException: Unable to locate a login
configuration
DEBUG [main-SendThread(10.0.2.106:2181)] 2012-09-25 14:03:16,418
org.apache.zookeeper.client.ZooKeeperSaslClient Could not retrieve login
configuration: java.lang.SecurityException: Unable to locate a login
configuration
DEBUG [main-SendThread(10.0.2.106:2181)] 2012-09-25 14:03:16,431
org.apache.zookeeper.client.ZooKeeperSaslClient Could not retrieve login
configuration: java.lang.SecurityException: Unable to locate a login
configuration
DEBUG [main-SendThread(10.0.2.106:2181)] 2012-09-25 14:03:16,438
org.apache.zookeeper.client.ZooKeeperSaslClient Could not retrieve login
configuration: java.lang.SecurityException: Unable to locate a login
configuration
DEBUG [main-SendThread(10.0.2.106:2181)] 2012-09-25 14:03:16,443
org.apache.zookeeper.ClientCnxn Reading reply sessionid:0x139ff2e85b60006,
packet:: clientPath:/ serverPath:/ finished:false header:: 1,12 replyHeader::
1,8292982,0 request:: '/,F response::
v{'ro,'row-index,'zkbtest,'consumers,'reindex,'hotstandby,'bigdir,'vs,'orestes,'eurybates,'shardedcly,'row-locks,'id-counter,'zookeeper,'cly,'locks,'rwlocks,'tickets,'brokers},s{0,0,0,0,0,61,0,0,0,19,8292893}
DEBUG [main-SendThread(10.0.2.106:2181)] 2012-09-25 14:03:16,444
org.apache.zookeeper.client.ZooKeeperSaslClient Could not retrieve login
configuration: java.lang.SecurityException: Unable to locate a login
configuration
OK(Set(cly, row-locks, hotstandby, locks, tickets, bigdir, zkbtest, row-index,
reindex, id-counter, eurybates, vs, rwlocks, shardedcly, brokers, consumers,
zookeeper, orestes, ro),0,0,0,0,0,61,0,0,0,19,8292893)
The server only logs this:
2012-09-25 14:02:29,671 [myid:] - INFO
[NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxnFactory@197] - Accepted
socket connection from /10.0.2.107:39645
2012-09-25 14:02:29,675 [myid:] - INFO
[NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:ZooKeeperServer@839] - Client
attempting to establish new session at /10.0.2.107:39645
2012-09-25 14:02:29,685 [myid:] - INFO [SyncThread:0:ZooKeeperServer@595] -
Established session 0x139ff2e85b60005 with negotiated timeout 40000 for client
/10.0.2.107:39645
2012-09-25 14:02:56,354 [myid:] - WARN
[NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@349] - caught end of
stream exception
EndOfStreamException: Unable to read additional data from client sessionid
0x139ff2e85b60005, likely client has closed socket
