zookeeper-user mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Mahadev Konar <maha...@hortonworks.com>
Subject Re: SASL problem with 3.4.4 Java client
Date Wed, 26 Sep 2012 15:08:03 GMT
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 <xbz9el@rojoma.com> wrote:
> 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