zookeeper-user mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Robert Macomber <xbz...@rojoma.com>
Subject SASL problem with 3.4.4 Java client
Date Tue, 25 Sep 2012 21:43:14 GMT
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


Mime
View raw message