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 <[email protected]> wrote: > 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 >> >
