On 2012-09-26, Mahadev Konar <[email protected]> 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 <[email protected]> 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, [email protected] 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 >
