[
https://issues.apache.org/jira/browse/ZOOKEEPER-1534?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Stevo Slavic updated ZOOKEEPER-1534:
------------------------------------
Description:
Server side: zookeeper 3.4.3 with patch ZOOKEEPER-1437.patch 22/Jun/12 00:24
Client side: java, Curator 1.1.15, zookeeper 3.4.3 with patch
ZOOKEEPER-1437.patch 22/Jun/12 00:24
Environment configured to use Sasl authentication.
While the authenticatiion is successful, everything works fine.
In case of authentication failue, it seems that the zk server catch the
SaslException and close the socket without sending any additional notification
to the client, so despite the client has an implementation to handle Sasl
authentication failure, it is never used…
Details:
=========
zk server log:
{noformat}
2012-08-10 11:00:46,730 [myid:] - INFO
[NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxnFactory@213] - Accepted
socket connection from /127.0.0.1:50208
2012-08-10 11:00:46,731 [myid:] - DEBUG
[NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:ZooKeeperServer@780] - Session
establishment request from client /127.0.0.1:50208 client's lastZxid is 0x0
2012-08-10 11:00:46,731 [myid:] - INFO
[NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:ZooKeeperServer@838] - Client
attempting to establish new session at /127.0.0.1:50208
2012-08-10 11:00:46,733 [myid:] - DEBUG [SyncThread:0:FinalRequestProcessor@88]
- Processing request:: sessionid:0x1390fd2ee630004 type:createSession cxid:0x0
zxid:0x26b txntype:-10 reqpath:n/a
2012-08-10 11:00:46,733 [myid:] - DEBUG
[SyncThread:0:FinalRequestProcessor@160] - sessionid:0x1390fd2ee630004
type:createSession cxid:0x0 zxid:0x26b txntype:-10 reqpath:n/a
2012-08-10 11:00:46,734 [myid:] - INFO [SyncThread:0:ZooKeeperServer@604] -
Established session 0x1390fd2ee630004 with negotiated timeout 40000 for client
/127.0.0.1:50208
2012-08-10 11:00:46,736 [myid:] - DEBUG
[NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:ZooKeeperServer@919] - Responding to
client SASL token.
2012-08-10 11:00:46,736 [myid:] - DEBUG
[NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:ZooKeeperServer@923] - Size of
client SASL token: 0
2012-08-10 11:00:46,736 [myid:] - DEBUG
[NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:ZooKeeperServer@954] - Size of
server SASL response: 101
2012-08-10 11:00:46,740 [myid:] - DEBUG
[NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:ZooKeeperServer@919] - Responding to
client SASL token.
2012-08-10 11:00:46,741 [myid:] - DEBUG
[NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:ZooKeeperServer@923] - Size of
client SASL token: 272
2012-08-10 11:00:46,741 [myid:] - DEBUG
[NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:SaslServerCallbackHandler@106] -
client supplied realm: zk-sasl-md5
2012-08-10 11:00:46,741 [myid:] - WARN
[NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:ZooKeeperServer@939] - Client failed
to SASL authenticate: javax.security.sasl.SaslException: DIGEST-MD5: digest
response format violation. Mismatched response.
2012-08-10 11:00:46,742 [myid:] - WARN
[NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:ZooKeeperServer@945] - Closing
client connection due to SASL authentication failure.
2012-08-10 11:00:46,742 [myid:] - INFO
[NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@1000] - Closed socket
connection for client /127.0.0.1:50208 which had sessionid 0x1390fd2ee630004
2012-08-10 11:00:46,743 [myid:] - ERROR
[NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@180] - Unexpected
Exception:
java.nio.channels.CancelledKeyException
at
sun.nio.ch.SelectionKeyImpl.ensureValid(SelectionKeyImpl.java:55)
at
sun.nio.ch.SelectionKeyImpl.interestOps(SelectionKeyImpl.java:59)
at
org.apache.zookeeper.server.NIOServerCnxn.sendBuffer(NIOServerCnxn.java:153)
at
org.apache.zookeeper.server.NIOServerCnxn.sendResponse(NIOServerCnxn.java:1075)
at
org.apache.zookeeper.server.ZooKeeperServer.processPacket(ZooKeeperServer.java:906)
at
org.apache.zookeeper.server.NIOServerCnxn.readRequest(NIOServerCnxn.java:365)
at
org.apache.zookeeper.server.NIOServerCnxn.readPayload(NIOServerCnxn.java:202)
at
org.apache.zookeeper.server.NIOServerCnxn.doIO(NIOServerCnxn.java:236)
at
org.apache.zookeeper.server.NIOServerCnxnFactory.run(NIOServerCnxnFactory.java:224)
at java.lang.Thread.run(Thread.java:662)
{noformat}
At the corresponding source: org.apache.zookeeper.server.ZooKeeperServer
{noformat}
private Record processSasl(ByteBuffer incomingBuffer, ServerCnxn cnxn) throws
IOException {
LOG.debug("Responding to client SASL token.");
GetSASLRequest clientTokenRecord = new GetSASLRequest();
ByteBufferInputStream.byteBuffer2Record(incomingBuffer,clientTokenRecord);
byte[] clientToken = clientTokenRecord.getToken();
LOG.debug("Size of client SASL token: " + clientToken.length);
byte[] responseToken = null;
try {
ZooKeeperSaslServer saslServer = cnxn.zooKeeperSaslServer;
try {
// note that clientToken might be empty (clientToken.length ==
0):
// if using the DIGEST-MD5 mechanism, clientToken will be empty
at the beginning of the
// SASL negotiation process.
responseToken = saslServer.evaluateResponse(clientToken);
if (saslServer.isComplete() == true) {
String authorizationID = saslServer.getAuthorizationID();
LOG.info("adding SASL authorization for authorizationID: "
+ authorizationID);
cnxn.addAuthInfo(new Id("sasl",authorizationID));
}
}
catch (SaslException e) {
LOG.warn("Client failed to SASL authenticate: " + e);
if ((System.getProperty("zookeeper.allowSaslFailedClients") !=
null)
&&
(System.getProperty("zookeeper.allowSaslFailedClients").equals("true"))) {
LOG.warn("Maintaining client connection despite SASL
authentication failure.");
} else {
LOG.warn("Closing client connection due to SASL
authentication failure.");
cnxn.close(); Tally: at this stage the socket is closed
without sending any notification to the client
}
}
}
catch (NullPointerException e) {
LOG.error("cnxn.saslServer is null: cnxn object did not initialize
its saslServer properly.");
}
if (responseToken != null) {
LOG.debug("Size of server SASL response: " + responseToken.length);
}
// wrap SASL response token to client inside a Response object.
return new SetSASLResponse(responseToken);
}
{noformat}
The client log shows that the client identified the socket closer and just
retry to connect as if the zk server just went down..
{noformat}
[10-Aug-2012 11:00:44.558 IST] INFO
<org.apache.zookeeper.ClientCnxn$SendThread> Opening socket connection to
server 127.0.0.1/127.0.0.1:2181
[10-Aug-2012 11:00:44.559 IST] INFO
<org.apache.zookeeper.client.ZooKeeperSaslClient> Found Login Context section
'Client': will use it to attempt to SASL-authenticate.
[10-Aug-2012 11:00:44.560 IST] INFO
<org.apache.zookeeper.client.ZooKeeperSaslClient> Client will use DIGEST-MD5 as
SASL mechanism.
[10-Aug-2012 11:00:44.561 IST] INFO
<org.apache.zookeeper.ClientCnxn$SendThread> Socket connection established to
127.0.0.1/127.0.0.1:2181, initiating session
[10-Aug-2012 11:00:44.563 IST] DEBUG
<org.apache.zookeeper.ClientCnxn$SendThread> Session establishment request sent
on 127.0.0.1/127.0.0.1:2181
[10-Aug-2012 11:00:44.564 IST] DEBUG <org.apache.zookeeper.ClientCnxnSocketNIO>
deferring non-priming packet: clientPath:null serverPath:null finished:false
header:: 0,3 replyHeader:: 0,0,0 request:: '/dev,F response:: until SASL
authentication completes.
[10-Aug-2012 11:00:44.566 IST] DEBUG <org.apache.zookeeper.ClientCnxnSocketNIO>
deferring non-priming packet: clientPath:/ serverPath:/ finished:false header::
0,9 replyHeader:: 0,0,0 request:: '/ response:: until SASL authentication
completes.
[10-Aug-2012 11:00:44.568 IST] INFO
<org.apache.zookeeper.ClientCnxn$SendThread> Session establishment complete on
server 127.0.0.1/127.0.0.1:2181, sessionid = 0x1390fd2ee630003, negotiated
timeout = 40000
[10-Aug-2012 11:00:44.569 IST] INFO
<com.netflix.curator.framework.state.ConnectionStateManager> State change:
RECONNECTED
[10-Aug-2012 11:00:44.569 IST] DEBUG <org.apache.zookeeper.ClientCnxnSocketNIO>
deferring non-priming packet: clientPath:null serverPath:null finished:false
header:: 0,3 replyHeader:: 0,0,0 request:: '/dev,F response:: until SASL
authentication completes.
[10-Aug-2012 11:00:44.572 IST] DEBUG <org.apache.zookeeper.ClientCnxnSocketNIO>
deferring non-priming packet: clientPath:/ serverPath:/ finished:false header::
0,9 replyHeader:: 0,0,0 request:: '/ response:: until SASL authentication
completes.
[10-Aug-2012 11:00:44.574 IST] DEBUG <org.apache.zookeeper.ClientCnxnSocketNIO>
deferring non-priming packet: clientPath:null serverPath:null finished:false
header:: 0,3 replyHeader:: 0,0,0 request:: '/dev,F response:: until SASL
authentication completes.
[10-Aug-2012 11:00:44.576 IST] DEBUG <org.apache.zookeeper.ClientCnxnSocketNIO>
deferring non-priming packet: clientPath:/ serverPath:/ finished:false header::
0,9 replyHeader:: 0,0,0 request:: '/ response:: until SASL authentication
completes.
[10-Aug-2012 11:00:44.578 IST] DEBUG
<org.apache.zookeeper.client.ZooKeeperSaslClient>
ClientCnxn:sendSaslPacket:length=0
[10-Aug-2012 11:00:44.579 IST] DEBUG <org.apache.zookeeper.ClientCnxnSocketNIO>
deferring non-priming packet: clientPath:null serverPath:null finished:false
header:: 0,3 replyHeader:: 0,0,0 request:: '/dev,F response:: until SASL
authentication completes.
[10-Aug-2012 11:00:44.581 IST] DEBUG <org.apache.zookeeper.ClientCnxnSocketNIO>
deferring non-priming packet: clientPath:/ serverPath:/ finished:false header::
0,9 replyHeader:: 0,0,0 request:: '/ response:: until SASL authentication
completes.
[10-Aug-2012 11:00:44.583 IST] DEBUG <org.apache.zookeeper.ClientCnxnSocketNIO>
deferring non-priming packet: clientPath:/ serverPath:/ finished:false header::
0,9 replyHeader:: 0,0,0 request:: '/ response:: until SASL authentication
completes.
[10-Aug-2012 11:00:44.585 IST] DEBUG <org.apache.zookeeper.ClientCnxnSocketNIO>
deferring non-priming packet: clientPath:null serverPath:null finished:false
header:: 0,3 replyHeader:: 0,0,0 request:: '/dev,F response:: until SASL
authentication completes.
[10-Aug-2012 11:00:44.587 IST] DEBUG <org.apache.zookeeper.ClientCnxnSocketNIO>
deferring non-priming packet: clientPath:/ serverPath:/ finished:false header::
0,9 replyHeader:: 0,0,0 request:: '/ response:: until SASL authentication
completes.
[10-Aug-2012 11:00:44.589 IST] DEBUG <org.apache.zookeeper.ClientCnxnSocketNIO>
deferring non-priming packet: clientPath:/ serverPath:/ finished:false header::
0,9 replyHeader:: 0,0,0 request:: '/ response:: until SASL authentication
completes.
[10-Aug-2012 11:00:44.591 IST] DEBUG
<org.apache.zookeeper.client.ZooKeeperSaslClient$2>
saslClient.evaluateChallenge(len=101)
[10-Aug-2012 11:00:44.592 IST] DEBUG
<org.apache.zookeeper.client.ZooKeeperSaslClient>
ClientCnxn:sendSaslPacket:length=272
[10-Aug-2012 11:00:44.593 IST] DEBUG <org.apache.zookeeper.ClientCnxnSocketNIO>
deferring non-priming packet: clientPath:null serverPath:null finished:false
header:: 0,3 replyHeader:: 0,0,0 request:: '/dev,F response:: until SASL
authentication completes.
[10-Aug-2012 11:00:44.596 IST] DEBUG <org.apache.zookeeper.ClientCnxnSocketNIO>
deferring non-priming packet: clientPath:/ serverPath:/ finished:false header::
0,9 replyHeader:: 0,0,0 request:: '/ response:: until SASL authentication
completes.
[10-Aug-2012 11:00:44.598 IST] DEBUG <org.apache.zookeeper.ClientCnxnSocketNIO>
deferring non-priming packet: clientPath:/ serverPath:/ finished:false header::
0,9 replyHeader:: 0,0,0 request:: '/ response:: until SASL authentication
completes.
[10-Aug-2012 11:00:44.600 IST] INFO
<org.apache.zookeeper.ClientCnxn$SendThread> Unable to read additional data
from server sessionid 0x1390fd2ee630003, likely server has closed socket,
closing socket connection and attempting reconnect
[10-Aug-2012 11:00:44.701 IST] ERROR
<com.netflix.curator.framework.imps.CuratorFrameworkImpl> Background operation
retry gave up
org.apache.zookeeper.KeeperException$ConnectionLossException: KeeperErrorCode =
ConnectionLoss
at
org.apache.zookeeper.KeeperException.create(KeeperException.java:99)
at
com.netflix.curator.framework.imps.CuratorFrameworkImpl.processBackgroundOperation(CuratorFrameworkImpl.java:438)
at
com.netflix.curator.framework.imps.BackgroundSyncImpl$1.processResult(BackgroundSyncImpl.java:49)
at
org.apache.zookeeper.ClientCnxn$EventThread.processEvent(ClientCnxn.java:606)
at
org.apache.zookeeper.ClientCnxn$EventThread.run(ClientCnxn.java:495)
[10-Aug-2012 11:00:44.706 IST] INFO
<com.netflix.curator.framework.state.ConnectionStateManager> State change: LOST
[10-Aug-2012 11:00:44.708 IST] WARN
<com.netflix.curator.framework.state.ConnectionStateManager>
ConnectionStateManager queue full - dropping events to make room
[10-Aug-2012 11:00:44.710 IST] INFO
<com.netflix.curator.framework.state.ConnectionStateManager> State change:
SUSPENDED
{noformat}
was:
Server side: zookeeper 3.4.3 with patch ZOOKEEPER-1437.patch 22/Jun/12 00:24
Client side: java, Curator 1.1.15, zookeeper 3.4.3 with patch
ZOOKEEPER-1437.patch 22/Jun/12 00:24
Environment configured to use Sasl authentication.
While the authenticatiion is successful, everything works fine.
In case of authentication failue, it seems that the zk server catch the
SaslException and close the socket without sending any additional notification
to the client, so despite the client has an implementation to handle Sasl
authentication failure, it is never used…
Details:
=========
zk server log:
2012-08-10 11:00:46,730 [myid:] - INFO
[NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxnFactory@213] - Accepted
socket connection from /127.0.0.1:50208
2012-08-10 11:00:46,731 [myid:] - DEBUG
[NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:ZooKeeperServer@780] - Session
establishment request from client /127.0.0.1:50208 client's lastZxid is 0x0
2012-08-10 11:00:46,731 [myid:] - INFO
[NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:ZooKeeperServer@838] - Client
attempting to establish new session at /127.0.0.1:50208
2012-08-10 11:00:46,733 [myid:] - DEBUG [SyncThread:0:FinalRequestProcessor@88]
- Processing request:: sessionid:0x1390fd2ee630004 type:createSession cxid:0x0
zxid:0x26b txntype:-10 reqpath:n/a
2012-08-10 11:00:46,733 [myid:] - DEBUG
[SyncThread:0:FinalRequestProcessor@160] - sessionid:0x1390fd2ee630004
type:createSession cxid:0x0 zxid:0x26b txntype:-10 reqpath:n/a
2012-08-10 11:00:46,734 [myid:] - INFO [SyncThread:0:ZooKeeperServer@604] -
Established session 0x1390fd2ee630004 with negotiated timeout 40000 for client
/127.0.0.1:50208
2012-08-10 11:00:46,736 [myid:] - DEBUG
[NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:ZooKeeperServer@919] - Responding to
client SASL token.
2012-08-10 11:00:46,736 [myid:] - DEBUG
[NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:ZooKeeperServer@923] - Size of
client SASL token: 0
2012-08-10 11:00:46,736 [myid:] - DEBUG
[NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:ZooKeeperServer@954] - Size of
server SASL response: 101
2012-08-10 11:00:46,740 [myid:] - DEBUG
[NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:ZooKeeperServer@919] - Responding to
client SASL token.
2012-08-10 11:00:46,741 [myid:] - DEBUG
[NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:ZooKeeperServer@923] - Size of
client SASL token: 272
2012-08-10 11:00:46,741 [myid:] - DEBUG
[NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:SaslServerCallbackHandler@106] -
client supplied realm: zk-sasl-md5
2012-08-10 11:00:46,741 [myid:] - WARN
[NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:ZooKeeperServer@939] - Client failed
to SASL authenticate: javax.security.sasl.SaslException: DIGEST-MD5: digest
response format violation. Mismatched response.
2012-08-10 11:00:46,742 [myid:] - WARN
[NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:ZooKeeperServer@945] - Closing
client connection due to SASL authentication failure.
2012-08-10 11:00:46,742 [myid:] - INFO
[NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@1000] - Closed socket
connection for client /127.0.0.1:50208 which had sessionid 0x1390fd2ee630004
2012-08-10 11:00:46,743 [myid:] - ERROR
[NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@180] - Unexpected
Exception:
java.nio.channels.CancelledKeyException
at
sun.nio.ch.SelectionKeyImpl.ensureValid(SelectionKeyImpl.java:55)
at
sun.nio.ch.SelectionKeyImpl.interestOps(SelectionKeyImpl.java:59)
at
org.apache.zookeeper.server.NIOServerCnxn.sendBuffer(NIOServerCnxn.java:153)
at
org.apache.zookeeper.server.NIOServerCnxn.sendResponse(NIOServerCnxn.java:1075)
at
org.apache.zookeeper.server.ZooKeeperServer.processPacket(ZooKeeperServer.java:906)
at
org.apache.zookeeper.server.NIOServerCnxn.readRequest(NIOServerCnxn.java:365)
at
org.apache.zookeeper.server.NIOServerCnxn.readPayload(NIOServerCnxn.java:202)
at
org.apache.zookeeper.server.NIOServerCnxn.doIO(NIOServerCnxn.java:236)
at
org.apache.zookeeper.server.NIOServerCnxnFactory.run(NIOServerCnxnFactory.java:224)
at java.lang.Thread.run(Thread.java:662)
At the corresponding source: org.apache.zookeeper.server.ZooKeeperServer
private Record processSasl(ByteBuffer incomingBuffer, ServerCnxn cnxn) throws
IOException {
LOG.debug("Responding to client SASL token.");
GetSASLRequest clientTokenRecord = new GetSASLRequest();
ByteBufferInputStream.byteBuffer2Record(incomingBuffer,clientTokenRecord);
byte[] clientToken = clientTokenRecord.getToken();
LOG.debug("Size of client SASL token: " + clientToken.length);
byte[] responseToken = null;
try {
ZooKeeperSaslServer saslServer = cnxn.zooKeeperSaslServer;
try {
// note that clientToken might be empty (clientToken.length ==
0):
// if using the DIGEST-MD5 mechanism, clientToken will be empty
at the beginning of the
// SASL negotiation process.
responseToken = saslServer.evaluateResponse(clientToken);
if (saslServer.isComplete() == true) {
String authorizationID = saslServer.getAuthorizationID();
LOG.info("adding SASL authorization for authorizationID: "
+ authorizationID);
cnxn.addAuthInfo(new Id("sasl",authorizationID));
}
}
catch (SaslException e) {
LOG.warn("Client failed to SASL authenticate: " + e);
if ((System.getProperty("zookeeper.allowSaslFailedClients") !=
null)
&&
(System.getProperty("zookeeper.allowSaslFailedClients").equals("true"))) {
LOG.warn("Maintaining client connection despite SASL
authentication failure.");
} else {
LOG.warn("Closing client connection due to SASL
authentication failure.");
cnxn.close(); Tally: at this stage the socket is closed
without sending any notification to the client
}
}
}
catch (NullPointerException e) {
LOG.error("cnxn.saslServer is null: cnxn object did not initialize
its saslServer properly.");
}
if (responseToken != null) {
LOG.debug("Size of server SASL response: " + responseToken.length);
}
// wrap SASL response token to client inside a Response object.
return new SetSASLResponse(responseToken);
}
The client log shows that the client identified the socket closer and just
retry to connect as if the zk server just went down..
[10-Aug-2012 11:00:44.558 IST] INFO
<org.apache.zookeeper.ClientCnxn$SendThread> Opening socket connection to
server 127.0.0.1/127.0.0.1:2181
[10-Aug-2012 11:00:44.559 IST] INFO
<org.apache.zookeeper.client.ZooKeeperSaslClient> Found Login Context section
'Client': will use it to attempt to SASL-authenticate.
[10-Aug-2012 11:00:44.560 IST] INFO
<org.apache.zookeeper.client.ZooKeeperSaslClient> Client will use DIGEST-MD5 as
SASL mechanism.
[10-Aug-2012 11:00:44.561 IST] INFO
<org.apache.zookeeper.ClientCnxn$SendThread> Socket connection established to
127.0.0.1/127.0.0.1:2181, initiating session
[10-Aug-2012 11:00:44.563 IST] DEBUG
<org.apache.zookeeper.ClientCnxn$SendThread> Session establishment request sent
on 127.0.0.1/127.0.0.1:2181
[10-Aug-2012 11:00:44.564 IST] DEBUG <org.apache.zookeeper.ClientCnxnSocketNIO>
deferring non-priming packet: clientPath:null serverPath:null finished:false
header:: 0,3 replyHeader:: 0,0,0 request:: '/dev,F response:: until SASL
authentication completes.
[10-Aug-2012 11:00:44.566 IST] DEBUG <org.apache.zookeeper.ClientCnxnSocketNIO>
deferring non-priming packet: clientPath:/ serverPath:/ finished:false header::
0,9 replyHeader:: 0,0,0 request:: '/ response:: until SASL authentication
completes.
[10-Aug-2012 11:00:44.568 IST] INFO
<org.apache.zookeeper.ClientCnxn$SendThread> Session establishment complete on
server 127.0.0.1/127.0.0.1:2181, sessionid = 0x1390fd2ee630003, negotiated
timeout = 40000
[10-Aug-2012 11:00:44.569 IST] INFO
<com.netflix.curator.framework.state.ConnectionStateManager> State change:
RECONNECTED
[10-Aug-2012 11:00:44.569 IST] DEBUG <org.apache.zookeeper.ClientCnxnSocketNIO>
deferring non-priming packet: clientPath:null serverPath:null finished:false
header:: 0,3 replyHeader:: 0,0,0 request:: '/dev,F response:: until SASL
authentication completes.
[10-Aug-2012 11:00:44.572 IST] DEBUG <org.apache.zookeeper.ClientCnxnSocketNIO>
deferring non-priming packet: clientPath:/ serverPath:/ finished:false header::
0,9 replyHeader:: 0,0,0 request:: '/ response:: until SASL authentication
completes.
[10-Aug-2012 11:00:44.574 IST] DEBUG <org.apache.zookeeper.ClientCnxnSocketNIO>
deferring non-priming packet: clientPath:null serverPath:null finished:false
header:: 0,3 replyHeader:: 0,0,0 request:: '/dev,F response:: until SASL
authentication completes.
[10-Aug-2012 11:00:44.576 IST] DEBUG <org.apache.zookeeper.ClientCnxnSocketNIO>
deferring non-priming packet: clientPath:/ serverPath:/ finished:false header::
0,9 replyHeader:: 0,0,0 request:: '/ response:: until SASL authentication
completes.
[10-Aug-2012 11:00:44.578 IST] DEBUG
<org.apache.zookeeper.client.ZooKeeperSaslClient>
ClientCnxn:sendSaslPacket:length=0
[10-Aug-2012 11:00:44.579 IST] DEBUG <org.apache.zookeeper.ClientCnxnSocketNIO>
deferring non-priming packet: clientPath:null serverPath:null finished:false
header:: 0,3 replyHeader:: 0,0,0 request:: '/dev,F response:: until SASL
authentication completes.
[10-Aug-2012 11:00:44.581 IST] DEBUG <org.apache.zookeeper.ClientCnxnSocketNIO>
deferring non-priming packet: clientPath:/ serverPath:/ finished:false header::
0,9 replyHeader:: 0,0,0 request:: '/ response:: until SASL authentication
completes.
[10-Aug-2012 11:00:44.583 IST] DEBUG <org.apache.zookeeper.ClientCnxnSocketNIO>
deferring non-priming packet: clientPath:/ serverPath:/ finished:false header::
0,9 replyHeader:: 0,0,0 request:: '/ response:: until SASL authentication
completes.
[10-Aug-2012 11:00:44.585 IST] DEBUG <org.apache.zookeeper.ClientCnxnSocketNIO>
deferring non-priming packet: clientPath:null serverPath:null finished:false
header:: 0,3 replyHeader:: 0,0,0 request:: '/dev,F response:: until SASL
authentication completes.
[10-Aug-2012 11:00:44.587 IST] DEBUG <org.apache.zookeeper.ClientCnxnSocketNIO>
deferring non-priming packet: clientPath:/ serverPath:/ finished:false header::
0,9 replyHeader:: 0,0,0 request:: '/ response:: until SASL authentication
completes.
[10-Aug-2012 11:00:44.589 IST] DEBUG <org.apache.zookeeper.ClientCnxnSocketNIO>
deferring non-priming packet: clientPath:/ serverPath:/ finished:false header::
0,9 replyHeader:: 0,0,0 request:: '/ response:: until SASL authentication
completes.
[10-Aug-2012 11:00:44.591 IST] DEBUG
<org.apache.zookeeper.client.ZooKeeperSaslClient$2>
saslClient.evaluateChallenge(len=101)
[10-Aug-2012 11:00:44.592 IST] DEBUG
<org.apache.zookeeper.client.ZooKeeperSaslClient>
ClientCnxn:sendSaslPacket:length=272
[10-Aug-2012 11:00:44.593 IST] DEBUG <org.apache.zookeeper.ClientCnxnSocketNIO>
deferring non-priming packet: clientPath:null serverPath:null finished:false
header:: 0,3 replyHeader:: 0,0,0 request:: '/dev,F response:: until SASL
authentication completes.
[10-Aug-2012 11:00:44.596 IST] DEBUG <org.apache.zookeeper.ClientCnxnSocketNIO>
deferring non-priming packet: clientPath:/ serverPath:/ finished:false header::
0,9 replyHeader:: 0,0,0 request:: '/ response:: until SASL authentication
completes.
[10-Aug-2012 11:00:44.598 IST] DEBUG <org.apache.zookeeper.ClientCnxnSocketNIO>
deferring non-priming packet: clientPath:/ serverPath:/ finished:false header::
0,9 replyHeader:: 0,0,0 request:: '/ response:: until SASL authentication
completes.
[10-Aug-2012 11:00:44.600 IST] INFO
<org.apache.zookeeper.ClientCnxn$SendThread> Unable to read additional data
from server sessionid 0x1390fd2ee630003, likely server has closed socket,
closing socket connection and attempting reconnect
[10-Aug-2012 11:00:44.701 IST] ERROR
<com.netflix.curator.framework.imps.CuratorFrameworkImpl> Background operation
retry gave up
org.apache.zookeeper.KeeperException$ConnectionLossException: KeeperErrorCode =
ConnectionLoss
at
org.apache.zookeeper.KeeperException.create(KeeperException.java:99)
at
com.netflix.curator.framework.imps.CuratorFrameworkImpl.processBackgroundOperation(CuratorFrameworkImpl.java:438)
at
com.netflix.curator.framework.imps.BackgroundSyncImpl$1.processResult(BackgroundSyncImpl.java:49)
at
org.apache.zookeeper.ClientCnxn$EventThread.processEvent(ClientCnxn.java:606)
at
org.apache.zookeeper.ClientCnxn$EventThread.run(ClientCnxn.java:495)
[10-Aug-2012 11:00:44.706 IST] INFO
<com.netflix.curator.framework.state.ConnectionStateManager> State change: LOST
[10-Aug-2012 11:00:44.708 IST] WARN
<com.netflix.curator.framework.state.ConnectionStateManager>
ConnectionStateManager queue full - dropping events to make room
[10-Aug-2012 11:00:44.710 IST] INFO
<com.netflix.curator.framework.state.ConnectionStateManager> State change:
SUSPENDED
> Zookeeper server do not send Sal authentication failure notification to the
> client
> ----------------------------------------------------------------------------------
>
> Key: ZOOKEEPER-1534
> URL: https://issues.apache.org/jira/browse/ZOOKEEPER-1534
> Project: ZooKeeper
> Issue Type: Bug
> Components: server
> Affects Versions: 3.4.3
> Environment: Windows 7. Zookeeper 3.4.3 Curator 1.1.15 Java 1.6
> Reporter: Tally Tsabary
>
> Server side: zookeeper 3.4.3 with patch ZOOKEEPER-1437.patch 22/Jun/12 00:24
> Client side: java, Curator 1.1.15, zookeeper 3.4.3 with patch
> ZOOKEEPER-1437.patch 22/Jun/12 00:24
> Environment configured to use Sasl authentication.
> While the authenticatiion is successful, everything works fine.
> In case of authentication failue, it seems that the zk server catch the
> SaslException and close the socket without sending any additional
> notification to the client, so despite the client has an implementation to
> handle Sasl authentication failure, it is never used…
>
> Details:
> =========
>
>
> zk server log:
> {noformat}
> 2012-08-10 11:00:46,730 [myid:] - INFO
> [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxnFactory@213] -
> Accepted socket connection from /127.0.0.1:50208
> 2012-08-10 11:00:46,731 [myid:] - DEBUG
> [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:ZooKeeperServer@780] - Session
> establishment request from client /127.0.0.1:50208 client's lastZxid is 0x0
> 2012-08-10 11:00:46,731 [myid:] - INFO
> [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:ZooKeeperServer@838] - Client
> attempting to establish new session at /127.0.0.1:50208
> 2012-08-10 11:00:46,733 [myid:] - DEBUG
> [SyncThread:0:FinalRequestProcessor@88] - Processing request::
> sessionid:0x1390fd2ee630004 type:createSession cxid:0x0 zxid:0x26b
> txntype:-10 reqpath:n/a
> 2012-08-10 11:00:46,733 [myid:] - DEBUG
> [SyncThread:0:FinalRequestProcessor@160] - sessionid:0x1390fd2ee630004
> type:createSession cxid:0x0 zxid:0x26b txntype:-10 reqpath:n/a
> 2012-08-10 11:00:46,734 [myid:] - INFO [SyncThread:0:ZooKeeperServer@604] -
> Established session 0x1390fd2ee630004 with negotiated timeout 40000 for
> client /127.0.0.1:50208
> 2012-08-10 11:00:46,736 [myid:] - DEBUG
> [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:ZooKeeperServer@919] - Responding
> to client SASL token.
> 2012-08-10 11:00:46,736 [myid:] - DEBUG
> [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:ZooKeeperServer@923] - Size of
> client SASL token: 0
> 2012-08-10 11:00:46,736 [myid:] - DEBUG
> [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:ZooKeeperServer@954] - Size of
> server SASL response: 101
> 2012-08-10 11:00:46,740 [myid:] - DEBUG
> [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:ZooKeeperServer@919] - Responding
> to client SASL token.
> 2012-08-10 11:00:46,741 [myid:] - DEBUG
> [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:ZooKeeperServer@923] - Size of
> client SASL token: 272
> 2012-08-10 11:00:46,741 [myid:] - DEBUG
> [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:SaslServerCallbackHandler@106] -
> client supplied realm: zk-sasl-md5
> 2012-08-10 11:00:46,741 [myid:] - WARN
> [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:ZooKeeperServer@939] - Client
> failed to SASL authenticate: javax.security.sasl.SaslException: DIGEST-MD5:
> digest response format violation. Mismatched response.
> 2012-08-10 11:00:46,742 [myid:] - WARN
> [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:ZooKeeperServer@945] - Closing
> client connection due to SASL authentication failure.
> 2012-08-10 11:00:46,742 [myid:] - INFO
> [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@1000] - Closed
> socket connection for client /127.0.0.1:50208 which had sessionid
> 0x1390fd2ee630004
> 2012-08-10 11:00:46,743 [myid:] - ERROR
> [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@180] - Unexpected
> Exception:
> java.nio.channels.CancelledKeyException
> at
> sun.nio.ch.SelectionKeyImpl.ensureValid(SelectionKeyImpl.java:55)
> at
> sun.nio.ch.SelectionKeyImpl.interestOps(SelectionKeyImpl.java:59)
> at
> org.apache.zookeeper.server.NIOServerCnxn.sendBuffer(NIOServerCnxn.java:153)
> at
> org.apache.zookeeper.server.NIOServerCnxn.sendResponse(NIOServerCnxn.java:1075)
> at
> org.apache.zookeeper.server.ZooKeeperServer.processPacket(ZooKeeperServer.java:906)
> at
> org.apache.zookeeper.server.NIOServerCnxn.readRequest(NIOServerCnxn.java:365)
> at
> org.apache.zookeeper.server.NIOServerCnxn.readPayload(NIOServerCnxn.java:202)
> at
> org.apache.zookeeper.server.NIOServerCnxn.doIO(NIOServerCnxn.java:236)
> at
> org.apache.zookeeper.server.NIOServerCnxnFactory.run(NIOServerCnxnFactory.java:224)
> at java.lang.Thread.run(Thread.java:662)
> {noformat}
>
> At the corresponding source: org.apache.zookeeper.server.ZooKeeperServer
>
> {noformat}
> private Record processSasl(ByteBuffer incomingBuffer, ServerCnxn cnxn) throws
> IOException {
> LOG.debug("Responding to client SASL token.");
> GetSASLRequest clientTokenRecord = new GetSASLRequest();
>
> ByteBufferInputStream.byteBuffer2Record(incomingBuffer,clientTokenRecord);
> byte[] clientToken = clientTokenRecord.getToken();
> LOG.debug("Size of client SASL token: " + clientToken.length);
> byte[] responseToken = null;
> try {
> ZooKeeperSaslServer saslServer = cnxn.zooKeeperSaslServer;
> try {
> // note that clientToken might be empty (clientToken.length
> == 0):
> // if using the DIGEST-MD5 mechanism, clientToken will be
> empty at the beginning of the
> // SASL negotiation process.
> responseToken = saslServer.evaluateResponse(clientToken);
> if (saslServer.isComplete() == true) {
> String authorizationID = saslServer.getAuthorizationID();
> LOG.info("adding SASL authorization for authorizationID:
> " + authorizationID);
> cnxn.addAuthInfo(new Id("sasl",authorizationID));
> }
> }
> catch (SaslException e) {
> LOG.warn("Client failed to SASL authenticate: " + e);
> if ((System.getProperty("zookeeper.allowSaslFailedClients")
> != null)
> &&
>
> (System.getProperty("zookeeper.allowSaslFailedClients").equals("true"))) {
> LOG.warn("Maintaining client connection despite SASL
> authentication failure.");
> } else {
> LOG.warn("Closing client connection due to SASL
> authentication failure.");
> cnxn.close(); Tally: at this stage the socket is closed
> without sending any notification to the client
> }
> }
> }
> catch (NullPointerException e) {
> LOG.error("cnxn.saslServer is null: cnxn object did not
> initialize its saslServer properly.");
> }
> if (responseToken != null) {
> LOG.debug("Size of server SASL response: " +
> responseToken.length);
> }
> // wrap SASL response token to client inside a Response object.
> return new SetSASLResponse(responseToken);
> }
> {noformat}
>
>
> The client log shows that the client identified the socket closer and just
> retry to connect as if the zk server just went down..
> {noformat}
> [10-Aug-2012 11:00:44.558 IST] INFO
> <org.apache.zookeeper.ClientCnxn$SendThread> Opening socket connection to
> server 127.0.0.1/127.0.0.1:2181
> [10-Aug-2012 11:00:44.559 IST] INFO
> <org.apache.zookeeper.client.ZooKeeperSaslClient> Found Login Context section
> 'Client': will use it to attempt to SASL-authenticate.
> [10-Aug-2012 11:00:44.560 IST] INFO
> <org.apache.zookeeper.client.ZooKeeperSaslClient> Client will use DIGEST-MD5
> as SASL mechanism.
> [10-Aug-2012 11:00:44.561 IST] INFO
> <org.apache.zookeeper.ClientCnxn$SendThread> Socket connection established to
> 127.0.0.1/127.0.0.1:2181, initiating session
> [10-Aug-2012 11:00:44.563 IST] DEBUG
> <org.apache.zookeeper.ClientCnxn$SendThread> Session establishment request
> sent on 127.0.0.1/127.0.0.1:2181
> [10-Aug-2012 11:00:44.564 IST] DEBUG
> <org.apache.zookeeper.ClientCnxnSocketNIO> deferring non-priming packet:
> clientPath:null serverPath:null finished:false header:: 0,3 replyHeader::
> 0,0,0 request:: '/dev,F response:: until SASL authentication completes.
> [10-Aug-2012 11:00:44.566 IST] DEBUG
> <org.apache.zookeeper.ClientCnxnSocketNIO> deferring non-priming packet:
> clientPath:/ serverPath:/ finished:false header:: 0,9 replyHeader:: 0,0,0
> request:: '/ response:: until SASL authentication completes.
> [10-Aug-2012 11:00:44.568 IST] INFO
> <org.apache.zookeeper.ClientCnxn$SendThread> Session establishment complete
> on server 127.0.0.1/127.0.0.1:2181, sessionid = 0x1390fd2ee630003, negotiated
> timeout = 40000
> [10-Aug-2012 11:00:44.569 IST] INFO
> <com.netflix.curator.framework.state.ConnectionStateManager> State change:
> RECONNECTED
> [10-Aug-2012 11:00:44.569 IST] DEBUG
> <org.apache.zookeeper.ClientCnxnSocketNIO> deferring non-priming packet:
> clientPath:null serverPath:null finished:false header:: 0,3 replyHeader::
> 0,0,0 request:: '/dev,F response:: until SASL authentication completes.
> [10-Aug-2012 11:00:44.572 IST] DEBUG
> <org.apache.zookeeper.ClientCnxnSocketNIO> deferring non-priming packet:
> clientPath:/ serverPath:/ finished:false header:: 0,9 replyHeader:: 0,0,0
> request:: '/ response:: until SASL authentication completes.
> [10-Aug-2012 11:00:44.574 IST] DEBUG
> <org.apache.zookeeper.ClientCnxnSocketNIO> deferring non-priming packet:
> clientPath:null serverPath:null finished:false header:: 0,3 replyHeader::
> 0,0,0 request:: '/dev,F response:: until SASL authentication completes.
> [10-Aug-2012 11:00:44.576 IST] DEBUG
> <org.apache.zookeeper.ClientCnxnSocketNIO> deferring non-priming packet:
> clientPath:/ serverPath:/ finished:false header:: 0,9 replyHeader:: 0,0,0
> request:: '/ response:: until SASL authentication completes.
> [10-Aug-2012 11:00:44.578 IST] DEBUG
> <org.apache.zookeeper.client.ZooKeeperSaslClient>
> ClientCnxn:sendSaslPacket:length=0
> [10-Aug-2012 11:00:44.579 IST] DEBUG
> <org.apache.zookeeper.ClientCnxnSocketNIO> deferring non-priming packet:
> clientPath:null serverPath:null finished:false header:: 0,3 replyHeader::
> 0,0,0 request:: '/dev,F response:: until SASL authentication completes.
> [10-Aug-2012 11:00:44.581 IST] DEBUG
> <org.apache.zookeeper.ClientCnxnSocketNIO> deferring non-priming packet:
> clientPath:/ serverPath:/ finished:false header:: 0,9 replyHeader:: 0,0,0
> request:: '/ response:: until SASL authentication completes.
> [10-Aug-2012 11:00:44.583 IST] DEBUG
> <org.apache.zookeeper.ClientCnxnSocketNIO> deferring non-priming packet:
> clientPath:/ serverPath:/ finished:false header:: 0,9 replyHeader:: 0,0,0
> request:: '/ response:: until SASL authentication completes.
> [10-Aug-2012 11:00:44.585 IST] DEBUG
> <org.apache.zookeeper.ClientCnxnSocketNIO> deferring non-priming packet:
> clientPath:null serverPath:null finished:false header:: 0,3 replyHeader::
> 0,0,0 request:: '/dev,F response:: until SASL authentication completes.
> [10-Aug-2012 11:00:44.587 IST] DEBUG
> <org.apache.zookeeper.ClientCnxnSocketNIO> deferring non-priming packet:
> clientPath:/ serverPath:/ finished:false header:: 0,9 replyHeader:: 0,0,0
> request:: '/ response:: until SASL authentication completes.
> [10-Aug-2012 11:00:44.589 IST] DEBUG
> <org.apache.zookeeper.ClientCnxnSocketNIO> deferring non-priming packet:
> clientPath:/ serverPath:/ finished:false header:: 0,9 replyHeader:: 0,0,0
> request:: '/ response:: until SASL authentication completes.
> [10-Aug-2012 11:00:44.591 IST] DEBUG
> <org.apache.zookeeper.client.ZooKeeperSaslClient$2>
> saslClient.evaluateChallenge(len=101)
> [10-Aug-2012 11:00:44.592 IST] DEBUG
> <org.apache.zookeeper.client.ZooKeeperSaslClient>
> ClientCnxn:sendSaslPacket:length=272
> [10-Aug-2012 11:00:44.593 IST] DEBUG
> <org.apache.zookeeper.ClientCnxnSocketNIO> deferring non-priming packet:
> clientPath:null serverPath:null finished:false header:: 0,3 replyHeader::
> 0,0,0 request:: '/dev,F response:: until SASL authentication completes.
> [10-Aug-2012 11:00:44.596 IST] DEBUG
> <org.apache.zookeeper.ClientCnxnSocketNIO> deferring non-priming packet:
> clientPath:/ serverPath:/ finished:false header:: 0,9 replyHeader:: 0,0,0
> request:: '/ response:: until SASL authentication completes.
> [10-Aug-2012 11:00:44.598 IST] DEBUG
> <org.apache.zookeeper.ClientCnxnSocketNIO> deferring non-priming packet:
> clientPath:/ serverPath:/ finished:false header:: 0,9 replyHeader:: 0,0,0
> request:: '/ response:: until SASL authentication completes.
> [10-Aug-2012 11:00:44.600 IST] INFO
> <org.apache.zookeeper.ClientCnxn$SendThread> Unable to read additional data
> from server sessionid 0x1390fd2ee630003, likely server has closed socket,
> closing socket connection and attempting reconnect
> [10-Aug-2012 11:00:44.701 IST] ERROR
> <com.netflix.curator.framework.imps.CuratorFrameworkImpl> Background
> operation retry gave up
> org.apache.zookeeper.KeeperException$ConnectionLossException: KeeperErrorCode
> = ConnectionLoss
> at
> org.apache.zookeeper.KeeperException.create(KeeperException.java:99)
> at
> com.netflix.curator.framework.imps.CuratorFrameworkImpl.processBackgroundOperation(CuratorFrameworkImpl.java:438)
> at
> com.netflix.curator.framework.imps.BackgroundSyncImpl$1.processResult(BackgroundSyncImpl.java:49)
> at
> org.apache.zookeeper.ClientCnxn$EventThread.processEvent(ClientCnxn.java:606)
> at
> org.apache.zookeeper.ClientCnxn$EventThread.run(ClientCnxn.java:495)
> [10-Aug-2012 11:00:44.706 IST] INFO
> <com.netflix.curator.framework.state.ConnectionStateManager> State change:
> LOST
> [10-Aug-2012 11:00:44.708 IST] WARN
> <com.netflix.curator.framework.state.ConnectionStateManager>
> ConnectionStateManager queue full - dropping events to make room
> [10-Aug-2012 11:00:44.710 IST] INFO
> <com.netflix.curator.framework.state.ConnectionStateManager> State change:
> SUSPENDED
> {noformat}
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
