zookeeper-user mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Steven Wu <stevenz...@gmail.com>
Subject Re: zookeeper server close connection unexpected
Date Sun, 24 Aug 2014 03:35:29 GMT
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 <michi@cs.stanford.edu>
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 <stevenz3wu@gmail.com> 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 <michi@cs.stanford.edu
> >
> > 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 <stevenz3wu@gmail.com>
> 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 <shralex@gmail.com>
> >> > 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 <stevenz3wu@gmail.com>
> >> >> 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)
> >> >> >
> >> >>
> >
> >
>

Mime
  • Unnamed multipart/alternative (inline, None, 0 bytes)
View raw message