zookeeper-user mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Robert Macomber <xbz...@rojoma.com>
Subject Re: SASL problem with 3.4.4 Java client
Date Wed, 26 Sep 2012 13:38:48 GMT
On 2012-09-26, 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.

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 <julio.lopez@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
>


Mime
View raw message