got logging works in my IDE. highlight'ed the reason (in red) why server close/refuse session request. I don't have this problem with earlier version of zookeeper (e.g. 3.3.1). note that I am testing with 3.5.0-rc1.
Thanks, Steven 14/08/23 19:51:32 INFO [main-SendThread(zkserver:2181)] (ClientCnxn.java:1091) - Opening socket connection to server zkserver/ 192.168.1.2:2181. Will not attempt to authenticate using SASL (unknown error) 14/08/23 19:51:32 INFO [NIOServerCxnFactory.AcceptThread:/192.168.1.2:2181] (NIOServerCnxnFactory.java:296) - Accepted socket connection from / 192.168.1.2:52468 14/08/23 19:51:32 INFO [main-SendThread(zkserver:2181)] (ClientCnxn.java:961) - Socket connection established to zkserver/ 192.168.1.2:2181, initiating session 14/08/23 19:51:32 DEBUG [main-SendThread(zkserver:2181)] (ClientCnxn.java:1001) - Session establishment request sent on zkserver/ 192.168.1.2:2181 14/08/23 19:51:32 DEBUG [NIOWorkerThread-6] (ZooKeeperServer.java:822) - Session establishment request from client /192.168.1.2:52468 client's lastZxid is 0x7 14/08/23 19:51:32 INFO [NIOWorkerThread-6] (ZooKeeperServer.java:853) - Refusing session request for client /192.168.1.2:52468 as it has seen zxid 0x7 our last zxid is 0x0 client must try another server 14/08/23 19:51:32 INFO [NIOWorkerThread-6] (NIOServerCnxn.java:1006) - Closed socket connection for client /192.168.1.2:52468 (no session established for client) 14/08/23 19:51:32 INFO [main-SendThread(zkserver:2181)] (ClientCnxn.java:1208) - Unable to read additional data from server sessionid 0x14805ec4abd0000, likely server has closed socket, closing socket connection and attempting reconnect EndOfStreamException: Unable to read additional data from server sessionid 0x14805ec4abd0000, likely server has closed socket at org.apache.zookeeper.ClientCnxnSocketNIO.doIO(ClientCnxnSocketNIO.java:75) at org.apache.zookeeper.ClientCnxnSocketNIO.doTransport(ClientCnxnSocketNIO.java:363) at org.apache.zookeeper.ClientCnxn$SendThread.run(ClientCnxn.java:1190) On Sat, Aug 23, 2014 at 4:16 PM, Michi Mutsuzaki <[email protected]> wrote: > Yes, it would be great if you can get the zookeeper server log at the > DEBUG level. > > On Sat, Aug 23, 2014 at 2:54 PM, Steven Wu <[email protected]> wrote: > > It's a unit test. so I started the zookeeper server programmatically in > > localhost. looks like I better get log4j to work so that I can see logs > from > > ZooKeeperServer. > > > > > > On Sat, Aug 23, 2014 at 12:02 PM, Michi Mutsuzaki <[email protected] > > > > wrote: > >> > >> It would be helpful if you have the zookeeper server log from > >> 192.168.1.2:2181. > >> > >> On Sat, Aug 23, 2014 at 9:31 AM, Steven Wu <[email protected]> > wrote: > >> > client got the connected NIO event to the 2nd server instance. I also > >> > tried > >> > telnet to 192.168.1.2:2181. for whatever reason (e.g. protocol/auth), > >> > server decides to close the connection. > >> > > >> > > >> > On Sat, Aug 23, 2014 at 7:49 AM, Alexander Shraer <[email protected]> > >> > wrote: > >> > > >> >> is it possible that the new server isn't listening on the 2181 client > >> >> port > >> >> ? > >> >> perhaps something is misconfigured on the server side. > >> >> > >> >> > >> >> On Fri, Aug 22, 2014 at 9:32 PM, Steven Wu <[email protected]> > >> >> wrote: > >> >> > >> >> > I am writing a unit test to simulate a scenario where server > changes > >> >> > IP, > >> >> > which can happen in cloud env. During push, new instance can get a > >> >> > different private IP. > >> >> > > >> >> > As you can see from pasted code, I am running the test using > >> >> > zkclient. > >> >> > ZooKeeper#updateServerList works well by forcing resolution to new > IP > >> >> > address that 2nd ZooKeeperServer object binds to. but the weird > thing > >> >> > is > >> >> > that after connection established, it seems that server closes > >> >> > connection > >> >> > immediately. please see the log output in the end. I added some > debug > >> >> > System.out. > >> >> > > >> >> > I am using zookeeper-3.5.0-rc1. Any help is appreciated! > >> >> > > >> >> > Thanks, > >> >> > Steven > >> >> > > >> >> > ############################################### > >> >> > /** > >> >> > * To test this unit testing, the followings should be done first > >> >> > * > >> >> > * ====== pre-test setup ====== > >> >> > * # bind 192.168.1.1 and 192.168.1.2 to lo0 interface as alias > >> >> > * sudo ifconfig lo0 192.168.1.1 alias > >> >> > * sudo ifconfig lo0 192.168.1.2 alias > >> >> > * > >> >> > * ====== manual test ====== > >> >> > * - add mapping to /etc/hosts > >> >> > * 192.168.1.1 zkserver > >> >> > * - run test. it should stuck in the line of second > >> >> > client.createEphemeral(...) > >> >> > * - change mapping in /etc/hosts > >> >> > * 192.168.1.2 zkserver > >> >> > * - test should proceed and finish > >> >> > */ > >> >> > @Ignore > >> >> > public class TestServerIpChange { > >> >> > > >> >> > @Test > >> >> > public void test() throws InterruptedException, IOException { > >> >> > System.setProperty("log4j.logger.org.apache.zookeeper", > >> >> > "INFO"); > >> >> > ZkServer _zkServer = > >> >> TestUtil.startZkServer("Zk_SERVER_IP_Change", > >> >> > "192.168.1.1", 2181); > >> >> > > >> >> > ZkClient client = new ZkClient("zkserver:2181", 10000, > 5000); > >> >> > client.createEphemeral("/a"); > >> >> > for (int i = 0; i < 5; ++i) { > >> >> > System.out.println("send and receive data: " + i); > >> >> > client.readData("/a"); > >> >> > client.writeData("/a", Integer.toString(i)); > >> >> > Thread.sleep(1000); > >> >> > System.out.println("sleeping..." + i); > >> >> > } > >> >> > _zkServer.shutdown(); > >> >> > > >> >> > _zkServer = TestUtil.startZkServer("Zk_SERVER_IP_Change", > >> >> > "192.168.1.2", 2181); > >> >> > // change /etc/hosts > >> >> > client.createEphemeral("/a"); > >> >> > for (int i = 0; i < 5; ++i) { > >> >> > System.out.println("send and receive data: " + i); > >> >> > client.readData("/a"); > >> >> > client.writeData("/a", Integer.toString(i)); > >> >> > Thread.sleep(1000); > >> >> > System.out.println("sleeping..." + i); > >> >> > } > >> >> > _zkServer.shutdown(); > >> >> > } > >> >> > > >> >> > } > >> >> > > >> >> > ########################################### > >> >> > 14/08/22 21:17:46 INFO [main] (ZkServer.java:85) - Starting > ZkServer > >> >> > on: > >> >> > hostname = 192.168.1.1, port = 2181 > >> >> > 14/08/22 21:17:46 INFO [main] (ZkServer.java:99) - Start single > >> >> zookeeper > >> >> > server... > >> >> > 14/08/22 21:17:46 INFO [main] (ZkServer.java:100) - data dir: > >> >> > > >> >> > > >> >> > >> >> > /Users/stevenwu/workspaces/github/stevenzwu/zkclient/./build/test/Zk_SERVER_IP_Change/data > >> >> > 14/08/22 21:17:46 INFO [main] (ZkServer.java:101) - data log dir: > >> >> > > >> >> > > >> >> > >> >> > /Users/stevenwu/workspaces/github/stevenzwu/zkclient/./build/test/Zk_SERVER_IP_Change/log > >> >> > 14/08/22 21:17:47 INFO [ZkClient-EventThread-17-zkserver:2181] > >> >> > (ZkEventThread.java:64) - Starting ZkClient event thread. > >> >> > connected to null > >> >> > 14/08/22 21:17:47 INFO [main-EventThread] (ZkClient.java:450) - > >> >> zookeeper > >> >> > state changed (SyncConnected) > >> >> > send and receive data: 0 > >> >> > sleeping...0 > >> >> > send and receive data: 1 > >> >> > sleeping...1 > >> >> > send and receive data: 2 > >> >> > sleeping...2 > >> >> > send and receive data: 3 > >> >> > sleeping...3 > >> >> > send and receive data: 4 > >> >> > sleeping...4 > >> >> > 14/08/22 21:17:52 INFO [main] (ZkServer.java:124) - Shutting down > >> >> > ZkServer... > >> >> > 14/08/22 21:17:52 INFO [main] (ZkServer.java:143) - Shutting down > >> >> > ZkServer...done > >> >> > 14/08/22 21:17:52 INFO [main] (ZkServer.java:85) - Starting > ZkServer > >> >> > on: > >> >> > hostname = 192.168.1.2, port = 2181 > >> >> > 14/08/22 21:17:52 INFO [main] (ZkServer.java:99) - Start single > >> >> zookeeper > >> >> > server... > >> >> > 14/08/22 21:17:52 INFO [main] (ZkServer.java:100) - data dir: > >> >> > > >> >> > > >> >> > >> >> > /Users/stevenwu/workspaces/github/stevenzwu/zkclient/./build/test/Zk_SERVER_IP_Change/data > >> >> > 14/08/22 21:17:52 INFO [main] (ZkServer.java:101) - data log dir: > >> >> > > >> >> > > >> >> > >> >> > /Users/stevenwu/workspaces/github/stevenzwu/zkclient/./build/test/Zk_SERVER_IP_Change/log > >> >> > > >> >> > EndOfStreamException: Unable to read additional data from server > >> >> sessionid > >> >> > 0x14801159e240000, likely server has closed socket > >> >> > at > >> >> > > >> >> > >> >> > org.apache.zookeeper.ClientCnxnSocketNIO.doIO(ClientCnxnSocketNIO.java:75) > >> >> > at > >> >> > > >> >> > > >> >> > >> >> > org.apache.zookeeper.ClientCnxnSocketNIO.doTransport(ClientCnxnSocketNIO.java:363) > >> >> > at > >> >> > > org.apache.zookeeper.ClientCnxn$SendThread.run(ClientCnxn.java:1190) > >> >> > 14/08/22 21:17:52 INFO [main-EventThread] (ZkClient.java:450) - > >> >> zookeeper > >> >> > state changed (Disconnected) > >> >> > > >> >> > ... > >> >> > > >> >> > java.net.ConnectException: Connection refused > >> >> > at sun.nio.ch.SocketChannelImpl.checkConnect(Native Method) > >> >> > at > >> >> > > sun.nio.ch.SocketChannelImpl.finishConnect(SocketChannelImpl.java:735) > >> >> > at > >> >> > > >> >> > > >> >> > >> >> > org.apache.zookeeper.ClientCnxnSocketNIO.doTransport(ClientCnxnSocketNIO.java:356) > >> >> > at > >> >> > > org.apache.zookeeper.ClientCnxn$SendThread.run(ClientCnxn.java:1190) > >> >> > > >> >> > ... > >> >> > > >> >> > java.net.ConnectException: Connection refused > >> >> > at sun.nio.ch.SocketChannelImpl.checkConnect(Native Method) > >> >> > at > >> >> > > sun.nio.ch.SocketChannelImpl.finishConnect(SocketChannelImpl.java:735) > >> >> > at > >> >> > > >> >> > > >> >> > >> >> > org.apache.zookeeper.ClientCnxnSocketNIO.doTransport(ClientCnxnSocketNIO.java:356) > >> >> > at > >> >> > > org.apache.zookeeper.ClientCnxn$SendThread.run(ClientCnxn.java:1190) > >> >> > > >> >> > ... > >> >> > > >> >> > connected to zkserver/192.168.1.2:2181 > >> >> > EndOfStreamException: Unable to read additional data from server > >> >> sessionid > >> >> > 0x14801159e240000, likely server has closed socket > >> >> > at > >> >> > > >> >> > >> >> > org.apache.zookeeper.ClientCnxnSocketNIO.doIO(ClientCnxnSocketNIO.java:75) > >> >> > at > >> >> > > >> >> > > >> >> > >> >> > org.apache.zookeeper.ClientCnxnSocketNIO.doTransport(ClientCnxnSocketNIO.java:363) > >> >> > at > >> >> > > org.apache.zookeeper.ClientCnxn$SendThread.run(ClientCnxn.java:1190) > >> >> > > >> >> > ... > >> >> > > >> >> > connected to zkserver/192.168.1.2:2181 > >> >> > EndOfStreamException: Unable to read additional data from server > >> >> sessionid > >> >> > 0x14801159e240000, likely server has closed socket > >> >> > at > >> >> > > >> >> > >> >> > org.apache.zookeeper.ClientCnxnSocketNIO.doIO(ClientCnxnSocketNIO.java:75) > >> >> > at > >> >> > > >> >> > > >> >> > >> >> > org.apache.zookeeper.ClientCnxnSocketNIO.doTransport(ClientCnxnSocketNIO.java:363) > >> >> > at > >> >> > > org.apache.zookeeper.ClientCnxn$SendThread.run(ClientCnxn.java:1190) > >> >> > > >> >> > > > > >
