You are viewing a plain text version of this content. The canonical link for it is here.
Posted to user@zookeeper.apache.org by Robert Macomber <xb...@rojoma.com> on 2012/09/25 23:43:14 UTC
SASL problem with 3.4.4 Java client
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
Re: SASL problem with 3.4.4 Java client
Posted by Mahadev Konar <ma...@hortonworks.com>.
Not a bad idea Pat. Lets wait until EOD today. Eugene and myself will
be taking a look during the day and we can see if we should be able to
fix it quickly or we should revert.
thanks
mahadev
On Wed, Sep 26, 2012 at 6:35 AM, Patrick Hunt <ph...@apache.org> wrote:
> How about if we revert
> https://issues.apache.org/jira/browse/ZOOKEEPER-1437 and cut 3.4.5 RC0
> today? Robert, Julio, et. al. could help verify the "fix". We can
> re-introduce 1437 in 3.4.6 and significantly reduce the risk until
> that's had more time to bake (say cut 3.4.6 a few months down the
> line).
>
> Patrick
>
> On Tue, Sep 25, 2012 at 10:05 PM, Mahadev Konar <ma...@hortonworks.com> wrote:
>> Thanks for point this out JL and Robert. We have a jira for this
>> https://issues.apache.org/jira/browse/ZOOKEEPER-1477 and we will be
>> doing a 3.4.5 ASAP to address this.
>>
>> thanks
>> mahadev
>>
>> On Tue, Sep 25, 2012 at 3:37 PM, JL <ju...@lycos.com> wrote:
>>> This may be related. We are not using SSL, but the underlying cause may be the same: socket disconnection or failure to deliver data from the underlying channel.
>>>
>>> We experienced connection drops (after about ~3000ms) with Curator 1.1.18 and ZK 3.4.4. on openjdk 6 (on Linux), and JDK 7u7 on OS X.
>>>
>>> Oracle JVM 1.6.0_32 on Linux and v. 1.6.0_35 on OS X, seem to work.
>>>
>>> Here's the error we get over and over.
>>>
>>> E 09-25 17:01:35.408 http-bio-8081-exec-7-EventThread c.n.c.f.i.CuratorFrameworkImpl:486 :::] Background operation retry gave up
>>> org.apache.zookeeper.KeeperException$ConnectionLossException: KeeperErrorCode = ConnectionLoss
>>> at org.apache.zookeeper.KeeperException.create(KeeperException.java:99) ~[zookeeper-3.4.4.jar:3.4.4-1386507]
>>> at com.netflix.curator.framework.imps.CuratorFrameworkImpl.processBackgroundOperation(CuratorFrameworkImpl.java:448) ~[curator-framework-1.1.18.jar:na]
>>> at com.netflix.curator.framework.imps.BackgroundSyncImpl$1.processResult(BackgroundSyncImpl.java:49) [curator-framework-1.1.18.jar:na]
>>> at org.apache.zookeeper.ClientCnxn$EventThread.processEvent(ClientCnxn.java:606) [zookeeper-3.4.4.jar:3.4.4-1386507]
>>> at org.apache.zookeeper.ClientCnxn$EventThread.run(ClientCnxn.java:495) [zookeeper-3.4.4.jar:3.4.4-1386507]
>>>
>>>
>>> Cheers,
>>>
>>> -Julio
>>>
>>> Sep 25, 2012 02:45:30 PM, user@zookeeper.apache.org wrote:
>>>
>>> ===========================================
>>>
>>> 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=
>>> 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=
>>> 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
Re: SASL problem with 3.4.4 Java client
Posted by Patrick Hunt <ph...@apache.org>.
Thanks Eugene!
Patrick
On Fri, Sep 28, 2012 at 10:53 AM, Mahadev Konar <ma...@hortonworks.com> wrote:
> Thanks to Eugene we have all green on our builds (including jdk7). Ill
> spin up a new RC.
>
> Thanks again Eugene!
> mahadev
>
> On Wed, Sep 26, 2012 at 11:26 AM, Eugene Koontz <ek...@hiro-tan.org> wrote:
>> On 9/26/12 11:08 AM, Patrick Hunt wrote:
>>>
>>>
>>> I didn't notice any feedback to the list on these issues, perhaps I missed
>>> it?
>>>
>> Hi Pat,
>>
>> I should have mentioned the test failures that we noticed with
>> ZOOKEEPER-1497; I regret not bringing these to yours and the community's
>> attention. I will look into it more today.
>>
>> -Eugene
Re: SASL problem with 3.4.4 Java client
Posted by Mahadev Konar <ma...@hortonworks.com>.
Thanks to Eugene we have all green on our builds (including jdk7). Ill
spin up a new RC.
Thanks again Eugene!
mahadev
On Wed, Sep 26, 2012 at 11:26 AM, Eugene Koontz <ek...@hiro-tan.org> wrote:
> On 9/26/12 11:08 AM, Patrick Hunt wrote:
>>
>>
>> I didn't notice any feedback to the list on these issues, perhaps I missed
>> it?
>>
> Hi Pat,
>
> I should have mentioned the test failures that we noticed with
> ZOOKEEPER-1497; I regret not bringing these to yours and the community's
> attention. I will look into it more today.
>
> -Eugene
Re: SASL problem with 3.4.4 Java client
Posted by Eugene Koontz <ek...@hiro-tan.org>.
On 9/26/12 11:08 AM, Patrick Hunt wrote:
>
> I didn't notice any feedback to the list on these issues, perhaps I missed it?
>
Hi Pat,
I should have mentioned the test failures that we noticed with
ZOOKEEPER-1497; I regret not bringing these to yours and the community's
attention. I will look into it more today.
-Eugene
Re: SASL problem with 3.4.4 Java client
Posted by Patrick Hunt <ph...@apache.org>.
On Wed, Sep 26, 2012 at 10:42 AM, Eugene Koontz <ek...@hiro-tan.org> wrote:
> On 9/26/12 9:56 AM, Andrew Purtell wrote:
>>
>> Hi Pat,
>>
>> We didn't take up the changes from ZOOKEEPER-1497 yet and I believe we are
>> still checking the existence of a system property to determine if SASL is
>> configured. Eugene could confirm. Anyhow we have been testing with Oracle
>> JRE 7 (u4 I believe was the most recent) so it seems we've had no exposure
>> to ZOOKEEPER-1550 and tests have all been good.
>>
>> Before ZOOKEEPER-1437 went in, when starting secure HBase regionservers up
>> on EC2 test clusters, at one point most of the time they would lose the
>> race, fail to authenticate, and abort. This was different from results on
>> earlier versions (of HBase and from 3.4 branch), but because that timing
>> problem was latent only then.
>
>
> Hi Pat and Andy and all ZK devs,
> Andy is right; we had a lot of problems with test failures after merging
> ZOOKEEPER-1497, so we removed this fix (ZOOKEEPER-1497) from our branch. So
> we still reply on checking the system property to determine whether SASL is
> configured. I'll be looking at all of these problems in 3.4.4 today.
> -Eugene
>
I didn't notice any feedback to the list on these issues, perhaps I missed it?
1437 definitely has some issue though - I just noticed this on
jenkins: https://builds.apache.org/view/S-Z/view/ZooKeeper/job/ZooKeeper-trunk-jdk7/
Seems the build started failing when 1437 was introduced (sep10). 1497
went in earlier (aug 29th) w/o any issues in terms of jdk7 unit tests.
https://builds.apache.org/view/S-Z/view/ZooKeeper/job/ZooKeeper-trunk-jdk7/changes
Perhaps we're missing some tests on 1497 that trigger the issue you
saw? Would be great to add a test for that.
Thanks Eugene/Andrew!
Patrick
Re: SASL problem with 3.4.4 Java client
Posted by Eugene Koontz <ek...@hiro-tan.org>.
On 9/26/12 9:56 AM, Andrew Purtell wrote:
> Hi Pat,
>
> We didn't take up the changes from ZOOKEEPER-1497 yet and I believe we are
> still checking the existence of a system property to determine if SASL is
> configured. Eugene could confirm. Anyhow we have been testing with Oracle
> JRE 7 (u4 I believe was the most recent) so it seems we've had no exposure
> to ZOOKEEPER-1550 and tests have all been good.
>
> Before ZOOKEEPER-1437 went in, when starting secure HBase regionservers up
> on EC2 test clusters, at one point most of the time they would lose the
> race, fail to authenticate, and abort. This was different from results on
> earlier versions (of HBase and from 3.4 branch), but because that timing
> problem was latent only then.
Hi Pat and Andy and all ZK devs,
Andy is right; we had a lot of problems with test failures after
merging ZOOKEEPER-1497, so we removed this fix (ZOOKEEPER-1497) from our
branch. So we still reply on checking the system property to determine
whether SASL is configured. I'll be looking at all of these problems in
3.4.4 today.
-Eugene
Re: SASL problem with 3.4.4 Java client
Posted by Andrew Purtell <ap...@apache.org>.
Hi Pat,
We didn't take up the changes from ZOOKEEPER-1497 yet and I believe we are
still checking the existence of a system property to determine if SASL is
configured. Eugene could confirm. Anyhow we have been testing with Oracle
JRE 7 (u4 I believe was the most recent) so it seems we've had no exposure
to ZOOKEEPER-1550 and tests have all been good.
Before ZOOKEEPER-1437 went in, when starting secure HBase regionservers up
on EC2 test clusters, at one point most of the time they would lose the
race, fail to authenticate, and abort. This was different from results on
earlier versions (of HBase and from 3.4 branch), but because that timing
problem was latent only then.
On Wednesday, September 26, 2012, Patrick Hunt wrote:
> On Wed, Sep 26, 2012 at 8:44 AM, Andrew Purtell <apurtell@apache.org<javascript:;>>
> wrote:
> > Without ZOOKEEPER-1437 secure HBase is not functional in our environment.
> >
>
> Hi Andrew, that's a good reason to not revert it then.
>
> I'd feel more comfortable if we had more feedback from users that
> 3.4.4 is working (other than the noted issue)
>
> Andrew can you give us insight into your testing and how stable 3.4.4
> is for you?
>
> Patrick
>
> > On Wed, Sep 26, 2012 at 6:35 AM, Patrick Hunt <ph...@apache.org> wrote:
> >> How about if we revert
> >> https://issues.apache.org/jira/browse/ZOOKEEPER-1437 and cut 3.4.5 RC0
> >> today? Robert, Julio, et. al. could help verify the "fix". We can
> >> re-introduce 1437 in 3.4.6 and significantly reduce the risk until
> >> that's had more time to bake (say cut 3.4.6 a few months down the
> >> line).
> >>
> >> Patrick
> >>
> >> On Tue, Sep 25, 2012 at 10:05 PM, Mahadev Konar <
> mahadev@hortonworks.com> wrote:
> >>> Thanks for point this out JL and Robert. We have a jira for this
> >>> https://issues.apache.org/jira/browse/ZOOKEEPER-1477 and we will be
> >>> doing a 3.4.5 ASAP to address this.
> >>>
> >>> thanks
> >>> mahadev
> >>>
> >>> On Tue, Sep 25, 2012 at 3:37 PM, JL <ju...@lycos.com> wrote:
> >>>> This may be related. We are not using SSL, but the underlying cause
> may be the same: socket disconnection or failure to deliver data from the
> underlying channel.
> >>>>
> >>>> We experienced connection drops (after about ~3000ms) with Curator
> 1.1.18 and ZK 3.4.4. on openjdk 6 (on Linux), and JDK 7u7 on OS X.
> >>>>
> >>>> Oracle JVM 1.6.0_32 on Linux and v. 1.6.0_35 on OS X, seem to work.
> >>>>
> >>>> Here's the error we get over and over.
> >>>>
> >>>> E 09-25 17:01:35.408 http-bio-8081-exec-7-EventThread
> c.n.c.f.i.CuratorFrameworkImpl:486 :::] Background operation retry gave up
> >>>> org.apache.zookeeper.KeeperException$ConnectionLossException:
> KeeperErrorCode = ConnectionLoss
> >>>> at
> org.apache.zookeeper.KeeperException.create(KeeperException.java:99)
> ~[zookeeper-3.4.4.jar:3.4.4-1386507]
> >>>> at
> com.netflix.curator.framework.imps.CuratorFrameworkImpl.processBackgroundOperation(CuratorFrameworkImpl.java:448)
> ~[curator-framework-1.1.18.jar:na]
> >>>> at
> com.netflix.curator.framework.imps.BackgroundSyncImpl$1.processResult(BackgroundSyncImpl.java:49)
> [curator-framework-1.1.18.jar:na]
> >>>> at
> org.apache.zookeeper.ClientCnxn$EventThread.processEvent(ClientCnxn.java:606)
> [zookeeper-3.4.4.jar:3.4.4-1386507]
> >>>> at
> org.apache.zookeeper.ClientCnxn$EventThread.run(ClientCnxn.java:495)
> [zookeeper-3.4.4.jar:3.4.4-1386507]
> >>>>
> >>>>
> >>>> Cheers,
> >>>>
> >>>> -Julio
> >>>>
> >>>> Sep 25, 2012 02:45:30 PM, user@zookeeper.apache.org wrote:
> >>>>
> >>>> ===========================================
> >>>>
> >>>> 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.
>
--
Best regards,
- Andy
Problems worthy of attack prove their worth by hitting back. - Piet Hein
(via Tom White)
Re: SASL problem with 3.4.4 Java client
Posted by Patrick Hunt <ph...@apache.org>.
On Wed, Sep 26, 2012 at 8:44 AM, Andrew Purtell <ap...@apache.org> wrote:
> Without ZOOKEEPER-1437 secure HBase is not functional in our environment.
>
Hi Andrew, that's a good reason to not revert it then.
I'd feel more comfortable if we had more feedback from users that
3.4.4 is working (other than the noted issue)
Andrew can you give us insight into your testing and how stable 3.4.4
is for you?
Patrick
> On Wed, Sep 26, 2012 at 6:35 AM, Patrick Hunt <ph...@apache.org> wrote:
>> How about if we revert
>> https://issues.apache.org/jira/browse/ZOOKEEPER-1437 and cut 3.4.5 RC0
>> today? Robert, Julio, et. al. could help verify the "fix". We can
>> re-introduce 1437 in 3.4.6 and significantly reduce the risk until
>> that's had more time to bake (say cut 3.4.6 a few months down the
>> line).
>>
>> Patrick
>>
>> On Tue, Sep 25, 2012 at 10:05 PM, Mahadev Konar <ma...@hortonworks.com> wrote:
>>> Thanks for point this out JL and Robert. We have a jira for this
>>> https://issues.apache.org/jira/browse/ZOOKEEPER-1477 and we will be
>>> doing a 3.4.5 ASAP to address this.
>>>
>>> thanks
>>> mahadev
>>>
>>> On Tue, Sep 25, 2012 at 3:37 PM, JL <ju...@lycos.com> wrote:
>>>> This may be related. We are not using SSL, but the underlying cause may be the same: socket disconnection or failure to deliver data from the underlying channel.
>>>>
>>>> We experienced connection drops (after about ~3000ms) with Curator 1.1.18 and ZK 3.4.4. on openjdk 6 (on Linux), and JDK 7u7 on OS X.
>>>>
>>>> Oracle JVM 1.6.0_32 on Linux and v. 1.6.0_35 on OS X, seem to work.
>>>>
>>>> Here's the error we get over and over.
>>>>
>>>> E 09-25 17:01:35.408 http-bio-8081-exec-7-EventThread c.n.c.f.i.CuratorFrameworkImpl:486 :::] Background operation retry gave up
>>>> org.apache.zookeeper.KeeperException$ConnectionLossException: KeeperErrorCode = ConnectionLoss
>>>> at org.apache.zookeeper.KeeperException.create(KeeperException.java:99) ~[zookeeper-3.4.4.jar:3.4.4-1386507]
>>>> at com.netflix.curator.framework.imps.CuratorFrameworkImpl.processBackgroundOperation(CuratorFrameworkImpl.java:448) ~[curator-framework-1.1.18.jar:na]
>>>> at com.netflix.curator.framework.imps.BackgroundSyncImpl$1.processResult(BackgroundSyncImpl.java:49) [curator-framework-1.1.18.jar:na]
>>>> at org.apache.zookeeper.ClientCnxn$EventThread.processEvent(ClientCnxn.java:606) [zookeeper-3.4.4.jar:3.4.4-1386507]
>>>> at org.apache.zookeeper.ClientCnxn$EventThread.run(ClientCnxn.java:495) [zookeeper-3.4.4.jar:3.4.4-1386507]
>>>>
>>>>
>>>> Cheers,
>>>>
>>>> -Julio
>>>>
>>>> Sep 25, 2012 02:45:30 PM, user@zookeeper.apache.org wrote:
>>>>
>>>> ===========================================
>>>>
>>>> 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=
>>>> 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=
>>>> 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
>
>
>
> --
> Best regards,
>
> - Andy
>
> Problems worthy of attack prove their worth by hitting back. - Piet
> Hein (via Tom White)
Re: SASL problem with 3.4.4 Java client
Posted by Mahadev Konar <ma...@hortonworks.com>.
Andrew,
Hopefully it should be minor fixes and we can make some fixes today.
If not we might have to do another release in a week or 2 with just
ZK-1437 and revert it in the upcoming 3.4.5 release.
mahadev
On Wed, Sep 26, 2012 at 8:44 AM, Andrew Purtell <ap...@apache.org> wrote:
> Without ZOOKEEPER-1437 secure HBase is not functional in our environment.
>
> On Wed, Sep 26, 2012 at 6:35 AM, Patrick Hunt <ph...@apache.org> wrote:
>> How about if we revert
>> https://issues.apache.org/jira/browse/ZOOKEEPER-1437 and cut 3.4.5 RC0
>> today? Robert, Julio, et. al. could help verify the "fix". We can
>> re-introduce 1437 in 3.4.6 and significantly reduce the risk until
>> that's had more time to bake (say cut 3.4.6 a few months down the
>> line).
>>
>> Patrick
>>
>> On Tue, Sep 25, 2012 at 10:05 PM, Mahadev Konar <ma...@hortonworks.com> wrote:
>>> Thanks for point this out JL and Robert. We have a jira for this
>>> https://issues.apache.org/jira/browse/ZOOKEEPER-1477 and we will be
>>> doing a 3.4.5 ASAP to address this.
>>>
>>> thanks
>>> mahadev
>>>
>>> On Tue, Sep 25, 2012 at 3:37 PM, JL <ju...@lycos.com> wrote:
>>>> This may be related. We are not using SSL, but the underlying cause may be the same: socket disconnection or failure to deliver data from the underlying channel.
>>>>
>>>> We experienced connection drops (after about ~3000ms) with Curator 1.1.18 and ZK 3.4.4. on openjdk 6 (on Linux), and JDK 7u7 on OS X.
>>>>
>>>> Oracle JVM 1.6.0_32 on Linux and v. 1.6.0_35 on OS X, seem to work.
>>>>
>>>> Here's the error we get over and over.
>>>>
>>>> E 09-25 17:01:35.408 http-bio-8081-exec-7-EventThread c.n.c.f.i.CuratorFrameworkImpl:486 :::] Background operation retry gave up
>>>> org.apache.zookeeper.KeeperException$ConnectionLossException: KeeperErrorCode = ConnectionLoss
>>>> at org.apache.zookeeper.KeeperException.create(KeeperException.java:99) ~[zookeeper-3.4.4.jar:3.4.4-1386507]
>>>> at com.netflix.curator.framework.imps.CuratorFrameworkImpl.processBackgroundOperation(CuratorFrameworkImpl.java:448) ~[curator-framework-1.1.18.jar:na]
>>>> at com.netflix.curator.framework.imps.BackgroundSyncImpl$1.processResult(BackgroundSyncImpl.java:49) [curator-framework-1.1.18.jar:na]
>>>> at org.apache.zookeeper.ClientCnxn$EventThread.processEvent(ClientCnxn.java:606) [zookeeper-3.4.4.jar:3.4.4-1386507]
>>>> at org.apache.zookeeper.ClientCnxn$EventThread.run(ClientCnxn.java:495) [zookeeper-3.4.4.jar:3.4.4-1386507]
>>>>
>>>>
>>>> Cheers,
>>>>
>>>> -Julio
>>>>
>>>> Sep 25, 2012 02:45:30 PM, user@zookeeper.apache.org wrote:
>>>>
>>>> ===========================================
>>>>
>>>> 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=
>>>> 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=
>>>> 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
>
>
>
> --
> Best regards,
>
> - Andy
>
> Problems worthy of attack prove their worth by hitting back. - Piet
> Hein (via Tom White)
Re: SASL problem with 3.4.4 Java client
Posted by Andrew Purtell <ap...@apache.org>.
Without ZOOKEEPER-1437 secure HBase is not functional in our environment.
On Wed, Sep 26, 2012 at 6:35 AM, Patrick Hunt <ph...@apache.org> wrote:
> How about if we revert
> https://issues.apache.org/jira/browse/ZOOKEEPER-1437 and cut 3.4.5 RC0
> today? Robert, Julio, et. al. could help verify the "fix". We can
> re-introduce 1437 in 3.4.6 and significantly reduce the risk until
> that's had more time to bake (say cut 3.4.6 a few months down the
> line).
>
> Patrick
>
> On Tue, Sep 25, 2012 at 10:05 PM, Mahadev Konar <ma...@hortonworks.com> wrote:
>> Thanks for point this out JL and Robert. We have a jira for this
>> https://issues.apache.org/jira/browse/ZOOKEEPER-1477 and we will be
>> doing a 3.4.5 ASAP to address this.
>>
>> thanks
>> mahadev
>>
>> On Tue, Sep 25, 2012 at 3:37 PM, JL <ju...@lycos.com> wrote:
>>> This may be related. We are not using SSL, but the underlying cause may be the same: socket disconnection or failure to deliver data from the underlying channel.
>>>
>>> We experienced connection drops (after about ~3000ms) with Curator 1.1.18 and ZK 3.4.4. on openjdk 6 (on Linux), and JDK 7u7 on OS X.
>>>
>>> Oracle JVM 1.6.0_32 on Linux and v. 1.6.0_35 on OS X, seem to work.
>>>
>>> Here's the error we get over and over.
>>>
>>> E 09-25 17:01:35.408 http-bio-8081-exec-7-EventThread c.n.c.f.i.CuratorFrameworkImpl:486 :::] Background operation retry gave up
>>> org.apache.zookeeper.KeeperException$ConnectionLossException: KeeperErrorCode = ConnectionLoss
>>> at org.apache.zookeeper.KeeperException.create(KeeperException.java:99) ~[zookeeper-3.4.4.jar:3.4.4-1386507]
>>> at com.netflix.curator.framework.imps.CuratorFrameworkImpl.processBackgroundOperation(CuratorFrameworkImpl.java:448) ~[curator-framework-1.1.18.jar:na]
>>> at com.netflix.curator.framework.imps.BackgroundSyncImpl$1.processResult(BackgroundSyncImpl.java:49) [curator-framework-1.1.18.jar:na]
>>> at org.apache.zookeeper.ClientCnxn$EventThread.processEvent(ClientCnxn.java:606) [zookeeper-3.4.4.jar:3.4.4-1386507]
>>> at org.apache.zookeeper.ClientCnxn$EventThread.run(ClientCnxn.java:495) [zookeeper-3.4.4.jar:3.4.4-1386507]
>>>
>>>
>>> Cheers,
>>>
>>> -Julio
>>>
>>> Sep 25, 2012 02:45:30 PM, user@zookeeper.apache.org wrote:
>>>
>>> ===========================================
>>>
>>> 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=
>>> 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=
>>> 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
--
Best regards,
- Andy
Problems worthy of attack prove their worth by hitting back. - Piet
Hein (via Tom White)
Re: SASL problem with 3.4.4 Java client
Posted by Mahadev Konar <ma...@hortonworks.com>.
Not a bad idea Pat. Lets wait until EOD today. Eugene and myself will
be taking a look during the day and we can see if we should be able to
fix it quickly or we should revert.
thanks
mahadev
On Wed, Sep 26, 2012 at 6:35 AM, Patrick Hunt <ph...@apache.org> wrote:
> How about if we revert
> https://issues.apache.org/jira/browse/ZOOKEEPER-1437 and cut 3.4.5 RC0
> today? Robert, Julio, et. al. could help verify the "fix". We can
> re-introduce 1437 in 3.4.6 and significantly reduce the risk until
> that's had more time to bake (say cut 3.4.6 a few months down the
> line).
>
> Patrick
>
> On Tue, Sep 25, 2012 at 10:05 PM, Mahadev Konar <ma...@hortonworks.com> wrote:
>> Thanks for point this out JL and Robert. We have a jira for this
>> https://issues.apache.org/jira/browse/ZOOKEEPER-1477 and we will be
>> doing a 3.4.5 ASAP to address this.
>>
>> thanks
>> mahadev
>>
>> On Tue, Sep 25, 2012 at 3:37 PM, JL <ju...@lycos.com> wrote:
>>> This may be related. We are not using SSL, but the underlying cause may be the same: socket disconnection or failure to deliver data from the underlying channel.
>>>
>>> We experienced connection drops (after about ~3000ms) with Curator 1.1.18 and ZK 3.4.4. on openjdk 6 (on Linux), and JDK 7u7 on OS X.
>>>
>>> Oracle JVM 1.6.0_32 on Linux and v. 1.6.0_35 on OS X, seem to work.
>>>
>>> Here's the error we get over and over.
>>>
>>> E 09-25 17:01:35.408 http-bio-8081-exec-7-EventThread c.n.c.f.i.CuratorFrameworkImpl:486 :::] Background operation retry gave up
>>> org.apache.zookeeper.KeeperException$ConnectionLossException: KeeperErrorCode = ConnectionLoss
>>> at org.apache.zookeeper.KeeperException.create(KeeperException.java:99) ~[zookeeper-3.4.4.jar:3.4.4-1386507]
>>> at com.netflix.curator.framework.imps.CuratorFrameworkImpl.processBackgroundOperation(CuratorFrameworkImpl.java:448) ~[curator-framework-1.1.18.jar:na]
>>> at com.netflix.curator.framework.imps.BackgroundSyncImpl$1.processResult(BackgroundSyncImpl.java:49) [curator-framework-1.1.18.jar:na]
>>> at org.apache.zookeeper.ClientCnxn$EventThread.processEvent(ClientCnxn.java:606) [zookeeper-3.4.4.jar:3.4.4-1386507]
>>> at org.apache.zookeeper.ClientCnxn$EventThread.run(ClientCnxn.java:495) [zookeeper-3.4.4.jar:3.4.4-1386507]
>>>
>>>
>>> Cheers,
>>>
>>> -Julio
>>>
>>> Sep 25, 2012 02:45:30 PM, user@zookeeper.apache.org wrote:
>>>
>>> ===========================================
>>>
>>> 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=
>>> 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=
>>> 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
Re: SASL problem with 3.4.4 Java client
Posted by Patrick Hunt <ph...@apache.org>.
How about if we revert
https://issues.apache.org/jira/browse/ZOOKEEPER-1437 and cut 3.4.5 RC0
today? Robert, Julio, et. al. could help verify the "fix". We can
re-introduce 1437 in 3.4.6 and significantly reduce the risk until
that's had more time to bake (say cut 3.4.6 a few months down the
line).
Patrick
On Tue, Sep 25, 2012 at 10:05 PM, Mahadev Konar <ma...@hortonworks.com> wrote:
> Thanks for point this out JL and Robert. We have a jira for this
> https://issues.apache.org/jira/browse/ZOOKEEPER-1477 and we will be
> doing a 3.4.5 ASAP to address this.
>
> thanks
> mahadev
>
> On Tue, Sep 25, 2012 at 3:37 PM, JL <ju...@lycos.com> wrote:
>> This may be related. We are not using SSL, but the underlying cause may be the same: socket disconnection or failure to deliver data from the underlying channel.
>>
>> We experienced connection drops (after about ~3000ms) with Curator 1.1.18 and ZK 3.4.4. on openjdk 6 (on Linux), and JDK 7u7 on OS X.
>>
>> Oracle JVM 1.6.0_32 on Linux and v. 1.6.0_35 on OS X, seem to work.
>>
>> Here's the error we get over and over.
>>
>> E 09-25 17:01:35.408 http-bio-8081-exec-7-EventThread c.n.c.f.i.CuratorFrameworkImpl:486 :::] Background operation retry gave up
>> org.apache.zookeeper.KeeperException$ConnectionLossException: KeeperErrorCode = ConnectionLoss
>> at org.apache.zookeeper.KeeperException.create(KeeperException.java:99) ~[zookeeper-3.4.4.jar:3.4.4-1386507]
>> at com.netflix.curator.framework.imps.CuratorFrameworkImpl.processBackgroundOperation(CuratorFrameworkImpl.java:448) ~[curator-framework-1.1.18.jar:na]
>> at com.netflix.curator.framework.imps.BackgroundSyncImpl$1.processResult(BackgroundSyncImpl.java:49) [curator-framework-1.1.18.jar:na]
>> at org.apache.zookeeper.ClientCnxn$EventThread.processEvent(ClientCnxn.java:606) [zookeeper-3.4.4.jar:3.4.4-1386507]
>> at org.apache.zookeeper.ClientCnxn$EventThread.run(ClientCnxn.java:495) [zookeeper-3.4.4.jar:3.4.4-1386507]
>>
>>
>> Cheers,
>>
>> -Julio
>>
>> Sep 25, 2012 02:45:30 PM, user@zookeeper.apache.org wrote:
>>
>> ===========================================
>>
>> 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=
>> 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=
>> 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
Re: SASL problem with 3.4.4 Java client
Posted by Patrick Hunt <ph...@apache.org>.
How about if we revert
https://issues.apache.org/jira/browse/ZOOKEEPER-1437 and cut 3.4.5 RC0
today? Robert, Julio, et. al. could help verify the "fix". We can
re-introduce 1437 in 3.4.6 and significantly reduce the risk until
that's had more time to bake (say cut 3.4.6 a few months down the
line).
Patrick
On Tue, Sep 25, 2012 at 10:05 PM, Mahadev Konar <ma...@hortonworks.com> wrote:
> Thanks for point this out JL and Robert. We have a jira for this
> https://issues.apache.org/jira/browse/ZOOKEEPER-1477 and we will be
> doing a 3.4.5 ASAP to address this.
>
> thanks
> mahadev
>
> On Tue, Sep 25, 2012 at 3:37 PM, JL <ju...@lycos.com> wrote:
>> This may be related. We are not using SSL, but the underlying cause may be the same: socket disconnection or failure to deliver data from the underlying channel.
>>
>> We experienced connection drops (after about ~3000ms) with Curator 1.1.18 and ZK 3.4.4. on openjdk 6 (on Linux), and JDK 7u7 on OS X.
>>
>> Oracle JVM 1.6.0_32 on Linux and v. 1.6.0_35 on OS X, seem to work.
>>
>> Here's the error we get over and over.
>>
>> E 09-25 17:01:35.408 http-bio-8081-exec-7-EventThread c.n.c.f.i.CuratorFrameworkImpl:486 :::] Background operation retry gave up
>> org.apache.zookeeper.KeeperException$ConnectionLossException: KeeperErrorCode = ConnectionLoss
>> at org.apache.zookeeper.KeeperException.create(KeeperException.java:99) ~[zookeeper-3.4.4.jar:3.4.4-1386507]
>> at com.netflix.curator.framework.imps.CuratorFrameworkImpl.processBackgroundOperation(CuratorFrameworkImpl.java:448) ~[curator-framework-1.1.18.jar:na]
>> at com.netflix.curator.framework.imps.BackgroundSyncImpl$1.processResult(BackgroundSyncImpl.java:49) [curator-framework-1.1.18.jar:na]
>> at org.apache.zookeeper.ClientCnxn$EventThread.processEvent(ClientCnxn.java:606) [zookeeper-3.4.4.jar:3.4.4-1386507]
>> at org.apache.zookeeper.ClientCnxn$EventThread.run(ClientCnxn.java:495) [zookeeper-3.4.4.jar:3.4.4-1386507]
>>
>>
>> Cheers,
>>
>> -Julio
>>
>> Sep 25, 2012 02:45:30 PM, user@zookeeper.apache.org wrote:
>>
>> ===========================================
>>
>> 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=
>> 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=
>> 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
Re: SASL problem with 3.4.4 Java client
Posted by Mahadev Konar <ma...@hortonworks.com>.
Thanks for point this out JL and Robert. We have a jira for this
https://issues.apache.org/jira/browse/ZOOKEEPER-1477 and we will be
doing a 3.4.5 ASAP to address this.
thanks
mahadev
On Tue, Sep 25, 2012 at 3:37 PM, JL <ju...@lycos.com> wrote:
> This may be related. We are not using SSL, but the underlying cause may be the same: socket disconnection or failure to deliver data from the underlying channel.
>
> We experienced connection drops (after about ~3000ms) with Curator 1.1.18 and ZK 3.4.4. on openjdk 6 (on Linux), and JDK 7u7 on OS X.
>
> Oracle JVM 1.6.0_32 on Linux and v. 1.6.0_35 on OS X, seem to work.
>
> Here's the error we get over and over.
>
> E 09-25 17:01:35.408 http-bio-8081-exec-7-EventThread c.n.c.f.i.CuratorFrameworkImpl:486 :::] Background operation retry gave up
> org.apache.zookeeper.KeeperException$ConnectionLossException: KeeperErrorCode = ConnectionLoss
> at org.apache.zookeeper.KeeperException.create(KeeperException.java:99) ~[zookeeper-3.4.4.jar:3.4.4-1386507]
> at com.netflix.curator.framework.imps.CuratorFrameworkImpl.processBackgroundOperation(CuratorFrameworkImpl.java:448) ~[curator-framework-1.1.18.jar:na]
> at com.netflix.curator.framework.imps.BackgroundSyncImpl$1.processResult(BackgroundSyncImpl.java:49) [curator-framework-1.1.18.jar:na]
> at org.apache.zookeeper.ClientCnxn$EventThread.processEvent(ClientCnxn.java:606) [zookeeper-3.4.4.jar:3.4.4-1386507]
> at org.apache.zookeeper.ClientCnxn$EventThread.run(ClientCnxn.java:495) [zookeeper-3.4.4.jar:3.4.4-1386507]
>
>
> Cheers,
>
> -Julio
>
> Sep 25, 2012 02:45:30 PM, user@zookeeper.apache.org wrote:
>
> ===========================================
>
> 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=
> 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=
> 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
Re: SASL problem with 3.4.4 Java client
Posted by dcgregorya <gr...@omnigon.com>.
Just want to note, this issue also occurs with Sun JDK 7u7 on Windows 7.
--
View this message in context: http://zookeeper-user.578899.n2.nabble.com/SASL-problem-with-3-4-4-Java-client-tp7577983p7577992.html
Sent from the zookeeper-user mailing list archive at Nabble.com.
Re: SASL problem with 3.4.4 Java client
Posted by Robert Macomber <xb...@rojoma.com>.
On 2012-09-26, Mahadev Konar <ma...@hortonworks.com> wrote:
> Hi Robert,
> Thanks for digging. The explanation makes sense. Can you please open
> a jira with the details?
Done; https://issues.apache.org/jira/browse/ZOOKEEPER-1550
Re: SASL problem with 3.4.4 Java client
Posted by Mahadev Konar <ma...@hortonworks.com>.
Hi Robert,
Thanks for digging. The explanation makes sense. Can you please open
a jira with the details?
thanks
mahadev
On Wed, Sep 26, 2012 at 6:38 AM, Robert Macomber <xb...@rojoma.com> wrote:
> On 2012-09-26, Mahadev Konar <ma...@hortonworks.com> wrote:
>> Thanks for point this out JL and Robert. We have a jira for this
>> https://issues.apache.org/jira/browse/ZOOKEEPER-1477 and we will be
>> doing a 3.4.5 ASAP to address this.
>
> This ticket doesn't look like it describes my problem. For me, it's
> OSX that works fine and Linux which does not, with rather different
> symptoms -- the client is explicitly deciding not to send any packets.
>
> I think I've tracked it down. In Linux,
> ZooKeeperSaslClient.clientTunneledAuthenticationInProgress is not
> receiving any SecurityException out of the call to
> javax.security.auth.login.Configuration.getConfiguration so that
> method thinks it's actually trying SASL. On OSX an exception is
> thrown and so the "Could not retrieve login configuration" log line is
> triggered. It looks like the constructor's idea of what constitutes
> "I'm going to do SASL" and the cTAIP method's idea differ a bit!
>
> Digging slightly further, the looks like it might be a difference
> between openjdk and the Oracle JVM rather than Linux/OSX. On openjdk,
> j.s.a.l.Configuration.getConfiguration succeeds on every system I've
> tried I've tried (admittedly all debian/ubuntu), but the Oracle JVM
> throws a SecurityException.
>
>
>> thanks
>> mahadev
>>
>> On Tue, Sep 25, 2012 at 3:37 PM, JL <ju...@lycos.com> wrote:
>>> This may be related. We are not using SSL, but the underlying cause may be the same: socket disconnection or failure to deliver data from the underlying channel.
>>>
>>> We experienced connection drops (after about ~3000ms) with Curator 1.1.18 and ZK 3.4.4. on openjdk 6 (on Linux), and JDK 7u7 on OS X.
>>>
>>> Oracle JVM 1.6.0_32 on Linux and v. 1.6.0_35 on OS X, seem to work.
>>>
>>> Here's the error we get over and over.
>>>
>>> E 09-25 17:01:35.408 http-bio-8081-exec-7-EventThread c.n.c.f.i.CuratorFrameworkImpl:486 :::] Background operation retry gave up
>>> org.apache.zookeeper.KeeperException$ConnectionLossException: KeeperErrorCode = ConnectionLoss
>>> at org.apache.zookeeper.KeeperException.create(KeeperException.java:99) ~[zookeeper-3.4.4.jar:3.4.4-1386507]
>>> at com.netflix.curator.framework.imps.CuratorFrameworkImpl.processBackgroundOperation(CuratorFrameworkImpl.java:448) ~[curator-framework-1.1.18.jar:na]
>>> at com.netflix.curator.framework.imps.BackgroundSyncImpl$1.processResult(BackgroundSyncImpl.java:49) [curator-framework-1.1.18.jar:na]
>>> at org.apache.zookeeper.ClientCnxn$EventThread.processEvent(ClientCnxn.java:606) [zookeeper-3.4.4.jar:3.4.4-1386507]
>>> at org.apache.zookeeper.ClientCnxn$EventThread.run(ClientCnxn.java:495) [zookeeper-3.4.4.jar:3.4.4-1386507]
>>>
>>>
>>> Cheers,
>>>
>>> -Julio
>>>
>>> Sep 25, 2012 02:45:30 PM, user@zookeeper.apache.org wrote:
>>>
>>> ===========================================
>>>
>>> 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=
>>> 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=
>>> 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
>>
>
Re: SASL problem with 3.4.4 Java client
Posted by Robert Macomber <xb...@rojoma.com>.
On 2012-09-26, Mahadev Konar <ma...@hortonworks.com> wrote:
> Thanks for point this out JL and Robert. We have a jira for this
> https://issues.apache.org/jira/browse/ZOOKEEPER-1477 and we will be
> doing a 3.4.5 ASAP to address this.
This ticket doesn't look like it describes my problem. For me, it's
OSX that works fine and Linux which does not, with rather different
symptoms -- the client is explicitly deciding not to send any packets.
I think I've tracked it down. In Linux,
ZooKeeperSaslClient.clientTunneledAuthenticationInProgress is not
receiving any SecurityException out of the call to
javax.security.auth.login.Configuration.getConfiguration so that
method thinks it's actually trying SASL. On OSX an exception is
thrown and so the "Could not retrieve login configuration" log line is
triggered. It looks like the constructor's idea of what constitutes
"I'm going to do SASL" and the cTAIP method's idea differ a bit!
Digging slightly further, the looks like it might be a difference
between openjdk and the Oracle JVM rather than Linux/OSX. On openjdk,
j.s.a.l.Configuration.getConfiguration succeeds on every system I've
tried I've tried (admittedly all debian/ubuntu), but the Oracle JVM
throws a SecurityException.
> thanks
> mahadev
>
> On Tue, Sep 25, 2012 at 3:37 PM, JL <ju...@lycos.com> wrote:
>> This may be related. We are not using SSL, but the underlying cause may be the same: socket disconnection or failure to deliver data from the underlying channel.
>>
>> We experienced connection drops (after about ~3000ms) with Curator 1.1.18 and ZK 3.4.4. on openjdk 6 (on Linux), and JDK 7u7 on OS X.
>>
>> Oracle JVM 1.6.0_32 on Linux and v. 1.6.0_35 on OS X, seem to work.
>>
>> Here's the error we get over and over.
>>
>> E 09-25 17:01:35.408 http-bio-8081-exec-7-EventThread c.n.c.f.i.CuratorFrameworkImpl:486 :::] Background operation retry gave up
>> org.apache.zookeeper.KeeperException$ConnectionLossException: KeeperErrorCode = ConnectionLoss
>> at org.apache.zookeeper.KeeperException.create(KeeperException.java:99) ~[zookeeper-3.4.4.jar:3.4.4-1386507]
>> at com.netflix.curator.framework.imps.CuratorFrameworkImpl.processBackgroundOperation(CuratorFrameworkImpl.java:448) ~[curator-framework-1.1.18.jar:na]
>> at com.netflix.curator.framework.imps.BackgroundSyncImpl$1.processResult(BackgroundSyncImpl.java:49) [curator-framework-1.1.18.jar:na]
>> at org.apache.zookeeper.ClientCnxn$EventThread.processEvent(ClientCnxn.java:606) [zookeeper-3.4.4.jar:3.4.4-1386507]
>> at org.apache.zookeeper.ClientCnxn$EventThread.run(ClientCnxn.java:495) [zookeeper-3.4.4.jar:3.4.4-1386507]
>>
>>
>> Cheers,
>>
>> -Julio
>>
>> Sep 25, 2012 02:45:30 PM, user@zookeeper.apache.org wrote:
>>
>> ===========================================
>>
>> 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=
>> 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=
>> 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
>
Re: SASL problem with 3.4.4 Java client
Posted by JL <ju...@lycos.com>.
This may be related. We are not using SSL, but the underlying cause may be the same: socket disconnection or failure to deliver data from the underlying channel.
We experienced connection drops (after about ~3000ms) with Curator 1.1.18 and ZK 3.4.4. on openjdk 6 (on Linux), and JDK 7u7 on OS X.
Oracle JVM 1.6.0_32 on Linux and v. 1.6.0_35 on OS X, seem to work.
Here's the error we get over and over.
E 09-25 17:01:35.408 http-bio-8081-exec-7-EventThread c.n.c.f.i.CuratorFrameworkImpl:486 :::] Background operation retry gave up
org.apache.zookeeper.KeeperException$ConnectionLossException: KeeperErrorCode = ConnectionLoss
at org.apache.zookeeper.KeeperException.create(KeeperException.java:99) ~[zookeeper-3.4.4.jar:3.4.4-1386507]
at com.netflix.curator.framework.imps.CuratorFrameworkImpl.processBackgroundOperation(CuratorFrameworkImpl.java:448) ~[curator-framework-1.1.18.jar:na]
at com.netflix.curator.framework.imps.BackgroundSyncImpl$1.processResult(BackgroundSyncImpl.java:49) [curator-framework-1.1.18.jar:na]
at org.apache.zookeeper.ClientCnxn$EventThread.processEvent(ClientCnxn.java:606) [zookeeper-3.4.4.jar:3.4.4-1386507]
at org.apache.zookeeper.ClientCnxn$EventThread.run(ClientCnxn.java:495) [zookeeper-3.4.4.jar:3.4.4-1386507]
Cheers,
-Julio
Sep 25, 2012 02:45:30 PM, user@zookeeper.apache.org wrote:
===========================================
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=
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=
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